changeset 180997544b2e in trytond:default
details: https://hg.tryton.org/trytond?cmd=changeset&node=180997544b2e
description:
Add duration and truncate data in logging messages
issue11530
issue5228
review423311003
diffstat:
trytond/ir/cron.py | 12 +++++++++---
trytond/protocols/dispatcher.py | 32 +++++++++++++++++++++++++-------
trytond/worker.py | 21 +++++++++++++++------
3 files changed, 49 insertions(+), 16 deletions(-)
diffs (168 lines):
diff -r a1491526301b -r 180997544b2e trytond/ir/cron.py
--- a/trytond/ir/cron.py Sun Jul 17 00:07:23 2022 +0200
+++ b/trytond/ir/cron.py Sun Jul 17 23:52:44 2022 +0200
@@ -159,8 +159,10 @@
])
for cron in crons:
+ def duration():
+ return (time.monotonic() - started) * 1000
+ started = time.monotonic()
name = '<Cron %s@%s %s>' % (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 @@
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 -r a1491526301b -r 180997544b2e trytond/protocols/dispatcher.py
--- a/trytond/protocols/dispatcher.py Sun Jul 17 00:07:23 2022 +0200
+++ b/trytond/protocols/dispatcher.py Sun Jul 17 23:52:44 2022 +0200
@@ -32,6 +32,7 @@
ir_lang = Table('ir_lang')
ir_module = Table('ir_module')
res_user = Table('res_user')
+_MAX_LENGTH = 80
@app.route('/<string:database_name>/', methods=['POST'])
@@ -137,6 +138,14 @@
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 @@
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 @@
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 @@
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 -r a1491526301b -r 180997544b2e trytond/worker.py
--- a/trytond/worker.py Sun Jul 17 00:07:23 2022 +0200
+++ b/trytond/worker.py Sun Jul 17 23:52:44 2022 +0200
@@ -114,8 +114,11 @@
pool.init()
Queue = pool.get('ir.queue')
Error = pool.get('ir.error')
+
+ def duration():
+ return (time.monotonic() - started) * 1000
+ started = time.monotonic()
name = '<Task %s@%s>' % (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 @@
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 @@
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)
