Correlation IDs in FastAPI Logs

One async request scatters a dozen log lines through concurrent traffic. Thread a correlation ID through FastAPI with contextvars and trace it in OpenSearch.

An operator pings me: “the request I sent around 14:05 came back with a 500, can you check?” I open the logs, and there are forty other requests in that same second. My service logged a handler entry, three database calls, an outbound HTTP call to a model endpoint, and a stack trace, all interleaved with everyone else’s forty requests doing the same. Which log lines belong to their request? Without something tying them together, I’m reading tea leaves.

The fix is old, boring, and works. Give every incoming request a unique ID, attach it to every log line that request produces, and return it in the response so the caller can quote it back to you. This is a correlation ID (some shops call it a request ID or trace ID).

This post is for engineers running a FastAPI backend who want to pull one request’s story out of a busy log stream. I’ll show the middleware, the part that makes it work under async, the specific ways it breaks, and how it lands in OpenSearch, where I actually read these logs.

The running example is the kind of backend I worked on for Archi, the retrieval copilot for CMS computing operations at CERN, and the operator console in CMS workflow operations. Both are FastAPI services whose logs end up in OpenSearch, and both have had the “which lines are mine” problem.

Why the naive version doesn’t survive async

The instinct is to generate an ID at the top of the handler and pass it down as an argument:

@app.post("/answer")
async def answer(req: Query):
    request_id = uuid.uuid4().hex
    log.info("received query", extra={"request_id": request_id})
    docs = await retrieve(req.text, request_id)   # thread it through
    reply = await generate(docs, request_id)       # ...and again
    return {"answer": reply}

This works for exactly one function. The moment retrieve calls a repository, which calls an HTTP client, which logs a retry, you are either plumbing request_id through every function signature in the codebase or you have lost it. Threading a logging concern through your business logic looks fine in a demo and rots in a real service.

You might reach for a global variable instead. That is worse, and the reason is specific to how FastAPI runs. FastAPI is an ASGI app (ASGI is the Asynchronous Server Gateway Interface) served on an event loop, so many requests are in flight on the same thread, each suspended at its own await point. A plain global holds one value for the whole process, so request B overwrites request A’s ID while A is parked waiting on a database. threading.local doesn’t save you either, because all these requests share a thread. You need storage scoped to a single logical task: not to a thread, and not to the process.

contextvars: storage scoped to one request

Python’s answer is contextvars, added in 3.7 for exactly this problem. A ContextVar holds a value that is local to the current context, and asyncio gives every task its own copy of the context. If you set it inside one request’s task, a concurrent request’s task still sees its own value, not yours. The standard library uses the same mechanism to keep Decimal precision settings from leaking between tasks.

Declaring one takes a single line:

# context.py
from contextvars import ContextVar

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

The default="-" matters. Code that logs outside any request (startup, a background job) still has something to write, so your log formatter never blows up on a missing value.

Setting the ID in middleware

Set the ID once, at the edge, before anything else runs. In Starlette (which FastAPI is built on), that means middleware, a layer that wraps every request. I write it as pure ASGI rather than BaseHTTPMiddleware. That is partly habit, and partly because BaseHTTPMiddleware has a long history of surprising interactions with background tasks and streaming responses.

# middleware.py
import uuid
from starlette.types import ASGIApp, Receive, Scope, Send
from context import request_id_var

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

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

        headers = dict(scope["headers"])  # bytes keys and values
        incoming = headers.get(b"x-request-id")
        request_id = incoming.decode() if incoming else uuid.uuid4().hex
        token = request_id_var.set(request_id)

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

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

The middleware does three things:

  1. Adopt or mint the ID. If the client (or a load balancer, or an upstream service) already sent an X-Request-ID, adopt it so the ID spans service boundaries. Otherwise, mint a fresh one.
  2. Echo it in the response. Wrapping send puts the same ID in the response headers. That is what lets an operator read the ID off a failed response and hand it to you.
  3. Reset it afterwards. Calling reset on the contextvar in a finally block keeps the value from bleeding into whatever the worker handles next.

One caution on adopting the header: you are now trusting a client-supplied string. If it flows straight into logs and dashboards, cap its length and character set. A caller who puts a newline or a few kilobytes in X-Request-ID is either fuzzing you or injecting fake log lines. I whitelist to something like ^[A-Za-z0-9_-]{1,64}$ and fall back to a generated UUID when it doesn’t match. The OWASP log injection notes are the short version of why.

Getting the ID onto every log line

The middleware sets the value; now every log record has to read it. The clean way is a logging Filter, which, despite the name, is allowed to modify the record as it passes through. The filter below attaches the current request ID as an attribute, and the formatter references it as %(request_id)s:

# logging_setup.py
import logging
from pythonjsonlogger import jsonlogger
from context import request_id_var

class RequestIdFilter(logging.Filter):
    def filter(self, record: logging.LogRecord) -> bool:
        record.request_id = request_id_var.get()
        return True  # never actually drop the record

def configure_logging() -> None:
    handler = logging.StreamHandler()
    handler.addFilter(RequestIdFilter())
    handler.setFormatter(
        jsonlogger.JsonFormatter(
            "%(asctime)s %(levelname)s %(name)s %(request_id)s %(message)s"
        )
    )
    root = logging.getLogger()
    root.handlers = [handler]
    root.setLevel(logging.INFO)

I emit JSON here on purpose. Plain-text logs are readable at your terminal and miserable in a log store. OpenSearch and the Elastic stack both want structured fields, so you can filter on request_id instead of grepping a string out of a message blob. The python-json-logger formatter turns each record into one JSON object per line, and every key becomes a field you can query. A log line now looks like this:

{"asctime": "2026-09-23 14:05:02,113", "levelname": "INFO",
 "name": "archi.retrieve", "request_id": "9f2c1a7b4e",
 "message": "retrieved 8 candidates in 41ms"}

Every line that request produces, from any module, carries 9f2c1a7b4e. The diagram below is the whole story: the ID is set once at the edge, a contextvar carries it, and the filter stamps it onto records that nobody had to thread it through.

A left-to-right flow diagram. A client, which may send an X-Request-ID header, calls an ASGI middleware that adopts the header or mints a fresh UUID and sets a contextvar. The route handler runs business logic and forwards the ID on its downstream httpx call, and echoes the ID back in the response header. A logging filter reads the same contextvar and stamps every log record; those records serialize to JSON lines that land in OpenSearch, where you filter one request out by its request_id field.

Carry it across the network

Inside one service, the contextvar does the work. The ID earns its keep when it crosses into the next service, so forward it on outbound calls. With httpx, an event hook (a function the client runs on every request) stamps the header without touching any call sites:

import httpx
from context import request_id_var

async def _propagate(request: httpx.Request) -> None:
    request.headers["X-Request-ID"] = request_id_var.get()

client = httpx.AsyncClient(event_hooks={"request": [_propagate]})

The downstream service’s own middleware adopts that header instead of minting a new one, so the same ID now spans both services’ logs. You can chase one operator report across the retrieval service and the model gateway with a single filter.

Where it bites

The thread-pool boundary is the big one. contextvars propagate to tasks you await, but not automatically to code you push onto a thread pool. If a handler calls a blocking function via run_in_executor or starlette.concurrency.run_in_threadpool, the log lines from inside that function come out with the default -. (run_in_threadpool is what sync def route handlers and dependencies, as opposed to async def ones, use under the hood.) FastAPI’s own run_in_threadpool copies the context for you, so plain sync endpoints are fine; a bare loop.run_in_executor(pool, fn) is not.

The fix is to run the function inside a copy of the current context, using contextvars.copy_context():

import contextvars, functools

ctx = contextvars.copy_context()
await loop.run_in_executor(pool, functools.partial(ctx.run, blocking_fn))

I once lost an afternoon to logs from a sync database driver showing - while everything else in the same request had the real ID. This was why.

Uvicorn’s access log is a separate stream. The GET /answer 200 line comes from uvicorn.access, which never touches your contextvar. It won’t carry the ID unless you attach your filter and formatter to that logger too. It is easy to forget, and then half your “request done” lines are the ones missing the ID.

Background tasks outlive the request. A Starlette BackgroundTask runs after the response is sent, and depending on how you scheduled it, the contextvar may already be reset. To log the background work under the same ID, capture the value in a local variable while you are still inside the request and pass that in, rather than reading the contextvar from inside the task.

IDs are for correlation, not counting. A uuid4 is random, so treat it as an opaque label: don’t parse it, don’t assume it’s globally unique forever, and don’t build logic on it. It exists to answer “show me this one request”, nothing more.

This is not distributed tracing

A correlation ID and a distributed trace solve overlapping problems, so it is worth being clear where the line is. The ID gives you a flat filter: every log line for one request, in one query. It does not give you the shape of the request: which call was slow, what nested inside what, where the 300ms went. That is what spans (the timed, nested units of work in a trace) are for. I wrote a separate post on tracing an LLM pipeline with OpenTelemetry that covers the heavier machinery.

The honest tradeoff: a correlation ID is a couple of dozen lines of code and zero new infrastructure, and on its own it answers 80% of “what happened to this request” questions. Full tracing needs a collector, a backend, and instrumentation on every hop. It earns that cost once you are debugging latency across several services, rather than reconstructing one request’s log story.

If you already run OpenTelemetry, reuse the trace context trace_id as your correlation ID instead of minting a parallel one, so your logs and traces join on the same key. Start with the correlation ID, and add tracing when the flat view stops being enough.

Reading it back in OpenSearch

Once these JSON lines are shipped to OpenSearch, the payoff is a one-line query. In Dashboards, request_id: "9f2c1a7b4e" pulls that request’s entire life across every service, in order, and nothing else. That is the exact query I run when an operator quotes an ID back from a failed response.

It is also why the JSON step isn’t optional. request_id has to be a real field for that filter to work, and a grep over a text blob won’t cut it once you are at any volume. For the operator consoles behind CMS workflow operations, where logs from several services land in the same OpenSearch cluster, this one field is the difference between a two-minute lookup and a wild afternoon.

What I’d do differently

If I were wiring this up on a new service today, I’d reach for asgi-correlation-id rather than hand-rolling the middleware. It is the same idea, it handles the header adoption, validation, and contextvar plumbing, and it has already been bitten by the thread-pool edge case so you don’t have to be.

I still like writing it out by hand the first time. When the ID goes missing at 2am, you want to understand every line between the request and the log, not debug someone else’s abstraction. Either way, the shape is the same: set the ID once at the edge, carry it in a contextvar, stamp it on every line, and forward it on the way out.

Related posts: Tracing an LLM pipeline with OpenTelemetry · Graceful shutdown for FastAPI on Kubernetes · OpenSearch ISM: automate index rollover