openerp/netsvc.py

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