Trace context in async Python

Article.

Tracing is instrumented once and then breaks silently. A request produces four spans instead of eleven, a Celery task shows up as its own orphan trace, and the logs from a thread pool carry trace_id as thirty-two zeros.

None of that is a bug in OpenTelemetry. It is one mechanism — contextvars — behaving exactly as documented at boundaries people do not think of as boundaries. Learn the copy rule and every one of these becomes predictable.

The mechanism: context is copied, never shared

A ContextVar is not a global. It reads from the current context, and asyncio gives each Task its own.

import asyncio, contextvars

trace_id = contextvars.ContextVar("trace_id", default=None)

async def child():
    print("child sees:", trace_id.get())    # abc
    trace_id.set("changed-by-child")

async def parent():
    trace_id.set("abc")
    await asyncio.create_task(child())
    print("parent sees:", trace_id.get())   # abc  <- NOT changed-by-child

Two rules, and they explain everything below:

1. A new Task gets a copy of the spawning context. Values flow down.
2. Writes in the child are invisible to the parent. Nothing flows up.

Awaiting is not spawning

The distinction that catches people, because both use await:

await child()                     # SAME context; child's set() is visible here
await asyncio.create_task(child())  # COPY; child's set() is not
await asyncio.gather(a(), b())      # gather wraps each in a Task -> copies

await coro() runs the coroutine inline in the caller’s context. create_task and gather create Tasks, so each gets its own snapshot. Setting a context value inside a gather branch and expecting to read it afterwards is the commonest version of this mistake.

Where the context does not go at all

The last row is the one that matters most: no in-process mechanism crosses a broker or an HTTP call. Context must be serialised into the message and restored on the other side, which is what traceparent is for.

Binding it at the edge

Pure ASGI, not BaseHTTPMiddleware

import uuid, contextvars
from starlette.types import ASGIApp, Scope, Receive, Send

trace_id = contextvars.ContextVar("trace_id", default=None)

class TraceIDMiddleware:
    """Pure ASGI: runs in the SAME task as the app, so no copy boundary."""

    def __init__(self, app: ASGIApp) -> None:
        self.app = app

    async def __call__(self, scope: Scope, receive: Receive, send: Send) -> None:
        if scope["type"] != "http":
            return await self.app(scope, receive, send)

        headers = dict(scope["headers"])
        tid = headers.get(b"x-trace-id", b"").decode() or str(uuid.uuid4())
        token = trace_id.set(tid)

        async def send_with_header(message):
            if message["type"] == "http.response.start":
                message.setdefault("headers", []).append((b"x-trace-id", tid.encode()))
            await send(message)

        try:
            await self.app(scope, receive, send_with_header)
        finally:
            trace_id.reset(token)

Why the base class loses values

Pure ASGI middleware rather than BaseHTTPMiddleware is a deliberate choice. BaseHTTPMiddleware runs the downstream app in a separate task, so values it sets before call_next propagate down fine — but anything the application sets is invisible when control returns. Middleware that tries to read a value the handler set (a resolved tenant, a user id, an enriched request id) gets None, and the reason is not in that middleware’s code.

The reset(token) in the finally is hygiene rather than strict necessity — each request is its own task with its own context — but it keeps the invariant true if the middleware is ever reused inside one task.

Getting it into every log line

Correlation is only worth the wiring if it is automatic. With structlog, one processor does it:

import structlog

def add_trace_id(logger, method_name, event_dict):
    tid = trace_id.get()
    if tid:
        event_dict["trace_id"] = tid
    return event_dict

structlog.configure(
    processors=[
        add_trace_id,
        structlog.processors.add_log_level,
        structlog.processors.TimeStamper(fmt="iso"),
        structlog.processors.JSONRenderer(),
    ],
)

log = structlog.get_logger()
log.info("charging", amount=99.99)
# {"event": "charging", "amount": 99.99, "trace_id": "abc-123", ...}

No call site changes, and the field is present or the binding is broken — which makes a missing trace_id a usable signal rather than an oversight.

Crossing a process boundary

The context has to travel in the message. For Celery, signals do it once for every task rather than task by task:

from celery.signals import before_task_publish, task_prerun

