[REF] Refactoring according to the review of CHS
[odoo/odoo.git] / openerp / netsvc.py
index 170108a..755f651 100644 (file)
@@ -1,4 +1,3 @@
-#!/usr/bin/env python
 # -*- coding: utf-8 -*-
 ##############################################################################
 #
 #
 ##############################################################################
 
-import errno
+
 import logging
 import logging.handlers
 import os
-import platform
 import release
-import socket
 import sys
 import threading
 import time
 import types
 from pprint import pformat
+import psutil
 
-# TODO modules that import netsvc only for things from loglevels must be changed to use loglevels.
-from loglevels import *
 import tools
 import openerp
 
 _logger = logging.getLogger(__name__)
 
-def close_socket(sock):
-    """ Closes a socket instance cleanly
-
-    :param sock: the network socket to close
-    :type sock: socket.socket
-    """
-    try:
-        sock.shutdown(socket.SHUT_RDWR)
-    except socket.error, e:
-        # On OSX, socket shutdowns both sides if any side closes it
-        # causing an error 57 'Socket is not connected' on shutdown
-        # of the other side (or something), see
-        # http://bugs.python.org/issue4397
-        # note: stdlib fixed test, not behavior
-        if e.errno != errno.ENOTCONN or platform.system() != 'Darwin':
-            raise
-    sock.close()
-
-
-#.apidoc title: Common Services: netsvc
-#.apidoc module-mods: member-order: bysource
-
-def abort_response(dummy_1, description, dummy_2, details):
-    # TODO Replace except_{osv,orm} with these directly.
-    raise openerp.osv.osv.except_osv(description, details)
-
-class Service(object):
-    """ Base class for *Local* services
-
-        Functionality here is trusted, no authentication.
-    """
-    _services = {}
-    def __init__(self, name):
-        Service._services[name] = self
-        self.__name = name
-
-    @classmethod
-    def exists(cls, name):
-        return name in cls._services
-
-    @classmethod
-    def remove(cls, name):
-        if cls.exists(name):
-            cls._services.pop(name)
-
 def LocalService(name):
-  # Special case for addons support, will be removed in a few days when addons
-  # are updated to directly use openerp.osv.osv.service.
-  if name == 'object_proxy':
-      return openerp.osv.osv.service
-
-  return Service._services[name]
-
-class ExportService(object):
-    """ Proxy for exported services.
-
-    Note that this class has no direct proxy, capable of calling
-    eservice.method(). Rather, the proxy should call
-    dispatch(method, params)
     """
