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