Add duration and truncate data in logging messages

issue11530
issue5228
review423311003

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 %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 @@ 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)

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('/<string:database_name>/', 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())

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 %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 @@ 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)