From f1161d2abaf7773c1debc7e4cd2bc55fc89f4242 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?C=C3=A9dric=20Krier?= Date: Tue, 5 Nov 2024 19:05:41 +0100 Subject: [PATCH] Log request duration at wsgi_app level instead of with_pool This gives more accurate duration as other decorators may take time to execute. Closes #13650 --- trytond/trytond/protocols/wrappers.py | 16 ----- trytond/trytond/wsgi.py | 92 +++++++++++++++------------ 2 files changed, 50 insertions(+), 58 deletions(-) diff --git a/trytond/trytond/protocols/wrappers.py b/trytond/trytond/protocols/wrappers.py index c9b8e2454d..e6c68a4b02 100644 --- a/trytond/trytond/protocols/wrappers.py +++ b/trytond/trytond/protocols/wrappers.py @@ -196,34 +196,18 @@ def with_pool(func): with Transaction().start(database_name, 0, readonly=True): pool.init() - log_message = '%s in %i ms' - - def duration(): - return (time.monotonic() - started) * 1000 - started = time.monotonic() - try: result = func(request, pool, *args, **kwargs) - except exceptions.HTTPException: - logger.info( - log_message, request, duration(), - exc_info=logger.isEnabledFor(logging.DEBUG)) - raise except (UserError, UserWarning) as e: - logger.info( - log_message, request, duration(), - exc_info=logger.isEnabledFor(logging.DEBUG)) if request.rpc_method: raise else: abort(HTTPStatus.BAD_REQUEST, e) except Exception as e: - logger.exception(log_message, request, duration()) if request.rpc_method: raise else: abort(HTTPStatus.INTERNAL_SERVER_ERROR, e) - logger.info(log_message, request, duration()) return result return wrapper diff --git a/trytond/trytond/wsgi.py b/trytond/trytond/wsgi.py index 2dd9fe058e..2a94f2629a 100644 --- a/trytond/trytond/wsgi.py +++ b/trytond/trytond/wsgi.py @@ -6,6 +6,7 @@ import logging import os import posixpath import sys +import time import traceback import urllib.parse from functools import wraps @@ -142,51 +143,58 @@ class TrytondWSGI(object): return response def wsgi_app(self, environ, start_response): - for cls in self.protocols: - if cls.content_type in environ.get('CONTENT_TYPE', ''): - request = cls.request(environ) - break - else: - request = Request(environ) - logger.info('%s', request) + def duration(): + return (time.monotonic() - started) * 1000 + started, request = time.monotonic(), None + try: - origin = request.headers.get('Origin') - origin_host = urllib.parse.urlparse(origin).netloc if origin else '' - host = request.headers.get('Host') - if origin and origin != 'null' and origin_host != host: - cors = filter( - None, config.get('web', 'cors', default='').splitlines()) - if origin not in cors: - if (origin.startswith('moz-extension://') - or origin.startswith('chrome-extension://')): - origin = 'null' - else: - abort(HTTPStatus.FORBIDDEN) - if origin == 'null': - adapter = self.url_map.bind_to_environ(request.environ) - endpoint = adapter.match()[0] - if not getattr(endpoint, 'allow_null_origin', False): - abort(HTTPStatus.FORBIDDEN) - - with processing(request): - data = self.dispatch_request(request) - if not isinstance(data, (Response, exceptions.HTTPException)): - response = self.make_response(request, data) + for cls in self.protocols: + if cls.content_type in environ.get('CONTENT_TYPE', ''): + request = cls.request(environ) + break else: - response = data + request = Request(environ) - if origin and isinstance(response, Response): - response.headers['Access-Control-Allow-Origin'] = origin - response.headers['Vary'] = 'Origin' - method = request.headers.get('Access-Control-Request-Method') - if method: - response.headers['Access-Control-Allow-Methods'] = method - headers = request.headers.get('Access-Control-Request-Headers') - if headers: - response.headers['Access-Control-Allow-Headers'] = headers - response.headers['Access-Control-Max-Age'] = config.getint( - 'web', 'cache_timeout') - return response(environ, start_response) + origin = request.headers.get('Origin') + origin_host = ( + urllib.parse.urlparse(origin).netloc if origin else '') + host = request.headers.get('Host') + if origin and origin != 'null' and origin_host != host: + cors = filter( + None, config.get('web', 'cors', default='').splitlines()) + if origin not in cors: + if (origin.startswith('moz-extension://') + or origin.startswith('chrome-extension://')): + origin = 'null' + else: + abort(HTTPStatus.FORBIDDEN) + if origin == 'null': + adapter = self.url_map.bind_to_environ(request.environ) + endpoint = adapter.match()[0] + if not getattr(endpoint, 'allow_null_origin', False): + abort(HTTPStatus.FORBIDDEN) + + with processing(request): + data = self.dispatch_request(request) + if not isinstance(data, (Response, exceptions.HTTPException)): + response = self.make_response(request, data) + else: + response = data + + if origin and isinstance(response, Response): + response.headers['Access-Control-Allow-Origin'] = origin + response.headers['Vary'] = 'Origin' + method = request.headers.get('Access-Control-Request-Method') + if method: + response.headers['Access-Control-Allow-Methods'] = method + headers = request.headers.get('Access-Control-Request-Headers') + if headers: + response.headers['Access-Control-Allow-Headers'] = headers + response.headers['Access-Control-Max-Age'] = config.getint( + 'web', 'cache_timeout') + return response(environ, start_response) + finally: + logger.info('%s in %i ms', request, duration()) def __call__(self, environ, start_response): return self.wsgi_app(environ, start_response)