How to debug a RIFF phone call (the full-everything trace)

Every newly recorded call leaves a unified trace: aligned caller and outbound audio, source-labeled transcripts, FSM state visits, slot writes, tool calls, and guard verdicts. The aligned artifacts share the session call clock. Raw audit tracks remain available but are explicitly not synchronized.

Open http://127.0.0.1:8765/state-program-debugger.html, choose a recent call, and use Play, Pause, Step, or the scrubber. The cursor is shared by audio, conversation evidence, and state inspection. The same normalized artifact is available to Codex and Claude through scripts/state_program_debugger.py.

Operator ruling: "the transcription and audio are the source of truth." The FSM tells you what the machine did; the audio/transcript tell you what actually happened to the caller. Debug from both.

1. Where a call lives

Each call is a directory under data/sessions/<session_id>/:

The manifest's extras.audio_timeline.tracks is the clock authority. A track is step-synchronized only when its status is aligned; unverified never means aligned. The outbound replay channel proves what RIFF queued or sent, not what the carrier or caller ultimately heard.

Find the call you want:

# most recent sessions with a trace, newest last
find data/sessions -maxdepth 2 -name bus_events.jsonl -mmin -120 -print | while read f; do
  d=$(dirname "$f"); echo "$(stat -f '%Sm' -t '%H:%M' "$f")  $d"; done | sort

2. The six lanes (bus_events.jsonl)

Everything you need is in bus_events.jsonl, grouped by event type:

• PATH — transition_committed (from_state -> to_state, reason, turn_index)
• HEAR — transcription (live Gemini text; often empty, see §4) or the hydrated backup
• SLOTS — slot_write (slot, old -> new, writer) — the ground truth of what was captured
• TOOLS — tool_called (tool_name, args, result_preview) — often carries the actual values
• VERDICTS — transition_verdict (winner + each candidate edge's result) — which edge fired and why
• GUARDS — guard_evaluated (guard_name -> result, slots_read) — why an edge did/didn't fire

transition_verdict is the single most useful lane: it names the winning edge. That is how the 32-minute intake loop (FX-033) was pinned — the verdict said must_include_slot_changed matched, and tool_called seq 122 vs 362 showed the model re-transcribed the name ("David Marr" -> "David Mar").

Quick reconstruction:

python - "$D/bus_events.jsonl" <<'PY'
import json,sys,collections
rows=[json.loads(l) for l in open(sys.argv[1]) if l.strip()]
print(dict(collections.Counter(r.get("type") for r in rows)))
for r in rows:
    if r.get("type")=="transition_committed":
        print(f"t{r.get('turn_index','?'):>2} {r['from_state']} -> {r['to_state']}  [{r.get('reason')}]")
PY

3. State Program Debugger — the primary view

The browser debugger is the primary human view. It combines:

• synchronized audio and transcript spans;
• the current state visit and its legal exits;
• entry, current, and recorded-exit values;
• tool, LLM, guard, and transition evidence;
• recorded versus derived versus unavailable provenance.

For an AI or terminal client, build the same artifact and issue deterministic commands instead of reading screenshots:

python scripts/state_program_debugger.py build data/sessions/<session_id> \
  --out /tmp/state-program-debugger.json
python scripts/state_program_debugger.py command /tmp/state-program-debugger.json \
  --json '{"action":"list_visits"}'

When a state repeats, compare its two visits semantically and then move the shared cursor to the first supported difference:

python scripts/state_program_debugger.py command /tmp/state-program-debugger.json \
  --json '{"action":"compare_visits","baseline_visit_id":"menu#1","candidate_visit_id":"menu#2"}'
python scripts/state_program_debugger.py command /tmp/state-program-debugger.json \
  --json '{"action":"rewind_to_first_divergence","baseline_visit_id":"menu#1","candidate_visit_id":"menu#2"}'

The comparison ignores volatile IDs and timestamps, but preserves Entry/Exit variable differences, acted-on input, transcript source, slot writes, playback, and winning edge. A late event carries both causal_visit_id and observed_visit_id; use the causal visit when explaining which state handled the caller's input.

For a deterministic pause audit, run:

python scripts/state_program_debugger.py command /tmp/state-program-debugger.json \
  --json '{"action":"inspect_pause_gaps"}'

It distinguishes caller wait from agent response delay and duplicate/back-to-back output. This debugger projection makes zero model calls and consumes zero model tokens; live-call model token usage remains unavailable unless retained with the session artifacts.

To mark a point durably, use the retained-session command. The response returns the new determinism hash and latest marker revision:

python scripts/state_program_debugger.py session-command data/sessions/<session_id> \
  --json '{"action":"record_issue","issue":{"issue_id":"issue:repeat-1","status":"confirmed","time_ms":123400,"event_id":"bus:42","visit_id":"menu#3","reporter":"claude","category":"duplicate_agent_playback","note":"Same outbound prompt played twice."}}'

The marker is an annotation with explicit provenance. It does not alter or masquerade as recorded call evidence.

call_replay.py remains a compact legacy lane report:

python scripts/call_replay.py data/sessions/<session_id>   # writes replay.html

Renders HEAR / PATH / SLOTS / VERDICTS lanes on one timeline. The HEAR lane reads live transcription events if present, else the Whisper-hydrated backup (§4).

4. Transcript: Gemini (primary) + Whisper (backup)

The transcript comes from Gemini's live audio transcription (primary). It can be missing — Gemini delivers transcriptions asynchronously and the per-turn buffer is sometimes empty at emit (a known gap). So there is a post-call Whisper backup:

python scripts/hydrate_transcript.py data/sessions/<session_id>

It splits audio_replay.wav before transcription, transcribes caller-left and agent-right separately, and writes manifest-backed whisper_transcript.jsonl rows. Each row retains its role, source channel, model, start/end span, clock status, and source artifact. The debugger presents Whisper and live-model transcription as separate observations; disagreement is evidence, not something to overwrite.

If no aligned replay exists, the hydrator can use raw per-role tracks, but those rows are marked unverified and are not placed on the step clock.

Debugging a "hang" with no live transcript: hydrate the aligned replay first. For an older call without replay alignment, Whisper the outbound played track as content-only evidence and do not compare its timestamps to FSM timestamps:

python - "$D/audio_agent_played.wav" <<'PY'
import sys,mlx_whisper
for s in mlx_whisper.transcribe(sys.argv[1], path_or_hf_repo="mlx-community/whisper-small.en-mlx")["segments"]:
    print(f"[{s['start']:6.1f}s] {s['text'].strip()}")
PY

Sanity-check the audio first. audio_replay.wav should match manifest duration_sec. Raw tracks can be longer because they preserve generation and transport evidence without a shared sample clock; that is why the debugger must not auto-select them for synchronized stepping.

5. The debugging loop (what actually works)

1. Reproduce from the trace, not memory. Read transition_verdict for the state in question — it names the edge. Read tool_called args for the real values (they're often unredacted locally). Read slot_write for what got captured.
2. Line the transcript up. If the debugger has no Whisper spans, hydrate (§4), reload the call, and confirm each row says clock_status: aligned before using its timestamp to blame a state.
3. Separate "my processing dropped it" from "the source has nothing" — re-run the raw source (e.g. whisper with the filter off). B-409 was pinned this way: the raw caller channel was all silence-hallucination, so the audio was wrong, not the filter.
4. Check the artifact's own duration vs the manifest before blaming downstream.
5. Write it down. Every real fix gets a docs/fixlog/FX-NNN-*.md (Symptom / Root cause / Fix / Why / Shift-left gate / Test / Success / Evidence), searchable via scripts/fixlog.py. Narrate the iteration in docs/fixlog/LOOP-LOG.md. That is how the next AI recollects this call.

6. Recording invariants (so the trace is always there)

• Audio recording is a checked deploy property: deploy_business.py prints ✅ call recording ON (FX-032). It is gated by RIFF_RECORD_CALLS.
• Post-call Whisper is enabled with RIFF_POSTCALL_WHISPER_ENABLED=1. The finalizer records pending, complete, or failed in the manifest; a missing transcript is therefore distinguishable from silence.
• Both need the phone node running the current code — Python changes (session/recorder/ transport) require a node restart, not just a flow reload.

Worked example — the verify-code "hang" (FX-041)

Operator: "the verify code section seems to be hanging."

1. bus_events TOOLS lane: intake_send_verification_link fired twice (+0.0s and +2.5s) — two codes sent.
2. Agent whisper (§4): "…say the four digit code" voiced twice (~52s, ~62s).
3. Root cause: the model re-called the send tool before the caller could ask; the tool had no in-flight dedup. Removing it from the state's allowlist would not help — B-271's reachable-target look-ahead re-admits it via the retry state.
4. Fix: tool-level idempotency window; regression tests; FX-041 journal.

One call, fully explained — audio + transcript + states + tools on one clock.