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