openerp/netsvc.py

   1 #!/usr/bin/env python
   2 # -*- coding: utf-8 -*-
   3 ##############################################################################
   4 #
   5 #    OpenERP, Open Source Management Solution
   6 #    Copyright (C) 2004-2011 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 import errno
  24 import logging
  25 import logging.handlers
  26 import os
  27 import platform
  28 import release
  29 import socket
  30 import sys
  31 import threading
  32 import time
  33 import types
  34 from pprint import pformat
  35
  36 # TODO modules that import netsvc only for things from loglevels must be changed to use loglevels.
  37 from loglevels import *
  38 import tools
  39 import openerp
  40
  41 _logger = logging.getLogger(__name__)
  42
  43 def close_socket(sock):
  44     """ Closes a socket instance cleanly
  45
  46     :param sock: the network socket to close
  47     :type sock: socket.socket
  48     """
  49     try:
  50         sock.shutdown(socket.SHUT_RDWR)
  51     except socket.error, e:
  52         # On OSX, socket shutdowns both sides if any side closes it
  53         # causing an error 57 'Socket is not connected' on shutdown
  54         # of the other side (or something), see
  55         # http://bugs.python.org/issue4397
  56         # note: stdlib fixed test, not behavior
  57         if e.errno != errno.ENOTCONN or platform.system() != 'Darwin':
  58             raise
  59     sock.close()
  60
  61
  62 #.apidoc title: Common Services: netsvc
  63 #.apidoc module-mods: member-order: bysource
  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
  72         Functionality here is trusted, no authentication.
  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
 149 def init_logger():
 150     from tools.translate import resetlocale
 151     resetlocale()
 152
 153     # create a format for log messages and dates
 154     format = '%(asctime)s %(pid)s %(levelname)s %(dbname)s %(name)s: %(message)s'
 155
 156     if tools.config['syslog']:
 157         # SysLog Handler
 158         if os.name == 'nt':
 159             handler = logging.handlers.NTEventLogHandler("%s %s" % (release.description, release.version))
 160         else:
 161             handler = logging.handlers.SysLogHandler('/dev/log')
 162         format = '%s %s' % (release.description, release.version) \
 163                 + ':%(dbname)s:%(levelname)s:%(name)s:%(message)s'
 164
 165     elif tools.config['logfile']:
 166         # LogFile Handler
 167         logf = tools.config['logfile']
 168         try:
 169             dirname = os.path.dirname(logf)
 170             if dirname and not os.path.isdir(dirname):
 171                 os.makedirs(dirname)
 172             if tools.config['logrotate'] is not False:
 173                 handler = logging.handlers.TimedRotatingFileHandler(logf,'D',1,30)
 174             elif os.name == 'posix':
 175                 handler = logging.handlers.WatchedFileHandler(logf)
 176             else:
 177                 handler = logging.handlers.FileHandler(logf)
 178         except Exception:
 179             sys.stderr.write("ERROR: couldn't create the logfile directory. Logging to the standard output.\n")
 180             handler = logging.StreamHandler(sys.stdout)
 181     else:
 182         # Normal Handler on standard output
 183         handler = logging.StreamHandler(sys.stdout)
 184
 185     if isinstance(handler, logging.StreamHandler) and os.isatty(handler.stream.fileno()):
 186         formatter = ColoredFormatter(format)
 187     else:
 188         formatter = DBFormatter(format)
 189     handler.setFormatter(formatter)
 190
 191     # Configure handlers
 192     default_config = [
 193         'openerp.netsvc.rpc.request:INFO',
 194         'openerp.netsvc.rpc.response:INFO',
 195         'openerp.addons.web.common.http:INFO',
 196         'openerp.addons.web.common.openerplib:INFO',
 197         'openerp.sql_db:INFO',
 198         ':INFO',
 199     ]
 200
 201     if tools.config['log_level'] == 'info':
 202         pseudo_config = []
 203     elif tools.config['log_level'] == 'debug_rpc':
 204         pseudo_config = ['openerp:DEBUG','openerp.netsvc.rpc.request:DEBUG']
 205     elif tools.config['log_level'] == 'debug_rpc_answer':
 206         pseudo_config = ['openerp:DEBUG','openerp.netsvc.rpc.request:DEBUG', 'openerp.netsvc.rpc.response:DEBUG']
 207     elif tools.config['log_level'] == 'debug':
 208         pseudo_config = ['openerp:DEBUG']
 209     elif tools.config['log_level'] == 'test':
 210         pseudo_config = ['openerp:TEST']
 211     elif tools.config['log_level'] == 'warn':
 212         pseudo_config = ['openerp:WARNING']
 213     elif tools.config['log_level'] == 'error':
 214         pseudo_config = ['openerp:ERROR']
 215     elif tools.config['log_level'] == 'critical':
 216         pseudo_config = ['openerp:CRITICAL']
 217     elif tools.config['log_level'] == 'debug_sql':
 218         pseudo_config = ['openerp.sql_db:DEBUG']
 219     else:
 220         pseudo_config = []
 221
 222     logconfig = tools.config['log_handler']
 223
 224     for logconfig_item in default_config + pseudo_config + logconfig:
 225         loggername, level = logconfig_item.split(':')
 226         level = getattr(logging, level, logging.INFO)
 227         logger = logging.getLogger(loggername)
 228         logger.handlers = []
 229         logger.setLevel(level)
 230         logger.addHandler(handler)
 231         if loggername != '':
 232             logger.propagate = False
 233
 234     for logconfig_item in default_config + pseudo_config + logconfig:
 235         _logger.debug('logger level set: "%s"', logconfig_item)
 236
 237 # A alternative logging scheme for automated runs of the
 238 # server intended to test it.
 239 def init_alternative_logger():
 240     class H(logging.Handler):
 241       def emit(self, record):
 242         if record.levelno > 20:
 243           print record.levelno, record.pathname, record.msg
 244     handler = H()
 245     # Add the handler to the 'openerp' logger.
 246     logger = logging.getLogger('openerp')
 247     logger.addHandler(handler)
 248     logger.setLevel(logging.ERROR)
 249
 250 class Server:
 251     """ Generic interface for all servers with an event loop etc.
 252         Override this to impement http, net-rpc etc. servers.
 253
 254         Servers here must have threaded behaviour. start() must not block,
 255         there is no run().
 256     """
 257     __is_started = False
 258     __servers = []
 259     __starter_threads = []
 260
 261     # we don't want blocking server calls (think select()) to
 262     # wait forever and possibly prevent exiting the process,
 263     # but instead we want a form of polling/busy_wait pattern, where
 264     # _server_timeout should be used as the default timeout for
 265     # all I/O blocking operations
 266     _busywait_timeout = 0.5
 267
 268     def __init__(self):
 269         Server.__servers.append(self)
 270         if Server.__is_started:
 271             # raise Exception('All instances of servers must be inited before the startAll()')
 272             # Since the startAll() won't be called again, allow this server to
 273             # init and then start it after 1sec (hopefully). Register that
 274             # timer thread in a list, so that we can abort the start if quitAll
 275             # is called in the meantime
 276             t = threading.Timer(1.0, self._late_start)
 277             t.name = 'Late start timer for %s' % str(self.__class__)
 278             Server.__starter_threads.append(t)
 279             t.start()
 280
 281     def start(self):
 282         _logger.debug("called stub Server.start")
 283
 284     def _late_start(self):
 285         self.start()
 286         for thr in Server.__starter_threads:
 287             if thr.finished.is_set():
 288                 Server.__starter_threads.remove(thr)
 289
 290     def stop(self):
 291         _logger.debug("called stub Server.stop")
 292
 293     def stats(self):
 294         """ This function should return statistics about the server """
 295         return "%s: No statistics" % str(self.__class__)
 296
 297     @classmethod
 298     def startAll(cls):
 299         if cls.__is_started:
 300             return
 301         _logger.info("Starting %d services" % len(cls.__servers))
 302         for srv in cls.__servers:
 303             srv.start()
 304         cls.__is_started = True
 305
 306     @classmethod
 307     def quitAll(cls):
 308         if not cls.__is_started:
 309             return
 310         _logger.info("Stopping %d services" % len(cls.__servers))
 311         for thr in cls.__starter_threads:
 312             if not thr.finished.is_set():
 313                 thr.cancel()
 314             cls.__starter_threads.remove(thr)
 315
 316         for srv in cls.__servers:
 317             srv.stop()
 318         cls.__is_started = False
 319
 320     @classmethod
 321     def allStats(cls):
 322         res = ["Servers %s" % ('stopped', 'started')[cls.__is_started]]
 323         res.extend(srv.stats() for srv in cls.__servers)
 324         return '\n'.join(res)
 325
 326     def _close_socket(self):
 327         close_socket(self.socket)
 328
 329 def replace_request_password(args):
 330     # password is always 3rd argument in a request, we replace it in RPC logs
 331     # so it's easier to forward logs for diagnostics/debugging purposes...
 332     if len(args) > 2:
 333         args = list(args)
 334         args[2] = '*'
 335     return tuple(args)
 336
 337 def log(logger, level, prefix, msg, depth=None):
 338     indent=''
 339     indent_after=' '*len(prefix)
 340     for line in (prefix+pformat(msg, depth=depth)).split('\n'):
 341         logger.log(level, indent+line)
 342         indent=indent_after
 343
 344 def dispatch_rpc(service_name, method, params):
 345     """ Handle a RPC call.
 346
 347     This is pure Python code, the actual marshalling (from/to XML-RPC or
 348     NET-RPC) is done in a upper layer.
 349     """
 350     try:
 351         rpc_request = logging.getLogger(__name__ + '.rpc.request')
 352         rpc_response = logging.getLogger(__name__ + '.rpc.response')
 353         rpc_request_flag = rpc_request.isEnabledFor(logging.DEBUG)
 354         rpc_response_flag = rpc_response.isEnabledFor(logging.DEBUG)
 355         if rpc_request_flag or rpc_response_flag:
 356             start_time = time.time()
 357             if rpc_request and rpc_response_flag:
 358                 log(rpc_request,logging.DEBUG,'%s.%s'%(service_name,method), replace_request_password(params))
 359
 360         threading.current_thread().uid = None
 361         threading.current_thread().dbname = None
 362         result = ExportService.getService(service_name).dispatch(method, params)
 363
 364         if rpc_request_flag or rpc_response_flag:
 365             end_time = time.time()
 366             if rpc_response_flag:
 367                 log(rpc_response,logging.DEBUG,'%s.%s time:%.3fs '%(service_name,method,end_time - start_time), result)
 368             else:
 369                 log(rpc_request,logging.DEBUG,'%s.%s time:%.3fs '%(service_name,method,end_time - start_time), replace_request_password(params), depth=1)
 370
 371         return result
 372     except openerp.exceptions.AccessError:
 373         raise
 374     except openerp.exceptions.AccessDenied:
 375         raise
 376     except openerp.exceptions.Warning:
 377         raise
 378     except openerp.exceptions.DeferredException, e:
 379         _logger.error(tools.exception_to_unicode(e))
 380         post_mortem(e.traceback)
 381         raise
 382     except Exception, e:
 383         _logger.error(tools.exception_to_unicode(e))
 384         post_mortem(sys.exc_info())
 385         raise
 386
 387 def post_mortem(info):
 388     if tools.config['debug_mode'] and isinstance(info[2], types.TracebackType):
 389         import pdb
 390         pdb.post_mortem(info[2])
 391
 392 # vim:expandtab:smartindent:tabstop=4:softtabstop=4:shiftwidth=4: