diff --git a/CLAUDE.md b/CLAUDE.md index e2f4ebd..8056ed5 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -15,14 +15,14 @@ xray has exactly two write surfaces; both are documented and Valibot-validated a 1. **Control plane (the SDK calls these directly).** - `POST /v1/conversations` — idempotent upsert of the Conversation spec (turns + per-turn assertions + conversation-level judges) keyed by its content hash. The server computes the hash; the SDK never hashes anything. Same canonical JSON in → same hash → row upsert (last-write-wins on `name`). - `POST /v1/replays` — eager Replay-row creation (`lifecycle_state='pending'`). Returns `replay_id` so the SDK can propagate it (LiveKit room metadata → OTEL baggage) BEFORE the dev's agent emits its first span. - - `POST /v1/replays/:id/audio` — driver uploads the 48kHz int16 **stereo WAV** (L = user, R = agent, wall-clock-aligned). Flips `lifecycle_state` to `recording_uploaded`. - - `POST /v1/replays/:id/analyze` — enqueues the bunqueue `analyze-replay` job. The server transitions to `lifecycle_state='analyzing'` with `analysis_step='vad'`. **Three-stage chain**: `analyze-replay` (VAD per channel + Whisper transcription per turn + turn_idx backfill on tool_calls/model_usage) → `calculate-metrics` (agent_response_ms, ttft_ms, interrupted) → `evaluate-replay` (runs declared assertions + judges, writes `assertion_results` / `judge_results` / `replay_evaluations`, flips lifecycle to `completed`). Each stage enqueues the next on success; any stage's failure stamps `lifecycle_state='failed'` with a stage-specific `failure_reason`. + - `POST /v1/replays/:id/audio` — driver uploads the 48kHz int16 **stereo WAV** (L = user, R = agent, wall-clock-aligned), plus the `X-Recording-Started-At` header: the wall-clock of audio sample 0, persisted as `replays.recording_started_at` — the sole origin for mapping span timestamps onto the audio timeline. Flips `lifecycle_state` to `recording_uploaded`. + - `POST /v1/replays/:id/analyze` — enqueues the bunqueue `analyze-replay` job. The server transitions to `lifecycle_state='analyzing'` with `analysis_step='vad'`. **Three-stage chain**: `analyze-replay` (VAD per channel + Whisper transcription per turn) → `calculate-metrics` (audio-frame metrics: agent_response_ms, interrupted) → `evaluate-replay` (runs declared assertions + judges, writes `assertion_results` / `judge_results` / `replay_evaluations`, flips lifecycle to `completed`). Each stage enqueues the next on success; any stage's failure stamps `lifecycle_state='failed'` with a stage-specific `failure_reason`. Tool/model spans are attributed to turns at eval/read time by mapping their wall-clock `started_at` onto the audio timeline (origin = `replays.recording_started_at`, see `docs/specs/0001-timeline-clock-alignment.md`) — there is no stored `turn_idx` on those rows and no backfill stage. - `GET /v1/replays/:id/events` — SSE stream of `state` / `progress` / `evaluation_complete` / `failed` events. The `evaluation_complete` event carries the full `ReplayResult` payload (verdict + per-assertion + per-judge + per-turn metrics) — the SDK returns immediately without a follow-up GET. - `GET /v1/replays/:id/result` — same `ReplayResult` payload outside the SSE stream for late subscribers / inspector hydration. - `PATCH /v1/replays/:id` — driver-side failures only (`failure_reason='driver_aborted'` / `audio_missing` / `agent_not_joined`). Lifecycle transitions during the analyze chain are server-owned. 2. **OTLP/HTTP receiver (the dev's agent emits spans).** - - `POST /v1/otlp/v1/traces` — OpenTelemetry traces (JSON + protobuf). **Filters, not gates**: routes spans by the `xray.replay.id` resource attribute and runs each through a vocabulary registry (`src/server/otlp/vocabularies/`: `xray.*`, OTel GenAI semconv `gen_ai.*`, Langfuse). Unknown vocabularies are dropped silently; unknown replay ids are dropped silently. Extracted fields land in `tool_calls` and `model_usage` with `turn_idx=NULL` (the `analyze-replay` job backfills `turn_idx` by matching the span's `started_at` to a `replay_turns.voice_start_ms..voice_end_ms` window). Every accepted span lands in `spans`. `xray.turn` / `xray.stage.*` are accepted as raw spans only. `xray.assertion` and `xray.judge` are no longer recognized — evaluation runs from the declared `Assertion` / `Judge` catalog. + - `POST /v1/otlp/v1/traces` — OpenTelemetry traces (JSON + protobuf). **Filters, not gates**: routes spans by the `xray.replay.id` resource attribute and runs each through a vocabulary registry (`src/server/otlp/vocabularies/`: `xray.*`, OTel GenAI semconv `gen_ai.*`, Langfuse). Unknown vocabularies are dropped silently; unknown replay ids are dropped silently. Extracted fields land in `tool_calls` and `model_usage` with no stored turn association — turn membership is derived at eval/read time from each row's wall-clock `started_at` against the audio timeline (origin = `replays.recording_started_at`, sent by the driver as the `X-Recording-Started-At` header on the audio upload). Model TTFT, when the agent's instrumentation emits `gen_ai.response.time_to_first_chunk`, lands on `model_usage.ttft_ms`. Every accepted span lands in `spans`. `xray.turn` / `xray.stage.*` are accepted as raw spans only. `xray.assertion` and `xray.judge` are no longer recognized — evaluation runs from the declared `Assertion` / `Judge` catalog. The two paths are coupled by trust: the OTLP receiver doesn't create Conversation or Replay rows, ever. The trust boundary is the SDK's POST. The analyze chain adds three "internal" write paths — the embedded bunqueue workers writing `replay_turns` + `speech_segments` + `turn_transcripts` + `replay_metrics` + `assertion_results` + `judge_results` + `replay_evaluations` after reading the uploaded WAV + the declared spec. diff --git a/docs/architecture.md b/docs/architecture.md index e439d19..791eddf 100644 --- a/docs/architecture.md +++ b/docs/architecture.md @@ -121,10 +121,10 @@ flowchart TB subgraph CP["Control plane — Valibot-validated, idempotent"] CP1["POST /v1/conversations
multipart spec + audio bytes
server hashes canonical turns → conversation_hash
upsert by hash (last-write-wins on name)
"] CP2["POST /v1/replays
eager row create — lifecycle_state='pending'
returns replay_id
"] - CP3["POST /v1/replays/:id/audio
stereo WAV → XRAY_AUDIO_ROOT
lifecycle_state='recording_uploaded'
"] + CP3["POST /v1/replays/:id/audio
stereo WAV → XRAY_AUDIO_ROOT
X-Recording-Started-At → replays.recording_started_at
lifecycle_state='recording_uploaded'
"] CP4["POST /v1/replays/:id/analyze
enqueue bunqueue job
lifecycle_state='analyzing'
analysis_step='vad'
"] CP5["PATCH /v1/replays/:id
lifecycle_state / failure_reason / finished_at"] - CP6["analyze-chain workers
analyze-replay: VAD + Whisper → speech_segments + replay_turns + turn_transcripts
calculate-metrics: agent_response_ms + ttft + interrupted → replay_metrics
evaluate-replay: assertions + judges → assertion_results + judge_results + replay_evaluations
lifecycle_state='completed' on chain success
"] + CP6["analyze-chain workers
analyze-replay: VAD + Whisper → speech_segments + replay_turns + turn_transcripts
calculate-metrics: agent_response_ms + interrupted → replay_metrics
evaluate-replay: assertions + judges → assertion_results + judge_results + replay_evaluations
lifecycle_state='completed' on chain success
"] end subgraph RX["OTLP receiver — filters, not gates"] RX1["POST /v1/otlp/v1/traces
JSON or protobuf

Routes by xray.replay.id resource attr.
Unknown replay_id → silent drop.
Unknown vocabulary → silent drop.

Vocabularies in src/server/otlp/vocabularies/:
• xray.ts (xray.* recognized, raw spans only)
• gen-ai-semconv.ts (gen_ai.* per OTel)
• langfuse.ts (Langfuse-flavoured GenAI)"] @@ -226,10 +226,16 @@ longer recognized: the spec-0001 server reads its checks from the driver-emitted spans. **Tool / model → turn attribution** is timestamp-based, not span-tag -based. The OTLP receiver writes `tool_calls.turn_idx` / -`model_usage.turn_idx` as `NULL`; the `analyze-replay` job backfills -those values from the VAD-derived `replay_turns.voice_start_ms..voice_end_ms` -window in the same transaction that writes the turn rows. +based — and derived, not stored. `tool_calls` / `model_usage` rows carry +only their wall-clock `started_at`; turn membership is computed at +eval/read time by mapping `started_at` onto the audio timeline +(`audio_offset_ms = started_at − replays.recording_started_at`, the +anchor the driver sends via the `X-Recording-Started-At` upload header) +and testing the VAD-derived turn window `[turn_start_ms, turn_end_ms)`. +There is no `turn_idx` column on those tables and no backfill stage — +see `docs/specs/0001-timeline-clock-alignment.md` for why +`replays.started_at` (row-creation time) must never be used as the +origin. **gen_ai semconv** (`gen-ai-semconv.ts`) — `gen_ai.tool` → `tool_calls`, `gen_ai.client.operation` → `model_usage`. **Langfuse** vocabulary @@ -268,15 +274,15 @@ sequenceDiagram end D->>D: assemble stereo WAV
(L = user PCM, R = agent PCM,
wall-clock-aligned) - D->>X: POST /v1/replays/:id/audio
→ lifecycle_state='recording_uploaded' + D->>X: POST /v1/replays/:id/audio
+ X-Recording-Started-At (audio t=0)
→ lifecycle_state='recording_uploaded' D->>X: POST /v1/replays/:id/analyze
→ lifecycle_state='analyzing' X->>W: bunqueue enqueue analyze-replay - W->>W: read WAV, downsample to 16k,
VAD per channel,
derive turn boundaries,
backfill tool_calls/model_usage turn_idx + W->>W: read WAV, downsample to 16k,
VAD per channel,
derive turn boundaries W->>X: insert speech_segments + replay_turns
analysis_step='transcribe' W->>W: slice per-turn audio, call Whisper
(Promise.all over turns) W->>X: insert turn_transcripts
enqueue calculate-metrics X->>W: bunqueue enqueue calculate-metrics - W->>W: compute agent_response_ms + ttft_ms
+ interrupted per turn + W->>W: compute agent_response_ms
+ interrupted per turn W->>X: insert replay_metrics
analysis_step='evaluate'
enqueue evaluate-replay X->>W: bunqueue enqueue evaluate-replay W->>W: run each declared Assertion
(pure ts-pattern dispatch)
+ each declared Judge
(OpenAI Chat Completions) diff --git a/docs/integrate.md b/docs/integrate.md index adba7ce..7d204e0 100644 --- a/docs/integrate.md +++ b/docs/integrate.md @@ -230,7 +230,16 @@ What `xray.run` does: 3. Bind the driver, attach replay baggage, run the driver — playing user audio + capturing agent audio + transcripts. 4. Assemble a 48 kHz int16 **stereo WAV** (L = user, R = agent, - wall-clock-aligned) and POST it to `/v1/replays/:id/audio`. + wall-clock-aligned) and POST it to `/v1/replays/:id/audio`, with the + `X-Recording-Started-At` header set to the wall-clock (ISO-8601 UTC) of + audio sample 0. This anchor is the sole origin for mapping span + timestamps onto the audio timeline — the server derives each tool / + model / span row's per-turn membership from it. **A custom `Runtime` + that produces audio MUST report it**: return + `RuntimeResult.recording_started_at_epoch` (Unix epoch seconds of sample + 0) and `xray.run` sends the header for you. Omit it and span→turn + attribution is skipped — every `tool_called` / `tool_not_called` / + `tool_args_match` / `max_ttft_ms` assertion comes back `errored`. 5. POST `/v1/replays/:id/analyze` — server enqueues the three-stage analyze chain (`analyze-replay` → `calculate-metrics` → `evaluate-replay`). @@ -274,7 +283,10 @@ one file each in `src/server/tts/`. Each carries `judge_idx`, `kind`, `status`, the LLM's 0..100 `score`, and the LLM's natural-language `reason`. - `metrics: tuple[TurnMetrics, ...]` — per-turn timing computed - server-side: `agent_response_ms`, `ttft_ms`, `interrupted`. + server-side: `agent_response_ms`, `interrupted`. (Model TTFT is a + per-call attribute on the replay's `model_usage` rows, populated when + the agent's instrumentation emits + `gen_ai.response.time_to_first_chunk` — not a per-turn metric.) - `replay_id` + `conversation_hash` — pointers back to the server-side rows for follow-up inspection. @@ -337,9 +349,9 @@ This release moves assertion + judge evaluation onto the server. down, judge crashing) raise `ReplayEvaluationError`. - **Three-stage server chain.** `/analyze` now enqueues `analyze-replay` (VAD + per-turn Whisper transcription), which - enqueues `calculate-metrics` (agent_response_ms, ttft_ms, - interrupted), which enqueues `evaluate-replay` (runs all assertions - + judges, emits `evaluation_complete` SSE). + enqueues `calculate-metrics` (agent_response_ms, interrupted), which + enqueues `evaluate-replay` (runs all assertions + judges, emits + `evaluation_complete` SSE). - **SSE event renamed.** The `completed` event is gone; the chain emits `evaluation_complete` with the full `ReplayResult` payload. - **`GET /v1/replays/:id/result`** — fetches the same payload outside diff --git a/docs/specs/0001-timeline-clock-alignment.md b/docs/specs/0001-timeline-clock-alignment.md new file mode 100644 index 0000000..794c13b --- /dev/null +++ b/docs/specs/0001-timeline-clock-alignment.md @@ -0,0 +1,275 @@ +# 0001 · Timeline clock alignment + timeline-native span model + +Status: **implemented** (server + SDK + client; verified: `bun test` 680 pass, `tsc` clean, biome clean, SDK `pytest` 93 pass, `pyright --strict` clean) +Branch: `feat/metrics-eval` + +> Spec numbering: no prior spec exists on this branch; `0001` chosen to +> match the per-feature convention used on earlier branches. Renumber if +> a global sequence is adopted. + +--- + +## 1 · The bug, precisely + +xray computes per-turn metrics and attributes OTLP spans (`tool_calls`, +`model_usage`) to turns by mapping each span's wall-clock timestamp onto +the **audio timeline** (ms from the recording's `t=0`). The map it uses +is wrong: + +```ts +// analyze-replay.processor.ts:346 & calculate-metrics.processor.ts:259 +offsetMs = Date.parse(span.started_at) − Date.parse(replays.started_at) +``` + +`replays.started_at` is stamped at **replay-row creation** (POST +`/v1/replays`, `replays.service.ts:65`), which happens **before** the +driver connects the LiveKit room, waits for the agent to join +(`livekit.py:219`), publishes the track, and begins the first turn. +Audio `t=0` is `min(segment.started_at)` — the first turn's driver-clock +`time.time()` (`livekit.py:581`). The two instants differ by the entire +connect + agent-join + publish latency. + +### Evidence (authentic snapshot) + +`snapshot/xray.db`, replay `7b8e2770…`: + +| quantity | wall-clock | +|---|---| +| `replays.started_at` | `14:31:28.688` | +| first `xray.turn` span ≈ audio `t=0` | `14:31:31.023` | + +**Gap = 2335 ms**, run-dependent and unbounded (scales with agent +cold-start). Worked example — tool call `get_current_year` at +`14:31:37.265`, VAD turn windows `t0[360,2190) t1[2550,4680) +t2[7110,11070)`: + +- code offset `37265 − 28688 = 8577` → lands in `t2` voice window +- true offset `37265 − 31023 = 6242` → lands in `t2`'s pre-voice gap + +The two errors (wrong origin; voice-window-only matching) happen to +partially cancel here. They do not in general. + +### Why the server can't fix it alone + +At the driver→server boundary the driver observes a **join**: +`(wall_clock ↔ audio_sample ↔ turn_structure)`. It ships raw audio bytes +(no timestamps) + raw OTLP spans (wall-clock, mixed clock domains) and +**discards the join**. `started_at` is a server-clock stamp of an +unrelated event; it does not contain the join. The fix must **preserve +the join across the boundary** — the driver is the only party that knows +audio `t=0` in wall-clock terms. + +### Clock domains in play + +| Domain | Owns | Notes | +|---|---|---| +| Server | `replays.started_at` | unrelated to audio; row-creation time | +| Driver (test runner) | the mixdown, audio `t=0`; `xray.turn` spans | the join lives here | +| Agent under test | `gen_ai.*` / tool spans | separate process; the timestamps we attribute | + +Runs are short → clock-rate drift is negligible → the correction is a +pure **offset**, not an affine slope. + +--- + +## 2 · Decisions (resolved with the maintainer) + +| # | Decision | Choice | Rationale | +|---|---|---|---| +| D1 | Agent-clock correlation | **Co-located anchor.** Driver ships audio `t=0`; assume agent clock ≈ driver clock. **No** out-of-range flagging. | Common setup is one host. Spans legitimately fire outside any turn's audio (prep, speculative gen), so "outside the audio" is not an error condition. | +| D2 | Turn source | **VAD-authoritative, unchanged.** | Required for live mode; out of scope to revisit here. | +| D3 | Anchor granularity | **Single recording-start anchor.** | One offset map for the whole run; driver already knows `t=0`. | +| D4 | `ttft_ms` meaning | **Model TTFT from GenAI semconv, optional.** | The value is a same-clock delta — correlation-free. Treated as one more optional extracted field, no special pipeline. | +| D5 | Anchor wire surface | **`X-Recording-Started-At` header on POST `/audio`.** | The anchor is a property *of the audio*; persisted once at upload, read by the chain. | +| D6 | Refactor scope | **Drop stored `turn_idx`; delete `backfillTurnIdx`.** Spans carry a read-derived `audio_offset_ms`; display by timeline overlap; assertions compute per-turn membership at eval time. | A stored `turn_idx` denormalizes a spatial fact the timeline already encodes, and forces one lossy global attribution rule. | +| D7 | Per-turn assertion window | **`[turnStartMs, turnEnd)`** — the agent turn's *own* window (tiles the timeline). | Strict: a too-early (speculative during the user's turn) or too-late tool call lands in a neighbour tile → flagged. Speculative-execution leniency deferred to an explicit eval-SDK opt-in. | + +--- + +## 3 · Design + +### 3.1 The anchor + +- New column **`replays.recording_started_at`** (`text`, nullable, + ISO-8601 UTC). +- POST `/audio` reads header **`X-Recording-Started-At`**, Valibot-validated + (ISO datetime), persists it on the replay row alongside `audio_path`. +- **Absent header** (legacy SDK / unset): store `null`. Degrade gracefully + — no offset, no per-turn tool attribution (see §3.4). Never fall back + to `started_at`. New SDK always sends it. + +### 3.2 Unified timeline — `audio_offset_ms` + +A single pure helper maps wall-clock → audio offset: + +```ts +// audio_offset_ms = parse(startedAtIso) − parse(recordingStartedAtIso) +// → number | null (null if either timestamp is missing/unparseable) +``` + +Derived **at read** for every `span` / `tool_call` / `model_usage` from +data already stored (`started_at` on the row + `recording_started_at` on +the replay). **Not** a stored column — single source of truth, cannot +drift. Used by both the response builder (inspector timeline) and the +assertion evaluator. + +The inspector renders all spans + VAD turns on one ms axis; turn overlap +is **visual**, not a stored foreign key. A span in a gap (prep / +speculative) renders in the gap and reads correctly. + +### 3.3 TTFT — optional, no special handling + +- `gen-ai-semconv.ts` extracts `gen_ai.response.time_to_first_chunk` + (seconds, float; semconv stability *Development* — pin against the + emitting instrumentation's semconv version) → `ttftMs = round(s*1000)`. + Added to `ExtractedModelUsage`. Null when the span doesn't carry it + (the common case today — the example v2v agent emits none). +- New column **`model_usage.ttft_ms`** (`integer`, nullable). Written by + `persistExtracted`. Rides the timeline as a model-call attribute. +- **Removed** from `replay_metrics` entirely. + +### 3.4 Assertions — eval-time membership + +**Scope: this window governs `tool_called` / `tool_not_called` / +`tool_args_match` / `max_ttft_ms` evaluation only.** Every recognized +`tool_call` / `model_usage` / span is still recorded *unconditionally* +(`otlp.service.ts` `persistExtracted` — no turn association at rest, since +D6 drops `turn_idx`) and rendered on the timeline at its true +`audio_offset_ms`, in-turn or not. The window never filters storage or +display: a speculative tool call that fires during the user's turn is +still stored and still shown — it just doesn't count toward the agent +turn's assertion. + +`buildAssertionContext` (`evaluate-replay.processor.ts`) computes each +turn's tool/model rows on demand: + +- A `tool_call` / `model_usage` row belongs to turn `N` iff its + `audio_offset_ms ∈ [turnStartMs_N, turnEndMs_N)` — the turn's **own** + window from `deriveTurns`, where `turnStartMs` = the previous + (opposite-role) turn's `voiceEndMs` (0 if none) and `turnEndMs` = this + turn's `voiceEndMs`. Since `turnStartMs_N = voiceEndMs_{N-1}`, the + windows **tile** the timeline with no gaps or overlap — every call maps + to **exactly one** turn. +- **Strict by design.** A call that fires *before* the user stopped + (speculative-during-user-turn) or *after* the agent finished lands in a + neighbouring turn's tile → **not** counted for turn `N` → `tool_called` + flags it. A mistimed tool call is a real agent bug worth surfacing. The + pre-voice "thinking" gap stays in-turn (it sits in `N`'s tile, after the + user stopped). +- `max_ttft_ms` sources `ttftMs` from the **earliest in-window** + `model_usage` row (the first LLM call's perceived first-chunk latency). +- **No `recording_started_at` → no offsets → tool/ttft assertions + `errored`** with a clear message (`"no recording anchor; cannot + attribute spans to turns"`). Honest, not silently failing. + +> Future opt-in: if speculative execution outside the bot turn proves +> common, add an explicit eval-SDK knob (e.g. an assertion param +> `allow_speculative`, or a widened window) rather than loosening the +> default. Strict-by-default; widen on demand. + +### 3.5 calculate-metrics simplification + +With TTFT gone from `replay_metrics`, the stage no longer reads `spans` +or `recording_started_at`. It computes only audio-derived, single-frame +metrics — both already correct: + +- `agent_response_ms` = `voiceStartMs − priorUserVoiceEndMs` +- `interrupted` / `interruption_start_ms` + +`computeMetrics` loses its `ttftSpans` + `replayStartMs` params and the +`ttftFor` helper is deleted. + +--- + +## 4 · Change surface + +### Deletions + +- `analyze-replay.processor.ts`: `backfillTurnIdx`, `turnIdxForStartedAt`, + and all `tool_calls` / `model_usage` writes from this stage. +- `calculate-metrics.processor.ts`: `ttftFor`; `ttftSpans` + `replayStartMs` + plumbing. +- `model_usage.turn_idx`, `tool_calls.turn_idx` columns. +- `replay_metrics.ttft_ms` column. + +### Server + +- `store/schema.ts` + migration: `+replays.recording_started_at`, + `+model_usage.ttft_ms`, `−*.turn_idx`, `−replay_metrics.ttft_ms`. +- `audio.router.ts` / `audio.service.ts` / `audio.types.ts`: parse + persist + the header. +- `replays/timeline.ts` (new small slice): the `audio_offset_ms` helper + + the membership-window predicate. Co-located test. +- `otlp/vocabularies/gen-ai-semconv.ts`: extract `time_to_first_chunk`. +- `otlp.service.ts` (`persistExtracted`): write `model_usage.ttft_ms`; stop + writing `turn_idx`. +- `evaluate-replay.processor.ts`: eval-time membership; ttft from model_usage. +- `replays.service.ts` + `replays.types.ts`: response shapes (§5). + +### Wire contract (breaking) + +| Schema | Change | +|---|---| +| `ToolCallResponse` | −`turn_idx`, +`audio_offset_ms` (nullable) | +| `ModelUsageResponse` | −`turn_idx`, +`audio_offset_ms` (nullable), +`ttft_ms` (nullable) | +| `TurnMetricsResponse` | −`ttft_ms` | +| POST `/audio` | +`X-Recording-Started-At` request header (optional) | + +### SDK + +- `RuntimeResult`: +`recording_started_at_epoch: float | None` (the mixdown + `t=0`, already computed in `write_stereo_mixdown` / `write_live_mixdown`). +- `livekit.py`: return it from `run()`. +- `orchestrator.py` `_upload_replay_audio`: send the `X-Recording-Started-At` + header (ISO from the epoch). + +### Client + +- Inspector: render spans on the shared timeline by `audio_offset_ms`; + drop the per-turn `turn_idx` grouping for tool/model rows; surface + `model_usage.ttft_ms` when present. + +--- + +## 5 · Test plan (TDD — tests land red first) + +- **Regression (the decisive one):** evaluate-replay with + `recording_started_at` deliberately ≠ `started_at` (a multi-second gap) + + spans whose wall-clock matches the agent's real emit time → assert tool + calls attribute to the correct turn. This is the case **no current test + exercises** — today's fixtures bake `span = started_at + offset` + (`calculate-metrics.processor.test.ts:89`), encoding the bug. +- gen-ai-semconv: `time_to_first_chunk` → `ttft_ms` (present / absent / unit). +- timeline helper: offset math; null when either timestamp missing. +- membership tiling `[turnStartMs, turnEndMs)` — exactly-one-turn; a + speculative-during-user-turn call lands in the user tile and is + **flagged** for the agent turn (`tool_called` fails); no-anchor → + `errored`. +- audio router: header parse (valid / malformed / absent). +- store migration test. +- Re-point / simplify calculate-metrics + analyze-replay tests (backfill gone). + +--- + +## 6 · Risks & accepted assumptions + +- **Co-located clocks (D1).** Agent on a different, non-NTP-synced host → + timeline positions and tool attribution skew, **silently** (no flag, per + D1). Documented; revisit with audio cross-correlation or trace-context + propagation if distributed runs become real. +- **VAD real-audio accuracy.** Every remaining audio-frame metric + (`agent_response_ms`, `interrupted`) and every assertion window rests on + VAD, currently calibrated on synthetic sines only. Unchanged here, but now + the *sole* dependency. Separate follow-up. +- **TTFT availability.** Depends on the dev's instrumentation emitting the + experimental `gen_ai.response.time_to_first_chunk`. Null otherwise. + Accepted (D4). +- **No anchor (legacy SDK).** Timeline + tool/ttft assertions degrade to + null / `errored`. New SDK always sends the header. + +## 7 · Out of scope + +- Turn-source redesign (driver-declared / hybrid) — D2. +- Distributed-clock correlation (cross-correlation / trace propagation). +- `xray.stage.stt` / `xray.stage.tts` → stage-latency metrics. +- Real-audio VAD calibration. diff --git a/package.json b/package.json index 4432666..e8b33b6 100644 --- a/package.json +++ b/package.json @@ -58,7 +58,7 @@ "class-variance-authority": "0.7.1", "clsx": "2.1.1", "drizzle-orm": "0.45.2", - "hono": "4.12.21", + "hono": "4.12.25", "hono-openapi": "1.3.0", "ky": "2.0.2", "lucide-react": "1.14.0", diff --git a/pnpm-lock.yaml b/pnpm-lock.yaml index 3bfcfe7..bf4e1b8 100644 --- a/pnpm-lock.yaml +++ b/pnpm-lock.yaml @@ -10,6 +10,8 @@ overrides: express>qs: ^6.15.2 body-parser>qs: ^6.15.2 cosmiconfig>js-yaml: ^4.2.0 + '@modelcontextprotocol/sdk>hono': ^4.12.25 + '@hono/node-server>hono': ^4.12.25 importers: @@ -23,10 +25,10 @@ importers: version: 5.2.11 '@hono/standard-validator': specifier: 0.2.2 - version: 0.2.2(@standard-schema/spec@1.1.0)(hono@4.12.21) + version: 0.2.2(@standard-schema/spec@1.1.0)(hono@4.12.25) '@scalar/hono-api-reference': specifier: 0.10.14 - version: 0.10.14(hono@4.12.21) + version: 0.10.14(hono@4.12.25) '@tanstack/react-query': specifier: 5.100.9 version: 5.100.9(react@19.2.6) @@ -55,11 +57,11 @@ importers: specifier: 0.45.2 version: 0.45.2(bun-types@1.3.13) hono: - specifier: 4.12.21 - version: 4.12.21 + specifier: 4.12.25 + version: 4.12.25 hono-openapi: specifier: 1.3.0 - version: 1.3.0(@hono/standard-validator@0.2.2(@standard-schema/spec@1.1.0)(hono@4.12.21))(@standard-community/standard-json@0.3.5(@standard-schema/spec@1.1.0)(@types/json-schema@7.0.15)(@valibot/to-json-schema@1.7.0(valibot@1.3.1(typescript@6.0.3)))(quansync@0.2.11)(valibot@1.3.1(typescript@6.0.3))(zod-to-json-schema@3.25.2(zod@4.4.3))(zod@4.4.3))(@standard-community/standard-openapi@0.2.9(@standard-community/standard-json@0.3.5(@standard-schema/spec@1.1.0)(@types/json-schema@7.0.15)(@valibot/to-json-schema@1.7.0(valibot@1.3.1(typescript@6.0.3)))(quansync@0.2.11)(valibot@1.3.1(typescript@6.0.3))(zod-to-json-schema@3.25.2(zod@4.4.3))(zod@4.4.3))(@standard-schema/spec@1.1.0)(openapi-types@12.1.3)(valibot@1.3.1(typescript@6.0.3))(zod@4.4.3))(@types/json-schema@7.0.15)(hono@4.12.21)(openapi-types@12.1.3) + version: 1.3.0(@hono/standard-validator@0.2.2(@standard-schema/spec@1.1.0)(hono@4.12.25))(@standard-community/standard-json@0.3.5(@standard-schema/spec@1.1.0)(@types/json-schema@7.0.15)(@valibot/to-json-schema@1.7.0(valibot@1.3.1(typescript@6.0.3)))(quansync@0.2.11)(valibot@1.3.1(typescript@6.0.3))(zod-to-json-schema@3.25.2(zod@4.4.3))(zod@4.4.3))(@standard-community/standard-openapi@0.2.9(@standard-community/standard-json@0.3.5(@standard-schema/spec@1.1.0)(@types/json-schema@7.0.15)(@valibot/to-json-schema@1.7.0(valibot@1.3.1(typescript@6.0.3)))(quansync@0.2.11)(valibot@1.3.1(typescript@6.0.3))(zod-to-json-schema@3.25.2(zod@4.4.3))(zod@4.4.3))(@standard-schema/spec@1.1.0)(openapi-types@12.1.3)(valibot@1.3.1(typescript@6.0.3))(zod@4.4.3))(@types/json-schema@7.0.15)(hono@4.12.25)(openapi-types@12.1.3) ky: specifier: 2.0.2 version: 2.0.2 @@ -656,7 +658,7 @@ packages: resolution: {integrity: sha512-GwtvgtXxnWsucXvbQXkRgqksiH2Qed37H9xHZocE5sA3N8O8O8/8FA3uclQXxXVzc9XBZuEOMK7+r02FmSpHtw==} engines: {node: '>=18.14.1'} peerDependencies: - hono: ^4 + hono: ^4.12.25 '@hono/standard-validator@0.2.2': resolution: {integrity: sha512-mJ7W84Bt/rSvoIl63Ynew+UZOHAzzRAoAXb3JaWuxAkM/Lzg+ZHTCUiz77KOtn2e623WNN8LkD57Dk0szqUrIw==} @@ -2196,8 +2198,8 @@ packages: hono: optional: true - hono@4.12.21: - resolution: {integrity: sha512-uV63apnb0kyPtAUwoWgaGh9HyIFcv8lgmzPZSiTBQAFOFGIzka5EZ1dZocmGnn0XdX0+XTqJ6Tqv7selMuGLRQ==} + hono@4.12.25: + resolution: {integrity: sha512-2NFaIyNVgJmBs/ecmtGzlmluTFs5cHEWGTdu0t1HBwYzoGXOL5nUQBRMXsXWla5i4KkG//QMzVP88m1+I3fdAQ==} engines: {node: '>=16.9.0'} http-errors@2.0.1: @@ -3198,14 +3200,14 @@ snapshots: - bufferutil - utf-8-validate - '@hono/node-server@1.19.14(hono@4.12.21)': + '@hono/node-server@1.19.14(hono@4.12.25)': dependencies: - hono: 4.12.21 + hono: 4.12.25 - '@hono/standard-validator@0.2.2(@standard-schema/spec@1.1.0)(hono@4.12.21)': + '@hono/standard-validator@0.2.2(@standard-schema/spec@1.1.0)(hono@4.12.25)': dependencies: '@standard-schema/spec': 1.1.0 - hono: 4.12.21 + hono: 4.12.25 '@inquirer/ansi@2.0.5': {} @@ -3236,7 +3238,7 @@ snapshots: '@modelcontextprotocol/sdk@1.29.0(zod@4.4.3)': dependencies: - '@hono/node-server': 1.19.14(hono@4.12.21) + '@hono/node-server': 1.19.14(hono@4.12.25) ajv: 8.20.0 ajv-formats: 3.0.1(ajv@8.20.0) content-type: 1.0.5 @@ -3246,7 +3248,7 @@ snapshots: eventsource-parser: 3.0.8 express: 5.2.1 express-rate-limit: 8.5.1(express@5.2.1) - hono: 4.12.21 + hono: 4.12.25 jose: 6.2.3 json-schema-typed: 8.0.2 pkce-challenge: 5.0.1 @@ -4083,10 +4085,10 @@ snapshots: '@scalar/helpers@0.6.0': {} - '@scalar/hono-api-reference@0.10.14(hono@4.12.21)': + '@scalar/hono-api-reference@0.10.14(hono@4.12.25)': dependencies: '@scalar/client-side-rendering': 0.1.7 - hono: 4.12.21 + hono: 4.12.25 '@scalar/types@0.9.6': dependencies: @@ -4683,17 +4685,17 @@ snapshots: '@types/set-cookie-parser': 2.4.10 set-cookie-parser: 3.1.0 - hono-openapi@1.3.0(@hono/standard-validator@0.2.2(@standard-schema/spec@1.1.0)(hono@4.12.21))(@standard-community/standard-json@0.3.5(@standard-schema/spec@1.1.0)(@types/json-schema@7.0.15)(@valibot/to-json-schema@1.7.0(valibot@1.3.1(typescript@6.0.3)))(quansync@0.2.11)(valibot@1.3.1(typescript@6.0.3))(zod-to-json-schema@3.25.2(zod@4.4.3))(zod@4.4.3))(@standard-community/standard-openapi@0.2.9(@standard-community/standard-json@0.3.5(@standard-schema/spec@1.1.0)(@types/json-schema@7.0.15)(@valibot/to-json-schema@1.7.0(valibot@1.3.1(typescript@6.0.3)))(quansync@0.2.11)(valibot@1.3.1(typescript@6.0.3))(zod-to-json-schema@3.25.2(zod@4.4.3))(zod@4.4.3))(@standard-schema/spec@1.1.0)(openapi-types@12.1.3)(valibot@1.3.1(typescript@6.0.3))(zod@4.4.3))(@types/json-schema@7.0.15)(hono@4.12.21)(openapi-types@12.1.3): + hono-openapi@1.3.0(@hono/standard-validator@0.2.2(@standard-schema/spec@1.1.0)(hono@4.12.25))(@standard-community/standard-json@0.3.5(@standard-schema/spec@1.1.0)(@types/json-schema@7.0.15)(@valibot/to-json-schema@1.7.0(valibot@1.3.1(typescript@6.0.3)))(quansync@0.2.11)(valibot@1.3.1(typescript@6.0.3))(zod-to-json-schema@3.25.2(zod@4.4.3))(zod@4.4.3))(@standard-community/standard-openapi@0.2.9(@standard-community/standard-json@0.3.5(@standard-schema/spec@1.1.0)(@types/json-schema@7.0.15)(@valibot/to-json-schema@1.7.0(valibot@1.3.1(typescript@6.0.3)))(quansync@0.2.11)(valibot@1.3.1(typescript@6.0.3))(zod-to-json-schema@3.25.2(zod@4.4.3))(zod@4.4.3))(@standard-schema/spec@1.1.0)(openapi-types@12.1.3)(valibot@1.3.1(typescript@6.0.3))(zod@4.4.3))(@types/json-schema@7.0.15)(hono@4.12.25)(openapi-types@12.1.3): dependencies: '@standard-community/standard-json': 0.3.5(@standard-schema/spec@1.1.0)(@types/json-schema@7.0.15)(@valibot/to-json-schema@1.7.0(valibot@1.3.1(typescript@6.0.3)))(quansync@0.2.11)(valibot@1.3.1(typescript@6.0.3))(zod-to-json-schema@3.25.2(zod@4.4.3))(zod@4.4.3) '@standard-community/standard-openapi': 0.2.9(@standard-community/standard-json@0.3.5(@standard-schema/spec@1.1.0)(@types/json-schema@7.0.15)(@valibot/to-json-schema@1.7.0(valibot@1.3.1(typescript@6.0.3)))(quansync@0.2.11)(valibot@1.3.1(typescript@6.0.3))(zod-to-json-schema@3.25.2(zod@4.4.3))(zod@4.4.3))(@standard-schema/spec@1.1.0)(openapi-types@12.1.3)(valibot@1.3.1(typescript@6.0.3))(zod@4.4.3) '@types/json-schema': 7.0.15 openapi-types: 12.1.3 optionalDependencies: - '@hono/standard-validator': 0.2.2(@standard-schema/spec@1.1.0)(hono@4.12.21) - hono: 4.12.21 + '@hono/standard-validator': 0.2.2(@standard-schema/spec@1.1.0)(hono@4.12.25) + hono: 4.12.25 - hono@4.12.21: {} + hono@4.12.25: {} http-errors@2.0.1: dependencies: diff --git a/pnpm-workspace.yaml b/pnpm-workspace.yaml index c7d903e..d49a706 100644 --- a/pnpm-workspace.yaml +++ b/pnpm-workspace.yaml @@ -115,6 +115,22 @@ overrides: # satisfies the advisory's >=4.1.2. Surgical pin on the cosmiconfig parent. # Remove once cosmiconfig bumps js-yaml. Added 2026-06-16. "cosmiconfig>js-yaml": "^4.2.0" + # GHSA-j6c9-x7qj-28xf / GHSA-rv63-4mwf-qqc2 / GHSA-wgpf-jwqj-8h8p — hono + # <4.12.25 has body-limit-middleware bypasses (Content-Length understated on + # AWS Lambda) and a Lambda@Edge adapter that keeps only the last value of a + # repeated request header. We pin hono@4.12.25 directly (package.json), but + # bunqueue's embedded MCP server pulls a second, older copy: both + # @modelcontextprotocol/sdk>hono and @modelcontextprotocol/sdk> + # @hono/node-server>hono resolve 4.12.21. xray deploys on Bun.serve as a + # single image, never AWS Lambda / Lambda@Edge, so neither advisory is + # reachable here — but `pnpm audit --audit-level=moderate` (supply-chain CI) + # blocks merge until the transitive copies are bumped. Surgical pins on the + # MCP-SDK subtree so the override disappears once the SDK bumps its hono. + # 4.12.25 was published 2026-06-09, past the 7-day cooldown (no + # minimumReleaseAgeExclude needed). Remove once @modelcontextprotocol/sdk + # ships a release on hono >=4.12.25. Added 2026-06-17. + "@modelcontextprotocol/sdk>hono": "^4.12.25" + "@hono/node-server>hono": "^4.12.25" # VEX-style "not affected" disposition: GHSA-gv7w-rqvm-qjhr is unreachable in # this repo, so the audit gate is told to skip that one advisory — we do NOT diff --git a/sdk/python/src/xray/conversation.py b/sdk/python/src/xray/conversation.py index 081fdd6..391a503 100644 --- a/sdk/python/src/xray/conversation.py +++ b/sdk/python/src/xray/conversation.py @@ -143,6 +143,11 @@ def max_latency_ms(cls, max_ms: int) -> Assertion: @classmethod def max_ttft_ms(cls, max_ms: int) -> Assertion: + """Model time-to-first-token of the turn's earliest LLM call must be + ≤ ``max_ms``. Sourced from the GenAI semconv span attribute + ``gen_ai.response.time_to_first_chunk`` — the assertion ``errors`` + (≠ fails) when the agent's instrumentation doesn't emit it or the + upload carried no recording anchor.""" if max_ms < 1: raise ValueError( f"Assertion.max_ttft_ms: max_ms must be >= 1 (got {max_ms})", @@ -442,12 +447,16 @@ class JudgeOutcome: @dataclass(frozen=True) class TurnMetrics: - """Per-turn timing metrics computed server-side.""" + """Per-turn timing metrics computed server-side. + + Model TTFT is no longer a per-turn metric — it's an optional per-call + attribute (``model_usage.ttft_ms``) surfaced on the inspector timeline + (see spec 0001), not part of this struct. + """ turn_idx: int role: Role agent_response_ms: int | None - ttft_ms: int | None interrupted: bool diff --git a/sdk/python/src/xray/orchestrator.py b/sdk/python/src/xray/orchestrator.py index 34e06fe..4b340c7 100644 --- a/sdk/python/src/xray/orchestrator.py +++ b/sdk/python/src/xray/orchestrator.py @@ -332,9 +332,28 @@ async def _drive_replay( and runtime_result is not None and runtime_result.full_audio_path is not None ): + if runtime_result.recording_started_at_epoch is None: + # A runtime that produced audio but didn't report its sample-0 + # wall-clock leaves the server unable to place spans on the audio + # timeline: every tool_called / tool_not_called / tool_args_match / + # max_ttft_ms assertion comes back 'errored'. Warn loudly so a + # custom Runtime author sees the one missing field instead of + # debugging the server. (The built-in LiveKit runtimes always set + # it; this guards the documented pluggable ABC.) + logger.warning( + "replay %s: runtime produced audio but left " + "RuntimeResult.recording_started_at_epoch unset — span→turn " + "attribution is skipped and tool/ttft assertions will report " + "'errored'. Set it to the Unix-epoch-seconds wall-clock of audio " + "sample 0.", + replay_id, + ) try: await _upload_replay_audio( - client=client, replay_id=replay_id, audio_path=runtime_result.full_audio_path + client=client, + replay_id=replay_id, + audio_path=runtime_result.full_audio_path, + recording_started_at_epoch=runtime_result.recording_started_at_epoch, ) except XrayError as e: logger.exception("audio upload failed on replay %s", replay_id) @@ -445,7 +464,6 @@ class _TurnMetricsPayload(BaseModel): turn_idx: int role: Role agent_response_ms: int | None = None - ttft_ms: int | None = None interrupted: bool @@ -500,7 +518,6 @@ def _result_from_payload(payload: _ReplayResultPayload, *, replay_id: str) -> Re turn_idx=m.turn_idx, role=m.role, agent_response_ms=m.agent_response_ms, - ttft_ms=m.ttft_ms, interrupted=m.interrupted, ) for m in payload.metrics.turns @@ -648,20 +665,36 @@ def _raise_for_status_typed(response: httpx.Response, endpoint: str) -> None: async def _upload_replay_audio( - *, client: httpx.AsyncClient, replay_id: str, audio_path: str + *, + client: httpx.AsyncClient, + replay_id: str, + audio_path: str, + recording_started_at_epoch: float | None, ) -> None: path = Path(audio_path) bytes_ = path.read_bytes() if len(bytes_) > MAX_AUDIO_BYTES: raise AudioTooLargeError(byte_size=len(bytes_), max_bytes=MAX_AUDIO_BYTES) + headers = {"content-type": "audio/wav"} + # The recording anchor: wall-clock of audio sample 0. The server maps span + # timestamps onto the audio timeline against it (spec 0001). Omitted when + # the runtime produced no timed audio — the server then skips attribution. + if recording_started_at_epoch is not None: + headers["x-recording-started-at"] = _epoch_to_iso_z(recording_started_at_epoch) response = await client.post( f"/v1/replays/{replay_id}/audio", content=bytes_, - headers={"content-type": "audio/wav"}, + headers=headers, ) _raise_for_status_typed(response, f"POST /v1/replays/{replay_id}/audio") +def _epoch_to_iso_z(epoch_seconds: float) -> str: + """Unix epoch seconds → UTC ISO-8601 with a trailing ``Z`` — the + ``X-Recording-Started-At`` anchor format the server validates.""" + return datetime.fromtimestamp(epoch_seconds, tz=timezone.utc).isoformat().replace("+00:00", "Z") + + def _check_recorded_audio_exists(conversation: Conversation) -> None: for idx, turn in enumerate(conversation.turns): audio = turn.audio diff --git a/sdk/python/src/xray/runtime/base.py b/sdk/python/src/xray/runtime/base.py index 7c65b54..d0a7164 100644 --- a/sdk/python/src/xray/runtime/base.py +++ b/sdk/python/src/xray/runtime/base.py @@ -33,6 +33,11 @@ class RuntimeResult: # (if produced). The orchestrator uploads it to xray. full_audio_path: str | None = None full_transcript: str | None = None + # Wall-clock (Unix epoch seconds) of audio sample 0 in the mixdown — the + # earliest turn ``started_at``. The orchestrator sends it as the + # ``X-Recording-Started-At`` header so the server can map span timestamps + # onto the audio timeline (see spec 0001). None when no audio was produced. + recording_started_at_epoch: float | None = None class Runtime(ABC): diff --git a/sdk/python/src/xray/runtime/livekit.py b/sdk/python/src/xray/runtime/livekit.py index 629446d..55a3794 100644 --- a/sdk/python/src/xray/runtime/livekit.py +++ b/sdk/python/src/xray/runtime/livekit.py @@ -237,10 +237,11 @@ def _on_transcription( finally: await room.disconnect() - mixdown_path = self._write_mixdown(segments) + mixdown_path, recording_t0 = self._write_mixdown(segments) return RuntimeResult( responses=responses, full_audio_path=str(mixdown_path) if mixdown_path is not None else None, + recording_started_at_epoch=recording_t0, full_transcript=" ".join(r.transcript for r in responses if r.transcript).strip() or None, ) @@ -434,17 +435,17 @@ async def _consume_frames() -> None: duration_ms=int((segment.ended_at - segment.started_at) * 1000), ) - def _write_mixdown(self, segments: list[_TurnSegment]) -> Path | None: + def _write_mixdown(self, segments: list[_TurnSegment]) -> tuple[Path | None, float | None]: if not segments: - return None + return None, None mixdown_root = self.mixdown_dir or (self.cache_root / "replays") mixdown_root.mkdir(parents=True, exist_ok=True) out_path = mixdown_root / f"{self.replay_id}.wav" try: - write_stereo_mixdown(segments=segments, out_path=out_path) + recording_t0 = write_stereo_mixdown(segments=segments, out_path=out_path) except OSError as e: raise MixdownError(f"could not write mixdown WAV: {e}") from e - return out_path + return out_path, recording_t0 def _injected_user_pcm(self, idx: int) -> bytes: """PCM for user turn ``idx`` from the orchestrator-injected map. @@ -556,7 +557,7 @@ def mint_user_token( return builder.to_jwt() -def write_stereo_mixdown(*, segments: list[_TurnSegment], out_path: Path) -> None: +def write_stereo_mixdown(*, segments: list[_TurnSegment], out_path: Path) -> float | None: """Write segments as a wall-clock-aligned stereo WAV: left = user, right = agent. Each segment is placed at its captured `started_at` offset from t0 (the earliest started_at across all segments). Gaps @@ -568,6 +569,10 @@ def write_stereo_mixdown(*, segments: list[_TurnSegment], out_path: Path) -> Non concat) is gone — VAD on the server reads the wall-clock-aligned file to derive turn boundaries (`turn_start_ms` / `voice_start_ms` in `replay_turns`). + + Returns ``t0`` — the Unix-epoch wall-clock of audio sample 0 — so the + orchestrator can send it as the recording anchor. None when no audio + was placed (empty WAV). """ placed = [s for s in segments if s.pcm and s.started_at is not None] if not placed: @@ -576,7 +581,7 @@ def write_stereo_mixdown(*, segments: list[_TurnSegment], out_path: Path) -> Non w.setnchannels(2) w.setsampwidth(SAMPLE_WIDTH_BYTES) w.setframerate(SAMPLE_RATE) - return + return None t0 = min(s.started_at for s in placed if s.started_at is not None) total_samples = 0 @@ -608,13 +613,15 @@ def write_stereo_mixdown(*, segments: list[_TurnSegment], out_path: Path) -> Non w.setframerate(SAMPLE_RATE) w.writeframes(_interleave_lr(left=bytes(left), right=bytes(right))) + return t0 + def write_live_mixdown( *, user_frames: list[tuple[float, bytes]], agent_frames: list[tuple[float, bytes]], out_path: Path, -) -> None: +) -> float | None: """Write a wall-clock-aligned stereo WAV (L = user mic, R = agent) for a live session. Each frame is ``(wall_clock_seconds, int16_pcm_bytes)``. @@ -639,7 +646,7 @@ def write_live_mixdown( w.setnchannels(2) w.setsampwidth(SAMPLE_WIDTH_BYTES) w.setframerate(SAMPLE_RATE) - return + return None t0 = min(t for t, _pcm in [*user, *agent]) user_placed, user_total = _place_live_frames(user, t0) @@ -659,6 +666,8 @@ def write_live_mixdown( w.setframerate(SAMPLE_RATE) w.writeframes(_interleave_lr(left=bytes(left), right=bytes(right))) + return t0 + def _place_live_frames( frames: list[tuple[float, bytes]], t0: float diff --git a/sdk/python/src/xray/runtime/livekit_live.py b/sdk/python/src/xray/runtime/livekit_live.py index 3af02b1..848d2fd 100644 --- a/sdk/python/src/xray/runtime/livekit_live.py +++ b/sdk/python/src/xray/runtime/livekit_live.py @@ -255,10 +255,11 @@ def _on_track(track: LkTrack, _publication: object, participant: LkParticipant) len(user_frames), len(agent_frames), ) - mixdown_path = self._write_mixdown(user_frames, agent_frames) + mixdown_path, recording_t0 = self._write_mixdown(user_frames, agent_frames) return RuntimeResult( responses=[], full_audio_path=str(mixdown_path) if mixdown_path is not None else None, + recording_started_at_epoch=recording_t0, full_transcript=None, ) @@ -335,19 +336,19 @@ async def _pump_agent( def _write_mixdown( self, user_frames: list[TimedFrame], agent_frames: list[TimedFrame] - ) -> Path | None: + ) -> tuple[Path | None, float | None]: if not user_frames and not agent_frames: - return None + return None, None mixdown_root = self.mixdown_dir or (self.cache_root / "replays") mixdown_root.mkdir(parents=True, exist_ok=True) out_path = mixdown_root / f"{self.replay_id}.wav" try: - write_live_mixdown( + recording_t0 = write_live_mixdown( user_frames=user_frames, agent_frames=agent_frames, out_path=out_path ) except OSError as e: raise MixdownError(f"could not write live mixdown WAV: {e}") from e - return out_path + return out_path, recording_t0 @override async def aclose(self) -> None: diff --git a/sdk/python/tests/test_live_runtime.py b/sdk/python/tests/test_live_runtime.py index 9be874a..ee701cf 100644 --- a/sdk/python/tests/test_live_runtime.py +++ b/sdk/python/tests/test_live_runtime.py @@ -483,10 +483,12 @@ def _boom_factory(*, sample_rate: int, frame_samples: int) -> Any: def test_write_live_mixdown_wall_clock_aligned(tmp_path: Path): # User speaks at t0 for 200ms; agent replies 0.5s in for 500ms. # Total span = max(0.0+0.2, 0.5+0.5) = 1.0s = SAMPLE_RATE frames. + # Returns t0 — the recording anchor the orchestrator sends on upload. user = [(10.0, _silence(200))] agent = [(10.5, _silence(500))] out = tmp_path / "live.wav" - write_live_mixdown(user_frames=user, agent_frames=agent, out_path=out) + recording_t0 = write_live_mixdown(user_frames=user, agent_frames=agent, out_path=out) + assert recording_t0 == 10.0 with wave.open(str(out), "rb") as w: assert w.getnchannels() == 2 assert w.getnframes() == SAMPLE_RATE @@ -505,7 +507,8 @@ def test_write_live_mixdown_bursts_laid_sequentially(tmp_path: Path): def test_write_live_mixdown_empty(tmp_path: Path): out = tmp_path / "empty.wav" - write_live_mixdown(user_frames=[], agent_frames=[], out_path=out) + recording_t0 = write_live_mixdown(user_frames=[], agent_frames=[], out_path=out) + assert recording_t0 is None with wave.open(str(out), "rb") as w: assert w.getnchannels() == 2 assert w.getnframes() == 0 diff --git a/sdk/python/tests/test_livekit_runtime.py b/sdk/python/tests/test_livekit_runtime.py index 2370c18..d4d0495 100644 --- a/sdk/python/tests/test_livekit_runtime.py +++ b/sdk/python/tests/test_livekit_runtime.py @@ -285,15 +285,17 @@ def test_write_stereo_mixdown_round_trips(tmp_path: Path): def test_write_stereo_mixdown_wall_clock_aligned(tmp_path: Path): """Segments placed at their wall-clock offsets, with silence padding - between. Agent starts 0.5s after t0; total span = 1s (agent 0.5–1.0s).""" + between. Agent starts 0.5s after t0; total span = 1s (agent 0.5–1.0s). + Returns t0 — the recording anchor the orchestrator sends on upload.""" user = _TurnSegment(role="user", idx=0, key="u0", started_at=10.0) user.pcm.extend(_make_silence_pcm(200)) # 200ms agent = _TurnSegment(role="agent", idx=1, key="a0", started_at=10.5) agent.pcm.extend(_make_silence_pcm(500)) # 500ms out = tmp_path / "wall_clock.wav" - write_stereo_mixdown(segments=[user, agent], out_path=out) + recording_t0 = write_stereo_mixdown(segments=[user, agent], out_path=out) + assert recording_t0 == 10.0 with wave.open(str(out), "rb") as w: assert w.getnchannels() == 2 # t0 = 10.0, span = max(10.0+0.2, 10.5+0.5) - 10.0 = 1.0s = 48000 frames @@ -301,9 +303,11 @@ def test_write_stereo_mixdown_wall_clock_aligned(tmp_path: Path): def test_write_stereo_mixdown_handles_empty_segments(tmp_path: Path): - """All-silent input: produces a valid empty stereo WAV (header only).""" + """All-silent input: produces a valid empty stereo WAV (header only), + and no anchor — there is no sample 0 to timestamp.""" out = tmp_path / "empty.wav" - write_stereo_mixdown(segments=[], out_path=out) + recording_t0 = write_stereo_mixdown(segments=[], out_path=out) + assert recording_t0 is None with wave.open(str(out), "rb") as w: assert w.getnchannels() == 2 assert w.getnframes() == 0 @@ -324,6 +328,9 @@ def test_runtime_publishes_injected_user_turn_and_produces_mixdown(tmp_path: Pat room = rtc.Room.rooms[0] assert room.local_participant.publish_track.await_count == 1 assert result.full_audio_path is not None + # The recording anchor (wall-clock of mixdown sample 0) rides along so + # the orchestrator can send X-Recording-Started-At on upload. + assert result.recording_started_at_epoch is not None out_path = Path(result.full_audio_path) assert out_path.exists() and out_path.stat().st_size > 44 # WAV header is 44 B with wave.open(str(out_path), "rb") as w: diff --git a/sdk/python/tests/test_orchestrator.py b/sdk/python/tests/test_orchestrator.py index 256897a..779d799 100644 --- a/sdk/python/tests/test_orchestrator.py +++ b/sdk/python/tests/test_orchestrator.py @@ -10,6 +10,7 @@ import json import wave from collections.abc import Iterable +from datetime import datetime, timezone from pathlib import Path import httpx @@ -108,10 +109,12 @@ def __init__( responses: list[AgentResponse] | None = None, *, full_audio_path: str | None = None, + recording_started_at_epoch: float | None = None, raise_on_run: Exception | None = None, ) -> None: self.responses = responses or [] self.full_audio_path = full_audio_path + self.recording_started_at_epoch = recording_started_at_epoch self.raise_on_run = raise_on_run self.bound: dict[str, str] | None = None self.closed = False @@ -123,7 +126,11 @@ def bind(self, *, replay_id: str, conversation_hash: str) -> None: async def run(self, conversation: Conversation) -> RuntimeResult: if self.raise_on_run is not None: raise self.raise_on_run - return RuntimeResult(responses=self.responses, full_audio_path=self.full_audio_path) + return RuntimeResult( + responses=self.responses, + full_audio_path=self.full_audio_path, + recording_started_at_epoch=self.recording_started_at_epoch, + ) @override async def aclose(self) -> None: @@ -228,9 +235,16 @@ async def test_full_chain_returns_replay_result_with_passed_true(tmp_path: Path) ), ) + # Anchor: wall-clock of mixdown sample 0. Built from a known datetime + # so the expected header string is exact, not re-derived via the + # helper under test. + recording_t0 = datetime(2026, 5, 26, 14, 31, 31, 23000, tzinfo=timezone.utc) result = await run( conversation=conversation, - runtime=StubRuntime(full_audio_path=str(wav)), + runtime=StubRuntime( + full_audio_path=str(wav), + recording_started_at_epoch=recording_t0.timestamp(), + ), xray_url="http://test.local", ) @@ -245,6 +259,9 @@ async def test_full_chain_returns_replay_result_with_passed_true(tmp_path: Path) assert post_conv.called assert post_replay.called assert post_audio.called + audio_request: object = getattr(post_audio.calls[0], "request", None) + assert isinstance(audio_request, httpx.Request) + assert audio_request.headers["x-recording-started-at"] == "2026-05-26T14:31:31.023000Z" assert post_analyze.called assert sse.called diff --git a/sdk/python/tests/test_run_live.py b/sdk/python/tests/test_run_live.py index 01e89c9..2f49ebd 100644 --- a/sdk/python/tests/test_run_live.py +++ b/sdk/python/tests/test_run_live.py @@ -126,7 +126,6 @@ async def test_run_live_full_chain_returns_passed_result(tmp_path: Path): "turn_idx": 0, "role": "user", "agent_response_ms": None, - "ttft_ms": None, "interrupted": False, } ], diff --git a/src/client/inspector/analysis-progress/analysis-progress.test.tsx b/src/client/inspector/analysis-progress/analysis-progress.test.tsx index ab8b49f..935ecfd 100644 --- a/src/client/inspector/analysis-progress/analysis-progress.test.tsx +++ b/src/client/inspector/analysis-progress/analysis-progress.test.tsx @@ -17,6 +17,7 @@ function buildReplay(overrides: Partial = {}): ReplayDetai failure_reason: null, started_at: "2026-05-15T10:00:00.000Z", finished_at: null, + recording_started_at: null, audio_path: "/data/audio/replay.wav", job_id: "job-1", run_config: null, diff --git a/src/client/inspector/evaluation/evaluation.test-utils.ts b/src/client/inspector/evaluation/evaluation.test-utils.ts index 5e0b21d..e8b796c 100644 --- a/src/client/inspector/evaluation/evaluation.test-utils.ts +++ b/src/client/inspector/evaluation/evaluation.test-utils.ts @@ -36,7 +36,6 @@ export function makeTurnMetrics(overrides: Partial = {}): T turn_idx: 0, role: "agent", agent_response_ms: 250, - ttft_ms: 80, interrupted: false, interruption_start_ms: null, ...overrides, diff --git a/src/client/inspector/inspector.test.tsx b/src/client/inspector/inspector.test.tsx index a60c1e9..33809e6 100644 --- a/src/client/inspector/inspector.test.tsx +++ b/src/client/inspector/inspector.test.tsx @@ -23,6 +23,7 @@ function buildReplay(overrides: Partial = {}): ReplayDetai failure_reason: null, started_at: "2026-05-15T10:00:00.000Z", finished_at: "2026-05-15T10:00:30.000Z", + recording_started_at: null, audio_path: null, job_id: null, run_config: null, @@ -192,6 +193,7 @@ describe("Inspector TraceCard", () => { started_at: "2026-05-25T10:00:00.200Z", ended_at: "2026-05-25T10:00:01.400Z", attributes_json: "{}", + audio_offset_ms: 200, }, ], }), diff --git a/src/client/inspector/inspector.tsx b/src/client/inspector/inspector.tsx index 2de48b1..7da8bda 100644 --- a/src/client/inspector/inspector.tsx +++ b/src/client/inspector/inspector.tsx @@ -219,12 +219,7 @@ function TraceCard({ replay }: { replay: ReplayDetailResponse }) { - + ); diff --git a/src/client/inspector/live-updates/replay-live-updates.test.tsx b/src/client/inspector/live-updates/replay-live-updates.test.tsx index 860754b..62e6938 100644 --- a/src/client/inspector/live-updates/replay-live-updates.test.tsx +++ b/src/client/inspector/live-updates/replay-live-updates.test.tsx @@ -68,6 +68,7 @@ function buildReplay(overrides: Partial = {}): ReplayDetai failure_reason: null, started_at: "2026-05-15T10:00:00.000Z", finished_at: null, + recording_started_at: null, audio_path: null, job_id: null, run_config: null, diff --git a/src/client/inspector/metrics/turn-metrics.test.tsx b/src/client/inspector/metrics/turn-metrics.test.tsx index 94b24c6..602a3f6 100644 --- a/src/client/inspector/metrics/turn-metrics.test.tsx +++ b/src/client/inspector/metrics/turn-metrics.test.tsx @@ -13,7 +13,6 @@ function turn(overrides: Partial): TurnMetricsResponse { turn_idx: 0, role: "agent", agent_response_ms: 250, - ttft_ms: 80, interrupted: false, interruption_start_ms: null, ...overrides, @@ -21,12 +20,12 @@ function turn(overrides: Partial): TurnMetricsResponse { } describe("TurnMetricsSection", () => { - it("renders a row per turn with the response/ttft timings", () => { + it("renders a row per turn with the response timing", () => { render( , ); @@ -34,7 +33,6 @@ describe("TurnMetricsSection", () => { expect(screen.getByText("T01")).toBeTruthy(); // formatDurationMs renders ≥1000ms as seconds, sub-second as ms. expect(screen.getByText("2.43s")).toBeTruthy(); - expect(screen.getByText("520ms")).toBeTruthy(); }); it("shows the barge-in time as a clock for an interrupted turn", () => { diff --git a/src/client/inspector/metrics/turn-metrics.tsx b/src/client/inspector/metrics/turn-metrics.tsx index 52493e5..7eee71c 100644 --- a/src/client/inspector/metrics/turn-metrics.tsx +++ b/src/client/inspector/metrics/turn-metrics.tsx @@ -15,8 +15,9 @@ const METRIC_HEAD = "h-7 text-[10px] uppercase tracking-wider text-muted-foregro /** * Per-turn timing for the Run details panel: the silence gap before the agent - * responds (`agent_response_ms`), time-to-first-token, and barge-in. Sits with - * model usage + tool calls — observability data, not a pass/fail verdict. + * responds (`agent_response_ms`) and barge-in. Sits with model usage + tool + * calls — observability data, not a pass/fail verdict. (Model TTFT moved to a + * per-call attribute on the span detail — spec 0001.) */ export function TurnMetricsSection({ turns }: { turns: TurnMetricsResponse[] }) { if (turns.length === 0) return null; @@ -36,7 +37,6 @@ export function TurnMetricsSection({ turns }: { turns: TurnMetricsResponse[] }) turn role resp - ttft barge-in @@ -60,9 +60,6 @@ function TurnMetricRow({ turn }: { turn: TurnMetricsResponse }) { {formatMetricMs(turn.agent_response_ms)} - - {formatMetricMs(turn.ttft_ms)} - {turn.interrupted ? ( diff --git a/src/client/inspector/transcript/transcript.test.tsx b/src/client/inspector/transcript/transcript.test.tsx index 90dfe59..deecb07 100644 --- a/src/client/inspector/transcript/transcript.test.tsx +++ b/src/client/inspector/transcript/transcript.test.tsx @@ -18,6 +18,7 @@ function buildReplay(overrides: Partial = {}): ReplayDetai failure_reason: null, started_at: "2026-05-15T10:00:00.000Z", finished_at: "2026-05-15T10:00:30.000Z", + recording_started_at: null, audio_path: "/data/audio/replay.wav", job_id: null, run_config: null, diff --git a/src/client/replays/compare.test.tsx b/src/client/replays/compare.test.tsx index b2c477e..4fb6ae6 100644 --- a/src/client/replays/compare.test.tsx +++ b/src/client/replays/compare.test.tsx @@ -25,6 +25,7 @@ function buildReplay( failure_reason: null, started_at: "2026-05-15T10:00:00.000Z", finished_at: "2026-05-15T10:00:30.000Z", + recording_started_at: null, audio_path: null, job_id: null, run_config, diff --git a/src/client/trace-tree/attribution.test.ts b/src/client/trace-tree/attribution.test.ts index 44de95d..139e01d 100644 --- a/src/client/trace-tree/attribution.test.ts +++ b/src/client/trace-tree/attribution.test.ts @@ -1,11 +1,8 @@ import type { ReplayTurnResponse, SpanResponse } from "@/client/api/api.types.ts"; -import { attributeSpansToTurns, toReplaySeconds } from "./attribution.ts"; +import { attributeSpansToTurns, spanStartSeconds } from "./attribution.ts"; import { describe, expect, it } from "bun:test"; -const REPLAY_START = "2026-05-25T10:00:00.000Z"; -const REPLAY_START_MS = Date.parse(REPLAY_START); - function turn( idx: number, role: "user" | "agent", @@ -22,8 +19,7 @@ function turn( }; } -function span(id: number, name: string, offsetFromReplayStartMs: number): SpanResponse { - const started = new Date(REPLAY_START_MS + offsetFromReplayStartMs).toISOString(); +function span(id: number, name: string, audioOffsetMs: number | null): SpanResponse { return { id, trace_id: "trace", @@ -31,58 +27,71 @@ function span(id: number, name: string, offsetFromReplayStartMs: number): SpanRe parent_span_id: null, name, vocabulary: "xray", - started_at: started, - ended_at: started, + started_at: "2026-05-25T10:00:00.000Z", + ended_at: "2026-05-25T10:00:00.000Z", attributes_json: "{}", + audio_offset_ms: audioOffsetMs, }; } describe("attributeSpansToTurns", () => { + // turn_end_ms 2_500 then 6_500 → clamped windows [0,2500), [2500,6500). const turns: readonly ReplayTurnResponse[] = [ turn(0, "user", 0, 2_500), - turn(1, "agent", 3_000, 6_500), + turn(1, "agent", 2_500, 6_500), ]; - it("places each span on its enclosing turn", () => { - const result = attributeSpansToTurns( - turns, - [span(1, "stt.transcribe", 500), span(2, "tts.synthesize", 4_000)], - REPLAY_START, - ); + it("places each span on its enclosing turn by audio_offset_ms", () => { + const result = attributeSpansToTurns(turns, [ + span(1, "stt.transcribe", 500), + span(2, "tts.synthesize", 4_000), + ]); expect(result.perTurn.get(0)?.map((s) => s.id)).toEqual([1]); expect(result.perTurn.get(1)?.map((s) => s.id)).toEqual([2]); expect(result.untimed).toEqual([]); }); - it("collects spans outside any turn into untimed", () => { - const result = attributeSpansToTurns( - turns, - [span(1, "setup", -1_000), span(2, "teardown", 7_000)], - REPLAY_START, - ); + it("collects spans outside every window into untimed", () => { + const result = attributeSpansToTurns(turns, [ + span(1, "setup", -1_000), // before the first window + span(2, "teardown", 7_000), // after the last window + ]); expect(result.untimed.map((s) => s.id)).toEqual([1, 2]); expect(result.perTurn.get(0)).toEqual([]); expect(result.perTurn.get(1)).toEqual([]); }); + it("puts a span with a null offset (no recording anchor) into untimed", () => { + const result = attributeSpansToTurns(turns, [span(1, "unplaceable", null)]); + expect(result.untimed.map((s) => s.id)).toEqual([1]); + expect(result.perTurn.get(0)).toEqual([]); + }); + it("places a span on the exact start boundary inside that turn", () => { - const result = attributeSpansToTurns(turns, [span(1, "boundary", 0)], REPLAY_START); + const result = attributeSpansToTurns(turns, [span(1, "boundary", 0)]); expect(result.perTurn.get(0)?.map((s) => s.id)).toEqual([1]); expect(result.untimed).toEqual([]); }); - it("places a span on the exact end boundary inside that turn", () => { - const result = attributeSpansToTurns(turns, [span(1, "boundary", 2_500)], REPLAY_START); - expect(result.perTurn.get(0)?.map((s) => s.id)).toEqual([1]); + it("assigns a boundary span to the LATER turn — matching the server's half-open window", () => { + // The shared turn edge at 2500 belongs to turn 1 (half-open [2500,6500)), + // not turn 0. This is the rule the assertion evaluator uses, so the + // inspector groups the span under the same turn its assertion scored. + const result = attributeSpansToTurns(turns, [span(1, "boundary", 2_500)]); + expect(result.perTurn.get(1)?.map((s) => s.id)).toEqual([1]); + expect(result.perTurn.get(0)).toEqual([]); }); - it("falls into untimed when a span sits in the gap between turns", () => { - const result = attributeSpansToTurns(turns, [span(1, "gap", 2_700)], REPLAY_START); - expect(result.untimed.map((s) => s.id)).toEqual([1]); + it("tiles with no gaps: a span between voice ends still lands in the later turn", () => { + // turn_end 2500 then 6500 leaves no gap once clamped — offset 2700 is in + // turn 1's window, never untimed. + const result = attributeSpansToTurns(turns, [span(1, "between", 2_700)]); + expect(result.perTurn.get(1)?.map((s) => s.id)).toEqual([1]); + expect(result.untimed).toEqual([]); }); it("returns empty buckets for each turn when no spans land", () => { - const result = attributeSpansToTurns(turns, [], REPLAY_START); + const result = attributeSpansToTurns(turns, []); expect(result.perTurn.size).toBe(2); expect(result.perTurn.get(0)).toEqual([]); expect(result.perTurn.get(1)).toEqual([]); @@ -90,14 +99,16 @@ describe("attributeSpansToTurns", () => { }); }); -describe("toReplaySeconds", () => { - it("subtracts the replay start and converts to seconds", () => { - const result = toReplaySeconds(new Date(REPLAY_START_MS + 3_250).toISOString(), REPLAY_START); - expect(result).toBeCloseTo(3.25, 5); +describe("spanStartSeconds", () => { + it("converts audio_offset_ms to seconds", () => { + expect(spanStartSeconds(span(1, "x", 3_250))).toBeCloseTo(3.25, 5); + }); + + it("preserves a negative offset (span before recording t=0)", () => { + expect(spanStartSeconds(span(1, "x", -500))).toBeCloseTo(-0.5, 5); }); - it("returns negative seconds for events before replay start", () => { - const result = toReplaySeconds(new Date(REPLAY_START_MS - 500).toISOString(), REPLAY_START); - expect(result).toBeCloseTo(-0.5, 5); + it("returns null when the span has no offset", () => { + expect(spanStartSeconds(span(1, "x", null))).toBeNull(); }); }); diff --git a/src/client/trace-tree/attribution.ts b/src/client/trace-tree/attribution.ts index d154e86..e31b928 100644 --- a/src/client/trace-tree/attribution.ts +++ b/src/client/trace-tree/attribution.ts @@ -1,4 +1,5 @@ import type { ReplayTurnResponse, SpanResponse } from "@/client/api/api.types.ts"; +import { clampedTurnWindows, offsetInTurnWindow } from "@/server/replays/timeline.ts"; export type AttributionResult = Readonly<{ perTurn: ReadonlyMap; @@ -6,45 +7,50 @@ export type AttributionResult = Readonly<{ }>; /** - * Time-range attribution: a span belongs to turn `t` iff its - * `started_at` falls inside `[replayStart + t.turn_start_ms, - * replayStart + t.turn_end_ms]`. Spans matching no turn end up in - * `untimed`. + * Group spans under the turn that owns their audio-timeline offset, for DISPLAY + * clustering in the trace tree. A span belongs to turn `t` iff its + * server-derived `audio_offset_ms` falls in `t`'s clamped attribution window + * `[turnStartMs, turnEndMs)` — the SAME windows and half-open rule the + * assertion evaluator uses (`clampedTurnWindows` / `offsetInTurnWindow` from + * `@/server/replays/timeline.ts`), so the inspector can never cluster a + * tool/model span under a different turn than the one its assertion was scored + * against. * - * Pure function — no React, no I/O. Boundary inputs (`turns`, `spans`, - * `replayStartIso`) are already validated by the API codec. + * Spans with a null `audio_offset_ms` (the replay has no recording anchor, so + * nothing is placeable) land in `untimed` — never silently shifted onto a + * fallback origin (spec 0001 §3.1). + * + * Pure function — no React, no I/O. Boundary inputs are already validated by the + * API codec. */ export function attributeSpansToTurns( turns: readonly ReplayTurnResponse[], spans: readonly SpanResponse[], - replayStartIso: string, ): AttributionResult { - const replayStartMs = Date.parse(replayStartIso); + // Windows tile by each turn's voice_end_ms — the SAME boundary the server + // evaluator attributes against (spec 0001 §3.4), so display can't drift from + // the scored result. + const windows = clampedTurnWindows(turns.map((t) => t.voice_end_ms)); const perTurn = new Map(); + for (const turn of turns) perTurn.set(turn.idx, []); const untimed: SpanResponse[] = []; - for (const turn of turns) { - perTurn.set(turn.idx, []); - } - for (const span of spans) { - const spanStartMs = Date.parse(span.started_at) - replayStartMs; - const owner = turns.find((t) => spanStartMs >= t.turn_start_ms && spanStartMs <= t.turn_end_ms); - if (owner === undefined) { - untimed.push(span); - } else { - const bucket = perTurn.get(owner.idx); - if (bucket === undefined) { - untimed.push(span); - } else { - bucket.push(span); - } - } + const offset = span.audio_offset_ms; + const ownerIdx = offset === null ? -1 : windows.findIndex((w) => offsetInTurnWindow(offset, w)); + const owner = ownerIdx === -1 ? undefined : turns[ownerIdx]; + const bucket = owner === undefined ? undefined : perTurn.get(owner.idx); + if (bucket === undefined) untimed.push(span); + else bucket.push(span); } return { perTurn, untimed }; } -export function toReplaySeconds(isoTimestamp: string, replayStartIso: string): number { - return (Date.parse(isoTimestamp) - Date.parse(replayStartIso)) / 1000; +/** + * Seconds from the recording's t=0 to a span's `audio_offset_ms`, the offset the + * waveform/playhead use. Null when the span can't be placed (no anchor). + */ +export function spanStartSeconds(span: SpanResponse): number | null { + return span.audio_offset_ms === null ? null : span.audio_offset_ms / 1000; } diff --git a/src/client/trace-tree/build-tree.test.ts b/src/client/trace-tree/build-tree.test.ts index 38cf22a..7f36a37 100644 --- a/src/client/trace-tree/build-tree.test.ts +++ b/src/client/trace-tree/build-tree.test.ts @@ -39,16 +39,13 @@ function span( started_at: new Date(REPLAY_START_MS + offsetStartMs).toISOString(), ended_at: new Date(REPLAY_START_MS + offsetEndMs).toISOString(), attributes_json: "{}", + audio_offset_ms: offsetStartMs, }; } describe("buildTree", () => { it("emits one row per turn in idx order", () => { - const { rows } = buildTree( - [turn(0, "user", 0, 2_500), turn(1, "agent", 3_000, 6_500)], - [], - REPLAY_START, - ); + const { rows } = buildTree([turn(0, "user", 0, 2_500), turn(1, "agent", 3_000, 6_500)], []); const turnRows = rows.filter((r) => r.kind === "turn"); expect(turnRows.map((r) => r.kind === "turn" && r.idx)).toEqual([0, 1]); }); @@ -57,7 +54,6 @@ describe("buildTree", () => { const { rows } = buildTree( [turn(0, "user", 0, 2_500)], [span(1, "stt.transcribe", 200, 1_400)], - REPLAY_START, ); const spanRows = rows.filter((r) => r.kind === "span"); expect(spanRows).toHaveLength(1); @@ -73,7 +69,6 @@ describe("buildTree", () => { span(2, "rag_retrieve", 300, 800, "s-1"), span(3, "openai_embed", 320, 700, "s-2"), ], - REPLAY_START, ); const depthByName = new Map( rows @@ -89,7 +84,6 @@ describe("buildTree", () => { const { rows } = buildTree( [turn(0, "user", 0, 2_500)], [span(1, "tool_call", 200, 1_400), span(2, "rag_retrieve", 300, 800, "s-1")], - REPLAY_START, ); const names = rows.map((r) => r.kind === "span" ? r.name : r.kind === "turn" ? `turn-${r.idx}` : r.id, @@ -98,11 +92,7 @@ describe("buildTree", () => { }); it("appends an untimed-group row at the end when spans miss every turn", () => { - const { rows } = buildTree( - [turn(0, "user", 0, 2_500)], - [span(1, "setup", -1_000, -500)], - REPLAY_START, - ); + const { rows } = buildTree([turn(0, "user", 0, 2_500)], [span(1, "setup", -1_000, -500)]); expect(rows[rows.length - 2]?.kind).toBe("untimed-group"); expect(rows[rows.length - 1]?.kind).toBe("span"); }); @@ -111,7 +101,6 @@ describe("buildTree", () => { const { scale } = buildTree( [turn(0, "user", 0, 2_500)], [span(1, "setup", -500, -100), span(2, "stt", 200, 1_400)], - REPLAY_START, ); expect(scale.startSec).toBeLessThanOrEqual(-0.5); expect(scale.endSec).toBeGreaterThanOrEqual(2.5); @@ -126,7 +115,7 @@ describe("buildTree", () => { const b = span(2, "b", 300, 500); const cyclicA: typeof a = { ...a, parent_span_id: "s-2" }; const cyclicB: typeof b = { ...b, parent_span_id: "s-1" }; - const { rows } = buildTree([turn(0, "user", 0, 2_500)], [cyclicA, cyclicB], REPLAY_START); + const { rows } = buildTree([turn(0, "user", 0, 2_500)], [cyclicA, cyclicB]); const spanRows = rows.filter((r) => r.kind === "span"); expect(spanRows.map((r) => r.kind === "span" && r.name).sort()).toEqual(["a", "b"]); for (const r of spanRows) { @@ -138,7 +127,6 @@ describe("buildTree", () => { const { rows } = buildTree( [turn(0, "user", 0, 2_500), turn(1, "agent", 3_000, 6_500)], [span(1, "stt", 100, 1_000)], - REPLAY_START, ); const turnRows = rows.filter((r) => r.kind === "turn"); expect(turnRows[0]?.kind === "turn" && turnRows[0].hasChildren).toBe(true); diff --git a/src/client/trace-tree/build-tree.ts b/src/client/trace-tree/build-tree.ts index 4254743..5841092 100644 --- a/src/client/trace-tree/build-tree.ts +++ b/src/client/trace-tree/build-tree.ts @@ -1,8 +1,20 @@ import type { ReplayTurnResponse, SpanResponse } from "@/client/api/api.types.ts"; -import { attributeSpansToTurns, toReplaySeconds } from "./attribution.ts"; +import { attributeSpansToTurns, spanStartSeconds } from "./attribution.ts"; import type { SpanRow, TraceScale, TreeRow, TurnRow, UntimedGroupRow } from "./trace-tree.types.ts"; +/** + * A span's start/end on the recording-t=0 axis (seconds). Start comes from the + * server-derived `audio_offset_ms` (0 when the span can't be placed — a replay + * with no anchor renders every span clustered at 0 rather than at a wrong + * wall-clock origin); end is start + the span's own duration. + */ +function spanSeconds(span: SpanResponse): { startSec: number; endSec: number } { + const startSec = spanStartSeconds(span) ?? 0; + const durMs = Math.max(0, Date.parse(span.ended_at) - Date.parse(span.started_at)); + return { startSec, endSec: startSec + durMs / 1_000 }; +} + export type TreeBuildResult = Readonly<{ rows: readonly TreeRow[]; scale: TraceScale; @@ -20,9 +32,8 @@ export type TreeBuildResult = Readonly<{ export function buildTree( turns: readonly ReplayTurnResponse[], spans: readonly SpanResponse[], - replayStartIso: string, ): TreeBuildResult { - const { perTurn, untimed } = attributeSpansToTurns(turns, spans, replayStartIso); + const { perTurn, untimed } = attributeSpansToTurns(turns, spans); const rows: TreeRow[] = []; let minSec = Number.POSITIVE_INFINITY; @@ -49,7 +60,7 @@ export function buildTree( hasChildren: clusterSpans.length > 0, }; rows.push(turnRow); - appendSpanTree(rows, clusterSpans, turnRow.id, 1, replayStartIso, observe); + appendSpanTree(rows, clusterSpans, turnRow.id, 1, observe); } if (untimed.length > 0) { @@ -62,12 +73,10 @@ export function buildTree( }; rows.push(untimedRow); for (const span of untimed) { - observe( - toReplaySeconds(span.started_at, replayStartIso), - toReplaySeconds(span.ended_at, replayStartIso), - ); + const { startSec, endSec } = spanSeconds(span); + observe(startSec, endSec); } - appendSpanTree(rows, untimed, untimedRow.id, 1, replayStartIso, observe); + appendSpanTree(rows, untimed, untimedRow.id, 1, observe); } const startSec = minSec === Number.POSITIVE_INFINITY ? 0 : Math.min(0, minSec); @@ -86,7 +95,6 @@ function appendSpanTree( pool: readonly SpanResponse[], rootParentRowId: string, rootDepth: number, - replayStartIso: string, observe: (start: number, end: number) => void, ): void { const bySpanId = new Map(); @@ -107,8 +115,7 @@ function appendSpanTree( const visited = new Set(); const emit = (span: SpanResponse, depth: number, parentRowId: string): SpanRow => { visited.add(span.span_id); - const startedAtSec = toReplaySeconds(span.started_at, replayStartIso); - const endedAtSec = toReplaySeconds(span.ended_at, replayStartIso); + const { startSec: startedAtSec, endSec: endedAtSec } = spanSeconds(span); observe(startedAtSec, endedAtSec); const children = childrenBySpanId.get(span.span_id) ?? []; const reachableChildren = children.filter((c) => !visited.has(c.span_id)); diff --git a/src/client/trace-tree/span-detail/span-detail-model.test.ts b/src/client/trace-tree/span-detail/span-detail-model.test.ts index ba0c719..61c35dc 100644 --- a/src/client/trace-tree/span-detail/span-detail-model.test.ts +++ b/src/client/trace-tree/span-detail/span-detail-model.test.ts @@ -1,15 +1,8 @@ import type { ModelUsageResponse, SpanResponse, ToolCallResponse } from "@/client/api/api.types.ts"; -import { - offsetSec, - parseSpanAttributes, - resolveSpanDetail, - spanDurationMs, -} from "./span-detail-model.ts"; +import { parseSpanAttributes, resolveSpanDetail, spanDurationMs } from "./span-detail-model.ts"; import { describe, expect, it } from "bun:test"; -const REPLAY_START = "2026-05-25T10:00:00.000Z"; - function span(overrides: Partial = {}): SpanResponse { return { id: 1, @@ -21,6 +14,7 @@ function span(overrides: Partial = {}): SpanResponse { started_at: "2026-05-25T10:00:00.000Z", ended_at: "2026-05-25T10:00:04.300Z", attributes_json: "{}", + audio_offset_ms: null, ...overrides, }; } @@ -28,13 +22,14 @@ function span(overrides: Partial = {}): SpanResponse { function usage(spanId: string | null): ModelUsageResponse { return { id: 1, - turn_idx: 0, + audio_offset_ms: null, span_id: spanId, provider: "Gemini", model: "gemini-3.1-flash-live-preview", input_tokens: 1222, output_tokens: 111, total_tokens: 1333, + ttft_ms: null, started_at: null, ended_at: null, latency_ms: 4302, @@ -44,7 +39,7 @@ function usage(spanId: string | null): ModelUsageResponse { function toolCall(spanId: string | null): ToolCallResponse { return { id: 1, - turn_idx: 0, + audio_offset_ms: null, span_id: spanId, name: "get_current_year", args_json: "{}", @@ -69,20 +64,6 @@ describe("spanDurationMs", () => { }); }); -describe("offsetSec", () => { - it("returns seconds elapsed since replay start", () => { - expect(offsetSec("2026-05-25T10:00:04.300Z", REPLAY_START)).toBe(4.3); - }); - - it("returns 0 for unparseable input", () => { - expect(offsetSec("nope", REPLAY_START)).toBe(0); - }); - - it("clamps a span that starts before replay start to 0", () => { - expect(offsetSec("2026-05-25T09:59:59.000Z", REPLAY_START)).toBe(0); - }); -}); - describe("parseSpanAttributes", () => { it("splits each key into namespace + leaf and sorts by key", () => { const result = parseSpanAttributes( @@ -131,9 +112,8 @@ describe("parseSpanAttributes", () => { describe("resolveSpanDetail", () => { const source = { - replayStartIso: REPLAY_START, spans: [ - span({ span_id: "parent", name: "agent_turn" }), + span({ span_id: "parent", name: "agent_turn", audio_offset_ms: 0 }), span({ id: 2, span_id: "child", @@ -141,6 +121,7 @@ describe("resolveSpanDetail", () => { name: "execute_tool", vocabulary: "gen_ai", attributes_json: '{"gen_ai.tool.name":"get_current_year"}', + audio_offset_ms: 0, }), ], modelUsage: [usage("parent"), usage("other")], @@ -164,6 +145,18 @@ describe("resolveSpanDetail", () => { expect(detail?.endOffsetSec).toBe(4.3); }); + it("leaves both offsets null when the span has no audio_offset_ms (no anchor)", () => { + const detail = resolveSpanDetail("unplaceable", { + spans: [span({ span_id: "unplaceable", audio_offset_ms: null })], + modelUsage: [], + toolCalls: [], + }); + expect(detail?.startOffsetSec).toBeNull(); + expect(detail?.endOffsetSec).toBeNull(); + // Duration is still computed from the span's own timestamps. + expect(detail?.durationMs).toBe(4300); + }); + it("links only the tool_calls that share the span_id and resolves the parent name", () => { const detail = resolveSpanDetail("child", source); expect(detail?.toolCalls).toHaveLength(1); diff --git a/src/client/trace-tree/span-detail/span-detail-model.ts b/src/client/trace-tree/span-detail/span-detail-model.ts index 21fac0a..54af316 100644 --- a/src/client/trace-tree/span-detail/span-detail-model.ts +++ b/src/client/trace-tree/span-detail/span-detail-model.ts @@ -14,16 +14,6 @@ export function spanDurationMs(startedAt: string, endedAt: string): number { return Number.isFinite(ms) && ms >= 0 ? ms : 0; } -/** - * Seconds from replay start to `iso`, the offset the waveform/playhead use. - * Clamped to 0: a span timestamped before the recording's t=0 has no place on - * a waveform that starts at 0, same as `spanDurationMs`. - */ -export function offsetSec(iso: string, replayStartIso: string): number { - const sec = (Date.parse(iso) - Date.parse(replayStartIso)) / 1_000; - return Number.isFinite(sec) && sec >= 0 ? sec : 0; -} - /** * Parse `spans.attributes_json` into sorted, namespace-split entries. The * stored value is always a flat JSON object in practice, but parse @@ -68,11 +58,13 @@ export function resolveSpanDetail( if (spanId === null) return null; const span = source.spans.find((s) => s.span_id === spanId); if (span === undefined) return null; + const durationMs = spanDurationMs(span.started_at, span.ended_at); + const startOffsetSec = span.audio_offset_ms === null ? null : span.audio_offset_ms / 1_000; return { span, - durationMs: spanDurationMs(span.started_at, span.ended_at), - startOffsetSec: offsetSec(span.started_at, source.replayStartIso), - endOffsetSec: offsetSec(span.ended_at, source.replayStartIso), + durationMs, + startOffsetSec, + endOffsetSec: startOffsetSec === null ? null : startOffsetSec + durationMs / 1_000, parentName: resolveParentName(span.parent_span_id, source.spans), attributes: parseSpanAttributes(span.attributes_json), usage: source.modelUsage.filter((u) => u.span_id === spanId), diff --git a/src/client/trace-tree/span-detail/span-detail.test.tsx b/src/client/trace-tree/span-detail/span-detail.test.tsx index 470b605..be27185 100644 --- a/src/client/trace-tree/span-detail/span-detail.test.tsx +++ b/src/client/trace-tree/span-detail/span-detail.test.tsx @@ -30,6 +30,7 @@ function span(overrides: Partial = {}): SpanResponse { started_at: REPLAY_START, ended_at: "2026-05-25T10:00:04.300Z", attributes_json: '{"gen_ai.operation.name":"chat","gen_ai.usage.input_tokens":1222}', + audio_offset_ms: 0, ...overrides, }; } @@ -66,13 +67,14 @@ function model(overrides: Partial = {}): SpanDetailModel { const USAGE: ModelUsageResponse = { id: 1, - turn_idx: 0, + audio_offset_ms: null, span_id: "span-1", provider: "Gemini", model: "gemini-3.1-flash-live-preview", input_tokens: 1222, output_tokens: 111, total_tokens: 1333, + ttft_ms: null, started_at: null, ended_at: null, latency_ms: 4302, @@ -80,7 +82,7 @@ const USAGE: ModelUsageResponse = { const TOOL_CALL: ToolCallResponse = { id: 1, - turn_idx: 0, + audio_offset_ms: null, span_id: "span-1", name: "get_current_year", args_json: "{}", @@ -170,6 +172,7 @@ function replay(overrides: Partial = {}): ReplayDetailResp failure_reason: null, started_at: REPLAY_START, finished_at: null, + recording_started_at: null, audio_path: null, job_id: null, run_config: null, diff --git a/src/client/trace-tree/span-detail/span-detail.tsx b/src/client/trace-tree/span-detail/span-detail.tsx index 775b0b0..f950577 100644 --- a/src/client/trace-tree/span-detail/span-detail.tsx +++ b/src/client/trace-tree/span-detail/span-detail.tsx @@ -29,7 +29,6 @@ export function SpanDetailAside({ replay }: { replay: ReplayDetailResponse }) { const { selectedSpanId, clear } = useSpanSelection(); if (replay.spans.length === 0) return null; const detail = resolveSpanDetail(selectedSpanId, { - replayStartIso: replay.started_at, spans: replay.spans, modelUsage: replay.model_usage, toolCalls: replay.tool_calls, @@ -144,7 +143,11 @@ function SpanTimingGrid({ detail }: { detail: SpanDetailModel }) {
@@ -194,9 +197,14 @@ function UsageRow({ usage: u }: { usage: ModelUsageResponse }) { {u.model ?? "—"} {u.provider !== null && /{u.provider}} - {u.latency_ms !== null && ( - {u.latency_ms}ms - )} + + {u.ttft_ms !== null && ( + + ttft {u.ttft_ms}ms + + )} + {u.latency_ms !== null && {u.latency_ms}ms} +
diff --git a/src/client/trace-tree/span-detail/span-detail.types.ts b/src/client/trace-tree/span-detail/span-detail.types.ts index 04ca3cc..5697489 100644 --- a/src/client/trace-tree/span-detail/span-detail.types.ts +++ b/src/client/trace-tree/span-detail/span-detail.types.ts @@ -33,21 +33,19 @@ export type SpanAttributes = export type SpanDetailModel = Readonly<{ span: SpanResponse; durationMs: number; - startOffsetSec: number; - endOffsetSec: number; + // Offsets on the audio timeline (seconds from recording t=0), from the span's + // server-derived `audio_offset_ms`. Null when the replay has no anchor and the + // span can't be placed — the panel renders "—" rather than a misleading 0:00. + startOffsetSec: number | null; + endOffsetSec: number | null; parentName: string | null; attributes: SpanAttributes; usage: readonly ModelUsageResponse[]; toolCalls: readonly ToolCallResponse[]; }>; -/** - * The slices of a `ReplayDetailResponse` needed to resolve a span detail. - * `replayStartIso` lets the panel show start/end as a clock offset from - * replay start — the same reading the waveform and the trace playhead use. - */ +/** The slices of a `ReplayDetailResponse` needed to resolve a span detail. */ export type SpanDetailSource = Readonly<{ - replayStartIso: string; spans: readonly SpanResponse[]; modelUsage: readonly ModelUsageResponse[]; toolCalls: readonly ToolCallResponse[]; diff --git a/src/client/trace-tree/trace-tree.test.tsx b/src/client/trace-tree/trace-tree.test.tsx index a26ae8c..fb4caa3 100644 --- a/src/client/trace-tree/trace-tree.test.tsx +++ b/src/client/trace-tree/trace-tree.test.tsx @@ -54,6 +54,7 @@ function span( started_at: new Date(REPLAY_START_MS + offsetStartMs).toISOString(), ended_at: new Date(REPLAY_START_MS + offsetEndMs).toISOString(), attributes_json: "{}", + audio_offset_ms: offsetStartMs, }; } @@ -61,7 +62,7 @@ describe("TraceTree", () => { it("renders the empty state when there are no spans", () => { render( - + , ); expect(screen.getByText(/No spans recorded/i)).toBeTruthy(); @@ -73,7 +74,6 @@ describe("TraceTree", () => { , @@ -89,7 +89,6 @@ describe("TraceTree", () => { , @@ -118,7 +117,6 @@ describe("TraceTree", () => { , @@ -136,7 +134,6 @@ describe("TraceTree", () => { , @@ -157,7 +154,6 @@ describe("TraceTree", () => { , @@ -171,7 +167,6 @@ describe("TraceTree", () => { , @@ -194,7 +189,6 @@ describe("TraceTree selection", () => { @@ -263,7 +257,7 @@ describe("TracePlayhead", () => { render( - + , ); return (state: PlayheadState) => act(() => publish(state)); @@ -272,7 +266,7 @@ describe("TracePlayhead", () => { it("renders no cursor when the player is not ready (no audio)", () => { render( - + , ); expect(screen.queryByTestId("trace-playhead")).toBeNull(); diff --git a/src/client/trace-tree/trace-tree.tsx b/src/client/trace-tree/trace-tree.tsx index 1c6ca05..6e8d904 100644 --- a/src/client/trace-tree/trace-tree.tsx +++ b/src/client/trace-tree/trace-tree.tsx @@ -24,7 +24,6 @@ const ZOOM_STEP = 1.5; interface TraceTreeProps { turns: readonly ReplayTurnResponse[]; spans: readonly SpanResponse[]; - replayStartIso: string; zoom: number; } @@ -32,12 +31,12 @@ type RenderState = | { kind: "empty" } | { kind: "ready"; rows: readonly TreeRow[]; scale: TraceScale }; -export function TraceTree({ turns, spans, replayStartIso, zoom }: TraceTreeProps) { +export function TraceTree({ turns, spans, zoom }: TraceTreeProps) { const state = useMemo(() => { - const { rows, scale } = buildTree(turns, spans, replayStartIso); + const { rows, scale } = buildTree(turns, spans); if (rows.length === 0) return { kind: "empty" }; return { kind: "ready", rows, scale }; - }, [turns, spans, replayStartIso]); + }, [turns, spans]); return match(state) .with({ kind: "empty" }, () => ) diff --git a/src/server/assertions/assertions.evaluator.test.ts b/src/server/assertions/assertions.evaluator.test.ts index e0b4959..99a1348 100644 --- a/src/server/assertions/assertions.evaluator.test.ts +++ b/src/server/assertions/assertions.evaluator.test.ts @@ -238,6 +238,40 @@ describe("evaluateAssertion — max_ttft_ms", () => { }); }); +describe("evaluateAssertion — no recording anchor", () => { + // Without recording_started_at the server can't map span timestamps onto + // the audio timeline, so span-attributed assertions can't be evaluated — + // they must `error`, never silently pass/fail. Text/latency assertions are + // unaffected (they don't depend on the timeline). + it("errors tool_called / tool_not_called / tool_args_match / max_ttft_ms", () => { + const ctx = makeAssertionContext({ + hasRecordingAnchor: false, + toolCalls: [makeToolCallRow({ name: "lookup" })], + ttftMs: 100, + }); + for (const assertion of [ + { kind: "tool_called", name: "lookup" }, + { kind: "tool_not_called", name: "lookup" }, + { kind: "tool_args_match", name: "lookup", args: {} }, + { kind: "max_ttft_ms", max_ms: 500 }, + ] as const) { + expect(evaluateAssertion(assertion, ctx).status).toBe("errored"); + } + }); + + it("does NOT error text or latency assertions (timeline-independent)", () => { + const ctx = makeAssertionContext({ + hasRecordingAnchor: false, + transcript: "hello world", + agentResponseMs: 1200, + }); + expect( + evaluateAssertion({ kind: "contains", text: "hello", case_insensitive: true }, ctx).status, + ).toBe("passed"); + expect(evaluateAssertion({ kind: "max_latency_ms", max_ms: 2000 }, ctx).status).toBe("passed"); + }); +}); + describe("deepPartialMatch", () => { it("matches nested objects partially", () => { expect(deepPartialMatch({ a: 1, b: { c: 2 } }, { a: 1, b: { c: 2, d: 3 }, e: 99 })).toBe(true); diff --git a/src/server/assertions/assertions.evaluator.ts b/src/server/assertions/assertions.evaluator.ts index 7c25305..aafae7b 100644 --- a/src/server/assertions/assertions.evaluator.ts +++ b/src/server/assertions/assertions.evaluator.ts @@ -3,6 +3,23 @@ import { match } from "ts-pattern"; import type { Assertion, AssertionContext, AssertionOutcome } from "./assertions.types.ts"; const NO_TRANSCRIPT_MESSAGE = "no transcript available for this turn"; +const NO_ANCHOR_MESSAGE = + "no recording anchor — cannot attribute spans to turns (upload omitted X-Recording-Started-At)"; + +/** + * Assertion kinds whose verdict depends on span→turn attribution, which needs + * the recording anchor. Classified once here rather than guarded ad hoc in each + * arm: without the anchor these all map to `errored` (not a misleading + * pass/fail), and a new timeline-dependent kind inherits that behaviour by + * being added to this set — the omission is visible in one place instead of + * hiding behind a forgotten per-arm guard. + */ +const TIMELINE_DEPENDENT_KINDS: ReadonlySet = new Set([ + "tool_called", + "tool_not_called", + "tool_args_match", + "max_ttft_ms", +]); const passed: AssertionOutcome = { status: "passed", message: null }; function failed(message: string): AssertionOutcome { @@ -25,6 +42,9 @@ function errored(message: string): AssertionOutcome { * misleading "no match" verdict that's actually a transcription failure. */ export function evaluateAssertion(assertion: Assertion, ctx: AssertionContext): AssertionOutcome { + if (!ctx.hasRecordingAnchor && TIMELINE_DEPENDENT_KINDS.has(assertion.kind)) { + return errored(NO_ANCHOR_MESSAGE); + } return match(assertion) .with({ kind: "contains" }, (a) => { if (ctx.transcript === null) return errored(NO_TRANSCRIPT_MESSAGE); @@ -102,7 +122,15 @@ export function evaluateAssertion(assertion: Assertion, ctx: AssertionContext): }) .with({ kind: "max_ttft_ms" }, (a) => { if (ctx.metrics.ttftMs === null) { - return errored("no ttft_ms metric — no gen_ai.client.* span attributed to this turn"); + // Distinguish the two failure modes so the dev knows whether the + // problem is "no LLM call landed in this turn" (mistiming / + // attribution) vs "the calls that did land don't emit TTFT" + // (instrumentation gap) — they need different fixes. + return errored( + ctx.modelUsage.length === 0 + ? "no ttft_ms — no model call landed in this turn's window" + : "no ttft_ms — no in-window model call carried gen_ai.response.time_to_first_chunk", + ); } return ctx.metrics.ttftMs <= a.max_ms ? passed diff --git a/src/server/assertions/assertions.test-utils.ts b/src/server/assertions/assertions.test-utils.ts index 95214bb..146325b 100644 --- a/src/server/assertions/assertions.test-utils.ts +++ b/src/server/assertions/assertions.test-utils.ts @@ -6,6 +6,7 @@ export interface MakeAssertionContextOverrides { turnIdx?: number; turnRole?: "user" | "agent"; transcript?: string | null; + hasRecordingAnchor?: boolean; toolCalls?: readonly ToolCallRow[]; modelUsage?: readonly ModelUsageRow[]; agentResponseMs?: number | null; @@ -19,6 +20,10 @@ export function makeAssertionContext( turnIdx: overrides.turnIdx ?? 0, turnRole: overrides.turnRole ?? "agent", transcript: overrides.transcript === undefined ? "" : overrides.transcript, + // Default true: most assertion tests aren't exercising the no-anchor + // path, and a false default would silently flip every tool test to + // `errored`. + hasRecordingAnchor: overrides.hasRecordingAnchor ?? true, toolCalls: overrides.toolCalls ?? [], modelUsage: overrides.modelUsage ?? [], metrics: { @@ -37,7 +42,6 @@ export function makeToolCallRow(overrides: Partial = {}): ToolCallR return { id: overrides.id ?? toolCallId, replayId: overrides.replayId ?? "00000000-0000-0000-0000-000000000001", - turnIdx: overrides.turnIdx ?? 0, spanId: overrides.spanId ?? `span-${toolCallId}`, name: overrides.name ?? "lookup", argsJson: overrides.argsJson ?? null, diff --git a/src/server/assertions/assertions.types.ts b/src/server/assertions/assertions.types.ts index 0f42474..6acd5a8 100644 --- a/src/server/assertions/assertions.types.ts +++ b/src/server/assertions/assertions.types.ts @@ -98,13 +98,24 @@ export const AssertionsArraySchema = v.pipe( * — every text-based assertion variant maps that to `status: "errored"` * with a stable message, rather than asserting against an empty string. * - * `toolCalls` / `modelUsage` arrive pre-filtered to this turn by the - * caller — the evaluator does not re-filter by `turn_idx`. + * `toolCalls` / `modelUsage` arrive pre-filtered to this turn by the caller + * — membership is the audio-timeline window `[turnStartMs, turnEndMs)` + * computed in the evaluate-replay stage (see `src/server/replays/timeline.ts`), + * not a stored `turn_idx`. + * + * `hasRecordingAnchor` is false when the replay has no `recording_started_at` + * (older SDK). Without it, span `started_at` can't be mapped onto the audio + * timeline, so tool-presence and ttft assertions can't be attributed to a + * turn — they map to `errored`, never a misleading pass/fail. + * + * `metrics.ttftMs` is the earliest in-window model call's + * `model_usage.ttft_ms` (or null), NOT a per-turn aggregate. */ export interface AssertionContext { readonly turnIdx: number; readonly turnRole: TurnRole; readonly transcript: string | null; + readonly hasRecordingAnchor: boolean; readonly toolCalls: readonly ToolCallRow[]; readonly modelUsage: readonly ModelUsageRow[]; readonly metrics: { diff --git a/src/server/audio/audio.errors.test.ts b/src/server/audio/audio.errors.test.ts index 7abec9e..45e33c7 100644 --- a/src/server/audio/audio.errors.test.ts +++ b/src/server/audio/audio.errors.test.ts @@ -7,6 +7,7 @@ import { AudioTurnsInvariantError, InvalidAudioExtensionError, InvalidAudioPathError, + InvalidRecordingStartedAtError, UnsupportedAudioContentTypeError, } from "./audio.errors.ts"; import { describe, expect, it } from "bun:test"; @@ -29,6 +30,23 @@ describe("audio errors", () => { expect(e.issues).toBe(issues); }); + it("InvalidRecordingStartedAtError is an AudioError with issues", () => { + const issues = [ + { + kind: "schema", + type: "iso_timestamp", + input: "nope", + expected: "ISO timestamp", + received: "nope", + message: "m", + }, + ] as const; + const e = new InvalidRecordingStartedAtError(issues); + expect(e).toBeInstanceOf(AudioError); + expect(e.name).toBe("InvalidRecordingStartedAtError"); + expect(e.issues).toBe(issues); + }); + it("UnsupportedAudioContentTypeError keeps the offending content type", () => { const e = new UnsupportedAudioContentTypeError("application/json"); expect(e.name).toBe("UnsupportedAudioContentTypeError"); diff --git a/src/server/audio/audio.errors.ts b/src/server/audio/audio.errors.ts index f65174d..515a3c7 100644 --- a/src/server/audio/audio.errors.ts +++ b/src/server/audio/audio.errors.ts @@ -19,6 +19,17 @@ export class InvalidAudioPathError extends AudioError { } } +/** `X-Recording-Started-At` header was present but not a valid ISO timestamp. */ +export class InvalidRecordingStartedAtError extends AudioError { + readonly issues: readonly BaseIssue[]; + + constructor(issues: readonly BaseIssue[]) { + super("Invalid X-Recording-Started-At header"); + this.name = "InvalidRecordingStartedAtError"; + this.issues = issues; + } +} + export class UnsupportedAudioContentTypeError extends AudioError { readonly contentType: string | null; diff --git a/src/server/audio/audio.router.test.ts b/src/server/audio/audio.router.test.ts index 08cb6a9..f8e85f6 100644 --- a/src/server/audio/audio.router.test.ts +++ b/src/server/audio/audio.router.test.ts @@ -1,8 +1,10 @@ +import { eq } from "drizzle-orm"; import * as v from "valibot"; import { makeFakeJobRunner } from "@/server/jobs/jobs.test-utils.ts"; import { makeReplayEvents } from "@/server/replays/replays.events.ts"; import { createApp } from "@/server/server.ts"; +import { replays } from "@/server/store/schema.ts"; import type { Store } from "@/server/store/store.ts"; import { makeTempStore } from "@/server/store/test-utils.ts"; import { makeFakeTtsProvider } from "@/server/tts/tts.test-utils.ts"; @@ -71,6 +73,56 @@ describe("POST /v1/replays/:id/audio — happy path", () => { }); }); +describe("POST /v1/replays/:id/audio — X-Recording-Started-At header", () => { + async function replayRowAfterUpload(headers: Record) { + const { replayId } = await seedReplayForAudio(store); + const res = await app.request(replayAudioUrl(replayId), { + method: "POST", + headers: { "Content-Type": "audio/wav", ...headers }, + body: fakeAudioBytes(), + }); + const row = store.db.select().from(replays).where(eq(replays.id, replayId)).get(); + return { res, row }; + } + + it("persists the anchor on the replay row", async () => { + const anchor = "2026-05-26T14:31:31.023Z"; + const { res, row } = await replayRowAfterUpload({ "X-Recording-Started-At": anchor }); + expect(res.status).toBe(200); + expect(row?.recordingStartedAt).toBe(anchor); + }); + + it("stores null when the header is absent (older SDK)", async () => { + const { res, row } = await replayRowAfterUpload({}); + expect(res.status).toBe(200); + expect(row?.recordingStartedAt).toBeNull(); + }); + + it("rejects a malformed anchor with 400 — never silently drops a provided value", async () => { + const { res, row } = await replayRowAfterUpload({ "X-Recording-Started-At": "yesterday-ish" }); + expect(res.status).toBe(400); + const body = v.parse( + v.object({ error: v.literal("invalid_recording_started_at") }), + await res.json(), + ); + expect(body.error).toBe("invalid_recording_started_at"); + expect(row?.recordingStartedAt).toBeNull(); + }); + + // These pass valibot's ISO regex but Date.parse() returns NaN for them, so + // storing them would make every downstream offset null while the row looks + // anchored — tool/ttft assertions would then report misleading fail/pass + // instead of `errored`. Reject at the boundary instead. + it.each([ + "2026-05-26T14:31:31+02", + "2026-05-26T14:31:31 +02:00", + ])("rejects an ISO-shaped but unparseable anchor (%s) with 400", async (anchor) => { + const { res, row } = await replayRowAfterUpload({ "X-Recording-Started-At": anchor }); + expect(res.status).toBe(400); + expect(row?.recordingStartedAt).toBeNull(); + }); +}); + describe("POST /v1/replays/:id/audio — rejections", () => { it("rejects an unsupported content type with 415", async () => { const { replayId } = await seedReplayForAudio(store); @@ -130,8 +182,6 @@ describe("POST /v1/replays/:id/audio — rejections", () => { describe("POST /v1/replays/:id/audio — lifecycle 409", () => { it("returns 409 when the replay is `analyzing`", async () => { const { replayId } = await seedReplayForAudio(store); - const { replays } = await import("@/server/store/schema.ts"); - const { eq } = await import("drizzle-orm"); store.db .update(replays) .set({ lifecycleState: "analyzing", analysisStep: "vad", jobId: "j-1" }) @@ -147,8 +197,6 @@ describe("POST /v1/replays/:id/audio — lifecycle 409", () => { it("returns 409 when the replay is `completed`", async () => { const { replayId } = await seedReplayForAudio(store); - const { replays } = await import("@/server/store/schema.ts"); - const { eq } = await import("drizzle-orm"); store.db .update(replays) .set({ lifecycleState: "completed" }) diff --git a/src/server/audio/audio.router.ts b/src/server/audio/audio.router.ts index 462df9f..981f893 100644 --- a/src/server/audio/audio.router.ts +++ b/src/server/audio/audio.router.ts @@ -23,6 +23,7 @@ import { AudioReplayNotFoundError, InvalidAudioExtensionError, InvalidAudioPathError, + InvalidRecordingStartedAtError, ReplayUploadStateError, UnsupportedAudioContentTypeError, } from "./audio.errors.ts"; @@ -33,6 +34,7 @@ import { CONTENT_TYPE_TO_EXTENSION, EXTENSION_TO_RESPONSE_CONTENT_TYPE, MAX_AUDIO_BYTES, + RecordingStartedAtSchema, UploadAudioResponseSchema, } from "./audio.types.ts"; @@ -61,6 +63,14 @@ export function createAudioRouter(store: Store, audioRoot: string): Hono { required: true, schema: openApiSchemaFromValibot(ReplayIdSchema), }, + { + in: "header", + name: "X-Recording-Started-At", + required: false, + description: + "Wall-clock (UTC ISO-8601) of audio sample 0 — the driver's earliest turn `started_at`. The sole origin for mapping span timestamps onto the audio timeline. Omit only from older SDKs; span→turn attribution is skipped when absent.", + schema: openApiSchemaFromValibot(RecordingStartedAtSchema), + }, ], requestBody: { required: true, content: UPLOAD_CONTENT_MAP }, responses: { @@ -71,7 +81,8 @@ export function createAudioRouter(store: Store, audioRoot: string): Hono { }, }, "400": { - description: "Path failed validation.", + description: + "Replay id failed validation (`invalid_audio_path`), or the X-Recording-Started-At header was present but not a parseable ISO-8601 timestamp (`invalid_recording_started_at`).", content: { "application/json": { schema: openApiSchemaFromValibot(ValidationErrorResponseSchema) }, }, @@ -114,12 +125,14 @@ export function createAudioRouter(store: Store, audioRoot: string): Hono { async (c) => { const replayId = parseReplayIdParam(c.req.param("id")); const contentType = parseAudioContentType(c.req.header("content-type")); + const recordingStartedAt = parseRecordingStartedAt(c.req.header("x-recording-started-at")); const buffer = await c.req.arrayBuffer(); const bytes = new Uint8Array(buffer); const audioPath = await uploadReplayAudio(store, audioRoot, { replayId, contentType, bytes, + recordingStartedAt, }); return c.json({ ok: true, audio_path: audioPath }); }, @@ -177,6 +190,9 @@ export function createAudioRouter(store: Store, audioRoot: string): Hono { .with(P.instanceOf(InvalidAudioPathError), (e) => c.json({ error: "invalid_audio_path", issues: sanitizeIssues(e.issues) }, 400), ) + .with(P.instanceOf(InvalidRecordingStartedAtError), (e) => + c.json({ error: "invalid_recording_started_at", issues: sanitizeIssues(e.issues) }, 400), + ) .with(P.instanceOf(UnsupportedAudioContentTypeError), (e) => c.json({ error: "unsupported_content_type", content_type: e.contentType }, 415), ) @@ -231,3 +247,13 @@ function parseAudioContentType(header: string | undefined): AudioContentType { if (!result.success) throw new UnsupportedAudioContentTypeError(stripped); return result.output; } + +// Optional: absent header ⇒ null (older SDK; offsets undefined, attribution +// skipped). Present-but-malformed ⇒ 400 — a provided anchor we can't parse is +// a client bug we surface loudly, never silently drop. +function parseRecordingStartedAt(header: string | undefined): string | null { + if (header === undefined) return null; + const result = v.safeParse(RecordingStartedAtSchema, header.trim()); + if (!result.success) throw new InvalidRecordingStartedAtError(result.issues); + return result.output; +} diff --git a/src/server/audio/audio.service.test.ts b/src/server/audio/audio.service.test.ts index 60a327e..eda8f72 100644 --- a/src/server/audio/audio.service.test.ts +++ b/src/server/audio/audio.service.test.ts @@ -36,6 +36,7 @@ describe("uploadReplayAudio / readReplayAudio", () => { const rel = await uploadReplayAudio(store, audio.path, { replayId, contentType: "audio/wav", + recordingStartedAt: null, bytes, }); expect(rel).toBe(join(replayId, "replay.wav")); @@ -49,12 +50,14 @@ describe("uploadReplayAudio / readReplayAudio", () => { await uploadReplayAudio(store, audio.path, { replayId, contentType: "audio/wav", + recordingStartedAt: null, bytes: fakeAudioBytes(1), }); const second = fakeAudioBytes(2); await uploadReplayAudio(store, audio.path, { replayId, contentType: "audio/wav", + recordingStartedAt: null, bytes: second, }); const result = await readReplayAudio(store, audio.path, replayId); @@ -80,6 +83,7 @@ describe("uploadReplayAudio / readReplayAudio", () => { uploadReplayAudio(store, audio.path, { replayId: "00000000-0000-0000-0000-000000000099", contentType: "audio/wav", + recordingStartedAt: null, bytes: fakeAudioBytes(), }), ).rejects.toBeInstanceOf(AudioReplayNotFoundError); @@ -98,6 +102,7 @@ describe("uploadReplayAudio — lifecycle guard", () => { uploadReplayAudio(store, audio.path, { replayId, contentType: "audio/wav", + recordingStartedAt: null, bytes: fakeAudioBytes(), }), ).resolves.toBeString(); @@ -108,6 +113,7 @@ describe("uploadReplayAudio — lifecycle guard", () => { await uploadReplayAudio(store, audio.path, { replayId, contentType: "audio/wav", + recordingStartedAt: null, bytes: fakeAudioBytes(1), }); // Now in recording_uploaded — re-upload should still work (e.g. @@ -116,6 +122,7 @@ describe("uploadReplayAudio — lifecycle guard", () => { uploadReplayAudio(store, audio.path, { replayId, contentType: "audio/wav", + recordingStartedAt: null, bytes: fakeAudioBytes(2), }), ).resolves.toBeString(); @@ -132,6 +139,7 @@ describe("uploadReplayAudio — lifecycle guard", () => { uploadReplayAudio(store, audio.path, { replayId, contentType: "audio/wav", + recordingStartedAt: null, bytes: fakeAudioBytes(), }), ); @@ -152,6 +160,7 @@ describe("uploadReplayAudio — lifecycle guard", () => { uploadReplayAudio(store, audio.path, { replayId, contentType: "audio/wav", + recordingStartedAt: null, bytes: fakeAudioBytes(), }), ).rejects.toBeInstanceOf(ReplayUploadStateError); @@ -168,6 +177,7 @@ describe("uploadReplayAudio — lifecycle guard", () => { uploadReplayAudio(store, audio.path, { replayId, contentType: "audio/wav", + recordingStartedAt: null, bytes: fakeAudioBytes(), }), ).rejects.toBeInstanceOf(ReplayUploadStateError); diff --git a/src/server/audio/audio.service.ts b/src/server/audio/audio.service.ts index b3439fc..4f1de64 100644 --- a/src/server/audio/audio.service.ts +++ b/src/server/audio/audio.service.ts @@ -119,9 +119,19 @@ export async function readConversationTurnAudio( export async function uploadReplayAudio( store: Store, audioRoot: string, - params: { replayId: string; contentType: AudioContentType; bytes: Uint8Array }, + params: { + replayId: string; + contentType: AudioContentType; + bytes: Uint8Array; + /** Wall-clock of audio sample 0 (driver's `min(segment.started_at)`), + * from the `X-Recording-Started-At` header. `null` when the SDK doesn't + * send it — span→audio attribution is then skipped (spec 0001). Required + * (not optional) so a caller can never silently persist a null anchor by + * forgetting the field; passing `null` is an explicit choice. */ + recordingStartedAt: string | null; + }, ): Promise { - const { replayId, contentType, bytes } = params; + const { replayId, contentType, bytes, recordingStartedAt } = params; const existing = findReplay(store, replayId); if (existing === undefined) { throw new AudioReplayNotFoundError(replayId); @@ -140,7 +150,7 @@ export async function uploadReplayAudio( store.db .update(replays) - .set({ audioPath: relativePath, lifecycleState: "recording_uploaded" }) + .set({ audioPath: relativePath, lifecycleState: "recording_uploaded", recordingStartedAt }) .where(eq(replays.id, replayId)) .run(); diff --git a/src/server/audio/audio.types.ts b/src/server/audio/audio.types.ts index 9b49fc2..c5f3199 100644 --- a/src/server/audio/audio.types.ts +++ b/src/server/audio/audio.types.ts @@ -48,6 +48,23 @@ export const UploadAudioResponseSchema = v.object({ }); export type UploadAudioResponse = v.InferOutput; +// Wall-clock (UTC ISO-8601) of audio sample 0, sent as the +// `X-Recording-Started-At` request header on POST /audio. Optional — older +// SDKs omit it, in which case span→audio offsets are undefined and attribution +// is skipped (see spec 0001). When present it must be a valid ISO timestamp. +// +// The extra Date.parse gate is load-bearing: valibot's `isoTimestamp()` accepts +// forms `Date.parse` returns NaN for (e.g. an hour-only offset `…+02`, a space +// before the offset). Storing one of those would leave the replay looking +// anchored while every derived `audio_offset_ms` is null — tool/ttft assertions +// would then report a misleading pass/fail instead of `errored`. Since every +// consumer maps the anchor via `Date.parse`, reject anything it can't parse. +export const RecordingStartedAtSchema = v.pipe( + v.string(), + v.isoTimestamp(), + v.check((s) => Number.isFinite(Date.parse(s)), "must be a Date.parse-able ISO-8601 timestamp"), +); + export interface AudioStream { readonly stream: ReadableStream; readonly contentLength: number; diff --git a/src/server/jobs/analyze-replay/analyze-replay.processor.test.ts b/src/server/jobs/analyze-replay/analyze-replay.processor.test.ts index 15fd902..91a7939 100644 --- a/src/server/jobs/analyze-replay/analyze-replay.processor.test.ts +++ b/src/server/jobs/analyze-replay/analyze-replay.processor.test.ts @@ -8,14 +8,7 @@ import type { StereoWav } from "@/server/audio/audio.types.ts"; import { writeStereoWav } from "@/server/audio/audio.wav.ts"; import { makeFakeJobRunner } from "@/server/jobs/jobs.test-utils.ts"; import { makeReplayEvents } from "@/server/replays/replays.events.ts"; -import { - modelUsage, - replays, - replayTurns, - speechSegments, - toolCalls, - turnTranscripts, -} from "@/server/store/schema.ts"; +import { replays, replayTurns, speechSegments, turnTranscripts } from "@/server/store/schema.ts"; import type { Store } from "@/server/store/store.ts"; import { makeTempStore } from "@/server/store/test-utils.ts"; import { makeFakeTranscriptionProvider } from "@/server/transcription/transcription.test-utils.ts"; @@ -152,58 +145,6 @@ describe("analyze-replay processor", () => { expect(runner.enqueued).toEqual([{ name: "calculate-metrics", payload: { replayId } }]); }); - it("backfills tool_calls.turn_idx by timestamp window inside the VAD transaction", async () => { - const { replayId } = await seedReplayForAudio(store); - const wav = makeStereo({ - userBlocks: [ - { durationMs: 100, voiced: false }, - { durationMs: 300, voiced: true }, - { durationMs: 100, voiced: false }, - ], - agentBlocks: [ - { durationMs: 500, voiced: false }, - { durationMs: 300, voiced: true }, - ], - }); - const wavBytes = writeStereoWav(wav); - const relPath = `${replayId}/replay.wav`; - const absPath = join(audio.path, relPath); - await mkdir(dirname(absPath), { recursive: true }); - await writeFile(absPath, wavBytes); - store.db - .update(replays) - .set({ audioPath: relPath, lifecycleState: "analyzing", analysisStep: "vad" }) - .where(eq(replays.id, replayId)) - .run(); - - const replayRow = store.db.select().from(replays).where(eq(replays.id, replayId)).get(); - if (replayRow === undefined) throw new Error("replay row vanished"); - // Tool call recorded mid-agent-turn (agent voice starts at ~500ms). - // 600ms after the replay's start should land in the agent turn. - const replayStartMs = Date.parse(replayRow.startedAt); - store.db - .insert(toolCalls) - .values({ - replayId, - turnIdx: null, - spanId: "s1", - name: "lookup", - argsJson: null, - resultJson: null, - startedAt: new Date(replayStartMs + 600).toISOString(), - endedAt: new Date(replayStartMs + 700).toISOString(), - latencyMs: 100, - }) - .run(); - - const { processor } = makeProcessor(); - await processor({ replayId }); - - const tcRows = store.db.select().from(toolCalls).where(eq(toolCalls.replayId, replayId)).all(); - expect(tcRows.length).toBe(1); - expect(tcRows[0]?.turnIdx).not.toBeNull(); - }); - it("stamps failed + failure_reason='transcription_failed' when the provider errors", async () => { const { replayId } = await seedReplayForAudio(store); const wav = makeStereo({ @@ -284,7 +225,3 @@ describe("analyze-replay processor", () => { ); }); }); - -// Silence the unused-import lint on modelUsage — kept for parity with the -// implementation under test (turn_idx is backfilled on both tables). -void modelUsage; diff --git a/src/server/jobs/analyze-replay/analyze-replay.processor.ts b/src/server/jobs/analyze-replay/analyze-replay.processor.ts index a238f60..a804791 100644 --- a/src/server/jobs/analyze-replay/analyze-replay.processor.ts +++ b/src/server/jobs/analyze-replay/analyze-replay.processor.ts @@ -1,7 +1,7 @@ import { readFile } from "node:fs/promises"; import { join } from "node:path"; -import { and, eq, isNull } from "drizzle-orm"; +import { eq } from "drizzle-orm"; import { sliceTurnAudio } from "@/server/audio/audio.slice.ts"; import { deriveTurns } from "@/server/audio/audio.turns.ts"; @@ -10,14 +10,7 @@ import { runVadOnChannel } from "@/server/audio/audio.vad.ts"; import { readStereoWav, resamplePcm } from "@/server/audio/audio.wav.ts"; import type { ReplayEvents } from "@/server/replays/replays.events.ts"; import { findReplay, markReplayFailed } from "@/server/replays/replays.service.ts"; -import { - modelUsage, - replays, - replayTurns, - speechSegments, - toolCalls, - turnTranscripts, -} from "@/server/store/schema.ts"; +import { replays, replayTurns, speechSegments, turnTranscripts } from "@/server/store/schema.ts"; import type { Store } from "@/server/store/store.ts"; import { MissingProviderCredentialError } from "@/server/transcription/transcription.errors.ts"; import type { TranscriptionProvider } from "@/server/transcription/transcription.types.ts"; @@ -43,11 +36,10 @@ const VAD_SAMPLE_RATE = 16_000; * all in two commits inside the same processor invocation so a partial * transcription failure leaves the VAD output intact for debugging. * - * Backfills `tool_calls.turn_idx` and `model_usage.turn_idx` from the - * derived turn boundaries inside the VAD transaction. The OTLP receiver - * writes those rows with `turn_idx=null`; turn attribution is server- - * authoritative based on `replay_turns.voice_start_ms..voice_end_ms`, - * not on driver-emitted span baggage. + * Tool/model spans carry no stored turn idx — they're attributed to turns + * at read/eval time by mapping their wall-clock `started_at` onto the audio + * timeline (see `src/server/replays/timeline.ts`), so this stage no longer + * touches `tool_calls` / `model_usage`. * * On success: enqueues `calculate-metrics` for the same replay id and * leaves the row in `analyzing` (analysis_step transitions vad → @@ -136,8 +128,6 @@ export function makeAnalyzeProcessor( .run(); } - backfillTurnIdx(tx, replayId, replay.startedAt, turns); - tx.update(replays).set({ analysisStep: "transcribe" }).where(eq(replays.id, replayId)).run(); return true; @@ -276,76 +266,3 @@ async function runTranscriptionStage( return rows.length; } - -type TxHandle = Parameters[0]>[0]; - -interface TurnWindow { - readonly idx: number; - readonly voiceStartMs: number; - readonly voiceEndMs: number; -} - -/** - * Set `turn_idx` on `tool_calls` / `model_usage` rows whose `started_at` - * falls inside one of the derived turns' voice window. The OTLP receiver - * writes these rows before VAD has a chance to compute turn boundaries — - * this UPDATE is the single point of attribution. - * - * `started_at` is the wall-clock ISO timestamp the span carried; - * `replays.started_at` is the wall-clock at the start of the run. - * Convert both to ms-since-epoch and subtract to get an offset in the - * same coordinate space as `voice_start_ms / voice_end_ms` (ms since the - * recording's t=0). Rows with no `started_at` stay null — there's - * nothing to attribute them to. - * - * Done in JS rather than SQL because SQLite's ISO-8601 parsing is - * sub-millisecond-lossy and the join logic is small enough to stay - * legible inline. - */ -function backfillTurnIdx( - tx: TxHandle, - replayId: string, - replayStartedAtIso: string, - turns: readonly TurnWindow[], -): void { - if (turns.length === 0) return; - const replayStartMs = Date.parse(replayStartedAtIso); - if (!Number.isFinite(replayStartMs)) return; - - const toolRows = tx - .select({ id: toolCalls.id, startedAt: toolCalls.startedAt }) - .from(toolCalls) - .where(and(eq(toolCalls.replayId, replayId), isNull(toolCalls.turnIdx))) - .all(); - for (const row of toolRows) { - const idx = turnIdxForStartedAt(row.startedAt, replayStartMs, turns); - if (idx === null) continue; - tx.update(toolCalls).set({ turnIdx: idx }).where(eq(toolCalls.id, row.id)).run(); - } - - const usageRows = tx - .select({ id: modelUsage.id, startedAt: modelUsage.startedAt }) - .from(modelUsage) - .where(and(eq(modelUsage.replayId, replayId), isNull(modelUsage.turnIdx))) - .all(); - for (const row of usageRows) { - const idx = turnIdxForStartedAt(row.startedAt, replayStartMs, turns); - if (idx === null) continue; - tx.update(modelUsage).set({ turnIdx: idx }).where(eq(modelUsage.id, row.id)).run(); - } -} - -function turnIdxForStartedAt( - startedAtIso: string | null, - replayStartMs: number, - turns: readonly TurnWindow[], -): number | null { - if (startedAtIso === null) return null; - const spanStartMs = Date.parse(startedAtIso); - if (!Number.isFinite(spanStartMs)) return null; - const offsetMs = spanStartMs - replayStartMs; - for (const t of turns) { - if (offsetMs >= t.voiceStartMs && offsetMs < t.voiceEndMs) return t.idx; - } - return null; -} diff --git a/src/server/jobs/calculate-metrics/calculate-metrics.processor.test.ts b/src/server/jobs/calculate-metrics/calculate-metrics.processor.test.ts index a445841..e14750e 100644 --- a/src/server/jobs/calculate-metrics/calculate-metrics.processor.test.ts +++ b/src/server/jobs/calculate-metrics/calculate-metrics.processor.test.ts @@ -4,16 +4,9 @@ import { seedConversation } from "@/server/conversations/conversations.test-util import { makeFakeJobRunner } from "@/server/jobs/jobs.test-utils.ts"; import { makeReplayEvents } from "@/server/replays/replays.events.ts"; import { createReplay } from "@/server/replays/replays.service.ts"; -import { - replayEvaluations, - replayMetrics, - replays, - replayTurns, - spans, - speechSegments, -} from "@/server/store/schema.ts"; +import { replayEvaluations, replayMetrics, replays, replayTurns } from "@/server/store/schema.ts"; import { makeTempStore } from "@/server/store/test-utils.ts"; -import type { ReplayTurnRow, SpanRow, SpeechSegmentRow } from "@/server/store/types.ts"; +import type { ReplayTurnRow, SpeechSegmentRow } from "@/server/store/types.ts"; import { computeMetrics, makeCalculateMetricsProcessor } from "./calculate-metrics.processor.ts"; import { describe, expect, it } from "bun:test"; @@ -59,85 +52,11 @@ describe("computeMetrics (pure)", () => { voiceEndMs: 2500, }, ]; - const rows = computeMetrics("r", turns, [], [], 0); + const rows = computeMetrics("r", turns, []); expect(rows[1]?.agentResponseMs).toBe(300); expect(rows[0]?.agentResponseMs).toBeNull(); }); - it("computes positive ttftMs from the earliest gen_ai span in [turnStartMs, voiceStartMs)", () => { - const turns: ReplayTurnRow[] = [ - { - replayId: "r", - idx: 0, - role: "agent", - turnStartMs: 800, - turnEndMs: 2000, - voiceStartMs: 1500, - voiceEndMs: 2000, - }, - ]; - const replayStartMs = Date.parse("2026-05-18T12:00:00.000Z"); - const ttftSpans: SpanRow[] = [ - { - id: 1, - replayId: "r", - traceId: "t", - spanId: "s", - parentSpanId: null, - name: "chat", - vocabulary: "gen_ai", - startedAt: new Date(replayStartMs + 1000).toISOString(), - endedAt: new Date(replayStartMs + 1400).toISOString(), - attributesJson: "{}", - }, - { - id: 2, - replayId: "r", - traceId: "t", - spanId: "s2", - parentSpanId: null, - name: "chat2", - vocabulary: "gen_ai", - startedAt: new Date(replayStartMs + 1200).toISOString(), - endedAt: new Date(replayStartMs + 1450).toISOString(), - attributesJson: "{}", - }, - ]; - const rows = computeMetrics("r", turns, [], ttftSpans, replayStartMs); - expect(rows[0]?.ttftMs).toBe(500); - }); - - it("returns null when no gen_ai span lands in the LLM-call attribution window", () => { - const turns: ReplayTurnRow[] = [ - { - replayId: "r", - idx: 0, - role: "agent", - turnStartMs: 1000, - turnEndMs: 2000, - voiceStartMs: 1500, - voiceEndMs: 2000, - }, - ]; - const replayStartMs = Date.parse("2026-05-18T12:00:00.000Z"); - const ttftSpans: SpanRow[] = [ - { - id: 1, - replayId: "r", - traceId: "t", - spanId: "s", - parentSpanId: null, - name: "chat", - vocabulary: "gen_ai", - startedAt: new Date(replayStartMs + 1600).toISOString(), - endedAt: new Date(replayStartMs + 1700).toISOString(), - attributesJson: "{}", - }, - ]; - const rows = computeMetrics("r", turns, [], ttftSpans, replayStartMs); - expect(rows[0]?.ttftMs).toBeNull(); - }); - it("flags interrupted=true when opposite channel starts a segment inside the turn", () => { const turns: ReplayTurnRow[] = [ { @@ -153,7 +72,7 @@ describe("computeMetrics (pure)", () => { const segments: SpeechSegmentRow[] = [ { id: 1, replayId: "r", channel: "user", startMs: 1200, endMs: 1500 }, ]; - const rows = computeMetrics("r", turns, segments, [], 0); + const rows = computeMetrics("r", turns, segments); expect(rows[0]?.interrupted).toBe(true); expect(rows[0]?.interruptionStartMs).toBe(1200); }); @@ -173,7 +92,7 @@ describe("computeMetrics (pure)", () => { const segments: SpeechSegmentRow[] = [ { id: 1, replayId: "r", channel: "agent", startMs: 600, endMs: 1500 }, ]; - const rows = computeMetrics("r", turns, segments, [], 0); + const rows = computeMetrics("r", turns, segments); expect(rows[0]?.interrupted).toBe(false); }); }); @@ -224,9 +143,6 @@ describe("makeCalculateMetricsProcessor", () => { it("stamps failed + failure_reason='metrics_failed' on internal error", async () => { const { store, replayId } = await setupReplay(); - // Force a unique-key collision on insert by pre-populating a row with - // the same composite PK — the second insert inside the processor - // will throw. store.db .insert(replayTurns) .values({ @@ -239,15 +155,8 @@ describe("makeCalculateMetricsProcessor", () => { voiceEndMs: 1, }) .run(); - // Pre-populate replay_metrics so the delete-then-insert path works - // but break it by inserting an invalid row beforehand via raw SQL? No - // — easier: stub the runner to throw on enqueue (after the write - // commits) → markReplayFailed runs in the catch. Hmm, that's not quite - // "metrics stage failed" though. Instead, drive the failure by giving - // the replay a malformed startedAt. Date.parse returns NaN, ttft stays - // null, but the processor doesn't throw on that. So instead: pre-write - // a metrics row outside the transaction to fight the delete? Not - // reliable. Easier: spy on the runner to throw. + // A throwing enqueue is the cheapest in-stage failure that reaches the + // processor's catch — the pure compute path has no injectable fault. const runner = makeFakeJobRunner(); const throwingRunner = { ...runner, @@ -337,7 +246,3 @@ describe("makeCalculateMetricsProcessor", () => { store.close(); }); }); - -// Silence the unused-import lint — `spans` is referenced through SpanRow. -void spans; -void speechSegments; diff --git a/src/server/jobs/calculate-metrics/calculate-metrics.processor.ts b/src/server/jobs/calculate-metrics/calculate-metrics.processor.ts index c970dee..7878828 100644 --- a/src/server/jobs/calculate-metrics/calculate-metrics.processor.ts +++ b/src/server/jobs/calculate-metrics/calculate-metrics.processor.ts @@ -1,4 +1,4 @@ -import { and, asc, eq } from "drizzle-orm"; +import { asc, eq } from "drizzle-orm"; import { getConversationSpec } from "@/server/conversations/conversations.service.ts"; import type { ReplayEvents } from "@/server/replays/replays.events.ts"; @@ -10,11 +10,10 @@ import { replayMetrics, replays, replayTurns, - spans, speechSegments, } from "@/server/store/schema.ts"; import type { Store } from "@/server/store/store.ts"; -import type { ReplayTurnRow, SpanRow, SpeechSegmentRow } from "@/server/store/types.ts"; +import type { ReplayTurnRow, SpeechSegmentRow } from "@/server/store/types.ts"; import type { JobRunner } from "../jobs.bunqueue.ts"; import { JobProcessingError } from "../jobs.errors.ts"; @@ -36,17 +35,17 @@ export type CalculateMetricsProcessor = (payload: JobPayload) => Promise { const sorted = [...turns].sort((a, b) => a.idx - b.idx); return sorted.map((turn, i) => { const agentResponseMs = turn.role === "agent" ? agentResponseFor(turn, sorted, i) : null; - const ttftMs = turn.role === "agent" ? ttftFor(turn, ttftSpans, replayStartMs) : null; const { interrupted, interruptionStartMs } = interruptionFor(turn, segments); return { replayId, turnIdx: turn.idx, agentResponseMs, - ttftMs, interrupted, interruptionStartMs, }; @@ -228,25 +216,6 @@ function agentResponseFor( return null; } -function ttftFor( - turn: ReplayTurnRow, - ttftSpans: readonly SpanRow[], - replayStartMs: number, -): number | null { - if (!Number.isFinite(replayStartMs)) return null; - let earliestOffsetMs: number | null = null; - for (const span of ttftSpans) { - const startMs = Date.parse(span.startedAt) - replayStartMs; - if (!Number.isFinite(startMs)) continue; - if (startMs < turn.turnStartMs || startMs >= turn.voiceStartMs) continue; - if (earliestOffsetMs === null || startMs < earliestOffsetMs) { - earliestOffsetMs = startMs; - } - } - if (earliestOffsetMs === null) return null; - return turn.voiceStartMs - earliestOffsetMs; -} - function interruptionFor( turn: ReplayTurnRow, segments: readonly SpeechSegmentRow[], diff --git a/src/server/jobs/evaluate-replay/evaluate-replay.processor.test.ts b/src/server/jobs/evaluate-replay/evaluate-replay.processor.test.ts index 22b64ee..03ca42c 100644 --- a/src/server/jobs/evaluate-replay/evaluate-replay.processor.test.ts +++ b/src/server/jobs/evaluate-replay/evaluate-replay.processor.test.ts @@ -13,10 +13,12 @@ import { createReplay } from "@/server/replays/replays.service.ts"; import { assertionResults, judgeResults, + modelUsage, replayEvaluations, replayMetrics, replays, replayTurns, + toolCalls, turnTranscripts, } from "@/server/store/schema.ts"; import { makeTempStore } from "@/server/store/test-utils.ts"; @@ -41,7 +43,6 @@ interface VadFixture { voiceStartMs?: number; voiceEndMs?: number; agentResponseMs?: number | null; - ttftMs?: number | null; } async function setupReplay(opts: { @@ -93,7 +94,6 @@ async function setupReplay(opts: { voiceStartMs: 1300, voiceEndMs: 2500, agentResponseMs: 300, - ttftMs: 100, }, ]; @@ -133,7 +133,6 @@ async function setupReplay(opts: { replayId: detail.id, turnIdx: t.idx, agentResponseMs: t.role === "agent" ? (t.agentResponseMs ?? 300) : null, - ttftMs: t.role === "agent" ? (t.ttftMs ?? 100) : null, interrupted: false, interruptionStartMs: null, })), @@ -458,4 +457,196 @@ describe("evaluate-replay processor", () => { expect(result.passed).toBe(true); }); }); + + describe("tool attribution by audio timeline", () => { + // The agent turn's window is [turnStartMs=1000, turnEndMs=2500). A tool + // call is attributed to it iff (started_at − recording_started_at) lands + // in that window. recording_started_at is the SOLE origin — never + // replays.started_at (row-creation time). See spec 0001. + const RECORDING_T0 = "2026-05-26T14:31:31.023Z"; + const atOffset = (ms: number) => new Date(Date.parse(RECORDING_T0) + ms).toISOString(); + + type ToolCtx = Awaited>; + + async function setupToolReplay(recordingStartedAt: string | null): Promise { + const ctx = await setupReplay({ + turns: [ + { role: "user", assertions: [] }, + { role: "agent", assertions: [{ kind: "tool_called", name: "lookup" }] }, + ], + judges: [], + }); + ctx.store.db + .update(replays) + .set({ recordingStartedAt }) + .where(eq(replays.id, ctx.replayId)) + .run(); + return ctx; + } + + function insertTool(ctx: ToolCtx, startedAt: string): void { + ctx.store.db + .insert(toolCalls) + .values({ + replayId: ctx.replayId, + spanId: "s1", + name: "lookup", + argsJson: null, + resultJson: null, + startedAt, + endedAt: startedAt, + latencyMs: 0, + }) + .run(); + } + + async function runAndGetToolStatus(ctx: ToolCtx): Promise { + await makeEvaluateReplayProcessor( + ctx.store, + makeReplayEvents(), + fakeJudge(), + )({ + replayId: ctx.replayId, + }); + return ctx.store.db + .select() + .from(assertionResults) + .where(eq(assertionResults.replayId, ctx.replayId)) + .all() + .find((r) => r.kind === "tool_called")?.status; + } + + it("passes tool_called when the call lands inside the agent turn window", async () => { + const ctx = await setupToolReplay(RECORDING_T0); + insertTool(ctx, atOffset(1500)); // offset 1500 ∈ [1000, 2500) + expect(await runAndGetToolStatus(ctx)).toBe("passed"); + }); + + it("flags a mistimed call: speculative-during-user-turn is NOT in the agent turn", async () => { + const ctx = await setupToolReplay(RECORDING_T0); + insertTool(ctx, atOffset(500)); // offset 500 ∈ user turn [0,1000), not agent's + expect(await runAndGetToolStatus(ctx)).toBe("failed"); + }); + + it("errors tool_called when the replay has no recording anchor", async () => { + const ctx = await setupToolReplay(null); + insertTool(ctx, atOffset(1500)); + expect(await runAndGetToolStatus(ctx)).toBe("errored"); + }); + }); + + describe("ttft attribution by audio timeline", () => { + // Same agent turn window [1000, 2500) as the tool block. max_ttft_ms + // sources ttftMs from the earliest in-window model_usage row that + // carries one. recording_started_at is the sole origin. See spec 0001. + const RECORDING_T0 = "2026-05-26T14:31:31.023Z"; + const atOffset = (ms: number) => new Date(Date.parse(RECORDING_T0) + ms).toISOString(); + type Ctx = Awaited>; + + async function setupTtftReplay(): Promise { + const ctx = await setupReplay({ + turns: [ + { role: "user", assertions: [] }, + { role: "agent", assertions: [{ kind: "max_ttft_ms", max_ms: 500 }] }, + ], + judges: [], + }); + ctx.store.db + .update(replays) + .set({ recordingStartedAt: RECORDING_T0 }) + .where(eq(replays.id, ctx.replayId)) + .run(); + return ctx; + } + + function insertUsage(ctx: Ctx, startedAt: string, ttftMs: number | null): void { + ctx.store.db + .insert(modelUsage) + .values({ + replayId: ctx.replayId, + spanId: `u-${startedAt}`, + provider: "openai", + model: "gpt-4o", + inputTokens: null, + outputTokens: null, + totalTokens: null, + ttftMs, + startedAt, + endedAt: startedAt, + latencyMs: 0, + }) + .run(); + } + + async function runAndGetTtft( + ctx: Ctx, + ): Promise<{ status: string | undefined; message: string | null | undefined }> { + await makeEvaluateReplayProcessor( + ctx.store, + makeReplayEvents(), + fakeJudge(), + )({ + replayId: ctx.replayId, + }); + const row = ctx.store.db + .select() + .from(assertionResults) + .where(eq(assertionResults.replayId, ctx.replayId)) + .all() + .find((r) => r.kind === "max_ttft_ms"); + return { status: row?.status, message: row?.message }; + } + + it("passes when the earliest in-window model call's ttft is under the limit", async () => { + const ctx = await setupTtftReplay(); + insertUsage(ctx, atOffset(1400), 300); // offset 1400 ∈ [1000, 2500) + expect((await runAndGetTtft(ctx)).status).toBe("passed"); + }); + + it("does NOT let a leading null-ttft call mask a later call that carries one", async () => { + // Regression: a first in-window call without the TTFT attribute + // (ttft=null) must not shadow a later call with a real measurement. + const ctx = await setupTtftReplay(); + insertUsage(ctx, atOffset(1100), null); // earliest, no measurement + insertUsage(ctx, atOffset(1400), 300); // later, carries TTFT under limit + expect((await runAndGetTtft(ctx)).status).toBe("passed"); + }); + + it("fails when the earliest measured ttft exceeds the limit", async () => { + const ctx = await setupTtftReplay(); + insertUsage(ctx, atOffset(1200), 4000); + const { status, message } = await runAndGetTtft(ctx); + expect(status).toBe("failed"); + expect(message).toContain("4000ms"); + }); + + it("errors with a 'no model call in window' message when no usage row lands in the turn", async () => { + const ctx = await setupTtftReplay(); + insertUsage(ctx, atOffset(500), 300); // offset 500 ∈ user turn, not agent's + const { status, message } = await runAndGetTtft(ctx); + expect(status).toBe("errored"); + expect(message).toContain("no model call landed"); + }); + + it("errors with an 'attribute missing' message when in-window calls carry no ttft", async () => { + const ctx = await setupTtftReplay(); + insertUsage(ctx, atOffset(1400), null); + const { status, message } = await runAndGetTtft(ctx); + expect(status).toBe("errored"); + expect(message).toContain("time_to_first_chunk"); + }); + + it("errors when the replay has no recording anchor", async () => { + const ctx = await setupTtftReplay(); + ctx.store.db + .update(replays) + .set({ recordingStartedAt: null }) + .where(eq(replays.id, ctx.replayId)) + .run(); + insertUsage(ctx, atOffset(1400), 300); + const { status, message } = await runAndGetTtft(ctx); + expect(status).toBe("errored"); + expect(message).toContain("no recording anchor"); + }); + }); }); diff --git a/src/server/jobs/evaluate-replay/evaluate-replay.processor.ts b/src/server/jobs/evaluate-replay/evaluate-replay.processor.ts index 1521371..a7ae79d 100644 --- a/src/server/jobs/evaluate-replay/evaluate-replay.processor.ts +++ b/src/server/jobs/evaluate-replay/evaluate-replay.processor.ts @@ -16,6 +16,8 @@ import type { JudgeOutcomeResponse, ReplayResult, } from "@/server/replays/replays.types.ts"; +import type { TurnWindow } from "@/server/replays/timeline.ts"; +import { audioOffsetMs, clampedTurnWindows, rowsInTurnWindow } from "@/server/replays/timeline.ts"; import { projectTurnMetrics } from "@/server/replays/turn-metrics.ts"; import { assertionResults, @@ -130,6 +132,20 @@ export function makeEvaluateReplayProcessor( .where(eq(modelUsage.replayId, replayId)) .all(); + // Tiling attribution windows for every VAD turn, in idx order, built + // from each turn's voiceEndMs — the voice-active boundary the spec + // attributes against (0001 §3.4), not turnEndMs (equal today, but + // stored separately for future overlap handling). Built once (the + // cursor accumulates across all turns, including extra VAD turns the + // spec doesn't assert) and looked up per matched turn. + const windows = clampedTurnWindows(turnRows.map((t) => t.voiceEndMs)); + const windowByIdx = new Map(); + for (let t = 0; t < turnRows.length; t++) { + const row = turnRows[t]; + const window = windows[t]; + if (row !== undefined && window !== undefined) windowByIdx.set(row.idx, window); + } + const evaluatedAt = new Date().toISOString(); const assertionRows: AssertionResultInsert[] = []; const assertionOutcomes: AssertionOutcomeResponse[] = []; @@ -161,7 +177,15 @@ export function makeEvaluateReplayProcessor( const assertions = turn.assertions ?? []; if (assertions.length === 0) continue; - const ctx = buildAssertionContext(matched, transcripts, metricRows, toolRows, usageRows); + const ctx = buildAssertionContext( + matched, + windowByIdx.get(matched.idx), + transcripts, + metricRows, + toolRows, + usageRows, + replay.recordingStartedAt, + ); for (let j = 0; j < assertions.length; j++) { const assertion = assertions[j]; if (assertion === undefined) continue; @@ -305,37 +329,77 @@ export function makeEvaluateReplayProcessor( /** * Build the per-assertion context against a specific VAD-derived turn. * - * All downstream lookups (`transcripts`, `metrics`, `tool_calls`, - * `model_usage`) are keyed on the VAD-row's `idx`, NOT the spec's turn - * position. The analyze-replay stage wrote those tables using VAD-derived - * indexes, and the calculate-metrics + OTLP backfill stages followed the - * same convention. Pairing here must use the matched VAD idx so the - * spec's `assertions[i]` sees the matched VAD turn's transcript, not the - * spec position's transcript (which doesn't exist when spec/VAD diverge). + * `transcripts` + `metrics` are keyed on the VAD row's `idx`. `tool_calls` / + * `model_usage` carry no stored turn idx — membership is the tiling attribution + * `window` (`clampedTurnWindows`, see `src/server/replays/timeline.ts`) applied + * to each row's wall-clock `started_at` against the replay's + * `recording_started_at`. A row whose call fired before the user stopped + * (speculative) or after the agent finished lands in a neighbouring turn's tile + * and is excluded — `tool_called` then flags the mistiming. + * + * `ttftMs` is the earliest in-window model call's `model_usage.ttft_ms` — a + * span-level, same-clock delta, not a per-turn aggregate. + * + * When `recordingStartedAt` is null (or no window exists for this turn) the rows + * can't be placed on the timeline; `hasRecordingAnchor` is false and the + * evaluator maps tool/ttft assertions to `errored` rather than a misleading + * pass/fail. */ function buildAssertionContext( matched: ReplayTurnRow, + window: TurnWindow | undefined, transcripts: readonly TurnTranscriptRow[], metrics: readonly ReplayMetricRow[], toolRows: readonly ToolCallRow[], usageRows: readonly ModelUsageRow[], + recordingStartedAt: string | null, ): AssertionContext { const vadIdx = matched.idx; const transcript = transcripts.find((t) => t.turnIdx === vadIdx)?.text ?? null; const metric = metrics.find((m) => m.turnIdx === vadIdx); + const usageInWindow = + window === undefined ? [] : rowsInTurnWindow(usageRows, window, recordingStartedAt); return { turnIdx: vadIdx, turnRole: matched.role, transcript, - toolCalls: toolRows.filter((tc) => tc.turnIdx === vadIdx), - modelUsage: usageRows.filter((mu) => mu.turnIdx === vadIdx), + hasRecordingAnchor: recordingStartedAt !== null && window !== undefined, + toolCalls: window === undefined ? [] : rowsInTurnWindow(toolRows, window, recordingStartedAt), + modelUsage: usageInWindow, metrics: { agentResponseMs: metric?.agentResponseMs ?? null, - ttftMs: metric?.ttftMs ?? null, + ttftMs: earliestTtftMs(usageInWindow, recordingStartedAt), }, }; } +/** + * TTFT of the earliest (by audio offset) in-window model call that actually + * carries one, or null when none does. We pick the earliest call's measurement + * (spec §3.4: "the first LLM call's perceived first-chunk latency"), but skip + * rows whose `ttftMs` is null — a leading call that didn't emit + * `gen_ai.response.time_to_first_chunk` (e.g. a Langfuse-vocabulary span, which + * never carries it) must not mask a later call that did, which would make + * `max_ttft_ms` falsely report "no call carried TTFT". + */ +function earliestTtftMs( + usageInWindow: readonly ModelUsageRow[], + recordingStartedAt: string | null, +): number | null { + let earliestTtft: number | null = null; + let earliestOffset = Number.POSITIVE_INFINITY; + for (const row of usageInWindow) { + if (row.ttftMs === null) continue; + const offset = audioOffsetMs(row.startedAt, recordingStartedAt); + if (offset === null) continue; + if (offset < earliestOffset) { + earliestOffset = offset; + earliestTtft = row.ttftMs; + } + } + return earliestTtft; +} + function buildJudgeTurns( turnRows: readonly ReplayTurnRow[], transcripts: readonly TurnTranscriptRow[], diff --git a/src/server/otlp/otlp.service.test.ts b/src/server/otlp/otlp.service.test.ts index 41e88a8..c863a90 100644 --- a/src/server/otlp/otlp.service.test.ts +++ b/src/server/otlp/otlp.service.test.ts @@ -117,6 +117,8 @@ describe("ingestOtlpTraces — gen_ai vocabulary", () => { "gen_ai.request.model": "gpt-4o", "gen_ai.usage.input_tokens": 42, "gen_ai.usage.output_tokens": 17, + // Seconds (semconv) → ms. 0.25 encodes as a doubleValue. + "gen_ai.response.time_to_first_chunk": 0.25, }, }, ], @@ -129,6 +131,7 @@ describe("ingestOtlpTraces — gen_ai vocabulary", () => { expect(usage?.outputTokens).toBe(17); expect(usage?.totalTokens).toBe(59); expect(usage?.latencyMs).toBe(500); + expect(usage?.ttftMs).toBe(250); store.close(); }); @@ -179,6 +182,8 @@ describe("ingestOtlpTraces — langfuse vocabulary", () => { expect(usage?.model).toBe("claude-3-5-sonnet"); expect(usage?.inputTokens).toBe(5); expect(usage?.outputTokens).toBe(9); + // No time_to_first_chunk on this span → null, like the token counts. + expect(usage?.ttftMs).toBeNull(); store.close(); }); }); diff --git a/src/server/otlp/otlp.service.ts b/src/server/otlp/otlp.service.ts index 07dee5e..f029438 100644 --- a/src/server/otlp/otlp.service.ts +++ b/src/server/otlp/otlp.service.ts @@ -127,14 +127,13 @@ export function ingestOtlpTraces( } /** - * Persist extracted tool_calls / model_usage rows with `turn_idx = null`. - * The analyze-replay job backfills `turn_idx` from `replay_turns` once VAD - * has produced authoritative turn boundaries — see spec 0001 §8. - * - * The receiver no longer trusts driver-emitted `xray.turn.idx`: spans can - * arrive before VAD has run (or with stale baggage from a prior turn). - * Timestamp-based attribution against `replay_turns.voice_start_ms..voice_end_ms` - * is the single source of truth. + * Persist extracted tool_calls / model_usage rows. No turn association is + * stored — rows carry only their wall-clock `started_at`. Turn membership is + * derived at read/eval time by mapping `started_at` onto the audio timeline + * (`audio_offset_ms = started_at − replays.recording_started_at`) and testing + * the turn window — see `docs/specs/0001-timeline-clock-alignment.md` and + * `src/server/replays/timeline.ts`. Every recognized row is recorded + * unconditionally; the timeline placement decides display + assertion scope. */ function persistExtracted( tx: StoreDb, @@ -147,7 +146,6 @@ function persistExtracted( .values( extraction.toolCalls.map((tc) => ({ replayId, - turnIdx: null, spanId: span.spanId, name: tc.name, argsJson: tc.argsJson, @@ -164,13 +162,13 @@ function persistExtracted( .values( extraction.modelUsage.map((mu) => ({ replayId, - turnIdx: null, spanId: span.spanId, provider: mu.provider, model: mu.model, inputTokens: mu.inputTokens, outputTokens: mu.outputTokens, totalTokens: mu.totalTokens, + ttftMs: mu.ttftMs, startedAt: mu.startedAt, endedAt: mu.endedAt, latencyMs: mu.latencyMs, diff --git a/src/server/otlp/vocabularies/attrs.ts b/src/server/otlp/vocabularies/attrs.ts index 5f4ba49..88ab3ef 100644 --- a/src/server/otlp/vocabularies/attrs.ts +++ b/src/server/otlp/vocabularies/attrs.ts @@ -20,6 +20,20 @@ export function asInteger(v: FlatAttributes[string] | undefined): number | null return null; } +/** + * Parse a finite floating-point value (number, or numeric string incl. + * decimals). Used for semconv durations expressed in seconds — e.g. + * `gen_ai.response.time_to_first_chunk` = `0.5`. + */ +export function asFiniteNumber(v: FlatAttributes[string] | undefined): number | null { + if (typeof v === "number") return Number.isFinite(v) ? v : null; + if (typeof v === "string" && v.trim() !== "") { + const n = Number(v); + return Number.isFinite(n) ? n : null; + } + return null; +} + export function safeJsonString(maybeJson: string): string { try { const parsed = JSON.parse(maybeJson); diff --git a/src/server/otlp/vocabularies/gen-ai-semconv.test.ts b/src/server/otlp/vocabularies/gen-ai-semconv.test.ts index 80e8bfd..bc1f321 100644 --- a/src/server/otlp/vocabularies/gen-ai-semconv.test.ts +++ b/src/server/otlp/vocabularies/gen-ai-semconv.test.ts @@ -26,6 +26,7 @@ describe("genAiSemconvVocabulary — chat / text_completion", () => { inputTokens: 42, outputTokens: 7, totalTokens: 49, + ttftMs: null, startedAt: "2026-05-18T12:00:00.000Z", endedAt: "2026-05-18T12:00:00.250Z", latencyMs: 250, @@ -33,6 +34,30 @@ describe("genAiSemconvVocabulary — chat / text_completion", () => { ]); }); + it("converts gen_ai.response.time_to_first_chunk (seconds) to ttftMs", () => { + const span = makeProjectedSpan({ + name: "chat gpt-4o", + attributes: { + "gen_ai.operation.name": "chat", + "gen_ai.response.time_to_first_chunk": 0.25, + }, + }); + const out = genAiSemconvVocabulary(span, EMPTY_RESOURCE); + expect(out?.modelUsage?.[0]?.ttftMs).toBe(250); + }); + + it("drops a negative time_to_first_chunk to null", () => { + const span = makeProjectedSpan({ + name: "chat gpt-4o", + attributes: { + "gen_ai.operation.name": "chat", + "gen_ai.response.time_to_first_chunk": -1, + }, + }); + const out = genAiSemconvVocabulary(span, EMPTY_RESOURCE); + expect(out?.modelUsage?.[0]?.ttftMs).toBeNull(); + }); + it("falls back to gen_ai.request.model when response.model is absent", () => { const span = makeProjectedSpan({ name: "chat gpt-4o", diff --git a/src/server/otlp/vocabularies/gen-ai-semconv.ts b/src/server/otlp/vocabularies/gen-ai-semconv.ts index 10eeb10..f2cdea0 100644 --- a/src/server/otlp/vocabularies/gen-ai-semconv.ts +++ b/src/server/otlp/vocabularies/gen-ai-semconv.ts @@ -1,5 +1,12 @@ import type { FlatAttributes, ProjectedSpan } from "../otlp.types.ts"; -import { asInteger, asString, msBetween, pickPrefixed, safeJsonString } from "./attrs.ts"; +import { + asFiniteNumber, + asInteger, + asString, + msBetween, + pickPrefixed, + safeJsonString, +} from "./attrs.ts"; import type { ExtractedModelUsage, ExtractedToolCall, @@ -67,6 +74,7 @@ export const genAiSemconvVocabulary: SpanVocabularyMatcher = ( asInteger(a["gen_ai.usage.input_tokens"]), asInteger(a["gen_ai.usage.output_tokens"]), ), + ttftMs: ttftMsFromSeconds(a["gen_ai.response.time_to_first_chunk"]), startedAt, endedAt, latencyMs, @@ -87,3 +95,14 @@ function addOrNull(a: number | null, b: number | null): number | null { if (a === null && b === null) return null; return (a ?? 0) + (b ?? 0); } + +/** + * `gen_ai.response.time_to_first_chunk` is seconds (semconv, Development + * stability). Convert to whole ms for `model_usage.ttft_ms`. A negative value + * is nonsensical for a latency and dropped to null. + */ +function ttftMsFromSeconds(raw: FlatAttributes[string] | undefined): number | null { + const seconds = asFiniteNumber(raw); + if (seconds === null || seconds < 0) return null; + return Math.round(seconds * 1000); +} diff --git a/src/server/otlp/vocabularies/langfuse.test.ts b/src/server/otlp/vocabularies/langfuse.test.ts index 26031d6..6d6e020 100644 --- a/src/server/otlp/vocabularies/langfuse.test.ts +++ b/src/server/otlp/vocabularies/langfuse.test.ts @@ -26,6 +26,7 @@ describe("langfuseVocabulary — generation observations", () => { inputTokens: 100, outputTokens: 25, totalTokens: 125, + ttftMs: null, startedAt: "2026-05-18T12:00:00.000Z", endedAt: "2026-05-18T12:00:00.400Z", latencyMs: 400, diff --git a/src/server/otlp/vocabularies/langfuse.ts b/src/server/otlp/vocabularies/langfuse.ts index 543f910..deed9ae 100644 --- a/src/server/otlp/vocabularies/langfuse.ts +++ b/src/server/otlp/vocabularies/langfuse.ts @@ -38,6 +38,9 @@ export const langfuseVocabulary: SpanVocabularyMatcher = ( inputTokens: asInteger(a["langfuse.observation.usage_details.input"]), outputTokens: asInteger(a["langfuse.observation.usage_details.output"]), totalTokens: asInteger(a["langfuse.observation.usage_details.total"]), + // TTFT is sourced from the GenAI semconv attribute only (spec 0001); + // Langfuse's completion_start_time is a possible future source. + ttftMs: null, startedAt, endedAt, latencyMs, diff --git a/src/server/otlp/vocabularies/vocabularies.types.ts b/src/server/otlp/vocabularies/vocabularies.types.ts index ebe6543..ef6ce6b 100644 --- a/src/server/otlp/vocabularies/vocabularies.types.ts +++ b/src/server/otlp/vocabularies/vocabularies.types.ts @@ -19,6 +19,9 @@ export interface ExtractedModelUsage { inputTokens: number | null; outputTokens: number | null; totalTokens: number | null; + /** Model time-to-first-token (ms), from `gen_ai.response.time_to_first_chunk` + * (seconds). Optional, like the token counts — null when unemitted. */ + ttftMs: number | null; startedAt: string | null; endedAt: string | null; latencyMs: number | null; diff --git a/src/server/replays/replays.router.test.ts b/src/server/replays/replays.router.test.ts index b5316b6..2ec92a7 100644 --- a/src/server/replays/replays.router.test.ts +++ b/src/server/replays/replays.router.test.ts @@ -363,7 +363,6 @@ describe("GET /v1/replays/:id/result", () => { replayId, turnIdx: 1, agentResponseMs: 100, - ttftMs: 50, interrupted: false, interruptionStartMs: null, }, diff --git a/src/server/replays/replays.service.test.ts b/src/server/replays/replays.service.test.ts index 61d8724..27d5127 100644 --- a/src/server/replays/replays.service.test.ts +++ b/src/server/replays/replays.service.test.ts @@ -478,7 +478,6 @@ describe("getReplayResult — interruption timing", () => { replayId, turnIdx: 0, agentResponseMs: 250, - ttftMs: 80, interrupted: true, interruptionStartMs: 1450, }) diff --git a/src/server/replays/replays.service.ts b/src/server/replays/replays.service.ts index 2cfc993..dbccc08 100644 --- a/src/server/replays/replays.service.ts +++ b/src/server/replays/replays.service.ts @@ -53,6 +53,7 @@ import type { TurnTranscriptResponse, UpdateReplayRequest, } from "./replays.types.ts"; +import { offsetFromOriginMs } from "./timeline.ts"; import { projectTurnMetrics } from "./turn-metrics.ts"; export interface CreateReplayOptions { @@ -79,6 +80,7 @@ export function createReplay( failureReason: null, startedAt, finishedAt: null, + recordingStartedAt: null, audioPath: null, runConfigJson: req.run_config === undefined ? null : JSON.stringify(req.run_config), jobId: null, @@ -194,6 +196,12 @@ function buildReplayDetail(store: Store, r: ReplayRow): ReplayDetailResponse { .where(eq(turnTranscripts.replayId, id)) .all(); transcriptRows.sort((a, b) => a.turnIdx - b.turnIdx); + + // Parse the timeline origin once for the whole detail payload — every + // span / tool_call / model_usage offset measures from the same string. + const parsedOrigin = r.recordingStartedAt === null ? null : Date.parse(r.recordingStartedAt); + const originMs = parsedOrigin !== null && Number.isFinite(parsedOrigin) ? parsedOrigin : null; + const offsetOf = (startedAt: string | null) => offsetFromOriginMs(startedAt, originMs); return { id: r.id, conversation_hash: r.conversationHash, @@ -202,6 +210,7 @@ function buildReplayDetail(store: Store, r: ReplayRow): ReplayDetailResponse { failure_reason: r.failureReason, started_at: r.startedAt, finished_at: r.finishedAt, + recording_started_at: r.recordingStartedAt, audio_path: r.audioPath, job_id: r.jobId, run_config: parseJsonOrNull(r.runConfigJson), @@ -209,9 +218,9 @@ function buildReplayDetail(store: Store, r: ReplayRow): ReplayDetailResponse { speech_segments: segments.map(toSegmentResponse), transcripts: transcriptRows.map(toTranscriptResponse), turn_metrics: buildTurnMetrics(store, id), - tool_calls: toolCallRows.map(toToolCallResponse), - model_usage: modelUsageRows.map(toModelUsageResponse), - spans: spanRows.map(toSpanResponse), + tool_calls: toolCallRows.map((row) => toToolCallResponse(row, offsetOf(row.startedAt))), + model_usage: modelUsageRows.map((row) => toModelUsageResponse(row, offsetOf(row.startedAt))), + spans: spanRows.map((row) => toSpanResponse(row, offsetOf(row.startedAt))), }; } @@ -271,10 +280,10 @@ function toSegmentResponse(row: SpeechSegmentRow): SpeechSegmentResponse { }; } -function toToolCallResponse(row: ToolCallRow): ToolCallResponse { +function toToolCallResponse(row: ToolCallRow, audioOffsetMs: number | null): ToolCallResponse { return { id: row.id, - turn_idx: row.turnIdx, + audio_offset_ms: audioOffsetMs, span_id: row.spanId, name: row.name, args_json: row.argsJson, @@ -285,23 +294,27 @@ function toToolCallResponse(row: ToolCallRow): ToolCallResponse { }; } -function toModelUsageResponse(row: ModelUsageRow): ModelUsageResponse { +function toModelUsageResponse( + row: ModelUsageRow, + audioOffsetMs: number | null, +): ModelUsageResponse { return { id: row.id, - turn_idx: row.turnIdx, + audio_offset_ms: audioOffsetMs, span_id: row.spanId, provider: row.provider, model: row.model, input_tokens: row.inputTokens, output_tokens: row.outputTokens, total_tokens: row.totalTokens, + ttft_ms: row.ttftMs, started_at: row.startedAt, ended_at: row.endedAt, latency_ms: row.latencyMs, }; } -function toSpanResponse(row: SpanRow): SpanResponse { +function toSpanResponse(row: SpanRow, audioOffsetMs: number | null): SpanResponse { return { id: row.id, trace_id: row.traceId, @@ -312,6 +325,7 @@ function toSpanResponse(row: SpanRow): SpanResponse { started_at: row.startedAt, ended_at: row.endedAt, attributes_json: row.attributesJson, + audio_offset_ms: audioOffsetMs, }; } diff --git a/src/server/replays/replays.types.ts b/src/server/replays/replays.types.ts index 12abc40..5f60c66 100644 --- a/src/server/replays/replays.types.ts +++ b/src/server/replays/replays.types.ts @@ -45,7 +45,10 @@ export const RUN_CONFIG_MAX_BYTES = MAX_RUN_CONFIG_BYTES; export const ToolCallResponseSchema = v.object({ id: v.number(), - turn_idx: v.nullable(v.number()), + // Offset on the audio timeline (ms from recording t=0), derived from + // started_at − replays.recording_started_at. Null when either is missing + // — the row is still listed; it just can't be placed on the timeline. + audio_offset_ms: v.nullable(v.number()), span_id: v.nullable(v.string()), name: v.string(), args_json: v.nullable(v.string()), @@ -58,13 +61,16 @@ export type ToolCallResponse = v.InferOutput; export const ModelUsageResponseSchema = v.object({ id: v.number(), - turn_idx: v.nullable(v.number()), + audio_offset_ms: v.nullable(v.number()), span_id: v.nullable(v.string()), provider: v.nullable(v.string()), model: v.nullable(v.string()), input_tokens: v.nullable(v.number()), output_tokens: v.nullable(v.number()), total_tokens: v.nullable(v.number()), + // Model time-to-first-token (ms), from gen_ai.response.time_to_first_chunk. + // Null when the agent's instrumentation doesn't emit it. + ttft_ms: v.nullable(v.number()), started_at: v.nullable(v.string()), ended_at: v.nullable(v.string()), latency_ms: v.nullable(v.number()), @@ -127,19 +133,27 @@ export const SpanResponseSchema = v.object({ started_at: v.string(), ended_at: v.string(), attributes_json: v.string(), + // Offset of started_at on the audio timeline (ms from recording t=0), + // derived from started_at − replays.recording_started_at. Null when the + // replay has no anchor — the span is then unplaceable and renders untimed. + // The single origin for client span placement (spec 0001 §3.2): the client + // never re-derives offsets from wall-clock, so it can't diverge from the + // assertion evaluator's view. + audio_offset_ms: v.nullable(v.number()), }); export type SpanResponse = v.InferOutput; /** - * Per-turn timing — the silence/gap before an agent responds (`agent_response_ms`), - * time-to-first-token, and barge-in. Observability data: rides the replay detail - * (Run details UI) AND the evaluation result (SDK `ReplayResult.metrics`). + * Per-turn timing — the silence/gap before an agent responds + * (`agent_response_ms`) and barge-in. Observability data: rides the replay + * detail (Run details UI) AND the evaluation result (SDK + * `ReplayResult.metrics`). Model TTFT is no longer a per-turn metric — it's an + * optional per-call attribute (`model_usage.ttft_ms`, spec 0001). */ export const TurnMetricsResponseSchema = v.object({ turn_idx: v.number(), role: TurnRoleSchema, agent_response_ms: v.nullable(v.number()), - ttft_ms: v.nullable(v.number()), interrupted: v.boolean(), interruption_start_ms: v.nullable(v.number()), }); @@ -166,6 +180,11 @@ export const ReplayDetailResponseSchema = v.object({ failure_reason: v.nullable(ReplayFailureReasonSchema), started_at: v.string(), finished_at: v.nullable(v.string()), + // Wall-clock of audio sample 0 (the timeline origin). The client maps any + // wall-clock timestamp (spans, tool calls, model usage) onto the audio + // timeline with `started_at − recording_started_at`. Null for older + // uploads that omitted the X-Recording-Started-At header. + recording_started_at: v.nullable(v.string()), audio_path: v.nullable(v.string()), job_id: v.nullable(v.string()), run_config: v.unknown(), diff --git a/src/server/replays/timeline.test.ts b/src/server/replays/timeline.test.ts new file mode 100644 index 0000000..6f95c3e --- /dev/null +++ b/src/server/replays/timeline.test.ts @@ -0,0 +1,124 @@ +import type { TurnWindow } from "./timeline.ts"; +import { + audioOffsetMs, + clampedTurnWindows, + offsetInTurnWindow, + rowsInTurnWindow, +} from "./timeline.ts"; +import { describe, expect, it } from "bun:test"; + +// Authentic numbers from snapshot/xray.db replay 7b8e2770… : +// replays.started_at (WRONG origin) = 14:31:28.688 +// recording t=0 (first xray.turn span) = 14:31:31.023 ← correct origin +// The 2335 ms gap between them is the bug this slice exists to kill. +const RECORDING_T0 = "2026-05-26T14:31:31.023Z"; +const ROW_CREATION = "2026-05-26T14:31:28.688Z"; // replays.started_at — must NOT be used as origin + +describe("audioOffsetMs", () => { + it("measures the offset from the recording origin, not row creation", () => { + // A span emitted 4000 ms into the recording. + const span = "2026-05-26T14:31:35.023Z"; + expect(audioOffsetMs(span, RECORDING_T0)).toBe(4000); + // Using the row-creation time as origin would inflate it by the 2335 ms + // gap — the exact bug. Documented here so the regression is legible. + expect(audioOffsetMs(span, ROW_CREATION)).toBe(6335); + }); + + it("returns null when either timestamp is missing", () => { + expect(audioOffsetMs(null, RECORDING_T0)).toBeNull(); + expect(audioOffsetMs("2026-05-26T14:31:35.023Z", null)).toBeNull(); + expect(audioOffsetMs(null, null)).toBeNull(); + }); + + it("returns null when a timestamp is unparseable", () => { + expect(audioOffsetMs("not-a-date", RECORDING_T0)).toBeNull(); + expect(audioOffsetMs("2026-05-26T14:31:35.023Z", "garbage")).toBeNull(); + }); + + it("can be negative for a span emitted before the recording started", () => { + expect(audioOffsetMs("2026-05-26T14:31:30.523Z", RECORDING_T0)).toBe(-500); + }); +}); + +// Snapshot-derived tiling: t0 agent, t1 user, t2 agent. turnStart_N == voiceEnd_{N-1}. +const T0: TurnWindow = { turnStartMs: 0, turnEndMs: 2190 }; +const T1: TurnWindow = { turnStartMs: 2190, turnEndMs: 4680 }; +const T2: TurnWindow = { turnStartMs: 4680, turnEndMs: 11070 }; + +describe("offsetInTurnWindow", () => { + it("includes the start, excludes the end (half-open)", () => { + expect(offsetInTurnWindow(2190, T1)).toBe(true); + expect(offsetInTurnWindow(4680, T1)).toBe(false); // belongs to T2 + expect(offsetInTurnWindow(4680, T2)).toBe(true); + }); + + it("tiles: every offset belongs to exactly one turn", () => { + const turns = [T0, T1, T2]; + for (const offset of [0, 100, 2189, 2190, 4679, 4680, 11069]) { + expect(turns.filter((t) => offsetInTurnWindow(offset, t)).length).toBe(1); + } + }); +}); + +describe("clampedTurnWindows", () => { + it("tiles strictly-interleaved turns: start_N = end_{N-1}, no gaps", () => { + // Three turns whose voice ends are already monotonic: 2190, 4680, 11070. + const windows = clampedTurnWindows([2190, 4680, 11070]); + expect(windows).toEqual([ + { turnStartMs: 0, turnEndMs: 2190 }, + { turnStartMs: 2190, turnEndMs: 4680 }, + { turnStartMs: 4680, turnEndMs: 11070 }, + ]); + }); + + it("collapses an inverted window and never overlaps under barge-in", () => { + // Agent voiceEnd 5000, user (barged-in) voiceEnd 3500, agent resumes 8000. + // Raw windows would be [0,5000), [5000,3500) (inverted!), [3500,8000) + // (overlapping the first). The monotonic cursor fixes both. + const windows = clampedTurnWindows([5000, 3500, 8000]); + expect(windows).toEqual([ + { turnStartMs: 0, turnEndMs: 5000 }, + { turnStartMs: 5000, turnEndMs: 5000 }, // empty — fully barged over + { turnStartMs: 5000, turnEndMs: 8000 }, + ]); + // A call at offset 4200 (fired during agent turn 0) lands in exactly ONE + // window — turn 0 — not also turn 2 as the raw overlap would allow. + const hits = windows.filter((w) => offsetInTurnWindow(4200, w)); + expect(hits).toEqual([{ turnStartMs: 0, turnEndMs: 5000 }]); + }); + + it("every offset belongs to exactly one clamped window", () => { + const windows = clampedTurnWindows([5000, 3500, 8000]); + for (const offset of [0, 4200, 4999, 5000, 6000, 7999]) { + expect(windows.filter((w) => offsetInTurnWindow(offset, w)).length).toBe(1); + } + }); + + it("returns [] for no turns", () => { + expect(clampedTurnWindows([])).toEqual([]); + }); +}); + +describe("rowsInTurnWindow", () => { + const rows = [ + { id: "prep-t2", startedAt: "2026-05-26T14:31:35.023Z" }, // offset 4000 → T1 + { id: "voice-t2", startedAt: "2026-05-26T14:31:37.265Z" }, // offset 6242 → T2 + { id: "no-ts", startedAt: null }, + ]; + + it("selects only rows whose offset lands in the window", () => { + expect(rowsInTurnWindow(rows, T2, RECORDING_T0).map((r) => r.id)).toEqual(["voice-t2"]); + expect(rowsInTurnWindow(rows, T1, RECORDING_T0).map((r) => r.id)).toEqual(["prep-t2"]); + }); + + it("flags a mistimed call: with the correct origin a 4000ms call is NOT in the agent turn T2", () => { + // This is the regression. With the buggy origin (ROW_CREATION) the same + // row maps to offset 6335 and would be wrongly counted into T2. + expect(rowsInTurnWindow(rows, T2, RECORDING_T0).map((r) => r.id)).not.toContain("prep-t2"); + expect(rowsInTurnWindow(rows, T2, ROW_CREATION).map((r) => r.id)).toContain("prep-t2"); + }); + + it("drops every row when there is no recording anchor", () => { + expect(rowsInTurnWindow(rows, T2, null)).toEqual([]); + }); +}); diff --git a/src/server/replays/timeline.ts b/src/server/replays/timeline.ts new file mode 100644 index 0000000..318f429 --- /dev/null +++ b/src/server/replays/timeline.ts @@ -0,0 +1,112 @@ +/** + * Audio-timeline coordinate mapping. The single place that converts a span's + * wall-clock `started_at` into an offset on the audio timeline (ms from the + * recording's t=0), and decides which turn's window an offset falls in. + * + * See `docs/specs/0001-timeline-clock-alignment.md`. The origin is ALWAYS + * `replays.recording_started_at` (the driver's audio sample-0 wall-clock) — + * never `replays.started_at`, which is row-creation time and precedes the + * recording by the room-connect + agent-join latency. + */ + +/** + * Offset of a wall-clock ISO timestamp on the audio timeline, in ms from the + * recording's t=0. + * + * Returns `null` when either input is missing or unparseable — callers MUST + * treat `null` as "cannot place this span" and skip attribution, NOT fall back + * to a different origin. + */ +export function audioOffsetMs( + startedAtIso: string | null, + recordingStartedAtIso: string | null, +): number | null { + if (recordingStartedAtIso === null) return null; + const origin = Date.parse(recordingStartedAtIso); + if (!Number.isFinite(origin)) return null; + return offsetFromOriginMs(startedAtIso, origin); +} + +/** + * Offset of a wall-clock ISO timestamp from a pre-parsed origin (epoch ms), or + * null if `startedAtIso` is missing/unparseable. Lets a read path that places + * many rows against one replay's origin parse that origin once instead of + * re-parsing the same string per row. + */ +export function offsetFromOriginMs( + startedAtIso: string | null, + originMs: number | null, +): number | null { + if (startedAtIso === null || originMs === null) return null; + const start = Date.parse(startedAtIso); + if (!Number.isFinite(start)) return null; + return start - originMs; +} + +/** + * An attribution window on the audio timeline: the half-open ms range a turn + * owns for span/tool/model membership. NOT the same as a turn's display extent + * (`turn_start_ms`/`turn_end_ms`), which may overlap a neighbour visually — see + * `clampedTurnWindows` for why attribution windows must tile while display + * bars need not. + */ +export interface TurnWindow { + readonly turnStartMs: number; + readonly turnEndMs: number; +} + +/** True iff `offsetMs` falls in `[turnStartMs, turnEndMs)`. */ +export function offsetInTurnWindow(offsetMs: number, turn: TurnWindow): boolean { + return offsetMs >= turn.turnStartMs && offsetMs < turn.turnEndMs; +} + +/** + * Build the tiling attribution windows for a replay's turns, in `idx` order, + * from each turn's `voiceEndMs`. + * + * The naive rule "turnStartMs = previous turn's voiceEndMs, turnEndMs = this + * turn's voiceEndMs" tiles cleanly ONLY when VAD turns strictly interleave. Per + * channel VAD plus barge-in (overlapping user/agent speech — the case the + * `interrupted` metric flags) produces non-monotonic `voiceEndMs`, which makes + * raw windows invert (`start > end`) or overlap, so one tool call lands in two + * turns and a fully-barged-over turn gets a window that can never match. + * + * A monotonic cursor fixes both: each window starts where the previous ended + * and ends at `max(cursor, voiceEndMs)`. An interrupted turn collapses to an + * empty `[c, c)` window (no rows attributed — correct, it was talked over) and + * the overlap region goes to the earlier turn (the ownership the deleted stored + * `turn_idx` backfill gave it). The result always tiles: every offset falls in + * exactly one window. Shared by the server evaluator and the client trace tree + * so attribution can never diverge between them. + */ +export function clampedTurnWindows(turnEndsMs: readonly number[]): TurnWindow[] { + const windows: TurnWindow[] = []; + let cursor = 0; + for (const end of turnEndsMs) { + const turnEndMs = Math.max(cursor, end); + windows.push({ turnStartMs: cursor, turnEndMs }); + cursor = turnEndMs; + } + return windows; +} + +/** + * The subset of `rows` whose `started_at` maps to an offset inside the turn's + * window. Used by the assertion evaluator to build a turn's tool/model context + * at eval time (replacing the deleted stored `turn_idx`). + * + * A row with no `started_at`, or when `recordingStartedAtIso` is null, is + * dropped — it cannot be placed on the timeline. The caller distinguishes + * "no anchor at all" (→ errored assertion) from "anchor present, row simply + * out of window" (→ failed assertion); this function only does geometry. + */ +export function rowsInTurnWindow( + rows: readonly T[], + turn: TurnWindow, + recordingStartedAtIso: string | null, +): T[] { + return rows.filter((row) => { + const offset = audioOffsetMs(row.startedAt, recordingStartedAtIso); + return offset !== null && offsetInTurnWindow(offset, turn); + }); +} diff --git a/src/server/replays/turn-metrics.test.ts b/src/server/replays/turn-metrics.test.ts index 6540ee0..4dd7ab4 100644 --- a/src/server/replays/turn-metrics.test.ts +++ b/src/server/replays/turn-metrics.test.ts @@ -12,14 +12,12 @@ describe("projectTurnMetrics", () => { { turnIdx: 1, agentResponseMs: 300, - ttftMs: 90, interrupted: true, interruptionStartMs: 1200, }, { turnIdx: 0, agentResponseMs: null, - ttftMs: null, interrupted: false, interruptionStartMs: null, }, @@ -30,7 +28,6 @@ describe("projectTurnMetrics", () => { turn_idx: 1, role: "agent", agent_response_ms: 300, - ttft_ms: 90, interrupted: true, interruption_start_ms: 1200, }); @@ -43,7 +40,6 @@ describe("projectTurnMetrics", () => { turn_idx: 0, role: "agent", agent_response_ms: null, - ttft_ms: null, interrupted: false, interruption_start_ms: null, }, diff --git a/src/server/replays/turn-metrics.ts b/src/server/replays/turn-metrics.ts index 850f24f..049271f 100644 --- a/src/server/replays/turn-metrics.ts +++ b/src/server/replays/turn-metrics.ts @@ -10,7 +10,6 @@ interface TurnLike { interface TurnMetricLike { readonly turnIdx: number; readonly agentResponseMs: number | null; - readonly ttftMs: number | null; readonly interrupted: boolean; readonly interruptionStartMs: number | null; } @@ -45,7 +44,6 @@ export function projectTurnMetrics( turn_idx: turn.idx, role: turn.role, agent_response_ms: m?.agentResponseMs ?? null, - ttft_ms: m?.ttftMs ?? null, interrupted: m?.interrupted ?? false, interruption_start_ms: m?.interruptionStartMs ?? null, }; diff --git a/src/server/store/migrations/0002_slim_master_chief.sql b/src/server/store/migrations/0002_slim_master_chief.sql new file mode 100644 index 0000000..e1275eb --- /dev/null +++ b/src/server/store/migrations/0002_slim_master_chief.sql @@ -0,0 +1,5 @@ +ALTER TABLE `model_usage` ADD `ttft_ms` integer;--> statement-breakpoint +ALTER TABLE `model_usage` DROP COLUMN `turn_idx`;--> statement-breakpoint +ALTER TABLE `replays` ADD `recording_started_at` text;--> statement-breakpoint +ALTER TABLE `replay_metrics` DROP COLUMN `ttft_ms`;--> statement-breakpoint +ALTER TABLE `tool_calls` DROP COLUMN `turn_idx`; \ No newline at end of file diff --git a/src/server/store/migrations/meta/0002_snapshot.json b/src/server/store/migrations/meta/0002_snapshot.json new file mode 100644 index 0000000..9ebcf1f --- /dev/null +++ b/src/server/store/migrations/meta/0002_snapshot.json @@ -0,0 +1,1226 @@ +{ + "version": "6", + "dialect": "sqlite", + "id": "114db5ae-a1af-4f49-8f47-b2a6728f787f", + "prevId": "cf3a83d4-c9c9-4a2e-b104-4cc2119e5f99", + "tables": { + "assertion_results": { + "name": "assertion_results", + "columns": { + "id": { + "name": "id", + "type": "integer", + "primaryKey": true, + "notNull": true, + "autoincrement": true + }, + "replay_id": { + "name": "replay_id", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "turn_idx": { + "name": "turn_idx", + "type": "integer", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "assertion_idx": { + "name": "assertion_idx", + "type": "integer", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "kind": { + "name": "kind", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "params_json": { + "name": "params_json", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "status": { + "name": "status", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "message": { + "name": "message", + "type": "text", + "primaryKey": false, + "notNull": false, + "autoincrement": false + }, + "evaluated_at": { + "name": "evaluated_at", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + } + }, + "indexes": { + "idx_assertion_results_replay_turn": { + "name": "idx_assertion_results_replay_turn", + "columns": [ + "replay_id", + "turn_idx" + ], + "isUnique": false + }, + "uq_assertion_results_replay_turn_idx": { + "name": "uq_assertion_results_replay_turn_idx", + "columns": [ + "replay_id", + "turn_idx", + "assertion_idx" + ], + "isUnique": true + } + }, + "foreignKeys": { + "assertion_results_replay_id_replays_id_fk": { + "name": "assertion_results_replay_id_replays_id_fk", + "tableFrom": "assertion_results", + "tableTo": "replays", + "columnsFrom": [ + "replay_id" + ], + "columnsTo": [ + "id" + ], + "onDelete": "cascade", + "onUpdate": "no action" + } + }, + "compositePrimaryKeys": {}, + "uniqueConstraints": {}, + "checkConstraints": { + "assertion_results_status_ck": { + "name": "assertion_results_status_ck", + "value": "\"assertion_results\".\"status\" IN ('passed', 'failed', 'errored')" + } + } + }, + "conversations": { + "name": "conversations", + "columns": { + "hash": { + "name": "hash", + "type": "text", + "primaryKey": true, + "notNull": true, + "autoincrement": false + }, + "name": { + "name": "name", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "turns_json": { + "name": "turns_json", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "created_at": { + "name": "created_at", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "last_run_at": { + "name": "last_run_at", + "type": "text", + "primaryKey": false, + "notNull": false, + "autoincrement": false + } + }, + "indexes": { + "idx_conversations_last_run_at": { + "name": "idx_conversations_last_run_at", + "columns": [ + "last_run_at" + ], + "isUnique": false + } + }, + "foreignKeys": {}, + "compositePrimaryKeys": {}, + "uniqueConstraints": {}, + "checkConstraints": { + "conversations_hash_ck": { + "name": "conversations_hash_ck", + "value": "length(\"conversations\".\"hash\") = 64" + } + } + }, + "judge_results": { + "name": "judge_results", + "columns": { + "id": { + "name": "id", + "type": "integer", + "primaryKey": true, + "notNull": true, + "autoincrement": true + }, + "replay_id": { + "name": "replay_id", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "judge_idx": { + "name": "judge_idx", + "type": "integer", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "kind": { + "name": "kind", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "params_json": { + "name": "params_json", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "status": { + "name": "status", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "score": { + "name": "score", + "type": "integer", + "primaryKey": false, + "notNull": false, + "autoincrement": false + }, + "reason": { + "name": "reason", + "type": "text", + "primaryKey": false, + "notNull": false, + "autoincrement": false + }, + "provider": { + "name": "provider", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "model": { + "name": "model", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "evaluated_at": { + "name": "evaluated_at", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + } + }, + "indexes": { + "idx_judge_results_replay": { + "name": "idx_judge_results_replay", + "columns": [ + "replay_id" + ], + "isUnique": false + }, + "uq_judge_results_replay_judge_idx": { + "name": "uq_judge_results_replay_judge_idx", + "columns": [ + "replay_id", + "judge_idx" + ], + "isUnique": true + } + }, + "foreignKeys": { + "judge_results_replay_id_replays_id_fk": { + "name": "judge_results_replay_id_replays_id_fk", + "tableFrom": "judge_results", + "tableTo": "replays", + "columnsFrom": [ + "replay_id" + ], + "columnsTo": [ + "id" + ], + "onDelete": "cascade", + "onUpdate": "no action" + } + }, + "compositePrimaryKeys": {}, + "uniqueConstraints": {}, + "checkConstraints": { + "judge_results_status_ck": { + "name": "judge_results_status_ck", + "value": "\"judge_results\".\"status\" IN ('passed', 'failed', 'errored')" + }, + "judge_results_score_ck": { + "name": "judge_results_score_ck", + "value": "\"judge_results\".\"score\" IS NULL OR (\"judge_results\".\"score\" >= 0 AND \"judge_results\".\"score\" <= 100)" + } + } + }, + "model_usage": { + "name": "model_usage", + "columns": { + "id": { + "name": "id", + "type": "integer", + "primaryKey": true, + "notNull": true, + "autoincrement": true + }, + "replay_id": { + "name": "replay_id", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "span_id": { + "name": "span_id", + "type": "text", + "primaryKey": false, + "notNull": false, + "autoincrement": false + }, + "provider": { + "name": "provider", + "type": "text", + "primaryKey": false, + "notNull": false, + "autoincrement": false + }, + "model": { + "name": "model", + "type": "text", + "primaryKey": false, + "notNull": false, + "autoincrement": false + }, + "input_tokens": { + "name": "input_tokens", + "type": "integer", + "primaryKey": false, + "notNull": false, + "autoincrement": false + }, + "output_tokens": { + "name": "output_tokens", + "type": "integer", + "primaryKey": false, + "notNull": false, + "autoincrement": false + }, + "total_tokens": { + "name": "total_tokens", + "type": "integer", + "primaryKey": false, + "notNull": false, + "autoincrement": false + }, + "ttft_ms": { + "name": "ttft_ms", + "type": "integer", + "primaryKey": false, + "notNull": false, + "autoincrement": false + }, + "started_at": { + "name": "started_at", + "type": "text", + "primaryKey": false, + "notNull": false, + "autoincrement": false + }, + "ended_at": { + "name": "ended_at", + "type": "text", + "primaryKey": false, + "notNull": false, + "autoincrement": false + }, + "latency_ms": { + "name": "latency_ms", + "type": "integer", + "primaryKey": false, + "notNull": false, + "autoincrement": false + } + }, + "indexes": { + "idx_model_usage_replay": { + "name": "idx_model_usage_replay", + "columns": [ + "replay_id", + "started_at" + ], + "isUnique": false + } + }, + "foreignKeys": { + "model_usage_replay_id_replays_id_fk": { + "name": "model_usage_replay_id_replays_id_fk", + "tableFrom": "model_usage", + "tableTo": "replays", + "columnsFrom": [ + "replay_id" + ], + "columnsTo": [ + "id" + ], + "onDelete": "cascade", + "onUpdate": "no action" + } + }, + "compositePrimaryKeys": {}, + "uniqueConstraints": {}, + "checkConstraints": {} + }, + "replay_evaluations": { + "name": "replay_evaluations", + "columns": { + "replay_id": { + "name": "replay_id", + "type": "text", + "primaryKey": true, + "notNull": true, + "autoincrement": false + }, + "passed": { + "name": "passed", + "type": "integer", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "assertions_total": { + "name": "assertions_total", + "type": "integer", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "assertions_passed": { + "name": "assertions_passed", + "type": "integer", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "judges_total": { + "name": "judges_total", + "type": "integer", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "judges_passed": { + "name": "judges_passed", + "type": "integer", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "evaluated_at": { + "name": "evaluated_at", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + } + }, + "indexes": {}, + "foreignKeys": { + "replay_evaluations_replay_id_replays_id_fk": { + "name": "replay_evaluations_replay_id_replays_id_fk", + "tableFrom": "replay_evaluations", + "tableTo": "replays", + "columnsFrom": [ + "replay_id" + ], + "columnsTo": [ + "id" + ], + "onDelete": "cascade", + "onUpdate": "no action" + } + }, + "compositePrimaryKeys": {}, + "uniqueConstraints": {}, + "checkConstraints": {} + }, + "replay_metrics": { + "name": "replay_metrics", + "columns": { + "replay_id": { + "name": "replay_id", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "turn_idx": { + "name": "turn_idx", + "type": "integer", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "agent_response_ms": { + "name": "agent_response_ms", + "type": "integer", + "primaryKey": false, + "notNull": false, + "autoincrement": false + }, + "interrupted": { + "name": "interrupted", + "type": "integer", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "interruption_start_ms": { + "name": "interruption_start_ms", + "type": "integer", + "primaryKey": false, + "notNull": false, + "autoincrement": false + } + }, + "indexes": {}, + "foreignKeys": { + "replay_metrics_replay_id_replays_id_fk": { + "name": "replay_metrics_replay_id_replays_id_fk", + "tableFrom": "replay_metrics", + "tableTo": "replays", + "columnsFrom": [ + "replay_id" + ], + "columnsTo": [ + "id" + ], + "onDelete": "cascade", + "onUpdate": "no action" + } + }, + "compositePrimaryKeys": { + "replay_metrics_pk": { + "columns": [ + "replay_id", + "turn_idx" + ], + "name": "replay_metrics_pk" + } + }, + "uniqueConstraints": {}, + "checkConstraints": {} + }, + "replay_turns": { + "name": "replay_turns", + "columns": { + "replay_id": { + "name": "replay_id", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "idx": { + "name": "idx", + "type": "integer", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "role": { + "name": "role", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "turn_start_ms": { + "name": "turn_start_ms", + "type": "integer", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "turn_end_ms": { + "name": "turn_end_ms", + "type": "integer", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "voice_start_ms": { + "name": "voice_start_ms", + "type": "integer", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "voice_end_ms": { + "name": "voice_end_ms", + "type": "integer", + "primaryKey": false, + "notNull": true, + "autoincrement": false + } + }, + "indexes": {}, + "foreignKeys": { + "replay_turns_replay_id_replays_id_fk": { + "name": "replay_turns_replay_id_replays_id_fk", + "tableFrom": "replay_turns", + "tableTo": "replays", + "columnsFrom": [ + "replay_id" + ], + "columnsTo": [ + "id" + ], + "onDelete": "cascade", + "onUpdate": "no action" + } + }, + "compositePrimaryKeys": { + "replay_turns_pk": { + "columns": [ + "replay_id", + "idx" + ], + "name": "replay_turns_pk" + } + }, + "uniqueConstraints": {}, + "checkConstraints": { + "replay_turns_role_ck": { + "name": "replay_turns_role_ck", + "value": "\"replay_turns\".\"role\" IN ('user', 'agent')" + } + } + }, + "replays": { + "name": "replays", + "columns": { + "id": { + "name": "id", + "type": "text", + "primaryKey": true, + "notNull": true, + "autoincrement": false + }, + "conversation_hash": { + "name": "conversation_hash", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "lifecycle_state": { + "name": "lifecycle_state", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "analysis_step": { + "name": "analysis_step", + "type": "text", + "primaryKey": false, + "notNull": false, + "autoincrement": false + }, + "failure_reason": { + "name": "failure_reason", + "type": "text", + "primaryKey": false, + "notNull": false, + "autoincrement": false + }, + "started_at": { + "name": "started_at", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "finished_at": { + "name": "finished_at", + "type": "text", + "primaryKey": false, + "notNull": false, + "autoincrement": false + }, + "recording_started_at": { + "name": "recording_started_at", + "type": "text", + "primaryKey": false, + "notNull": false, + "autoincrement": false + }, + "audio_path": { + "name": "audio_path", + "type": "text", + "primaryKey": false, + "notNull": false, + "autoincrement": false + }, + "run_config_json": { + "name": "run_config_json", + "type": "text", + "primaryKey": false, + "notNull": false, + "autoincrement": false + }, + "job_id": { + "name": "job_id", + "type": "text", + "primaryKey": false, + "notNull": false, + "autoincrement": false + } + }, + "indexes": { + "idx_replays_conversation_hash": { + "name": "idx_replays_conversation_hash", + "columns": [ + "conversation_hash", + "started_at" + ], + "isUnique": false + }, + "idx_replays_started_at": { + "name": "idx_replays_started_at", + "columns": [ + "started_at" + ], + "isUnique": false + } + }, + "foreignKeys": { + "replays_conversation_hash_conversations_hash_fk": { + "name": "replays_conversation_hash_conversations_hash_fk", + "tableFrom": "replays", + "tableTo": "conversations", + "columnsFrom": [ + "conversation_hash" + ], + "columnsTo": [ + "hash" + ], + "onDelete": "restrict", + "onUpdate": "no action" + } + }, + "compositePrimaryKeys": {}, + "uniqueConstraints": {}, + "checkConstraints": { + "replays_lifecycle_state_ck": { + "name": "replays_lifecycle_state_ck", + "value": "\"replays\".\"lifecycle_state\" IN ('pending', 'running', 'recording_uploaded', 'analyzing', 'completed', 'failed')" + }, + "replays_analysis_step_ck": { + "name": "replays_analysis_step_ck", + "value": "\"replays\".\"analysis_step\" IS NULL OR \"replays\".\"analysis_step\" IN ('vad', 'transcribe', 'metrics', 'evaluate')" + }, + "replays_failure_reason_ck": { + "name": "replays_failure_reason_ck", + "value": "\"replays\".\"failure_reason\" IS NULL OR \"replays\".\"failure_reason\" IN ('stalled', 'timeout', 'explicit_fail', 'max_attempts_exceeded', 'worker_lost', 'upload_failed', 'driver_aborted', 'agent_not_joined', 'audio_missing', 'missing_credential', 'transcription_failed', 'metrics_failed', 'evaluation_failed', 'spec_vad_mismatch')" + } + } + }, + "spans": { + "name": "spans", + "columns": { + "id": { + "name": "id", + "type": "integer", + "primaryKey": true, + "notNull": true, + "autoincrement": true + }, + "replay_id": { + "name": "replay_id", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "trace_id": { + "name": "trace_id", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "span_id": { + "name": "span_id", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "parent_span_id": { + "name": "parent_span_id", + "type": "text", + "primaryKey": false, + "notNull": false, + "autoincrement": false + }, + "name": { + "name": "name", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "vocabulary": { + "name": "vocabulary", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "started_at": { + "name": "started_at", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "ended_at": { + "name": "ended_at", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "attributes_json": { + "name": "attributes_json", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + } + }, + "indexes": { + "idx_spans_replay_started": { + "name": "idx_spans_replay_started", + "columns": [ + "replay_id", + "started_at" + ], + "isUnique": false + }, + "idx_spans_trace": { + "name": "idx_spans_trace", + "columns": [ + "trace_id" + ], + "isUnique": false + }, + "spans_replay_span_uk": { + "name": "spans_replay_span_uk", + "columns": [ + "replay_id", + "span_id" + ], + "isUnique": true + } + }, + "foreignKeys": { + "spans_replay_id_replays_id_fk": { + "name": "spans_replay_id_replays_id_fk", + "tableFrom": "spans", + "tableTo": "replays", + "columnsFrom": [ + "replay_id" + ], + "columnsTo": [ + "id" + ], + "onDelete": "cascade", + "onUpdate": "no action" + } + }, + "compositePrimaryKeys": {}, + "uniqueConstraints": {}, + "checkConstraints": { + "spans_vocabulary_ck": { + "name": "spans_vocabulary_ck", + "value": "\"spans\".\"vocabulary\" IN ('xray', 'gen_ai', 'langfuse')" + } + } + }, + "speech_segments": { + "name": "speech_segments", + "columns": { + "id": { + "name": "id", + "type": "integer", + "primaryKey": true, + "notNull": true, + "autoincrement": true + }, + "replay_id": { + "name": "replay_id", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "channel": { + "name": "channel", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "start_ms": { + "name": "start_ms", + "type": "integer", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "end_ms": { + "name": "end_ms", + "type": "integer", + "primaryKey": false, + "notNull": true, + "autoincrement": false + } + }, + "indexes": { + "idx_speech_segments_replay_start": { + "name": "idx_speech_segments_replay_start", + "columns": [ + "replay_id", + "start_ms" + ], + "isUnique": false + } + }, + "foreignKeys": { + "speech_segments_replay_id_replays_id_fk": { + "name": "speech_segments_replay_id_replays_id_fk", + "tableFrom": "speech_segments", + "tableTo": "replays", + "columnsFrom": [ + "replay_id" + ], + "columnsTo": [ + "id" + ], + "onDelete": "cascade", + "onUpdate": "no action" + } + }, + "compositePrimaryKeys": {}, + "uniqueConstraints": {}, + "checkConstraints": { + "speech_segments_channel_ck": { + "name": "speech_segments_channel_ck", + "value": "\"speech_segments\".\"channel\" IN ('user', 'agent')" + } + } + }, + "tool_calls": { + "name": "tool_calls", + "columns": { + "id": { + "name": "id", + "type": "integer", + "primaryKey": true, + "notNull": true, + "autoincrement": true + }, + "replay_id": { + "name": "replay_id", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "span_id": { + "name": "span_id", + "type": "text", + "primaryKey": false, + "notNull": false, + "autoincrement": false + }, + "name": { + "name": "name", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "args_json": { + "name": "args_json", + "type": "text", + "primaryKey": false, + "notNull": false, + "autoincrement": false + }, + "result_json": { + "name": "result_json", + "type": "text", + "primaryKey": false, + "notNull": false, + "autoincrement": false + }, + "started_at": { + "name": "started_at", + "type": "text", + "primaryKey": false, + "notNull": false, + "autoincrement": false + }, + "ended_at": { + "name": "ended_at", + "type": "text", + "primaryKey": false, + "notNull": false, + "autoincrement": false + }, + "latency_ms": { + "name": "latency_ms", + "type": "integer", + "primaryKey": false, + "notNull": false, + "autoincrement": false + } + }, + "indexes": { + "idx_tool_calls_replay": { + "name": "idx_tool_calls_replay", + "columns": [ + "replay_id", + "started_at" + ], + "isUnique": false + } + }, + "foreignKeys": { + "tool_calls_replay_id_replays_id_fk": { + "name": "tool_calls_replay_id_replays_id_fk", + "tableFrom": "tool_calls", + "tableTo": "replays", + "columnsFrom": [ + "replay_id" + ], + "columnsTo": [ + "id" + ], + "onDelete": "cascade", + "onUpdate": "no action" + } + }, + "compositePrimaryKeys": {}, + "uniqueConstraints": {}, + "checkConstraints": {} + }, + "tts_synth_cache": { + "name": "tts_synth_cache", + "columns": { + "fingerprint": { + "name": "fingerprint", + "type": "text", + "primaryKey": true, + "notNull": true, + "autoincrement": false + }, + "audio_sha256": { + "name": "audio_sha256", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "provider": { + "name": "provider", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "model": { + "name": "model", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "voice": { + "name": "voice", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "created_at": { + "name": "created_at", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + } + }, + "indexes": {}, + "foreignKeys": {}, + "compositePrimaryKeys": {}, + "uniqueConstraints": {}, + "checkConstraints": { + "tts_synth_cache_fingerprint_ck": { + "name": "tts_synth_cache_fingerprint_ck", + "value": "length(\"tts_synth_cache\".\"fingerprint\") = 64" + }, + "tts_synth_cache_audio_sha256_ck": { + "name": "tts_synth_cache_audio_sha256_ck", + "value": "length(\"tts_synth_cache\".\"audio_sha256\") = 64" + } + } + }, + "turn_transcripts": { + "name": "turn_transcripts", + "columns": { + "replay_id": { + "name": "replay_id", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "turn_idx": { + "name": "turn_idx", + "type": "integer", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "text": { + "name": "text", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "language": { + "name": "language", + "type": "text", + "primaryKey": false, + "notNull": false, + "autoincrement": false + }, + "words_json": { + "name": "words_json", + "type": "text", + "primaryKey": false, + "notNull": false, + "autoincrement": false + }, + "duration_ms": { + "name": "duration_ms", + "type": "integer", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "provider": { + "name": "provider", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + }, + "model": { + "name": "model", + "type": "text", + "primaryKey": false, + "notNull": true, + "autoincrement": false + } + }, + "indexes": {}, + "foreignKeys": { + "turn_transcripts_replay_id_replays_id_fk": { + "name": "turn_transcripts_replay_id_replays_id_fk", + "tableFrom": "turn_transcripts", + "tableTo": "replays", + "columnsFrom": [ + "replay_id" + ], + "columnsTo": [ + "id" + ], + "onDelete": "cascade", + "onUpdate": "no action" + } + }, + "compositePrimaryKeys": { + "turn_transcripts_pk": { + "columns": [ + "replay_id", + "turn_idx" + ], + "name": "turn_transcripts_pk" + } + }, + "uniqueConstraints": {}, + "checkConstraints": {} + } + }, + "views": {}, + "enums": {}, + "_meta": { + "schemas": {}, + "tables": {}, + "columns": {} + }, + "internal": { + "indexes": {} + } +} \ No newline at end of file diff --git a/src/server/store/migrations/meta/_journal.json b/src/server/store/migrations/meta/_journal.json index c1b56da..d5c431b 100644 --- a/src/server/store/migrations/meta/_journal.json +++ b/src/server/store/migrations/meta/_journal.json @@ -15,6 +15,13 @@ "when": 1780499814403, "tag": "0001_fast_lightspeed", "breakpoints": true + }, + { + "idx": 2, + "version": "6", + "when": 1781126983039, + "tag": "0002_slim_master_chief", + "breakpoints": true } ] } \ No newline at end of file diff --git a/src/server/store/schema.ts b/src/server/store/schema.ts index b6e1a2c..4f94f6d 100644 --- a/src/server/store/schema.ts +++ b/src/server/store/schema.ts @@ -105,6 +105,15 @@ export const replays = sqliteTable( failureReason: text("failure_reason").$type(), startedAt: text("started_at").notNull(), finishedAt: text("finished_at"), + // Wall-clock (UTC ISO-8601) of audio sample 0 — the driver's + // `min(segment.started_at)`, sent via the `X-Recording-Started-At` + // header on POST /audio. This is the SOLE origin for mapping a span's + // wall-clock `started_at` onto the audio timeline + // (`audio_offset_ms = started_at − recording_started_at`). Null when an + // older SDK omits the header: offsets are then undefined and span→turn + // attribution is skipped rather than mis-anchored to `started_at` + // (which is row-creation time, not recording start — see spec 0001). + recordingStartedAt: text("recording_started_at"), // Path under XRAY_AUDIO_ROOT to the uploaded stereo WAV. audioPath: text("audio_path"), // Opaque dev-side snapshot of the SUT config at run start. @@ -208,7 +217,6 @@ export const toolCalls = sqliteTable( replayId: text("replay_id") .notNull() .references(() => replays.id, { onDelete: "cascade" }), - turnIdx: integer("turn_idx"), spanId: text("span_id"), name: text("name").notNull(), argsJson: text("args_json"), @@ -227,13 +235,17 @@ export const modelUsage = sqliteTable( replayId: text("replay_id") .notNull() .references(() => replays.id, { onDelete: "cascade" }), - turnIdx: integer("turn_idx"), spanId: text("span_id"), provider: text("provider"), model: text("model"), inputTokens: integer("input_tokens"), outputTokens: integer("output_tokens"), totalTokens: integer("total_tokens"), + // Model time-to-first-token (ms), from the GenAI semconv span attribute + // `gen_ai.response.time_to_first_chunk` (seconds → ms). Optional, exactly + // like the token counts: null when the agent's instrumentation doesn't + // emit it. A same-clock delta, so it needs no audio-timeline correlation. + ttftMs: integer("ttft_ms"), startedAt: text("started_at"), endedAt: text("ended_at"), latencyMs: integer("latency_ms"), @@ -265,11 +277,13 @@ export const turnTranscripts = sqliteTable( // Per-turn timing metrics. Produced by `calculate-metrics`. // // `agent_response_ms` is `voice_start_ms - prior_user_turn.voice_end_ms` for -// agent turns; null for user turns. `ttft_ms` is the gap from the agent -// turn's `voice_start_ms` back to the start of the FIRST `gen_ai.client.*` -// span attributed to this turn — null if no such span exists. -// `interrupted` is true when an opposite-channel speech segment started -// while this turn was still active. +// agent turns; null for user turns. `interrupted` is true when an +// opposite-channel speech segment started while this turn was still active. +// +// These are the audio-frame metrics — both operands of every value come from +// VAD on the same recording, so they need no cross-clock correlation. Model +// TTFT is NOT here: it's a span-level attribute on `model_usage.ttft_ms` +// (see spec 0001), surfaced on the timeline rather than aggregated per turn. export const replayMetrics = sqliteTable( "replay_metrics", { @@ -278,7 +292,6 @@ export const replayMetrics = sqliteTable( .references(() => replays.id, { onDelete: "cascade" }), turnIdx: integer("turn_idx").notNull(), agentResponseMs: integer("agent_response_ms"), - ttftMs: integer("ttft_ms"), interrupted: integer("interrupted", { mode: "boolean" }).notNull(), interruptionStartMs: integer("interruption_start_ms"), }, diff --git a/src/server/store/store.test.ts b/src/server/store/store.test.ts index 2ba06de..ad33d35 100644 --- a/src/server/store/store.test.ts +++ b/src/server/store/store.test.ts @@ -1,4 +1,4 @@ -import { existsSync, mkdtempSync, rmSync } from "node:fs"; +import { existsSync, mkdtempSync, readFileSync, rmSync } from "node:fs"; import { tmpdir } from "node:os"; import { join } from "node:path"; @@ -200,3 +200,57 @@ describe("openStoreFromEnv", () => { second.close(); }); }); + +describe("migration 0002 — slim_master_chief (populated-DB upgrade)", () => { + const migrationSql = (file: string) => + readFileSync(new URL(`./migrations/${file}`, import.meta.url).pathname, "utf8"); + + function columnNames(db: Database, table: string): string[] { + return db + .query<{ name: string }, []>(`PRAGMA table_info(${table})`) + .all() + .map((r) => r.name); + } + + it("drops turn_idx / replay_metrics.ttft_ms and adds model_usage.ttft_ms + recording_started_at while preserving existing rows", () => { + const db = new Database(":memory:"); + // FK off: we seed leaf rows without a parent `replays` row — the test is + // about the ALTER TABLE structural change, not referential integrity. + db.exec("PRAGMA foreign_keys = OFF"); + db.exec(migrationSql("0000_init.sql")); + db.exec(migrationSql("0001_fast_lightspeed.sql")); + + // Seed old-shape rows: tool/model rows carrying the soon-to-be-dropped + // turn_idx, and a replay_metrics row carrying the soon-to-be-dropped + // ttft_ms. + db.exec("INSERT INTO tool_calls (replay_id, turn_idx, name) VALUES ('r1', 3, 'lookup')"); + db.exec("INSERT INTO model_usage (replay_id, turn_idx, provider) VALUES ('r1', 2, 'openai')"); + db.exec( + "INSERT INTO replay_metrics (replay_id, turn_idx, ttft_ms, interrupted) VALUES ('r1', 0, 500, 0)", + ); + + // The destructive upgrade. + db.exec(migrationSql("0002_slim_master_chief.sql")); + + expect(columnNames(db, "tool_calls")).not.toContain("turn_idx"); + expect(columnNames(db, "model_usage")).not.toContain("turn_idx"); + expect(columnNames(db, "model_usage")).toContain("ttft_ms"); + expect(columnNames(db, "replay_metrics")).not.toContain("ttft_ms"); + expect(columnNames(db, "replays")).toContain("recording_started_at"); + + // Surviving columns keep their data; the new nullable columns default to null. + const tool = db + .query<{ name: string }, []>("SELECT name FROM tool_calls WHERE replay_id = 'r1'") + .get(); + expect(tool?.name).toBe("lookup"); + const usage = db + .query<{ provider: string; ttft_ms: number | null }, []>( + "SELECT provider, ttft_ms FROM model_usage WHERE replay_id = 'r1'", + ) + .get(); + expect(usage?.provider).toBe("openai"); + expect(usage?.ttft_ms).toBeNull(); + + db.close(); + }); +});