feat(logs): add duration measures to worker logs.

Closes #180
topsport-com-au · Jan 11, 2023 · b209a23 · b209a23
1 parent f20209b
commit b209a23
Show file tree

Hide file tree

Showing 2 changed files with 10 additions and 0 deletions.
diff --git a/src/starlite_saqlalchemy/log/worker.py b/src/starlite_saqlalchemy/log/worker.py
@@ -28,6 +28,10 @@ async def after_process(ctx: Context) -> None:
     # parse log context from `ctx`
     job: Job = ctx["job"]
     log_ctx = {k: getattr(job, k) for k in settings.log.JOB_FIELDS}
+    # add duration measures
+    log_ctx["pickup_time_ms"] = job.started - job.queued
+    log_ctx["completed_time_ms"] = job.completed - job.started
+    log_ctx["total_time_ms"] = job.completed - job.queued
     # emit the log
     if job.error:
         level = logging.ERROR

diff --git a/tests/unit/test_log.py b/tests/unit/test_log.py
@@ -346,6 +346,9 @@ async def test_after_process(job: Job, cap_logger: CapturingLogger) -> None:
                 "event": "Worker",
                 "level": "info",
                 "timestamp": ANY,
+                "pickup_time_ms": 0,
+                "completed_time_ms": 0,
+                "total_time_ms": 0,
             },
         )
     ] == cap_logger.calls
@@ -373,6 +376,9 @@ async def test_after_process_logs_at_error(job: Job, cap_logger: CapturingLogger
                 "event": "Worker",
                 "level": "error",
                 "timestamp": ANY,
+                "pickup_time_ms": 0,
+                "completed_time_ms": 0,
+                "total_time_ms": 0,
             },
         )
     ] == cap_logger.calls