Trace nested and resumed agents whole, once, with their real usage

[miguel-border]

Fixes the gaps measured on a long multi-agent session (2,783 agent transcripts) against live Langfuse: agents missing at depth 2 and 3, resumed background agents cut short, and zero-usage generations since Claude Code 2.1.301. It also adds a guarded backfill that repairs past sessions.

Review rounds 1 and 2 refuted earlier versions of this PR (round 1: re-sends counted twice; round 2: once-only export lost work). Round 3 held, with residuals that the last commit closes. This body describes the current tip.

Root causes (VERIFIED on the real transcripts)

• Resumed background agents were emitted once, at an interim result.
  • A background agent that ends a turn while its own background work runs sends a completed notification marked "may be interim". The same task-id notifies again later. The hook emitted the agent at the first notification and never again.
  • Of the depth-2 and depth-3 agents absent from Langfuse whose parent was present, 112 of 113 started after the parent's exported span end. 85 more were absent because their parent was absent.
• Notifications that a working agent receives were invisible.
  • Inside a subagent, a child's notification arrives as an attachment row, {"type":"queued_command","prompt":"<task-notification>…"}, not as a user row.
  • The hook never saw these, so every async launch inside a subagent looked unresolved forever. One codegen agent: 5 launches, 0 recognised notifications.
• Request echo rows were read as chat rows.
  • 2.1.301 writes api-request, api-request-shape and api-request-blob rows. A blob has message.role but no id, usage or timestamp.
  • Each assistant blob became a zero-usage generation, and each user blob started a phantom turn.
• str.splitlines() dropped rows that contain a raw U+2028 or U+0085. In two agents that was the row holding a split message's final usage.
• Notifications delivered to a subagent as isMeta user rows were swallowed. They look like [SYSTEM NOTIFICATION …] with origin kind task-notification. The injected-context branch ran before the notification branch and ate them (1,314 such rows). They are now matched first.
• A half-written agent message counted as finished. A message is written as several rows; the earlier ones carry partial usage (for example output 4 of 336) and stop_reason: null. Only the main transcript is guaranteed complete at a Stop. An agent's LAST message is now held until its last row has a stop_reason; a later message also proves an earlier one complete (319 earlier messages end with a null stop_reason and are complete).
• Launches that never notify held work until SessionEnd. A Workflow stopped with TaskStop never notifies.
• Queue remove rows now carry the notification content. A notification routed to a subagent was counted as undelivered, which held the main turn open.

Fix

• Every observation is exported exactly once, in final form.
  • Langfuse v4 reads do not merge two exports of one id: events_core and events_full are read without FINAL or LIMIT BY, and duplicates collapse only at a background merge. So nothing is re-sent, and the first version's re-send design is gone.
  • While an agent runs, only observations that can no longer change ship.
  • The agent span ships once, when the agent settles. Settled means: no async launch without its notification, no undelivered queued notification, no tool call without its result. Otherwise it ships at SessionEnd.
  • A sync launch's tool_result and a workflow journal result also prove an agent is done.
  • An agent killed mid-message settles once its transcript has been idle for 30 min. An agent idle for CC_LANGFUSE_MAX_DEFER_HOURS (default 12) settles whatever it waits on.
• Revisits between Stops. A registered agent is re-read when its transcript grew. It is also re-read when it is not at rest yet or holds a message back, once the idle bound that could settle it is due, and always at SessionEnd. This is what lets a woken agent's final message (written with stop_reason: null) ship, and makes the idle bounds work for an agent first seen fresh.
• Background shells. A background shell (backgroundTaskId, from run_in_background or a command that outlived its timeout) keeps its agent awake until the shell's notification, which may carry only the task id. This is counted for agents only; main turns keep their own gate.
• Waiting main turns. A successful TaskStop result resolves the stopped task through a synthetic notification. A main turn still waiting after CC_LANGFUSE_MAX_DEFER_HOURS ships as it is.
• Deterministic observation ids (sha256(trace id + message, tool_use or agent id)) let children exported in an earlier firing point at an agent span that ships later, and make backfill ids reproducible. They are not relied on for deduplication. CC_LANGFUSE_DETERMINISTIC_IDS=false falls back to one-shot agents (the old behavior).
• Agent registry.
  • Stored as langfuse_agents.<key>.json beside the state file, under the session lock. It records each agent's first parent, its first-seen start, the keys it has exported, and whether its span has shipped.
  • Each firing continues the agents whose transcript grew. At SessionEnd it also finalizes agents whose span has not shipped yet.
  • The previous version is kept as .bak and is loaded if the file is torn. When late work may be lost, a WARNING is logged. The registry cannot be rebuilt from transcripts, because re-sending would double count. Stray .tmp files are swept.
• Smaller fixes.
  • Echo rows are dropped, and typed non-chat rows no longer fall back to message.role.
  • JSONL is split on \n only.
  • Workflow and subagent maps are passed through both agent kinds.
  • A queue remove row that carries a notification takes it off the gate.
  • A time-dependent test is fixed.
• Version 1.2.2.

Backfill

• uv run --script hooks/langfuse_hook.py --backfill <session-id>.jsonl [--dry-run] [--replace-session-traces] [--namespace NAME] [--force]
• Upload: one SessionEnd-style pass into traces of its own namespace, default backfill-v1.
• Read-back. flush() never raises on a rejected batch, so after the upload the backfill lists the session's traces with their observation ids, retrying for up to 10 min. Unless every uploaded observation is visible, it deletes nothing and exits 4.
• Recovery after exit 4. If Langfuse is only slow to ingest, run again with --verify-only and the same --namespace. It uploads nothing (the ids are deterministic), re-reads, and with --replace-session-traces finishes the replacement. --verify-minutes changes the read-back window. If the upload really failed, use a new --namespace with --replace-session-traces, which also removes the partial upload. An empty expectation never counts as verified.
• Refusals.
  • A --session-id that is not the transcript's own: both the file name and the rows must match.
  • A session with any file under its directory (agents, workflows) modified in the last 30 minutes, unless --force.
  • A namespace that already holds traces of the session. A second upload would count twice; supersede it with a new namespace.
• --replace-session-traces.
  • Runs after the upload has been flushed.
  • Deletes only the session's traces named Claude Code Turn that are outside the backfill's own set. Traces under any other name are never touched.
  • With --dry-run, it lists them (a read-only call) and deletes nothing.

Tests and controls

• Suite: 359 tests pass on Python 3.10, 3.11 and 3.12. Ruff is clean, and the hook smoke check exits 0.

• Agent completion tests (test_agent_completion.py).

  • An isMeta notification resolves its launch, so the agent settles at the Stop.
  • A half-written last message is held, with no partial generation shipped, then ships once with its final usage.
  • A running agent ships only immutable observations, then SessionEnd finalizes it.
  • TaskStop resolves a waiting turn, while a failed TaskStop keeps it waiting.
  • The defer bound ships a stale turn, and both agent idle bounds settle an agent.

• New backfill tests. A fake server records list, delete and flush order. It covers a rejected upload (exit 4, nothing deleted), a partly landed upload (nothing deleted), rows of another session, and a recently written agent file.

• No server-side dedupe is assumed anywhere. Tests count raw exports.

• Fixture resumed_background_agent (synthetic rows in 2.1.301 shapes):

  • Tree: main → orch (bg) → child1 (bg) → grand, plus orch → Workflow → w1 → wchild, plus child2, which is launched after orch resumes.
  • Notifications arrive as attachment rows, and the last one lands in a later turn.
  • The orch span does not ship at the interim Stop, and does ship at the Stop where it settles. Its start is the first sighting, and its end and output are final.
  • No observation id is exported twice across the session.
  • Every agent has exactly one span, and generation counts and token totals equal an independent per-message-id count of each transcript.
  • A growth test appends orch's rows one per firing and counts the exports of each firing.
  • Also tested: a quiet firing exports nothing, a sync agent ending on a tool call ships when its result arrives, and the registry keeps the first parent.

• Backfill guard tests use a fake trace API that records list, delete and flush order:

  • a session-id mismatch, and a transcript named for another session;
  • the idle check, and --force;
  • upload-then-delete order, deleting by name only, keeping the backfill's own traces;
  • the same-namespace refusal, and the dry-run delete plan.

• Round-4 tests.

  • A woken agent whose final message never gets a stop_reason: held, then shipped once at SessionEnd, and also via the idle bound alone.
  • An agent first seen fresh then aged, for both the 12-hour and the streaming bound.
  • A background shell resolved by a task-id-only notification.
  • TaskStop: a failed stop with a dict result, idempotence, the task-id fallback map, and each of the two expansion points alone (a later-firing stop releasing a deferred turn; an agent stopping its own workflow).
  • The deferred-queue age-out on its own path.
  • A read-back that succeeds only on its second attempt.
  • --verify-only success and refusal, and an empty expectation refused.

• Mutation check: 38 mutations were applied to a scratch copy of the hook, one per guard, and every one fails the suite. The earlier 15:

  • refresh off, stored start ignored, latest parent recorded instead of first;
  • plan ignores the name, plan ignores the keep set;
  • always settled, never settled;
  • attachment notifications ignored, sync completion proof removed;
  • namespace refusal, session check and idle check each removed;
  • echo filter off, splitlines restored, queue remove ignored.

• The 11 added in round 3:

  • notification matched after the isMeta check, streaming hold off;
  • TaskStop resolution off, defer bound off;
  • SessionEnd not finalizing, completed_only off;
  • read-back skipped, per-row session check off, main-file-only mtime;
  • both agent idle bounds off.

• The 12 added in round 4:

  • unsettled agents not revisited, SessionEnd ignoring held messages;
  • background shells ignored, a failed TaskStop resolving;
  • queue age-out off, emit age-out off;
  • TaskStop not idempotent, no fallback map, each expansion point removed;
  • a single read-back attempt, the empty-expectation guard removed.

• Real-data oracle (read-only snapshot, nothing sent):

  • The full-session dry run gives 373 turns, 2,783 agent spans and 81,411 generations, equal to 81,411 distinct message ids across 2,785 transcripts. Input, output, cache-read and cache-write totals are exact, with 0 per-agent mismatches.
  • 9 generations have zero usage, and their transcript usage is zero as well.

• Firing-by-firing replay of the m038 batch window (65 Stops plus SessionEnd, each Stop seeing files truncated to its time): 5,588 exports onto 5,588 ids, so 0 re-sends. All 54 of 54 agents have one span each, and usage equals the transcript for every agent.

  • The old hook on the same replay has 6 agents absent (the same ids as in live Langfuse), the orchestrator at 63 of 116 messages, and doubled generation counts.

• Reviewer's probe, repeated on real data. Appending one row to the codegen agent a1e18cad… and firing, with history capture on, exports 0 observations. Appending one new assistant message exports exactly 1.

• Stop-only versus SessionEnd on a fresh read-only session copy (one firing over the whole session, real file mtimes preserved).

  • Stop-only: 174,221 observations, 2,782 agent spans, 81,840 generations.
  • SessionEnd: 174,232 observations, 2,786 agent spans, 81,844 generations. That equals the 81,844 distinct message ids counted independently, with 0 observations pointing at an absent parent.
  • The 4 agent spans still pending after Stop-only are the 4 agents that were running at copy time. The 672 generations and 796 tools pointing at a not-yet-exported parent are theirs.
  • The refuter measured 72,079 observations and 1,200 spans for Stop-only before this fix.

• No test touches the network. Clients are fakes or the in-process recorder, and the comparison runs used http://127.0.0.1:9 with the keys unset.

• Live-sequence replay at this tip (the reviewer's scripts, on a fresh read-only session copy). It re-runs 1,046 real Stops, each seeing every file as it was at that moment with mtimes and a faked clock, plus SessionEnd.

  • 175,156 exports onto 175,156 distinct ids, equal to the final id set: 0 exported twice, 0 lost, 0 phantom, 0 generations with wrong usage.
  • The final generations equal the 82,263 distinct message ids counted independently. Only 85 observations wait for SessionEnd.
  • Median firing 0.115 s, maximum 2.15 s, peak RSS 275 MB, 0 firing errors.
  • Agent spans exported before their transcript's last row fell from 68 to 31. The remainder are agents resumed after they settled, or after the 12-hour idle bound (see residuals).

Residuals

• An agent resumed after it settled (a SendMessage to a finished agent): its new observations ship under its span, but the span's end time and output stay the ones it settled with. Updating them would mean a second export of the span, which Langfuse v4 would count twice.
• The idle bounds are heuristics. An agent that is genuinely blocked for more than 12 h on a child that later reports is finalized early. Its later work still ships under its span, with a stale span end.
• Root span: it still exports once at turn emission; a root whose agents run on is not re-ended. The round-3 replay found 164 main turns whose root end time or output differs from the final value. The cause was not found; background shells notifying after the root shipped are a candidate, since main turns do not wait on them.
• Background shells in main turns: they are not counted as unresolved there, which is accepted to keep main-turn timing unchanged.
• Registry size: a few MB for a session of the measured size, written once per firing.
• Backfill cost: a whole-session backfill of the measured session took 23 s and 1.7 GB RSS in a dry run. A cold live firing on a large session is heavy too: the reviewer measured about 40 s and 1.18 GB on 2,446 agents.
• One workflow agent (wf_f74c5905-29c/agent-ad6a4ece…) is never registered: its transcript holds no assistant message (started, then stopped), so there is nothing to emit.
• Pre-hook history: rows from before the hook was active on that machine (2026-10-04 to 2026-10-12) are only recoverable by the backfill.

🤖 Generated with Claude Code

https://claude.ai/code/session_01Ga4FKjMftJRxoPaQaiPLHy