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_SQL: (WHITE, MAGENTA),
 129     logging.DEBUG_RPC: (BLUE, WHITE),
 130     logging.DEBUG_RPC_ANSWER: (BLUE, WHITE),
 131     logging.DEBUG: (BLUE, DEFAULT),
 132     logging.INFO: (GREEN, DEFAULT),
 133     logging.TEST: (WHITE, BLUE),
 134     logging.WARNING: (YELLOW, DEFAULT),
 135     logging.ERROR: (RED, DEFAULT),
 136     logging.CRITICAL: (WHITE, RED),
 137 }
 138
 139 class DBFormatter(logging.Formatter):
 140     def format(self, record):
 141         record.pid = os.getpid()
 142         record.dbname = getattr(threading.currentThread(), 'dbname', '?')
 143         return logging.Formatter.format(self, record)
 144
 145 class ColoredFormatter(DBFormatter):
 146     def format(self, record):
 147         fg_color, bg_color = LEVEL_COLOR_MAPPING[record.levelno]
 148         record.levelname = COLOR_PATTERN % (30 + fg_color, 40 + bg_color, record.levelname)
 149         return DBFormatter.format(self, record)
 150
 151
 152 def init_logger():
 153     from tools.translate import resetlocale
 154     resetlocale()
 155
 156     # create a format for log messages and dates
 157     format = '[%(asctime)s][%(dbname)s] %(levelname)s:%(name)s:%(message)s'
 158     format = '%(asctime)s %(pid)s %(levelname)s %(dbname)s %(name)s: %(message)s'
 159
 160     if tools.config['syslog']:
 161         # SysLog Handler
 162         if os.name == 'nt':
 163             handler = logging.handlers.NTEventLogHandler("%s %s" % (release.description, release.version))
 164         else:
 165             handler = logging.handlers.SysLogHandler('/dev/log')
 166         format = '%s %s' % (release.description, release.version) \
 167                 + ':%(dbname)s:%(levelname)s:%(name)s:%(message)s'
 168
 169     elif tools.config['logfile']:
 170         # LogFile Handler
 171         logf = tools.config['logfile']
 172         try:
 173             dirname = os.path.dirname(logf)
 174             if dirname and not os.path.isdir(dirname):
 175                 os.makedirs(dirname)
 176             if tools.config['logrotate'] is not False:
 177                 handler = logging.handlers.TimedRotatingFileHandler(logf,'D',1,30)
 178             elif os.name == 'posix':
 179                 handler = logging.handlers.WatchedFileHandler(logf)
 180             else:
 181                 handler = logging.handlers.FileHandler(logf)
 182         except Exception:
 183             sys.stderr.write("ERROR: couldn't create the logfile directory. Logging to the standard output.\n")
 184             handler = logging.StreamHandler(sys.stdout)
 185     else:
 186         # Normal Handler on standard output
 187         handler = logging.StreamHandler(sys.stdout)
 188
 189     if isinstance(handler, logging.StreamHandler) and os.isatty(handler.stream.fileno()):
 190         formatter = ColoredFormatter(format)
 191     else:
 192         formatter = DBFormatter(format)
 193     handler.setFormatter(formatter)
 194
 195     # Configure handlers
 196     logconfig = tools.config['log_handler']
 197     for i in logconfig:
 198         prefix, level = i.split(':')
 199         level = getattr(logging, level, logging.INFO)
 200         logger = logging.getLogger(prefix)
 201         logger.handlers = []
 202         logger.setLevel(level)
 203         logger.addHandler(handler)
 204         if prefix != '':
 205             logger.propagate = False
 206
 207
 208 # A alternative logging scheme for automated runs of the
 209 # server intended to test it.
 210 def init_alternative_logger():
 211     class H(logging.Handler):
 212       def emit(self, record):
 213         if record.levelno > 20:
 214           print record.levelno, record.pathname, record.msg
 215     handler = H()
 216     # Add the handler to the 'openerp' logger.
 217     logger = logging.getLogger('openerp')
 218     logger.addHandler(handler)
 219     logger.setLevel(logging.ERROR)
 220
 221 class Server:
 222     """ Generic interface for all servers with an event loop etc.
 223         Override this to impement http, net-rpc etc. servers.
 224
 225         Servers here must have threaded behaviour. start() must not block,
 226         there is no run().
 227     """
 228     __is_started = False
 229     __servers = []
 230     __starter_threads = []
 231
 232     # we don't want blocking server calls (think select()) to
 233     # wait forever and possibly prevent exiting the process,
 234     # but instead we want a form of polling/busy_wait pattern, where
 235     # _server_timeout should be used as the default timeout for
 236     # all I/O blocking operations
 237     _busywait_timeout = 0.5
 238
 239     def __init__(self):
 240         Server.__servers.append(self)
 241         if Server.__is_started:
 242             # raise Exception('All instances of servers must be inited before the startAll()')
 243             # Since the startAll() won't be called again, allow this server to
 244             # init and then start it after 1sec (hopefully). Register that
 245             # timer thread in a list, so that we can abort the start if quitAll
 246             # is called in the meantime
 247             t = threading.Timer(1.0, self._late_start)
 248             t.name = 'Late start timer for %s' % str(self.__class__)
 249             Server.__starter_threads.append(t)
 250             t.start()
 251
 252     def start(self):
 253         _logger.debug("called stub Server.start")
 254
 255     def _late_start(self):
 256         self.start()
 257         for thr in Server.__starter_threads:
 258             if thr.finished.is_set():
 259                 Server.__starter_threads.remove(thr)
 260
 261     def stop(self):
 262         _logger.debug("called stub Server.stop")
 263
 264     def stats(self):
 265         """ This function should return statistics about the server """
 266         return "%s: No statistics" % str(self.__class__)
 267
 268     @classmethod
 269     def startAll(cls):
 270         if cls.__is_started:
 271             return
 272         _logger.info("Starting %d services" % len(cls.__servers))
 273         for srv in cls.__servers:
 274             srv.start()
 275         cls.__is_started = True
 276
 277     @classmethod
 278     def quitAll(cls):
 279         if not cls.__is_started:
 280             return
 281         _logger.info("Stopping %d services" % len(cls.__servers))
 282         for thr in cls.__starter_threads:
 283             if not thr.finished.is_set():
 284                 thr.cancel()
 285             cls.__starter_threads.remove(thr)
 286
 287         for srv in cls.__servers:
 288             srv.stop()
 289         cls.__is_started = False
 290
 291     @classmethod
 292     def allStats(cls):
 293         res = ["Servers %s" % ('stopped', 'started')[cls.__is_started]]
 294         res.extend(srv.stats() for srv in cls.__servers)
 295         return '\n'.join(res)
 296
 297     def _close_socket(self):
 298         close_socket(self.socket)
 299
 300 def replace_request_password(args):
 301     # password is always 3rd argument in a request, we replace it in RPC logs
 302     # so it's easier to forward logs for diagnostics/debugging purposes...
 303     if len(args) > 2:
 304         args = list(args)
 305         args[2] = '*'
 306     return tuple(args)
 307
 308 def dispatch_rpc_log(logger, prefix, msg, depth=None):
 309     indent=''
 310     indent_after=' '*len(prefix)
 311     for line in (prefix+pformat(msg, depth=depth)).split('\n'):
 312         logger.debug(indent+line)
 313         indent=indent_after
 314
 315 def dispatch_rpc(service_name, method, params):
 316     """ Handle a RPC call.
 317
 318     This is pure Python code, the actual marshalling (from/to XML-RPC or
 319     NET-RPC) is done in a upper layer.
 320     """
 321     try:
 322         rpc_short = logging.getLogger(__name__ + '.rpc_short')
 323         rpc_full = logging.getLogger(__name__ + '.rpc_full')
 324         rpc_short_flag = rpc_short.isEnabledFor(logging.DEBUG)
 325         rpc_full_flag = rpc_full.isEnabledFor(logging.DEBUG)
 326         if rpc_short_flag or rpc_full_flag:
 327             start_time = time.time()
 328             if rpc_full_flag:
 329                 dispatch_rpc_log(rpc_full,'%s.%s:request '%(service_name,method), replace_request_password(params))
 330
 331         result = ExportService.getService(service_name).dispatch(method, params)
 332
 333         if rpc_short_flag or rpc_full_flag:
 334             end_time = time.time()
 335             if rpc_full_flag:
 336                 dispatch_rpc_log(rpc_full,'%s.%s:reply time:%.3fs '%(service_name,method,end_time - start_time), result)
 337             else:
 338                 dispatch_rpc_log(rpc_short,'%s.%s time:%.3fs '%(service_name,method,end_time - start_time), replace_request_password(params), depth=1)
 339
 340         return result
 341     except openerp.exceptions.AccessError:
 342         raise
 343     except openerp.exceptions.AccessDenied:
 344         raise
 345     except openerp.exceptions.Warning:
 346         raise
 347     except openerp.exceptions.DeferredException, e:
 348         _logger.error(tools.exception_to_unicode(e))
 349         post_mortem(e.traceback)
 350         raise
 351     except Exception, e:
 352         _logger.error(tools.exception_to_unicode(e))
 353         post_mortem(sys.exc_info())
 354         raise
 355
 356 def post_mortem(info):
 357     if tools.config['debug_mode'] and isinstance(info[2], types.TracebackType):
 358         import pdb
 359         pdb.post_mortem(info[2])
 360
 361 # vim:expandtab:smartindent:tabstop=4:softtabstop=4:shiftwidth=4: