openerp/netsvc.py

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