Merge pull request #648 from odoo-dev/7.0-fix-searchbar-navigation-ged
[odoo/odoo.git] / openerp / netsvc.py
index 7f84330..6e477f3 100644 (file)
@@ -1,9 +1,8 @@
-#!/usr/bin/env python
 # -*- coding: utf-8 -*-
 ##############################################################################
 #
 #    OpenERP, Open Source Management Solution
-#    Copyright (C) 2004-2011 OpenERP SA (<http://www.openerp.com>)
+#    Copyright (C) 2004-2014 OpenERP SA (<http://www.openerp.com>)
 #
 #    This program is free software: you can redistribute it and/or modify
 #    it under the terms of the GNU Affero General Public License as
@@ -20,6 +19,9 @@
 #
 ##############################################################################
 
+#.apidoc title: Common Services: netsvc
+#.apidoc module-mods: member-order: bysource
+
 import errno
 import logging
 import logging.handlers
@@ -33,6 +35,11 @@ import time
 import types
 from pprint import pformat
 
+try:
+    import psutil
+except ImportError:
+    psutil = None
+
 # TODO modules that import netsvc only for things from loglevels must be changed to use loglevels.
 from loglevels import *
 import tools
@@ -40,6 +47,7 @@ import openerp
 
 _logger = logging.getLogger(__name__)
 
+
 def close_socket(sock):
     """ Closes a socket instance cleanly
 
@@ -54,22 +62,18 @@ def close_socket(sock):
         # 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':
+        if e.errno != errno.ENOTCONN or platform.system() not in ['Darwin', 'Windows']:
             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.
+    """ Base class for Local services
+    Functionality here is trusted, no authentication.
+    Workflow engine and reports subclass this.
     """
     _services = {}
     def __init__(self, name):
@@ -145,8 +149,13 @@ class ColoredFormatter(DBFormatter):
         record.levelname = COLOR_PATTERN % (30 + fg_color, 40 + bg_color, record.levelname)
         return DBFormatter.format(self, record)
 
-
+_logger_init = False
 def init_logger():
+    global _logger_init
+    if _logger_init:
+        return
+    _logger_init = True
+
     from tools.translate import resetlocale
     resetlocale()
 
@@ -182,18 +191,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)
 
+    logging.getLogger().addHandler(handler)
+
     # 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.addons.web.http:INFO',
         'openerp.sql_db:INFO',
         ':INFO',
     ]
@@ -216,6 +232,8 @@ def init_logger():
         pseudo_config = ['openerp:CRITICAL']
     elif tools.config['log_level'] == 'debug_sql':
         pseudo_config = ['openerp.sql_db:DEBUG']
+    else:
+        pseudo_config = []
 
     logconfig = tools.config['log_handler']
 
@@ -223,11 +241,7 @@ def init_logger():
         loggername, level = logconfig_item.split(':')
         level = getattr(logging, level, logging.INFO)
         logger = logging.getLogger(loggername)
-        logger.handlers = []
         logger.setLevel(level)
-        logger.addHandler(handler)
-        if loggername != '':
-            logger.propagate = False
 
     for logconfig_item in default_config + pseudo_config + logconfig:
         _logger.debug('logger level set: "%s"', logconfig_item)
@@ -245,85 +259,6 @@ def init_alternative_logger():
     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...
@@ -352,6 +287,9 @@ 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
+            if psutil:
+                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))
 
@@ -359,10 +297,14 @@ def dispatch_rpc(service_name, method, params):
 
         if rpc_request_flag or rpc_response_flag:
             end_time = time.time()
+            end_rss, end_vms = 0, 0
+            if psutil:
+                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.exceptions.AccessError:
@@ -372,11 +314,11 @@ def dispatch_rpc(service_name, method, params):
     except openerp.exceptions.Warning:
         raise
     except openerp.exceptions.DeferredException, e:
-        _logger.error(tools.exception_to_unicode(e))
+        _logger.exception(tools.exception_to_unicode(e))
         post_mortem(e.traceback)
         raise
     except Exception, e:
-        _logger.error(tools.exception_to_unicode(e))
+        _logger.exception(tools.exception_to_unicode(e))
         post_mortem(sys.exc_info())
         raise