🐍 Backend with Python · Chapter 13

Structured logging, metrics and tracing

At 3 AM you won't have a debugger — only what your service chose to write down, so decide now what it says, in what shape, and how one request's story gets stitched back together.

Study this lesson free in the app →

The basics

Observability is being able to answer "what is my service doing, and why is this request slow?" from the outside, without shipping new code. It rests on three signals.

The problem it solves: in production you can't attach a debugger or add a print — you only have what the service already emits.

The mental model: metrics tell you that something is wrong, traces tell you where, and logs tell you why.

• Structured logs — one JSON object per event, with fields (request_id, rider, fare_paise) you can filter on, instead of sentences you grep.
• Metrics — cheap numbers aggregated over time: a counter (requests served, only goes up), a gauge (connections in use, up and down), a histogram (latency spread into buckets). For a service, watch RED: rate, errors, duration.
• Percentiles — p99 = 99% of requests were faster than this. Averages hide the slow tail; percentiles show it.
• Traces — one request's journey as a tree of timed spans (handler → DB query → payment call), linked across services by the traceparent header.

The thread that ties all three together is an ID: a request ID in every log line, a trace ID in every span.

Explained

The courier's tracking number

You send a parcel from Chennai to Guwahati through four hubs.

• Metrics are the board at head office: "14,200 parcels today, 1.8% delayed, 95% delivered within 3 days." You learn something is wrong at a glance — but not which parcel.
• Logs are each hub's register: "10:42 — parcel arrived, label smudged, re-labelled." Detailed, but useless unless every entry carries the tracking number.
• A trace is that tracking page: Chennai 2 h → Vijayawada 9 h → Kolkata 31 h → Guwahati 4 h. One look and you know Kolkata is the problem.

The tracking number printed on the parcel and passed hub to hub is the traceparent header. A hub that doesn't copy the number onto its own register breaks the chain — and that's the most common way tracing fails in real services.

JSON logs with a request ID in every line

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

class JsonFormatter(logging.Formatter):
    def format(self, record):
        doc = {"level": record.levelname, "logger": record.name,
               "msg": record.getMessage(), "request_id": request_id.get()}
        doc.update(getattr(record, "fields", {}))
        if record.exc_info:
            doc["exc"] = self.formatException(record.exc_info).splitlines()[-1]
        return json.dumps(doc)

@app.middleware("http")
async def add_request_id(request: Request, call_next):
    rid = request.headers.get("x-request-id") or uuid.uuid4().hex[:12]
    token = request_id.set(rid)
    try:
        response = await call_next(request)
    finally:
        request_id.reset(token)
    response.headers["x-request-id"] = rid
    return response

Calling POST /rides with x-request-id: req-7f3a printed:

{"level": "INFO", "logger": "rides", "msg": "fare quoted", "request_id": "req-7f3a", "rider": "asha", "fare_paise": 17000}
{"level": "ERROR", "logger": "rides", "msg": "surge calc failed", "request_id": "req-7f3a", "exc": "ZeroDivisionError: division by zero"}
response header: req-7f3a
{"level": "INFO", "logger": "rides", "msg": "outside any request", "request_id": "-"}

The handler never mentions the ID — the contextvar carries it. A log.debug in the same handler printed nothing: the logger level was INFO.

Why a contextvar, and what to put in a log line

An async server runs hundreds of requests interleaved on one thread. A global CURRENT_REQUEST_ID would be overwritten by whichever request ran last. A ContextVar gives each asyncio task (and each threadpool call FastAPI makes for a sync endpoint — it copies the context) its own value. Always reset(token) in finally.

Levels (numeric): DEBUG 10 < INFO 20 < WARNING 30 < ERROR 40 < CRITICAL 50. Production runs at INFO; a record below the logger's level is dropped before formatting.

A good log line has: an event name that doesn't change ("fare quoted", not an f-string with the fare inside), fields as keys, the request ID, and for errors log.exception(...) so the traceback is captured.

Never log: passwords, tokens, full card numbers, OTPs, Aadhaar numbers. Logs get copied to more places than your database does.

Don't log what a metric should count. "Request served" at INFO on 5,000 req/s is 430 million lines a day — and you still can't graph latency from it cheaply.

The average that lied

1,000 requests: 980 normal (~45 ms) and 20 that hit a slow partner call (1.8–2.6 s). Computed with a nearest-rank percentile:

def pct(data, p):
    s = sorted(data)
    k = max(1, math.ceil(p / 100 * len(s)))
    return s[k - 1]

print("mean", round(statistics.mean(lat), 1))   # mean 88.1

Counter, gauge, histogram — the three metric types

class Counter:
    def inc(self, n=1): self.value += n          # only ever goes up
class Gauge:
    def set(self, v): self.value = v              # goes up and down
class Histogram:                                  # upper bounds in ms, last = +Inf
    def observe(self, v):
        self.counts[bisect.bisect_left(self.buckets, v)] += 1
        self.sum += v

for ms, status in [(31, 200), (48, 200), (52, 200), (40, 500), (900, 200), (2300, 504)]:
    requests.inc()
    if status >= 500: errors.inc()
    latency.observe(ms)

rate: requests = 6
errors: 2 (33%)
duration buckets: {'25': 0, '50': 3, '100': 1, '250': 0, '500': 0, '1000': 1, '+Inf': 1}
in_flight gauge: 3

That's RED for one endpoint: Rate (counter, graphed as per-second change), Errors (counter of 5xx), Duration (histogram). For resources — CPU, the DB pool, a queue — use USE: Utilisation, Saturation (how much is waiting), Errors.

Why histograms and not stored percentiles: bucket counts from 40 pods add up; p99s from 40 pods don't. Prometheus stores buckets cumulatively (le="50" includes everything ≤ 50) and estimates quantiles from them; the idea is the same.

Spans: a request as a tree of timings

Real output: db.select rider 13 ms, http payments.charge 185 ms, POST /rides 198 ms. One glance: 93% of this request is the payment call. OpenTelemetry is the standard that does exactly this for you — spans, parent links, export to a backend — through instrumentation packages for FastAPI, httpx and SQLAlchemy. It isn't installed here, so this is the mechanism in plain Python, not its API.

Crossing services: the traceparent header

Inside one process the parent link lives in a contextvar. Across a network call it travels in the W3C Trace Context header:

traceparent: 00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01
             ││ └──────── trace-id (32 hex) ─────┘ └ parent-id (16) ┘ └ flags
             └ version

• trace-id: the same for every span in the whole request, across every service.
• parent-id: the caller's span id. The callee makes a new span id for itself and records this as its parent.
• flags 01 = sampled (record this trace). All-zero ids are invalid.

def child_traceparent(incoming):
    m = TRACEPARENT.match(incoming)
    if not m:
        return new_traceparent()              # bad header: start a fresh trace
    trace_id, _parent_span, flags = m.groups()
    return f"00-{trace_id}-{secrets.token_hex(8)}-{flags}"

00-4bf92f3577b34da6a3ce929d0e0e4736-3d898714fad67daf-01
same trace: True
new span:   True
55 00-

Log the trace-id as a field too, and you can jump from a slow span straight to its log lines.

Sunday 26 May 2024, 9:10 PM — IPL final night

Food-delivery checkout. The dashboard's average latency reads 140 ms, flat. Support has 600 tickets saying "payment stuck".

1. Metrics: p50 = 120 ms, but p99 = 8.2 s, starting 21:04. Error rate 0.4% → 3.1%. The DB pool gauge sits at 50/50 — saturated (the S in USE).
2. Traces: sample a slow checkout. The tree shows POST /checkout 8.1 s, of which http wallet.debit is 7.9 s — the wallet partner, not us.
3. Logs: filter trace_id = … → {"msg": "wallet debit timeout", "attempt": 3}. We retry three times, each holding a DB connection while waiting. That's why the pool is full and unrelated endpoints slowed too.

Fix that night: release the DB connection before the partner call, and cap the partner timeout at 2 s (next lesson). Without percentiles, a trace and a request-scoped log line, this is three hours of guessing instead of eleven minutes.

Words to know

In two minutes

• Three signals: metrics say something is wrong, traces say where, logs say why.
• Structured logs are one JSON object per event with stable message names and fields you can filter on.
• A request ID set by middleware in a ContextVar appears in every log line without passing it around.
• Metrics come in three types: counter (only up), gauge (up and down), histogram (distribution in buckets).
• RED for services: rate, errors, duration. USE for resources: utilisation, saturation, errors.
• Use percentiles, not averages: p99 shows the tail; histograms can be merged across pods, percentiles can't.
• A trace is a tree of timed spans; the W3C traceparent header carries trace-id and parent span id across services.
• Bounded labels, no secrets in logs, and never drop traceparent on outgoing calls.

Test yourself

There are 10 questions, 3 puzzles and 5 recall cards for this lesson in the app — the recall cards come back on later days, just before you would forget.