+    The openerp.netsvc.LocalService() function is deprecated. It still works
+    in two cases: workflows and reports. For workflows, instead of using
+    LocalService('workflow'), openerp.workflow should be used (better yet,
+    methods on openerp.osv.orm.Model should be used). For reports,
+    openerp.report.render_report() should be used (methods on the Model should
+    be provided too in the future).
+    """
+    assert openerp.conf.deprecation.allow_local_service
+    _logger.warning("LocalService() is deprecated since march 2013 (it was called with '%s')." % name)
 
-    _services = {}
-    
-    def __init__(self, name):
-        ExportService._services[name] = self
-        self.__name = name
-        _logger.debug("Registered an exported service: %s" % name)
-
-    @classmethod
-    def getService(cls,name):
-        return cls._services[name]
+    if name == 'workflow':
+        return openerp.workflow
 
-    # Dispatch a RPC call w.r.t. the method name. The dispatching
-    # w.r.t. the service (this class) is done by OpenERPDispatcher.
-    def dispatch(self, method, params):
-        raise Exception("stub dispatch at %s" % self.__name)
+    if name.startswith('report.'):
+        report = openerp.report.interface.report_int._reports.get(name)
+        if report:
+            return report
+        else:
+            dbname = getattr(threading.currentThread(), 'dbname', None)
+            if dbname:
+                registry = openerp.modules.registry.RegistryManager.get(dbname)
+                with registry.cursor() as cr:
+                    return registry['ir.actions.report.xml']._lookup_report(cr, name[len('report.'):])
 
 BLACK, RED, GREEN, YELLOW, BLUE, MAGENTA, CYAN, WHITE, _NOTHING, DEFAULT = range(10)
 #The background is set with 40 plus the number of the color, and the foreground with 30
@@ -127,7 +72,6 @@ COLOR_PATTERN = "%s%s%%s%s" % (COLOR_SEQ, COLOR_SEQ, RESET_SEQ)
 LEVEL_COLOR_MAPPING = {
     logging.DEBUG: (BLUE, DEFAULT),
     logging.INFO: (GREEN, DEFAULT),
-    logging.TEST: (WHITE, BLUE),
     logging.WARNING: (YELLOW, DEFAULT),
     logging.ERROR: (RED, DEFAULT),
     logging.CRITICAL: (WHITE, RED),
@@ -145,7 +89,6 @@ class ColoredFormatter(DBFormatter):
         record.levelname = COLOR_PATTERN % (30 + fg_color, 40 + bg_color, record.levelname)
         return DBFormatter.format(self, record)
 
-
 def init_logger():
     from tools.translate import resetlocale
     resetlocale()
@@ -182,46 +125,25 @@ def init_logger():
         # Normal Handler on standard output
         handler = logging.StreamHandler(sys.stdout)
 
-    if isinstance(handler, logging.StreamHandler) and os.isatty(handler.stream.fileno()):
+    # Check that handler.stream has a fileno() method: when running OpenERP
+    # behind Apache with mod_wsgi, handler.stream will have type mod_wsgi.Log,
+    # which has no fileno() method. (mod_wsgi.Log is what is being bound to
+    # sys.stderr when the logging.StreamHandler is being constructed above.)
+    if isinstance(handler, logging.StreamHandler) \
+        and hasattr(handler.stream, 'fileno') \
+        and os.isatty(handler.stream.fileno()):
         formatter = ColoredFormatter(format)
     else:
         formatter = DBFormatter(format)
     handler.setFormatter(formatter)
 
     # Configure handlers
-    default_config = [
-        'openerp.netsvc.rpc.request:INFO',
-        'openerp.netsvc.rpc.response:INFO',
-        'openerp.addons.web.common.http:INFO',
-        'openerp.addons.web.common.openerplib:INFO',
-        'openerp.sql_db:INFO',
-        ':INFO',
-    ]
-
-    if tools.config['log_level'] == 'info':
-        pseudo_config = []
-    elif tools.config['log_level'] == 'debug_rpc':
-        pseudo_config = ['openerp:DEBUG','openerp.netsvc.rpc.request:DEBUG']
-    elif tools.config['log_level'] == 'debug_rpc_answer':
-        pseudo_config = ['openerp:DEBUG','openerp.netsvc.rpc.request:DEBUG', 'openerp.netsvc.rpc.response:DEBUG']
-    elif tools.config['log_level'] == 'debug':
-        pseudo_config = ['openerp:DEBUG']
-    elif tools.config['log_level'] == 'test':
-        pseudo_config = ['openerp:TEST']
-    elif tools.config['log_level'] == 'warn':
-        pseudo_config = ['openerp:WARNING']
-    elif tools.config['log_level'] == 'error':
-        pseudo_config = ['openerp:ERROR']
-    elif tools.config['log_level'] == 'critical':
-        pseudo_config = ['openerp:CRITICAL']
-    elif tools.config['log_level'] == 'debug_sql':
-        pseudo_config = ['openerp.sql_db:DEBUG']
-    else:
-        pseudo_config = []
+    pseudo_config = PSEUDOCONFIG_MAPPER.get(tools.config['log_level'], [])
 
     logconfig = tools.config['log_handler']
 
-    for logconfig_item in default_config + pseudo_config + logconfig:
+    logging_configurations = DEFAULT_LOG_CONFIGURATION + pseudo_config + logconfig
+    for logconfig_item in logging_configurations:
         loggername, level = logconfig_item.split(':')
         level = getattr(logging, level, logging.INFO)
         logger = logging.getLogger(loggername)
@@ -231,101 +153,41 @@ def init_logger():
         if loggername != '':
             logger.propagate = False
 
-    for logconfig_item in default_config + pseudo_config + logconfig:
+    for logconfig_item in logging_configurations:
         _logger.debug('logger level set: "%s"', logconfig_item)
 
+DEFAULT_LOG_CONFIGURATION = [
+    'openerp.workflow.workitem:WARNING',
+    'openerp.netsvc.rpc.request:INFO',
+    'openerp.netsvc.rpc.response:INFO',
+    'openerp.addons.web.http:INFO',
+    'openerp.sql_db:INFO',
+    ':INFO',
+]
+PSEUDOCONFIG_MAPPER = {
+    'debug_rpc_answer': ['openerp:DEBUG','openerp.netsvc.rpc.request:DEBUG', 'openerp.netsvc.rpc.response:DEBUG'],
+    'debug_rpc': ['openerp:DEBUG','openerp.netsvc.rpc.request:DEBUG'],
+    'debug': ['openerp:DEBUG'],
+    'debug_sql': ['openerp.sql_db:DEBUG'],
+    'info': [],
+    'warn': ['openerp:WARNING'],
+    'error': ['openerp:ERROR'],
+    'critical': ['openerp:CRITICAL'],
+}
+
 # A alternative logging scheme for automated runs of the
 # server intended to test it.
 def init_alternative_logger():
     class H(logging.Handler):
-      def emit(self, record):
-        if record.levelno > 20:
-          print record.levelno, record.pathname, record.msg
+        def emit(self, record):
+            if record.levelno > 20:
+                print record.levelno, record.pathname, record.msg
     handler = H()
     # Add the handler to the 'openerp' logger.
     logger = logging.getLogger('openerp')
     logger.addHandler(handler)
     logger.setLevel(logging.ERROR)
 
-class Server:
-    """ Generic interface for all servers with an event loop etc.
-        Override this to impement http, net-rpc etc. servers.
-
-        Servers here must have threaded behaviour. start() must not block,
-        there is no run().
-    """
-    __is_started = False
-    __servers = []
-    __starter_threads = []
-
-    # we don't want blocking server calls (think select()) to
-    # wait forever and possibly prevent exiting the process,
-    # but instead we want a form of polling/busy_wait pattern, where
-    # _server_timeout should be used as the default timeout for
-    # all I/O blocking operations
-    _busywait_timeout = 0.5
-
-    def __init__(self):
-        Server.__servers.append(self)
-        if Server.__is_started:
-            # raise Exception('All instances of servers must be inited before the startAll()')
-            # Since the startAll() won't be called again, allow this server to
-            # init and then start it after 1sec (hopefully). Register that
-            # timer thread in a list, so that we can abort the start if quitAll
-            # is called in the meantime
-            t = threading.Timer(1.0, self._late_start)
-            t.name = 'Late start timer for %s' % str(self.__class__)
-            Server.__starter_threads.append(t)
-            t.start()
-
-    def start(self):
-        _logger.debug("called stub Server.start")
-
-    def _late_start(self):
-        self.start()
-        for thr in Server.__starter_threads:
-            if thr.finished.is_set():
-                Server.__starter_threads.remove(thr)
-
-    def stop(self):
-        _logger.debug("called stub Server.stop")
-
-    def stats(self):
-        """ This function should return statistics about the server """
-        return "%s: No statistics" % str(self.__class__)
-
-    @classmethod
-    def startAll(cls):
-        if cls.__is_started:
-            return
-        _logger.info("Starting %d services" % len(cls.__servers))
-        for srv in cls.__servers:
-            srv.start()
-        cls.__is_started = True
-
-    @classmethod
-    def quitAll(cls):
-        if not cls.__is_started:
-            return
-        _logger.info("Stopping %d services" % len(cls.__servers))
-        for thr in cls.__starter_threads:
-            if not thr.finished.is_set():
-                thr.cancel()
-            cls.__starter_threads.remove(thr)
-
-        for srv in cls.__servers:
-            srv.stop()
-        cls.__is_started = False
-
-    @classmethod
-    def allStats(cls):
-        res = ["Servers %s" % ('stopped', 'started')[cls.__is_started]]
-        res.extend(srv.stats() for srv in cls.__servers)
-        return '\n'.join(res)
-
-    def _close_socket(self):
-        close_socket(self.socket)
-
 def replace_request_password(args):
     # password is always 3rd argument in a request, we replace it in RPC logs
     # so it's easier to forward logs for diagnostics/debugging purposes...
@@ -344,8 +206,8 @@ def log(logger, level, prefix, msg, depth=None):
 def dispatch_rpc(service_name, method, params):
     """ Handle a RPC call.
 
