openerp/netsvc.py

   1 #!/usr/bin/env python
   2 # -*- coding: utf-8 -*-
   3 ##############################################################################
   4 #
   5 #    OpenERP, Open Source Management Solution
   6 #    Copyright (C) 2004-2012 OpenERP SA (<http://www.openerp.com>)
   7 #
   8 #    This program is free software: you can redistribute it and/or modify
   9 #    it under the terms of the GNU Affero General Public License as
  10 #    published by the Free Software Foundation, either version 3 of the
  11 #    License, or (at your option) any later version.
  12 #
  13 #    This program is distributed in the hope that it will be useful,
  14 #    but WITHOUT ANY WARRANTY; without even the implied warranty of
  15 #    MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
  16 #    GNU Affero General Public License for more details.
  17 #
  18 #    You should have received a copy of the GNU Affero General Public License
  19 #    along with this program.  If not, see <http://www.gnu.org/licenses/>.
  20 #
  21 ##############################################################################
  22
  23 #.apidoc title: Common Services: netsvc
  24 #.apidoc module-mods: member-order: bysource
  25
  26 import errno
  27 import logging
  28 import logging.handlers
  29 import os
  30 import platform
  31 import release
  32 import socket
  33 import sys
  34 import threading
  35 import time
  36 import types
  37 from pprint import pformat
  38
  39 try:
  40     import psutil
  41 except ImportError:
  42     psutil = None
  43
  44 # TODO modules that import netsvc only for things from loglevels must be changed to use loglevels.
  45 from loglevels import *
  46 import tools
  47 import openerp
  48
  49 _logger = logging.getLogger(__name__)
  50
  51
  52 def close_socket(sock):
  53     """ Closes a socket instance cleanly
  54
  55     :param sock: the network socket to close
  56     :type sock: socket.socket
  57     """
  58     try:
  59         sock.shutdown(socket.SHUT_RDWR)
  60     except socket.error, e:
  61         # On OSX, socket shutdowns both sides if any side closes it
  62         # causing an error 57 'Socket is not connected' on shutdown
  63         # of the other side (or something), see
  64         # http://bugs.python.org/issue4397
  65         # note: stdlib fixed test, not behavior
  66         if e.errno != errno.ENOTCONN or platform.system() not in ['Darwin', 'Windows']:
  67             raise
  68     sock.close()
  69
  70 def abort_response(dummy_1, description, dummy_2, details):
  71     # TODO Replace except_{osv,orm} with these directly.
  72     raise openerp.osv.osv.except_osv(description, details)
  73
  74 class Service(object):
  75     """ Base class for Local services
  76     Functionality here is trusted, no authentication.
  77     Workflow engine and reports subclass this.
  78     """
  79     _services = {}
  80     def __init__(self, name):
  81         Service._services[name] = self
  82         self.__name = name
  83
  84     @classmethod
  85     def exists(cls, name):
  86         return name in cls._services
  87
  88     @classmethod
  89     def remove(cls, name):
  90         if cls.exists(name):
  91             cls._services.pop(name)
  92
  93 def LocalService(name):
  94     # Special case for addons support, will be removed in a few days when addons
  95     # are updated to directly use openerp.osv.osv.service.
  96     if name == 'object_proxy':
  97         return openerp.osv.osv.service
  98
  99     return Service._services[name]
 100
 101 class ExportService(object):
 102     """ Proxy for exported services.
 103
 104     Note that this class has no direct proxy, capable of calling
 105     eservice.method(). Rather, the proxy should call
 106     dispatch(method, params)
 107     """
 108
 109     _services = {}
 110
 111     def __init__(self, name):
 112         ExportService._services[name] = self
 113         self.__name = name
 114         _logger.debug("Registered an exported service: %s" % name)
 115
 116     @classmethod
 117     def getService(cls,name):
 118         return cls._services[name]
 119
 120     # Dispatch a RPC call w.r.t. the method name. The dispatching
 121     # w.r.t. the service (this class) is done by OpenERPDispatcher.
 122     def dispatch(self, method, params):
 123         raise Exception("stub dispatch at %s" % self.__name)
 124
 125 BLACK, RED, GREEN, YELLOW, BLUE, MAGENTA, CYAN, WHITE, _NOTHING, DEFAULT = range(10)
 126 #The background is set with 40 plus the number of the color, and the foreground with 30
 127 #These are the sequences need to get colored ouput
 128 RESET_SEQ = "\033[0m"
 129 COLOR_SEQ = "\033[1;%dm"
 130 BOLD_SEQ = "\033[1m"
 131 COLOR_PATTERN = "%s%s%%s%s" % (COLOR_SEQ, COLOR_SEQ, RESET_SEQ)
 132 LEVEL_COLOR_MAPPING = {
 133     logging.DEBUG: (BLUE, DEFAULT),
 134     logging.INFO: (GREEN, DEFAULT),
 135     logging.TEST: (WHITE, BLUE),
 136     logging.WARNING: (YELLOW, DEFAULT),
 137     logging.ERROR: (RED, DEFAULT),
 138     logging.CRITICAL: (WHITE, RED),
 139 }
 140
 141 class DBFormatter(logging.Formatter):
 142     def format(self, record):
 143         record.pid = os.getpid()
 144         record.dbname = getattr(threading.currentThread(), 'dbname', '?')
 145         return logging.Formatter.format(self, record)
 146
 147 class ColoredFormatter(DBFormatter):
 148     def format(self, record):
 149         fg_color, bg_color = LEVEL_COLOR_MAPPING[record.levelno]
 150         record.levelname = COLOR_PATTERN % (30 + fg_color, 40 + bg_color, record.levelname)
 151         return DBFormatter.format(self, record)
 152
 153 def init_logger():
 154     from tools.translate import resetlocale
 155     resetlocale()
 156
 157     # create a format for log messages and dates
 158     format = '%(asctime)s %(pid)s %(levelname)s %(dbname)s %(name)s: %(message)s'
 159
 160     if tools.config['syslog']:
 161         # SysLog Handler
 162         if os.name == 'nt':
 163             handler = logging.handlers.NTEventLogHandler("%s %s" % (release.description, release.version))
 164         else:
 165             handler = logging.handlers.SysLogHandler('/dev/log')
 166         format = '%s %s' % (release.description, release.version) \
 167                 + ':%(dbname)s:%(levelname)s:%(name)s:%(message)s'
 168
 169     elif tools.config['logfile']:
 170         # LogFile Handler
 171         logf = tools.config['logfile']
 172         try:
 173             dirname = os.path.dirname(logf)
 174             if dirname and not os.path.isdir(dirname):
 175                 os.makedirs(dirname)
 176             if tools.config['logrotate'] is not False:
 177                 handler = logging.handlers.TimedRotatingFileHandler(logf,'D',1,30)
 178             elif os.name == 'posix':
 179                 handler = logging.handlers.WatchedFileHandler(logf)
 180             else:
 181                 handler = logging.handlers.FileHandler(logf)
 182         except Exception:
 183             sys.stderr.write("ERROR: couldn't create the logfile directory. Logging to the standard output.\n")
 184             handler = logging.StreamHandler(sys.stdout)
 185     else:
 186         # Normal Handler on standard output
 187         handler = logging.StreamHandler(sys.stdout)
 188
 189     # Check that handler.stream has a fileno() method: when running OpenERP
 190     # behind Apache with mod_wsgi, handler.stream will have type mod_wsgi.Log,
 191     # which has no fileno() method. (mod_wsgi.Log is what is being bound to
 192     # sys.stderr when the logging.StreamHandler is being constructed above.)
 193     if isinstance(handler, logging.StreamHandler) \
 194         and hasattr(handler.stream, 'fileno') \
 195         and os.isatty(handler.stream.fileno()):
 196         formatter = ColoredFormatter(format)
 197     else:
 198         formatter = DBFormatter(format)
 199     handler.setFormatter(formatter)
 200
 201     # Configure handlers
 202     default_config = [
 203         'openerp.netsvc.rpc.request:INFO',
 204         'openerp.netsvc.rpc.response:INFO',
 205         'openerp.addons.web.http:INFO',
 206         'openerp.sql_db:INFO',
 207         ':INFO',
 208     ]
 209
 210     if tools.config['log_level'] == 'info':
 211         pseudo_config = []
 212     elif tools.config['log_level'] == 'debug_rpc':
 213         pseudo_config = ['openerp:DEBUG','openerp.netsvc.rpc.request:DEBUG']
 214     elif tools.config['log_level'] == 'debug_rpc_answer':
 215         pseudo_config = ['openerp:DEBUG','openerp.netsvc.rpc.request:DEBUG', 'openerp.netsvc.rpc.response:DEBUG']
 216     elif tools.config['log_level'] == 'debug':
 217         pseudo_config = ['openerp:DEBUG']
 218     elif tools.config['log_level'] == 'test':
 219         pseudo_config = ['openerp:TEST']
 220     elif tools.config['log_level'] == 'warn':
 221         pseudo_config = ['openerp:WARNING']
 222     elif tools.config['log_level'] == 'error':
 223         pseudo_config = ['openerp:ERROR']
 224     elif tools.config['log_level'] == 'critical':
 225         pseudo_config = ['openerp:CRITICAL']
 226     elif tools.config['log_level'] == 'debug_sql':
 227         pseudo_config = ['openerp.sql_db:DEBUG']
 228     else:
 229         pseudo_config = []
 230
 231     logconfig = tools.config['log_handler']
 232
 233     for logconfig_item in default_config + pseudo_config + logconfig:
 234         loggername, level = logconfig_item.split(':')
 235         level = getattr(logging, level, logging.INFO)
 236         logger = logging.getLogger(loggername)
 237         logger.handlers = []
 238         logger.setLevel(level)
 239         logger.addHandler(handler)
 240         if loggername != '':
 241             logger.propagate = False
 242
 243     for logconfig_item in default_config + pseudo_config + logconfig:
 244         _logger.debug('logger level set: "%s"', logconfig_item)
 245
 246 # A alternative logging scheme for automated runs of the
 247 # server intended to test it.
 248 def init_alternative_logger():
 249     class H(logging.Handler):
 250         def emit(self, record):
 251             if record.levelno > 20:
 252                 print record.levelno, record.pathname, record.msg
 253     handler = H()
 254     # Add the handler to the 'openerp' logger.
 255     logger = logging.getLogger('openerp')
 256     logger.addHandler(handler)
 257     logger.setLevel(logging.ERROR)
 258
 259 def replace_request_password(args):
 260     # password is always 3rd argument in a request, we replace it in RPC logs
 261     # so it's easier to forward logs for diagnostics/debugging purposes...
 262     if len(args) > 2:
 263         args = list(args)
 264         args[2] = '*'
 265     return tuple(args)
 266
 267 def log(logger, level, prefix, msg, depth=None):
 268     indent=''
 269     indent_after=' '*len(prefix)
 270     for line in (prefix+pformat(msg, depth=depth)).split('\n'):
 271         logger.log(level, indent+line)
 272         indent=indent_after
 273
 274 def dispatch_rpc(service_name, method, params):
 275     """ Handle a RPC call.
 276
 277     This is pure Python code, the actual marshalling (from/to XML-RPC or
 278     NET-RPC) is done in a upper layer.
 279     """
 280     try:
 281         rpc_request = logging.getLogger(__name__ + '.rpc.request')
 282         rpc_response = logging.getLogger(__name__ + '.rpc.response')
 283         rpc_request_flag = rpc_request.isEnabledFor(logging.DEBUG)
 284         rpc_response_flag = rpc_response.isEnabledFor(logging.DEBUG)
 285         if rpc_request_flag or rpc_response_flag:
 286             start_time = time.time()
 287             start_rss, start_vms = 0, 0
 288             if psutil:
 289                 start_rss, start_vms = psutil.Process(os.getpid()).get_memory_info()
 290             if rpc_request and rpc_response_flag:
 291                 log(rpc_request,logging.DEBUG,'%s.%s'%(service_name,method), replace_request_password(params))
 292
 293         result = ExportService.getService(service_name).dispatch(method, params)
 294
 295         if rpc_request_flag or rpc_response_flag:
 296             end_time = time.time()
 297             end_rss, end_vms = 0, 0
 298             if psutil:
 299                 end_rss, end_vms = psutil.Process(os.getpid()).get_memory_info()
 300             logline = '%s.%s time:%.3fs mem: %sk -> %sk (diff: %sk)' % (service_name, method, end_time - start_time, start_vms / 1024, end_vms / 1024, (end_vms - start_vms)/1024)
 301             if rpc_response_flag:
 302                 log(rpc_response,logging.DEBUG, logline, result)
 303             else:
 304                 log(rpc_request,logging.DEBUG, logline, replace_request_password(params), depth=1)
 305
 306         return result
 307     except openerp.exceptions.AccessError:
 308         raise
 309     except openerp.exceptions.AccessDenied:
 310         raise
 311     except openerp.exceptions.Warning:
 312         raise
 313     except openerp.exceptions.DeferredException, e:
 314         _logger.exception(tools.exception_to_unicode(e))
 315         post_mortem(e.traceback)
 316         raise
 317     except Exception, e:
 318         _logger.exception(tools.exception_to_unicode(e))
 319         post_mortem(sys.exc_info())
 320         raise
 321
 322 def post_mortem(info):
 323     if tools.config['debug_mode'] and isinstance(info[2], types.TracebackType):
 324         import pdb
 325         pdb.post_mortem(info[2])
 326
 327 # vim:expandtab:smartindent:tabstop=4:softtabstop=4:shiftwidth=4: