Carry the request id from the dispatching request into the worker - #283
Merged
Conversation
A scan starts as an HTTP request and finishes minutes later inside a worker. Those two halves could not be joined up in the logs: the middleware binds request_id for the request, but apply_async sends only the task arguments, so every line the worker emitted belonged to no request. Tracing a scan back to the request that started it meant guessing from timestamps. Three Celery signals close the gap without touching a call site. before_task_publish copies request_id onto the message while the dispatching context still exists; task_prerun reads it back in the worker and binds it with the task name and the Celery task id; task_postrun clears exactly those three. The clear matters as much as the bind: worker slots are reused, and an id left behind would attach itself to the next task and misattribute its logs to an unrelated request while looking perfectly valid. Handling this at signal level rather than per task is what makes the coverage complete. Twenty-four task modules bind context by hand today and each binds a different subset; ten bind nothing at all. Tasks beat dispatches have no request behind them and get no request_id, which is a meaningful absence rather than a gap to fill with a substitute. The handlers swallow their own errors. Losing a context field is a degradation; failing a scan because logging broke is an outage. Task-owned context (scan_id, dry_run) is untouched. Those belong to the task, which binds and unbinds them itself, and the handlers clear only their own keys so nothing is dropped mid-flight. The contributor guide claimed worker logs already carried request_id. That was not true until now; it is now, and the entry says where the propagation happens and why a beat task has no id.
The handler wrote celery_task_id while twelve task modules bind task_id for the same value. Both paths run on the same task, so every scan log line would have carried the Celery task id twice under two names, and a reader would have had to know which one to filter on. Using the existing names means the handler writes the same field the task does. Where both run the values agree and the task's later bind wins, so the duplication disappears instead of being introduced. task_name was already aligned; task_id is now too. The doc entry gains the numbers behind the change: 22 modules bound task_name and 12 bound task_id, which is why the ten that bound neither had no way to say what had run.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
First half of the observability groundwork (O1). The signal handlers this adds are also where O4 will write its task-run rows, which is why the two were sequenced together: this way the handlers get written once.
The gap
A scan starts as an HTTP request and finishes minutes later inside a worker. The middleware binds
request_idfor the request, butapply_asyncsends only the task arguments, so every line the worker logs belongs to no request at all. Tracing a scan back to the request that started it meant guessing from timestamps.The fix
Three Celery signals, no call site touched:
before_task_publishrequest_idonto the message headers while the request context still existstask_preruntask_nameandcelery_task_idtask_postrunThe clear matters as much as the bind. Worker slots are reused, so an id left behind attaches itself to the next task and misattributes its logs to an unrelated request, while looking perfectly valid. There is a test for precisely that.
Handling this at signal level rather than per task is what makes the coverage complete: 24 task modules bind context by hand today, each a different subset, and 10 bind nothing. Tasks that beat dispatches have no request behind them and get no
request_id. That absence is meaningful, so it is not filled with a substitute.What is deliberately not done
Task-owned context stays where it is.
scan_id,dry_runand friends belong to the task, which binds and unbinds them itself; the handlers clear only their own keys. Removing the manual binds mechanically would dropscan_idfrom scan logs, which would make this change reduce correlation rather than add it.The two duplicated keys (
task_name,task_id) now have both paths writing them.bind_contextvarslets the later call win, so the task's value survives, and the values agree. Cleaning that duplication up is tidying, not correctness, and belongs in its own change.Handlers never raise
Each one swallows its own errors and logs a warning. Losing a context field is a degradation; failing a scan because logging broke is an outage. Three tests drive that path directly.
Docs
The contributor guide claimed worker logs already carried
request_id. That was not true until this change. The entry now says where the propagation happens, and that a beat task legitimately has none. EN and KO both.Verification
15 new tests, full backend unit suite green (5798 passed; the 28 errors are the DB-backed tests, which need a local instance and are unaffected by this change),
ruff checkclean,mypyclean across 818 files.Signals are connected with explicit
connect()calls rather than the@signal.connectdecorator: Celery ships no types for those decorators, so decorating erases the annotations and mypy stops checking the bodies.