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
  24 import logging
  25 import logging.handlers
  26 import os
  27 import release
  28 import sys
  29 import threading
  30 import time
  31 import types
  32 from pprint import pformat
  33
  34 try:
  35     import psutil
  36 except ImportError:
  37     psutil = None
  38
  39 # TODO modules that import netsvc only for things from loglevels must be changed to use loglevels.
  40 from loglevels import *
  41 import tools
  42 import openerp
  43
  44 _logger = logging.getLogger(__name__)
  45
  46 def LocalService(name):
  47     """
  48     The openerp.netsvc.LocalService() function is deprecated. It still works
  49     in two cases: workflows and reports. For workflows, instead of using
  50     LocalService('workflow'), openerp.workflow should be used (better yet,
  51     methods on openerp.osv.orm.Model should be used). For reports,
  52     openerp.report.render_report() should be used (methods on the Model should
  53     be provided too in the future).
  54     """
  55     assert openerp.conf.deprecation.allow_local_service
  56     _logger.warning("LocalService() is deprecated since march 2013 (it was called with '%s')." % name)
  57
  58     if name == 'workflow':
  59         return openerp.workflow
  60
  61     if name.startswith('report.'):
  62         report = openerp.report.interface.report_int._reports.get(name)
  63         if report:
  64             return report
  65         else:
  66             dbname = getattr(threading.currentThread(), 'dbname', None)
  67             if dbname:
  68                 registry = openerp.modules.registry.RegistryManager.get(dbname)
  69                 with registry.cursor() as cr:
  70                     return registry['ir.actions.report.xml']._lookup_report(cr, name[len('report.'):])
  71
  72 BLACK, RED, GREEN, YELLOW, BLUE, MAGENTA, CYAN, WHITE, _NOTHING, DEFAULT = range(10)
  73 #The background is set with 40 plus the number of the color, and the foreground with 30
  74 #These are the sequences need to get colored ouput
  75 RESET_SEQ = "\033[0m"
  76 COLOR_SEQ = "\033[1;%dm"
  77 BOLD_SEQ = "\033[1m"
  78 COLOR_PATTERN = "%s%s%%s%s" % (COLOR_SEQ, COLOR_SEQ, RESET_SEQ)
  79 LEVEL_COLOR_MAPPING = {
  80     logging.DEBUG: (BLUE, DEFAULT),
  81     logging.INFO: (GREEN, DEFAULT),
  82     logging.TEST: (WHITE, BLUE),
  83     logging.WARNING: (YELLOW, DEFAULT),
  84     logging.ERROR: (RED, DEFAULT),
  85     logging.CRITICAL: (WHITE, RED),
  86 }
  87
  88 class DBFormatter(logging.Formatter):
  89     def format(self, record):
  90         record.pid = os.getpid()
  91         record.dbname = getattr(threading.currentThread(), 'dbname', '?')
  92         return logging.Formatter.format(self, record)
  93
  94 class ColoredFormatter(DBFormatter):
  95     def format(self, record):
  96         fg_color, bg_color = LEVEL_COLOR_MAPPING[record.levelno]
  97         record.levelname = COLOR_PATTERN % (30 + fg_color, 40 + bg_color, record.levelname)
  98         return DBFormatter.format(self, record)
  99
 100 def init_logger():
 101     from tools.translate import resetlocale
 102     resetlocale()
 103
 104     # create a format for log messages and dates
 105     format = '%(asctime)s %(pid)s %(levelname)s %(dbname)s %(name)s: %(message)s'
 106
 107     if tools.config['syslog']:
 108         # SysLog Handler
 109         if os.name == 'nt':
 110             handler = logging.handlers.NTEventLogHandler("%s %s" % (release.description, release.version))
 111         else:
 112             handler = logging.handlers.SysLogHandler('/dev/log')
 113         format = '%s %s' % (release.description, release.version) \
 114                 + ':%(dbname)s:%(levelname)s:%(name)s:%(message)s'
 115
 116     elif tools.config['logfile']:
 117         # LogFile Handler
 118         logf = tools.config['logfile']
 119         try:
 120             dirname = os.path.dirname(logf)
 121             if dirname and not os.path.isdir(dirname):
 122                 os.makedirs(dirname)
 123             if tools.config['logrotate'] is not False:
 124                 handler = logging.handlers.TimedRotatingFileHandler(logf,'D',1,30)
 125             elif os.name == 'posix':
 126                 handler = logging.handlers.WatchedFileHandler(logf)
 127             else:
 128                 handler = logging.handlers.FileHandler(logf)
 129         except Exception:
 130             sys.stderr.write("ERROR: couldn't create the logfile directory. Logging to the standard output.\n")
 131             handler = logging.StreamHandler(sys.stdout)
 132     else:
 133         # Normal Handler on standard output
 134         handler = logging.StreamHandler(sys.stdout)
 135
 136     # Check that handler.stream has a fileno() method: when running OpenERP
 137     # behind Apache with mod_wsgi, handler.stream will have type mod_wsgi.Log,
 138     # which has no fileno() method. (mod_wsgi.Log is what is being bound to
 139     # sys.stderr when the logging.StreamHandler is being constructed above.)
 140     if isinstance(handler, logging.StreamHandler) \
 141         and hasattr(handler.stream, 'fileno') \
 142         and os.isatty(handler.stream.fileno()):
 143         formatter = ColoredFormatter(format)
 144     else:
 145         formatter = DBFormatter(format)
 146     handler.setFormatter(formatter)
 147
 148     # Configure handlers
 149     default_config = [
 150         'openerp.netsvc.rpc.request:INFO',
 151         'openerp.netsvc.rpc.response:INFO',
 152         'openerp.addons.web.http:INFO',
 153         'openerp.sql_db:INFO',
 154         ':INFO',
 155     ]
 156
 157     if tools.config['log_level'] == 'info':
 158         pseudo_config = []
 159     elif tools.config['log_level'] == 'debug_rpc':
 160         pseudo_config = ['openerp:DEBUG','openerp.netsvc.rpc.request:DEBUG']
 161     elif tools.config['log_level'] == 'debug_rpc_answer':
 162         pseudo_config = ['openerp:DEBUG','openerp.netsvc.rpc.request:DEBUG', 'openerp.netsvc.rpc.response:DEBUG']
 163     elif tools.config['log_level'] == 'debug':
 164         pseudo_config = ['openerp:DEBUG']
 165     elif tools.config['log_level'] == 'test':
 166         pseudo_config = ['openerp:TEST']
 167     elif tools.config['log_level'] == 'warn':
 168         pseudo_config = ['openerp:WARNING']
 169     elif tools.config['log_level'] == 'error':
 170         pseudo_config = ['openerp:ERROR']
 171     elif tools.config['log_level'] == 'critical':
 172         pseudo_config = ['openerp:CRITICAL']
 173     elif tools.config['log_level'] == 'debug_sql':
 174         pseudo_config = ['openerp.sql_db:DEBUG']
 175     else:
 176         pseudo_config = []
 177
 178     logconfig = tools.config['log_handler']
 179
 180     for logconfig_item in default_config + pseudo_config + logconfig:
 181         loggername, level = logconfig_item.split(':')
 182         level = getattr(logging, level, logging.INFO)
 183         logger = logging.getLogger(loggername)
 184         logger.handlers = []
 185         logger.setLevel(level)
 186         logger.addHandler(handler)
 187         if loggername != '':
 188             logger.propagate = False
 189
 190     for logconfig_item in default_config + pseudo_config + logconfig:
 191         _logger.debug('logger level set: "%s"', logconfig_item)
 192
 193 # A alternative logging scheme for automated runs of the
 194 # server intended to test it.
 195 def init_alternative_logger():
 196     class H(logging.Handler):
 197         def emit(self, record):
 198             if record.levelno > 20:
 199                 print record.levelno, record.pathname, record.msg
 200     handler = H()
 201     # Add the handler to the 'openerp' logger.
 202     logger = logging.getLogger('openerp')
 203     logger.addHandler(handler)
 204     logger.setLevel(logging.ERROR)
 205
 206 def replace_request_password(args):
 207     # password is always 3rd argument in a request, we replace it in RPC logs
 208     # so it's easier to forward logs for diagnostics/debugging purposes...
 209     if len(args) > 2:
 210         args = list(args)
 211         args[2] = '*'
 212     return tuple(args)
 213
 214 def log(logger, level, prefix, msg, depth=None):
 215     indent=''
 216     indent_after=' '*len(prefix)
 217     for line in (prefix+pformat(msg, depth=depth)).split('\n'):
 218         logger.log(level, indent+line)
 219         indent=indent_after
 220
 221 def dispatch_rpc(service_name, method, params):
 222     """ Handle a RPC call.
 223
 224     This is pure Python code, the actual marshalling (from/to XML-RPC) is done
 225     in a upper layer.
 226     """
 227     try:
 228         rpc_request = logging.getLogger(__name__ + '.rpc.request')
 229         rpc_response = logging.getLogger(__name__ + '.rpc.response')
 230         rpc_request_flag = rpc_request.isEnabledFor(logging.DEBUG)
 231         rpc_response_flag = rpc_response.isEnabledFor(logging.DEBUG)
 232         if rpc_request_flag or rpc_response_flag:
 233             start_time = time.time()
 234             start_rss, start_vms = 0, 0
 235             if psutil:
 236                 start_rss, start_vms = psutil.Process(os.getpid()).get_memory_info()
 237             if rpc_request and rpc_response_flag:
 238                 log(rpc_request,logging.DEBUG,'%s.%s'%(service_name,method), replace_request_password(params))
 239
 240         threading.current_thread().uid = None
 241         threading.current_thread().dbname = None
 242         if service_name == 'common':
 243             dispatch = openerp.service.common.dispatch
 244         elif service_name == 'db':
 245             dispatch = openerp.service.db.dispatch
 246         elif service_name == 'object':
 247             dispatch = openerp.service.model.dispatch
 248         elif service_name == 'report':
 249             dispatch = openerp.service.report.dispatch
 250         else:
 251             dispatch = openerp.service.wsgi_server.rpc_handlers.get(service_name)
 252         result = dispatch(method, params)
 253
 254         if rpc_request_flag or rpc_response_flag:
 255             end_time = time.time()
 256             end_rss, end_vms = 0, 0
 257             if psutil:
 258                 end_rss, end_vms = psutil.Process(os.getpid()).get_memory_info()
 259             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)
 260             if rpc_response_flag:
 261                 log(rpc_response,logging.DEBUG, logline, result)
 262             else:
 263                 log(rpc_request,logging.DEBUG, logline, replace_request_password(params), depth=1)
 264
 265         return result
 266     except openerp.osv.orm.except_orm:
 267         raise
 268     except openerp.exceptions.AccessError:
 269         raise
 270     except openerp.exceptions.AccessDenied:
 271         raise
 272     except openerp.exceptions.Warning:
 273         raise
 274     except openerp.exceptions.RedirectWarning:
 275         raise
 276     except openerp.exceptions.DeferredException, e:
 277         _logger.exception(tools.exception_to_unicode(e))
 278         post_mortem(e.traceback)
 279         raise
 280     except Exception, e:
 281         _logger.exception(tools.exception_to_unicode(e))
 282         post_mortem(sys.exc_info())
 283         raise
 284
 285 def post_mortem(info):
 286     if tools.config['debug_mode'] and isinstance(info[2], types.TracebackType):
 287         import pdb
 288         pdb.post_mortem(info[2])
 289
 290 # vim:expandtab:smartindent:tabstop=4:softtabstop=4:shiftwidth=4: