Python Observability

Configuring Logging for FastAPI and Uvicorn

A default FastAPI deployment emits three log formats at once: Uvicorn's coloured startup lines, its fixed-format access log, and whatever your application does. This page replaces all three with one JSON pipeline, adds request context where it is actually available, and keeps the result consistent under reload and under multiple workers. It builds on logging configuration and dictConfig, part of the Python logging fundamentals and structured data section.

Three formats by default, one after you take over The upper half shows a default FastAPI deployment. Uvicorn's error logger emits coloured human-readable startup and shutdown lines. Its access logger emits a fixed text line built from the ASGI scope, with no room for extra fields. Application loggers emit whatever the project configured, often JSON. Three formats reach the container's stdout, so the log backend must parse three shapes and correlation across them is impossible. The lower half shows the same deployment after taking over the log config: all three loggers are given the same JSON formatter and the same handler, uvicorn.access is disabled in favour of an access record emitted from application middleware where the request ID is available, and the result is a single shape with a request_id field on every line. default: three formatters, one stdout uvicorn.error coloured text uvicorn.access fixed text line your loggers JSON, probably stdout three shapes to parse after: one formatter, one shape, one correlation key uvicorn.error your JSON formatter uvicorn.access disabled your middleware access + request_id stdout one shape, always uvicorn.access is dropped rather than reformatted: it builds its message before your middleware runs, so it can never carry the request ID an access record emitted from the outermost middleware has the id, the route template, the status and the duration in one place
Uvicorn's access logger is the one component worth replacing rather than reformatting — it renders its line before any of your context exists.

Prerequisites

pip install "fastapi>=0.115.0,<1.0.0" \
            "uvicorn[standard]>=0.30.0,<1.0.0" \
            "python-json-logger>=2.0.7,<4.0.0"

export LOG_LEVEL=INFO
export UVICORN_WORKERS=4

Implementation

Step 1 — Hand Uvicorn your own config. Uvicorn applies log_config through dictConfig at startup. Supplying the whole dict is better than patching afterwards, because it runs at exactly the right point in the lifecycle and works identically in every start mode.

# logging_config.py
import os

LOG_CONFIG = {
    "version": 1,
    "disable_existing_loggers": False,
    "formatters": {
        "json": {
            "()": "pythonjsonlogger.jsonlogger.JsonFormatter",
            "format": "%(asctime)s %(levelname)s %(name)s %(message)s",
        },
    },
    "filters": {"request_context": {"()": "app.logging_filters.RequestContextFilter"}},
    "handlers": {
        "stdout": {
            "class": "logging.StreamHandler",
            "formatter": "json",
            "filters": ["request_context"],
            "stream": "ext://sys.stdout",
        },
    },
    "loggers": {
        "uvicorn":        {"handlers": ["stdout"], "level": "INFO", "propagate": False},
        "uvicorn.error":  {"handlers": ["stdout"], "level": "INFO", "propagate": False},
        "uvicorn.access": {"handlers": [],          "level": "CRITICAL", "propagate": False},
    },
    "root": {"handlers": ["stdout"], "level": os.environ.get("LOG_LEVEL", "INFO")},
}

uvicorn.access is switched off rather than reformatted. Its handler builds a message from the ASGI scope inside Uvicorn's protocol layer, before any application middleware has run, so it can never carry your request ID — and an access log that cannot be joined to the application log is a second, parallel source of truth.

Step 2 — Start with it. Both entry points work; pick one and use it everywhere so development and production agree.

# main.py
import uvicorn
from logging_config import LOG_CONFIG

if __name__ == "__main__":
    uvicorn.run(
        "app:app",
        host="0.0.0.0",
        port=8000,
        log_config=LOG_CONFIG,
        workers=int(os.environ.get("UVICORN_WORKERS", "1")),
    )

uvicorn app:app --log-config logging.json --workers 4

Step 3 — Set request context in pure ASGI middleware. A BaseHTTPMiddleware subclass runs in a separate task in some Starlette versions, which can put the contextvar in a different context from the endpoint. Pure ASGI middleware runs in the caller's context, which is what you want.

# app/middleware.py
import time
import uuid
import logging
from .context import request_id_var

logger = logging.getLogger("app.access")

class RequestContextMiddleware:
    def __init__(self, app):
        self.app = app

    async def __call__(self, scope, receive, send):
        if scope["type"] != "http":
            await self.app(scope, receive, send)
            return

        headers = dict(scope.get("headers") or [])
        rid = headers.get(b"x-request-id", b"").decode() or uuid.uuid4().hex[:12]
        token = request_id_var.set(rid)
        start = time.perf_counter()
        status_holder = {"status": 500}

        async def send_wrapper(message):
            if message["type"] == "http.response.start":
                status_holder["status"] = message["status"]
                message.setdefault("headers", []).append((b"x-request-id", rid.encode()))
            await send(message)

        try:
            await self.app(scope, receive, send_wrapper)
        finally:
            request_id_var.reset(token)
            logger.info(
                "request",
                extra={
                    "method": scope["method"],
                    "path": scope["path"],
                    "route": _route_template(scope),      # the pattern, never the raw path
                    "status": status_holder["status"],
                    "duration_ms": round((time.perf_counter() - start) * 1000, 2),
                },
            )

The access record is emitted in finally, so a request that raises still produces one — with the 500 default status, which is exactly the case Uvicorn's own access log handles least well. _route_template should read scope["route"].path when Starlette has resolved a route, and fall back to a single value for unmatched paths, for the same cardinality reason that applies to controlling label cardinality in Prometheus.

Register it as the outermost middleware so everything inside — including exception handlers — runs with the contextvar set:

from fastapi import FastAPI
from .middleware import RequestContextMiddleware

app = FastAPI()
app.add_middleware(RequestContextMiddleware)     # added last = outermost
Where the request ID is in scope, and where it is not The ASGI stack drawn from the outside in. Uvicorn's protocol layer sits outermost and is where the built-in access logger renders its line; nothing set by application middleware is visible there, which is why that line can never carry a request ID. Inside it, the request context middleware sets the contextvar and starts the timer. Inside that, Starlette's exception middleware and the router run, then the endpoint. Every layer inside the context middleware sees the request ID, including exception handlers, which is why registering it outermost matters: registered inside the exception middleware, a handled 500 would be logged without the id. Background tasks started during the request inherit the context at creation time, so they keep the id; tasks started after the response has been sent do not. the stack, outside in — the dashed band is where your context exists Uvicorn protocol layer uvicorn.access renders its line here — no application context is in scope yet RequestContextMiddleware — the contextvar is set from here down Starlette exception middleware a handled 500 is logged here — with the request id, because it is inside router → endpoint your handlers, your service layer, your database calls background tasks created here inherit the context — tasks created after the response do not
Register the context middleware outermost. One layer further in and every exception the framework handles is logged without a request ID.

Step 4 — Check the reload and worker paths. --reload re-executes the module in a child process, and --workers N forks after startup. A dictConfig call at module import runs in each child; a call guarded by if __name__ == "__main__" does not. Passing log_config avoids the question entirely, which is the main argument for it.

Four start modes, four places the config has to apply Four ways a FastAPI service is started, with the process in which logging is configured marked in each. A single Uvicorn process applies log_config once at startup, which is the simple case everybody tests. Under reload, a supervisor process watches files and re-executes the application in a child, so a configuration applied only under an if name equals main guard never runs in that child and the child logs with defaults. Under multiple workers, the parent spawns worker processes that each import the application module, so an import-time dictConfig call runs per worker while a guarded one does not. Under gunicorn with Uvicorn workers there are two configuration systems: gunicorn's own logconfig_dict in the master and Uvicorn's log_config in each worker, and both must describe the same handlers or the master's lifecycle records and the workers' request records end up in different formats. A footer notes that passing log_config to Uvicorn is what makes the middle two cases work without thinking about them. where does the config actually get applied? single process uvicorn · config here the case everybody tests locally always works --reload supervisor child · re-executes a guarded dictConfig never runs in the child --workers 4 parent worker worker each imports the module import-time config runs 4× gunicorn + uvicorn master · logconfig_dict worker · log_config two config systems both must agree passing log_config to Uvicorn is what makes the middle two work without thinking about it — Uvicorn applies it in whichever process ends up serving, which an if-name-equals-main guard cannot promise
The single-process column is the one that always works, and the only one most services test. The other three are where a guarded dictConfig call quietly does nothing.

Configuration options

Option Where Default Recommended
log_config uvicorn.run Uvicorn's colour config your dict
uvicorn.access logger enabled, text disabled; emit from middleware
uvicorn.error logger text JSON, level INFO
propagate uvicorn loggers True False when they carry handlers
Middleware order add_middleware — context middleware added last
access_log uvicorn.run True False when you emit your own
--reload CLI off development only; verify config applies in the child

Verification

uvicorn app:app --log-config logging.json --port 8000 &
curl -s -H 'X-Request-ID: r-9f3c' localhost:8000/orders/1 > /dev/null

Expected Output:

{"asctime": "2026-08-02 12:58:03,110", "levelname": "INFO", "name": "uvicorn.error", "message": "Application startup complete."}
{"asctime": "2026-08-02 12:58:07,442", "levelname": "INFO", "name": "app.orders", "message": "order fetched", "request_id": "r-9f3c", "order_id": 1}
{"asctime": "2026-08-02 12:58:07,443", "levelname": "INFO", "name": "app.access", "message": "request", "request_id": "r-9f3c", "method": "GET", "route": "/orders/{order_id}", "status": 200, "duration_ms": 4.18}

Three records, one shape, one request_id joining them — and the access record carries the route template rather than /orders/1. Then confirm the failure path: an endpoint that raises must still produce an access record, with status 500 and the same ID.

Common mistakes

Startup lines are coloured text and everything else is JSON

Error signature: the log backend parses application records and stores Uvicorn's as unstructured text. Root cause: log_config was never replaced, so Uvicorn's default colour formatter is still installed on uvicorn.error. Remediation: pass the full dict as log_config; do not rely on a later dictConfig call to override it.

The request ID is missing from records inside exception handlers

Error signature: normal records carry request_id, records logged while handling a 500 do not. Root cause: the context middleware was registered inside Starlette's exception middleware. Remediation: add it last so it wraps everything, and set the contextvar before calling the inner app.

Records appear twice under --workers

Error signature: duplicate lines, doubling with each worker. Root cause: handlers attached both to the uvicorn loggers and to the root, with propagation left on. Remediation: set propagate: False on every uvicorn logger you give handlers to.

What belongs in the access record

Replacing Uvicorn's access log means deciding what yours contains, and the default set is worth more thought than it usually gets. Six fields cover almost every question anyone asks of an access log.

The route template, not the path. /orders/{order_id} rather than /orders/8812. The concrete path is available in the trace; the template is what makes the log aggregatable, and it is the same reasoning that applies to metric labels.

The status and the duration. Both obvious, both worth stating: status as an integer so range queries work, duration in milliseconds as a float with a sensible precision. Two decimal places is plenty — microsecond precision on a network-bound operation is noise.

The request ID and the trace ID. The first for correlation with anything that only has a request ID, the second for the trace. Carrying both during a migration is fine; carrying both permanently is a sign the migration never finished.

The client identity, carefully. The authenticated principal — a user ID, a service account, an API key fingerprint — is the field that turns an access log into something you can answer security questions with. The raw client address is much less useful behind a load balancer, and the forwarded header it comes from is caller-controlled, so treat it as untrusted input.

logger.info(
    "request",
    extra={
        "route": route_template,          # the pattern
        "method": scope["method"],
        "status": status_holder["status"],
        "duration_ms": round(elapsed * 1000, 2),
        "request_id": rid,
        "principal": principal_id,        # who, not where
    },
)
Field Type Why it earns its place
route string aggregatable; bounded by the route table
method string five values, and half the queries need it
status integer range queries; error-rate panels
duration_ms float the only latency number in the log stream
request_id string joins to everything else about this request
principal string the field security questions are asked of

Streaming responses and WebSockets

Two request shapes break the assumption that a request has a duration. A streaming response returns headers early and then produces a body for an arbitrary period, so the duration measured at http.response.start is meaningless and the duration measured at the end may be minutes. A WebSocket has no response at all in the HTTP sense; the ASGI scope type is websocket, and a middleware written for http must pass it through untouched rather than trying to time it.

The practical handling is to record two fields for streaming responses — time to first byte and total duration — and to emit a separate record type for WebSocket connect and disconnect events, with the connection duration on the second. Trying to force either shape into the request record produces a latency distribution with a tail that is entirely artefact.

Sizing the pipeline

An access record per request is the largest single source of log volume in most services, and it is also the most valuable, which makes it the wrong thing to sample and the right thing to keep compact. Two decisions carry most of the weight: keep the field set to the six above plus whatever your domain genuinely needs, and exclude probe traffic entirely rather than sampling it — a readiness probe every second across twenty replicas is 1.7 million access records a day that answer a question the readiness metric already answers.

PROBE_ROUTES = frozenset({"/healthz", "/readyz", "/metrics"})

if route_template not in PROBE_ROUTES:
    logger.info("request", extra={...})

That single condition typically removes more volume than every other optimisation on this page combined, and it removes nothing anyone would have queried.

Frequently Asked Questions

Why do my logs come out twice under Uvicorn?

Uvicorn's default config attaches handlers to uvicorn, uvicorn.error and uvicorn.access, and your own config attaches one at the root. Records from those loggers are handled by their own handler and then propagate up to yours. Either set propagate to False on the uvicorn loggers when you give them handlers, or give them none and let the root handle everything.

Should I use log_config=None or pass a dict?

Pass a dict when the configuration is static — it keeps the wiring in one declarative place that Uvicorn applies at exactly the right moment. Use log_config=None plus your own dictConfig call when the configuration must be computed, but then you own the ordering, and under reload or multiple workers you must ensure the call actually runs in each child process.

How do I get the request ID into Uvicorn's access log line?

You cannot, cleanly — uvicorn.access builds its message from a fixed set of scope values before your filter runs, and the contextvar is set by middleware that runs later in the ASGI chain. The practical answer is to disable uvicorn.access and emit your own access record from the outermost middleware, where you have the request ID, the route template, the status and the duration all at once.

Does gunicorn with Uvicorn workers change any of this?

Yes. Gunicorn configures logging in the master process before importing your app, then each Uvicorn worker configures again in the child. Configure gunicorn through logconfig_dict and pass the same shape to the worker through log_config, or the master's lifecycle records and the workers' request records end up in two different formats.

Related Guides