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 #.apidoc title: Common Services: netsvc
  23 #.apidoc module-mods: member-order: bysource
  24
  25 import errno
  26 import logging
  27 import logging.handlers
  28 import os
  29 import platform
  30 import release
  31 import socket
  32 import sys
  33 import threading
  34 import time
  35 import types
  36 from pprint import pformat
  37
  38 try:
  39     import psutil
  40 except ImportError:
  41     psutil = None
  42
  43 # TODO modules that import netsvc only for things from loglevels must be changed to use loglevels.
  44 from loglevels import *
  45 import tools
  46 import openerp
  47
  48 _logger = logging.getLogger(__name__)
  49
  50
  51 def close_socket(sock):
  52     """ Closes a socket instance cleanly
  53
  54     :param sock: the network socket to close
  55     :type sock: socket.socket
  56     """
  57     try:
  58         sock.shutdown(socket.SHUT_RDWR)
  59     except socket.error, e:
  60         # On OSX, socket shutdowns both sides if any side closes it
  61         # causing an error 57 'Socket is not connected' on shutdown
  62         # of the other side (or something), see
  63         # http://bugs.python.org/issue4397
  64         # note: stdlib fixed test, not behavior
  65         if e.errno != errno.ENOTCONN or platform.system() not in ['Darwin', 'Windows']:
  66             raise
  67     sock.close()
  68
  69 def abort_response(dummy_1, description, dummy_2, details):
  70     # TODO Replace except_{osv,orm} with these directly.
  71     raise openerp.osv.osv.except_osv(description, details)
  72
  73 class Service(object):
  74     """ Base class for Local services
  75     Functionality here is trusted, no authentication.
  76     Workflow engine and reports subclass this.
  77     """
  78     _services = {}
  79     def __init__(self, name):
  80         Service._services[name] = self
  81         self.__name = name
  82
  83     @classmethod
  84     def exists(cls, name):
  85         return name in cls._services
  86
  87     @classmethod
  88     def remove(cls, name):
  89         if cls.exists(name):
  90             cls._services.pop(name)
  91
  92 def LocalService(name):
  93     # Special case for addons support, will be removed in a few days when addons
  94     # are updated to directly use openerp.osv.osv.service.
  95     if name == 'object_proxy':
  96         return openerp.osv.osv.service
  97
  98     return Service._services[name]
  99
 100 class ExportService(object):
 101     """ Proxy for exported services.
 102
 103     Note that this class has no direct proxy, capable of calling
 104     eservice.method(). Rather, the proxy should call
 105     dispatch(method, params)
 106     """
 107
 108     _services = {}
 109
 110     def __init__(self, name):
 111         ExportService._services[name] = self
 112         self.__name = name
 113         _logger.debug("Registered an exported service: %s" % name)
 114
 115     @classmethod
 116     def getService(cls,name):
 117         return cls._services[name]
 118
 119     # Dispatch a RPC call w.r.t. the method name. The dispatching
 120     # w.r.t. the service (this class) is done by OpenERPDispatcher.
 121     def dispatch(self, method, params):
 122         raise Exception("stub dispatch at %s" % self.__name)
 123
 124 BLACK, RED, GREEN, YELLOW, BLUE, MAGENTA, CYAN, WHITE, _NOTHING, DEFAULT = range(10)
 125 #The background is set with 40 plus the number of the color, and the foreground with 30
 126 #These are the sequences need to get colored ouput
 127 RESET_SEQ = "\033[0m"
 128 COLOR_SEQ = "\033[1;%dm"
 129 BOLD_SEQ = "\033[1m"
 130 COLOR_PATTERN = "%s%s%%s%s" % (COLOR_SEQ, COLOR_SEQ, RESET_SEQ)
 131 LEVEL_COLOR_MAPPING = {
 132     logging.DEBUG: (BLUE, DEFAULT),
 133     logging.INFO: (GREEN, DEFAULT),
 134     logging.TEST: (WHITE, BLUE),
 135     logging.WARNING: (YELLOW, DEFAULT),
 136     logging.ERROR: (RED, DEFAULT),
 137     logging.CRITICAL: (WHITE, RED),
 138 }
 139
 140 class DBFormatter(logging.Formatter):
 141     def format(self, record):
 142         record.pid = os.getpid()
 143         record.dbname = getattr(threading.currentThread(), 'dbname', '?')
 144         return logging.Formatter.format(self, record)
 145
 146 class ColoredFormatter(DBFormatter):
 147     def format(self, record):
 148         fg_color, bg_color = LEVEL_COLOR_MAPPING[record.levelno]
 149         record.levelname = COLOR_PATTERN % (30 + fg_color, 40 + bg_color, record.levelname)
 150         return DBFormatter.format(self, record)
 151
 152 _logger_init = False
 153 def init_logger():
 154     global _logger_init
 155     if _logger_init:
 156         return
 157     _logger_init = True
 158
 159     from tools.translate import resetlocale
 160     resetlocale()
 161
 162     # create a format for log messages and dates
 163     format = '%(asctime)s %(pid)s %(levelname)s %(dbname)s %(name)s: %(message)s'
 164
 165     if tools.config['syslog']:
 166         # SysLog Handler
 167         if os.name == 'nt':
 168             handler = logging.handlers.NTEventLogHandler("%s %s" % (release.description, release.version))
 169         else:
 170             handler = logging.handlers.SysLogHandler('/dev/log')
 171         format = '%s %s' % (release.description, release.version) \
 172                 + ':%(dbname)s:%(levelname)s:%(name)s:%(message)s'
 173
 174     elif tools.config['logfile']:
 175         # LogFile Handler
 176         logf = tools.config['logfile']
 177         try:
 178             dirname = os.path.dirname(logf)
 179             if dirname and not os.path.isdir(dirname):
 180                 os.makedirs(dirname)
 181             if tools.config['logrotate'] is not False:
 182                 handler = logging.handlers.TimedRotatingFileHandler(logf,'D',1,30)
 183             elif os.name == 'posix':
 184                 handler = logging.handlers.WatchedFileHandler(logf)
 185             else:
 186                 handler = logging.handlers.FileHandler(logf)
 187         except Exception:
 188             sys.stderr.write("ERROR: couldn't create the logfile directory. Logging to the standard output.\n")
 189             handler = logging.StreamHandler(sys.stdout)
 190     else:
 191         # Normal Handler on standard output
 192         handler = logging.StreamHandler(sys.stdout)
 193
 194     # Check that handler.stream has a fileno() method: when running OpenERP
 195     # behind Apache with mod_wsgi, handler.stream will have type mod_wsgi.Log,
 196     # which has no fileno() method. (mod_wsgi.Log is what is being bound to
 197     # sys.stderr when the logging.StreamHandler is being constructed above.)
 198     if isinstance(handler, logging.StreamHandler) \
 199         and hasattr(handler.stream, 'fileno') \
 200         and os.isatty(handler.stream.fileno()):
 201         formatter = ColoredFormatter(format)
 202     else:
 203         formatter = DBFormatter(format)
 204     handler.setFormatter(formatter)
 205
 206     logging.getLogger().addHandler(handler)
 207
 208     # Configure handlers
 209     default_config = [
 210         'openerp.netsvc.rpc.request:INFO',
 211         'openerp.netsvc.rpc.response:INFO',
 212         'openerp.addons.web.http:INFO',
 213         'openerp.sql_db:INFO',
 214         ':INFO',
 215     ]
 216
 217     if tools.config['log_level'] == 'info':
 218         pseudo_config = []
 219     elif tools.config['log_level'] == 'debug_rpc':
 220         pseudo_config = ['openerp:DEBUG','openerp.netsvc.rpc.request:DEBUG']
 221     elif tools.config['log_level'] == 'debug_rpc_answer':
 222         pseudo_config = ['openerp:DEBUG','openerp.netsvc.rpc.request:DEBUG', 'openerp.netsvc.rpc.response:DEBUG']
 223     elif tools.config['log_level'] == 'debug':
 224         pseudo_config = ['openerp:DEBUG']
 225     elif tools.config['log_level'] == 'test':
 226         pseudo_config = ['openerp:TEST']
 227     elif tools.config['log_level'] == 'warn':
 228         pseudo_config = ['openerp:WARNING']
 229     elif tools.config['log_level'] == 'error':
 230         pseudo_config = ['openerp:ERROR']
 231     elif tools.config['log_level'] == 'critical':
 232         pseudo_config = ['openerp:CRITICAL']
 233     elif tools.config['log_level'] == 'debug_sql':
 234         pseudo_config = ['openerp.sql_db:DEBUG']
 235     else:
 236         pseudo_config = []
 237
 238     logconfig = tools.config['log_handler']
 239
 240     for logconfig_item in default_config + pseudo_config + logconfig:
 241         loggername, level = logconfig_item.split(':')
 242         level = getattr(logging, level, logging.INFO)
 243         logger = logging.getLogger(loggername)
 244         logger.setLevel(level)
 245
 246     for logconfig_item in default_config + pseudo_config + logconfig:
 247         _logger.debug('logger level set: "%s"', logconfig_item)
 248
 249 # A alternative logging scheme for automated runs of the
 250 # server intended to test it.
 251 def init_alternative_logger():
 252     class H(logging.Handler):
 253         def emit(self, record):
 254             if record.levelno > 20:
 255                 print record.levelno, record.pathname, record.msg
 256     handler = H()
 257     # Add the handler to the 'openerp' logger.
 258     logger = logging.getLogger('openerp')
 259     logger.addHandler(handler)
 260     logger.setLevel(logging.ERROR)
 261
 262 def replace_request_password(args):
 263     # password is always 3rd argument in a request, we replace it in RPC logs
 264     # so it's easier to forward logs for diagnostics/debugging purposes...
 265     if len(args) > 2:
 266         args = list(args)
 267         args[2] = '*'
 268     return tuple(args)
 269
 270 def log(logger, level, prefix, msg, depth=None):
 271     indent=''
 272     indent_after=' '*len(prefix)
 273     for line in (prefix+pformat(msg, depth=depth)).split('\n'):
 274         logger.log(level, indent+line)
 275         indent=indent_after
 276
 277 def dispatch_rpc(service_name, method, params):
 278     """ Handle a RPC call.
 279
 280     This is pure Python code, the actual marshalling (from/to XML-RPC or
 281     NET-RPC) is done in a upper layer.
 282     """
 283     try:
 284         rpc_request = logging.getLogger(__name__ + '.rpc.request')
 285         rpc_response = logging.getLogger(__name__ + '.rpc.response')
 286         rpc_request_flag = rpc_request.isEnabledFor(logging.DEBUG)
 287         rpc_response_flag = rpc_response.isEnabledFor(logging.DEBUG)
 288         if rpc_request_flag or rpc_response_flag:
 289             start_time = time.time()
 290             start_rss, start_vms = 0, 0
 291             if psutil:
 292                 start_rss, start_vms = psutil.Process(os.getpid()).get_memory_info()
 293             if rpc_request and rpc_response_flag:
 294                 log(rpc_request,logging.DEBUG,'%s.%s'%(service_name,method), replace_request_password(params))
 295
 296         result = ExportService.getService(service_name).dispatch(method, params)
 297
 298         if rpc_request_flag or rpc_response_flag:
 299             end_time = time.time()
 300             end_rss, end_vms = 0, 0
 301             if psutil:
 302                 end_rss, end_vms = psutil.Process(os.getpid()).get_memory_info()
 303             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)
 304             if rpc_response_flag:
 305                 log(rpc_response,logging.DEBUG, logline, result)
 306             else:
 307                 log(rpc_request,logging.DEBUG, logline, replace_request_password(params), depth=1)
 308
 309         return result
 310     except openerp.exceptions.AccessError:
 311         raise
 312     except openerp.exceptions.AccessDenied:
 313         raise
 314     except openerp.exceptions.Warning:
 315         raise
 316     except openerp.exceptions.DeferredException, e:
 317         _logger.exception(tools.exception_to_unicode(e))
 318         post_mortem(e.traceback)
 319         raise
 320     except Exception, e:
 321         _logger.exception(tools.exception_to_unicode(e))
 322         post_mortem(sys.exc_info())
 323         raise
 324
 325 def post_mortem(info):
 326     if tools.config['debug_mode'] and isinstance(info[2], types.TracebackType):
 327         import pdb
 328         pdb.post_mortem(info[2])
 329
 330 # vim:expandtab:smartindent:tabstop=4:softtabstop=4:shiftwidth=4: