Week 12: Observability & Production Readiness

1. Structured Logs & Request IDs

A log line like logging.info(f"Task {task_id} updated") is fine to read in a terminal and useless at scale: once logs are shipped to something like Loki, CloudWatch, or an ELK stack, you want every field — timestamp, level, logger name, the actual message, and any request-specific context — queryable on its own, not buried inside a formatted sentence. A JSON log formatter emits one JSON object per line instead, so "show me every log line for request abc-123" becomes a simple field filter rather than a regex:

import json
import logging
from datetime import datetime, timezone

class JsonFormatter(logging.Formatter):
    def format(self, record: logging.LogRecord) -> str:
        payload = {
            "timestamp": datetime.now(timezone.utc).isoformat(),
            "level": record.levelname,
            "logger": record.name,
            "message": record.getMessage(),
            "request_id": getattr(record, "request_id", None),
        }
        return json.dumps(payload)

getattr(record, "request_id", None) reads a field that isn't on LogRecord by default — it has to be attached to every record some other way, which is exactly what a request-scoped correlation ID needs. The tricky part in an async app is that a plain module-level variable would leak between concurrent requests being handled interleaved on the same event loop; a contextvars.ContextVar is the async-safe equivalent of "thread-local" storage, correctly isolated per request even as different requests' coroutines take turns running:

import uuid
from contextvars import ContextVar
from starlette.middleware.base import BaseHTTPMiddleware

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

class RequestIdMiddleware(BaseHTTPMiddleware):
    async def dispatch(self, request, call_next):
        incoming = request.headers.get("x-request-id")
        request_id = incoming or str(uuid.uuid4())
        request_id_var.set(request_id)

        response = await call_next(request)
        response.headers["X-Request-Id"] = request_id
        return response

A logging.Filter that reads request_id_var.get() and stamps it onto every LogRecord before it reaches the formatter ties the two pieces together: every log statement anywhere in the call stack for that request — in a route, a service function, a repository — automatically carries the same request_id, with no need to thread it through every function signature by hand. Honoring an incoming X-Request-Id header (instead of always minting a fresh one) also lets an upstream gateway or another service propagate its own ID through, so one logical request stays correlated end to end.

2. Liveness & Readiness Checks

A single /health endpoint that just returns 200 OK answers the wrong question the moment you're running behind an orchestrator like Kubernetes. What you actually need are two distinct checks that trigger two distinct actions:

@app.get("/health/live")
async def liveness():
    # No dependency checks here on purpose -- see below.
    return {"status": "alive"}

@app.get("/health/ready")
async def readiness():
    await database.execute(text("SELECT 1"))
    return {"status": "ready"}

Liveness answers "is this process itself still functioning, or is it deadlocked/hung?" If it fails, the orchestrator's only correct response is to kill and restart the container — so a liveness check should touch nothing external. Do not check the database here: if Postgres has a brief network blip, every replica's liveness check fails at once, the orchestrator restarts all of them simultaneously, and you've turned a transient database hiccup into a self-inflicted outage — a restart fixes a hung process, not a database that's temporarily unreachable.

Readiness answers a different question: "can this specific instance serve traffic right now?" That's exactly where dependency checks belong — a failed SELECT 1 means the load balancer should stop routing new requests to this instance without killing it. The process keeps running, keeps retrying its connection to Postgres in the background, and gets added back into rotation automatically the moment /health/ready starts returning 200 again. Same underlying failure, two very different — and both correct — responses, depending on which check you attach it to.

3. Prometheus Metrics & Tracing Context

Prometheus's client library gives you a few metric types; the two you'll reach for constantly are Counter (a number that only goes up, like total requests) and Histogram (which buckets observed values, like request latency, so you can compute percentiles later):

from prometheus_client import Counter, Histogram

REQUESTS = Counter(
    "http_requests_total", "Requests", ["method", "route", "status"]
)
LATENCY = Histogram(
    "http_request_duration_seconds", "Request latency", ["method", "route"]
)

The label you pick for route matters enormously. Labeling with the raw request path — /tasks/42, /tasks/43, /tasks/44 — creates a brand-new time series in Prometheus for every distinct task ID that's ever requested, an unbounded and ever-growing set of series called a cardinality explosion; Prometheus (and whatever's storing this data long-term) will eventually choke on it. The fix is labeling with the route template instead — /tasks/{task_id} — which collapses every task lookup into one bounded series no matter how much data exists. FastAPI exposes this through the matched route on the request scope once routing has resolved:

from starlette.middleware.base import BaseHTTPMiddleware
import time

class MetricsMiddleware(BaseHTTPMiddleware):
    async def dispatch(self, request, call_next):
        start = time.perf_counter()
        response = await call_next(request)
        elapsed = time.perf_counter() - start

        route = request.scope.get("route")
        route_template = route.path if route else "unmatched"

        REQUESTS.labels(request.method, route_template, response.status_code).inc()
        LATENCY.labels(request.method, route_template).observe(elapsed)
        return response

Note that request.scope["route"] isn't populated until FastAPI's routing has actually matched a handler, which happens inside call_next() — reading it before that call would give you nothing. By the time call_next returns, routing has finished, so it's safe to read there.

Metrics tell you that something is slow; distributed tracing tells you where, across service boundaries. A trace ID identifies one logical end-to-end request; each hop or operation within it (an incoming request, an outbound httpx call to another service from Week 9) gets its own span ID nested under that trace. Propagating a trace context header (the W3C traceparent format is the common standard) on every service-to-service call means that once you view a trace in a tool like Jaeger or Tempo, you see the whole request's path across every service it touched, not just the one that happened to log an error. This course won't stand up a full OpenTelemetry collector, but recognizing what a trace/span ID is for — correlating work across process boundaries the way a request ID correlates it within one — is worth internalizing now.

4. Hands-on Exercise

5. Knowledge Check

Four quick questions. Expand each to check your answer.