Using contextvars for Request Tracing in Python
Every log line a request produces should carry the same correlation ID - across await points, spawned tasks, and offloaded work - without that ID being threaded through every function signature. This page is for backend engineers and SREs running an async Python service who need request-scoped tracing that survives an event loop multiplexing hundreds of requests onto one OS thread. It implements that with contextvars, the only standard-library primitive that stays correct under that concurrency model. It is a focused task within the context variables and thread safety reference and part of the Python Logging Fundamentals and Structured Data guide.
Prerequisites
contextvars is standard library from Python 3.7, so there is nothing to install for the primitive itself; the examples target Python 3.11 or newer, where asyncio.to_thread and PEP 604 type unions are both available. Only the middleware example needs a third-party package, and it should be pinned rather than installed bare:
pip install "starlette>=0.37.0,<1.0.0"
# pyproject.toml — the same pin, expressed for a real service
[project]
name = "orders-api"
requires-python = ">=3.11,<3.14"
dependencies = [
"starlette>=0.37.0,<1.0.0", # only for the ASGI middleware example
] # contextvars and logging are stdlib
Two environment inputs are worth wiring up front: a service name, so downstream tooling can label the records, and the header name your edge proxy uses for an explicit identifier, so the middleware is not hard-coded to one deployment.
export OTEL_SERVICE_NAME="orders-api"
export TRACE_HEADER="X-Trace-ID" # explicit override; traceparent is still honoured
Implementation
The flow has four steps: declare the slot, seed it at the request boundary, read it in a filter, and reset it on teardown.
-
Declare one module-level
ContextVar. Define it once with aNonedefault so every module that imports it shares the same slot and the filter can detect a missing value. Declaring it inside a request handler would create a fresh slot per call and defeat propagation entirely, and aContextVarcreated in a loop also leaks, because the runtime never garbage-collects context variable slots. -
Seed the value in ASGI middleware. Middleware owns the whole request lifecycle, so it is the right place to extract the inbound identifier and to guarantee the matching reset. Prefer an explicit
X-Trace-IDheader, then the trace-id segment of a W3Ctraceparent, and finally a generated UUID so a request is never untraceable. -
Read the value in a logging filter. The filter runs once per record, resolves the active value, and attaches it as a
LogRecordattribute that the formatter consumes with a%(trace_id)splaceholder. Attach the filter to the handler, not to one logger, so records emitted by third-party libraries through the same handler are tagged too. -
Reset on teardown. Reset the variable in a
finallyblock so its value never survives into the next request the worker handles.
The header precedence in step two is deliberate. An explicit X-Trace-ID lets an upstream proxy or test harness pin a known value; the W3C traceparent carries the trace ID propagated by an instrumented caller, sitting in the second hyphen-delimited segment of a 00-<trace-id>-<span-id>-<flags> string; and the UUID fallback guarantees that even an uninstrumented client produces a correlatable request. Preserving an inbound trace ID rather than minting a fresh one is what keeps a single logical operation stitched together as it crosses service boundaries - the same rule that governs context propagation and baggage on the tracing side, applied here to logs.
The middleware seeds and resets the context:
import contextvars
import uuid
from starlette.middleware.base import BaseHTTPMiddleware
from starlette.requests import Request
from starlette.responses import Response
# Declared once, at import time — every module shares this one slot.
trace_id_ctx: contextvars.ContextVar[str | None] = contextvars.ContextVar(
"trace_id", default=None
)
class TraceMiddleware(BaseHTTPMiddleware):
async def dispatch(self, request: Request, call_next) -> Response:
# Prefer explicit header, then traceparent's trace-id, then generate.
traceparent = request.headers.get("traceparent", "")
parts = traceparent.split("-") # 00-<trace-id>-<span-id>-<flags>
inbound = request.headers.get("X-Trace-ID") or (
parts[1] if len(parts) > 1 else None
)
token = trace_id_ctx.set(inbound or uuid.uuid4().hex) # keep the token
try:
return await call_next(request)
finally:
trace_id_ctx.reset(token) # runs on success or exception
Expected behaviour: every request resolves trace_id_ctx to a 32-character W3C trace ID or a generated UUID hex, and teardown unconditionally restores the previous value so no identifier bleeds into the next request.
The reset matters most under connection reuse: a keep-alive worker that skips it starts the next request with the previous request's trace ID still active, and the leak is invisible until two unrelated requests share an ID in your dashboards. Because reset restores the exact prior state rather than clearing the slot, nesting is safe - an inner scope that overrides the trace ID for a sub-operation returns the outer request's value on exit.
The filter stamps that value onto every record, with a fallback for code that runs outside a request:
import logging
# trace_id_ctx is imported from the module above.
class TraceFilter(logging.Filter):
def filter(self, record: logging.LogRecord) -> bool:
# Resolved per record, so it reflects the coroutine actually emitting.
record.trace_id = trace_id_ctx.get() or "no-trace"
return True # never drop the record
logger = logging.getLogger("app")
logger.setLevel(logging.INFO)
_handler = logging.StreamHandler()
_handler.setFormatter(logging.Formatter("[%(trace_id)s] %(message)s"))
_handler.addFilter(TraceFilter()) # on the handler, not the logger
logger.addHandler(_handler)
logger.info("processing step")
Expected Output:
[no-trace] processing step
Inside a request the same line would read [4bf92f3577b34da6a3ce929d0e0e4736] processing step. The no-trace fallback fires only for code emitting outside any request scope, which makes orphaned log lines easy to spot. Attaching the filter to the handler rather than to the app logger is what extends the tag to library records - a database driver or HTTP client logging through the same handler is stamped with the same trace ID, which is exactly what you want when reconstructing a request from mixed sources. The formatter above is deliberately minimal; in production the field belongs in a JSON payload, following the conventions in structured logging with the standard library, and the whole handler/filter wiring can be declared as data via configuring logging with dictConfig.
Coroutines spawned during the request inherit the value with no extra work, because asyncio copies the context when it creates a task:
import asyncio
import logging
# trace_id_ctx and the configured logger from above.
async def worker() -> None:
logging.getLogger("app").info("inside spawned task")
async def main() -> None:
trace_id_ctx.set("req-abc-123")
await asyncio.create_task(worker()) # task inherits the context snapshot
if __name__ == "__main__":
asyncio.run(main())
Expected Output:
[req-abc-123] inside spawned task
The copy is one-directional and shallow: the child task sees the parent's values at creation time, but a set() inside the task is invisible to the parent, and a value set in the parent after the task was created never reaches it. Seed the trace ID before you fan out, never after.
Crossing thread, executor, and process boundaries
The automatic copy is a property of asyncio.Task creation, not of concurrency in general, so every other boundary needs an explicit decision.
A raw ThreadPoolExecutor.submit or loop.run_in_executor runs the callable under whatever context the worker thread already had - usually empty - so the trace ID silently becomes no-trace. There are two correct fixes. asyncio.to_thread copies the caller's context for you and is the right default in async code. When you are outside a loop, or need the same snapshot for several submissions, take it yourself:
import contextvars
from concurrent.futures import ThreadPoolExecutor
def blocking_work() -> str | None:
return trace_id_ctx.get() # reads the snapshot, not the thread's own context
def offload(pool: ThreadPoolExecutor) -> str | None:
ctx = contextvars.copy_context() # snapshot taken in the calling context
return pool.submit(ctx.run, blocking_work).result()
Expected Output: offload returns the caller's trace ID; replacing ctx.run with a bare pool.submit(blocking_work) returns None, which the filter then renders as no-trace.
Generators and async generators capture context at the point they are resumed, not where they were defined, so a generator built inside one request and consumed inside another logs under the consumer's trace ID. Materialise the values, or bind the ID explicitly into the payload, before handing a generator across a request boundary.
Processes inherit nothing at all: neither fork nor spawn keeps a live link to the parent's context, so the identifier has to travel as an argument and be re-established in the child, as covered in thread-safe logging in multiprocessing. The same reasoning applies to background workers - schedulers, queue consumers, retry loops - which have no request to inherit from and should set their own trace ID at the start of each unit of work and reset it when that unit finishes. Relying on the no-trace default there produces a stream of uncorrelatable log lines exactly when an incident makes correlation most valuable.
For synchronous WSGI servers the principle holds but the finally lives in different machinery: wrap the application callable so the set happens before dispatch and the reset happens in a finally around the response iterator, or register a teardown callback the framework guarantees to run before the worker returns to the pool.
Configuration options
| Decision | Option | Recommended | Reason |
|---|---|---|---|
| Default value | None vs sentinel string |
None |
Lets the filter detect a miss and substitute a fallback |
| Identifier source | header vs generated | header first, UUID fallback | Preserves an upstream trace, never leaves a request untagged |
| Read site | filter vs formatter | filter | Decouples context resolution from output format, reusable across handlers |
| Filter attachment | logger vs handler | handler | Tags third-party records that share the handler, not just your own |
| Reset site | finally vs none |
finally |
Guarantees reset on exception, prevents cross-request bleed |
| Thread pool | raw submit vs copy_context() |
copy_context() or asyncio.to_thread |
Thread pools do not inherit the caller's context |
Verification
Confirm propagation with a test that asserts a spawned task observes the parent's trace ID and that teardown clears it:
import asyncio
import contextvars
trace_id_ctx: contextvars.ContextVar[str | None] = contextvars.ContextVar(
"trace_id", default=None
)
async def child() -> str | None:
return trace_id_ctx.get()
async def main() -> None:
token = trace_id_ctx.set("req-abc-123")
try:
seen = await asyncio.create_task(child())
assert seen == "req-abc-123", seen # inheritance across task creation
finally:
trace_id_ctx.reset(token)
assert trace_id_ctx.get() is None # teardown restored the default
print("propagation OK")
if __name__ == "__main__":
asyncio.run(main())
Expected Output:
propagation OK
Run the mirror-image assertion for offloaded work: a ThreadPoolExecutor task must read the caller's value after an explicit copy_context() and must read None without one. Asserting both directions is what stops the test from passing for the wrong reason on a single-worker pool that happened to reuse the calling thread.
no-trace record emitted inside a request names both the bug and the boundary that caused it.A cheap continuous check is to assert in CI that no log line escapes with the no-trace sentinel during a request-path test. Pipe the structured output through a parser and fail the test if any record produced inside a simulated request carries the fallback value. Because the fallback only appears outside request scope, its presence inside one is a precise signal that a boundary was crossed without propagation - a missing middleware, a thread pool without copy_context(), or a generator that captured context too early. Treating the sentinel as a test assertion rather than just a log convenience turns propagation bugs into build failures instead of incident-time surprises. The same trace ID should also appear on the trace side of your pipeline; if it does not, reconcile the mapping described in adding trace IDs to log records before trusting either signal.
Common mistakes
-
Error signature:
ValueError: <Token ...> was created in a different Context, raised from theresetcall. Root cause: the token was captured in one context and reset in another - typically aset()whose return value was discarded and reconstructed later, or aresetperformed after anawaitmoved execution into a different task. Remediation: capture the token in the same scope as thesetand reset it in that scope'sfinally; never pass a token across a task boundary, and never store one on a shared object. -
Error signature: trace IDs mismatch between concurrent requests, with one request's ID appearing on another's log lines. Root cause: request state was stored in
threading.local(), which has one slot per OS thread whileasynciomultiplexes many requests onto a single thread. Remediation: replace everythreading.local()in the request path with aContextVar; the read cost is comparable and correctness under a shared event loop is restored. -
Error signature: log lines from the first few requests after a restart look fine, then every subsequent request logs under a stale identifier. Root cause: the middleware set the variable but skipped the reset, so a keep-alive worker began the next request with the previous request's value still active. Remediation: wrap the mutation in
try/finallyin the middleware itself, and add the teardown assertion from the verification section so the leak fails a test rather than a dashboard. -
Error signature: records emitted from a
run_in_executorcall, or from a blocking database driver, carry theno-tracesentinel while the surrounding request is tagged correctly. Root cause: the executor boundary was crossed without a context snapshot. Remediation: switch toasyncio.to_thread, or submitctx.runfrom acontextvars.copy_context()snapshot as shown above. If the offloaded work is only slow because of logging I/O, moving the handler behind non-blocking logging with QueueHandler removes the need to offload it at all.
Related
- Context variables and thread safety — the parent reference on request-scoped state, token lifecycle, and logging's own locks.
- Thread-safe logging in multiprocessing — what to do once the identifier has to cross a process boundary that context cannot.
- Adding trace IDs to log records — the filter and formatter side of correlation, including OpenTelemetry-sourced IDs.
- Structured logging with the standard library — emitting the tagged record as machine-parseable JSON.
- Binding context variables in structlog — the same propagation model with structlog's contextvars helpers instead of a hand-written filter.
Frequently Asked Questions
Does contextvars work with ThreadPoolExecutor?
Yes, but not automatically. Asyncio copies context for tasks it creates, but a thread pool does not. Snapshot the active context with copy_context() and run the offloaded callable through ctx.run() so the worker thread reads the caller's trace ID.
How do I handle a missing trace ID in a background task?
Give the ContextVar a None default and have the logging filter substitute a deterministic fallback such as a generated UUID when it reads None. Background workers that start outside any request should set their own trace ID at task entry rather than inheriting one.
Is there performance overhead compared with threading.local?
It is negligible for reads. A ContextVar get() is an O(1) lookup against an immutable mapping and adds well under a microsecond, with no GIL-contention penalty. The set() call is the costlier operation, so set once per request rather than per log line.
Should I read the trace ID in the formatter or in a filter?
Use a filter. The filter runs once per record and attaches the value as a LogRecord attribute that the formatter string then consumes with a placeholder. Reading context directly in the formatter couples context resolution to output formatting and breaks reuse across handlers.