Lesson 9 - Tracing - Spans, Replay, Redaction

Code: agentic-course/agentic/trace.py Tests: agentic-course/tests/test_loop.py Run it: python3 -m unittest tests.test_loop -v Concept: Tracing and Observability for LLM Apps covers the theory and the interview framing, without code.

What you will build

• A Tracer that records one run as a nested span tree, where nesting comes from a context manager rather than from you threading parent ids through every call.
• Per-span capture of the things that let you diagnose a failure you cannot reproduce: model, finish reason, tokens, cost, requested tools, tool outcome, duration.
• tree() for a human reading a broken run, export() as JSON Lines for a backend that ingests it.
• Key-based redaction for obvious secrets, plus the retention strategy that does the work redaction cannot do.

The idea

A unit test failure is a reproduction. You re-run it, you get the same failure, you bisect until the cause is cornered. An agent failure is not like that. Sampling is stochastic, the provider updates the model behind an alias you do not control, retrieval ties break differently, a tool times out at 9.8 seconds today and 3 seconds tomorrow. Re-running a failed agent run is not reproducing the bug — it is rolling the dice again and hoping for the same face.

So the trace is not telemetry you bolt on for dashboards. The trace is the bug report. It is the only artefact that survives the run, and if it is missing a field you needed, that failure is now permanently unexplainable.

The analogy worth holding is a flight data recorder, not an eyewitness. Investigators do not ask the aircraft to crash again; they read the recorder, which captured enough parameters to reconstruct the sequence. The standard a recorder is held to is replayability, and the same standard applies here — a trace you cannot replay is an anecdote. Replayable means something concrete: for the step that failed you captured the messages that went in, the tool arguments, the model identity and the prompt version, so you can re-drive that one step against a pinned model and watch it break.

Why the unit is a span tree, not a log line

One user action fans out. “Can I still refund order 4471?” becomes three model calls, two tool calls, and in a real system a retry inside one of those tools. A log line per event gives you a flat stream you reassemble by eye, sorting timestamps and guessing which model call belonged to which retry. A tree gives you that structure for free, and it turns “where did the four seconds go” into a subtraction instead of an argument.

Bad is print, which tells you things happened and nothing about how they relate or what they cost. Good is a structured event per action carrying a run id you can group by — a real improvement, and where most teams stop. It still flattens the causal structure: once a retry sits inside a tool call inside step three, “which model call belongs to which attempt” becomes an inference you make at 2am. Great is nesting that is structural, so it cannot be reassembled wrongly:

with tracer.span("agent.run", "run", task=task) as run_span:
    with tracer.span("model.call.0", "model") as m_span:
        m_span.set(input_tokens=120, output_tokens=8)

Span and Tracer

@dataclass
class Span:
    name: str
    kind: str  # "run" | "model" | "tool" | "retrieval" | "eval"
    span_id: str = field(default_factory=lambda: uuid.uuid4().hex[:12])
    parent_id: str | None = None
    started_at: float = field(default_factory=time.monotonic)
    ended_at: float | None = None
    attributes: dict[str, Any] = field(default_factory=dict)
    error: str | None = None

duration_ms is a property derived from started_at and ended_at, so an unfinished span still reports a live duration instead of None. kind is a small closed vocabulary on purpose: it is what makes of_kind("model") a useful query and what lets a dashboard say “p95 of tool spans” without string-matching on names.

Tracer keeps a stack. span() reads the top of the stack as its parent, pushes itself, and the context manager pops on exit — which is why nesting needs no bookkeeping at the call site:

def span(self, name: str, kind: str = "step", **attrs: Any) -> "_Ctx":
    s = Span(
        name=name,
        kind=kind,
        parent_id=self._stack[-1].span_id if self._stack else None,
        attributes=dict(attrs),
    )
    self.spans.append(s)
    self._stack.append(s)
    return Tracer._Ctx(self, s)

_Ctx.__exit__ is where the correctness lives. It stamps ended_at, records error as f"{exc_type.__name__}: {exc}" when the block raised, pops the stack, and returns False # never swallow. So an exception lands on the span that raised it — which is how you find the failing step without reading the whole tree — and the tracer never changes control flow. A tracer that swallows exceptions is worse than no tracer, because your observability layer has become a source of bugs. NullTracer keeps call sites clean for the same reason: it accepts spans and records nothing, so the agent loop never branches on whether tracing is on.

What to capture per span, and why each field earns its place

This is the real call site inside Agent.run, not a simplified version:

with self.tracer.span(f"model.call.{i}", "model") as m_span:
    completion = self.model.complete(messages,
                                     tools=self.registry.schemas() or None,
                                     max_output_tokens=self.max_output_tokens,
                                     temperature=self.temperature)
    step_cost = self.budget.cost_of(completion.input_tokens, completion.output_tokens)
    m_span.set(
        model=completion.model,
        finish_reason=completion.finish_reason,
        input_tokens=completion.input_tokens,
        output_tokens=completion.output_tokens,
        cost=step_cost,
        requested_tools=[tc.name for tc in completion.tool_calls],
    )

• model — attribution. When quality drops on a Tuesday and nothing shipped, the first question is whether the model identity changed behind an alias. Without this field the question is unanswerable.
• finish_reason — "length" means the output was truncated. Truncated JSON surfaces three layers up as a parsing bug, and you will spend an afternoon in the parser before you find it here in one second.
• input_tokens / output_tokens — where the money is and where latency creep comes from. Input growth across steps is the usual cause of a loop that gets slower as it runs.
• cost — per step, not per run, so a spike is attributable to a step rather than to a vague “expensive run”.
• requested_tools — the behavioural and security signal. What the model asked for differs from what ran, and lesson 12 is built on that gap.

The tool span records t_span.set(ok=result.ok, duration_ms=result.duration_ms). ok matters more than it looks: a tool that fails fast and often has healthy p50 latency and a broken agent, because each failure returns into the context and buys another model call.

The tracer sums those attributes across every span, which is what total_input_tokens, total_output_tokens and total_cost are. test_trace_accounts_tokens_and_cost pins the invariant that matters — tracer.total_input_tokens == run.input_tokens and tracer.total_cost == run.cost to nine places. If the two can drift, one of them is lying and you will trust the wrong one.

Cost belongs on the dashboard beside latency, not in a monthly finance review. Cost per successfully resolved task is the unit economic of an agent, and a change that lifts quality 30% while tripling cost per resolution is a business decision you cannot make if the only number you have is a pass rate.

Reading a trace - tree and export

tree() is the first thing you look at. From demo.py scenario 1, a real run with two tools:

answer     Order 4471 was delivered 12 days ago, inside the 30-day refund window.
stop       answered
executed   ['get_order', 'search_docs']
steps      3   tokens 123/19
cost       0.090000 (assumed unit prices)

trace
run:agent.run  0ms
  model:model.call.0  0ms  tok 22/1
  tool:tool.get_order  0ms
  model:model.call.1  0ms  tok 38/1
  tool:tool.search_docs  0ms
  model:model.call.2  0ms  tok 63/17

Durations read 0ms because FakeModel is a local scripted stand-in with no network in the way. Read the token column instead, because it shows the thing that bites in production: input tokens go 22, then 38, then 63. The conversation is re-sent every step, so the last model call in a long run pays for everything before it. That curve is why lesson 8 puts a token ceiling on the run, and why step count is a cost metric rather than a style preference.

test_trace_captures_nested_model_and_tool_spans asserts the shape this output implies: one run span with no parent, two model spans, one tool span, every non-root span parented to the run.

export() serialises each span with json.dumps and joins them with newlines — JSON Lines, one span per line, no enclosing array. That choice is deliberate: a line-delimited stream can be appended to, tailed, and truncated mid-write while staying parseable up to the last complete line, whereas a JSON array is only valid once closed, which is exactly what a crashing process fails to do. Real output:

{"span_id": "e4e0357394e8", "parent_id": null, "name": "agent.run", "kind": "run", "duration_ms": 0.09, "attributes": {"task": "Can I refund order 4471?", "stop": "answered", "steps": 3}}
{"span_id": "18ae10c6c2bd", "parent_id": "e4e0357394e8", "name": "model.call.0", "kind": "model", "duration_ms": 0.01, "attributes": {"model": "fake", "finish_reason": "tool_calls", "input_tokens": 22, "output_tokens": 1, "cost": 0.0125, "requested_tools": ["get_order"]}}

Swapping this for a real backend means replacing one method. That is the whole reason the tracer is a few hundred readable lines instead of a vendor SDK: the lesson is what to capture, and that survives every migration.

PII and retention - the section people skip

Look again at what a span holds. The run span’s attributes contain the raw user task. Tool spans contain arguments the model chose, usually derived from user text. Prompts and tool arguments are user data, so a trace store is a personal data store — subject to the same deletion requests, access controls and retention limits as your primary database, except nobody classified it that way because it was called “logs”.

The library gives you key-based redaction, applied recursively so a secret nested inside a tool argument is still caught:

SENSITIVE_KEYS = {"api_key", "authorization", "password", "token", "secret", "ssn"}

def _redact(value: Any) -> Any:
    if isinstance(value, dict):
        return {k: (REDACTED if k.lower() in SENSITIVE_KEYS else _redact(v))
                for k, v in value.items()}
    if isinstance(value, list):
        return [_redact(v) for v in value]
    return value

test_export_redacts_sensitive_keys pins the behaviour: sk-live- never appears in the export, [redacted] does, the benign field survives untouched.

Redaction is a backstop, not the strategy. It fires only on keys it knows, and the interesting data is free text under a benign key. Three rules are what actually hold:

1. Short retention for raw payloads. Prompts, tool arguments and outputs live for days — long enough to debug the incident you are currently debugging. Pick the number with your security and legal partners, write it into the storage lifecycle policy, and let the policy delete them rather than a person remembering to.
2. Long retention for metadata. Span ids, kinds, durations, token counts, cost, finish reasons, stop reasons, tool names, pass or fail. None of it is personal data, all of it is what trend analysis needs, and it is small enough to keep for a year without thinking about it.
3. Sample the raw tier, keep all of the metadata tier. Sample successful runs; keep 100% of runs that errored, hit a budget, or failed an eval. You do not need the payload of every happy path, you need every payload of every failure.

Then the rule that outranks all three: keep secrets out of the context in the first place. A credential the model never sees cannot be traced, summarised into memory, or leaked in an answer.

Exercise

Trace a run that calls two different tools, then assert the shape of the span tree and that the tracer’s accounting matches the Run. Save as tests/test_exercise_trace.py inside agentic-course/.

Success criterion: python3 -m unittest tests.test_exercise_trace -v reports OK, with assertions on span counts, parentage, tool order, and token and cost totals.

What broke when I wrote this

The redaction test passed and the export still contained the user’s data.

test_export_redacts_sensitive_keys puts a secret under the key api_key, so _redact fires and the test goes green. But the run span sets task=task, and a task is free text. Run the same export with personal data in the prompt:

{"span_id": "7ecb5a5454be", "parent_id": null, "name": "agent.run", "kind": "run", "duration_ms": 0.0, "attributes": {"task": "my ssn is 123-45-6789", "ssn": "[redacted]"}}

The value keyed ssn is gone. The identical value inside task is not, because redaction matches on the attribute name and the whole prompt lives under one benign name. A green redaction test had me believing I had a control; I had a spot check. That is why the retention rules above are the actual answer, and why the honest description of SENSITIVE_KEYS is “catches the accidental credential in a tool argument”.

Checkpoint

Why can you not treat a failed agent run like a failed unit test?

Because re-running it does not reproduce it. Sampling, model updates behind an alias, retrieval tie-breaks and tool latency all vary between runs, so the recorded trace is the only durable evidence.

What does a span tree give you that structured log events do not?

Causal structure for free. Parentage is recorded at the moment of nesting rather than inferred from timestamps later, which is the difference between reading a retry inside step three and guessing at it.

Which span field finds a truncated output fastest, and why?

finish_reason. A value of "length" says the model was cut off at the output cap. Without it, truncated JSON presents as a parser bug several layers from the cause.

Why JSON Lines rather than a JSON array?

A line-delimited stream stays parseable up to the last complete line, so it survives appends and a process that dies mid-write. An array is only valid once closed.

SENSITIVE_KEYS redacts a secret. Why is retention still the real control?

Redaction matches attribute names, and sensitive text usually sits in free-form fields like the task or a tool argument. Short retention on raw payloads, long retention on metadata, and sampling that keeps every failure is what actually bounds exposure.

Theory and interview framing: Become an AI Engineer