What structured logging with structlog is and why FastAPI services need it

structlog is often described as a nicer logger, but that undersells it. A better description is a pipeline: you bind key-value context (a request ID, a user ID, a route) once, and every log call made while handling that request picks it up automatically. The output is a structured event, not a string someone has to parse later.

That distinction matters once logs leave your terminal. A line like "GET /orders/42 returned 500 in 812ms" is readable, but a log aggregator can only search it as text. To find every slow 500 on one route, you write a regex and hope the message format never changed. With key-value JSON, status, path and duration_ms are fields. You can filter on them exactly, compute percentiles, group by route, and build alerts on thresholds instead of string matches. When a format change breaks a regex, alerts fail silently. JSON fields avoid that failure.

Backend engineers benefit when debugging: one request_id pulls every line for a failing request out of thousands of concurrent ones. Platform engineers benefit because consistent field names across services make dashboards and alerts reusable.

Anatomy of a per-request JSON line

A useful access log line carries these fields:

  • timestamp: ISO 8601, in UTC
  • level: info, warning, error
  • event: a short, stable name such as request_completed
  • logger: the module that emitted it
  • request_id: the correlation key
  • method and path: what was called
  • status: the response code
  • duration_ms: the latency, as a number rather than a string
import structlog
from structlog.contextvars import bind_contextvars, clear_contextvars

# Each processor enriches the event dict in turn; the renderer runs last.
structlog.configure(
    processors=[
        structlog.contextvars.merge_contextvars,  # pull in request-scoped context
        structlog.processors.add_log_level,       # adds "level"
        structlog.processors.TimeStamper(fmt="iso", utc=True),  # adds "timestamp"
        structlog.processors.JSONRenderer(),      # one JSON object per line
    ]
)

# Bind the emitting module once; it travels with every call on this logger.
log = structlog.get_logger(logger="app.access")


def handle_request() -> None:
    # Start each request with a clean slate so context never leaks between requests.
    clear_contextvars()
    # Bind once; every log call during this request inherits these keys.
    bind_contextvars(
        request_id="7f3c9a1e-placeholder",
        method="GET",
        path="/orders/42",
    )

    # Event is a stable name; the variable parts are typed fields, not prose.
    log.info("request_completed", status=500, duration_ms=812.4)


handle_request()
# Output is one line (wrapped here; key order may differ):
# {"logger": "app.access", "status": 500, "duration_ms": 812.4,
#  "event": "request_completed", "request_id": "7f3c9a1e-placeholder",
#  "method": "GET", "path": "/orders/42", "level": "info",
#  "timestamp": "2026-10-22T09:14:03.512345Z"}

A minimal structlog pipeline that binds request context once and renders a single JSON access line with timestamp, level, event, logger, request_id, method, path, status and a numeric duration_ms.

How the pipeline works: contextvars, processors and one formatter

Every record in that schema is produced by the same path, whether the call came from your code, a third-party library, or uvicorn itself.

The flow of one log record

  1. Middleware binds context. When a request arrives, middleware calls bind_contextvars(request_id=...). The value is stored in a context variable rather than passed through function arguments.
  2. Application code logs. A structlog logger call builds an event dict containing the message and any keyword arguments.
  3. Foreign records join. Records from the standard library logging module, including uvicorn's, reach a handler whose formatter is structlog's ProcessorFormatter. Its foreign_pre_chain turns each LogRecord into an event dict.
  4. Shared processors enrich. Both sources run through the same chain. merge_contextvars copies request_id into the event. add_log_level and TimeStamper add the level and timestamp. StackInfoRenderer and an exception processor such as format_exc_info turn stack and traceback data into fields.
  5. One renderer emits. A single JSONRenderer serializes the result. Because the renderer is defined once, every line has the same shape regardless of where it came from.

Why contextvars and not thread-locals

Under asyncio, many requests run on one event-loop thread and interleave at every await. A thread-local value would be shared by all of them, so request A could log with request B's ID after a context switch. Context variables are scoped to the asyncio task instead. Each request is handled in its own task, so the bound request_id stays with that request across awaits, and other requests running concurrently on the same thread cannot see it.

         HTTP request
              v
+---------------------------+
| Middleware                |
| bind_contextvars(         |
|   request_id=...)         |
+-------------+-------------+
              v  request_id held in a contextvar (per task)
+---------------------------+     +-------------------------------+
| App code (structlog)      |     | stdlib logging / uvicorn      |
| log.info("event", k=v)    |     | logging.LogRecord             |
+-------------+-------------+     +---------------+---------------+
              |                                   |  ProcessorFormatter
              |                                   |  foreign_pre_chain
              v                                   v
        +-----------------------------------------------+
        | Shared processor chain                        |
        |   merge_contextvars    -> adds request_id     |
        |   add_log_level                               |
        |   TimeStamper                                 |
        |   StackInfoRenderer                           |
        |   format_exc_info                             |
        +-----------------------+-----------------------+
                                v
                   +-------------------------+
                   | JSONRenderer (only one) |
                   +------------+------------+
                                v
           one JSON line, same shape for every source

Structlog calls from application code and stdlib or uvicorn records, converted to event dicts by ProcessorFormatter's foreign_pre_chain, pass through one shared processor chain that merges the request_id from contextvars, and are then serialized by a single JSONRenderer.

Configuring structlog and stdlib logging together

event loop never see it.

The setup module

Put configuration in one function, such as configure_logging(), and call it once before the app starts. It defines a shared_processors list: structlog.contextvars.merge_contextvars, structlog.stdlib.add_log_level, structlog.stdlib.add_logger_name, and structlog.processors.TimeStamper(fmt="iso"). Both structlog calls and plain logging records from libraries pass through this list, so every line has the same keys.

structlog.configure uses shared_processors plus a final structlog.stdlib.ProcessorFormatter.wrap_for_formatter. It sets logger_factory=structlog.stdlib.LoggerFactory() and wrapper_class=structlog.stdlib.BoundLogger. The structlog chain has no renderer. Rendering happens in one place: a ProcessorFormatter on a single root StreamHandler. Its foreign_pre_chain is shared_processors, and it ends with JSONRenderer() when LOG_FORMAT=json and ConsoleRenderer() otherwise. Make JSON the default so a missing variable in production still produces parseable output.

For uvicorn, uvicorn.error and uvicorn.access, clear handlers and set propagate = True so their records reach the root handler. If section 4's middleware writes access logs, also disable uvicorn.access. Start uvicorn with log_config=None so its default config does not replace yours.

Symptom Cause Fix
JSON string nested inside a JSON event field Renderer in both structlog.configure and the formatter Render only in ProcessorFormatter
Every uvicorn line appears twice uvicorn handler plus propagation to root Clear uvicorn handlers
Access lines in two formats uvicorn access log plus middleware log Disable uvicorn.access 
import logging
import os

import structlog


def configure_logging() -> None:
    # Run on structlog events and on plain logging records, so both have the same keys.
    shared_processors = [
        structlog.contextvars.merge_contextvars,
        structlog.stdlib.add_log_level,
        structlog.stdlib.add_logger_name,
        structlog.processors.TimeStamper(fmt="iso"),
    ]
    structlog.configure(
        # No renderer here. wrap_for_formatter passes the event dict to ProcessorFormatter.
        processors=shared_processors + [structlog.stdlib.ProcessorFormatter.wrap_for_formatter],
        logger_factory=structlog.stdlib.LoggerFactory(),
        wrapper_class=structlog.stdlib.BoundLogger,
        cache_logger_on_first_use=True,
    )
    # JSON is the default, so production output stays parseable if LOG_FORMAT is unset.
    use_json = os.getenv("LOG_FORMAT", "json") == "json"
    renderer = structlog.processors.JSONRenderer() if use_json else structlog.dev.ConsoleRenderer()
    handler = logging.StreamHandler()
    handler.setFormatter(structlog.stdlib.ProcessorFormatter(
        foreign_pre_chain=shared_processors,  # applied to records from stdlib loggers
        processors=[structlog.stdlib.ProcessorFormatter.remove_processors_meta, renderer],
    ))
    root = logging.getLogger()
    root.handlers = [handler]  # the only handler that renders output
    root.setLevel(logging.INFO)
    for name in ("uvicorn", "uvicorn.error", "uvicorn.access"):
        uv_logger = logging.getLogger(name)
        uv_logger.handlers.clear()  # without this, uvicorn lines are written twice
        uv_logger.propagate = True
    # Access lines come from the request middleware, so turn off uvicorn's access log.
    logging.getLogger("uvicorn.access").disabled = True

# Startup: configure_logging(); uvicorn.run(app, host="0.0.0.0", port=8000, log_config=None)

A configure_logging() function that renders output in a single ProcessorFormatter on the root handler, chooses JSON or console output from LOG_FORMAT, and sends uvicorn records to the root handler so no line is written twice or rendered twice.

Implementing request ID middleware and per-request access logs

The middleware's first job is structlog.contextvars.clear_contextvars(). Context variables are scoped to the task handling the request, but clearing them explicitly at the start ensures a reused worker task never carries a previous request's keys into the next one.

Next, read the incoming X-Request-ID header and decide whether to trust it. Accept it only if it is short (for example, at most 64 characters) and limited to a conservative character set such as letters, digits, hyphens, and underscores. Without that check, a client can inject newlines, oversized blobs, or values that break log parsers and dashboards.

  • If the header is valid, use it as request_id.
  • If it is missing or invalid, generate a UUID4.
  • If you rejected a value, also bind a truncated copy as upstream_request_id. This keeps traces correlatable with the proxy or caller.

Bind the result with bind_contextvars(request_id=...) before calling the next handler, so every log line emitted during the request inherits it.

Timing and the access log line

Record time.perf_counter() before dispatch. Emit the access line in a finally block containing:

  • method
  • path
  • status code
  • duration_ms

If the handler raised, log status 500 so failed requests still produce a line. Set the same ID on the response header so clients can quote it in bug reports.

Keeping or disabling uvicorn's access log

Uvicorn's access log knows nothing about your context, so its lines lack request_id. Running it alongside the middleware log produces the duplicate-format problem described above. Most teams start uvicorn with --no-access-log and rely on the middleware line instead.

Keep uvicorn's log only if you need records of requests rejected before they reach your application, such as malformed HTTP or requests refused during startup.

import re
import time
import uuid

import structlog
from fastapi import FastAPI, Request

app = FastAPI()
log = structlog.get_logger("access")

# fullmatch (not match + $) so a trailing newline is also rejected
VALID_ID = re.compile(r"[A-Za-z0-9_-]{1,64}")


@app.middleware("http")
async def request_context(request: Request, call_next):
    # Drop anything left over from a previous request on this task
    structlog.contextvars.clear_contextvars()

    incoming = request.headers.get("x-request-id")
    if incoming and VALID_ID.fullmatch(incoming):
        request_id = incoming
    else:
        request_id = str(uuid.uuid4())
        if incoming:
            # Keep a bounded copy for correlation; the JSON renderer escapes it
            structlog.contextvars.bind_contextvars(upstream_request_id=incoming[:64])
    structlog.contextvars.bind_contextvars(request_id=request_id)

    start = time.perf_counter()
    status = 500  # reported if the handler raises
    try:
        response = await call_next(request)
        status = response.status_code
        response.headers["X-Request-ID"] = request_id
        return response
    finally:
        log.info("request", method=request.method, path=request.url.path,
                 status=status, duration_ms=round((time.perf_counter() - start) * 1000, 2))

# Run with: uvicorn app:app --no-access-log  (this line replaces uvicorn's access log)

A FastAPI HTTP middleware that clears structlog context, validates or generates a request ID, keeps a rejected upstream ID for correlation, emits one timed access log line even on exceptions, and echoes the ID in the response header.

Adding context deeper in the stack and logging exceptions once

After authentication succeeds, call bind_contextvars(user_id=..., tenant_id=...) from the dependency that resolves the user. Every later log line in that request then carries those fields through merge_contextvars, so you never pass identifiers through function signatures. For context that matters only within one function or loop, use log = logger.bind(order_id=order.id). It returns a new logger and leaves the shared context unchanged, so a value bound during one iteration cannot appear on unrelated lines.

Inside a handler, call logger.exception(...) only when you catch an error and handle it there. If you re-raise, do not log, because whoever catches the error next will log it. Unhandled errors need exactly one owner. That can be either the request middleware or an Exception handler, not both. The owner logs once with the traceback while the request's contextvars are still bound, and it returns the 500 response itself. If the error propagates out of the app instead, uvicorn logs it a second time without your context.

Context propagation depends on how the work is scheduled:

  • Sync endpoints and dependencies that FastAPI runs in its threadpool keep the context.
  • asyncio.create_task copies the context when the task is created.
  • A raw ThreadPoolExecutor.submit or run_in_executor does not copy it. Wrap the call with contextvars.copy_context().run.
  • BackgroundTasks run after the response is sent. Whether they still see the request's fields depends on where your middleware clears them. Clearing at the start of each request is more forgiving than clearing in a finally block. The more robust option is to pass request_id explicitly and rebind it at the start of the task.
  • Queue workers run in a different process. Put request_id in the job payload and bind it when the worker picks up the job.

Testing the logging setup with pytest

Logging is easy to break without noticing. Someone reorders processors or renames a field, and nothing fails until you need the logs during an incident. A few targeted tests catch those regressions cheaply.

structlog.testing.capture_logs is a context manager that collects event dicts in a list instead of rendering them. It works by temporarily replacing the configured processor chain. That means merge_contextvars does not run, so a plain capture_logs() block will not show request_id even when the middleware works correctly. To test context propagation, write a fixture that configures structlog with merge_contextvars followed by a structlog.testing.LogCapture() instance. Then read .entries from that instance. If your production config sets cache_logger_on_first_use=True, call structlog.reset_defaults() in the fixture teardown. Otherwise loggers cached in one test keep their configuration in later tests.

Use FastAPI's TestClient and send a request with a valid inbound ID. Assert three things:

  • Every entry produced during the request has that ID.
  • The response header has the same value.
  • No entry logged after the request has it, which shows the context was cleared.

Then send a malformed ID, such as an oversized string or one with newlines. Assert that the header and the log entries both carry a newly generated ID that differs from the input.

These tests do not check the JSON renderer or the stdlib bridge. Test those separately. Run your real configuration and use pytest's capsys (or capfd, if the handler writes to the file descriptor directly) to read the output. Parse each line with json.loads and assert the required keys are present. Also emit a record through a standard logging.getLogger logger and confirm it comes out as the same JSON shape.

When to avoid it, alternatives, and impact on cost and engineering time

For a cron script or single-file internal tool, this setup is overkill. With no concurrent requests to correlate, logging.basicConfig and a readable format are faster to write and easier to read.

Failure modes to plan for

  • Rejected requests leave no log line. If the server rejects malformed HTTP, or middleware that runs before yours rejects the request, your middleware never runs and no access log line is written. Keep the server's own error log enabled as a backstop.
  • JSON is hard to read in a terminal. Use the console renderer when stdout is a TTY. Run CI and staging with the production JSON renderer so that key-name drift and serialization errors show up before production.
  • Call-site inspection adds overhead. Adding file, function and line costs work on every event. Profile your hot paths before enabling it globally.
  • Rich context increases volume and can leak data. A bound user object or request headers can carry emails and tokens. Allowlist the keys you log, or add a redaction processor.

Alternatives

Option Fits when Trade-off
stdlib logging + JSON formatter Few log calls, little per-request context Context passed manually via extra
Other structured logging libraries Team already standardised on one Different context and stdlib integration models
OpenTelemetry correlation Requests cross several services More infrastructure; trace IDs replace a homegrown request ID

Cost versus time saved

The work is front-loaded into initial setup and debugging the configuration. The payoff comes during incidents, when you can filter on one request ID instead of matching log lines by timestamp.

Illustrative estimate (assumed numbers, not a benchmark):

  • Break-even months = setup hours ÷ (hours saved per incident × incidents per month)
  • Assume 12 setup hours, 1 hour saved per incident and 3 incidents a month.
  • 12 ÷ (1 × 3) = 4 months.

How OneEnv can help

Disclosure: OneEnv is the product behind this blog.

OneEnv (oneenv.io) is a workspace-based governance platform for the things services share — environment variables, database structure, API routes and validation rules. A change to a shared value is staged on a branch, reviewed once, and then every affected service explicitly approves or rejects it before it goes live, so you can see who a change touches before it ships instead of finding out in production.

Applied to structlog fastapi, this is where it helps:

Saves time

  • Every service that inherits a shared value is listed in one place, so nobody searches repos and chats to find out who is affected.
  • One review per branch replaces coordinating each team separately; each service still keeps its own approve/reject.
  • Changing a shared variable is one edit and one review instead of editing every service's .env by hand.

Saves cost

  • Fewer production incidents and rollbacks caused by a shared value, route or column changing under a consumer unannounced.
  • Less duplicated configuration to maintain: one shared definition inherited by many services.
  • A wrong or stale value is caught at review time by the services it affects, not by a failed deploy.
  • OneEnv has a free plan (1 workspace, unlimited services and members, full governance), so trying it costs nothing.

These are qualitative benefits, not measured results — how much you save depends on how many services share the value.

Want to try it? Start at oneenv.io.