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