Structured Logging from Day One

Series: Building Backarch, engineering decisions from building backarch.com

A FastAPI application with default logging starts writing to stdout on day one. It looks fine. Then you get your first production bug and discover that your logs tell you what happened but not which user, not which request, and not in what order. You spend the next two hours adding context to 40 log calls you already wrote.

Structured logging with bound context isn't a refactor you do after the fact. It's a default you set up before writing your first route.

What plain logging costs you at 2am

Python's logging module writes strings. A string log is a one-way door: you can read it, you can grep it, but you can't aggregate it, filter it programmatically, or join it with another event from the same request.

INFO:     Request received
ERROR:    Something went wrong
INFO:     Done

Three events. No request ID. No user ID. No timestamp beyond what the log handler adds. If two requests interleaved, which they will in any async application, you have no way to reconstruct which events belong to which request.

The fix isn't grep patterns and timestamps. It's making every log event a structured object from the start.

structlog: bind once, log everywhere

structlog wraps the standard logging infrastructure and adds two things: a processor pipeline for transforming log events, and a bound logger that carries context through a call chain without you passing it explicitly.

Setup at application startup:

# app/core/logging.py
import structlog
 
def configure_logging(debug: bool = False) -> None:
    shared_processors = [
        structlog.stdlib.add_log_level,
        structlog.processors.TimeStamper(fmt="iso"),
        structlog.contextvars.merge_contextvars,   # inject async-safe context
        structlog.processors.StackInfoRenderer(),
    ]
 
    if debug:
        processors = shared_processors + [structlog.dev.ConsoleRenderer(colors=True)]
    else:
        processors = shared_processors + [
            structlog.processors.dict_tracebacks,
            structlog.processors.JSONRenderer(),
        ]
 
    structlog.configure(
        processors=processors,
        wrapper_class=structlog.make_filtering_bound_logger(
            logging.DEBUG if debug else logging.INFO
        ),
        logger_factory=structlog.PrintLoggerFactory(sys.stdout),
        cache_logger_on_first_use=True,
    )

Two output modes off one config: colourised, human-readable in dev, JSON for CloudWatch or Datadog in production, decided by a single boolean. merge_contextvars is the processor that makes bound context show up in every event. It pulls key-value pairs from a context store that survives across await boundaries, unlike threading.local(), which resets when you switch coroutines.

Binding at the ASGI middleware boundary

The request ID and user ID need to be available in every log event within a request. The right place to bind them is raw ASGI middleware, before any route handler runs:

# app/middleware/request_logging.py
import structlog
from app.core.logging import get_logger
 
log = get_logger("middleware.request")
 
class RequestLoggingMiddleware:
    async def __call__(self, scope, receive, send):
        if scope["type"] != "http":
            await self.app(scope, receive, send)
            return
 
        headers = dict(scope.get("headers", []))
        incoming = headers.get(b"x-request-id", b"").decode()
        request_id = incoming or f"req_{uuid.uuid4().hex[:12]}"
 
        # Best-effort JWT subject decode for logging only.
        # Real verification happens later in get_current_user.
        user_id = _extract_sub(headers)
 
        structlog.contextvars.clear_contextvars()
        structlog.contextvars.bind_contextvars(
            request_id=request_id,
            user_id=user_id,
            service="backarch-api",
        )
 
        try:
            await self.app(scope, receive, send)
        finally:
            structlog.contextvars.clear_contextvars()

One request-scoped http_request event closes out every request, with the method, path, status code, and duration attached directly rather than bound to context for the whole request:

def _log_request(method, path, status_code, duration_ms):
    level = log.error if status_code >= 500 else log.warning if status_code >= 400 else log.info
    level("http_request", method=method, path=path, status_code=status_code, duration_ms=duration_ms)

Now every log.info(...) anywhere in the call chain, however many layers deep, automatically carries request_id, user_id, and service, without passing a logger object down through every function signature.

What every log event looks like

{
  "event": "health_score_complete",
  "level": "info",
  "timestamp": "2026-06-07T14:23:11.842Z",
  "request_id": "req_a1b2c3d4e5f6",
  "user_id": "a1b2c3d4-...",
  "service": "backarch-api",
  "score": 62,
  "issues": 3
}

Every field is queryable. In CloudWatch Logs Insights: filter user_id = "a1b2c3d4" | sort timestamp. In Datadog: @request_id:req_a1b2c3d4e5f6 shows every event from that request in order. In a local terminal, jq 'select(.level == "error")' filters without grep patterns.

The service field identifies which process emitted the event, backarch-api for the main application. When an error surfaces, that's the first thing that tells you whether you're looking at a request-path bug or something in a background job.

In a system like backarch.com, where a single user interaction triggers AI calls, canvas health scoring, and pricing lookups in parallel, request_id correlation is what makes debugging tractable. Without it, interleaved async events from concurrent requests become indistinguishable noise.

The logger is a module-level import

Each module gets its own bound logger:

# app/services/health/graph.py
from app.core.logging import get_logger
 
log = get_logger(__name__)
 
async def compute_health_score(diagram: dict, constraints: dict) -> HealthResult:
    log.info("health_score_start", node_count=len(diagram["nodes"]))
    result = _run_rules(diagram, constraints)
    log.info("health_score_complete", score=result.score, issues=len(result.issues))
    return result

get_logger(__name__) is a thin wrapper over structlog.get_logger, kept in one place so the logging setup is never imported two different ways across the codebase.

No dependency injection. No logger parameter in function signatures. The module-level logger picks up the request context from contextvars at log time, not at function entry. This matters in deep call chains: a helper five layers down from the route handler logs with full request context, with no changes to any intermediate function signature.

Background jobs don't inherit the request context, and that's fine

The clear_contextvars call at middleware entry assumes a request is starting. Background jobs don't go through ASGI middleware at all, so binding request context to them isn't even the right model.

At backarch.com, pricing_cron is a standalone package: its own requirements.txt, its own entry point, run outside the main application process entirely. It doesn't import structlog. It sets up plain stdlib logging with a FileHandler writing to its own log file, appended on every run:

# pricing_cron/run_pricing_cron.py
import logging
 
LOG_FILE = Path(__file__).parent / "pricing_cron.log"
logging.getLogger().addHandler(logging.FileHandler(LOG_FILE, encoding="utf-8"))
logger = logging.getLogger("pricing_cron")
 
logger.info("Fetching AWS pricing...")

That's not an inconsistency to fix, it's the isolation working as intended. The API's structured logging exists to correlate concurrent, interleaved requests inside one process. A weekly batch job with no concurrent requests to disambiguate doesn't need contextvars-based correlation, a plain append-only log file that's grep-able after the fact is the right tool for a process that runs once, does its work sequentially, and exits.

What you lose when you bolt it on later

Adding structured logging to a mature application means finding every logger.info("some string") call and deciding what context it needs. If the context isn't already threaded through the call chain, you have two bad options: pass the logger (or a context dict) down through every function, or accept that those log events will never carry request context.

Structlog with contextvars is the third option, but you have to set it up before writing those log calls. The bind-at-middleware pattern only works if middleware runs before your code. That's true on day one; retrofitting it onto a working application means reorganising the middleware stack and auditing every function that currently calls the old logging.getLogger().

At backarch.com, structlog was one of the first dependencies added to the project, before most routes were written. The argument: if you're going to write logs, they should be queryable from day one. Adding it later would have meant touching every log call in the codebase.

Logs written without context are notes that lose their meaning the moment you forget the conversation that produced them. A structured log event is a self-contained fact: this event, this user, this request, this moment. The context doesn't depend on your memory of the incident.