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 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() not in ['Darwin', 'Windows']:
  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.http:INFO',
 196         'openerp.sql_db:INFO',
 197         ':INFO',
 198     ]
 199
 200     if tools.config['log_level'] == 'info':
 201         pseudo_config = []
 202     elif tools.config['log_level'] == 'debug_rpc':
 203         pseudo_config = ['openerp:DEBUG','openerp.netsvc.rpc.request:DEBUG']
 204     elif tools.config['log_level'] == 'debug_rpc_answer':
 205         pseudo_config = ['openerp:DEBUG','openerp.netsvc.rpc.request:DEBUG', 'openerp.netsvc.rpc.response:DEBUG']
 206     elif tools.config['log_level'] == 'debug':
 207         pseudo_config = ['openerp:DEBUG']
 208     elif tools.config['log_level'] == 'test':
 209         pseudo_config = ['openerp:TEST']
 210     elif tools.config['log_level'] == 'warn':
 211         pseudo_config = ['openerp:WARNING']
 212     elif tools.config['log_level'] == 'error':
 213         pseudo_config = ['openerp:ERROR']
 214     elif tools.config['log_level'] == 'critical':
 215         pseudo_config = ['openerp:CRITICAL']
 216     elif tools.config['log_level'] == 'debug_sql':
 217         pseudo_config = ['openerp.sql_db:DEBUG']
 218     else:
 219         pseudo_config = []
 220
 221     logconfig = tools.config['log_handler']
 222
 223     for logconfig_item in default_config + pseudo_config + logconfig:
 224         loggername, level = logconfig_item.split(':')
 225         level = getattr(logging, level, logging.INFO)
 226         logger = logging.getLogger(loggername)
 227         logger.handlers = []
 228         logger.setLevel(level)
 229         logger.addHandler(handler)
 230         if loggername != '':
 231             logger.propagate = False
 232
 233     for logconfig_item in default_config + pseudo_config + logconfig:
 234         _logger.debug('logger level set: "%s"', logconfig_item)
 235
 236 # A alternative logging scheme for automated runs of the
 237 # server intended to test it.
 238 def init_alternative_logger():
 239     class H(logging.Handler):
 240         def emit(self, record):
 241             if record.levelno > 20:
 242                 print record.levelno, record.pathname, record.msg
 243     handler = H()
 244     # Add the handler to the 'openerp' logger.
 245     logger = logging.getLogger('openerp')
 246     logger.addHandler(handler)
 247     logger.setLevel(logging.ERROR)
 248
 249 class Server:
 250     """ Generic interface for all servers with an event loop etc.
 251         Override this to impement http, net-rpc etc. servers.
 252
 253         Servers here must have threaded behaviour. start() must not block,
 254         there is no run().
 255     """
 256     __is_started = False
 257     __servers = []
 258     __starter_threads = []
 259
 260     # we don't want blocking server calls (think select()) to
 261     # wait forever and possibly prevent exiting the process,
 262     # but instead we want a form of polling/busy_wait pattern, where
 263     # _server_timeout should be used as the default timeout for
 264     # all I/O blocking operations
 265     _busywait_timeout = 0.5
 266
 267     def __init__(self):
 268         Server.__servers.append(self)
 269         if Server.__is_started:
 270             # raise Exception('All instances of servers must be inited before the startAll()')
 271             # Since the startAll() won't be called again, allow this server to
 272             # init and then start it after 1sec (hopefully). Register that
 273             # timer thread in a list, so that we can abort the start if quitAll
 274             # is called in the meantime
 275             t = threading.Timer(1.0, self._late_start)
 276             t.name = 'Late start timer for %s' % str(self.__class__)
 277             Server.__starter_threads.append(t)
 278             t.start()
 279
 280     def start(self):
 281         _logger.debug("called stub Server.start")
 282
 283     def _late_start(self):
 284         self.start()
 285         for thr in Server.__starter_threads:
 286             if thr.finished.is_set():
 287                 Server.__starter_threads.remove(thr)
 288
 289     def stop(self):
 290         _logger.debug("called stub Server.stop")
 291
 292     def stats(self):
 293         """ This function should return statistics about the server """
 294         return "%s: No statistics" % str(self.__class__)
 295
 296     @classmethod
 297     def startAll(cls):
 298         if cls.__is_started:
 299             return
 300         _logger.info("Starting %d services" % len(cls.__servers))
 301         for srv in cls.__servers:
 302             srv.start()
 303         cls.__is_started = True
 304
 305     @classmethod
 306     def quitAll(cls):
 307         if not cls.__is_started:
 308             return
 309         _logger.info("Stopping %d services" % len(cls.__servers))
 310         for thr in cls.__starter_threads:
 311             if not thr.finished.is_set():
 312                 thr.cancel()
 313             cls.__starter_threads.remove(thr)
 314
 315         for srv in cls.__servers:
 316             srv.stop()
 317         cls.__is_started = False
 318
 319     @classmethod
 320     def allStats(cls):
 321         res = ["Servers %s" % ('stopped', 'started')[cls.__is_started]]
 322         res.extend(srv.stats() for srv in cls.__servers)
 323         return '\n'.join(res)
 324
 325     def _close_socket(self):
 326         close_socket(self.socket)
 327
 328 def replace_request_password(args):
 329     # password is always 3rd argument in a request, we replace it in RPC logs
 330     # so it's easier to forward logs for diagnostics/debugging purposes...
 331     if len(args) > 2:
 332         args = list(args)
 333         args[2] = '*'
 334     return tuple(args)
 335
 336 def log(logger, level, prefix, msg, depth=None):
 337     indent=''
 338     indent_after=' '*len(prefix)
 339     for line in (prefix+pformat(msg, depth=depth)).split('\n'):
 340         logger.log(level, indent+line)
 341         indent=indent_after
 342
 343 def dispatch_rpc(service_name, method, params):
 344     """ Handle a RPC call.
 345
 346     This is pure Python code, the actual marshalling (from/to XML-RPC or
 347     NET-RPC) is done in a upper layer.
 348     """
 349     try:
 350         rpc_request = logging.getLogger(__name__ + '.rpc.request')
 351         rpc_response = logging.getLogger(__name__ + '.rpc.response')
 352         rpc_request_flag = rpc_request.isEnabledFor(logging.DEBUG)
 353         rpc_response_flag = rpc_response.isEnabledFor(logging.DEBUG)
 354         if rpc_request_flag or rpc_response_flag:
 355             start_time = time.time()
 356             if rpc_request and rpc_response_flag:
 357                 log(rpc_request,logging.DEBUG,'%s.%s'%(service_name,method), replace_request_password(params))
 358
 359         threading.current_thread().uid = None
 360         threading.current_thread().dbname = None
 361         result = ExportService.getService(service_name).dispatch(method, params)
 362
 363         if rpc_request_flag or rpc_response_flag:
 364             end_time = time.time()
 365             if rpc_response_flag:
 366                 log(rpc_response,logging.DEBUG,'%s.%s time:%.3fs '%(service_name,method,end_time - start_time), result)
 367             else:
 368                 log(rpc_request,logging.DEBUG,'%s.%s time:%.3fs '%(service_name,method,end_time - start_time), replace_request_password(params), depth=1)
 369
 370         return result
 371     except openerp.exceptions.AccessError:
 372         raise
 373     except openerp.exceptions.AccessDenied:
 374         raise
 375     except openerp.exceptions.Warning:
 376         raise
 377     except openerp.exceptions.DeferredException, e:
 378         _logger.exception(tools.exception_to_unicode(e))
 379         post_mortem(e.traceback)
 380         raise
 381     except Exception, e:
 382         _logger.exception(tools.exception_to_unicode(e))
 383         post_mortem(sys.exc_info())
 384         raise
 385
 386 def post_mortem(info):
 387     if tools.config['debug_mode'] and isinstance(info[2], types.TracebackType):
 388         import pdb
 389         pdb.post_mortem(info[2])
 390
 391 # vim:expandtab:smartindent:tabstop=4:softtabstop=4:shiftwidth=4: