How do you attach a correlation id to every LogRecord using a ContextVar and a logging Filter?
answer
- Ambient data, not a parameter
- Thread-local is wrong once tasks interleave
- The hook can also modify, not only reject
- Register it where every record passes
- Remember to put the old value back
basics
~20 sKeep the id in a contextvars.ContextVar, then add a logging.Filter whose filter() reads it, sets it as an attribute on the record and returns True. Attach that filter to the handler so every record it emits is stamped.
solid answer
~50 sA `logging.Filter` is any object with a `filter(record)` method; returning a falsy value drops the record and a truthy value keeps it, and because the record is handed over before formatting, the filter may also **enrich** it — `record.job_id = job_id_var.get()`. Storing the id in a `contextvars.ContextVar` rather than a `threading.local` is what makes it correct under asyncio: each `asyncio.Task` runs in its own copy of the context, so interleaved jobs on one thread cannot read each other's id. Attach the filter to the **handler**, not to a logger: a filter on a logger only sees records that logger created itself, whereas everything reaching the handler — including records from third-party loggers — passes the handler's filters. Set the variable with `var.set(...)`, keep the returned token, and `var.reset(token)` in a `finally` so a long-running worker does not stamp later records with a finished job's id.
code
python · 24 linesimport contextvars, logging, sys
job_id = contextvars.ContextVar("job_id", default="-")
class JobContextFilter(logging.Filter):
def filter(self, record):
record.job_id = job_id.get()
return True
handler = logging.StreamHandler(sys.stdout)
handler.setFormatter(logging.Formatter("%(job_id)s %(message)s"))
handler.addFilter(JobContextFilter())
log = logging.getLogger("thumbnails")
log.addHandler(handler)
log.setLevel(logging.INFO)
token = job_id.set("j-914")
try:
log.info("thumbnail written")
finally:
job_id.reset(token)
log.info("worker idle")go deeper
Know that a correlation id ties together all the log lines of one unit of work, and that Python can attach it automatically rather than you passing it into every function.
Explain the mechanics: a ContextVar holds the value, a Filter copies it onto each record and returns True, and the formatter then reads it as an ordinary record attribute.
Show that you have operated this: the filter goes on the handler so library logs are covered, the token is reset in a finally so ids do not leak across a long run, the filter cannot raise, and context does not cross a thread pool or process boundary by itself.
Decide the id's lifecycle across the estate: who mints it, how it is accepted from an inbound call, how it propagates outward, and how it lines up with the identifiers your tracing and metrics already use.
## The problem An image-thumbnail worker chews through a queue for six hours a night. When one job produces a corrupt output you want every line it logged — including lines from library code you did not write — tagged with that job's id, and you do not want to thread a `job_id` parameter through every function to get it. That is ambient context, and the stdlib answer is a context variable read by a logging filter. ## Why `contextvars` and not `threading.local` `threading.local` gives each OS thread its own value. That is fine for a thread-per-job worker and wrong the moment coroutines are involved: many tasks share one thread, so they would all see whichever value was set last. `contextvars.ContextVar` is scoped to the *context*, and the asyncio machinery gives every `Task` a copy of the context it was created in. Two jobs interleaved on one event loop therefore hold independent ids, and a value set inside a task does not leak back to its parent. The API is three calls. `var.get(default)` reads; `var.set(value)` writes and returns a `Token`; `var.reset(token)` restores the previous value. In a long-lived worker the `reset` matters: without it, a job that finishes without clearing the variable leaves its id in place, and the next records — idle-loop messages, the following job's start-up, an unrelated timer — are attributed to a job that ended. A `try/finally` around each job, or a small context manager, keeps this honest. One boundary catches people out: a plain worker thread starts with an **empty** context. Submitting work to a thread pool does not carry your variables across; the worker sees the variable's default. If you need the id in a pool worker, copy the context explicitly with `contextvars.copy_context()` and run the callable through it, or set the variable inside the worker from data you passed along. `asyncio.to_thread` already does that copy for you. Across a *process* boundary nothing carries at all — a separate interpreter has separate context variables — so an id must travel as data in the work item. ## The filter ```python class JobContextFilter(logging.Filter): def filter(self, record): record.job_id = job_id_var.get() return True ``` Three things to note. First, the return value is a *predicate*: falsy drops the record, truthy keeps it. A filter that forgets to `return True` returns `None` and silently discards every record it touches — a spectacular and very common self-inflicted outage. Second, since Python 3.12 a filter may return a `LogRecord` instance to *replace* the record rather than mutating it in place, which is useful when you want to leave the caller's record untouched. Third, since 3.2 a filter need not be a `Filter` subclass at all; any callable taking a record works, so a plain function is fine. A filter that raises is not contained. `Logger.callHandlers` does not wrap handler dispatch in a try/except for this, so an exception escaping your filter propagates out of the `logger.info(...)` call and into application code that had no reason to expect it. Give the filter a total function: use `var.get(default)` with a default, and never do I/O or lookups that can fail inside it. ## Where to attach it This is the decision that makes the difference between working and half-working. A `Filter` added to a `Logger` runs only for records that logger itself created — records arriving from elsewhere and reaching the same handler never see it. A `Filter` added to a `Handler` runs for every record that handler is about to emit. For an enrichment filter you almost always want the handler: it stamps your code, and library code, and anything a framework logs, with one registration in one place. The order of operations for each call is worth memorising: the logger's effective level is checked, the record is created, the logger's own filters run, the record walks up to each handler, that handler's level is checked, the handler's filters run, and only then does the formatter render. So a handler filter is guaranteed to run before formatting — which is why an attribute it sets is safe to reference from a format string or a JSON formatter — and it is guaranteed *not* to run for records the level check already rejected. ## The rest of the pattern Generating the id belongs at the edge: accept an inbound id if the caller supplied one and it looks sane, otherwise mint one (`uuid.uuid4().hex` is fine) so every unit of work has exactly one. Set it once, log it as a field rather than gluing it into the message text, and propagate it outward on any call you make so the id survives across services. Because the filter injects the attribute onto *every* record, a `%(job_id)s` in a format string is now safe — the default in `get()` guarantees the attribute is always present, which is exactly the guarantee a per-call `extra` cannot give you. The same filter is the natural place for other ambient fields — a worker name, a deployment version, a shard — as long as reading them is cheap and cannot fail.
- Would you attach this enriching filter to the logger or to the handler, and why?The handler. A filter on a logger runs only for records that logger created, so records from library loggers reach the shared handler unstamped and the field is missing exactly where you most need it. Registering on the handler covers everything that handler emits, in one place, and it still runs before the formatter, so a format string or JSON formatter can rely on the attribute being there.
- What happens to the correlation id when work crosses into a process pool?Nothing carries. Context variables live in one interpreter, so a worker process starts with defaults, and records created there are not the same objects as yours. The id has to travel as data: put it in the work item, set the variable at the top of the worker function, and let the same filter stamp records on that side. The same applies to any handler that ships records to another process.
- A filter starts dropping every record. What is the usual cause?It fell off the end of the function and returned None. The return value is a predicate: falsy drops the record, truthy keeps it, so an enrichment filter that forgets its `return True` silently deletes the log stream it was meant to annotate. Since 3.12 returning a LogRecord is also valid and means "use this record instead", but returning nothing has always meant "discard".
The context variable is a badge the current job is wearing; the filter is the doorman who writes the badge number on every form that goes past, so nobody has to remember to fill that box in.
saying these in an interview costs you the question
- Claims threading.local is equivalent for asyncio tasks
- Believes worker threads inherit the caller's context values
- Thinks a filter returning None keeps the record
- Stores the id on the shared logger object instead
- Says filters can only drop records, never modify them
- Never resets the variable, so ids leak between jobs