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