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 def close_socket(sock):
  42     """ Closes a socket instance cleanly
  43
  44     :param sock: the network socket to close
  45     :type sock: socket.socket
  46     """
  47     try:
  48         sock.shutdown(socket.SHUT_RDWR)
  49     except socket.error, e:
  50         # On OSX, socket shutdowns both sides if any side closes it
  51         # causing an error 57 'Socket is not connected' on shutdown
  52         # of the other side (or something), see
  53         # http://bugs.python.org/issue4397
  54         # note: stdlib fixed test, not behavior
  55         if e.errno != errno.ENOTCONN or platform.system() != 'Darwin':
  56             raise
  57     sock.close()
  58
  59
  60 #.apidoc title: Common Services: netsvc
  61 #.apidoc module-mods: member-order: bysource
  62
  63 def abort_response(dummy_1, description, dummy_2, details):
  64     # TODO Replace except_{osv,orm} with these directly.
  65     raise openerp.osv.osv.except_osv(description, details)
  66
  67 class Service(object):
  68     """ Base class for *Local* services
  69
  70         Functionality here is trusted, no authentication.
  71     """
  72     _services = {}
  73     def __init__(self, name):
  74         Service._services[name] = self
  75         self.__name = name
  76
  77     @classmethod
  78     def exists(cls, name):
  79         return name in cls._services
  80
  81     @classmethod
  82     def remove(cls, name):
  83         if cls.exists(name):
  84             cls._services.pop(name)
  85
  86 def LocalService(name):
  87   # Special case for addons support, will be removed in a few days when addons
  88   # are updated to directly use openerp.osv.osv.service.
  89   if name == 'object_proxy':
  90       return openerp.osv.osv.service
  91
  92   return Service._services[name]
  93
  94 class ExportService(object):
  95     """ Proxy for exported services.
  96
  97     Note that this class has no direct proxy, capable of calling
  98     eservice.method(). Rather, the proxy should call
  99     dispatch(method, params)
 100     """
 101
 102     _services = {}
 103     _logger = logging.getLogger('web-services')
 104
 105     def __init__(self, name):
 106         ExportService._services[name] = self
 107         self.__name = name
 108         self._logger.debug("Registered an exported service: %s" % name)
 109
 110     @classmethod
 111     def getService(cls,name):
 112         return cls._services[name]
 113
 114     # Dispatch a RPC call w.r.t. the method name. The dispatching
 115     # w.r.t. the service (this class) is done by OpenERPDispatcher.
 116     def dispatch(self, method, params):
 117         raise Exception("stub dispatch at %s" % self.__name)
 118
 119 BLACK, RED, GREEN, YELLOW, BLUE, MAGENTA, CYAN, WHITE, _NOTHING, DEFAULT = range(10)
 120 #The background is set with 40 plus the number of the color, and the foreground with 30
 121 #These are the sequences need to get colored ouput
 122 RESET_SEQ = "\033[0m"
 123 COLOR_SEQ = "\033[1;%dm"
 124 BOLD_SEQ = "\033[1m"
 125 COLOR_PATTERN = "%s%s%%s%s" % (COLOR_SEQ, COLOR_SEQ, RESET_SEQ)
 126 LEVEL_COLOR_MAPPING = {
 127     logging.DEBUG_SQL: (WHITE, MAGENTA),
 128     logging.DEBUG_RPC: (BLUE, WHITE),
 129     logging.DEBUG_RPC_ANSWER: (BLUE, WHITE),
 130     logging.DEBUG: (BLUE, DEFAULT),
 131     logging.INFO: (GREEN, DEFAULT),
 132     logging.TEST: (WHITE, BLUE),
 133     logging.WARNING: (YELLOW, DEFAULT),
 134     logging.ERROR: (RED, DEFAULT),
 135     logging.CRITICAL: (WHITE, RED),
 136 }
 137
 138 class DBFormatter(logging.Formatter):
 139     def format(self, record):
 140         record.dbname = getattr(threading.currentThread(), 'dbname', '?')
 141         return logging.Formatter.format(self, record)
 142
 143 class ColoredFormatter(DBFormatter):
 144     def format(self, record):
 145         fg_color, bg_color = LEVEL_COLOR_MAPPING[record.levelno]
 146         record.levelname = COLOR_PATTERN % (30 + fg_color, 40 + bg_color, record.levelname)
 147         return DBFormatter.format(self, record)
 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][%(dbname)s] %(levelname)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     # add the handler to the root logger
 192     logger = logging.getLogger()
 193     logger.handlers = []
 194     logger.addHandler(handler)
 195     logger.setLevel(int(tools.config['log_level'] or '0'))
 196
 197 # A alternative logging scheme for automated runs of the
 198 # server intended to test it.
 199 def init_alternative_logger():
 200     class H(logging.Handler):
 201       def emit(self, record):
 202         if record.levelno > 20:
 203           print record.levelno, record.pathname, record.msg
 204     handler = H()
 205     logger = logging.getLogger()
 206     logger.handlers = []
 207     logger.addHandler(handler)
 208     logger.setLevel(logging.ERROR)
 209
 210 class Server:
 211     """ Generic interface for all servers with an event loop etc.
 212         Override this to impement http, net-rpc etc. servers.
 213
 214         Servers here must have threaded behaviour. start() must not block,
 215         there is no run().
 216     """
 217     __is_started = False
 218     __servers = []
 219     __starter_threads = []
 220
 221     # we don't want blocking server calls (think select()) to
 222     # wait forever and possibly prevent exiting the process,
 223     # but instead we want a form of polling/busy_wait pattern, where
 224     # _server_timeout should be used as the default timeout for
 225     # all I/O blocking operations
 226     _busywait_timeout = 0.5
 227
 228
 229     __logger = logging.getLogger('server')
 230
 231     def __init__(self):
 232         Server.__servers.append(self)
 233         if Server.__is_started:
 234             # raise Exception('All instances of servers must be inited before the startAll()')
 235             # Since the startAll() won't be called again, allow this server to
 236             # init and then start it after 1sec (hopefully). Register that
 237             # timer thread in a list, so that we can abort the start if quitAll
 238             # is called in the meantime
 239             t = threading.Timer(1.0, self._late_start)
 240             t.name = 'Late start timer for %s' % str(self.__class__)
 241             Server.__starter_threads.append(t)
 242             t.start()
 243
 244     def start(self):
 245         self.__logger.debug("called stub Server.start")
 246
 247     def _late_start(self):
 248         self.start()
 249         for thr in Server.__starter_threads:
 250             if thr.finished.is_set():
 251                 Server.__starter_threads.remove(thr)
 252
 253     def stop(self):
 254         self.__logger.debug("called stub Server.stop")
 255
 256     def stats(self):
 257         """ This function should return statistics about the server """
 258         return "%s: No statistics" % str(self.__class__)
 259
 260     @classmethod
 261     def startAll(cls):
 262         if cls.__is_started:
 263             return
 264         cls.__logger.info("Starting %d services" % len(cls.__servers))
 265         for srv in cls.__servers:
 266             srv.start()
 267         cls.__is_started = True
 268
 269     @classmethod
 270     def quitAll(cls):
 271         if not cls.__is_started:
 272             return
 273         cls.__logger.info("Stopping %d services" % len(cls.__servers))
 274         for thr in cls.__starter_threads:
 275             if not thr.finished.is_set():
 276                 thr.cancel()
 277             cls.__starter_threads.remove(thr)
 278
 279         for srv in cls.__servers:
 280             srv.stop()
 281         cls.__is_started = False
 282
 283     @classmethod
 284     def allStats(cls):
 285         res = ["Servers %s" % ('stopped', 'started')[cls.__is_started]]
 286         res.extend(srv.stats() for srv in cls.__servers)
 287         return '\n'.join(res)
 288
 289     def _close_socket(self):
 290         close_socket(self.socket)
 291
 292 def replace_request_password(args):
 293     # password is always 3rd argument in a request, we replace it in RPC logs
 294     # so it's easier to forward logs for diagnostics/debugging purposes...
 295     args = list(args)
 296     if len(args) > 2:
 297         args[2] = '*'
 298     return args
 299
 300 def log(title, msg, channel=logging.DEBUG_RPC, depth=None, fn=""):
 301     logger = logging.getLogger(title)
 302     if logger.isEnabledFor(channel):
 303         indent=''
 304         indent_after=' '*len(fn)
 305         for line in (fn+pformat(msg, depth=depth)).split('\n'):
 306             logger.log(channel, indent+line)
 307             indent=indent_after
 308
 309 def dispatch_rpc(service_name, method, params):
 310     """ Handle a RPC call.
 311
 312     This is pure Python code, the actual marshalling (from/to XML-RPC or
 313     NET-RPC) is done in a upper layer.
 314     """
 315     def _log(title, msg, channel=logging.DEBUG_RPC, depth=None, fn=""):
 316         log(title, msg, channel=channel, depth=depth, fn=fn)
 317     try:
 318         logger = logging.getLogger('result')
 319         start_time = end_time = 0
 320         if logger.isEnabledFor(logging.DEBUG_RPC_ANSWER):
 321             _log('service', tuple(replace_request_password(params)), depth=None, fn='%s.%s'%(service_name,method))
 322         if logger.isEnabledFor(logging.DEBUG_RPC):
 323             start_time = time.time()
 324         result = ExportService.getService(service_name).dispatch(method, params)
 325         if logger.isEnabledFor(logging.DEBUG_RPC):
 326             end_time = time.time()
 327         if not logger.isEnabledFor(logging.DEBUG_RPC_ANSWER):
 328             _log('service (%.3fs)' % (end_time - start_time), tuple(replace_request_password(params)), depth=1, fn='%s.%s'%(service_name,method))
 329         _log('execution time', '%.3fs' % (end_time - start_time), channel=logging.DEBUG_RPC_ANSWER)
 330         _log('result', result, channel=logging.DEBUG_RPC_ANSWER)
 331         return result
 332     except openerp.exceptions.AccessError:
 333         raise
 334     except openerp.exceptions.AccessDenied:
 335         raise
 336     except openerp.exceptions.Warning:
 337         raise
 338     except openerp.exceptions.DeferredException, e:
 339         _log('exception', tools.exception_to_unicode(e))
 340         post_mortem(e.traceback)
 341         raise
 342     except Exception, e:
 343         _log('exception', tools.exception_to_unicode(e))
 344         post_mortem(sys.exc_info())
 345         raise
 346
 347 def post_mortem(info):
 348     if tools.config['debug_mode'] and isinstance(info[2], types.TracebackType):
 349         import pdb
 350         pdb.post_mortem(info[2])
 351
 352 # vim:expandtab:smartindent:tabstop=4:softtabstop=4:shiftwidth=4: