From b209a231c26fb6d174feb36fccbab2daeca466b0 Mon Sep 17 00:00:00 2001
From: Peter Schutt <peter.github@proton.me>
Date: Wed, 11 Jan 2023 16:09:43 +1000
Subject: [PATCH] feat(logs): add duration measures to worker logs.

Closes #180
---
 src/starlite_saqlalchemy/log/worker.py | 4 ++++
 tests/unit/test_log.py                 | 6 ++++++
 2 files changed, 10 insertions(+)

diff --git a/src/starlite_saqlalchemy/log/worker.py b/src/starlite_saqlalchemy/log/worker.py
index ea2f081c..406dd5e0 100644
--- 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
index 552af1e8..d09fbdc9 100644
--- 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