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