Implementing Custom Middleware for Request Tracing

Key takeaways:

  • Accept an inbound x-request-id and mint one only when it is missing, so one ID spans several services.
  • Bind it to a contextvar, which makes it readable from code that has no access to the request.
  • Attach a logging.Filter that stamps every record — no call site passes the ID, and none can forget to.
  • Reset the contextvar token in finally so a failed request cannot leak its ID into later work.
  • Return the ID in the response header and in error bodies, so a user's screenshot is a log query.

This guide builds the tracing middleware described in Middleware Implementation. Whether this belongs in middleware at all rather than in a dependency is worth settling first: see Middleware vs Dependencies for the general rule — tracing is the clearest case for middleware, because it must cover requests that never match a route.

The Problem This Solves

At 2am a customer reports that checkout failed at approximately 14:32. You have structured logs from six services, and the only shared field is a timestamp. Finding the twenty lines that describe that request means grepping a window, guessing which user id appeared, and hoping traffic was light.

The fix is one identifier attached at the edge and present on every line the request produces, in every service it touches. The mechanism is small — perhaps thirty lines — but the details determine whether it works everywhere or only in the handlers where someone remembered to pass it.

Why It Happens

The obstacle is that the request object is available in exactly one place: the handler signature. The code that most needs the ID — a payment client three layers down, a retry helper, a SQL logger — has no access to it, and giving it access means adding a request_id parameter to every function between here and there. That is a refactor nobody finishes, and it couples pure business logic to an observability concern.

contextvars solves this properly, and it is worth understanding why it works under async rather than treating it as a global that happens to be safe. A ContextVar reads its value from the current Context, and asyncio gives each task its own copy: when a task is created, it copies the current context, so values set inside it are invisible to its parent and to sibling tasks. Two requests handled concurrently on one event loop therefore see different values for the same variable, and no locking is involved. A thread-local would not do this, because many requests share one thread; a module-level global would be catastrophically wrong for the same reason.

The second mechanism is logging.Filter. Filters were designed to drop records, but they run for every record and receive it as a mutable object, so they are also the supported way to enrich records. A filter that reads the contextvar and assigns record.request_id makes the field available to the formatter for every log line in the process — including lines from libraries that have never heard of your tracing.

One identifier, four readersMiddleware takes the inbound header or mints an ID and binds it to a contextvar. The logging filter, deep service code and the exception handler all read the same contextvar, and the middleware writes the ID back onto the response header.x-request-idinbound (or absent)TracingMiddlewarereuse header, else mintctx.set(rid)request_id_ctxone value per task, no locking,invisible to concurrent requestsRequestIdFilterevery log recordservice codeno request objectexception handlerstamps error bodyresponse headerback to the clientNothing below the middleware receives the ID as an argument. All four readers pull it.That is what makes it impossible for a call site to forget.

The Fix

1. The contextvar and the middleware

# Readable from anywhere inside the request's async context, including a logging filter.
request_id_ctx: ContextVar[str] = ContextVar("request_id", default="-")

HEADER = "x-request-id"


class TracingMiddleware(BaseHTTPMiddleware):
    async def dispatch(self, request: Request, call_next):
        # Reuse an ID the caller already has, so one trace spans several services.
        rid = request.headers.get(HEADER) or str(uuid.uuid4())
        token = request_id_ctx.set(rid)
        try:
            response = await call_next(request)
        finally:
            # Reset even on failure, so the value can never bleed into the next task.
            request_id_ctx.reset(token)
        response.headers[HEADER] = rid
        return response

The try/finally around call_next is the part people leave out. ContextVar.set returns a token whose only purpose is restoring the previous value, and if a request raises before an unguarded reset, the variable stays bound. Under BaseHTTPMiddleware that context is not always the one you think it is, and a stale ID appearing on unrelated log lines is a genuinely confusing bug to chase — far worse than no ID at all, because it produces confident, wrong correlations.

A default of "-" rather than None matters too: the formatter interpolates %(request_id)s on every record, including ones emitted at import time before any request exists, and a missing attribute raises inside logging.

2. The logging filter

class RequestIdFilter(logging.Filter):
    """Puts request_id on every record so the formatter can rely on it existing."""

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

Attach it to the handler, not the logger. A filter on a logger only sees records logged directly to it, whereas a filter on a handler sees everything routed there, including records that propagated up from child loggers in third-party libraries.

3. Prove it end to end

The example logs from the handler, then from charge_card() — a function with no request object and no request_id parameter — and returns the captured log lines alongside the real response headers:

$ GET /selftest
200 OK
[
  {
    "case": "caller supplies an ID; it must be preserved",
    "request": "GET /orders/7  x-request-id: trace-from-gateway",
    "status": 200,
    "response_header": {
      "x-request-id": "trace-from-gateway"
    },
    "response_body": {
      "order_id": 7
    },
    "log_lines_emitted_during_this_request": [
      "{\"level\":\"INFO\",\"request_id\":\"trace-from-gateway\",\"msg\":\"loading order 7\"}",
      "{\"level\":\"INFO\",\"request_id\":\"trace-from-gateway\",\"msg\":\"charging 500 minor units\"}"
    ],
    "id_generated_by_middleware": false
  },
  {
    "case": "no ID supplied; middleware mints one",
    "request": "GET /orders/8",
    "status": 200,
    "response_header": {
      "x-request-id": "generated-0002"
    },
    "response_body": {
      "order_id": 8
    },
    "log_lines_emitted_during_this_request": [
      "{\"level\":\"INFO\",\"request_id\":\"generated-0002\",\"msg\":\"loading order 8\"}",
      "{\"level\":\"INFO\",\"request_id\":\"generated-0002\",\"msg\":\"charging 500 minor units\"}"
    ],
    "id_generated_by_middleware": true
  },
  {
    "case": "the request fails; the ID still reaches the body",
    "request": "GET /orders/9/fail  x-request-id: trace-abc",
    "status": 402,
    "response_header": {
      "x-request-id": "trace-abc"
    },
    "response_body": {
      "error": "payment_required",
      "request_id": "trace-abc"
    },
    "log_lines_emitted_during_this_request": [
      "{\"level\":\"WARNING\",\"request_id\":\"trace-abc\",\"msg\":\"request failed: payment_required\"}"
    ],
    "id_generated_by_middleware": false
  }
]

(The generated IDs read generated-0002 rather than a UUID because the example pins its ID factory to a counter so the recorded transcript stays stable; production code calls uuid.uuid4().)

Three properties are demonstrated rather than claimed. The supplied trace-from-gateway came back unchanged in the header and appears on both log lines — including the one from charge_card, which was never told anything. When no header was supplied, the middleware minted an ID and used it consistently. And on the 402, the exception handler read the same contextvar, so the client's error body carries the identifier that will find the server-side logs.

That last case is the one that pays for the whole exercise. A user can paste an error body into a support ticket, and the request_id in it is a direct query into your log store.

4. Propagate it outward

An ID that stops at your service boundary only solves the problem inside one service:

async def call_downstream(client: httpx.AsyncClient, url: str) -> httpx.Response:
    # Forward the same ID so the trace continues into the next service.
    return await client.get(url, headers={"x-request-id": request_id_ctx.get()})

Better still, set it once as a default header on a shared client, or install an httpx event hook, so no call site can omit it.

Verification

def test_supplied_id_is_preserved(client):
    resp = client.get("/orders/7", headers={"x-request-id": "abc-123"})
    assert resp.headers["x-request-id"] == "abc-123"


def test_missing_id_is_generated(client):
    assert client.get("/orders/7").headers["x-request-id"]


def test_deep_code_logs_the_id(client, caplog):
    with caplog.at_level(logging.INFO, logger="api"):
        client.get("/orders/7", headers={"x-request-id": "abc-123"})
    # The assertion that matters: the line from charge_card(), not just from the handler.
    assert all(r.request_id == "abc-123" for r in caplog.records)


def test_error_bodies_carry_the_id(client):
    body = client.get("/orders/9/fail", headers={"x-request-id": "abc-123"}).json()
    assert body["request_id"] == "abc-123"

In production the equivalent check is a log query: filter on one request_id and confirm the result includes lines from more than one module, and ideally more than one service. If every hit comes from your request-logging middleware, the filter is attached but nothing else is using it.

Trade-offs and When Not To

BaseHTTPMiddleware is the convenient base class and it is not free. It wraps the response in an anyio task group and streams the body through a memory channel, which adds overhead per request and has historically been the source of subtle interactions with streaming responses and background tasks. For a hot path where this matters, write the tracing as raw ASGI middleware — a function taking scope, receive, send — which does the same job with none of the wrapping. The contextvar and filter code stays identical.

Treat an inbound x-request-id as untrusted. It is a client-supplied string that will end up in your log store, so bound its length and character set before binding it, and never use it for anything but correlation. An attacker controlling it can otherwise inject newlines into log lines or poison a trace by reusing a known ID.

Finally, be clear about what this is not. A correlation ID gives you grouping; it does not give you timings, a span tree, or a view of which downstream call was slow. When the question moves from "which lines belong to this request" to "where did the 900ms go", you want real distributed tracing — see instrumenting FastAPI with OpenTelemetry. The two coexist happily, and OpenTelemetry's trace id can be the value you stamp into logs instead of minting your own.

FAQ

Why use a contextvar instead of passing the request ID as an argument? Because the code that needs it is usually several calls below the handler, and threading a request_id parameter through every service function couples them all to a tracing concern. A contextvar is set once per request and readable from anywhere in that request's async context, including a logging filter that no application code calls directly.

Should the middleware generate the ID or accept one from the caller? Accept an incoming x-request-id when present and generate one only when it is absent. A verified run shows a supplied value of trace-from-gateway surviving into both the response header and the log lines, which is what makes a single trace span several services.

How does a logging filter add the request ID to every log line? A logging.Filter attached to the handler runs for every record and can set attributes on it. Reading the contextvar there and assigning record.request_id makes the field available to the formatter for all records, so no call site has to pass anything or even know tracing exists.

Why must the contextvar token be reset in a finally block? Setting a contextvar returns a token that restores the previous value. Resetting in finally guarantees restoration even when the request raises, which keeps the value from surviving into whatever the worker handles next. Without it a failed request can leave a stale ID visible to later work on the same context.

Do background tasks and threadpool dependencies see the request ID? Context is copied into a threadpool call, so a sync dependency sees the value that was set when it was scheduled. Work that outlives the request is the real hazard: capture the ID into a local variable and pass it explicitly rather than relying on the contextvar still being bound.