Structured JSON Logging with Request IDs in FastAPI

Key takeaways:

  • A JSON formatter is a logging.Formatter subclass that returns json.dumps(...).
  • Fields passed via extra= land on the record as plain attributes; merging them needs a reserved-name list.
  • extra={"name": ...} raises KeyError — several obvious field names are already taken.
  • Installing the handler on the root logger reformats every library's logs too.
  • Records emitted outside a request carry no request id, and that is correct rather than a bug.

This guide builds the log substrate that Observability and Tracing depends on. It is about the formatter — the record-to-JSON layer and the sharp edges in Python's logging module. How one identifier is kept alive across an await or a thread hop is a separate problem, covered in correlating logs, traces and errors.

The Problem This Solves

At 03:00, with one user reporting a failed checkout, you need every line that request produced. With free-text logs you have a timestamp range and a guess. With structured logs you have request_id = "abc" and an exact answer.

The move from logger.info(f"order {id} failed for {user}") to logger.info("order failed", extra={"order_id": id, "user_id": user}) is the whole idea: stop encoding data into a sentence that a machine then has to parse back out. What makes this harder than it sounds is that Python's logging module was designed around formatted strings, and the seams show as soon as you push structured data through it.

Why It Happens: What a LogRecord Actually Is

Every call to logger.info(...) builds a LogRecord, an object with a fixed set of attributes: name, levelname, msg, args, pathname, lineno, exc_info, and roughly twenty more. A Formatter receives that record and returns a string. That is the entire contract, and a JSON formatter simply returns a different kind of string.

The extra dictionary is where structured data enters. logging copies each key onto the record as an attribute — it does not nest it, tag it, or namespace it. Two consequences follow, and both bite in production.

First, because extras become plain attributes, a formatter that wants to emit them must distinguish "field the caller added" from "field LogRecord always has". There is no flag for this; the only reliable way is to compare against the known reserved set.

Second, because they become attributes, a collision would silently destroy real record state. logging guards against that by raising KeyError at the call site instead. So extra={"module": "billing"} — a completely natural thing to write — throws.

How a log call becomes a JSON lineA logger call with an extra dictionary creates a LogRecord whose reserved attributes and caller extras are merged by a JSON formatter, which reads the request id from a context variable and emits one JSON object per line.logger.info(msg,extra={...})LogRecordextras become attrsKeyErroron reserved nameJsonFormattermerges + dumpsone JSON objectper record, per lineContextVarrequest_id

Prerequisites

  • Nothing beyond the standard library. logging and json are enough; packages such as structlog are a convenience layer over the same record model.
  • Middleware that assigns a request id. The example below inlines a minimal one.

The Fix

The formatter below is complete and executed. It derives the reserved set from a throwaway LogRecord rather than hard-coding a list, so it stays correct across Python versions.

import json
import logging
from contextvars import ContextVar

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

# LogRecord already owns these names. Passing any of them via `extra=` raises at call time,
# so a formatter that invites arbitrary extras has to know the reserved set.
RESERVED = set(logging.LogRecord("", 0, "", 0, "", (), None).__dict__) | {
    "message", "asctime", "taskName",
}


class JsonFormatter(logging.Formatter):
    def format(self, record: logging.LogRecord) -> str:
        payload = {
            # Fixed timestamp so the published transcript is byte-stable; production uses
            # dt.datetime.fromtimestamp(record.created, dt.timezone.utc).isoformat().
            "ts": "2026-07-20T12:00:00+00:00",
            "level": record.levelname,
            "logger": record.name,
            "msg": record.getMessage(),
            "request_id": request_id_ctx.get(),
        }
        # Anything the caller passed via extra= lands on the record as a plain attribute.
        payload.update({k: v for k, v in record.__dict__.items() if k not in RESERVED})
        if record.exc_info:
            exc_type, exc, _ = record.exc_info
            payload["exc_type"] = exc_type.__name__
            payload["exc_msg"] = str(exc)
        return json.dumps(payload)

Reading the request id from the context variable inside format rather than injecting it with a logging.Filter is a deliberate simplification: it is one fewer object to install. A filter is only needed if you want the id present on the record itself so that other handlers can see it too.

The app binds an id per request and logs three ways — a normal call with extras, a caught exception, and a deliberate collision with a reserved name:

@app.middleware("http")
async def bind_request_id(request: Request, call_next):
    rid = request.headers.get("x-request-id") or "rid-fixed-for-transcript"
    token = request_id_ctx.set(rid)
    try:
        return await call_next(request)
    finally:
        request_id_ctx.reset(token)   # Never leak the value into the next request.


@app.get("/orders/{order_id}")
async def read_order(order_id: int) -> dict[str, int]:
    log.info("order loaded", extra={"order_id": order_id, "cache": "miss"})
    return {"order_id": order_id}


@app.get("/fail")
async def fail() -> dict[str, str]:
    try:
        {}["missing"]
    except KeyError:
        log.exception("lookup failed")
    return {"status": "logged"}


@app.get("/reserved")
async def reserved() -> dict[str, str]:
    """`extra` keys that collide with LogRecord's own attributes are rejected outright."""
    try:
        log.info("attempt", extra={"name": "shadowed", "module": "shadowed"})
        return {"result": "logged"}
    except KeyError as exc:
        return {"result": "KeyError", "detail": str(exc)}

Here is what that app really emitted:

$ GET /orders/7
200 OK
{
  "order_id": 7
}

$ GET /fail
200 OK
{
  "status": "logged"
}

$ GET /reserved
200 OK
{
  "result": "KeyError",
  "detail": "\"Attempt to overwrite 'name' in LogRecord\""
}

$ GET /lines
200 OK
{
  "lines": [
    {
      "ts": "2026-07-20T12:00:00+00:00",
      "level": "INFO",
      "logger": "orders",
      "msg": "order loaded",
      "request_id": "rid-fixed-for-transcript",
      "order_id": 7,
      "cache": "miss"
    },
    {
      "ts": "2026-07-20T12:00:00+00:00",
      "level": "INFO",
      "logger": "httpx",
      "msg": "HTTP Request: GET http://testserver/orders/7 \"HTTP/1.1 200 OK\"",
      "request_id": "-"
    },
    {
      "ts": "2026-07-20T12:00:00+00:00",
      "level": "ERROR",
      "logger": "orders",
      "msg": "lookup failed",
      "request_id": "rid-fixed-for-transcript",
      "exc_type": "KeyError",
      "exc_msg": "'missing'"
    },
    {
      "ts": "2026-07-20T12:00:00+00:00",
      "level": "INFO",
      "logger": "httpx",
      "msg": "HTTP Request: GET http://testserver/fail \"HTTP/1.1 200 OK\"",
      "request_id": "-"
    },
    {
      "ts": "2026-07-20T12:00:00+00:00",
      "level": "INFO",
      "logger": "httpx",
      "msg": "HTTP Request: GET http://testserver/reserved \"HTTP/1.1 200 OK\"",
      "request_id": "-"
    }
  ]
}

Reading the output

The reserved-name collision is a hard failure. "Attempt to overwrite 'name' in LogRecord" is raised by logging before the record is ever emitted. Note where that happens: at the call site, inside your request handler. A field named name, module, filename, args or msg — all plausible domain names — turns a working endpoint into a 500 the first time that log line executes. Namespace your extras, or nest them under a single context key, and the entire class of failure disappears.

Note also which log line is missing. There is no record for "attempt" at all. The exception fired during record creation, so nothing was logged. The failure mode is a lost log line and an exception, not a degraded record.

Third-party loggers were reformatted. Three httpx records appear as JSON. Nobody asked for that: installing a handler on the root logger captures every logger that propagates to it. This is usually desirable, since one format across the whole process is the point, but it does mean a library's log volume is now your ingestion bill, and libraries that log at INFO per operation need their level raised explicitly.

Those library records carry request_id: "-". They were emitted by the outbound HTTP client, outside the middleware's context. That is the correct answer rather than a bug, and it is why the default value matters: a sentinel like "-" states "no request context", whereas omitting the key entirely makes its absence ambiguous in a log backend.

Exceptions became two indexed fields. exc_type and exc_msg are filterable; a raw traceback is not. Keeping the full traceback as an additional single-string field is fine — what breaks shippers is emitting it as literal multi-line output, because one record per line is the invariant most log agents rely on.

Verification

Assert on the parsed object, never on the string. Key ordering and timestamp formatting are implementation details:

def test_log_line_is_structured(client, captured):
    client.get("/orders/7", headers={"x-request-id": "rid-7"})
    record = json.loads(captured.lines[0])
    assert record["request_id"] == "rid-7"
    assert record["order_id"] == 7          # The extra survived as a real field.
    assert record["level"] == "INFO"

Worth adding one test nobody thinks to write: assert that every field name your code passes via extra is absent from the reserved set. A three-line test over a list of your field names prevents the 500 described above from ever reaching production.

In a running service, pipe a few seconds of output through jq -c 'select(.request_id != "-")'. If nothing comes back, the middleware is not setting the context variable in the same context the handler runs in.

Trade-offs and When Not To

JSON is unreadable in a terminal. During local development a plain-text formatter is far kinder. Select the formatter by environment rather than committing to JSON everywhere; the log calls stay identical either way, which is the real benefit of structured logging.

Volume is the actual cost. A JSON record is several times larger than its text equivalent. On a high-traffic service the ingestion bill, not CPU, is what makes teams regret logging once per request.

Do not log payloads. A structured formatter makes it trivially easy to attach an entire request body as a field. Log identifiers and shapes — item_count, order_id — and never credentials, tokens, or personal data, because logs are retained and widely readable.

A logging library may be the better answer. structlog and similar packages solve the reserved-name and merge problems for you. The value in writing the formatter yourself is understanding what those libraries protect you from; if the list above looks like maintenance you would rather avoid, take the dependency.

FAQ

Why does passing extra to a log call sometimes raise KeyError? Because LogRecord already owns names like name, module, args and levelname, and the logging module refuses to overwrite them. Passing any of those through extra raises KeyError at the call site, so a field name chosen innocently in application code can crash a request path that was never exercised in tests.

Why are my third-party library logs suddenly JSON too? Because installing a handler on the root logger catches every logger that propagates to it, which is nearly all of them. That is usually what you want for consistency, but those records were emitted outside any request and so carry no request id.

Should the traceback go in the JSON log line? Emit the exception type and message as separate indexed fields, and include the full traceback as a single string field rather than as raw multi-line output. Multi-line text breaks one-line-per-record log shippers and makes the record unparseable.

How do I make Uvicorn's access log match my format? Pass a logging config to Uvicorn that points its uvicorn.access logger at your JSON formatter, or disable the access log entirely and emit one yourself from middleware. Emitting it yourself is usually better because only your middleware knows the request id.

Is JSON logging slower than plain text? Serializing a dict costs more than formatting a string, but the cost lands per record and is small next to any I/O the request performs. The real risk is volume: JSON records are larger, so an over-chatty logger costs more in ingestion bills than in CPU.