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 traceback
  34 import types
  35 from pprint import pformat
  36
  37 # TODO modules that import netsvc only for things from loglevels must be changed to use loglevels.
  38 from loglevels import *
  39 import tools
  40 import openerp
  41
  42 def close_socket(sock):
  43     """ Closes a socket instance cleanly
  44
  45     :param sock: the network socket to close
  46     :type sock: socket.socket
  47     """
  48     try:
  49         sock.shutdown(socket.SHUT_RDWR)
  50     except socket.error, e:
  51         # On OSX, socket shutdowns both sides if any side closes it
  52         # causing an error 57 'Socket is not connected' on shutdown
  53         # of the other side (or something), see
  54         # http://bugs.python.org/issue4397
  55         # note: stdlib fixed test, not behavior
  56         if e.errno != errno.ENOTCONN or platform.system() != 'Darwin':
  57             raise
  58     sock.close()
  59
  60
  61 #.apidoc title: Common Services: netsvc
  62 #.apidoc module-mods: member-order: bysource
  63
  64 def abort_response(dummy_1, description, dummy_2, details):
  65     # TODO Replace except_{osv,orm} with these directly.
  66     raise openerp.osv.osv.except_osv(description, details)
  67
  68 class Service(object):
  69     """ Base class for *Local* services
  70
  71         Functionality here is trusted, no authentication.
  72     """
  73     _services = {}
  74     def __init__(self, name):
  75         Service._services[name] = self
  76         self.__name = name
  77
  78     @classmethod
  79     def exists(cls, name):
  80         return name in cls._services
  81
  82     @classmethod
  83     def remove(cls, name):
  84         if cls.exists(name):
  85             cls._services.pop(name)
  86
  87 def LocalService(name):
  88   # Special case for addons support, will be removed in a few days when addons
  89   # are updated to directly use openerp.osv.osv.service.
  90   if name == 'object_proxy':
  91       return openerp.osv.osv.service
  92
  93   return Service._services[name]
  94
  95 class ExportService(object):
  96     """ Proxy for exported services.
  97
  98     Note that this class has no direct proxy, capable of calling
  99     eservice.method(). Rather, the proxy should call
 100     dispatch(method, params)
 101     """
 102
 103     _services = {}
 104     _logger = logging.getLogger('web-services')
 105
 106     def __init__(self, name):
 107         ExportService._services[name] = self
 108         self.__name = name
 109         self._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.dbname = getattr(threading.currentThread(), 'dbname', '?')
 142         return logging.Formatter.format(self, record)
 143
 144 class ColoredFormatter(DBFormatter):
 145     def format(self, record):
 146         fg_color, bg_color = LEVEL_COLOR_MAPPING[record.levelno]
 147         record.levelname = COLOR_PATTERN % (30 + fg_color, 40 + bg_color, record.levelname)
 148         return DBFormatter.format(self, record)
 149
 150 def init_logger():
 151     from tools.translate import resetlocale
 152     resetlocale()
 153
 154     # create a format for log messages and dates
 155     format = '[%(asctime)s][%(dbname)s] %(levelname)s:%(name)s:%(message)s'
 156
 157     if tools.config['syslog']:
 158         # SysLog Handler
 159         if os.name == 'nt':
 160             handler = logging.handlers.NTEventLogHandler("%s %s" % (release.description, release.version))
 161         else:
 162             handler = logging.handlers.SysLogHandler('/dev/log')
 163         format = '%s %s' % (release.description, release.version) \
 164                 + ':%(dbname)s:%(levelname)s:%(name)s:%(message)s'
 165
 166     elif tools.config['logfile']:
 167         # LogFile Handler
 168         logf = tools.config['logfile']
 169         try:
 170             dirname = os.path.dirname(logf)
 171             if dirname and not os.path.isdir(dirname):
 172                 os.makedirs(dirname)
 173             if tools.config['logrotate'] is not False:
 174                 handler = logging.handlers.TimedRotatingFileHandler(logf,'D',1,30)
 175             elif os.name == 'posix':
 176                 handler = logging.handlers.WatchedFileHandler(logf)
 177             else:
 178                 handler = logging.handlers.FileHandler(logf)
 179         except Exception:
 180             sys.stderr.write("ERROR: couldn't create the logfile directory. Logging to the standard output.\n")
 181             handler = logging.StreamHandler(sys.stdout)
 182     else:
 183         # Normal Handler on standard output
 184         handler = logging.StreamHandler(sys.stdout)
 185
 186     if isinstance(handler, logging.StreamHandler) and os.isatty(handler.stream.fileno()):
 187         formatter = ColoredFormatter(format)
 188     else:
 189         formatter = DBFormatter(format)
 190     handler.setFormatter(formatter)
 191
 192     # add the handler to the root logger
 193     logger = logging.getLogger()
 194     logger.handlers = []
 195     logger.addHandler(handler)
 196     logger.setLevel(int(tools.config['log_level'] or '0'))
 197
 198 # A alternative logging scheme for automated runs of the
 199 # server intended to test it.
 200 def init_alternative_logger():
 201     class H(logging.Handler):
 202       def emit(self, record):
 203         if record.levelno > 20:
 204           print record.levelno, record.pathname, record.msg
 205     handler = H()
 206     logger = logging.getLogger()
 207     logger.handlers = []
 208     logger.addHandler(handler)
 209     logger.setLevel(logging.ERROR)
 210
 211 class Server:
 212     """ Generic interface for all servers with an event loop etc.
 213         Override this to impement http, net-rpc etc. servers.
 214
 215         Servers here must have threaded behaviour. start() must not block,
 216         there is no run().
 217     """
 218     __is_started = False
 219     __servers = []
 220     __starter_threads = []
 221
 222     # we don't want blocking server calls (think select()) to
 223     # wait forever and possibly prevent exiting the process,
 224     # but instead we want a form of polling/busy_wait pattern, where
 225     # _server_timeout should be used as the default timeout for
 226     # all I/O blocking operations
 227     _busywait_timeout = 0.5
 228
 229
 230     __logger = logging.getLogger('server')
 231
 232     def __init__(self):
 233         Server.__servers.append(self)
 234         if Server.__is_started:
 235             # raise Exception('All instances of servers must be inited before the startAll()')
 236             # Since the startAll() won't be called again, allow this server to
 237             # init and then start it after 1sec (hopefully). Register that
 238             # timer thread in a list, so that we can abort the start if quitAll
 239             # is called in the meantime
 240             t = threading.Timer(1.0, self._late_start)
 241             t.name = 'Late start timer for %s' % str(self.__class__)
 242             Server.__starter_threads.append(t)
 243             t.start()
 244
 245     def start(self):
 246         self.__logger.debug("called stub Server.start")
 247
 248     def _late_start(self):
 249         self.start()
 250         for thr in Server.__starter_threads:
 251             if thr.finished.is_set():
 252                 Server.__starter_threads.remove(thr)
 253
 254     def stop(self):
 255         self.__logger.debug("called stub Server.stop")
 256
 257     def stats(self):
 258         """ This function should return statistics about the server """
 259         return "%s: No statistics" % str(self.__class__)
 260
 261     @classmethod
 262     def startAll(cls):
 263         if cls.__is_started:
 264             return
 265         cls.__logger.info("Starting %d services" % len(cls.__servers))
 266         for srv in cls.__servers:
 267             srv.start()
 268         cls.__is_started = True
 269
 270     @classmethod
 271     def quitAll(cls):
 272         if not cls.__is_started:
 273             return
 274         cls.__logger.info("Stopping %d services" % len(cls.__servers))
 275         for thr in cls.__starter_threads:
 276             if not thr.finished.is_set():
 277                 thr.cancel()
 278             cls.__starter_threads.remove(thr)
 279
 280         for srv in cls.__servers:
 281             srv.stop()
 282         cls.__is_started = False
 283
 284     @classmethod
 285     def allStats(cls):
 286         res = ["Servers %s" % ('stopped', 'started')[cls.__is_started]]
 287         res.extend(srv.stats() for srv in cls.__servers)
 288         return '\n'.join(res)
 289
 290     def _close_socket(self):
 291         close_socket(self.socket)
 292
 293 def replace_request_password(args):
 294     # password is always 3rd argument in a request, we replace it in RPC logs
 295     # so it's easier to forward logs for diagnostics/debugging purposes...
 296     args = list(args)
 297     if len(args) > 2:
 298         args[2] = '*'
 299     return args
 300
 301 def log(title, msg, channel=logging.DEBUG_RPC, depth=None, fn=""):
 302     logger = logging.getLogger(title)
 303     if logger.isEnabledFor(channel):
 304         indent=''
 305         indent_after=' '*len(fn)
 306         for line in (fn+pformat(msg, depth=depth)).split('\n'):
 307             logger.log(channel, indent+line)
 308             indent=indent_after
 309
 310 def dispatch_rpc(service_name, method, params):
 311     """ Handle a RPC call.
 312
 313     This is pure Python code, the actual marshalling (from/to XML-RPC or
 314     NET-RPC) is done in a upper layer.
 315     """
 316     def _log(title, msg, channel=logging.DEBUG_RPC, depth=None, fn=""):
 317         log(title, msg, channel=channel, depth=depth, fn=fn)
 318     try:
 319         logger = logging.getLogger('result')
 320         start_time = end_time = 0
 321         if logger.isEnabledFor(logging.DEBUG_RPC_ANSWER):
 322             _log('service', tuple(replace_request_password(params)), depth=None, fn='%s.%s'%(service_name,method))
 323         if logger.isEnabledFor(logging.DEBUG_RPC):
 324             start_time = time.time()
 325         result = ExportService.getService(service_name).dispatch(method, params)
 326         if logger.isEnabledFor(logging.DEBUG_RPC):
 327             end_time = time.time()
 328         if not logger.isEnabledFor(logging.DEBUG_RPC_ANSWER):
 329             _log('service (%.3fs)' % (end_time - start_time), tuple(replace_request_password(params)), depth=1, fn='%s.%s'%(service_name,method))
 330         _log('execution time', '%.3fs' % (end_time - start_time), channel=logging.DEBUG_RPC_ANSWER)
 331         _log('result', result, channel=logging.DEBUG_RPC_ANSWER)
 332         return result
 333     except openerp.exceptions.AccessError:
 334         raise
 335     except openerp.exceptions.AccessDenied:
 336         raise
 337     except openerp.exceptions.Warning:
 338         raise
 339     except openerp.exceptions.DeferredException, e:
 340         _log('exception', tools.exception_to_unicode(e))
 341         post_mortem(e.traceback)
 342         raise
 343     except Exception, e:
 344         _log('exception', tools.exception_to_unicode(e))
 345         post_mortem(sys.exc_info())
 346         raise
 347
 348 def post_mortem(info):
 349     if tools.config['debug_mode'] and isinstance(info[2], types.TracebackType):
 350         import pdb
 351         pdb.post_mortem(info[2])
 352
 353 # vim:expandtab:smartindent:tabstop=4:softtabstop=4:shiftwidth=4: