Correlating Logs, Traces and Errors in FastAPI

Key takeaways:

  • One id, set once in middleware, read by the log filter, the span attributes and the error reporter.
  • contextvars survive await and are copied into asyncio.create_task — propagation across async code is automatic.
  • Starlette's run_in_threadpool copies the context into the worker thread; a bare executor submit does not.
  • Context flows into threads, never back out. A set() inside a thread is discarded.
  • Return the id to the client in a response header so a support ticket carries the key to your logs.

An alert fires, you open the error report, and you have a stack trace with no way to find the log lines that led to it or the trace that shows which downstream call was slow. This page — part of Observability and Tracing — is about making those three views join, and about the exact places where the id stops propagating.

One request id shared by logs, traces and error reports A contextvar set by middleware feeds the log filter, the span attributes and the error reporter, while a raw thread pool hop is shown losing the value. middleware sets ctxvar request_id = req-1 log filter every record tagged span attributes trace carries the id error reporter tagged at capture run_in_threadpool context copied: id kept run_in_executor fresh context: id lost
The same contextvar feeds all three views; the bottom row is where propagation depends on how the thread was started.

The Mechanism

A ContextVar is not thread-local storage and it is not a global. Python maintains a current Context — a mapping of context variables to values — and every coroutine runs in one. When you await, the same context stays current, which is why a value set at the top of a handler is visible in a helper five awaits deep without threading it through any signatures.

When asyncio.create_task schedules a coroutine, it calls contextvars.copy_context() and runs the task in that copy. The task inherits everything set at creation time, and anything it sets afterwards is invisible to the parent. This is exactly the behaviour you want for a request id: children inherit, siblings do not interfere, and a task that overwrites a span id cannot corrupt the caller's.

Threads are the boundary. A thread starts with an empty context unless something explicitly copies one into it. Starlette's run_in_threadpool — which is what FastAPI uses for every def (non-async) endpoint and dependency — goes through anyio's to_thread.run_sync, which propagates the caller's context. loop.run_in_executor and threading.Thread do not.

Proving Where It Survives

The example wires one contextvar for the request id and one for the current span, a logging filter that injects both into every record, and a handler that deliberately crosses each boundary.

import asyncio
import json
import logging
from concurrent.futures import ThreadPoolExecutor
from contextvars import ContextVar

from fastapi import FastAPI, Request
from starlette.concurrency import run_in_threadpool

request_id_ctx: ContextVar[str] = ContextVar("request_id", default="-")
span_ctx: ContextVar[str] = ContextVar("span_id", default="-")


class ContextFilter(logging.Filter):
    def filter(self, record: logging.LogRecord) -> bool:
        record.request_id = request_id_ctx.get()
        record.span_id = span_ctx.get()
        return True


class JsonFormatter(logging.Formatter):
    def format(self, record: logging.LogRecord) -> str:
        return json.dumps(
            {
                "level": record.levelname,
                "logger": record.name,
                "request_id": getattr(record, "request_id", "-"),
                "span_id": getattr(record, "span_id", "-"),
                "message": record.getMessage(),
            }
        )

The middleware sets both values and — importantly — resets them in a finally, then echoes the id back to the caller:

@app.middleware("http")
async def correlate(request: Request, call_next):
    # Production: `or f"req-{uuid.uuid4().hex[:8]}"`. A counter keeps this transcript stable.
    COUNTER["n"] += 1
    rid = request.headers.get("x-request-id") or f"req-{COUNTER['n']}"
    token = request_id_ctx.set(rid)
    span_token = span_ctx.set("span-http")
    try:
        response = await call_next(request)
        response.headers["x-request-id"] = rid   # Give the caller the id to quote in a ticket.
        return response
    finally:
        span_ctx.reset(span_token)
        request_id_ctx.reset(token)

The error reporter reads the same variables at capture time, which is what makes an error event joinable to the logs:

def capture_error(exc: Exception) -> None:
    """Stand-in for Sentry: attach the same id the logs and spans carry."""
    ERROR_REPORTS.append(
        {
            "error": f"{type(exc).__name__}: {exc}",
            "request_id": request_id_ctx.get(),
            "span_id": span_ctx.get(),
        }
    )

And the handler crosses every boundary in one request — a nested await, a child task, a Starlette threadpool call and a raw executor submit:

@app.get("/profile/{user_id}")
async def profile(user_id: str) -> dict[str, object]:
    log.info("handling profile request")
    profile_data = await load_profile(user_id)
    # asyncio tasks copy the current context at creation time, so the id follows them.
    child = asyncio.create_task(load_profile(user_id + "-related"))
    await child
    # Starlette's run_in_threadpool copies the context into the worker thread.
    via_starlette = await run_in_threadpool(render_report, user_id)
    # A bare executor submit does NOT: the callable starts with a fresh, empty context.
    loop = asyncio.get_running_loop()
    via_raw_executor = await loop.run_in_executor(POOL, render_report, user_id)
    return {"profile": profile_data, "reports": [via_starlette, via_raw_executor]}

This is the real log sequence that request produced, followed by a second request that failed and was reported:

$ GET /logs
200 OK
{
  "log_lines": [
    {
      "level": "INFO",
      "logger": "app",
      "request_id": "req-1",
      "span_id": "span-http",
      "message": "handling profile request"
    },
    {
      "level": "INFO",
      "logger": "app",
      "request_id": "req-1",
      "span_id": "span-db",
      "message": "SELECT profile user_id=u-42"
    },
    {
      "level": "INFO",
      "logger": "app",
      "request_id": "req-1",
      "span_id": "span-db",
      "message": "SELECT profile user_id=u-42-related"
    },
    {
      "level": "INFO",
      "logger": "app",
      "request_id": "req-1",
      "span_id": "span-http",
      "message": "rendering report for u-42"
    },
    {
      "level": "INFO",
      "logger": "app",
      "request_id": "-",
      "span_id": "-",
      "message": "rendering report for u-42"
    },
    {
      "level": "ERROR",
      "logger": "app",
      "request_id": "req-2",
      "span_id": "span-http",
      "message": "request failed"
    }
  ],
  "errors": [
    {
      "error": "ValueError: downstream billing service returned 502",
      "request_id": "req-2",
      "span_id": "span-http"
    }
  ]
}

Every line of that sequence is worth reading closely.

Lines one to four all carry req-1. The nested await kept it. The asyncio.create_task child kept it, and it also carried the span-db value the child set for itself — while line four, back in the handler, is span-http again, because the child's set() happened in its own copy of the context. The run_in_threadpool call kept the id too, which is the behaviour that makes correlation work automatically for synchronous endpoints and dependencies.

Line five is the failure. Identical function, identical log call, dispatched through loop.run_in_executor — and both fields are -. There is nothing in that log line to tie it to the request that caused it. In a real system this is the log entry you find during an incident, containing exactly the message you needed and none of the context required to use it.

Line six comes from the second request and carries req-2, matching the error report captured underneath. That match is the payoff: the error event and the log lines share a key, so one click goes from the exception to the request's full log context.

Fixing the Threadpool Hop

Three options, in order of preference.

Use run_in_threadpool. If you are offloading blocking work from an async endpoint, this is the right primitive anyway — it uses the same limiter as FastAPI's own sync-endpoint dispatch, so your offloaded work is subject to the same concurrency bound. Context propagation comes free. The concurrency implications are covered in running sync code in a threadpool.

Copy the context explicitly. When you must use a specific executor — a dedicated pool for CPU-bound work, say — copy the context and run the callable inside it:

import contextvars
import functools

ctx = contextvars.copy_context()
result = await loop.run_in_executor(POOL, functools.partial(ctx.run, render_report, user_id))

Pass the id as an argument. Unavoidable when the boundary is a process rather than a thread, and the only option for background jobs. A Celery or ARQ worker is a different process with a different context; the id must travel in the job payload and be re-set at the top of the worker function. That is the same discipline described in retry and idempotency for tasks — and it is why a background task failure often has no request id unless you deliberately forwarded one.

Joining to Traces

If you are running OpenTelemetry, the span context already carries a trace id and a span id, and the cheapest correlation is to put them on every log record:

from opentelemetry import trace


class TraceFilter(logging.Filter):
    def filter(self, record: logging.LogRecord) -> bool:
        span = trace.get_current_span()
        ctx = span.get_span_context()
        record.trace_id = format(ctx.trace_id, "032x") if ctx.is_valid else "-"
        record.span_id = format(ctx.span_id, "016x") if ctx.is_valid else "-"
        return True

OpenTelemetry propagates its span context through the same contextvars machinery, so everything above applies unchanged — including the threadpool caveat. Setting the request id as a span attribute (span.set_attribute("request.id", rid)) closes the loop in the other direction, letting you find the trace from a log line. The instrumentation itself is covered in instrumenting FastAPI with OpenTelemetry, and the formatter and filter plumbing in structured JSON logging with request IDs.

Verification

The test that matters asserts propagation across the boundary you actually cross:

def test_request_id_reaches_threadpool_code(client, caplog):
    client.get("/profile/u-42", headers={"x-request-id": "rid-7"})
    ids = {getattr(record, "request_id", None) for record in caplog.records}
    assert ids == {"rid-7"}          # No record escaped without the id.


def test_response_echoes_the_id(client):
    response = client.get("/profile/u-42", headers={"x-request-id": "rid-7"})
    assert response.headers["x-request-id"] == "rid-7"

The first assertion is deliberately strict: comparing the set of ids to a single value catches the - records that a lost context produces, which an assert "rid-7" in ids would not. In production the equivalent check is a dashboard panel counting log lines where request_id is empty. That number should be zero, and when it is not, it points straight at a code path that crossed a boundary without carrying context.

Trade-offs and When Not To

Resetting the contextvar in a finally is not optional. Skip it and the value survives into whatever the worker handles next, so a request with no id inherits the previous one's — worse than no correlation, because it is confidently wrong. The Token returned by set() exists for exactly this.

Do not put large objects in contextvars. They are cheap to read and they keep whatever you store alive for the lifetime of the context, so a request body or an ORM object parked there is a memory leak that scales with concurrency. Store the id and look everything else up.

And accept that correlation ids are not free at scale: they add a field to every log line and a tag to every error event. That cost is trivial next to the alternative, which is an incident spent grepping timestamps.

FAQ

Do contextvars survive an await? Yes. A coroutine runs in the context that was current when it was scheduled, so a value set before an await is still readable after it. asyncio.create_task copies the context at creation time, so tasks inherit the values that existed at that moment.

Why does my request id disappear inside a threadpool call? It depends on how the thread was started. Starlette's run_in_threadpool copies the current context into the worker thread, so the id survives. A bare loop.run_in_executor or a raw threading.Thread starts with an empty context and the id is gone.

Can a background thread write back to a contextvar the request can read? No. The thread gets a copy of the context, so any set() it performs applies to that copy and is discarded when the callable returns. Values flow in, never out; return the value instead.

Should the request id be the same as the trace id? They can be, and using the trace id as the correlation id removes a mapping step. Keep a separate header when clients or a gateway generate their own id, and log both fields so either one finds the request.

How do I correlate an error report with the logs around it? Attach the request id as a tag on the error event at capture time, reading it from the same contextvar the log filter uses. The error report then links to a log query, and both link to the trace.