Your Async Logs Are Lying to You: Correlation IDs with Contextvars

The Three Logs That Never Connected

An order fails at 14:02. The support ticket quotes a customer who saw a payment error, then a retry, then another error. Three log lines carry the same timestamp window, and none of them agree on what happened.

The payment service logged payment.authorized at 14:02:11. The order service logged order.failed at 14:02:11. The worker that was supposed to reconcile them logged worker.idle at 14:02:12. Three services, three log streams, three different stories. Somewhere between those lines a state change was lost, and nobody can say where, because nothing in the logs connects them.

This is the classic symptom of a system where every log line is locally true and globally useless. The fix is a correlation ID: one opaque string that travels with every request, crosses every service boundary, and gets stamped onto every log line it touches. In synchronous code this is a solved problem — a header, a middleware, done. In async Python, the interesting part is that the mechanism you reach for first is quietly wrong, and the one that works is hiding in a corner of the standard library most people have never imported.

Why Thread-Local State Breaks in Async Code

The instinctive move is threading.local(). One thread, one request, one context — that is the mental model that made thread-local storage popular, and it is exactly the model that async code violates.

An asyncio event loop runs thousands of tasks on one thread. The thread does not change when the application switches from handling request A to handling request B; the task does. threading.local() keys its storage on the thread identity, so every task on the same thread reads and writes the same slot. Request A sets request_id = "a1", awaits I/O, and while it is suspended, request B sets request_id = "b2". When A resumes and logs its next line, the filter reads request_id and stamps the line with "b2".

import threading

local = threading.local()

async def handle(request_id: str) -> None:
    local.request_id = request_id
    await some_io()          # loop switches to another task here
    print(local.request_id)  # may already be a different request's ID

The result is not a missing ID. It is worse: a wrong ID. Log lines get stamped with the neighbor's request, and the timeline you are trying to reconstruct becomes actively misleading. This is the "locally true, globally useless" failure in its purest form, and it is why the standard advice for async code is to stop storing context in places the runtime can swap underneath you.

Contextvars: State That Travels With the Task

contextvars exists to fix precisely this. A context variable holds one value per execution context, and an asyncio task carries its own context. When the loop suspends one task and resumes another, each task sees its own copy of every context variable, with no shared slot and no cross-talk.

import contextvars

request_id: contextvars.ContextVar[str] = contextvars.ContextVar("request_id", default="")

async def handle(request_id_value: str) -> None:
    request_id.set(request_id_value)
    await some_io()            # loop can switch tasks freely
    print(request_id.get())    # still "a1" for this task

Two properties make this safe. First, assignment inside a task is visible only to that task and to whatever it awaits; sibling tasks never observe it. Second, when the task finishes, its context is discarded, so there is no leak into the next request. The value follows the logical unit of work, not the thread — which is precisely the semantics a correlation ID needs.

There is a cost worth naming: contextvars is not free. Setting and reading a context variable involves dictionary lookups in the current context, and every await can trigger context bookkeeping. In a logging hot path the cost is negligible next to the I/O you are already doing, but if you were planning to use a context variable inside a tight numerical loop, measure first.

A Correlation ID Middleware in Thirty Lines

The middleware has three jobs: accept the ID from upstream if one exists, generate a fresh one if it does not, and make sure the response carries it back so the caller can attach it to their own logs. With contextvars the implementation is short enough to read in one pass.

import contextvars
import uuid
from starlette.middleware.base import BaseHTTPMiddleware

request_id_var: contextvars.ContextVar[str] = contextvars.ContextVar("request_id", default="")

class CorrelationMiddleware(BaseHTTPMiddleware):
    async def dispatch(self, request, call_next):
        incoming = request.headers.get("X-Request-ID", "").strip()
        rid = incoming or uuid.uuid4().hex[:16]
        request_id_var.set(rid)
        response = await call_next(request)
        response.headers["X-Request-ID"] = rid
        return response

The same shape ports to aiohttp middlewares, FastAPI dependencies, and raw asyncio server handlers. The important part is not the framework hook — it is that the ID lives in request_id_var, so every downstream function that awaits inside this request can read it without threading a parameter through a dozen call sites.

This matters more than it looks. The alternative — passing the ID as an explicit argument to every function that logs — turns every signature into a carrier for plumbing. Adding a field to a dataclass, a parameter to a helper, or an argument to a third-party callback all become breaking changes. The context variable keeps the data flow implicit, and the call sites stay honest: a function logs what it needs because the context is already there.

The Context Copy Trap: Threads and Executors

