From db81edc2872c4ccf9d4a3f596d0ec2040fa4a58f Mon Sep 17 00:00:00 2001 From: Olivier Dony Date: Fri, 1 Mar 2013 13:07:44 +0100 Subject: [PATCH] [FIX] *: fix/rationalize db logging to avoid incorrect values during logging The setting/clearing of the tracking were not done consistently, causing log messages that appeared to come from one database while coming from another one or none at all. The tracker is now set at the earliest points of request handling where we can: - in web client, when creating WebRequests (dbname, uid) - at RPC dispatching in server (uid) - at cron job acquisition in CronWorker (dbname) - at Registry acquisition in RegistryManager (dbname) The tracker is cleared at the very entrance of the request in the WSGI `application`, ensuring that no logging is produced with an obsolete db name. (It cannot be cleared at the end of the request handling because the werkzeug wrapper outputs more logging afterwards) bzr revid: odo@openerp.com-20130301120744-jfitcmze2jldecod --- openerp/addons/base/ir/ir_cron.py | 7 ++++++- openerp/modules/registry.py | 4 ++++ openerp/netsvc.py | 2 -- openerp/osv/osv.py | 1 - openerp/service/web_services.py | 4 ++++ openerp/service/wsgi_server.py | 11 ++++++++++- openerp/sql_db.py | 5 ----- 7 files changed, 24 insertions(+), 10 deletions(-) diff --git a/openerp/addons/base/ir/ir_cron.py b/openerp/addons/base/ir/ir_cron.py index 4bf99cf9934..a5c11d01152 100644 --- a/openerp/addons/base/ir/ir_cron.py +++ b/openerp/addons/base/ir/ir_cron.py @@ -18,8 +18,9 @@ # along with this program. If not, see . # ############################################################################## -import time import logging +import threading +import time import psycopg2 from datetime import datetime from dateutil.relativedelta import relativedelta @@ -181,6 +182,7 @@ class ir_cron(osv.osv): If a job was processed, returns True, otherwise returns False. """ db = openerp.sql_db.db_connect(db_name) + threading.current_thread().dbname = db_name cr = db.cursor() jobs = [] try: @@ -237,6 +239,9 @@ class ir_cron(osv.osv): # we're exiting due to an exception while acquiring the lock lock_cr.close() + if hasattr(threading.current_thread(), 'dbname'): # cron job could have removed it as side-effect + del threading.current_thread().dbname + def _try_lock(self, cr, uid, ids, context=None): """Try to grab a dummy exclusive write-lock to the rows with the given ids, to make sure a following write() or unlink() will not block due diff --git a/openerp/modules/registry.py b/openerp/modules/registry.py index b06c500a24c..d37f915c20e 100644 --- a/openerp/modules/registry.py +++ b/openerp/modules/registry.py @@ -190,6 +190,10 @@ class RegistryManager(object): except KeyError: return cls.new(db_name, force_demo, status, update_module) + finally: + # set db tracker - cleaned up at the WSGI + # dispatching phase in openerp.service.wsgi_server.application + threading.current_thread().dbname = db_name @classmethod def new(cls, db_name, force_demo=False, status=None, diff --git a/openerp/netsvc.py b/openerp/netsvc.py index d6f9dc49d84..9495cecd6fb 100644 --- a/openerp/netsvc.py +++ b/openerp/netsvc.py @@ -290,8 +290,6 @@ def dispatch_rpc(service_name, method, params): 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 rpc_request_flag or rpc_response_flag: diff --git a/openerp/osv/osv.py b/openerp/osv/osv.py index 42f50d94b04..13c4ecd0e78 100644 --- a/openerp/osv/osv.py +++ b/openerp/osv/osv.py @@ -189,7 +189,6 @@ class object_proxy(object): @check def execute(self, db, uid, obj, method, *args, **kw): - threading.currentThread().dbname = db cr = pooler.get_db(db).cursor() try: try: diff --git a/openerp/service/web_services.py b/openerp/service/web_services.py index 940ecdb23e8..49bbf474020 100644 --- a/openerp/service/web_services.py +++ b/openerp/service/web_services.py @@ -601,7 +601,11 @@ class objects_proxy(netsvc.ExportService): def dispatch(self, method, params): (db, uid, passwd ) = params[0:3] + + # set uid tracker - cleaned up at the WSGI + # dispatching phase in openerp.service.wsgi_server.application threading.current_thread().uid = uid + params = params[3:] if method == 'obj_list': raise NameError("obj_list has been discontinued via RPC as of 6.0, please query ir.model directly!") diff --git a/openerp/service/wsgi_server.py b/openerp/service/wsgi_server.py index 67436a1c0bf..23eb6a95dcf 100644 --- a/openerp/service/wsgi_server.py +++ b/openerp/service/wsgi_server.py @@ -384,6 +384,16 @@ def register_wsgi_handler(handler): def application_unproxied(environ, start_response): """ WSGI entry point.""" + # cleanup db/uid trackers - they're set at HTTP dispatch in + # web.session.OpenERPSession.send() and at RPC dispatch in + # openerp.service.web_services.objects_proxy.dispatch(). + # /!\ The cleanup cannot be done at the end of this `application` + # method because werkzeug still produces relevant logging afterwards + if hasattr(threading.current_thread(), 'uid'): + del threading.current_thread().uid + if hasattr(threading.current_thread(), 'dbname'): + del threading.current_thread().dbname + openerp.service.start_internal() # Try all handlers until one returns some result (i.e. not None). @@ -395,7 +405,6 @@ def application_unproxied(environ, start_response): continue return result - # We never returned from the loop. response = 'No handler found.\n' start_response('404 Not Found', [('Content-Type', 'text/plain'), ('Content-Length', str(len(response)))]) diff --git a/openerp/sql_db.py b/openerp/sql_db.py index 31540f7ae4c..9844de48d2a 100644 --- a/openerp/sql_db.py +++ b/openerp/sql_db.py @@ -41,7 +41,6 @@ import psycopg2.extensions from psycopg2.extensions import ISOLATION_LEVEL_AUTOCOMMIT, ISOLATION_LEVEL_READ_COMMITTED, ISOLATION_LEVEL_REPEATABLE_READ from psycopg2.pool import PoolError from psycopg2.psycopg1 import cursor as psycopg1cursor -from threading import currentThread psycopg2.extensions.register_type(psycopg2.extensions.UNICODE) @@ -520,7 +519,6 @@ def db_connect(db_name): global _Pool if _Pool is None: _Pool = ConnectionPool(int(tools.config['db_maxconn'])) - currentThread().dbname = db_name return Connection(_Pool, db_name) def close_db(db_name): @@ -528,9 +526,6 @@ def close_db(db_name): global _Pool if _Pool: _Pool.close_all(dsn(db_name)) - ct = currentThread() - if hasattr(ct, 'dbname'): - delattr(ct, 'dbname') # vim:expandtab:smartindent:tabstop=4:softtabstop=4:shiftwidth=4: