Seeing what the system did

An agent does something wrong in production and the first question anyone asks is what it actually did. Without a record you are reconstructing it from impressions, and the incident turns into an argument. A trace is that record: every model call, every tool invocation and its arguments, every result, with cost and timing attached and one id threading the run together. This section covers what to capture, how to thread it, and how to keep it useful without storing customer data you should not be keeping.

The first question anyone asks#

When an agent misbehaves, the first question is always what it actually did. Without a trace you are guessing, and the incident becomes an argument about what people think happened.

A trace is the full record of one run: every model call, every tool invocation and its arguments, every result, tokens, cost, timing, and which step failed.

Three words, defined#

The vocabulary is small and the tools all use it, so it is worth having exactly. A span is one unit of work with a start time, an end time and some attributes: a model call, a retrieval, a tool invocation. A span has a parent, which is the span it happened inside, so spans form a tree. A trace is that tree for one request, identified by a run id that every span in it carries. That is all. Everything a tracing product sells you is a way to store, search and draw those three things.

The reason the tree matters rather than a flat list is that a flat list cannot tell you whether the second retrieval was a retry of the first or a separate step in a later turn, and that distinction is the whole difference between a bug report and an argument.

One id, threaded through#

The single most valuable thing you can add is a run identifier attached to every log line. Without it you have a pile of unrelated calls and no way to reassemble them.

log.info("llm_call", extra={
    "run_id": run_id,          # ties the whole run together
    "step": "extract",
    "turn": turn,
    "model": model,
    "input_tokens": usage.input_tokens,
    "output_tokens": usage.output_tokens,
    "cached_tokens": usage.cache_read_input_tokens,
    "cost_usd": cost,
    "latency_ms": elapsed,
    "stop_reason": response.stop_reason,
})

Threading that id by hand means adding a run_id parameter to every function between the request handler and the model call, including the ones that have no other reason to know about it, and it is abandoned in most codebases about two weeks in. The mechanism that survives is an ambient variable: in Python a contextvars.ContextVar, which is set once at the top of the request and read by anything below it, and which works correctly under asyncio because each task gets its own copy. That one detail is why the tracer below is forty lines rather than a parameter threaded through forty functions.

For tool calls, record the name, the arguments, whether it succeeded, the error if not, and the size of what came back. Result size matters because it predicts the cost of every turn after it.

The whole mechanism, in forty lines#

Tracing products are worth paying for and they are not magic, and knowing what they do makes choosing between them a different conversation. A span is a context manager that records when it opened, what it was told, when it closed and whether it closed by exception. The parent is whatever span was open when this one started.

import contextvars, json, time, uuid

current = contextvars.ContextVar("current_span", default=None)
SPANS = []

class Span:
    """One step of one request. It knows its parent, so a run reassembles into a tree."""
    def __init__(self, name, **attrs):
        self.id = uuid.uuid4().hex[:8]
        self.name, self.attrs = name, attrs
        self.parent = current.get()
        self.run_id = self.parent.run_id if self.parent else uuid.uuid4().hex[:8]
        self.error = None

    def __enter__(self):
        self.t0 = time.perf_counter()
        self.token = current.set(self)
        return self

    def __exit__(self, exc_type, exc, tb):
        self.ms = (time.perf_counter() - self.t0) * 1000
        current.reset(self.token)
        if exc is not None:
            self.error = f"{exc_type.__name__}: {exc}"
        SPANS.append(self)
        print(json.dumps({
            "run_id": self.run_id, "span_id": self.id,
            "parent_id": self.parent.id if self.parent else None,
            "step": self.name, "latency_ms": round(self.ms, 1),
            "error": self.error, **self.attrs,
        }))
        return False                      # never swallow the exception

def record(**attrs):
    """Attach a measurement to whichever span is currently open."""
    span = current.get()
    if span is not None:
        span.attrs.update(attrs)

Wrapping the model call is then a matter of opening a span and recording the usage fields the response already carries. The client here is a stub so the file runs offline; the field names are the ones the real response object uses.

PRICES = {"small": (1.00, 5.00), "large": (5.00, 25.00)}   # usd per million tokens

class StubClient:
    """Stands in for the real client so this file runs offline. The return value has
    the shape the Anthropic SDK gives you: .usage.input_tokens, .usage.output_tokens,
    .usage.cache_read_input_tokens, and .stop_reason."""
    def call(self, model, prompt_tokens, output_tokens, cached=0):
        time.sleep(0.002 + output_tokens / 40000)
        usage = type("Usage", (), {"input_tokens": prompt_tokens,
                                   "output_tokens": output_tokens,
                                   "cache_read_input_tokens": cached})()
        return type("Response", (), {"stop_reason": "end_turn", "usage": usage})()

client = StubClient()

def cost_usd(model, usage):
    price_in, price_out = PRICES[model]
    billed_in = usage.input_tokens - usage.cache_read_input_tokens
    return (billed_in * price_in
            + usage.cache_read_input_tokens * price_in * 0.1      # cache reads are cheap
            + usage.output_tokens * price_out) / 1e6

def llm(step, model, prompt_tokens, output_tokens, cached=0):
    with Span("llm:" + step, model=model):
        r = client.call(model, prompt_tokens, output_tokens, cached)
        record(input_tokens=r.usage.input_tokens, output_tokens=r.usage.output_tokens,
               cached_tokens=r.usage.cache_read_input_tokens,
               cost_usd=round(cost_usd(model, r.usage), 6),
               stop_reason=r.stop_reason)
        return r

