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
  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 def init_logger():
  93     from tools.translate import resetlocale
  94     resetlocale()
  95
  96     # create a format for log messages and dates
  97     format = '%(asctime)s %(pid)s %(levelname)s %(dbname)s %(name)s: %(message)s'
  98
  99     if tools.config['syslog']:
 100         # SysLog Handler
 101         if os.name == 'nt':
 102             handler = logging.handlers.NTEventLogHandler("%s %s" % (release.description, release.version))
 103         else:
 104             handler = logging.handlers.SysLogHandler('/dev/log')
 105         format = '%s %s' % (release.description, release.version) \
 106                 + ':%(dbname)s:%(levelname)s:%(name)s:%(message)s'
 107
 108     elif tools.config['logfile']:
 109         # LogFile Handler
 110         logf = tools.config['logfile']
 111         try:
 112             dirname = os.path.dirname(logf)
 113             if dirname and not os.path.isdir(dirname):
 114                 os.makedirs(dirname)
 115             if tools.config['logrotate'] is not False:
 116                 handler = logging.handlers.TimedRotatingFileHandler(logf,'D',1,30)
 117             elif os.name == 'posix':
 118                 handler = logging.handlers.WatchedFileHandler(logf)
 119             else:
 120                 handler = logging.handlers.FileHandler(logf)
 121         except Exception:
 122             sys.stderr.write("ERROR: couldn't create the logfile directory. Logging to the standard output.\n")
 123             handler = logging.StreamHandler(sys.stdout)
 124     else:
 125         # Normal Handler on standard output
 126         handler = logging.StreamHandler(sys.stdout)
 127
 128     # Check that handler.stream has a fileno() method: when running OpenERP
 129     # behind Apache with mod_wsgi, handler.stream will have type mod_wsgi.Log,
 130     # which has no fileno() method. (mod_wsgi.Log is what is being bound to
 131     # sys.stderr when the logging.StreamHandler is being constructed above.)
 132     if isinstance(handler, logging.StreamHandler) \
 133         and hasattr(handler.stream, 'fileno') \
 134         and os.isatty(handler.stream.fileno()):
 135         formatter = ColoredFormatter(format)
 136     else:
 137         formatter = DBFormatter(format)
 138     handler.setFormatter(formatter)
 139
 140     # Configure handlers
 141     pseudo_config = PSEUDOCONFIG_MAPPER.get(tools.config['log_level'], [])
 142
 143     logconfig = tools.config['log_handler']
 144
 145     logging_configurations = DEFAULT_LOG_CONFIGURATION + pseudo_config + logconfig
 146     for logconfig_item in logging_configurations:
 147         loggername, level = logconfig_item.split(':')
 148         level = getattr(logging, level, logging.INFO)
 149         logger = logging.getLogger(loggername)
 150         logger.handlers = []
 151         logger.setLevel(level)
 152         logger.addHandler(handler)
 153         if loggername != '':
 154             logger.propagate = False
 155
 156     for logconfig_item in logging_configurations:
 157         _logger.debug('logger level set: "%s"', logconfig_item)
 158
 159 DEFAULT_LOG_CONFIGURATION = [
 160     'openerp.workflow.workitem:WARNING',
 161     'openerp.netsvc.rpc.request:INFO',
 162     'openerp.netsvc.rpc.response:INFO',
 163     'openerp.addons.web.http:INFO',
 164     'openerp.sql_db:INFO',
 165     ':INFO',
 166 ]
 167 PSEUDOCONFIG_MAPPER = {
 168     'debug_rpc_answer': ['openerp:DEBUG','openerp.netsvc.rpc.request:DEBUG', 'openerp.netsvc.rpc.response:DEBUG'],
 169     'debug_rpc': ['openerp:DEBUG','openerp.netsvc.rpc.request:DEBUG'],
 170     'debug': ['openerp:DEBUG'],
 171     'debug_sql': ['openerp.sql_db:DEBUG'],
 172     'info': [],
 173     'warn': ['openerp:WARNING'],
 174     'error': ['openerp:ERROR'],
 175     'critical': ['openerp:CRITICAL'],
 176 }
 177
 178 # A alternative logging scheme for automated runs of the
 179 # server intended to test it.
 180 def init_alternative_logger():
 181     class H(logging.Handler):
 182         def emit(self, record):
 183             if record.levelno > 20:
 184                 print record.levelno, record.pathname, record.msg
 185     handler = H()
 186     # Add the handler to the 'openerp' logger.
 187     logger = logging.getLogger('openerp')
 188     logger.addHandler(handler)
 189     logger.setLevel(logging.ERROR)
 190
 191 def replace_request_password(args):
 192     # password is always 3rd argument in a request, we replace it in RPC logs
 193     # so it's easier to forward logs for diagnostics/debugging purposes...
 194     if len(args) > 2:
 195         args = list(args)
 196         args[2] = '*'
 197     return tuple(args)
 198
 199 def log(logger, level, prefix, msg, depth=None):
 200     indent=''
 201     indent_after=' '*len(prefix)
 202     for line in (prefix+pformat(msg, depth=depth)).split('\n'):
 203         logger.log(level, indent+line)
 204         indent=indent_after
 205
 206 def dispatch_rpc(service_name, method, params):
 207     """ Handle a RPC call.
 208
 209     This is pure Python code, the actual marshalling (from/to XML-RPC) is done
 210     in a upper layer.
 211     """
 212     try:
 213         rpc_request = logging.getLogger(__name__ + '.rpc.request')
 214         rpc_response = logging.getLogger(__name__ + '.rpc.response')
 215         rpc_request_flag = rpc_request.isEnabledFor(logging.DEBUG)
 216         rpc_response_flag = rpc_response.isEnabledFor(logging.DEBUG)
 217         if rpc_request_flag or rpc_response_flag:
 218             start_time = time.time()
 219             start_rss, start_vms = 0, 0
 220             start_rss, start_vms = psutil.Process(os.getpid()).get_memory_info()
 221             if rpc_request and rpc_response_flag:
 222                 log(rpc_request,logging.DEBUG,'%s.%s'%(service_name,method), replace_request_password(params))
 223
 224         threading.current_thread().uid = None
 225         threading.current_thread().dbname = None
 226         if service_name == 'common':
 227             dispatch = openerp.service.common.dispatch
 228         elif service_name == 'db':
 229             dispatch = openerp.service.db.dispatch
 230         elif service_name == 'object':
 231             dispatch = openerp.service.model.dispatch
 232         elif service_name == 'report':
 233             dispatch = openerp.service.report.dispatch
 234         else:
 235             dispatch = openerp.service.wsgi_server.rpc_handlers.get(service_name)
 236         result = dispatch(method, params)
 237
 238         if rpc_request_flag or rpc_response_flag:
 239             end_time = time.time()
 240             end_rss, end_vms = 0, 0
 241             end_rss, end_vms = psutil.Process(os.getpid()).get_memory_info()
 242             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)
 243             if rpc_response_flag:
 244                 log(rpc_response,logging.DEBUG, logline, result)
 245             else:
 246                 log(rpc_request,logging.DEBUG, logline, replace_request_password(params), depth=1)
 247
 248         return result
 249     except openerp.osv.orm.except_orm:
 250         raise
 251     except openerp.exceptions.AccessError:
 252         raise
 253     except openerp.exceptions.AccessDenied:
 254         raise
 255     except openerp.exceptions.Warning:
 256         raise
 257     except openerp.exceptions.RedirectWarning:
 258         raise
 259     except openerp.exceptions.DeferredException, e:
 260         _logger.exception(tools.exception_to_unicode(e))
 261         post_mortem(e.traceback)
 262         raise
 263     except Exception, e:
 264         _logger.exception(tools.exception_to_unicode(e))
 265         post_mortem(sys.exc_info())
 266         raise
 267
 268 def post_mortem(info):
 269     if tools.config['debug_mode'] and isinstance(info[2], types.TracebackType):
 270         import pdb
 271         pdb.post_mortem(info[2])
 272
 273 # vim:expandtab:smartindent:tabstop=4:softtabstop=4:shiftwidth=4: