Structured logging in Python

Structured logging means emitting machine-parseable events (one JSON object per line) instead of prose. "Payment failed for order 42 after 3 retries" needs a regex to analyze; {"event": "payment_failed", "order_id": 42, "retries": 3} is immediately queryable in any log backend (05_elk_stack.md). Log events with fields, not sentences with values baked in.

stdlib logging: where plain formatting falls short

The standard logging pipeline (logger → handler → formatter) formats records into strings. Two problems:

• logger.info("payment failed order=%s", order_id) — the field is interpolated away; the backend sees one opaque string.
• extra={"order_id": 42} attaches real fields, but the default formatter ignores them and nothing enforces consistency.

Minimal JSON with stdlib only (via python-json-logger):

import logging
from pythonjsonlogger.json import JsonFormatter

handler = logging.StreamHandler()          # stdout — the 12-factor way
handler.setFormatter(JsonFormatter("%(timestamp)s %(level)s %(name)s %(message)s",
                                   timestamp=True))
logging.basicConfig(handlers=[handler], level=logging.INFO)

logging.getLogger("billing").info("payment_failed", extra={"order_id": 42, "retries": 3})
# {"timestamp": "...", "level": "INFO", "name": "billing", "message": "payment_failed", "order_id": 42, "retries": 3}

Workable, but field discipline stays manual. That’s the gap structlog fills.

structlog — the standard answer

structlog builds each log entry as a dict flowing through a processor pipeline, with first-class context binding:

import structlog

structlog.configure(
    processors=[
        structlog.contextvars.merge_contextvars,   # pull in request-scoped context
        structlog.processors.add_log_level,
        structlog.processors.TimeStamper(fmt="iso"),
        structlog.processors.dict_tracebacks,      # exceptions as structured data
        structlog.processors.JSONRenderer(),       # prod; ConsoleRenderer() for dev
    ],
)

log = structlog.get_logger()
log.info("payment_failed", order_id=42, retries=3, amount_cents=1999)

The two features that matter in services:

• bind() / contextvars — attach context once, every subsequent log line carries it:

# middleware, once per request
structlog.contextvars.bind_contextvars(request_id=req_id, user_id=user.id)
# any log call anywhere in the request now includes request_id and user_id

contextvars make this async-safe — each task sees its own context. The full request-ID propagation story (FastAPI middleware, httpx, Celery, Kafka) is 10_correlation_ids_async.md.

• Dev/prod split — same call sites, ConsoleRenderer (pretty, colored) locally and JSONRenderer in prod. Point structlog at stdlib handlers (stdlib.BoundLogger + ProcessorFormatter) when you also need third-party libraries’ stdlib logs rendered through the same pipeline.

What goes in every event

Keep event constant and put variables in fields: log.info("payment_failed", reason=...), never log.info(f"payment failed: {reason}") — f-strings in log calls quietly destroy structure (and evaluate even when the level is off).

Never log: passwords, tokens, full card numbers, raw PII. Logs outlive databases in backups and have looser access control. Add a redaction processor for known-sensitive keys.

Canonical log lines

High-signal pattern: emit one wide event per request at completion, carrying everything — route, status, duration, user, DB time, retries. One line answers “what happened on this request” without joining ten fragments; per-request cost stays predictable. Middleware accumulates fields on the contextvars, logs once in the finally.

Async and performance notes

• Handlers write synchronously — a slow destination stalls the event loop. Logging to stdout is fast; if you must ship to a network sink from-process, isolate with QueueHandler/QueueListener. Preferred: don’t ship from the app at all — stdout + node-level collector (../13_architecture_design/20_twelve_factor_app.md, 05_elk_stack.md).
• Levels are a cost dial: INFO for events you’d query, DEBUG gated off in prod (or sampled), WARNING+ for things a human might act on. Log volume is billed per GB in every backend.
• Exceptions: log.exception("task_failed", task_id=...) inside except — with dict_tracebacks the stack becomes structured data, not a 40-line string blob.

Common pitfalls

• f-string interpolation at call sites — kills queryability, the single most common regression.
• Unbounded field names (dict keys from user data) — mapping explosion in Elasticsearch (05_elk_stack.md); values vary, names must not.
• Two logging worlds — your app logs JSON but uvicorn/gunicorn access logs stay plaintext; route them through the same formatter or disable and log requests yourself.
• Binding context but never clearing it (clear_contextvars per request) — leaked fields from the previous request on reused workers.

Interview angle

• “What is structured logging and why?” — events with fields vs prose; queryability, aggregation, alerting; show a before/after line.
• “How do you get a request ID into every log line of an async service?” — contextvars + middleware bind; name why thread-locals fail under asyncio.
• “structlog vs stdlib?” — stdlib can emit JSON, structlog adds processor pipeline + context binding + dev/prod rendering; they integrate rather than compete.
• “What must never be logged?” — secrets/PII, plus the redaction-processor mitigation; mention logs’ long retention tail.