def tool(name, fail=False, result_chars=0):
    with Span("tool:" + name):
        time.sleep(0.003)
        record(result_chars=result_chars, ok=not fail)
        if fail:
            raise TimeoutError("upstream did not answer in 5s")

Now a request that does what a real one does: a cheap planning call, a tool that times out and is retried, and an expensive answering call.

def handle(question, user, feature):
    with Span("request", user=user, feature=feature, question=question) as run:
        llm("plan", "small", prompt_tokens=900, output_tokens=60, cached=800)
        try:
            tool("search_docs", fail=True)
        except TimeoutError:
            tool("search_docs", result_chars=18000)      # the retry that succeeded
        llm("answer", "large", prompt_tokens=6200, output_tokens=420, cached=800)
        return run.run_id

run_id = handle("how do I rotate an API key", user="u_417", feature="support-chat")

spans = [s for s in SPANS if s.run_id == run_id]
root = next(s for s in spans if s.parent is None)
answer = next(s for s in spans if s.name == "llm:answer")
total = sum(s.attrs.get("cost_usd", 0) for s in spans)
print(f"\n{len(spans)} spans, {sum(1 for s in spans if s.error)} failed, "
      f"{root.ms:.0f} ms wall clock, {total * 100:.3f} cents")
print(f"the answer call is {100 * answer.attrs['cost_usd'] / total:.0f}% of the money "
      f"and {100 * answer.ms / root.ms:.0f}% of the time")

{"run_id": "188a3f41", "span_id": "3b2c8fd0", "parent_id": "b72663ed", "step": "llm:plan", "latency_ms": 4.5, "error": null, "model": "small", "input_tokens": 900, "output_tokens": 60, "cached_tokens": 800, "cost_usd": 0.00048, "stop_reason": "end_turn"}
{"run_id": "188a3f41", "span_id": "1982b840", "parent_id": "b72663ed", "step": "tool:search_docs", "latency_ms": 3.8, "error": "TimeoutError: upstream did not answer in 5s", "result_chars": 0, "ok": false}
{"run_id": "188a3f41", "span_id": "498155e8", "parent_id": "b72663ed", "step": "tool:search_docs", "latency_ms": 3.8, "error": null, "result_chars": 18000, "ok": true}
{"run_id": "188a3f41", "span_id": "b0a156fa", "parent_id": "b72663ed", "step": "llm:answer", "latency_ms": 15.4, "error": null, "model": "large", "input_tokens": 6200, "output_tokens": 420, "cached_tokens": 800, "cost_usd": 0.0379, "stop_reason": "end_turn"}
{"run_id": "188a3f41", "span_id": "b72663ed", "parent_id": null, "step": "request", "latency_ms": 27.6, "error": null, "user": "u_417", "feature": "support-chat", "question": "how do I rotate an API key"}

5 spans, 1 failed, 28 ms wall clock, 3.838 cents
the answer call is 99% of the money and 56% of the time

Five lines of JSON and the run is reconstructable by anyone, including the person who did not write it. The failed search and its retry both appear, which matters: a tracer that only records the successful attempt reports a healthy system that is quietly retrying half its requests.

Structured logs, not print statements#

The difference is not tidiness, it is whether the question you will want to ask is answerable. One JSON object per span, with the same keys every time, means the whole day's traces are a table: which steps failed and how often, which model calls have zero cached tokens, what the 99th percentile latency of the retrieval step is, what one user cost last week. A log line reading 'calling model for step extract, 6200 tokens' answers none of those without someone writing a parser, and the parser breaks the first time the sentence is reworded.

Two rules make the table usable. Keys are stable and typed: latency_ms is always a number of milliseconds, never sometimes seconds and never a string. And the message field is a short constant name such as llm_call rather than a sentence, with everything variable in its own key, so grouping by name works.

What the trace lets you answer#

• Which step is slow, and whether it is the model or a tool.
• Which step is expensive, and whether caching is working.
• Whether the agent is repeating itself.
• Whether the right documents were retrieved for a wrong answer.
• What the model was actually sent, which is often not what you think.

Privacy#

Traces contain user content by definition, so they are subject to the same retention and access rules as any other personal data. Redact what you must, set a retention period deliberately, and do not let convenience during development quietly become the production default.

The practical shape is two tiers. Metadata, meaning the token counts, costs, latencies, step names, error types and the run id, is small, contains nothing personal, and can be kept for a year without anyone worrying. Payloads, meaning the rendered prompt and the model's output, are large and personal, and a much shorter retention on those buys most of the debugging value at a fraction of the risk. Splitting the two is a decision to make when you build the tracer, because retrofitting it means rewriting every consumer of the data.

What to carry, and what to skip#

• Carry: span, parent, run id. Every tracing tool is those three ideas, and being able to say so is the difference between evaluating tools and being sold one.
• Carry: an ambient context variable is what makes the run id reach the bottom of the stack. Threading it as a parameter is the approach that gets abandoned.
• Carry: record cost where the usage numbers are, and record failed attempts as well as successful ones.
• Skip: choosing a vendor before you have instrumented anything. Forty lines of your own will tell you what you actually want from one.
• Skip: tracing at the function level. Spans belong at the steps you would name in a sentence describing the run, and a trace with two hundred spans per request is one nobody reads.