From 9bcccacfb9e82ac035a58f2d3c1910ca6b0200da Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?C=C3=A9dric=20Krier?= Date: Sun, 17 Jul 2022 23:52:44 +0200 Subject: [PATCH] Add duration and truncate data in logging messages issue11530 issue5228 review423311003 --- trytond/ir/cron.py | 12 +++++++++--- trytond/protocols/dispatcher.py | 32 +++++++++++++++++++++++++------- trytond/worker.py | 21 +++++++++++++++------ 3 files changed, 49 insertions(+), 16 deletions(-) diff --git a/trytond/ir/cron.py b/trytond/ir/cron.py index f49f41d44f..6e586bde58 100644 --- a/trytond/ir/cron.py +++ b/trytond/ir/cron.py @@ -159,8 +159,10 @@ class Cron(DeactivableMixin, ModelSQL, ModelView): ]) for cron in crons: + def duration(): + return (time.monotonic() - started) * 1000 + started = time.monotonic() name = '' % (cron.id, db_name, cron.method) - logger.info("%s started", name) for count in range(retry, -1, -1): if count != retry: time.sleep(0.02 * (retry - count)) @@ -172,15 +174,19 @@ class Cron(DeactivableMixin, ModelSQL, ModelView): except Exception as e: if (isinstance(e, backend.DatabaseOperationalError) and count): + logger.debug("Retry: %i", retry - count + 1) continue if isinstance(e, (UserError, UserWarning)): Error.log(cron, e) - logger.info('%s failed', name) + logger.info( + "%s failed after %i ms", name, duration()) else: - logger.critical('%s failed', name, exc_info=True) + logger.exception( + "%s failed after %i ms", name, duration()) cron.next_call = cron.compute_next_call(now) cron.save() break + logger.info("%s in %i ms", name, duration()) while transaction.tasks: task_id = transaction.tasks.pop() run_task(db_name, task_id) diff --git a/trytond/protocols/dispatcher.py b/trytond/protocols/dispatcher.py index 2e86f55edc..26388af366 100644 --- a/trytond/protocols/dispatcher.py +++ b/trytond/protocols/dispatcher.py @@ -32,6 +32,7 @@ ir_configuration = Table('ir_configuration') ir_lang = Table('ir_lang') ir_module = Table('ir_module') res_user = Table('res_user') +_MAX_LENGTH = 80 @app.route('//', methods=['POST']) @@ -137,6 +138,14 @@ def help_method(request, pool): return pydoc.getdoc(getattr(obj, method)) +def _safe_repr(args, kwargs, short=False): + args = args + tuple('%s=%r' % (k, v) for k, v in kwargs.items()) + result = repr(args) + if not short or len(result) < _MAX_LENGTH: + return result + return result[:_MAX_LENGTH] + ' [truncated]...)' + + @app.auth_required @with_pool def _dispatch(request, pool, *args, **kwargs): @@ -157,13 +166,18 @@ def _dispatch(request, pool, *args, **kwargs): pool.database_name, user, session, context=context): abort(HTTPStatus.UNAUTHORIZED) - log_message = '%s.%s(*%s, **%s) from %s@%s%s' + log_message = '%s.%s%s from %s@%s%s in %i ms' username = request.authorization.username if isinstance(username, bytes): username = username.decode('utf-8') log_args = ( - obj, method, args, kwargs, username, request.remote_addr, request.path) - logger.debug(log_message, *log_args) + obj.__name__, method, + _safe_repr(args, kwargs, not logger.isEnabledFor(logging.DEBUG)), + username, request.remote_addr, request.path) + + def duration(): + return (time.monotonic() - started) * 1000 + started = time.monotonic() retry = config.getint('database', 'retry') for count in range(retry, -1, -1): @@ -190,15 +204,18 @@ def _dispatch(request, pool, *args, **kwargs): except backend.DatabaseOperationalError: if count and not rpc.readonly: transaction.rollback() + logger.debug("Retry: %i", retry - count + 1) continue - logger.error(log_message, *log_args, exc_info=True) + logger.exception(log_message, *log_args, duration()) raise except (ConcurrencyException, UserError, UserWarning, LoginException): - logger.debug(log_message, *log_args, exc_info=True) + logger.info( + log_message, *log_args, duration(), + exc_info=logger.isEnabledFor(logging.DEBUG)) raise except Exception: - logger.error(log_message, *log_args, exc_info=True) + logger.exception(log_message, *log_args, duration()) raise # Need to commit to unlock SQLite database transaction.commit() @@ -208,7 +225,8 @@ def _dispatch(request, pool, *args, **kwargs): if session: context = {'_request': request.context} security.reset(pool.database_name, session, context=context) - logger.debug('Result: %s', result) + logger.info(log_message, *log_args, duration()) + logger.debug('Result: %r', result) response = app.make_response(request, result) if rpc.readonly and rpc.cache: response.headers.extend(rpc.cache.headers()) diff --git a/trytond/worker.py b/trytond/worker.py index 5ce8ef0db6..b0d751fbf3 100644 --- a/trytond/worker.py +++ b/trytond/worker.py @@ -114,8 +114,11 @@ def run_task(pool, task_id): pool.init() Queue = pool.get('ir.queue') Error = pool.get('ir.error') + + def duration(): + return (time.monotonic() - started) * 1000 + started = time.monotonic() name = '' % (task_id, pool.database_name) - logger.info('%s started', name) retry = config.getint('database', 'retry') try: for count in range(retry, -1, -1): @@ -134,14 +137,17 @@ def run_task(pool, task_id): except backend.DatabaseOperationalError: if count: transaction.rollback() + logger.debug("Retry: %i", retry - count + 1) continue raise except (UserError, UserWarning) as e: Error.log(task, e) raise - logger.info('%s done', name) + logger.info("%s in %i ms", name, duration()) except backend.DatabaseOperationalError: - logger.info('%s failed, retrying', name, exc_info=True) + logger.info( + "%s failed after %i ms, retrying", name, duration(), + exc_info=logger.isEnabledFor(logging.DEBUG)) if not config.getboolean('queue', 'worker', default=False): time.sleep(0.02 * retry) try: @@ -159,8 +165,11 @@ def run_task(pool, task_id): Queue.push(task.name, task.data, scheduled_at=scheduled_at) except Exception: logger.critical( - 'rescheduling %s failed', name, exc_info=True) + "rescheduling %s failed", name, exc_info=True) except (UserError, UserWarning): - logger.info('%s failed', name) + logger.info( + "%s failed after %i ms", name, duration(), + exc_info=logger.isEnabledFor(logging.DEBUG)) except Exception: - logger.critical('%s failed', name, exc_info=True) + logger.critical( + "%s failed after %i ms", name, duration(), exc_info=True)