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