@before_task_publish.connect
def inject(headers=None, **kwargs):
    tid = trace_id.get()
    if tid:
        headers["trace_id"] = tid          # rides in the message headers

@task_prerun.connect
def restore(task_id, task, **kwargs):
    tid = (task.request.headers or {}).get("trace_id")
    if tid:
        trace_id.set(tid)

For Kafka the same shape applies with message headers, and for outbound HTTP a custom httpx transport injects the header on every request rather than at each call site.

Or let OpenTelemetry do it

If you are already running OpenTelemetry, do none of this. The Celery, Kafka and httpx instrumentations propagate W3C traceparent for you, and the OTel trace id is available anywhere:

from opentelemetry import trace

def current_trace_id() -> str | None:
    ctx = trace.get_current_span().get_span_context()
    return f"{ctx.trace_id:032x}" if ctx.is_valid else None

See OpenTelemetry for the propagation API. Note that OTel does not change the copy rules above — its context rides in the same contextvars machinery, so it breaks at exactly the same thread and task boundaries.

Where it breaks in production

Thirty-two zeros in the logs

The most diagnostic symptom there is:

{"event": "charge failed", "trace_id": "00000000000000000000000000000000"}

That is OTel’s invalid span context. It does not mean tracing is misconfigured — it means there was no active span at that exact line. The span ended earlier, or the code is running in a task or thread that never received the context. The zeros tell you where the chain broke, which is more than a missing field would.

The thread pool

# Loses context: the worker thread starts with an empty one.
result = await loop.run_in_executor(None, sync_function)

# Carries it: snapshot the context and run inside it.
ctx = contextvars.copy_context()
result = await loop.run_in_executor(None, ctx.run, sync_function)

# Or simply, since 3.9 — to_thread does the copy for you.
result = await asyncio.to_thread(sync_function)

asyncio.to_thread propagates context; raw run_in_executor does not. Any sync library wrapped in an executor — a blocking DB driver, an image transform — drops the trace unless you bridge it, and the logs from that call are the ones you most want when it is slow.

The task nobody awaited

asyncio.create_task(send_receipt(order))   # fire and forget
return {"ok": True}

The task copies the context at creation, so this one actually works. It breaks the other way round: a task spawned at startup — a background poller, a consumer loop — was created before any request existed, so it has an empty context forever, and every log line from it is uncorrelated. Those tasks need to start their own trace per unit of work, not inherit one.

Two ids that disagree

A hand-rolled x-trace-id and OTel’s traceparent both flowing, and they identify different things: the custom one spans the user’s whole session, the OTel one restarts per hop. Now a log line has two ids and neither reliably finds the trace.

Pick one. If OTel is in the stack, its trace id is the correlation id and a custom one is duplicated work with an extra failure mode. A separate id earns its place only for something OTel’s genuinely is not — a session or a business transaction spanning many traces — and then it should be named for that.

Sampling that drops half a trace

The trace is intact and still looks broken, because each service sampled independently and the middle hop was not kept. ParentBased samplers exist precisely for this — see Sampling Strategies for Tracing.

BaseHTTPMiddleware reading what the app set

Covered above, and worth repeating because the failure is so quiet: the value is None, no exception is raised, and the middleware’s own code is correct. If a middleware needs something the handler computed, put it on request.state/scope rather than a context variable, or make the middleware pure ASGI.

The trade not taken

The honest alternative is to pass it explicitly — a trace_id parameter threaded through every function that logs.

It is uglier and it is unbreakable. There is no copy semantics to reason about, no boundary that silently drops it, and the type checker tells you when a call site forgot. For a small service, or for a critical path where a lost trace means a lost incident, that is a defensible choice and it is worth saying so rather than treating implicit context as obviously right.

contextvars wins on reach, not on correctness: it gets the id into the third-party library’s log adapter, the ORM’s event hook and the exception handler, none of which will accept your extra argument. That reach is the whole value — and the price is exactly the boundary rules above, which is a fair trade only once you know them.

What to correlate

Stack them all in the log line. trace_id is the one that bridges processes; the others narrow a search once you are in the right trace.

Related

• OpenTelemetry - the propagation API and semantic conventions
• Structured logging in Python - the log side of the correlation
• run_in_executor and asyncio.to_thread - the executor boundary in depth