Here is the corner that catches most implementations: asyncio.create_task() copies the current context, but work dispatched to a thread pool executor does not inherit it.

A task that calls loop.run_in_executor(None, blocking_call) hands blocking_call to a worker thread. That thread runs with the default context, in which request_id is still the empty default. The correlation ID silently vanishes exactly at the boundary where you most need it — the slow, blocking call that takes real seconds and logs real failures.

import asyncio
import contextvars

request_id: contextvars.ContextVar[str] = contextvars.ContextVar("request_id", default="")

def blocking_call() -> None:
    print(request_id.get())  # "" — the executor thread has the default context

async def handle(rid: str) -> None:
    request_id.set(rid)
    await asyncio.get_running_loop().run_in_executor(None, blocking_call)

asyncio.run(handle("a1"))

The fix is to propagate the context explicitly. Python 3.11 added asyncio.to_thread(), which copies the caller's context before dispatching — the one-liner replacement that makes the ID survive the boundary:

async def handle(rid: str) -> None:
    request_id.set(rid)
    await asyncio.to_thread(blocking_call)  # context is copied automatically

For code that must stay on run_in_executor, copy the context by hand and run the callable inside it:

ctx = contextvars.copy_context()
await loop.run_in_executor(None, lambda: ctx.run(blocking_call))

Pick one rule and apply it everywhere: prefer asyncio.to_thread, and audit every remaining run_in_executor for an explicit ctx.run. A correlation ID that dies in the first thread pool is worse than none, because the logs now look complete while silently missing the section of the timeline that actually matters.

A Logging Filter So Every Line Carries the ID

A middleware sets the variable, but the logs still need to read it. Python's logging.Filter runs against every record before it is emitted, which makes it the natural home for stamping:

import logging

class RequestIDFilter(logging.Filter):
    def filter(self, record: logging.LogRecord) -> bool:
        record.request_id = request_id_var.get() or "-"
        return True

handler = logging.StreamHandler()
handler.addFilter(RequestIDFilter())
logging.basicConfig(handlers=[handler], level=logging.INFO,
                    format="%(asctime)s %(request_id)s %(name)s %(message)s")

Every line — from application code, from library loggers, from warning paths — now carries the ID, because the filter does not care who created the record. One filter, attached to the root handler, covers code you wrote and code you did not.

This is the property that makes the three logs connect again. The payment line, the order line, and the worker line all carry the same X-Request-ID value, and the support ticket becomes a search: filter the aggregated stream by that one string and the entire timeline of the failed order is contiguous. The correlation ID does not make the logs truthful; it makes them sortable by truth.

Verifying the Timeline Comes Back

The implementation is not finished until the cross-talk regression is actually tested. Two tests cover the failure modes that matter: concurrent tasks must not share IDs, and executor work must inherit them.

import asyncio
import contextvars

def test_tasks_do_not_share_ids():
    seen: set[str] = set()

    async def worker(value: str) -> str:
        request_id.set(value)
        await asyncio.sleep(0)
        return request_id.get()

    async def main() -> None:
        results = await asyncio.gather(worker("a1"), worker("b2"))
        seen.update(results)

    asyncio.run(main())
    assert seen == {"a1", "b2"}  # no task saw its neighbor's ID

def test_executor_inherits_context():
    captured: list[str] = []

    def blocking() -> None:
        captured.append(request_id.get())

    async def main() -> None:
        request_id.set("a1")
        await asyncio.to_thread(blocking)

    asyncio.run(main())
    assert captured == ["a1"]

Run these under the CI job that runs your async tests. If either fails, the fix is one of the two patterns above — not a new configuration flag and not a global variable.

When Contextvars Are Not Enough

The context variable carries the ID through one process. The moment the request crosses a network boundary, the ID must ride in the wire protocol: an X-Request-ID header on HTTP, a traceparent header for OpenTelemetry, a message_id field on a queue. The middleware already propagates the header forward; the same header should be read from upstream and attached to outbound calls, so a chain of three services produces one searchable ID instead of three locally unique ones.

For systems that already run OpenTelemetry, the pragmatic move is to back the correlation ID with the trace context rather than reinventing it — read traceparent, store the trace ID in the context variable, and let the filter stamp it. The pattern does not change; the source of the string does.

And one honest limit: contextvars does not magically make logs from a crashed process appear. It closes the gap between log lines that were both written; it cannot resurrect the line that was never written because the process died mid-flush. For that you still need durable, buffered shipping. But for the ordinary failure — the one where every service logged something and nobody could connect the dots — the correlation ID is the difference between a timeline and a pile of timestamps.

---

Originally published on Dispatch.