One run-scoped trace turns routing into something investigable

The escalation said the billing agent had told a customer their parcel was probably at the depot. The question had been about a delayed delivery, billing has no delivery tools, and the answer it produced was a confident guess. The engineer who picked it up had per-agent logs, which is what most teams have, and spent forty minutes with them before writing "cannot determine root cause" in the ticket.

# agent-logs/orders/2026-08-07.jsonl
{"ts":"2026-08-07T14:22:09.118Z","agent":"orders","event":"tool_call",
 "name":"transfer_to_billing","args":{},"result":"<Agent orders->?>"}
{"ts":"2026-08-07T14:22:09.121Z","agent":"orders","event":"turn_end",
 "output_tokens":142}

# agent-logs/billing/2026-08-07.jsonl
{"ts":"2026-08-07T14:22:11.402Z","agent":"billing","event":"turn_start",
 "input_tokens":19844,"session":"ws-7c22"}

Those two lines are the transfer, and they cannot be joined. The orders line does not name a destination in any field that survives serialisation; the billing line does not name a source; session is the websocket id, which is per-connection rather than per-run and gets reused; and the 2.3 s gap between them is not evidence of anything, since the agents write to different files from different pods with clock skew of up to 400 ms. Most importantly, neither line contains the thing the investigation needs, which is why the orders agent decided that billing was the right destination. The transfer_to_billing tool takes no arguments and returns an agent, so the reason existed for exactly as long as it took the model to emit the call, and was never written down.

Recording the decision, not just its effect#

A routing event has to carry enough to reconstruct the run without opening any of the per-agent logs, which means it is a wider record than a normal span, the entry a tracing system writes for one unit of work with a start, an end and a parent. A trace, in this sense, is the whole set of those entries that share one identifier, read in order, so a run-scoped trace is everything a single conversation did held together under the run's own id. The fields below are the ones that have earned their place; each of them has been the field that answered a question at some point.

@dataclass(frozen=True)
class RoutingEvent:
    run_id: str                  # one per conversation, minted at the first user turn
    seq: int                     # monotonic hop number within the run
    ts_ms: int                   # single clock, stamped in the transfer wrapper
    from_agent: str
    to_agent: str
    reason: str                  # the model's stated reason, verbatim, not a summary
    payload: Handoff             # what actually crossed the boundary
    state_before: StateDigest    # facts, constraints, open items held by the sender
    state_after: StateDigest     # the same, as the receiver will see them
    budget_after: RunBudget
    model: str
    tokens_in: int
    tokens_out: int
    cost_usd: float
    latency_ms: int

The two design choices in there are worth stating plainly. reason is a required argument on the transfer tool rather than something inferred later, which means the schema changes and the model is obliged to produce a justification at the moment it routes, and that string is the single most useful field in the record. state_before and state_after are digests of the payload contract from chapter 2 rather than raw context, so a hop that transferred without establishing anything is visible as a pair of identical digests.

seq and ts_ms are both there because they answer different questions and only one of them can be trusted for order. The 400 ms of clock skew that made the original two log lines unjoinable does not go away when the events get richer, so ordering a run by timestamp can still produce a hop that appears to precede the hop that caused it. A counter incremented in the transfer wrapper cannot do that, which makes seq the sort key and ts_ms the thing you subtract to get gaps. Those gaps are worth reading on their own: a 2.3 s gap between one agent ending and the next starting is model latency, and a 40 s gap is something queueing, which is a different investigation entirely.

The digests deserve a definition rather than a mention, since a digest that is too coarse makes the equality check useless and one that is too fine makes it never fire. What worked was a sorted tuple of the fact keys, the constraint texts, the open items in remaining, and the set of tool call ids whose results the sender held, hashed. Values are deliberately excluded, so a hop that re-reads the same order and gets the same answer still reads as establishing nothing, which is the behaviour you want when hunting circulation.

The emission site matters as much as the schema. Putting the logging call inside each agent guarantees that the sixth agent someone adds will not have it, so the event is emitted by the same wrapper that already enforces the declared graph from chapter 3, which is the one place every transfer must pass through.

def apply_transfer(state: RunState, to_agent: str, reason: str,
                   payload: Handoff) -> Agent | ToolError:
    if to_agent not in ALLOWED[state.current_agent]:
        return ToolError(...)
    trace.emit(RoutingEvent(
        run_id=state.run_id, seq=state.next_seq(), ts_ms=now_ms(),
        from_agent=state.current_agent, to_agent=to_agent, reason=reason,
        payload=payload,
        state_before=digest(state), state_after=digest_from(payload),
        budget_after=state.budget, model=state.model,
        tokens_in=state.turn_tokens_in, tokens_out=state.turn_tokens_out,
        cost_usd=state.turn_cost, latency_ms=state.turn_latency_ms,
    ))
    return AGENTS_BY_NAME[to_agent]

What the escalation looked like afterwards#

The same class of incident recurred eleven days later, and this time the run was one query away.

$ trace show run_5c19e2 --routing

seq  t+       from          to             cost   reason (verbatim)
  0  0.0s     —             triage         —      run start: "my order is late again"
  1  3.4s     triage        orders        $0.04   "delivery delay, orders owns tracking"
  2  11.9s    orders        billing       $0.19   "customer mentioned they were charged
                                                   twice for shipping; billing owns
                                                   charge questions"
  3  18.2s    billing       orders        $0.21   "the double charge is a shipping
                                                   surcharge; orders owns shipping"
  4  25.6s    orders        billing       $0.23   "customer still asking about the
                                                   charge, not the parcel"
  5  33.1s    billing       resolve       $0.26   "answered"

  state_after(seq=2) == state_after(seq=4)   [no new facts, no items closed]
  edge (orders, billing) taken 2x; edge (billing, orders) taken 1x

The reason strings make the failure legible in a way no amount of prompt archaeology would have. The customer's message contained two issues, the second of which was a shipping surcharge, and control bounced between the two agents that each correctly believed the other owned it. The billing agent's final answer was about the parcel because by hop 5 the parcel question was the oldest unanswered thing in the conversation and it had been handed the conversation twice with no instruction narrowing it. Nothing here is a prompt that needs tightening in isolation; it is a missing rule about which agent owns a mixed charge-and-delivery issue, and it took four minutes to find rather than forty.

Reading one of these#

A few patterns recur often enough to be worth looking for before anything else. Repeated (from, to) pairs within a run are the plainest signal of circulation, and a repeated pair in both directions is the mutual-deferral shape above. A hop where state_after equals state_before means control moved without anything being established, and a run made mostly of those hops is burning money to relocate a conversation. Reason strings that describe the destination rather than the customer's request — "billing handles billing" — indicate the routing decision was made on the agent's name, which is the failure mode chapter 3's handoff descriptions address. A receiving agent whose first tool call repeats the sender's last tool call is duplicated work, and it shows up as an exact repeat in the tool sequence across a hop boundary.

Each of those patterns is a query rather than a habit, which matters because the version of this that gets used is the one that runs nightly without anybody remembering to look. The events are flat rows, so the circulation check is ordinary SQL over a day of traffic.

-- edges taken more than once in a run without establishing anything new
SELECT run_id,
       from_agent || '->' || to_agent          AS edge,
       count(*)                                AS taken,
       round(sum(cost_usd), 2)                 AS wasted_usd,
       max(seq)                                AS last_hop
FROM routing_events
WHERE ts_ms > (unixepoch() - 86400) * 1000
  AND state_before_digest = state_after_digest
GROUP BY run_id, edge
HAVING count(*) >= 2
ORDER BY wasted_usd DESC
LIMIT 20;

run_id       edge                    taken  wasted_usd  last_hop
run_b41f07   triage->refunds             8       7.52         41
run_b41f07   refunds->triage             9       8.46         41
run_2d80c4   orders->billing             4       0.79         12
run_9a11fe   billing->orders             4       0.83         12
run_44c7e1   triage->billing             3       0.61          9

Over a representative week the top twenty rows of that query accounted for 31% of all spend on unresolved conversations, concentrated in eleven runs, which is the distribution these failures usually have: a small number of runs going badly wrong rather than a broad tax on everything. The query runs in about 200 ms over thirty days because it only touches the metadata columns, which is the reason the retention split below keeps those columns on every hop.

Accidental delegation needs a second query and one join, since the signal is a receiving agent repeating the work its sender just did. Comparing the receiver's first tool call against the sender's last one over the same arguments found it on 1.9% of hops, and 60% of those were a single pair: refunds looking up the order that triage had already looked up, which is chapter 2's re-ask failure showing up as a duplicated API call rather than as a duplicated question.

The team's own numbers on this were the argument that got it prioritised. Before the trace, the median time to explain a routing incident was 3.5 hours and 40% of tickets were closed without a cause; after, the median was 11 minutes and the unexplained rate was 6%. The build was about a week, most of which went into threading run_id through the tool layer rather than into the recorder.

What it costs to keep#

Full fidelity on every hop is more data than it sounds like, because payload, state_before and state_after together run 18–24 KB on a mature conversation.

Keeping metadata on everything and sampling the bodies is the arrangement that has survived contact with a finance review, with the exception carved out for runs that exhausted a budget or ended partial, since those are the ones anybody ever opens. If you are on a framework rather than a hand-rolled loop, much of this exists already — the Agents SDK emits spans for handoffs and the OpenAI Agents SDK Handoffs deep dive walks through the wiring together with input filters — and the GenAI semantic conventions of OpenTelemetry, the vendor-neutral standard for tracing that most observability tools already ingest, are converging on span attributes for agent invocation and tool calls, which is worth adopting for the field names even where you emit the events yourself.

Two ways the trace lies to you#

The first way is that it is incomplete and looks complete. A month after this went in, a run showed four hops in the trace and nineteen model calls on the bill, and the missing fifteen were made by a summariser the orders agent invokes when its context passes 18k tokens. That summariser calls the model itself and, in one branch, transfers the compacted conversation onward. It ran on a background task, run_id was being passed as a function argument through the agent runner, and the background task did not receive one, so the events it emitted carried run_id=None and landed in a partition no query had ever selected from. Across the previous fortnight 3.8% of routing events were in that state, which was invisible because the queries above group by run_id and a null group simply does not appear in the results.

An implicit carrier and a refusal to emit without one closes it, and both halves are needed, since a context variable that silently defaults to None reproduces the same hole with more machinery.

_run_id: ContextVar[str | None] = ContextVar("run_id", default=None)

def emit(event: RoutingEvent) -> None:
    rid = event.run_id or _run_id.get()
    if rid is None:
        raise MissingRunId(
            f"{event.from_agent}->{event.to_agent} emitted outside a run context. "
            f"Wrap background work in run_scope(run_id) before it calls the model."
        )
    sink.write(replace(event, run_id=rid))

Raising is right here even though raising was wrong for a budget breach in the next chapter, because a transfer that cannot be attributed to a run is a bug in the harness rather than a state the conversation can legitimately reach, and it will be found in the first minute of a test rather than in the second week of production. Alongside it, a nightly reconciliation compares the model-call count the billing export reports per run against the count the trace holds, and alerts on any run where they differ by more than 5%. That job is what would have caught the summariser in a day rather than a month, and it costs one query against each source.

The second way is subtler and does not have a fix. reason is what the model said it was doing, which is a statement generated alongside the routing decision rather than a cause of it, and a fluent reason can accompany a wrong hop. Reading 120 sampled hops against their payloads found nine reason strings that asserted a fact appearing nowhere in the payload, the transcript or any tool result — "the customer said this is a marketplace order" when nobody had said so. Those strings are evidence about what the agent believed and about how its instructions read to it, which is exactly what you want when you are deciding what to change in a prompt, and they are not a record of mechanism. Treating them as one leads to the investigation that fixes the wording of the reason rather than the routing.

A trace is a record of decisions and not a control over them. It made the mutual-deferral bug findable, and it did nothing to stop that run: the loop still ran, the customer still got a wrong answer, and if the two agents had deferred to each other twenty times instead of twice, the trace would have recorded all twenty in perfect detail while the bill grew. Which is the situation the next chapter starts in, with a $38 conversation, a green dashboard, and now a trace that shows exactly what happened.