From 38fc04785a6e37701741b1c8b3d54902c93fffd0 Mon Sep 17 00:00:00 2001 From: Martin Trigaux Date: Tue, 13 Jan 2015 12:07:49 +0100 Subject: [PATCH] [FIX] http: log rpc.request and rpc.response handlers The log level rec.request and rpc.response where no longer logged as the webclient no longer uses XMLRPC but JSONRPC instead. Duplicate the logging part from dispatch_rpc to dispatch method of JsonRequest to add rpc logs when using JSON requests. opw 617490 --- openerp/http.py | 34 ++++++++++++++++++++++++++++++++-- 1 file changed, 32 insertions(+), 2 deletions(-) diff --git a/openerp/http.py b/openerp/http.py index b59a4be86cb..6ee9aefe87b 100644 --- a/openerp/http.py +++ b/openerp/http.py @@ -13,6 +13,7 @@ import inspect import logging import mimetypes import os +import pprint import random import re import sys @@ -48,6 +49,8 @@ from openerp.tools.func import lazy_property from openerp.tools import ustr _logger = logging.getLogger(__name__) +rpc_request = logging.getLogger(__name__ + '.rpc.request') +rpc_response = logging.getLogger(__name__ + '.rpc.response') # 1 week cache for statics as advised by Google Page Speed STATIC_CACHE = 60 * 60 * 24 * 7 @@ -86,8 +89,6 @@ def dispatch_rpc(service_name, method, params): in a upper layer. """ try: - rpc_request = logging.getLogger(__name__ + '.rpc.request') - rpc_response = logging.getLogger(__name__ + '.rpc.response') rpc_request_flag = rpc_request.isEnabledFor(logging.DEBUG) rpc_response_flag = rpc_response.isEnabledFor(logging.DEBUG) if rpc_request_flag or rpc_response_flag: @@ -542,7 +543,36 @@ class JsonRequest(WebRequest): if self.jsonp_handler: return self.jsonp_handler() try: + rpc_request_flag = rpc_request.isEnabledFor(logging.DEBUG) + rpc_response_flag = rpc_response.isEnabledFor(logging.DEBUG) + if rpc_request_flag or rpc_response_flag: + endpoint = self.endpoint.method.__name__ + model = self.params.get('model') + method = self.params.get('method') + args = self.params.get('args', []) + + start_time = time.time() + _, start_vms = 0, 0 + if psutil: + _, start_vms = psutil.Process().get_memory_info() + if rpc_request and rpc_response_flag: + rpc_request.debug('%s: %s %s, %s', + endpoint, model, method, pprint.pformat(args)) + result = self._call_function(**self.params) + + if rpc_request_flag or rpc_response_flag: + end_time = time.time() + _, end_vms = 0, 0 + if psutil: + _, end_vms = psutil.Process().get_memory_info() + logline = '%s: %s %s: time:%.3fs mem: %sk -> %sk (diff: %sk)' % ( + endpoint, model, method, end_time - start_time, start_vms / 1024, end_vms / 1024, (end_vms - start_vms)/1024) + if rpc_response_flag: + rpc_response.debug('%s, %s', logline, pprint.pformat(result)) + else: + rpc_request.debug(logline) + return self._json_response(result) except Exception, e: return self._handle_exception(e)