-    This is pure Python code, the actual marshalling (from/to XML-RPC or
-    NET-RPC) is done in a upper layer.
+    This is pure Python code, the actual marshalling (from/to XML-RPC) is done
+    in a upper layer.
     """
     try:
         rpc_request = logging.getLogger(__name__ + '.rpc.request')
@@ -354,27 +216,46 @@ def dispatch_rpc(service_name, method, params):
         rpc_response_flag = rpc_response.isEnabledFor(logging.DEBUG)
         if rpc_request_flag or rpc_response_flag:
             start_time = time.time()
+            start_rss, start_vms = 0, 0
+            start_rss, start_vms = psutil.Process(os.getpid()).get_memory_info()
             if rpc_request and rpc_response_flag:
                 log(rpc_request,logging.DEBUG,'%s.%s'%(service_name,method), replace_request_password(params))
 
         threading.current_thread().uid = None
         threading.current_thread().dbname = None
-        result = ExportService.getService(service_name).dispatch(method, params)
+        if service_name == 'common':
+            dispatch = openerp.service.common.dispatch
+        elif service_name == 'db':
+            dispatch = openerp.service.db.dispatch
+        elif service_name == 'object':
+            dispatch = openerp.service.model.dispatch
+        elif service_name == 'report':
+            dispatch = openerp.service.report.dispatch
+        else:
+            dispatch = openerp.service.wsgi_server.rpc_handlers.get(service_name)
+        result = dispatch(method, params)
 
         if rpc_request_flag or rpc_response_flag:
             end_time = time.time()
+            end_rss, end_vms = 0, 0
+            end_rss, end_vms = psutil.Process(os.getpid()).get_memory_info()
+            logline = '%s.%s time:%.3fs mem: %sk -> %sk (diff: %sk)' % (service_name, method, end_time - start_time, start_vms / 1024, end_vms / 1024, (end_vms - start_vms)/1024)
             if rpc_response_flag:
-                log(rpc_response,logging.DEBUG,'%s.%s time:%.3fs '%(service_name,method,end_time - start_time), result)
+                log(rpc_response,logging.DEBUG, logline, result)
             else:
-                log(rpc_request,logging.DEBUG,'%s.%s time:%.3fs '%(service_name,method,end_time - start_time), replace_request_password(params), depth=1)
+                log(rpc_request,logging.DEBUG, logline, replace_request_password(params), depth=1)
 
         return result
+    except openerp.osv.orm.except_orm:
+        raise
     except openerp.exceptions.AccessError:
         raise
     except openerp.exceptions.AccessDenied:
         raise
     except openerp.exceptions.Warning:
         raise
+    except openerp.exceptions.RedirectWarning:
+        raise
     except openerp.exceptions.DeferredException, e:
         _logger.exception(tools.exception_to_unicode(e))
         post_mortem(e.traceback)