lesson 238 Observability & Operations · advanced

Follow one request with a trace

A slow or failed request passes through many steps: checking the user, querying the database, rendering. Tracing gives the request one trace id and records each step as a span with its parent and duration, so you can see where the time went and where it broke.

You'll be able to

Explain traces and spans: one trace id per request, one span per step, each span pointing at its parent
Record nested spans with a context manager that measures time with an injected clock and notes errors
Carry the current trace id into log records with a contextvars.ContextVar and a logging filter

The idea

Metrics tell you that p95 latency doubled; logs tell you about individual events. Neither tells you *which step of which request* was slow. Tracing does. Each incoming request gets a trace id. Every step it goes through (authentication, a database query, a call to another service) is a span: a name, its own id, the id of the span it ran inside (its parent), a start and a duration, and an error if it failed. The spans of one trace form a tree, and the slow branch stands out.

In real systems the ids are random (secrets.token_hex(8), the Secure Python module) and spans are sent to a tracing service. The idea fits in a few lines of Python: a context manager (see Decorators & Context Managers) opens a span, a stack remembers which span is open so the next one knows its parent, and finally records the duration even when the step fails.

Run each example to see what it prints. Running examples doesn't count toward progress.

example-1.py · Spans for one request

from contextlib import contextmanager

class Tracer:
    def __init__(self, clock):
        self.clock = clock
        self.finished = []
        self.open = []
        self.count = 0

    @contextmanager
    def span(self, trace_id, name):
        self.count += 1
        record = {"trace": trace_id, "span": f"s{self.count}", "name": name,
                  "parent": self.open[-1]["span"] if self.open else None, "error": None}
        start = self.clock()
        self.open.append(record)
        try:
            yield record
        except Exception as err:
            record["error"] = type(err).__name__
            raise
        finally:
            self.open.pop()
            record["ms"] = round((self.clock() - start) * 1000)
            self.finished.append(record)

readings = iter([0.000, 0.002, 0.010, 0.011, 0.241, 0.242, 0.250, 0.252])
tracer = Tracer(clock=readings.__next__)

with tracer.span("t-7f3a", "GET /repos/lumen-labs/pyauth/stars"):
    with tracer.span("t-7f3a", "check token"):
        pass
    with tracer.span("t-7f3a", "query stars"):
        pass
    with tracer.span("t-7f3a", "render json"):
        pass

for s in tracer.finished:
    print(s["span"], "parent", s["parent"], s["name"], s["ms"], "ms")

Spans explain the timing; logs explain the details. Joining them needs the trace id on every log record, but passing it as a parameter through every function is impractical. A `contextvars.ContextVar` holds a value for the current request: set it when the request starts, reset it when it ends, and a logging filter copies it onto every record. Reading a context variable that was never set, and has no default, is an error:

example-2.py · A context variable with no value

import contextvars

current_trace = contextvars.ContextVar("current_trace")
print(current_trace.get())

example-3.py · Every log record carries the trace id

import contextvars
import logging
import sys

current_trace = contextvars.ContextVar("current_trace", default="-")

class TraceFilter(logging.Filter):
    def filter(self, record):
        record.trace_id = current_trace.get()
        return True

log = logging.getLogger("api")
log.handlers.clear()
handler = logging.StreamHandler(sys.stdout)
handler.setFormatter(logging.Formatter("%(trace_id)s %(levelname)s %(message)s"))
handler.addFilter(TraceFilter())
log.addHandler(handler)
log.setLevel(logging.INFO)
log.propagate = False

def load_stars(repo):
    log.info("querying stars for %s", repo)
    return 2

def handle(trace_id, repo):
    token = current_trace.set(trace_id)
    try:
        log.info("request started")
        stars = load_stars(repo)
        log.info("responded with %d stars", stars)
    finally:
        current_trace.reset(token)

handle("t-7f3a", "lumen-labs/pyauth")
handle("t-91c0", "tidewater/easystore")
log.info("worker idle")

When to use it: anywhere one user action passes through several steps or services, which is most web and pipeline work. Mistakes to avoid: spans that record only successful steps (time and errors go in finally/except); forgetting reset, so a trace id leaks into the next request's logs; and ids that aren't unique (a counter per process is fine for a demo, not across servers).

Review

A trace follows one request; each step is a span with its own id, its parent's id, a duration and any error.
A context manager opens spans, a stack provides the parent, and finally records the duration even on failure.
A ContextVar plus a logging filter puts the trace id on every log record; always reset it.
Next: some failures are temporary. Retrying them well, with backoff.