From b28da2f2d6229725f34e46adf93f5dfd83fa7786 Mon Sep 17 00:00:00 2001 From: Jim Huang Date: Mon, 2 Nov 2026 16:17:18 +0800 Subject: [PATCH 1/4] Validate named observational audio fixtures Turn-taking replay needs a reproducible input identity before a browser or socket run can distinguish provider behavior from a malformed clip. The existing interruption smoke and fixed speech probes do not provide that shared contract. Define one named synthetic clip with exact-byte digests, transport-specific audio, fresh scenario gates and a bounded post-playback observation window. Reject ambiguous JSON, incompatible audio, container headers, unsafe file references and inputs beyond the byte or duration limits before transport access. Resumed-pause fixtures must contain an annotated quiet interval with signal on both sides. Document the existing entry points and the clock correlation, durable evidence and budget requirements the adapters must satisfy, without changing the current barge smoke or any Gemini endpointing, interruption, recovery or scoring behavior. Fourteen offline tests exercise the loader, CLI, file races, audio and pause boundaries. Twelve guard-removal mutants fail in an isolated copy. The full gate and final portable/browser lanes pass, including 2683 browser tests with no skips. Native desktop checks and cargo-deny remain unverified because required libraries or tools are unavailable. The fixtures prove input mechanics; browser/socket replay, provider outcome judgment and live stability acceptance remain separate work. Change-Id: Ia773182cf969d40955be4953b4acbf10eb07cfcd --- docs/observational-replay.md | 192 +++++++++++ docs/turn-timing.md | 3 + scripts/replay-fixture.cjs | 278 ++++++++++++++++ tests/browser/replay-fixture.test.js | 470 +++++++++++++++++++++++++++ 4 files changed, 943 insertions(+) create mode 100644 docs/observational-replay.md create mode 100644 scripts/replay-fixture.cjs create mode 100644 tests/browser/replay-fixture.test.js diff --git a/docs/observational-replay.md b/docs/observational-replay.md new file mode 100644 index 000000000..84f446848 --- /dev/null +++ b/docs/observational-replay.md @@ -0,0 +1,192 @@ +# Observational audio replay + +A named fixture identifies synthetic audio and the scenario it is meant to +exercise. It is an observation input, never an instruction to change Gemini's +endpointing, interruption, hint, recovery or scoring policy. The +[provider floor contract](turn-timing.md#provider-floor-observations) defines +what a provider observation means. Neither a PCM level nor transcript text +establishes provider activity or physical audibility. + +The offline loader is implemented. The browser and socket observational +adapters and trial judge described below are implementation requirements, not +claims of working live replay. The existing `barge` browser smoke is separate: +it still requires Speaking followed by a measured interrupted overlap. + +## Existing entry points and missing observations + +| Entry point | Observable today | Replay work required | +| --- | --- | --- | +| `scripts/barge-replay.cjs` | Page `#agent-state` text, microphone acquisition, decoded sample rate, duration and monotonic injection time; state rechecked after decoding/resume | Preserve this smoke; a separate named replay must support outcomes other than interruption and bound the gate wait. | +| `scripts/browser-check.cjs` | Room identity, Rust agent streams before tail trimming, capture JSON | Retain full-run latency alongside floor records and correlate each trial to the provider clock/record opening, not emission order. | +| `scripts/floor-capture.cjs` and its shell follower | Complete floor lines, including session/socket/sequence, retained beyond server cleanup | Reuse this writer. A highest *emitted* sequence is not an opening watermark. | +| `src/livekit/session.rs` tool response diagnostics | Allowlisted tool name, accepted response and separately the latency record's send outcome | Hint/tool gates need fresh accepted-and-sent evidence and invalidation at the reply/socket boundary. A caption, old hint count or accepted-but-unsent response cannot open a gate. | +| `tests/unit/livekit/cost.rs` spoken probes | Fixed restatement/question PCM, provider events and tool responses, streamed concurrently in 40 ms chunks | Add named input and a gated driver; these probes do not currently feed the production floor recorder or retain full-run latency. | +| `src/livekit/session.rs` / `src/livekit/floor.rs` | Provider activity mapped through room eligibility checks to floor observations | A direct socket driver must preserve this eligibility/mapping or label its evidence as harness-mapped, never as room/LiveKit acceptance. | + +## Fixture version 1 + +One manifest describes one clip and one attempted injection. It is UTF-8 JSON +of at most 16,384 bytes. Every listed field is required; duplicate keys, unknown fields, invalid +types and unsupported versions are refused. Audio is a regular file beside the +manifest, named by a single filename (1–128 ASCII letters, digits, `.`, `_` or +`-`, starting with a letter or digit). No paths or symlinks. The manifest must +also be a regular file, not a symlink. + +```json +{ + "version": 1, + "id": "short-backchannel", + "origin": "synthetic-speech", + "audio": { + "file": "short-backchannel.wav", + "sha256": "0000000000000000000000000000000000000000000000000000000000000000", + "format": "wav_pcm_s16le", + "sample_rate_hz": 48000, + "channels": 1, + "pause": null + }, + "gate": { + "state": "speaking", + "tool": null, + "timeout_ms": 30000, + "max_age_ms": 250 + }, + "observation_ms": 10000, + "expected": { "kind": "overlap", "outcome": "continued" } +} +``` + +Replace the placeholder digest with the lowercase SHA-256 of the complete audio +file's exact bytes, including a WAV header. `id` is 1–64 lowercase ASCII letters, +digits or hyphens, starting with a letter. `origin` is `synthetic-speech` or +`synthetic-tone`: consenting team speech/TTS or deterministic tone fixtures, +never candidate recordings. A tone can test transport mechanics locally; it +cannot establish a provider's speech, backchannel or interruption behavior. +Do not include transcript, credentials or candidate identity in a manifest. + +`audio.format` selects the transport and exact format: + +| Transport | Format | Sample rate | Limits | +| --- | --- | --- | --- | +| Browser | `wav_pcm_s16le` | 48,000 Hz, mono, signed 16-bit little-endian PCM in RIFF/WAVE | Positive duration up to 30 s; at most 2,945,536 file bytes (30 s plus 64 KiB for headers/chunks). | +| Direct socket | `pcm_s16le` | 16,000 Hz, mono, headerless signed 16-bit little-endian PCM | Positive duration up to 30 s; at most 960,000 bytes; whole 2-byte frames. | + +WAV must contain exactly one `fmt ` and one `data` chunk, consistent file/chunk +lengths, PCM tag 1, 16 bits, block alignment 2 and byte rate 96,000. Ancillary +RIFF chunks are permitted within the file cap. Known RIFF/RIFX/RF64/WAVE, +FORM (AIFF), OggS, fLaC and ID3 prefixes are refused +on the raw path. This is not a universal container detector: headerless PCM has +no self-describing rate/channel/endianness metadata, so its declared provenance +and any unrecognized encoding must be checked by the fixture author. +The loader verifies the digest and byte structure before any provider access. +The browser adapter must also retain the decoded buffer's actual rate/duration. +Socket streaming uses 1,280-byte / 40 ms chunks; a final partial chunk retains +all its whole frames without padding or dropping samples. Any transport-added +silence and its duration must be explicit in the trial artifact. + +## Gate and observation windows + +`gate.state` is `speaking`, `listening`, `hint` or `tool`. +Speaking/listening use `tool: null`; hint requires `tool: "log_hint"`; tool +requires a lowercase ASCII tool identifier, at most 64 characters, starting +with a letter. The identifier names the required event; spelling a name in a +manifest does not establish that it exists or was observed. + +A gate describes where to attempt injection, not a guarantee of the expected +provider outcome. For example, a listening gate does not establish an overlap; +the judge must require an actual aligned overlap record and cannot pass on the +gate alone. Disagreements between required scenario and observed injection +state are excluded; missing provider activity is unknown. + +`timeout_ms` bounds waiting for the gate, 1–120,000 ms. `max_age_ms` is +1–5,000 ms and no greater than `timeout_ms`; it bounds the age of the last +qualifying state observation at injection. Decode audio before the final gate +check. Recheck after every asynchronous step before injection, including audio +resume and budget admission. Expire hint/tool eligibility at any boundary or +replacement that invalidates it. Retain the observed state and its source, +clock, age and session/socket identity. Browser text alone supports only its +actual speaking/listening indication; an adapter without a trustworthy hint or +tool observable must refuse with `unsupported_gate`, not treat it as Speaking. +The full replay implementation must supply these observables for both paths. + +`observation_ms` is 1–120,000 ms of observation **after the final audio frame is +injected**. It is independent of the preceding gate timeout. Its end bounds +which provider events can determine an outcome, not when a delayed floor line +arrives. Include the injection and any internal pause in the evidence window. +After the window, finalize and drain retained evidence; never inject a follow-up +that could turn an unresolved observation into a successful trial. A teardown +may flush a previously resolved pause. A response first occurring after the +window cannot pass merely because its record arrived during finalization. + +Allowed expected pairs are: + +| Kind | Outcome | Scenario | +| --- | --- | --- | +| `overlap` | `continued` | Candidate backchannel during output; generation completes and playout estimate drains without interruption. | +| `overlap` | `interrupted` | Provider interruption or an eligible local stale-playout drop resolves an observed overlap. | +| `pause` | `respond` | New generation's tool call or accepted audio resolves the candidate pause. | +| `pause` | `continue` | A new candidate START resumes after the clip's internal pause before a new interviewer response. | + +For `pause/continue`, `audio.pause` is an object with integer `start_ms` and +`end_ms`: a nonempty interval strictly inside the clip. Integer milliseconds at the +allowed rates are always frame-aligned. Samples +in that interval must have absolute amplitude at most 500, with signal above +500 both before and after it. All other scenarios use `pause: null`. This +annotation makes a resumed-pause input possible; it is not evidence Gemini +emitted either activity signal. Human labels belong to the separately frozen +corpus. These four pairs are expected outcomes; an observed `unresolved` is +incomplete evidence, never a fifth passing outcome. + +## Trial identity, evidence and verdict requirements + +An emitted floor line cannot be joined to an injection by file position, max +emitted `seq`, or the floor line's `at` (coarse emission clock). Records open +before they emit, and can emit out of sequence. The adapters must establish an +opening watermark or explicit trial-to-provider-event join before injection, +with room/session/socket identity. Until that join and an event-window clock +mapping exist, a record is ambiguous and cannot pass. A socket replacement +invalidates trial alignment. Start with one fixture attempt per fresh session; +multiple trials require proof no pending observation can leak between them. + +Retain, before trimming any diagnostic tail: + +- Manifest and clip digests, fixture ID, executable commit/digest, model/config + identity and contract tuple; no secrets or transcript. +- Gate wait start, selected/observed state, evidence source, observation time, + injection start/end and their monotonic clock identities; actual audio format + and transport-added silence. +- Full-run floor and latency artifacts with room/session/socket identities, + record opening/settlement window evidence and finalization/drain status. A + rolling `latencyLog` tail is insufficient. Missing logs stay missing. +- Verdict and reason; aggregate `trials_started`, `injected`, `scored`, + `excluded`, `unknown`, `passed` and `failed` counts, with exclusion reasons. + Misaligned/failed trials still consume the configured run budget. + +Verdict precedence: an invalid fixture refuses before connecting. A gate +failure (`unsupported_gate`, `gate-timeout`, `misaligned`, `missing-microphone`, +`decode-or-resume-failed`, `unavailable`) excludes the trial. Missing, ambiguous, +truncated, unresolved or out-of-window evidence is `unknown`. Only complete, +aligned evidence can fail on a wrong outcome or pass on the expected outcome. +Every attempted trial counts; no retries erase a failure. Counts and artifacts +must survive failure, not just the successful exit path. + +Live adapters must refuse absent explicit isolated configuration and run +budgets before joining a room or connecting a socket. Their action/time/exposure +caps use the existing [run-budget controller](development.md#run-budget-for-live-validation) +where its protocol applies. Report provider usage as observed or unknown, not +as an enforced invoice ceiling. One clip/manifest is not a trial-count budget. +No live acceptance is implied by the offline validator or local doubles. + +## Offline validation + +```sh +node scripts/replay-fixture.cjs /absolute/path/manifest.json browser +node scripts/replay-fixture.cjs /absolute/path/manifest.json socket +node --test tests/browser/replay-fixture.test.js +``` + +Each validation command reads one manifest and its audio without connecting, +prints metadata and exits 0, or prints the input error and exits 2. Output +includes the manifest-byte digest, decoded frame count/duration and byte count, +not audio bytes. The tests generate deterministic WAV/PCM fixtures in temporary +directories and remove them afterward; their outcomes prove validation mechanics. diff --git a/docs/turn-timing.md b/docs/turn-timing.md index fd733db5e..71e181518 100644 --- a/docs/turn-timing.md +++ b/docs/turn-timing.md @@ -220,6 +220,9 @@ for its room in the durable file; transcript order alone cannot pass the smoke. This proves neither hint/tool-state alignment nor physical audibility. H-3/TT-2 still need separately digested WAV and headerless 16 kHz mono s16le PCM fixtures, a replay pilot and explicit exclusion counts for misaligned trials. +The [observational replay contract](observational-replay.md) defines the named +fixture format and offline validator; its transport and evidence requirements +remain prerequisites for that pilot. ## Continuity gaps diff --git a/scripts/replay-fixture.cjs b/scripts/replay-fixture.cjs new file mode 100644 index 000000000..029aefa04 --- /dev/null +++ b/scripts/replay-fixture.cjs @@ -0,0 +1,278 @@ +// Offline input validation shared by the observational replay transports. +const fs = require("node:fs"); +const path = require("node:path"); +const { TextDecoder } = require("node:util"); +const { parseWav, sha256 } = require("./long-interview-schedule.cjs"); + +const MANIFEST_BYTES = 16384; +const CLIP_MS = 30000; +const WAV_BYTES = 48000 * 2 * (CLIP_MS / 1000) + 65536; +const PCM_BYTES = 16000 * 2 * (CLIP_MS / 1000); +const PAIRS = new Set([ + "overlap/continued", + "overlap/interrupted", + "pause/respond", + "pause/continue", +]); + +function refuse(message) { + throw new Error(`replay fixture: ${message}`); +} + +function fields(value, keys, where) { + if (!value || typeof value !== "object" || Array.isArray(value)) + refuse(`${where} must be an object`); + const actual = Object.keys(value); + if ( + actual.length !== keys.length || + keys.some((key) => !Object.hasOwn(value, key)) + ) + refuse(`${where} requires exactly ${keys.join(", ")}`); +} + +function integer(value, min, max, where) { + if (!Number.isSafeInteger(value) || value < min || value > max) + refuse(`${where} must be an integer in ${min}..${max}`); +} + +function validateManifest(manifest) { + fields( + manifest, + ["version", "id", "origin", "audio", "gate", "observation_ms", "expected"], + "manifest", + ); + if (manifest.version !== 1) refuse("unsupported version"); + if ( + typeof manifest.id !== "string" || + !/^[a-z][a-z0-9-]{0,63}$/.test(manifest.id) + ) + refuse( + "id must be 1..64 lowercase letters, digits or hyphens, starting with a letter", + ); + if (!["synthetic-tone", "synthetic-speech"].includes(manifest.origin)) + refuse("origin must be synthetic-tone or synthetic-speech"); + const audio = manifest.audio; + fields( + audio, + ["file", "sha256", "format", "sample_rate_hz", "channels", "pause"], + "audio", + ); + if ( + typeof audio.file !== "string" || + !/^[a-zA-Z0-9][a-zA-Z0-9._-]{0,127}$/.test(audio.file) + ) + refuse("audio.file must be a filename beside the manifest"); + if (typeof audio.sha256 !== "string" || !/^[a-f0-9]{64}$/.test(audio.sha256)) + refuse("audio.sha256 must be 64 lowercase hex digits"); + if (!["wav_pcm_s16le", "pcm_s16le"].includes(audio.format)) + refuse("unsupported audio format"); + if (audio.channels !== 1) refuse("audio.channels must be 1"); + if ( + audio.sample_rate_hz !== (audio.format === "wav_pcm_s16le" ? 48000 : 16000) + ) + refuse("WAV must be 48000 Hz; raw PCM must be 16000 Hz"); + const gate = manifest.gate; + fields(gate, ["state", "tool", "timeout_ms", "max_age_ms"], "gate"); + if (!["speaking", "listening", "hint", "tool"].includes(gate.state)) + refuse("unsupported gate state"); + if (gate.state === "hint") { + if (gate.tool !== "log_hint") refuse("hint gate requires tool=log_hint"); + } else if (gate.state === "tool") { + if ( + typeof gate.tool !== "string" || + !/^[a-z][a-z0-9_]{0,63}$/.test(gate.tool) + ) + refuse("tool gate requires a tool name"); + } else if (gate.tool !== null) + refuse("speaking/listening gate requires tool=null"); + integer(gate.timeout_ms, 1, 120000, "gate.timeout_ms"); + integer(gate.max_age_ms, 1, 5000, "gate.max_age_ms"); + if (gate.max_age_ms > gate.timeout_ms) refuse("gate age exceeds timeout"); + integer(manifest.observation_ms, 1, 120000, "observation_ms"); + fields(manifest.expected, ["kind", "outcome"], "expected"); + if ( + typeof manifest.expected.kind !== "string" || + typeof manifest.expected.outcome !== "string" || + !PAIRS.has(`${manifest.expected.kind}/${manifest.expected.outcome}`) + ) + refuse("unsupported expected kind/outcome pair"); + if ( + manifest.expected.kind === "pause" && + manifest.expected.outcome === "continue" + ) { + fields(audio.pause, ["start_ms", "end_ms"], "audio.pause"); + integer(audio.pause.start_ms, 1, CLIP_MS - 1, "audio.pause.start_ms"); + integer( + audio.pause.end_ms, + audio.pause.start_ms + 1, + CLIP_MS - 1, + "audio.pause.end_ms", + ); + } else if (audio.pause !== null) + refuse("audio.pause is only used by pause/continue"); + return manifest; +} + +// Read at most the cap plus one byte even if a file grows after open/fstat. +function readBounded(filename, limit) { + const fd = fs.openSync( + filename, + fs.constants.O_RDONLY | + (fs.constants.O_NOFOLLOW ?? 0) | + (fs.constants.O_NONBLOCK ?? 0), + ); + try { + const stat = fs.fstatSync(fd); + if (!stat.isFile() || stat.size > limit) + refuse("input is not a bounded regular file"); + const bytes = Buffer.alloc(limit + 1); + let size = 0; + while (size <= limit) { + const count = fs.readSync(fd, bytes, size, limit + 1 - size, null); + if (!count) break; + size += count; + } + if (size > limit) refuse("input exceeds byte limit"); + return bytes.subarray(0, size); + } finally { + fs.closeSync(fd); + } +} + +function inspectAudio(audio, bytes) { + if (sha256(bytes) !== audio.sha256) refuse("audio digest mismatch"); + let frames; + let sampleAt; + if (audio.format === "pcm_s16le") { + if ( + ["RIFF", "RIFX", "RF64", "WAVE", "FORM", "OggS", "fLaC"].includes( + bytes.toString("latin1", 0, 4), + ) || + bytes.toString("latin1", 0, 3) === "ID3" + ) + refuse("raw PCM contains a container header"); + if (!bytes.length || bytes.length % 2) + refuse("raw PCM must contain whole nonempty s16le frames"); + frames = bytes.length / 2; + sampleAt = (i) => bytes.readInt16LE(i * 2); + } else { + const wav = parseWav(bytes); + if (wav.error) refuse(wav.error); + if (wav.channels !== 1 || wav.sampleRate !== 48000 || wav.bits !== 16) + refuse("WAV header disagrees with declared mono 48000 Hz s16le format"); + // parseWav decodes frames; check header consistency and ambiguity too. + let fmtCount = 0; + let dataCount = 0; + for (let offset = 12; offset < bytes.length;) { + const name = bytes.toString("ascii", offset, offset + 4); + const size = bytes.readUInt32LE(offset + 4); + const body = offset + 8; + if (name === "fmt ") { + fmtCount++; + if ( + size < 16 || + bytes.readUInt32LE(body + 8) !== 96000 || + bytes.readUInt16LE(body + 12) !== 2 + ) + refuse("WAV byte rate or block alignment is invalid"); + } + if (name === "data") dataCount++; + offset = body + size + (size % 2); + } + if (fmtCount !== 1 || dataCount !== 1) + refuse("WAV requires one fmt and one data chunk"); + frames = wav.samples.length; + sampleAt = (i) => wav.samples[i]; + } + const durationMs = (frames * 1000) / audio.sample_rate_hz; + if (durationMs <= 0 || durationMs > CLIP_MS) + refuse(`clip duration must be positive and at most ${CLIP_MS} ms`); + if (audio.pause !== null) { + const from = (audio.pause.start_ms * audio.sample_rate_hz) / 1000; + const to = (audio.pause.end_ms * audio.sample_rate_hz) / 1000; + if (to >= frames) + refuse("annotated pause must be frame-aligned and inside the clip"); + let before = false; + let after = false; + for (let i = 0; i < frames; i++) { + if (Math.abs(sampleAt(i)) <= 500) continue; + if (i < from) before = true; + else if (i < to) refuse("annotated pause is not quiet"); + else after = true; + } + if (!before || !after) + refuse("annotated pause requires signal before and after it"); + } + return { frames, duration_ms: durationMs }; +} + +function parseManifest(bytes) { + let text; + let manifest; + try { + text = new TextDecoder("utf-8", { fatal: true }).decode(bytes); + manifest = JSON.parse(text); + } catch { + refuse("manifest is not UTF-8 JSON"); + } + const tokens = /"(?:\\[\s\S]|[^"\\])*"|[{}\[\]]/g; + const stack = []; + for (const match of text.matchAll(tokens)) { + const token = match[0]; + if (token === "{") stack.push(new Set()); + else if (token === "[") stack.push(null); + else if (token === "}" || token === "]") stack.pop(); + else if ( + text + .slice(match.index + token.length) + .trimStart() + .startsWith(":") + ) { + const key = JSON.parse(token); + if (stack.at(-1).has(key)) refuse("manifest has a duplicate object key"); + stack.at(-1).add(key); + } + } + return manifest; +} + +function loadFixture(filename, transport) { + if (!["browser", "socket"].includes(transport)) + refuse("transport must be browser or socket"); + const manifestBytes = readBounded(filename, MANIFEST_BYTES); + const manifest = parseManifest(manifestBytes); + validateManifest(manifest); + const expectedFormat = + transport === "browser" ? "wav_pcm_s16le" : "pcm_s16le"; + if (manifest.audio.format !== expectedFormat) + refuse("audio format does not match transport"); + const directory = path.dirname(fs.realpathSync(filename)); + const audioPath = path.join(directory, manifest.audio.file); + const bytes = readBounded( + audioPath, + transport === "browser" ? WAV_BYTES : PCM_BYTES, + ); + const audio = inspectAudio(manifest.audio, bytes); + return { + manifest, + manifest_sha256: sha256(manifestBytes), + bytes, + ...audio, + }; +} + +module.exports = { loadFixture, validateManifest, inspectAudio }; + +if (require.main === module) { + try { + if (process.argv.length !== 4) + refuse("usage: node scripts/replay-fixture.cjs MANIFEST browser|socket"); + const { bytes, ...fixture } = loadFixture(process.argv[2], process.argv[3]); + console.log( + JSON.stringify({ ...fixture, byte_length: bytes.length }, null, 2), + ); + } catch (error) { + console.error(error.message); + process.exitCode = 2; + } +} diff --git a/tests/browser/replay-fixture.test.js b/tests/browser/replay-fixture.test.js new file mode 100644 index 000000000..900fecda2 --- /dev/null +++ b/tests/browser/replay-fixture.test.js @@ -0,0 +1,470 @@ +import assert from "node:assert/strict"; +import { test } from "node:test"; +import { createRequire } from "node:module"; +import fs from "node:fs"; +import os from "node:os"; +import path from "node:path"; +import crypto from "node:crypto"; +import { spawnSync } from "node:child_process"; +const require = createRequire(import.meta.url); +const { + loadFixture, + validateManifest, +} = require("../../scripts/replay-fixture.cjs"); + +function audio(format = "pcm_s16le", durationMs = 100) { + const rate = format === "pcm_s16le" ? 16000 : 48000; + const pcm = Buffer.alloc((rate * 2 * durationMs) / 1000); + for (let i = 0; i < pcm.length / 2; i++) + pcm.writeInt16LE(Math.round(6000 * Math.sin(i / 8)), i * 2); + if (format === "pcm_s16le") return pcm; + const header = Buffer.alloc(44); + header.write("RIFF"); + header.writeUInt32LE(36 + pcm.length, 4); + header.write("WAVEfmt ", 8); + header.writeUInt32LE(16, 16); + header.writeUInt16LE(1, 20); + header.writeUInt16LE(1, 22); + header.writeUInt32LE(rate, 24); + header.writeUInt32LE(rate * 2, 28); + header.writeUInt16LE(2, 32); + header.writeUInt16LE(16, 34); + header.write("data", 36); + header.writeUInt32LE(pcm.length, 40); + return Buffer.concat([header, pcm]); +} + +const digest = (bytes) => + crypto.createHash("sha256").update(bytes).digest("hex"); +function fixture(t, format = "pcm_s16le") { + const dir = fs.mkdtempSync(path.join(os.tmpdir(), "replay-fixture-")); + t.after(() => fs.rmSync(dir, { recursive: true, force: true })); + let bytes = audio(format); + const manifest = { + version: 1, + id: "backchannel", + origin: "synthetic-tone", + audio: { + file: format === "pcm_s16le" ? "clip.pcm" : "clip.wav", + sha256: digest(bytes), + format, + sample_rate_hz: format === "pcm_s16le" ? 16000 : 48000, + channels: 1, + pause: null, + }, + gate: { state: "speaking", tool: null, timeout_ms: 10000, max_age_ms: 250 }, + observation_ms: 5000, + expected: { kind: "overlap", outcome: "continued" }, + }; + const filename = path.join(dir, "manifest.json"); + const write = () => { + fs.writeFileSync(path.join(dir, manifest.audio.file), bytes); + fs.writeFileSync(filename, JSON.stringify(manifest)); + }; + write(); + return { + manifest, + filename, + dir, + write, + setBytes(b) { + bytes = b; + manifest.audio.sha256 = digest(b); + write(); + }, + }; +} + +test("loads named WAV and PCM with exact byte/manifest identity before any transport", (t) => { + for (const [format, transport, frames] of [ + ["pcm_s16le", "socket", 1600], + ["wav_pcm_s16le", "browser", 4800], + ]) { + const f = fixture(t, format); + const loaded = loadFixture(f.filename, transport); + assert.equal(loaded.manifest.id, "backchannel"); + assert.equal(loaded.frames, frames); + assert.equal(loaded.duration_ms, 100); + assert.deepEqual(loaded.bytes, audio(format)); + assert.equal(loaded.manifest_sha256, digest(fs.readFileSync(f.filename))); + assert.throws( + () => + loadFixture(f.filename, transport === "browser" ? "socket" : "browser"), + /match transport/, + ); + } +}); + +test("refuses malformed manifest fields, stale gates and invalid floor pairs", (t) => { + const f = fixture(t); + for (const change of [ + (m) => { + m.extra = true; + }, + (m) => { + m.version = 2; + }, + (m) => { + m.id = "../escape"; + }, + (m) => { + m.audio.file = "../clip.pcm"; + }, + (m) => { + m.audio.file = "/tmp/clip.pcm"; + }, + (m) => { + m.audio.sha256 = "0"; + }, + (m) => { + m.audio.channels = 2; + }, + (m) => { + m.audio.sample_rate_hz = 48000; + }, + (m) => { + m.audio.format = "mp3"; + }, + (m) => { + m.gate.state = "caption-looks-like-hint"; + }, + (m) => { + m.gate.state = "hint"; + }, + (m) => { + m.gate.tool = "log_hint"; + }, + (m) => { + m.gate.timeout_ms = 0; + }, + (m) => { + m.gate.timeout_ms = 120001; + }, + (m) => { + m.gate.max_age_ms = 5001; + }, + (m) => { + m.gate.max_age_ms = m.gate.timeout_ms + 1; + }, + (m) => { + m.observation_ms = 0.5; + }, + (m) => { + m.observation_ms = Infinity; + }, + (m) => { + m.expected = { kind: ["overlap"], outcome: ["continued"] }; + }, + (m) => { + m.expected = { kind: ["pause"], outcome: ["continue"] }; + }, + (m) => { + m.expected = { kind: null, outcome: "continue" }; + }, + (m) => { + m.expected = { kind: "pause", outcome: {} }; + }, + (m) => { + m.expected.outcome = "continue"; + }, + (m) => { + m.expected.outcome = "unresolved"; + }, + ]) { + const m = structuredClone(f.manifest); + change(m); + assert.throws( + () => validateManifest(m), + /replay fixture:/, + change.toString(), + ); + } + for (const [kind, outcome] of [ + ["overlap", "continued"], + ["overlap", "interrupted"], + ["pause", "respond"], + ]) { + validateManifest({ ...f.manifest, expected: { kind, outcome } }); + } +}); + +test("loader accepts PCM whose high-bit bytes only resemble container signatures", (t) => { + const f = fixture(t); + for (const head of [ + [0xd2, 0xc9, 0xc6, 0xc6], + [0xc9, 0xc4, 0x33], + ]) { + const bytes = audio(); + Buffer.from(head).copy(bytes); + f.setBytes(bytes); + assert.doesNotThrow(() => loadFixture(f.filename, "socket")); + } +}); +test("loader rejects changed bytes, odd/empty PCM, container headers and symlinks", (t) => { + const f = fixture(t); + fs.writeFileSync(path.join(f.dir, "clip.pcm"), Buffer.alloc(3200)); + assert.throws(() => loadFixture(f.filename, "socket"), /digest mismatch/); + for (const bytes of [ + Buffer.alloc(0), + Buffer.alloc(3), + Buffer.from("RIFFabcd"), + Buffer.from("RIFXabcd"), + Buffer.from("RF64abcd"), + Buffer.from("fLaCabcd"), + Buffer.from("OggSabcd"), + Buffer.from("FORMabcd"), + Buffer.from("WAVEabcd"), + Buffer.from("ID3xxxxx"), + ]) { + f.setBytes(bytes); + assert.throws(() => loadFixture(f.filename, "socket"), /frames|header/); + } + f.setBytes(audio()); + fs.writeFileSync(path.join(f.dir, "matching.pcm"), audio()); + fs.unlinkSync(path.join(f.dir, "clip.pcm")); + fs.symlinkSync("matching.pcm", path.join(f.dir, "clip.pcm")); + assert.throws(() => loadFixture(f.filename, "socket"), { code: "ELOOP" }); + const linkedManifest = path.join(f.dir, "linked.json"); + fs.symlinkSync("manifest.json", linkedManifest); + assert.throws(() => loadFixture(linkedManifest, "socket"), { code: "ELOOP" }); +}); + +test("WAV decoder checks rate, bits, alignment, lengths and duration", (t) => { + const f = fixture(t, "wav_pcm_s16le"); + for (const mutate of [ + (b) => b.writeUInt32LE(16000, 24), + (b) => b.writeUInt16LE(8, 34), + (b) => b.writeUInt16LE(4, 32), + (b) => b.writeUInt32LE(123, 28), + (b) => b.writeUInt32LE(0xffffffff, 40), + ]) { + const b = audio("wav_pcm_s16le"); + mutate(b); + f.setBytes(b); + assert.throws(() => loadFixture(f.filename, "browser"), /WAV|chunk/); + } + f.setBytes(audio("wav_pcm_s16le", 0)); + assert.throws(() => loadFixture(f.filename, "browser"), /duration/); +}); + +test("pause/continue requires a real internal quiet interval with signal on both sides", (t) => { + const f = fixture(t); + f.manifest.expected = { kind: "pause", outcome: "continue" }; + f.write(); + assert.throws(() => loadFixture(f.filename, "socket"), /audio.pause/); + f.manifest.audio.pause = { start_ms: 20, end_ms: 70 }; + const b = audio(); + f.setBytes(b); + assert.throws(() => loadFixture(f.filename, "socket"), /not quiet/); + b.fill(0, 20 * 32, 70 * 32); + f.setBytes(b); + assert.equal(loadFixture(f.filename, "socket").duration_ms, 100); + f.manifest.audio.pause.end_ms = 100; + f.write(); + assert.throws(() => loadFixture(f.filename, "socket"), /inside the clip/); + f.manifest.audio.pause.end_ms = 70; + b.fill(0); + f.setBytes(b); + assert.throws( + () => loadFixture(f.filename, "socket"), + /signal before and after/, + ); +}); + +test("caps are checked at the limit and one frame/byte past, without provider access", (t) => { + const f = fixture(t); + f.setBytes(audio("pcm_s16le", 30000)); + assert.equal(loadFixture(f.filename, "socket").duration_ms, 30000); + f.setBytes(Buffer.concat([audio("pcm_s16le", 30000), Buffer.alloc(2)])); + assert.throws( + () => loadFixture(f.filename, "socket"), + /bounded regular file/, + ); + fs.writeFileSync(f.filename, " ".repeat(16384)); + assert.throws(() => loadFixture(f.filename, "socket"), /UTF-8 JSON/); + fs.appendFileSync(f.filename, " "); + assert.throws( + () => loadFixture(f.filename, "socket"), + /bounded regular file/, + ); +}); + +test("CLI exits nonzero on invalid input and prints only offline fixture metadata", (t) => { + const f = fixture(t); + const run = (...args) => + spawnSync(process.execPath, ["scripts/replay-fixture.cjs", ...args], { + encoding: "utf8", + }); + const good = run(f.filename, "socket"); + assert.equal(good.status, 0, good.stderr); + const output = JSON.parse(good.stdout); + assert.equal(output.byte_length, 3200); + assert.equal(Object.hasOwn(output, "bytes"), false); + assert.equal(run(f.filename, "invalid").status, 2); + fs.writeFileSync(f.filename, Buffer.from([0xff, 0x7b, 0x7d])); + assert.equal(run(f.filename, "socket").status, 2); +}); + +test("duplicate JSON keys, including escaped equivalent keys, are refused", (t) => { + const f = fixture(t); + const text = fs.readFileSync(f.filename, "utf8"); + for (const key of ['"id"', '"\\u0069d"']) { + fs.writeFileSync( + f.filename, + text.replace('"id":', `${key}:"shadow", "id":`), + ); + assert.throws( + () => loadFixture(f.filename, "socket"), + /duplicate object key/, + ); + } + fs.writeFileSync( + f.filename, + text.replace('"continued"', '"continued","outcome":"continued"'), + ); + assert.throws( + () => loadFixture(f.filename, "socket"), + /duplicate object key/, + ); +}); + +test( + "non-regular FIFOs refuse before a blocking read or provider access", + { skip: process.platform === "win32" }, + (t) => { + const f = fixture(t); + const fifo = path.join(f.dir, "input.pipe"); + const made = spawnSync("mkfifo", [fifo], { encoding: "utf8" }); + assert.equal(made.status, 0, made.stderr); + const run = (filename) => + spawnSync( + process.execPath, + ["scripts/replay-fixture.cjs", filename, "socket"], + { encoding: "utf8", timeout: 5000 }, + ); + const manifestResult = run(fifo); + assert.equal(manifestResult.error, undefined); + assert.equal(manifestResult.status, 2); + assert.match(manifestResult.stderr, /bounded regular file/); + f.manifest.audio.file = "input.pipe"; + fs.writeFileSync(f.filename, JSON.stringify(f.manifest)); + const audioResult = run(f.filename); + assert.equal(audioResult.error, undefined); + assert.equal(audioResult.status, 2); + assert.match(audioResult.stderr, /bounded regular file/); + }, +); + +test("valid gate variants and timing endpoints are distinct from invalid combinations", (t) => { + const f = fixture(t); + for (const [state, tool] of [ + ["listening", null], + ["hint", "log_hint"], + ["tool", "read_editor"], + ]) { + const m = structuredClone(f.manifest); + m.gate = { state, tool, timeout_ms: 120000, max_age_ms: 5000 }; + m.observation_ms = 120000; + validateManifest(m); + m.gate = { state, tool, timeout_ms: 1, max_age_ms: 1 }; + m.observation_ms = 1; + validateManifest(m); + } + const m = structuredClone(f.manifest); + m.gate.timeout_ms = 100; + m.gate.max_age_ms = 101; + assert.throws(() => validateManifest(m), /age exceeds timeout/); + m.gate = { state: "tool", tool: null, timeout_ms: 100, max_age_ms: 50 }; + assert.throws(() => validateManifest(m), /requires a tool name/); +}); + +test("WAV ancillary chunks are accepted, but duplicate fmt/data chunks are refused", (t) => { + const f = fixture(t, "wav_pcm_s16le"); + const wav = audio("wav_pcm_s16le"); + const withChunk = (chunk) => { + const b = Buffer.concat([wav, chunk]); + b.writeUInt32LE(b.length - 8, 4); + return b; + }; + f.setBytes(withChunk(Buffer.from("JUNK\x01\x00\x00\x00\x00\x00", "binary"))); + assert.equal(loadFixture(f.filename, "browser").frames, 4800); + for (const chunk of [wav.subarray(12, 36), wav.subarray(36)]) { + f.setBytes(withChunk(chunk)); + assert.throws( + () => loadFixture(f.filename, "browser"), + /one fmt and one data/, + ); + } + const odd = Buffer.concat([wav, Buffer.alloc(2)]); + odd.writeUInt32LE(odd.length - 8, 4); + odd.writeUInt32LE(wav.length - 44 + 1, 40); + f.setBytes(odd); + assert.throws(() => loadFixture(f.filename, "browser"), /whole frames/); +}); + +test("growth after fstat is bounded by the read cap, not the old file size", (t) => { + const f = fixture(t); + const text = fs.readFileSync(f.filename, "utf8"); + fs.writeFileSync(f.filename, text.padEnd(16384)); + const realStat = fs.fstatSync; + let grew = false; + t.mock.method(fs, "fstatSync", (fd) => { + const stat = realStat(fd); + if (!grew) { + grew = true; + fs.appendFileSync(f.filename, " "); + } + return stat; + }); + assert.throws(() => loadFixture(f.filename, "socket"), /exceeds byte limit/); + assert.equal(grew, true); +}); + +test("WAV duration and file-byte ceilings accept exact boundaries and reject excess", (t) => { + const f = fixture(t, "wav_pcm_s16le"); + f.setBytes(audio("wav_pcm_s16le", 30000)); + assert.equal(loadFixture(f.filename, "browser").duration_ms, 30000); + f.setBytes(audio("wav_pcm_s16le", 30001)); + assert.throws(() => loadFixture(f.filename, "browser"), /duration/); + const wav = audio("wav_pcm_s16le"); + const chunk = Buffer.alloc(2945536 - wav.length); + chunk.write("JUNK"); + chunk.writeUInt32LE(chunk.length - 8, 4); + const atLimit = Buffer.concat([wav, chunk]); + atLimit.writeUInt32LE(atLimit.length - 8, 4); + f.setBytes(atLimit); + assert.equal(loadFixture(f.filename, "browser").bytes.length, 2945536); + assert.equal(loadFixture(f.filename, "browser").frames, 4800); + f.setBytes(Buffer.concat([atLimit, Buffer.alloc(1)])); + assert.throws( + () => loadFixture(f.filename, "browser"), + /bounded regular file/, + ); +}); + +test("pause threshold is inclusive at +/-500 and bounds require a real internal interval", (t) => { + const f = fixture(t); + f.manifest.expected = { kind: "pause", outcome: "continue" }; + f.manifest.audio.pause = { start_ms: 20, end_ms: 70 }; + const b = audio(); + b.fill(0, 20 * 32, 70 * 32); + for (const value of [500, -500]) { + b.writeInt16LE(value, 40 * 32); + f.setBytes(b); + assert.equal(loadFixture(f.filename, "socket").frames, 1600); + } + for (const value of [501, -501]) { + b.writeInt16LE(value, 40 * 32); + f.setBytes(b); + assert.throws(() => loadFixture(f.filename, "socket"), /not quiet/); + } + for (const pause of [ + { start_ms: 0, end_ms: 70 }, + { start_ms: 20, end_ms: 20 }, + { start_ms: 20, end_ms: 19 }, + ]) { + f.manifest.audio.pause = pause; + f.write(); + assert.throws(() => loadFixture(f.filename, "socket"), /audio.pause/); + } +}); From ed0c95dc5bac3fcb4c72deb3bbda955cdcc50e05 Mon Sep 17 00:00:00 2001 From: Jim Huang Date: Mon, 2 Nov 2026 17:45:12 +0800 Subject: [PATCH 2/4] Retain replay timing and boundary evidence A replay cannot attribute a floor outcome to injected audio from a rolling agent tail or the order in which records arrive. Pauses can settle long before teardown emits them, and tool context can expire without an active latency trace. Retain complete floor and latency diagnostic streams through owned server and agent shutdown. Bound UTF-8 lines by bytes, mark incomplete capture and source discontinuities, and drain each pipe before closing. Attempt every cleanup without replacing a primary budget or soak error. External dispatch logs explicitly report unavailable evidence. Record floor opening, first resolution and candidate activity end on the interview clock. Add sampled wall and monotonic clock uncertainty, process identity, unconditional accepted-handler boundary observations, and allowlisted accepted tool names with actual hint-counter changes. These observations do not change endpointing, interruption, recovery, tool responses, scoring or what is considered audible. Exercise real child streams, source rotation, truncation, short writes, UTF-8 limits and cleanup failure precedence. Cover first-resolution and activity-loss timing, tool acceptance and boundary emission without a trace. The full local gate passes with 2,705 browser tests and no browser skips; desktop checks need WebKitGTK and cargo-deny is not installed. Fifteen targeted guard-removal mutants fail their regression suites. This supplies replay evidence producers and retention. Named browser and socket adapters, event-clock joins and common trial judgment remain separate work; no live provider or physical audio acceptance is implied. Change-Id: Id22928886806469d60ca10394f0a3eb545b7e436 --- docs/latency-observability.md | 14 + docs/turn-timing.md | 87 +++- scripts/browser-check-cleanup.cjs | 37 ++ scripts/browser-check.cjs | 41 +- scripts/browser-check.sh | 15 +- scripts/floor-capture.cjs | 240 +++++++++-- scripts/rust-style-ceilings.json | 2 +- src/livekit/floor.rs | 19 +- src/livekit/latency.rs | 59 +++ src/livekit/session.rs | 110 +----- src/livekit/session/floor.rs | 75 ++++ src/livekit/session/observations.rs | 91 +++++ tests/browser/browser-check-cleanup.test.js | 184 +++++++++ tests/browser/diagnostic-capture.test.js | 416 ++++++++++++++++++++ tests/browser/floor-capture.test.js | 9 +- tests/unit/livekit/floor.rs | 126 ++++++ tests/unit/livekit/latency.rs | 23 ++ tests/unit/livekit/latency/gates.rs | 37 ++ tests/unit/livekit/session/floor.rs | 85 ++++ tests/unit/livekit/session/observations.rs | 86 ++++ 20 files changed, 1597 insertions(+), 159 deletions(-) create mode 100644 scripts/browser-check-cleanup.cjs create mode 100644 src/livekit/session/floor.rs create mode 100644 src/livekit/session/observations.rs create mode 100644 tests/browser/browser-check-cleanup.test.js create mode 100644 tests/browser/diagnostic-capture.test.js create mode 100644 tests/unit/livekit/latency/gates.rs create mode 100644 tests/unit/livekit/session/floor.rs create mode 100644 tests/unit/livekit/session/observations.rs diff --git a/docs/latency-observability.md b/docs/latency-observability.md index 2fc97a179..abc52e5ee 100644 --- a/docs/latency-observability.md +++ b/docs/latency-observability.md @@ -500,6 +500,20 @@ still has the anchor. `elapsed_ms` and every `interview_ms` read the same clock, which a socket replacement does not reset, so a long harness can verify the full duration from the last sample. +#### Emission clock samples + +Each new `reply_latency` record also carries a `clock` object containing +`start_unix_ms`, `emitted_unix_ms`, `emitted_ms` and `clock_uncertainty_ms`. +These additive fields keep the existing record version. The wall time is +sampled afresh, bracketed by monotonic reads; uncertainty includes the anchor +sample, current sampling and millisecond rounding. An absent wall reading or +anchor remains null, never zero. The event's `interview_ms` is distinct from +the emission sample: a provider event may have waited in the handler's queue. +These samples support detecting wall-clock drift in a short replay without +waiting for a minute clock line; they do not measure browser or network delay. +The [floor observation contract](turn-timing.md#opening-and-resolution-clocks) +defines the additional floor times and tool-gate invalidation diagnostics. + #### Microphone dequeue gaps Each `interview clock:` line also carries `mic_gap_max_ms=`, diff --git a/docs/turn-timing.md b/docs/turn-timing.md index 71e181518..cda186a96 100644 --- a/docs/turn-timing.md +++ b/docs/turn-timing.md @@ -186,26 +186,77 @@ logged. Activity is eligible only with a candidate audio track, outside a thinking hold and discarded output. PCM levels and transcripts cannot open records. +### Opening and resolution clocks + +Floor lines append `opened_ms`, `resolved_ms`, `activity_end_ms`, `emitted_ms`, +`emitted_unix_ms`, `start_unix_ms`, `clock_uncertainty_ms` and process `pid`. Event offsets use +the same anchored monotonic clock as latency records. Missing anchors stay +`unknown`; the runtime state's coarse display clock is never a substitute. +`resolved_ms` is set once when the outcome leaves unresolved, not when a +buffered record emits. For an overlap, `activity_end_ms` records candidate END +separately: END may precede or follow interruption/drain. Reset/lost activity +that turns an unended overlap back into unresolved clears its resolution. +These fields do not alter any observation outcome, flag or interview action. + +The emission clock pairs a fresh wall reading with monotonic sampling bounds. +`clock_uncertainty_ms` includes the original anchor's sampling duration, the +current sample's duration and whole-millisecond rounding. It does not bound +wall-clock steps/slew, network, provider, browser scheduling or handler lag. A consumer must retain +its own injection bracket and uncertainty, verify anchor identity and clock +drift, and reject ambiguous or out-of-window attribution. Emission order and +max emitted sequence remain insufficient for joining an injection to a record. + +Tool-response latency records include allowlisted `accepted_tool_names` and +`hint_given`, separate from `sent`. Accepted means no tool error, not that a +response was delivered. `hint_given` means this batch advanced an authored hint +rung or recorded a volunteered hint; withheld/exhausted requests cannot supply +hint context merely because their tool response has no error. It establishes +server tool context, never the content or audibility of a generated phrase. + +`codetrial replay_gate` JSON lines carry `event=gate_boundary`, version 1, +room/process/session/socket identity, optional turn, stage, event `interview_ms` +and an emission `clock` sample. Each invocation of the latency boundary handler +emits one, even without an open reply trace: accepted turn completion or +interruption, hold, and socket replacement cannot silently leave an old tool +gate eligible. Provider events rejected by existing acceptance, hold or discard +guards do not create new boundaries; the hold/replacement that invalidated +context is already authoritative. These diagnostics change neither provider +acceptance nor the room's state transitions. + ### Retaining browser-check evidence -For Rust and dispatch modes, `scripts/browser-check.sh` creates a private -`codetrial-floor.*` file outside its temporary server directory and prints its -path during cleanup. `BROWSER_CHECK_FLOOR_LOG` is an internal handoff to the -harness, not a caller-selected destination. The Node harness captures each -complete floor line before trimming its stderr buffer. A separate follower -reads dispatched-agent diagnostics from server byte zero, and uses a completion -marker to drain the server log after server teardown before the temporary -directory is deleted. Each line is appended with one synchronous write and is -not fsynced, so it survives a killed process but not power loss. On group -signals the follower waits for the completion marker, with a five-second -fallback; if its parent disappears it drains once and exits instead of polling -forever. Lines split across reads are joined; oversized lines and unrelated -output are excluded. Review and remove retained artifacts when no longer -needed. These diagnostics contain identifiers but no interview content. - -`BROWSER_CHECK_CAPTURE`, when provided, includes `floorLogPath`, a snapshot of -record fields (including socket and sequence ids), and barge replay -state/timestamp metadata. Refused injections record an exclusion category and +For Rust and dispatch modes, `scripts/browser-check.sh` creates private +`codetrial-floor.*` and `codetrial-latency.*` files outside its temporary server +directory and prints both paths during cleanup. `BROWSER_CHECK_FLOOR_LOG` and +`BROWSER_CHECK_LATENCY_LOG` are internal handoffs, not caller-selected paths. +The Node harness retains complete floor and latency lines before trimming its +stderr tail. The latency file also keeps `interview clock:`, `replacement start:`, +`replacement end:` and `codetrial replay_gate` lines. In dispatch mode a single follower reads server +diagnostics from byte zero and uses a completion marker to drain the server log +after teardown before the temporary directory is deleted. Rust mode captures +its own agent's pipes instead, including their final close after group shutdown. + +Each retained line is appended with one synchronous write and is not fsynced: +it survives a killed process but not power loss. Each pipe has a separate UTF-8 +line buffer; complete lines are capped at 4,096 bytes including the newline. +Unrelated output is excluded. Oversized, unterminated, malformed UTF-8 or +unframed diagnostics leave a content-free `codetrial capture_incomplete` marker +in the relevant file, with its family and reason. A pipe error, failed write, +missed drain deadline or observed source-file replacement/shrink also leaves +incomplete evidence or a nonzero harness exit. An observational judge must +classify these as incomplete, never passing evidence; the legacy barge smoke +still checks only for its measured interrupted overlap. No dropped stderr +content is copied into a marker. Dispatch against an external server marks +both artifacts unavailable because this runner cannot follow that server's log. + +On group signals the dispatched follower waits for the completion marker with +a five-second fallback; if its parent disappears it drains once and exits. +Review and remove retained artifacts when no longer needed. These diagnostics +contain identifiers but no interview content. + +`BROWSER_CHECK_CAPTURE`, when provided, includes `floorLogPath`, `latencyLogPath` +and a snapshot of floor record fields (including socket and sequence ids), plus +barge replay state/timestamp metadata. Refused injections record an exclusion category and observed state, so a misaligned trial stays distinct from a provider failure. Files survive failed and interrupted runs. Abrupt process termination cannot synthesize terminal records for still-open provider observations; missing END diff --git a/scripts/browser-check-cleanup.cjs b/scripts/browser-check-cleanup.cjs new file mode 100644 index 000000000..29edb9cc7 --- /dev/null +++ b/scripts/browser-check-cleanup.cjs @@ -0,0 +1,37 @@ +const { drainDiagnosticStreams } = require("./floor-capture.cjs"); + +// Attempt every owned-resource cleanup; a secondary failure cannot replace +// the run's budget/soak outcome, and the first cleanup failure keeps its cause. +async function cleanupBrowserCheck({ + stopAgent, + streams, + browser, + compilerExplorerMock, + operationFailed, +}) { + let failure; + for (const close of [ + stopAgent, + () => drainDiagnosticStreams(streams), + () => + compilerExplorerMock && + new Promise((resolve, reject) => { + compilerExplorerMock.server.close((error) => + error ? reject(error) : resolve(), + ); + }), + () => browser.close(), + ]) { + try { + await close(); + } catch (error) { + failure ??= error; + } + } + if (failure) { + if (!operationFailed) throw failure; + console.error("browser check cleanup also failed after the run failed"); + } +} + +module.exports = { cleanupBrowserCheck }; diff --git a/scripts/browser-check.cjs b/scripts/browser-check.cjs index feb140bc2..bf30ae363 100644 --- a/scripts/browser-check.cjs +++ b/scripts/browser-check.cjs @@ -19,10 +19,12 @@ const fs = require("fs"); const { mediaProbeSource, assertJimAudio } = require("./media-probe.cjs"); const { installBargeReplay } = require("./barge-replay.cjs"); const { - FloorCapture, + captureDiagnosticStream, + drainDiagnosticStreams, assertInterruptedOverlap, readFloorRecords, } = require("./floor-capture.cjs"); +const { cleanupBrowserCheck } = require("./browser-check-cleanup.cjs"); const http = require("http"); const { spawn } = require("child_process"); const { @@ -79,6 +81,7 @@ const { } = require("./soak-judge.cjs"); const floorLogPath = process.env.BROWSER_CHECK_FLOOR_LOG || null; +const latencyLogPath = process.env.BROWSER_CHECK_LATENCY_LOG || null; // Written before the run can fail, so an aborted run still points at its // retained floor log. @@ -91,6 +94,7 @@ function writeIncompleteCapture(fields) { flow: process.env.BROWSER_CHECK_FLOW, status: "incomplete", floorLogPath, + latencyLogPath, ...(soakSummary ? { soak: soakSummary } : {}), ...fields, }, @@ -1255,6 +1259,7 @@ async function isolateRustAgent( let rustAgent; let compilerExplorerMock; let agentDone = false; + const diagnosticStreams = []; // Before a browser or an agent exists: a run launched by // scripts/interview-run-budget.py joins its budget here, and a manifest the @@ -1291,7 +1296,10 @@ async function isolateRustAgent( console.error("run budget launcher is gone; stopping the check"); // The agent is detached, so neither this exit nor the shell reaches // it, and the launcher that would have reaped it is the one that died. - await stopAgentGroup(rustAgent, 1500, true); + await stopAgentGroup(rustAgent, 1500, true).catch(() => + console.error("agent stop failed during launcher cleanup"), + ); + await drainDiagnosticStreams(diagnosticStreams, 1500).catch(() => {}); const closing = browser ? browser.close().catch(() => {}) : null; await Promise.race([closing, new Promise((r) => setTimeout(r, 2000))]); process.exit(4); @@ -1346,6 +1354,7 @@ async function isolateRustAgent( process.exit(1); } + let operationFailed = false; try { const page = await browser.newPage(); let bargeReplay = null; @@ -1540,11 +1549,13 @@ async function isolateRustAgent( }, ); for (const stream of [rustAgent.stdout, rustAgent.stderr]) { - const streamCapture = floorLogPath - ? new FloorCapture(floorLogPath) - : null; + diagnosticStreams.push( + captureDiagnosticStream(stream, { + floor: floorLogPath, + latency: latencyLogPath, + }), + ); stream.on("data", (chunk) => { - streamCapture?.push(chunk); const text = redact(chunk); if ( text.includes( @@ -1555,7 +1566,6 @@ async function isolateRustAgent( agentOutput.push(text); while (agentOutput.join("").length > 12000) agentOutput.shift(); }); - stream.once("close", () => streamCapture?.close()); } agentFailure = new Promise((_, reject) => { rustAgent.once("exit", (code, signal) => { @@ -3290,6 +3300,7 @@ PatternLexicon.prototype.search = function(word) { agentAfterCandidate, rustAgentParticipants, floorLogPath, + latencyLogPath, floorRecords: floorLogPath ? readFloorRecords(floorLogPath) : [], @@ -3347,14 +3358,18 @@ PatternLexicon.prototype.search = function(word) { throw error; }); agentDone = true; + } catch (error) { + operationFailed = true; + throw error; } finally { agentDone = true; - await stopAgentGroup(rustAgent, 5000, false); - if (compilerExplorerMock) - await new Promise((resolve) => - compilerExplorerMock.server.close(resolve), - ); - await browser.close(); + await cleanupBrowserCheck({ + stopAgent: () => stopAgentGroup(rustAgent, 5000, false), + streams: diagnosticStreams, + browser, + compilerExplorerMock, + operationFailed, + }); } })().catch((error) => { // Redacted like every other error path in this file. This one is the last diff --git a/scripts/browser-check.sh b/scripts/browser-check.sh index 8183dcd1d..64a64862c 100755 --- a/scripts/browser-check.sh +++ b/scripts/browser-check.sh @@ -152,6 +152,9 @@ cleanup() if [ "${BROWSER_CHECK_FLOOR_LOG:-}" ]; then echo "Floor diagnostics retained at $BROWSER_CHECK_FLOOR_LOG" >&2 fi + if [ "${BROWSER_CHECK_LATENCY_LOG:-}" ]; then + echo "Latency diagnostics retained at $BROWSER_CHECK_LATENCY_LOG" >&2 + fi rm -r "$TMP" 2> /dev/null || true exit "$cleanup_status" } @@ -340,11 +343,15 @@ fi if [ "$BROWSER_CHECK_AGENT" = rust ] || [ "$BROWSER_CHECK_AGENT" = dispatch ]; then # Outside TMP: failure and signal cleanup must preserve early observations. BROWSER_CHECK_FLOOR_LOG=$(mktemp "${TMPDIR:-/tmp}/codetrial-floor.XXXXXX") - export BROWSER_CHECK_FLOOR_LOG - # Only a server this script launches writes SERVER_LOG. - if [ -z "${CODETRIAL_WEB_URL:-}" ]; then - node "$ROOT/scripts/floor-capture.cjs" "$SERVER_LOG" "$BROWSER_CHECK_FLOOR_LOG" "$TMP/floor.done" & + BROWSER_CHECK_LATENCY_LOG=$(mktemp "${TMPDIR:-/tmp}/codetrial-latency.XXXXXX") + export BROWSER_CHECK_FLOOR_LOG BROWSER_CHECK_LATENCY_LOG + # Dispatched agents log to this server; a Rust-mode agent has its own pipes. + if [ "$BROWSER_CHECK_AGENT" = dispatch ] && [ -z "${CODETRIAL_WEB_URL:-}" ]; then + node "$ROOT/scripts/floor-capture.cjs" "$SERVER_LOG" "$BROWSER_CHECK_FLOOR_LOG" "$TMP/floor.done" "$BROWSER_CHECK_LATENCY_LOG" & FLOOR_CAPTURE_PID=$! + elif [ "$BROWSER_CHECK_AGENT" = dispatch ]; then + printf '%s\n' 'codetrial capture_incomplete family=floor reason=external-server-log-unavailable' >> "$BROWSER_CHECK_FLOOR_LOG" + printf '%s\n' 'codetrial capture_incomplete family=latency reason=external-server-log-unavailable' >> "$BROWSER_CHECK_LATENCY_LOG" fi fi diff --git a/scripts/floor-capture.cjs b/scripts/floor-capture.cjs index d36d09696..425a7f81f 100644 --- a/scripts/floor-capture.cjs +++ b/scripts/floor-capture.cjs @@ -2,38 +2,192 @@ const fs = require("node:fs"); const { StringDecoder } = require("node:string_decoder"); -class FloorCapture { - constructor(path) { +const PREFIXES = { + floor: ["codetrial floor "], + latency: [ + "codetrial latency ", + "codetrial replay_gate ", + "interview clock: ", + "replacement start: ", + "replacement end: ", + ], +}; +const LINE_BYTES = 4096; + +class DiagnosticCapture { + constructor(path, family = "floor") { + if (!Object.hasOwn(PREFIXES, family)) + throw new Error("unknown diagnostic family"); this.path = path; + this.family = family; + this.prefixes = PREFIXES[family]; this.pending = ""; + this.pendingBytes = 0; + this.tail = ""; + this.diagnostic = false; this.decoder = new StringDecoder("utf8"); this.discarding = false; this.fd = null; + this.closed = false; + this.needsSeparator = false; + } + + write(line) { + if (this.closed) throw new Error("diagnostic capture is closed"); + this.fd ??= fs.openSync(this.path, "a", 0o600); + const bytes = Buffer.from((this.needsSeparator ? "\n" : "") + line); + try { + if (fs.writeSync(this.fd, bytes) !== bytes.length) + throw new Error("short diagnostic write"); + this.needsSeparator = false; + } catch (error) { + this.needsSeparator = true; + throw error; + } + } + + incomplete(reason) { + if (!/^[a-z][a-z0-9-]{0,63}$/.test(reason)) + throw new Error("invalid diagnostic failure category"); + this.write( + `codetrial capture_incomplete family=${this.family} reason=${reason}\n`, + ); } push(chunk) { + if (this.closed) throw new Error("diagnostic capture is closed"); const text = Buffer.isBuffer(chunk) ? this.decoder.write(chunk) : chunk; for (const part of text.match(/[^\n]*\n|[^\n]+$/g) ?? []) { const complete = part.endsWith("\n"); + const scanned = this.tail + part; + this.diagnostic ||= this.prefixes.some((prefix) => + scanned.includes(prefix), + ); + this.tail = scanned.slice(-32); if (!this.discarding) { - this.pending += part; - if (this.pending.length > 4096) this.discarding = true; + this.pendingBytes += Buffer.byteLength(part); + if (this.pendingBytes > LINE_BYTES) { + this.discarding = true; + this.pending = ""; + } else this.pending += part; } if (!complete) continue; - // One whole line per append write, so writers sharing the file never - // interleave. The page cache keeps it if this process is killed. - if (!this.discarding && this.pending.startsWith("codetrial floor ")) { - this.fd ??= fs.openSync(this.path, "a", 0o600); - fs.writeSync(this.fd, this.pending); + try { + if (this.diagnostic) { + if (this.discarding) this.incomplete("oversized-line"); + else if ( + !this.prefixes.some((prefix) => this.pending.startsWith(prefix)) + ) + this.incomplete("unframed-line"); + else if (this.pending.includes("\ufffd")) + this.incomplete("invalid-utf8"); + else this.write(this.pending); + } + } finally { + this.pending = ""; + this.pendingBytes = 0; + this.tail = ""; + this.diagnostic = false; + this.discarding = false; } + } + } + + discontinuity(reason) { + try { + this.incomplete(reason); + } finally { this.pending = ""; + this.pendingBytes = 0; + this.tail = ""; + this.diagnostic = false; this.discarding = false; + this.decoder = new StringDecoder("utf8"); } } close() { - if (this.fd !== null) fs.closeSync(this.fd); - this.fd = null; + if (this.closed) return; + try { + this.push(this.decoder.end()); + if ( + this.diagnostic || + (this.pending.length > 0 && + this.prefixes.some((prefix) => prefix.startsWith(this.pending))) + ) + this.incomplete( + this.discarding ? "oversized-line" : "unterminated-line", + ); + } finally { + this.closed = true; + if (this.fd !== null) fs.closeSync(this.fd); + this.fd = null; + } + } +} + +// Each pipe has its own line buffer. Completion includes every close/error +// path, so the caller can await drainage after stopping its own child group. +function captureDiagnosticStream(stream, paths) { + const captures = Object.entries(paths) + .filter(([, path]) => path) + .map(([family, path]) => new DiagnosticCapture(path, family)); + let failure = null; + const fail = (reason) => { + failure ??= reason; + for (const capture of captures) { + if (capture.closed) continue; + try { + capture.incomplete(reason); + } catch { + failure = "write-failed"; + } + } + }; + const closed = new Promise((resolve) => { + stream.on("data", (chunk) => { + if (failure) return; + try { + for (const capture of captures) capture.push(chunk); + } catch { + fail("write-failed"); + } + }); + stream.once("error", () => fail("stream-error")); + stream.once("close", () => { + for (const capture of captures) { + try { + capture.close(); + } catch { + failure = "write-failed"; + } + } + resolve(failure); + }); + }); + return { closed, incomplete: fail }; +} + +async function drainDiagnosticStreams(streams, timeoutMs = 5000) { + if (!streams.length) return; + let timer; + try { + const result = await Promise.race([ + Promise.all(streams.map((stream) => stream.closed)), + new Promise((resolve) => { + timer = setTimeout(() => resolve(null), timeoutMs); + }), + ]); + if (result === null) { + for (const stream of streams) stream.incomplete("drain-timeout"); + throw new Error( + "agent diagnostic pipes did not close before the drain deadline", + ); + } + if (result.some(Boolean)) + throw new Error("agent diagnostic capture failed"); + } finally { + clearTimeout(timer); } } @@ -69,25 +223,55 @@ function assertInterruptedOverlap(path, room) { } } -module.exports = { FloorCapture, assertInterruptedOverlap, readFloorRecords }; +module.exports = { + DiagnosticCapture, + captureDiagnosticStream, + drainDiagnosticStreams, + assertInterruptedOverlap, + readFloorRecords, +}; // The server owns dispatched-agent stderr. Follow from byte zero until cleanup, // including the bytes written after the browser exits or reports a failure. if (require.main === module) { - const [source, target, doneFile] = process.argv.slice(2); - const capture = new FloorCapture(target); + const [source, target, doneFile, latencyTarget] = process.argv.slice(2); + const captures = [new DiagnosticCapture(target)]; + if (latencyTarget) + captures.push(new DiagnosticCapture(latencyTarget, "latency")); let offset = 0; + let identity = null; + let missingReported = false; const parentPid = process.ppid; let stopDeadline = null; const buffer = Buffer.alloc(65536); - function poll() { - if (!fs.existsSync(source)) return; - const fd = fs.openSync(source, "r"); + function poll(final = false) { + let fd; + try { + fd = fs.openSync(source, "r"); + } catch (error) { + if (error.code !== "ENOENT") throw error; + if (!missingReported && (identity !== null || final)) { + for (const capture of captures) capture.discontinuity("source-missing"); + missingReported = true; + } + return; + } try { + const stat = fs.fstatSync(fd); + const nextIdentity = `${stat.dev}:${stat.ino}`; + if ( + (identity !== null && identity !== nextIdentity) || + stat.size < offset + ) { + for (const capture of captures) + capture.discontinuity("source-replaced-or-truncated"); + offset = 0; + } + identity = nextIdentity; let count; while ((count = fs.readSync(fd, buffer, 0, buffer.length, offset))) { offset += count; - capture.push(buffer.subarray(0, count)); + for (const capture of captures) capture.push(buffer.subarray(0, count)); } } finally { fs.closeSync(fd); @@ -95,17 +279,19 @@ if (require.main === module) { } const timer = setInterval(() => { poll(); - if ( - (doneFile && fs.existsSync(doneFile)) || - process.ppid !== parentPid || - (stopDeadline !== null && Date.now() >= stopDeadline) - ) - finish(); + if (doneFile && fs.existsSync(doneFile)) finish(); + else if (process.ppid !== parentPid) finish("parent-lost"); + else if (stopDeadline !== null && Date.now() >= stopDeadline) + finish("drain-timeout"); }, 50); - function finish() { + function finish(reason) { clearInterval(timer); - poll(); - process.exit(0); + poll(true); + for (const capture of captures) { + if (reason) capture.incomplete(reason); + capture.close(); + } + process.exit(reason ? 1 : 0); } function interrupted() { if (!doneFile) return finish(); diff --git a/scripts/rust-style-ceilings.json b/scripts/rust-style-ceilings.json index 339d0c964..c5579e26c 100644 --- a/scripts/rust-style-ceilings.json +++ b/scripts/rust-style-ceilings.json @@ -6,7 +6,7 @@ "src/agent/report.rs": 1730, "src/gemini.rs": 2838, "src/livekit.rs": 3572, - "src/livekit/session.rs": 3026, + "src/livekit/session.rs": 2956, "src/livekit/turn.rs": 2333, "tests/agent/framework.rs": 4640, "tests/agent/prompts.rs": 2380, diff --git a/src/livekit/floor.rs b/src/livekit/floor.rs index e6e91308d..d04d62278 100644 --- a/src/livekit/floor.rs +++ b/src/livekit/floor.rs @@ -19,6 +19,9 @@ pub(super) enum Event { #[derive(Debug, PartialEq, Eq)] pub(super) struct Record { pub seq: u64, + pub opened_at: Instant, + pub resolved_at: Option, + pub activity_end_at: Option, pub kind: &'static str, pub outcome: &'static str, pub gap_ms: Option, @@ -76,10 +79,13 @@ pub(super) struct FloorTracker { } impl FloorTracker { - fn record(&mut self, kind: &'static str) -> Record { + fn record(&mut self, kind: &'static str, now: Instant) -> Record { self.sequence += 1; Record { seq: self.sequence, + opened_at: now, + resolved_at: None, + activity_end_at: None, kind, outcome: "unresolved", gap_ms: None, @@ -124,6 +130,7 @@ impl FloorTracker { if let Some(mut pause) = self.pause.take() { if pause.record.outcome == "unresolved" { pause.record.outcome = "continue"; + pause.record.resolved_at = Some(now); pause.record.gap_ms = ms_since(now, pause.start); } else if pause .audio @@ -141,7 +148,7 @@ impl FloorTracker { emit(overlap.record); } if generating || !ahead.is_zero() { - let mut record = self.record("overlap"); + let mut record = self.record("overlap", now); record.playout_ahead_ms = Some(ahead.as_millis()); self.overlap = Some(Overlap { record, @@ -156,6 +163,7 @@ impl FloorTracker { && overlap.ended.is_none() { overlap.ended = Some(now); + overlap.record.activity_end_at = Some(now); overlap.record.overlap_ms = ms_since(now, overlap.start); } self.finish_overlap(emit); @@ -171,7 +179,7 @@ impl FloorTracker { if let Some(pause) = self.pause.take() { emit(pause.record); } - let record = self.record("pause"); + let record = self.record("pause", now); self.pause = Some(Pause { record, start: now, @@ -185,6 +193,7 @@ impl FloorTracker { if let Some(pause) = &mut self.pause { if first_output && pause.record.outcome == "unresolved" { pause.record.outcome = "respond"; + pause.record.resolved_at = Some(now); pause.record.gap_ms = ms_since(now, pause.start); } // `get_or_insert` keeps the generation's first chunk. @@ -198,6 +207,7 @@ impl FloorTracker { && overlap.record.outcome == "unresolved" { overlap.record.outcome = "interrupted"; + overlap.record.resolved_at = Some(now); } self.finish_overlap(emit); } @@ -220,6 +230,7 @@ impl FloorTracker { && overlap.record.outcome == "unresolved" { overlap.record.outcome = "continued"; + overlap.record.resolved_at = Some(now); overlap.drained = Some(now); } self.finish_overlap(emit); @@ -229,6 +240,7 @@ impl FloorTracker { self.active = false; if let Some(mut overlap) = self.overlap.take() { overlap.record.outcome = "unresolved"; + overlap.record.resolved_at = None; overlap.record.overlap_ms = None; emit(overlap.record); } @@ -242,6 +254,7 @@ impl FloorTracker { } if let Some(mut overlap) = self.overlap.take() { overlap.record.outcome = "unresolved"; + overlap.record.resolved_at = None; emit(overlap.record); } } diff --git a/src/livekit/latency.rs b/src/livekit/latency.rs index 0d56f127f..77da46415 100644 --- a/src/livekit/latency.rs +++ b/src/livekit/latency.rs @@ -242,6 +242,7 @@ pub(super) struct ReplyLatency { /// Wall-clock milliseconds at the anchor, `None` if the system clock reads /// before the epoch. start_unix_ms: Option, + anchor_uncertainty_ms: u64, /// The last whole minute a clock sample was logged for. sampled: u64, /// The last whole 30 second period a task sample was logged for. @@ -386,6 +387,33 @@ impl ReplyLatency { self.anchor.map(|anchor| offset_ms(now, anchor)) } + /// A fresh wall/monotonic pair for joining local harness observations. + /// Sampling delay and whole-millisecond rounding are uncertainty, not + /// drift. + pub(super) fn observation_clock(&self) -> Value { + let before = Instant::now(); + let unix = std::time::SystemTime::now() + .duration_since(std::time::UNIX_EPOCH) + .ok() + .map(crate::agent::saturating_ms); + self.observation_clock_at(before, unix, Instant::now()) + } + + fn observation_clock_at(&self, before: Instant, unix: Option, after: Instant) -> Value { + let sampling = after.checked_duration_since(before); + let uncertainty = self.start_unix_ms.zip(unix).and(sampling).map(|duration| { + self.anchor_uncertainty_ms + .saturating_add(crate::agent::saturating_ms(duration)) + .saturating_add(2) + }); + json!({ + "start_unix_ms": self.start_unix_ms, + "emitted_unix_ms": unix, + "emitted_ms": self.interview_ms(before), + "clock_uncertainty_ms": uncertainty, + }) + } + /// Starts a replacement episode and ties it to the reply still owed, which /// keeps its origin, start and number across the swap. Returns the episode /// number and that reply's obligation, if any. @@ -414,10 +442,13 @@ impl ReplyLatency { /// every sample so a log cut short or joined from two files still knows it. pub(super) fn anchor(&mut self, started: Instant) -> String { self.anchor = Some(started); + let sampling = Instant::now(); self.start_unix_ms = std::time::SystemTime::now() .checked_sub(started.elapsed()) .and_then(|at| at.duration_since(std::time::UNIX_EPOCH).ok()) .map(crate::agent::saturating_ms); + self.anchor_uncertainty_ms = + crate::agent::saturating_ms(sampling.elapsed()).saturating_add(2); self.sampled = 0; self.task_sampled = 0; self.clock_line(0, 0) @@ -938,7 +969,34 @@ impl ReplyLatency { Some(self.record("audio_accepted", now, Outcome::Open)) } + /// Unlike a reply trace, gate invalidation exists even with no output. + fn gate_boundary(&self, boundary: Boundary, now: Instant) -> Value { + json!({ + "event": "gate_boundary", "version": 1, + "pid": std::process::id(), "room": self.room, + "session": self.session, "socket": self.socket, + "turn": self.trace.as_ref().map(|trace| trace.turn), + "stage": boundary.label(), "interview_ms": self.interview_ms(now), + "clock": self.observation_clock(), + }) + } + pub(super) fn boundary(&mut self, boundary: Boundary, now: Instant) -> Option { + self.boundary_to(boundary, now, &mut std::io::stderr().lock()) + } + + fn boundary_to( + &mut self, + boundary: Boundary, + now: Instant, + output: &mut impl std::io::Write, + ) -> Option { + writeln!( + output, + "codetrial replay_gate {}", + self.gate_boundary(boundary, now) + ) + .expect("failed to write replay gate boundary"); if matches!(boundary, Boundary::Held) { self.voice_ended = false; self.voice_started = false; @@ -1036,6 +1094,7 @@ impl ReplyLatency { "tool_handler_ms": trace.tool_handler_ms, "context_tokens": self.context_tokens, "interview_ms": self.interview_ms(now), + "clock": self.observation_clock(), "obligation": owed.then_some(trace.turn), "obligation_outcome": owed.then(|| outcome.label()), "owed_start_interview_ms": self.interview_ms(trace.start).filter(|_| owed), diff --git a/src/livekit/session.rs b/src/livekit/session.rs index 2b5b4d2bc..3cf3a0e40 100644 --- a/src/livekit/session.rs +++ b/src/livekit/session.rs @@ -13,8 +13,14 @@ //! send them and go out from the parent, through [`send_model_text`], which is //! here because counting them is this half's job. +mod floor; +mod observations; mod recovery; +use floor::write_floor; +pub(super) use floor::{observe_floor, reconcile_floor}; +use observations::{HintCounters, ToolTiming, known_tool_name}; + use recovery::log_socket_pressure; pub(super) use recovery::{ apply_recovery_transcript, drain_retired_usage, prepare_input, prepare_listening_handoff, @@ -673,21 +679,6 @@ pub(super) fn accept_gemini_event( } } -/// A declared tool's name, never the model's text for an undeclared one. -fn known_tool_name(name: &str) -> &'static str { - [ - TOOL_READ_EDITOR, - TOOL_READ_BOARD, - TOOL_READ_CONVERSATION, - TOOL_LOG_HINT, - TOOL_RECORD_FRAMEWORK_EVIDENCE, - TOOL_END_INTERVIEW, - ] - .into_iter() - .find(|tool| *tool == name) - .unwrap_or("unknown") -} - /// Provider milestones are when the message arrived, not when the room loop /// got to it, so a busy loop is not charged to Gemini. fn received_at(gemini: &GeminiLiveSession) -> Instant { @@ -1045,6 +1036,7 @@ async fn on_tool_calls( let timed = !context.state.interviewer_silenced() && !context.activity.socket.discarding_output; let reviewed_revision = context.activity.substantive_revision_at_last_review; let tool_started = Instant::now(); + let hints_before = HintCounters::capture(context.state); let answers = execute_timed_tool_batch( context.state, context.activity, @@ -1091,23 +1083,19 @@ async fn on_tool_calls( // Gemini resumes the moment the responses land, so serializing them again // for the lines below waits until after the send. if !context.activity.socket.discarding_output && !context.state.interviewer_silenced() { - let batch_ms = crate::agent::saturating_ms(tool_started.elapsed()); - let mut timing = - context - .activity - .latency - .tool_response(Instant::now(), batch_ms, sent.is_ok()); - timing["tool_batch_ms"] = batch_ms.into(); - timing["tool_execute_ms"] = tool_execute_ms.into(); - timing["board_resend_ms"] = board_resend_ms.into(); - timing["tool_send_ms"] = tool_send_ms.into(); - timing["tool_count"] = answers.len().into(); - timing["tool_names"] = answers - .iter() - .map(|(call, _)| known_tool_name(&call.name)) - .collect::>() - .into(); - timing["sent"] = sent.is_ok().into(); + let timing = observations::tool_timing( + context.activity, + context.state, + &answers, + hints_before, + ToolTiming { + batch_ms: crate::agent::saturating_ms(tool_started.elapsed()), + execute_ms: tool_execute_ms, + board_ms: board_resend_ms, + send_ms: tool_send_ms, + sent: sent.is_ok(), + }, + ); latency::log(&timing); } for (call, response) in &answers { @@ -1378,64 +1366,6 @@ async fn on_input_transcript( Ok(()) } -/// Most events emit nothing, and some arrive per audio chunk or per loop step, -/// so the clock is only read when a record is written. -pub(super) fn observe_floor( - room: &str, - activity: &mut RuntimeActivity, - state: &RuntimeState, - event: super::floor::Event, -) { - write_floor( - room, - activity, - || log_clock(state), - event, - &mut std::io::stderr().lock(), - ); -} - -fn write_floor( - room: &str, - activity: &mut RuntimeActivity, - clock: impl Fn() -> String, - event: super::floor::Event, - output: &mut impl std::io::Write, -) { - let session = activity.live_session_id; - let socket = activity.live_socket; - // Read once, so every record one event emits carries the same `at`. - let mut at = None; - activity - .floor_tracker - .observe(event, Instant::now(), &mut |record| { - let at = at.get_or_insert_with(&clock); - writeln!(output, "{}", record.log_line(room, session, socket, at)) - .expect("failed to write floor observation"); - }); -} - -pub(super) fn reconcile_floor( - room: &str, - activity: &mut RuntimeActivity, - clock: impl Fn() -> String, - playing: bool, - output: &mut impl std::io::Write, -) { - if !activity.candidate_voice_active { - write_floor( - room, - activity, - &clock, - super::floor::Event::ActivityLost, - output, - ); - } - if !activity.generating && !playing { - write_floor(room, activity, &clock, super::floor::Event::Drained, output); - } -} - fn context_floor( room: &RoomLink, context: &mut GeminiEventContext<'_>, diff --git a/src/livekit/session/floor.rs b/src/livekit/session/floor.rs new file mode 100644 index 000000000..9b3ad62da --- /dev/null +++ b/src/livekit/session/floor.rs @@ -0,0 +1,75 @@ +//! Floor log emission, separate from the event state machine and turn policy. +use std::time::Instant; + +use crate::agent::RuntimeState; +use crate::livekit::floor::Event; +use crate::livekit::turn::RuntimeActivity; + +use super::log_clock; + +fn value(time: Option) -> String { + time.map_or_else(|| "unknown".into(), |n| n.to_string()) +} + +/// Most events emit nothing, and some arrive per audio chunk or per loop step, +/// so the clock is only read when a record is written. +pub(in crate::livekit) fn observe_floor( + room: &str, + activity: &mut RuntimeActivity, + state: &RuntimeState, + event: Event, +) { + write_floor( + room, + activity, + || log_clock(state), + event, + &mut std::io::stderr().lock(), + ); +} + +pub(super) fn write_floor( + room: &str, + activity: &mut RuntimeActivity, + clock: impl Fn() -> String, + event: Event, + output: &mut impl std::io::Write, +) { + let session = activity.live_session_id; + let socket = activity.live_socket; + let latency = &activity.latency; + let now = Instant::now(); + // Sampling is lazy: most events emit nothing, including audio chunks. + let mut at = None; + let mut sample = None; + activity.floor_tracker.observe(event, now, &mut |record| { + let at = at.get_or_insert_with(&clock); + let sample = sample.get_or_insert_with(|| latency.observation_clock()); + let number = |key: &str| value(sample[key].as_i64()); + let event_time = |at: Option| value(at.and_then(|at| latency.interview_ms(at))); + writeln!(output, "{} opened_ms={} resolved_ms={} activity_end_ms={} emitted_ms={} emitted_unix_ms={} start_unix_ms={} clock_uncertainty_ms={} pid={}", + record.log_line(room, session, socket, at), + event_time(Some(record.opened_at)), event_time(record.resolved_at), event_time(record.activity_end_at), + number("emitted_ms"), number("emitted_unix_ms"), number("start_unix_ms"), number("clock_uncertainty_ms"), std::process::id()) + .expect("failed to write floor observation"); + }); +} + +pub(in crate::livekit) fn reconcile_floor( + room: &str, + activity: &mut RuntimeActivity, + clock: impl Fn() -> String, + playing: bool, + output: &mut impl std::io::Write, +) { + if !activity.candidate_voice_active { + write_floor(room, activity, &clock, Event::ActivityLost, output); + } + if !activity.generating && !playing { + write_floor(room, activity, &clock, Event::Drained, output); + } +} + +#[cfg(test)] +#[path = "../../../tests/unit/livekit/session/floor.rs"] +mod tests; diff --git a/src/livekit/session/observations.rs b/src/livekit/session/observations.rs new file mode 100644 index 000000000..51551a3b8 --- /dev/null +++ b/src/livekit/session/observations.rs @@ -0,0 +1,91 @@ +//! Content-free tool context for the observational replay harness. +use std::time::Instant; + +use serde_json::Value; + +use crate::agent::RuntimeState; +use crate::gemini::GeminiFunctionCall; +use crate::livekit::turn::RuntimeActivity; +use crate::runtime::{ + TOOL_END_INTERVIEW, TOOL_LOG_HINT, TOOL_READ_BOARD, TOOL_READ_CONVERSATION, TOOL_READ_EDITOR, + TOOL_RECORD_FRAMEWORK_EVIDENCE, +}; + +/// A declared tool's name, never the model's text for an undeclared one. +pub(super) fn known_tool_name(name: &str) -> &'static str { + [ + TOOL_READ_EDITOR, + TOOL_READ_BOARD, + TOOL_READ_CONVERSATION, + TOOL_LOG_HINT, + TOOL_RECORD_FRAMEWORK_EVIDENCE, + TOOL_END_INTERVIEW, + ] + .into_iter() + .find(|tool| *tool == name) + .unwrap_or("unknown") +} + +pub(super) struct HintCounters { + rungs: usize, + volunteered: u32, +} + +impl HintCounters { + pub(super) fn capture(state: &RuntimeState) -> Self { + Self { + rungs: state.hint_rungs_given, + volunteered: state.volunteered_hints, + } + } + + fn advanced(&self, state: &RuntimeState) -> bool { + state.hint_rungs_given > self.rungs || state.volunteered_hints > self.volunteered + } +} + +pub(super) struct ToolTiming { + pub(super) batch_ms: u64, + pub(super) execute_ms: u64, + pub(super) board_ms: u64, + pub(super) send_ms: u64, + pub(super) sent: bool, +} + +pub(super) fn tool_timing( + activity: &mut RuntimeActivity, + state: &RuntimeState, + answers: &[(GeminiFunctionCall, Value)], + hints_before: HintCounters, + timing: ToolTiming, +) -> Value { + let mut record = activity + .latency + .tool_response(Instant::now(), timing.batch_ms, timing.sent); + record["tool_batch_ms"] = timing.batch_ms.into(); + record["tool_execute_ms"] = timing.execute_ms.into(); + record["board_resend_ms"] = timing.board_ms.into(); + record["tool_send_ms"] = timing.send_ms.into(); + record["tool_count"] = answers.len().into(); + record["tool_names"] = answers + .iter() + .map(|(call, _)| known_tool_name(&call.name)) + .collect::>() + .into(); + let accepted = answers + .iter() + .filter_map(|(call, response)| { + let name = known_tool_name(&call.name); + (name != "unknown" && response.get("error").is_none()).then_some(name) + }) + .collect::>(); + record["hint_given"] = + (accepted.contains(&TOOL_LOG_HINT) && hints_before.advanced(state)).into(); + record["accepted_tool_names"] = accepted.into(); + record["sent"] = timing.sent.into(); + record +} + +#[cfg(test)] +#[path = "../../../tests/unit/livekit/session/observations.rs"] +mod tests; diff --git a/tests/browser/browser-check-cleanup.test.js b/tests/browser/browser-check-cleanup.test.js new file mode 100644 index 000000000..9e8055e5d --- /dev/null +++ b/tests/browser/browser-check-cleanup.test.js @@ -0,0 +1,184 @@ +import assert from "node:assert/strict"; +import { test } from "node:test"; +import { PassThrough } from "node:stream"; +import fs from "node:fs"; +import os from "node:os"; +import path from "node:path"; +import { createRequire } from "node:module"; +import { withBackstop } from "./wait.js"; +const require = createRequire(import.meta.url); +const { + cleanupBrowserCheck, +} = require("../../scripts/browser-check-cleanup.cjs"); +const { captureDiagnosticStream } = require("../../scripts/floor-capture.cjs"); +const { BudgetDenied } = require("../../scripts/run-budget-guard.cjs"); + +const finish = (options) => + withBackstop(cleanupBrowserCheck(options), "browser check cleanup"); + +function failedStream(t) { + const dir = fs.mkdtempSync(path.join(os.tmpdir(), "check-cleanup-")); + t.after(() => fs.rmSync(dir, { recursive: true, force: true })); + const stream = new PassThrough(); + const capture = captureDiagnosticStream(stream, { + floor: path.join(dir, "floor.log"), + }); + stream.destroy(new Error("synthetic pipe failure")); + return capture; +} + +test("a pipe drain failure remains the cause while later resources are still closed", async (t) => { + const calls = []; + const capture = failedStream(t); + const cleanup = finish({ + stopAgent: async () => { + calls.push("agent"); + }, + streams: [capture], + compilerExplorerMock: { + server: { + close(callback) { + calls.push("mock"); + callback(new Error("later mock error")); + }, + }, + }, + browser: { + async close() { + calls.push("browser"); + throw new Error("later browser error"); + }, + }, + operationFailed: false, + }); + await assert.rejects(cleanup, /agent diagnostic capture failed/); + assert.deepEqual(calls, ["agent", "mock", "browser"]); +}); + +test("a failed stop cannot skip waiting for pipe drainage and later cleanup", async (t) => { + const dir = fs.mkdtempSync(path.join(os.tmpdir(), "check-cleanup-drain-")); + t.after(() => fs.rmSync(dir, { recursive: true, force: true })); + const stream = new PassThrough(); + t.after(() => stream.destroy()); + const capture = captureDiagnosticStream(stream, { + floor: path.join(dir, "floor.log"), + }); + const calls = []; + const first = new Error("stop failed"); + const cleanup = finish({ + stopAgent: async () => { + calls.push("agent"); + throw first; + }, + streams: [capture], + compilerExplorerMock: { + server: { + close(callback) { + calls.push("mock"); + callback(); + }, + }, + }, + browser: { + async close() { + calls.push("browser"); + }, + }, + operationFailed: false, + }); + let settled = false; + cleanup.then( + () => { + settled = true; + }, + () => { + settled = true; + }, + ); + const rejected = assert.rejects(cleanup, (error) => error === first); + // Flush queued promise work; the pipe is deliberately still open. + await new Promise((resolve) => setImmediate(resolve)); + assert.equal(settled, false); + assert.deepEqual(calls, ["agent"]); + stream.end(); + await rejected; + assert.deepEqual(calls, ["agent", "mock", "browser"]); +}); + +test("the real budget error survives multiple cleanup errors without printing private errors", async (t) => { + const printed = []; + t.mock.method(console, "error", (message) => printed.push(message)); + const primary = new BudgetDenied("synthetic budget denial"); + const calls = []; + const run = async () => { + try { + throw primary; + } finally { + await finish({ + stopAgent: async () => { + calls.push("agent"); + throw new Error("private stop detail"); + }, + streams: [failedStream(t)], + compilerExplorerMock: { + server: { + close(callback) { + calls.push("mock"); + callback(new Error("private mock detail")); + }, + }, + }, + browser: { + async close() { + calls.push("browser"); + throw new Error("private browser detail"); + }, + }, + operationFailed: true, + }); + } + }; + await assert.rejects( + run(), + (error) => error === primary && error instanceof BudgetDenied, + ); + assert.deepEqual(calls, ["agent", "mock", "browser"]); + assert.deepEqual(printed, [ + "browser check cleanup also failed after the run failed", + ]); +}); + +test("successful cleanup waits for the mock close callback before closing the browser", async () => { + const calls = []; + let released; + let ready; + const waiting = new Promise((resolve) => { + ready = resolve; + }); + const cleanup = finish({ + stopAgent: async () => { + calls.push("agent"); + }, + streams: [], + compilerExplorerMock: { + server: { + close(callback) { + calls.push("mock"); + released = callback; + ready(); + }, + }, + }, + browser: { + async close() { + calls.push("browser"); + }, + }, + operationFailed: false, + }); + await withBackstop(waiting, "the mock close request"); + assert.deepEqual(calls, ["agent", "mock"]); + released(); + await cleanup; + assert.deepEqual(calls, ["agent", "mock", "browser"]); +}); diff --git a/tests/browser/diagnostic-capture.test.js b/tests/browser/diagnostic-capture.test.js new file mode 100644 index 000000000..236360db0 --- /dev/null +++ b/tests/browser/diagnostic-capture.test.js @@ -0,0 +1,416 @@ +import assert from "node:assert/strict"; +import { test } from "node:test"; +import fs from "node:fs"; +import os from "node:os"; +import path from "node:path"; +import { PassThrough } from "node:stream"; +import { spawn } from "node:child_process"; +import { createRequire } from "node:module"; +import { until, withBackstop } from "./wait.js"; +const require = createRequire(import.meta.url); +const { + DiagnosticCapture, + captureDiagnosticStream, + drainDiagnosticStreams, +} = require("../../scripts/floor-capture.cjs"); +const floorLine = + "codetrial floor room=synthetic session=1 socket=1 seq=1 kind=overlap outcome=continued\n"; +const latencyLine = + 'codetrial latency {"room":"synthetic","stage":"tool_response","tool_names":["log_hint"],"sent":true}\n'; +const gateLine = + 'codetrial replay_gate {"event":"gate_boundary","version":1,"stage":"interrupted","room":"synthetic","session":1,"socket":1}\n'; +const clockLine = + "interview clock: pid=1 session=1 start_unix_ms=10000 elapsed_ms=0 sample=0 room=synthetic\n"; +function fixture(t) { + const dir = fs.mkdtempSync(path.join(os.tmpdir(), "diagnostic-capture-")); + t.after(() => fs.rmSync(dir, { recursive: true, force: true })); + const floor = path.join(dir, "floor.log"); + const latency = path.join(dir, "latency.log"); + fs.writeFileSync(floor, "", { mode: 0o600 }); + fs.writeFileSync(latency, "", { mode: 0o600 }); + return { dir, floor, latency }; +} +const read = (file) => fs.readFileSync(file, "utf8"); + +test("floor and full latency/clock/replacement lines stay separate, without unrelated output", (t) => { + const f = fixture(t); + const floor = new DiagnosticCapture(f.floor); + const latency = new DiagnosticCapture(f.latency, "latency"); + const replacements = + "replacement start: session=1 room=synthetic\nreplacement end: session=1 room=synthetic\n"; + const text = + floorLine + + "private unrelated output\n".repeat(2000) + + clockLine + + latencyLine + + gateLine + + replacements; + for (let i = 0; i < text.length; i += 7) { + floor.push(Buffer.from(text.slice(i, i + 7))); + latency.push(Buffer.from(text.slice(i, i + 7))); + } + floor.close(); + latency.close(); + assert.equal(read(f.floor), floorLine); + assert.equal( + read(f.latency), + clockLine + latencyLine + gateLine + replacements, + ); + assert.equal(fs.statSync(f.latency).mode & 0o777, 0o600); +}); + +test("the byte boundary includes the newline, and oversized diagnostics leave no content", (t) => { + const f = fixture(t); + const capture = new DiagnosticCapture(f.floor); + const exact = + "codetrial floor " + + "x".repeat(4096 - "codetrial floor ".length - 1) + + "\n"; + capture.push(exact); + capture.push(exact.slice(0, -1) + "x\n"); + capture.push("private".repeat(5000) + "\n"); + capture.close(); + assert.equal( + read(f.floor), + exact + "codetrial capture_incomplete family=floor reason=oversized-line\n", + ); +}); + +test("overflow detection finds diagnostic prefixes split after a long non-diagnostic prefix", (t) => { + const f = fixture(t); + const capture = new DiagnosticCapture(f.latency, "latency"); + capture.push("private".repeat(2000) + "codetrial lat"); + capture.push("ency secret-not-retained\n"); + capture.close(); + assert.equal( + read(f.latency), + "codetrial capture_incomplete family=latency reason=oversized-line\n", + ); +}); + +test("EOF and invalid UTF-8 cannot silently discard a diagnostic", (t) => { + const f = fixture(t); + const capture = new DiagnosticCapture(f.latency, "latency"); + // A two-byte fixture splits the decoder in the middle of a code point. + const valid = Buffer.from('codetrial latency {"fixture":"λ"}\n'); + const split = valid.indexOf(Buffer.from("λ")) + 1; + capture.push(valid.subarray(0, split)); + capture.push(valid.subarray(split)); + capture.push( + Buffer.concat([ + Buffer.from("codetrial latency "), + Buffer.from([0xff]), + Buffer.from("\n"), + ]), + ); + capture.push("log-level " + clockLine); + capture.push( + Buffer.concat([Buffer.from("codetrial latency "), Buffer.from([0xe2])]), + ); + capture.close(); + capture.close(); + assert.equal( + read(f.latency), + valid.toString() + + "codetrial capture_incomplete family=latency reason=invalid-utf8\n" + + "codetrial capture_incomplete family=latency reason=unframed-line\n" + + "codetrial capture_incomplete family=latency reason=unterminated-line\n", + ); + assert.throws(() => capture.push(latencyLine), /closed/); +}); + +test("oversized unterminated diagnostics are marked once and unrelated EOF is excluded", (t) => { + const f = fixture(t); + const capture = new DiagnosticCapture(f.floor); + capture.push("codetrial floor " + "x".repeat(5000)); + capture.close(); + capture.close(); + assert.equal( + read(f.floor), + "codetrial capture_incomplete family=floor reason=oversized-line\n", + ); + const other = new DiagnosticCapture(f.latency, "latency"); + other.push("unrelated private partial"); + other.close(); + assert.equal(read(f.latency), ""); +}); + +test("two pipe buffers preserve their own split lines in one append file", async (t) => { + const f = fixture(t); + const first = new PassThrough(); + const second = new PassThrough(); + const captures = [first, second].map((s) => + captureDiagnosticStream(s, { floor: f.floor, latency: f.latency }), + ); + first.write("codetrial fl"); + second.write("codetrial lat"); + first.end("oor " + floorLine.slice("codetrial floor ".length)); + second.end("ency " + latencyLine.slice("codetrial latency ".length)); + await drainDiagnosticStreams(captures); + assert.equal(read(f.floor), floorLine); + assert.equal(read(f.latency), latencyLine); +}); + +test("stream errors and write failures make drainage fail", async (t) => { + const f = fixture(t); + const stream = new PassThrough(); + const capture = captureDiagnosticStream(stream, { + floor: f.floor, + latency: f.latency, + }); + stream.destroy(new Error("synthetic stream failure")); + await assert.rejects(drainDiagnosticStreams([capture]), /capture failed/); + assert.match(read(f.floor), /reason=stream-error/); + assert.equal(read(f.floor).includes("synthetic stream failure"), false); + const bad = new PassThrough(); + const failed = captureDiagnosticStream(bad, { + floor: path.join(f.dir, "missing", "floor.log"), + }); + bad.end(floorLine); + await assert.rejects(drainDiagnosticStreams([failed]), /capture failed/); +}); + +test("a short write cannot be reported as a complete retained line", async (t) => { + const f = fixture(t); + const original = fs.writeSync; + let writes = 0; + t.mock.method(fs, "writeSync", (fd, bytes) => + original(fd, ++writes === 1 ? bytes.subarray(0, bytes.length - 1) : bytes), + ); + const stream = new PassThrough(); + const capture = captureDiagnosticStream(stream, { floor: f.floor }); + stream.end(floorLine); + await assert.rejects(drainDiagnosticStreams([capture]), /capture failed/); + assert.equal( + read(f.floor), + floorLine + + "codetrial capture_incomplete family=floor reason=write-failed\n", + ); +}); + +test("an unclosed pipe leaves a marker and fails a bounded drain", async (t) => { + const f = fixture(t); + const stream = new PassThrough(); + t.after(() => stream.destroy()); + const capture = captureDiagnosticStream(stream, { + floor: f.floor, + latency: f.latency, + }); + await assert.rejects(drainDiagnosticStreams([capture], 1), /drain deadline/); + assert.match(read(f.floor), /reason=drain-timeout/); + assert.match(read(f.latency), /reason=drain-timeout/); + stream.end(); + await capture.closed; +}); + +test("the real child pipes drain final diagnostics after targeted shutdown", async (t) => { + const f = fixture(t); + const script = `process.on('SIGTERM',()=>{process.stderr.write(${JSON.stringify(latencyLine + gateLine)});process.stdout.write(${JSON.stringify(floorLine)});process.exitCode=0;clearInterval(timer);});const timer=setInterval(()=>{},1000);process.stderr.write(${JSON.stringify(clockLine)});`; + const child = spawn(process.execPath, ["-e", script]); + t.after(() => child.kill("SIGKILL")); + const captures = [child.stdout, child.stderr].map((s) => + captureDiagnosticStream(s, { floor: f.floor, latency: f.latency }), + ); + await until( + () => read(f.latency).includes("sample=0"), + "the real child to start diagnostics", + ); + child.kill("SIGTERM"); + await withBackstop( + drainDiagnosticStreams(captures), + "the child pipes to drain", + ); + assert.equal(read(f.floor), floorLine); + assert.equal(read(f.latency), clockLine + latencyLine + gateLine); +}); + +test("server follower keeps both files through teardown and marks trailing diagnostics", async (t) => { + const f = fixture(t); + const source = path.join(f.dir, "server.log"); + const done = path.join(f.dir, "done"); + fs.writeFileSync(source, floorLine + clockLine); + const child = spawn(process.execPath, [ + "scripts/floor-capture.cjs", + source, + f.floor, + done, + f.latency, + ]); + t.after(() => child.kill("SIGKILL")); + const closed = new Promise((resolve, reject) => { + child.once("error", reject); + child.once("exit", (code) => + code === 0 ? resolve() : reject(new Error(`capture exit ${code}`)), + ); + }); + await until( + () => read(f.latency).includes("sample=0"), + "follower clock retention", + ); + fs.appendFileSync(source, latencyLine + gateLine + "codetrial floor partial"); + fs.writeFileSync(done, ""); + await withBackstop(closed, "the follower final drain"); + assert.equal(read(f.latency), clockLine + latencyLine + gateLine); + assert.equal( + read(f.floor), + floorLine + + "codetrial capture_incomplete family=floor reason=unterminated-line\n", + ); +}); + +test("multibyte byte limits reject character-count substitution across UTF-8 splits", (t) => { + const f = fixture(t); + const capture = new DiagnosticCapture(f.latency, "latency"); + // Two-byte code points make a character count weaker than the byte cap. + const prefix = "codetrial latency "; + const count = Math.floor((4096 - prefix.length - 1) / 2); + const exact = Buffer.from( + prefix + + "λ".repeat(count) + + "x".repeat((4096 - prefix.length - 1) % 2) + + "\n", + ); + assert.equal(exact.length, 4096); + const split = prefix.length + 1; + capture.push(exact.subarray(0, split)); + capture.push(exact.subarray(split)); + capture.push(Buffer.concat([exact.subarray(0, -1), Buffer.from("x\n")])); + capture.close(); + assert.equal( + read(f.latency), + exact.toString() + + "codetrial capture_incomplete family=latency reason=oversized-line\n", + ); +}); + +test("an EOF fragment of a known prefix leaves an incomplete marker", (t) => { + const f = fixture(t); + for (const fragment of [ + "codetrial latency", + "codetrial lat", + "interview clock:", + ]) { + fs.writeFileSync(f.latency, ""); + const capture = new DiagnosticCapture(f.latency, "latency"); + capture.push(fragment); + capture.close(); + assert.equal( + read(f.latency), + "codetrial capture_incomplete family=latency reason=unterminated-line\n", + ); + } +}); + +async function follower(t, f, initial) { + const source = path.join(f.dir, "server.log"); + const done = path.join(f.dir, "done"); + fs.writeFileSync(source, initial); + const child = spawn(process.execPath, [ + "scripts/floor-capture.cjs", + source, + f.floor, + done, + f.latency, + ]); + t.after(() => child.kill("SIGKILL")); + const exited = new Promise((resolve, reject) => { + child.once("error", reject); + child.once("exit", resolve); + }); + await until( + () => read(f.floor).includes("seq=1"), + "follower initial floor retention", + ); + return { source, done, child, exited }; +} + +test("source shrink and rotation cannot splice private new-source text into an old diagnostic", async (t) => { + for (const rotate of [false, true]) { + const f = fixture(t); + const initial = Buffer.concat([ + Buffer.from(floorLine + "codetrial latency " + "x".repeat(200)), + Buffer.from([0xe2]), + ]); + const run = await follower(t, f, initial); + if (rotate) fs.renameSync(run.source, run.source + ".old"); + fs.writeFileSync(run.source, "UNRELATED_PRIVATE_TEXT\n" + clockLine); + fs.writeFileSync(run.done, ""); + assert.equal( + await withBackstop(run.exited, "follower changed source drainage"), + 0, + ); + assert.equal( + read(f.latency), + "codetrial capture_incomplete family=latency reason=source-replaced-or-truncated\n" + + clockLine, + ); + assert.equal(read(f.latency).includes("UNRELATED_PRIVATE_TEXT"), false); + assert.equal( + read(f.floor).includes("reason=source-replaced-or-truncated"), + true, + ); + } +}); + +test("a source lost after retention is marked incomplete during final drainage", async (t) => { + const f = fixture(t); + const run = await follower(t, f, floorLine); + fs.unlinkSync(run.source); + fs.writeFileSync(run.done, ""); + assert.equal( + await withBackstop(run.exited, "follower missing source drainage"), + 0, + ); + assert.match(read(f.floor), /reason=source-missing/); + assert.match(read(f.latency), /reason=source-missing/); +}); + +test("the follower cannot report a completed drain when its completion marker never arrives", async (t) => { + const f = fixture(t); + const run = await follower(t, f, floorLine); + run.child.kill("SIGTERM"); + assert.equal( + await withBackstop(run.exited, "follower abandoned drainage", 15000), + 1, + ); + assert.match(read(f.floor), /reason=drain-timeout/); + assert.match(read(f.latency), /reason=drain-timeout/); +}); + +test("a failed discontinuity marker still clears old text and decoder state", (t) => { + const f = fixture(t); + const capture = new DiagnosticCapture(f.latency, "latency"); + capture.push( + Buffer.concat([Buffer.from("codetrial latency old"), Buffer.from([0xe2])]), + ); + const original = fs.writeSync; + const mock = t.mock.method(fs, "writeSync", () => { + throw new Error("synthetic full disk"); + }); + assert.throws( + () => capture.discontinuity("source-replaced-or-truncated"), + /full disk/, + ); + mock.mock.restore(); + assert.equal(fs.writeSync, original); + capture.push("UNRELATED_PRIVATE_TEXT\n" + clockLine); + capture.close(); + assert.equal(read(f.latency).trimStart(), clockLine); + assert.equal(read(f.latency).includes("PRIVATE"), false); +}); + +test("an oversized incomplete UTF-8 diagnostic at EOF still leaves a marker", (t) => { + const f = fixture(t); + const capture = new DiagnosticCapture(f.latency, "latency"); + capture.push( + Buffer.concat([ + Buffer.from("codetrial latency " + "x".repeat(5000)), + Buffer.from([0xe2]), + ]), + ); + capture.close(); + assert.equal( + read(f.latency), + "codetrial capture_incomplete family=latency reason=oversized-line\n", + ); +}); diff --git a/tests/browser/floor-capture.test.js b/tests/browser/floor-capture.test.js index df801f25c..2e0dabb7c 100644 --- a/tests/browser/floor-capture.test.js +++ b/tests/browser/floor-capture.test.js @@ -8,7 +8,7 @@ import { createRequire } from "node:module"; import { until, withBackstop } from "./wait.js"; const require = createRequire(import.meta.url); const { - FloorCapture, + DiagnosticCapture, assertInterruptedOverlap, readFloorRecords, } = require("../../scripts/floor-capture.cjs"); @@ -30,7 +30,7 @@ const persisted = (target) => test("split lines survive rolling-buffer overflow and exclude other output", (t) => { const { target } = fixture(t); - const capture = new FloorCapture(target); + const capture = new DiagnosticCapture(target); capture.push(Buffer.from(line.slice(0, 15))); capture.push(Buffer.from(line.slice(15))); capture.push("x".repeat(20000) + "\nprivate unrelated output\n"); @@ -180,5 +180,8 @@ test("orphaned follower exits when its shell parent disappears", async (t) => { }); parent.kill("SIGKILL"); await withBackstop(closed, "the orphaned follower to release its pipes"); - assert.equal(fs.readFileSync(target, "utf8"), line); + assert.equal( + fs.readFileSync(target, "utf8"), + line + "codetrial capture_incomplete family=floor reason=parent-lost\n", + ); }); diff --git a/tests/unit/livekit/floor.rs b/tests/unit/livekit/floor.rs index 280011620..a5be40d26 100644 --- a/tests/unit/livekit/floor.rs +++ b/tests/unit/livekit/floor.rs @@ -313,3 +313,129 @@ fn completed_tool_only_response_cannot_borrow_a_later_generations_audio() { assert_eq!(records[0].gap_ms, Some(100)); assert_eq!(records[0].suspect, None); } + +#[test] +fn deferred_pause_retains_its_opening_and_first_resolution() { + let records = run(vec![ + (10, Event::End), + (30, Event::Output { audio: false }), + (50, Event::Output { audio: true }), + (200, Event::Output { audio: true }), + (1000, Event::Reset), + ]); + assert_eq!(records.len(), 1); + let record = &records[0]; + assert_eq!(record.kind, "pause"); + assert_eq!(record.outcome, "respond"); + assert_eq!( + record.resolved_at.unwrap().duration_since(record.opened_at), + Duration::from_millis(20) + ); + assert_eq!(record.activity_end_at, None); +} + +#[test] +fn overlap_resolution_and_candidate_end_keep_distinct_clocks() { + for (resolve, end) in [(100, 500), (700, 500)] { + let mut events = vec![(0, start())]; + if resolve < end { + events.push((resolve, Event::Interrupted)); + } + events.push((end, Event::End)); + if resolve > end { + events.push((resolve, Event::Interrupted)); + } + events.push((1000, Event::Reset)); + let records = run(events); + let record = records.iter().find(|r| r.kind == "overlap").unwrap(); + assert_eq!( + record.resolved_at.unwrap().duration_since(record.opened_at), + Duration::from_millis(resolve) + ); + assert_eq!( + record + .activity_end_at + .unwrap() + .duration_since(record.opened_at), + Duration::from_millis(end) + ); + } +} + +#[test] +fn continuation_resolves_at_drain_without_borrowing_the_emission_time() { + let records = run(vec![ + (0, start()), + (100, Event::Complete { playing: true }), + (200, Event::Drained), + (500, Event::End), + ]); + let record = records.iter().find(|r| r.kind == "overlap").unwrap(); + assert_eq!(record.outcome, "continued"); + assert_eq!( + record.resolved_at.unwrap().duration_since(record.opened_at), + Duration::from_millis(200) + ); + assert_eq!( + record + .activity_end_at + .unwrap() + .duration_since(record.opened_at), + Duration::from_millis(500) + ); +} + +#[test] +fn loss_and_reset_clear_resolution_of_an_overlap_with_no_end() { + for event in [Event::Reset, Event::ActivityLost] { + let records = run(vec![(0, start()), (100, Event::Interrupted), (200, event)]); + assert_eq!(records.len(), 1); + assert_eq!(records[0].outcome, "unresolved"); + assert_eq!(records[0].resolved_at, None); + assert_eq!(records[0].activity_end_at, None); + } +} + +#[test] +fn resumed_pause_keeps_the_end_to_start_resolution_clock() { + let records = run(vec![ + (0, Event::End), + ( + 250, + Event::Start { + generating: false, + ahead: Duration::ZERO, + }, + ), + (600, Event::Reset), + ]); + assert_eq!(records.len(), 1); + assert_eq!(records[0].outcome, "continue"); + assert_eq!( + records[0] + .resolved_at + .unwrap() + .duration_since(records[0].opened_at), + Duration::from_millis(250) + ); +} + +#[test] +fn loss_after_end_does_not_clear_an_already_ended_overlap() { + let records = run(vec![ + (0, start()), + (100, Event::End), + (200, Event::ActivityLost), + (300, Event::Drained), + ]); + let record = records.iter().find(|r| r.kind == "overlap").unwrap(); + assert_eq!(record.outcome, "continued"); + assert_eq!(record.overlap_ms, Some(100)); + assert_eq!( + record + .activity_end_at + .unwrap() + .duration_since(record.opened_at), + Duration::from_millis(100) + ); +} diff --git a/tests/unit/livekit/latency.rs b/tests/unit/livekit/latency.rs index d63c53bdb..1c0015d79 100644 --- a/tests/unit/livekit/latency.rs +++ b/tests/unit/livekit/latency.rs @@ -1456,3 +1456,26 @@ fn a_reply_already_answered_is_not_owed_to_a_later_episode() { } include!("latency_parts/mic_mapping_and_mic_gaps.rs"); + +#[test] +fn observation_clock_pairs_bound_sampling_and_rounding_on_one_anchor() { + let (start, mut trace) = traced(); + let unanchored = trace.observation_clock_at(start, Some(10000), start); + assert!(unanchored["emitted_ms"].is_null()); + assert!(unanchored["clock_uncertainty_ms"].is_null()); + trace.anchor = Some(start); + trace.start_unix_ms = Some(10000); + trace.anchor_uncertainty_ms = 2; + let sample = trace.observation_clock_at(ms(start, 100), Some(10100), ms(start, 103)); + assert_eq!(sample["start_unix_ms"], 10000); + assert_eq!(sample["emitted_ms"], 100); + assert_eq!(sample["emitted_unix_ms"], 10100); + assert_eq!(sample["clock_uncertainty_ms"], 7); + let absent_wall = trace.observation_clock_at(start, None, start); + assert!(absent_wall["clock_uncertainty_ms"].is_null()); + let reversed = trace.observation_clock_at(ms(start, 1), Some(10001), start); + assert!(reversed["clock_uncertainty_ms"].is_null()); +} + +#[path = "latency/gates.rs"] +mod gates; diff --git a/tests/unit/livekit/latency/gates.rs b/tests/unit/livekit/latency/gates.rs new file mode 100644 index 000000000..4a6939a68 --- /dev/null +++ b/tests/unit/livekit/latency/gates.rs @@ -0,0 +1,37 @@ +use super::*; + +#[test] +fn gate_invalidation_exists_without_a_trace_for_every_boundary() { + let (start, mut trace) = traced(); + trace.anchor(start); + for (boundary, stage) in [ + (Boundary::TurnComplete, "turn_complete"), + (Boundary::Interrupted, "interrupted"), + (Boundary::Held, "held"), + (Boundary::SocketReplaced, "socket_replaced"), + ] { + let mut output = Vec::new(); + assert!( + trace + .boundary_to(boundary, ms(start, 50), &mut output) + .is_none() + ); + let text = String::from_utf8(output).unwrap(); + assert_eq!(text.lines().count(), 1); + let event: Value = serde_json::from_str( + text.trim_end() + .strip_prefix("codetrial replay_gate ") + .unwrap(), + ) + .unwrap(); + assert_eq!(event["event"], "gate_boundary"); + assert_eq!(event["version"], 1); + assert_eq!(event["stage"], stage); + assert_eq!(event["room"], "room"); + assert_eq!(event["session"], 4); + assert_eq!(event["socket"], 1); + assert!(event["turn"].is_null()); + assert_eq!(event["interview_ms"], 50); + assert!(event["clock"]["emitted_unix_ms"].as_u64().is_some()); + } +} diff --git a/tests/unit/livekit/session/floor.rs b/tests/unit/livekit/session/floor.rs new file mode 100644 index 000000000..709c5a37f --- /dev/null +++ b/tests/unit/livekit/session/floor.rs @@ -0,0 +1,85 @@ +use super::*; +use std::collections::HashMap; +use std::time::Duration; + +fn fields(line: &str) -> HashMap<&str, &str> { + line.split_whitespace() + .filter_map(|s| s.split_once('=')) + .collect() +} + +#[test] +fn emitted_floor_retains_precise_times_of_a_pause_resolved_before_teardown() { + let start = Instant::now() - Duration::from_secs(1); + let mut activity = RuntimeActivity::for_interview(start, 0, 123); + activity.latency.bind("synthetic", 123, 1, 1500); + activity.latency.anchor(start); + activity + .floor_tracker + .observe(Event::End, start + Duration::from_millis(100), &mut |_| { + panic!("pause must remain pending") + }); + activity.floor_tracker.observe( + Event::Output { audio: false }, + start + Duration::from_millis(250), + &mut |_| panic!("responded pause emits at a later boundary"), + ); + let mut output = Vec::new(); + write_floor( + "synthetic", + &mut activity, + || "coarse-clock".into(), + Event::Reset, + &mut output, + ); + let text = String::from_utf8(output).unwrap(); + let row = fields(&text); + assert_eq!(row["opened_ms"], "100"); + assert_eq!(row["resolved_ms"], "250"); + assert_eq!(row["activity_end_ms"], "unknown"); + assert!(row["emitted_ms"].parse::().unwrap() >= 1000); + assert!(row["start_unix_ms"].parse::().unwrap() > 0); + assert!(row["clock_uncertainty_ms"].parse::().unwrap() >= 4); + assert_eq!(row["pid"], std::process::id().to_string()); + assert_eq!(row["session"], "123"); + assert_eq!(row["socket"], "1"); +} + +#[test] +fn missing_anchor_does_not_fabricate_a_clock_from_runtime_state() { + let start = Instant::now(); + let mut activity = RuntimeActivity::for_interview(start, 0, 123); + let mut output = Vec::new(); + write_floor( + "synthetic", + &mut activity, + || "0:00".into(), + Event::End, + &mut output, + ); + write_floor( + "synthetic", + &mut activity, + || "0:00".into(), + Event::Output { audio: false }, + &mut output, + ); + write_floor( + "synthetic", + &mut activity, + || "0:00".into(), + Event::Reset, + &mut output, + ); + let text = String::from_utf8(output).unwrap(); + let row = fields(&text); + for key in [ + "opened_ms", + "resolved_ms", + "emitted_ms", + "start_unix_ms", + "clock_uncertainty_ms", + ] { + assert_eq!(row[key], "unknown", "{key}"); + } +} diff --git a/tests/unit/livekit/session/observations.rs b/tests/unit/livekit/session/observations.rs new file mode 100644 index 000000000..487a20c00 --- /dev/null +++ b/tests/unit/livekit/session/observations.rs @@ -0,0 +1,86 @@ +use super::*; +use crate::livekit::session::execute_tool_call; +use serde_json::json; + +fn call(name: &str, requested: bool) -> GeminiFunctionCall { + GeminiFunctionCall { + id: "synthetic".into(), + name: name.into(), + args: json!({"requested": requested}), + } +} + +fn timing(sent: bool) -> ToolTiming { + ToolTiming { + batch_ms: 10, + execute_ms: 2, + board_ms: 3, + send_ms: 4, + sent, + } +} + +#[test] +fn only_declared_error_free_responses_are_accepted_but_send_status_stays_separate() { + let state = RuntimeState::default(); + let mut activity = RuntimeActivity::for_interview(Instant::now(), 0, 4); + activity.latency.bind("synthetic", 4, 1, 1500); + let answers = vec![ + (call(TOOL_READ_EDITOR, true), json!({"result":"synthetic"})), + (call(TOOL_READ_BOARD, true), json!({"error":"disabled"})), + ( + call("unknown_private_text", true), + json!({"result":"ignored"}), + ), + ]; + for sent in [false, true] { + let record = tool_timing( + &mut activity, + &state, + &answers, + HintCounters::capture(&state), + timing(sent), + ); + assert_eq!(record["accepted_tool_names"], json!([TOOL_READ_EDITOR])); + assert_eq!(record["sent"], sent); + assert!(!record.to_string().contains("unknown_private_text")); + assert_eq!(record["hint_given"], false); + assert_eq!(record["tool_execute_ms"], 2); + assert_eq!(record["board_resend_ms"], 3); + assert_eq!(record["tool_send_ms"], 4); + } +} + +#[test] +fn hint_context_distinguishes_released_volunteered_withheld_and_exhausted_calls() { + for (ladder, requested, expected) in [ + (&["first", "last"][..], true, true), + (&["last"][..], true, false), + (&[][..], true, false), + (&[][..], false, true), + ] { + let mut state = RuntimeState { + hint_ladder: ladder, + ..RuntimeState::default() + }; + let before = HintCounters::capture(&state); + let call = call(TOOL_LOG_HINT, requested); + let response = execute_tool_call(&mut state, &call); + let mut activity = RuntimeActivity::for_interview(Instant::now(), 0, 4); + activity.latency.bind("synthetic", 4, 1, 1500); + let record = tool_timing( + &mut activity, + &state, + &[(call, response)], + before, + timing(true), + ); + assert_eq!(record["accepted_tool_names"], json!([TOOL_LOG_HINT])); + assert_eq!( + record["hint_given"], + expected, + "ladder={} requested={requested}", + ladder.len() + ); + } +} From e726e93d29d7fec601a2912b454264561d205fba Mon Sep 17 00:00:00 2001 From: Jim Huang Date: Mon, 2 Nov 2026 18:32:04 +0800 Subject: [PATCH 3/4] Correlate replay evidence on sampled event clocks Floor records can resolve inside an observation window and appear only at teardown. Correlate their opening times instead of treating emission order or the highest sequence as proof that injected audio caused them. Keep process, room, session and socket identity explicit and return all candidate, preexisting, ambiguous and unusable evidence without choosing an outcome that happens to match the fixture. Join trial-local producer and harness clock samples with distinct clock identities, sampled-drift checks and conservative uncertainty hulls. Include millisecond quantization and reserve uncertainty margins inside both sample brackets. Missing anchors, excessive uncertainty and events outside the supported brackets cannot support attribution. Read complete floor, reply, boundary, replacement and pressure records with physical UTF-8 byte limits and explicit finalization requirements. Reject incomplete framing, duplicate evidence and malformed timestamps; retain legacy unknown clocks as unusable. Share bounded regular-file and duplicate-key JSON validation with the existing fixture loader, including change detection across the read and BOM refusal. Cover delayed preexisting records, teardown resolution, closed interval edges, replaced sockets, real producer pressure summaries and input corruption. Forty-five focused tests pass, and thirteen targeted guard removals fail those tests in isolated scratch copies. The full local gate passes with 2,736 browser tests and no browser skips; desktop checks need WebKitGTK and cargo-deny is not installed. This supplies offline correlation for the remaining replay adapters. Live gate verification, named browser and socket injection, common trial judgment and provider acceptance remain separate work. No endpointing, recovery, tool response or scoring policy changes are included. Change-Id: Ibebfcb66e2320da6d1f6c65b586bc4461c6314c2 --- docs/observational-replay.md | 74 ++- scripts/replay-clock.cjs | 182 +++++++ scripts/replay-evidence.cjs | 514 ++++++++++++++++++ scripts/replay-fixture.cjs | 69 +-- scripts/replay-input.cjs | 88 +++ tests/browser/replay-clock.test.js | 204 +++++++ tests/browser/replay-evidence.test.js | 372 +++++++++++++ tests/browser/replay-input.test.js | 90 +++ .../replay-evidence/socket-pressure.json | 38 ++ 9 files changed, 1553 insertions(+), 78 deletions(-) create mode 100644 scripts/replay-clock.cjs create mode 100644 scripts/replay-evidence.cjs create mode 100644 scripts/replay-input.cjs create mode 100644 tests/browser/replay-clock.test.js create mode 100644 tests/browser/replay-evidence.test.js create mode 100644 tests/browser/replay-input.test.js create mode 100644 tests/fixtures/replay-evidence/socket-pressure.json diff --git a/docs/observational-replay.md b/docs/observational-replay.md index 84f446848..d1c1d55eb 100644 --- a/docs/observational-replay.md +++ b/docs/observational-replay.md @@ -14,14 +14,14 @@ it still requires Speaking followed by a measured interrupted overlap. ## Existing entry points and missing observations -| Entry point | Observable today | Replay work required | -| --- | --- | --- | -| `scripts/barge-replay.cjs` | Page `#agent-state` text, microphone acquisition, decoded sample rate, duration and monotonic injection time; state rechecked after decoding/resume | Preserve this smoke; a separate named replay must support outcomes other than interruption and bound the gate wait. | -| `scripts/browser-check.cjs` | Room identity, Rust agent streams before tail trimming, capture JSON | Retain full-run latency alongside floor records and correlate each trial to the provider clock/record opening, not emission order. | -| `scripts/floor-capture.cjs` and its shell follower | Complete floor lines, including session/socket/sequence, retained beyond server cleanup | Reuse this writer. A highest *emitted* sequence is not an opening watermark. | -| `src/livekit/session.rs` tool response diagnostics | Allowlisted tool name, accepted response and separately the latency record's send outcome | Hint/tool gates need fresh accepted-and-sent evidence and invalidation at the reply/socket boundary. A caption, old hint count or accepted-but-unsent response cannot open a gate. | -| `tests/unit/livekit/cost.rs` spoken probes | Fixed restatement/question PCM, provider events and tool responses, streamed concurrently in 40 ms chunks | Add named input and a gated driver; these probes do not currently feed the production floor recorder or retain full-run latency. | -| `src/livekit/session.rs` / `src/livekit/floor.rs` | Provider activity mapped through room eligibility checks to floor observations | A direct socket driver must preserve this eligibility/mapping or label its evidence as harness-mapped, never as room/LiveKit acceptance. | +| Entry point | Observable today | Replay work required | +| -------------------------------------------------- | --------------------------------------------------------------------------------------------------------------------------------------------------- | ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| `scripts/barge-replay.cjs` | Page `#agent-state` text, microphone acquisition, decoded sample rate, duration and monotonic injection time; state rechecked after decoding/resume | Preserve this smoke; a separate named replay must support outcomes other than interruption and bound the gate wait. | +| `scripts/browser-check.cjs` | Room identity, Rust agent streams before tail trimming, capture JSON | Retain full-run latency alongside floor records and correlate each trial to the provider clock/record opening, not emission order. | +| `scripts/floor-capture.cjs` and its shell follower | Complete floor lines, including session/socket/sequence, retained beyond server cleanup | Reuse this writer. A highest _emitted_ sequence is not an opening watermark. | +| `src/livekit/session.rs` tool response diagnostics | Allowlisted tool name, accepted response and separately the latency record's send outcome | Hint/tool gates need fresh accepted-and-sent evidence and invalidation at the reply/socket boundary. A caption, old hint count or accepted-but-unsent response cannot open a gate. | +| `tests/unit/livekit/cost.rs` spoken probes | Fixed restatement/question PCM, provider events and tool responses, streamed concurrently in 40 ms chunks | Add named input and a gated driver; these probes do not currently feed the production floor recorder or retain full-run latency. | +| `src/livekit/session.rs` / `src/livekit/floor.rs` | Provider activity mapped through room eligibility checks to floor observations | A direct socket driver must preserve this eligibility/mapping or label its evidence as harness-mapped, never as room/LiveKit acceptance. | ## Fixture version 1 @@ -66,10 +66,10 @@ Do not include transcript, credentials or candidate identity in a manifest. `audio.format` selects the transport and exact format: -| Transport | Format | Sample rate | Limits | -| --- | --- | --- | --- | -| Browser | `wav_pcm_s16le` | 48,000 Hz, mono, signed 16-bit little-endian PCM in RIFF/WAVE | Positive duration up to 30 s; at most 2,945,536 file bytes (30 s plus 64 KiB for headers/chunks). | -| Direct socket | `pcm_s16le` | 16,000 Hz, mono, headerless signed 16-bit little-endian PCM | Positive duration up to 30 s; at most 960,000 bytes; whole 2-byte frames. | +| Transport | Format | Sample rate | Limits | +| ------------- | --------------- | ------------------------------------------------------------- | ------------------------------------------------------------------------------------------------- | +| Browser | `wav_pcm_s16le` | 48,000 Hz, mono, signed 16-bit little-endian PCM in RIFF/WAVE | Positive duration up to 30 s; at most 2,945,536 file bytes (30 s plus 64 KiB for headers/chunks). | +| Direct socket | `pcm_s16le` | 16,000 Hz, mono, headerless signed 16-bit little-endian PCM | Positive duration up to 30 s; at most 960,000 bytes; whole 2-byte frames. | WAV must contain exactly one `fmt ` and one `data` chunk, consistent file/chunk lengths, PCM tag 1, 16 bits, block alignment 2 and byte rate 96,000. Ancillary @@ -120,12 +120,12 @@ window cannot pass merely because its record arrived during finalization. Allowed expected pairs are: -| Kind | Outcome | Scenario | -| --- | --- | --- | -| `overlap` | `continued` | Candidate backchannel during output; generation completes and playout estimate drains without interruption. | -| `overlap` | `interrupted` | Provider interruption or an eligible local stale-playout drop resolves an observed overlap. | -| `pause` | `respond` | New generation's tool call or accepted audio resolves the candidate pause. | -| `pause` | `continue` | A new candidate START resumes after the clip's internal pause before a new interviewer response. | +| Kind | Outcome | Scenario | +| --------- | ------------- | ----------------------------------------------------------------------------------------------------------- | +| `overlap` | `continued` | Candidate backchannel during output; generation completes and playout estimate drains without interruption. | +| `overlap` | `interrupted` | Provider interruption or an eligible local stale-playout drop resolves an observed overlap. | +| `pause` | `respond` | New generation's tool call or accepted audio resolves the candidate pause. | +| `pause` | `continue` | A new candidate START resumes after the clip's internal pause before a new interviewer response. | For `pause/continue`, `audio.pause` is an object with integer `start_ms` and `end_ms`: a nonempty interval strictly inside the clip. Integer milliseconds at the @@ -190,3 +190,41 @@ prints metadata and exits 0, or prints the input error and exits 2. Output includes the manifest-byte digest, decoded frame count/duration and byte count, not audio bytes. The tests generate deterministic WAV/PCM fixtures in temporary directories and remove them afterward; their outcomes prove validation mechanics. + +## Offline evidence correlation + +`scripts/replay-evidence.cjs` reads finalized, drained floor and latency +artifacts with the same bounded input reader used by the fixture loader. +Framing and capture-incomplete checks apply to the whole stream. Unknown +numeric clocks remain visible as unusable evidence; malformed fields and +ambiguous duplicate records refuse correlation. This utility is being +integrated into the named adapters; its existence does not establish a working +browser/socket replay or a trial verdict. + +The caller pins process, room, session and socket from pre-injection evidence. +It supplies a trial-local span of producer clock samples and bracketing harness +samples with an explicit clock identity. A Node clock and a page clock cannot +be substituted for each other. `scripts/replay-clock.cjs` checks sampled offset +intervals for consistency, then maps with their conservative hull rather than +using their intersection as extra precision. Each projected event includes the +producer's whole-millisecond quantization. Producer sampling uncertainty must +include at least two milliseconds of rounding; harness uncertainty must include +at least one. The trial window needs an additional full interval-width margin +inside the harness samples so every potentially touching event stays bracketed. `uncertainty_ms` is the complete +projected interval width, bounded by the caller's `maxUncertaintyMs`; a gate's +maximum age is a separate condition for the adapter to enforce. + +The selected sample span must include every retained sample between its +endpoints and bracket the trial; it cannot be chosen based on an expected +outcome. Drift outside the trial span is not a veto on its own. Unsampled wall +clock changes are not detectable from these samples. Missing brackets, +excessive uncertainty or inconsistent sampled clocks cannot support a verdict. +Record selection uses opening times, never arrival order or the largest emitted +sequence. A record whose opening interval touches a trial endpoint is ambiguous. +The utility returns all candidate, preexisting, unusable and invalidating +evidence; choosing and judging the scenario remains the common judge's job. + +A floor record's socket identifies its emission context. Current room recovery +flushes the floor tracker before advancing the socket; a consumer must still +check replacement evidence rather than treating a matching socket as proof of +an opening generation. No correlation result establishes physical audibility. diff --git a/scripts/replay-clock.cjs b/scripts/replay-clock.cjs new file mode 100644 index 000000000..9da61a05a --- /dev/null +++ b/scripts/replay-clock.cjs @@ -0,0 +1,182 @@ +// Joins sampled clocks only; transport delay and provider activity are separate evidence. +class ReplayClockError extends Error { + constructor(reason) { + super(`replay clock: ${reason}`); + this.reason = reason; + } +} + +function requireValue(condition, reason) { + if (!condition) throw new ReplayClockError(reason); +} + +function number(value) { + return ( + typeof value === "number" && + Number.isFinite(value) && + Math.abs(value) <= Number.MAX_SAFE_INTEGER + ); +} + +function whole(value) { + return Number.isSafeInteger(value) && value >= 0; +} + +function intersect(intervals) { + const low = Math.max(...intervals.map((interval) => interval.low)); + const high = Math.min(...intervals.map((interval) => interval.high)); + requireValue(low <= high, "clock-drift"); + return { low, high }; +} + +function interval(center, uncertainty) { + const low = center - uncertainty; + const high = center + uncertainty; + requireValue(number(low) && number(high), "unsafe-clock-range"); + return { low, high }; +} + +function clockId(value) { + return typeof value === "string" && /^[a-zA-Z0-9:._-]{1,256}$/.test(value); +} + +function hull(intervals) { + return { + low: Math.min(...intervals.map((item) => item.low)), + high: Math.max(...intervals.map((item) => item.high)), + }; +} + +function createClockJoin({ harness, provider, maxUncertaintyMs }) { + requireValue( + number(maxUncertaintyMs) && + maxUncertaintyMs > 0 && + maxUncertaintyMs <= 5000, + "invalid-uncertainty-limit", + ); + for (const samples of [harness, provider]) { + requireValue( + Array.isArray(samples) && samples.length >= 2 && samples.length <= 4096, + "missing-or-excessive-samples", + ); + } + const harnessId = harness[0]?.clock_id; + const providerId = provider[0]?.clock_id; + requireValue( + clockId(harnessId) && clockId(providerId), + "missing-clock-identity", + ); + requireValue(harnessId !== providerId, "mixed-clock-domain"); + const local = harness.map((sample) => { + requireValue( + sample && + sample.clock_id === harnessId && + number(sample.mono_ms) && + sample.mono_ms >= 0 && + whole(sample.unix_ms) && + number(sample.uncertainty_ms) && + sample.uncertainty_ms >= 1 && + sample.uncertainty_ms <= maxUncertaintyMs, + "invalid-harness-sample", + ); + return interval(sample.unix_ms - sample.mono_ms, sample.uncertainty_ms); + }); + const start = provider[0]?.start_unix_ms; + requireValue(whole(start), "missing-provider-anchor"); + const remote = provider.flatMap((sample) => { + requireValue( + sample && + sample.clock_id === providerId && + sample.start_unix_ms === start && + whole(sample.emitted_ms) && + whole(sample.emitted_unix_ms) && + whole(sample.clock_uncertainty_ms) && + sample.clock_uncertainty_ms >= 2 && + sample.clock_uncertainty_ms <= maxUncertaintyMs, + "invalid-provider-sample", + ); + return [ + interval( + sample.emitted_unix_ms - sample.emitted_ms, + sample.clock_uncertainty_ms, + ), + ]; + }); + for (let i = 1; i < harness.length; i++) { + requireValue( + harness[i].mono_ms > harness[i - 1].mono_ms, + "unordered-harness-samples", + ); + } + const firstRemote = Math.min(...provider.map((sample) => sample.emitted_ms)); + const lastRemote = Math.max(...provider.map((sample) => sample.emitted_ms)); + requireValue(firstRemote < lastRemote, "unbracketed-provider-clock"); + // Intersections detect inconsistency; their narrowing is not extra timing precision. + intersect(local); + intersect(remote); + const h = hull(local); + const p = hull(remote); + const delta = { low: p.low - h.high, high: p.high - h.low }; + requireValue(number(delta.low) && number(delta.high), "unsafe-clock-range"); + const uncertainty = delta.high - delta.low + 1; + requireValue(uncertainty <= maxUncertaintyMs, "excessive-clock-uncertainty"); + const firstHarness = harness[0].mono_ms; + const lastHarness = harness.at(-1).mono_ms; + return { + clock_id: harnessId, + provider_clock_id: providerId, + uncertainty_ms: uncertainty, + providerWindow(window) { + requireValue( + window && + window.clock_id === harnessId && + number(window.low) && + number(window.high) && + window.low < window.high && + window.low >= firstHarness && + window.high <= lastHarness, + "invalid-harness-window", + ); + requireValue( + window.low - uncertainty >= firstHarness && + window.high + uncertainty <= lastHarness, + "window-near-harness-boundary", + ); + const result = { + low: window.low - delta.high - 1, + high: window.high - delta.low, + }; + requireValue( + number(result.low) && + number(result.high) && + result.low >= firstRemote && + result.high <= lastRemote, + "window-outside-provider-samples", + ); + return result; + }, + project(eventMs, eventClockId) { + requireValue(eventClockId === providerId, "event-clock-mismatch"); + requireValue(whole(eventMs), "invalid-event-time"); + requireValue( + eventMs >= firstRemote && eventMs <= lastRemote, + "event-outside-provider-samples", + ); + const result = { + low: eventMs + delta.low, + high: eventMs + 1 + delta.high, + }; + requireValue( + number(result.low) && number(result.high), + "unsafe-clock-range", + ); + requireValue( + result.low >= firstHarness && result.high <= lastHarness, + "event-outside-harness-samples", + ); + return result; + }, + }; +} + +module.exports = { createClockJoin, ReplayClockError }; diff --git a/scripts/replay-evidence.cjs b/scripts/replay-evidence.cjs new file mode 100644 index 000000000..9c530d314 --- /dev/null +++ b/scripts/replay-evidence.cjs @@ -0,0 +1,514 @@ +// Complete diagnostic artifacts are evidence; arrival order is never event order. +const crypto = require("node:crypto"); +const { TextDecoder } = require("node:util"); +const { readReplayFile, decodeReplayJson } = require("./replay-input.cjs"); +const { createClockJoin } = require("./replay-clock.cjs"); + +const FILE_BYTES = 16 * 1024 * 1024; +const PREFIXES = [ + "codetrial floor ", + "codetrial latency ", + "codetrial replay_gate ", + "interview clock: ", + "replacement start: ", + "replacement end: ", +]; +const TOOLS = new Set([ + "read_editor", + "read_board", + "read_conversation", + "log_hint", + "record_framework_evidence", + "end_interview", +]); + +class ReplayEvidenceError extends Error { + constructor(reason) { + super(`replay evidence: ${reason}`); + this.reason = reason; + } +} +function requireValue(condition, reason) { + if (!condition) throw new ReplayEvidenceError(reason); +} +function integer(n) { + return Number.isSafeInteger(n) && n >= 0; +} +function room(n) { + return typeof n === "string" && /^[a-zA-Z0-9_.:-]{1,128}$/.test(n); +} +function optional(n) { + return n === null || integer(n); +} +function scope(record) { + return JSON.stringify([record.pid, record.room, record.session]); +} +function clockId(record) { + return `producer:${crypto + .createHash("sha256") + .update( + JSON.stringify([ + record.pid, + record.room, + record.session, + record.clock.start_unix_ms, + ]), + ) + .digest("hex")}`; +} + +function tokens(text) { + const result = Object.create(null); + for (const token of text.split(" ")) { + const match = /^([a-z][a-z0-9_]*)=(\S+)$/.exec(token); + requireValue( + match && !Object.hasOwn(result, match[1]), + "malformed-or-duplicate-field", + ); + result[match[1]] = match[2]; + } + return result; +} +function numeric(value) { + if (value === undefined || value === "unknown") return null; + requireValue( + /^(0|[1-9][0-9]*)$/.test(value) && integer(Number(value)), + "malformed-number", + ); + return Number(value); +} +function identity(record) { + requireValue( + integer(record.pid) && + room(record.room) && + integer(record.session) && + integer(record.socket), + "invalid-identity", + ); +} +function clock(value) { + if (value === null || value === undefined) return null; + requireValue( + value && typeof value === "object" && !Array.isArray(value), + "invalid-clock", + ); + const keys = [ + "start_unix_ms", + "emitted_ms", + "emitted_unix_ms", + "clock_uncertainty_ms", + ]; + for (const key of keys) requireValue(optional(value[key]), "invalid-clock"); + return Object.fromEntries(keys.map((key) => [key, value[key]])); +} +function floor(text) { + const fields = tokens(text); + const record = { + family: "floor", + room: fields.room, + kind: fields.kind, + outcome: fields.outcome, + }; + for (const key of [ + "pid", + "session", + "socket", + "seq", + "opened_ms", + "resolved_ms", + "activity_end_ms", + ]) + record[key] = numeric(fields[key]); + requireValue( + room(record.room) && + integer(record.session) && + integer(record.socket) && + integer(record.seq), + "invalid-floor-identity", + ); + const pairs = + record.kind === "pause" + ? ["respond", "continue", "unresolved"] + : record.kind === "overlap" + ? ["continued", "interrupted", "unresolved"] + : []; + requireValue(pairs.includes(record.outcome), "invalid-floor-outcome"); + record.clock = Object.fromEntries( + [ + "start_unix_ms", + "emitted_ms", + "emitted_unix_ms", + "clock_uncertainty_ms", + ].map((key) => [key, numeric(fields[key])]), + ); + // Older logs have no numeric opening clocks; they remain visible but unusable. + record.usable = + integer(record.pid) && + integer(record.opened_ms) && + Object.values(record.clock).every(integer); + if (record.usable) { + if (record.outcome !== "unresolved") + requireValue(integer(record.resolved_ms), "missing-floor-resolution"); + else + requireValue( + record.resolved_ms === null, + "unresolved-floor-has-resolution", + ); + requireValue( + [record.resolved_ms, record.activity_end_ms].every( + (time) => time === null || time >= record.opened_ms, + ), + "reversed-floor-time", + ); + requireValue( + [record.opened_ms, record.resolved_ms, record.activity_end_ms].every( + (time) => time === null || time <= record.clock.emitted_ms, + ), + "floor-time-after-emission", + ); + } + return record; +} +function jsonRecord(text, family) { + const value = decodeReplayJson(Buffer.from(text), "replay evidence"); + requireValue( + value && typeof value === "object" && !Array.isArray(value), + "invalid-record", + ); + identity(value); + if (family === "latency" && value.event === "socket_pressure") { + requireValue( + value.version === 2 && optional(value.interview_ms), + "invalid-pressure-schema", + ); + requireValue( + ["replacement", "terminal", "discarded"].includes(value.end) && + [ + "read_idle", + "closed", + "failed", + "credential", + "receiver_closed", + "stopped", + ].includes(value.reader_end), + "invalid-pressure-outcome", + ); + const counts = [ + "capacity", + "occupancy_high_water", + "blocked_sends", + "blocked_ms_total", + "blocked_ms_max", + "received", + "consumed", + ]; + for (const key of counts) + requireValue(integer(value[key]), "invalid-pressure-count"); + return { + family: "pressure", + pid: value.pid, + room: value.room, + session: value.session, + socket: value.socket, + interview_ms: value.interview_ms, + stage: value.end, + reader_end: value.reader_end, + usable: integer(value.interview_ms), + }; + } + requireValue( + value.event === + (family === "latency" ? "reply_latency" : "gate_boundary") && + value.version === (family === "latency" ? 2 : 1), + "unsupported-record-schema", + ); + requireValue( + typeof value.stage === "string" && + /^[a-z_]{1,64}$/.test(value.stage) && + optional(value.interview_ms), + "invalid-event-time-or-stage", + ); + requireValue(optional(value.turn), "invalid-turn"); + const record = { + family, + pid: value.pid, + room: value.room, + session: value.session, + socket: value.socket, + turn: value.turn, + stage: value.stage, + interview_ms: value.interview_ms, + clock: clock(value.clock), + }; + record.usable = + integer(record.interview_ms) && + record.clock !== null && + Object.values(record.clock).every(integer); + if (record.usable) + requireValue( + record.interview_ms <= record.clock.emitted_ms, + "event-after-emission", + ); + if (family === "latency") { + requireValue(integer(value.origin_socket), "invalid-origin-socket"); + record.origin_socket = value.origin_socket; + requireValue( + value.obligation_outcome === null || + ["open", "answered", "superseded", "ended"].includes( + value.obligation_outcome, + ), + "invalid-obligation-outcome", + ); + record.obligation_outcome = value.obligation_outcome; + if (value.stage === "tool_response") { + requireValue( + typeof value.sent === "boolean" && + typeof value.hint_given === "boolean" && + Array.isArray(value.accepted_tool_names) && + value.accepted_tool_names.length <= 64 && + value.accepted_tool_names.every((name) => TOOLS.has(name)), + "invalid-tool-context", + ); + record.sent = value.sent; + record.hint_given = value.hint_given; + record.accepted_tool_names = [...value.accepted_tool_names]; + } + } + return record; +} +function parseStream(bytes, family) { + requireValue( + Buffer.isBuffer(bytes) && bytes.length <= FILE_BYTES, + "invalid-stream-size", + ); + let text; + try { + text = new TextDecoder("utf-8", { fatal: true, ignoreBOM: true }).decode( + bytes, + ); + } catch { + throw new ReplayEvidenceError("invalid-utf8"); + } + requireValue(text.length === 0 || text.endsWith("\n"), "unterminated-stream"); + const records = []; + const seen = new Set(); + for (const line of text.split("\n").slice(0, -1)) { + requireValue( + Buffer.byteLength(line) + 1 <= 4096 && !line.includes("\r"), + "invalid-line-framing", + ); + requireValue( + !line.includes("codetrial capture_incomplete"), + "capture-incomplete", + ); + const prefixes = PREFIXES.filter((prefix) => line.includes(prefix)); + if (prefixes.length === 0) continue; + requireValue( + prefixes.length === 1 && line.startsWith(prefixes[0]), + "unframed-diagnostic", + ); + const prefix = prefixes[0]; + const body = line.slice(prefix.length); + let record; + if (prefix === "codetrial floor ") { + requireValue(family === "floor", "mixed-diagnostic-family"); + record = floor(body); + } else { + requireValue(family === "latency", "mixed-diagnostic-family"); + if ( + prefix === "codetrial latency " || + prefix === "codetrial replay_gate " + ) + record = jsonRecord( + body, + prefix === "codetrial latency " ? "latency" : "gate", + ); + else if ( + prefix === "replacement start: " || + prefix === "replacement end: " + ) { + const fields = tokens(body); + record = { + family: "replacement", + room: fields.room, + pid: numeric(fields.pid), + session: numeric(fields.session), + interview_ms: numeric(fields.interview_ms), + stage: prefix === "replacement start: " ? "start" : "end", + }; + requireValue( + integer(record.pid) && room(record.room) && integer(record.session), + "invalid-replacement-identity", + ); + record.usable = integer(record.interview_ms); + } else continue; + } + const key = + record.family === "pressure" + ? JSON.stringify([ + "pressure", + record.pid, + record.room, + record.session, + record.socket, + ]) + : record.family === "floor" + ? JSON.stringify([ + record.pid, + record.room, + record.session, + record.seq, + ]) + : line; + requireValue(!seen.has(key), "duplicate-evidence"); + seen.add(key); + records.push(record); + } + return records; +} + +function loadEvidence({ floorPath, latencyPath, finalized, drained }) { + requireValue( + finalized === true && drained === true, + "evidence-not-finalized", + ); + const records = [ + ...parseStream( + readReplayFile(floorPath, FILE_BYTES, "replay evidence"), + "floor", + ), + ...parseStream( + readReplayFile(latencyPath, FILE_BYTES, "replay evidence"), + "latency", + ), + ]; + return { finalized: true, drained: true, records }; +} + +function partitionFloor({ + evidence, + selected, + harness, + window, + sampleSpan, + maxUncertaintyMs, +}) { + requireValue( + evidence?.finalized === true && evidence?.drained === true, + "evidence-not-finalized", + ); + identity(selected); + requireValue( + window && + Number.isFinite(window.low) && + Number.isFinite(window.high) && + window.low < window.high && + Array.isArray(harness) && + harness.every((sample) => sample.clock_id === window.clock_id), + "invalid-trial-window", + ); + requireValue( + sampleSpan && + integer(sampleSpan.from_ms) && + integer(sampleSpan.through_ms) && + sampleSpan.from_ms < sampleSpan.through_ms, + "invalid-sample-span", + ); + const relevant = evidence.records.filter( + (record) => + scope(record) === scope(selected) || + (record.family === "floor" && + record.pid === null && + record.room === selected.room), + ); + const samples = relevant + .filter( + (record) => + record.usable && + record.clock && + record.clock.emitted_ms >= sampleSpan.from_ms && + record.clock.emitted_ms <= sampleSpan.through_ms, + ) + .map((record) => ({ ...record.clock, clock_id: clockId(record) })); + const joined = createClockJoin({ + harness, + provider: samples, + maxUncertaintyMs, + }); + const rawWindow = joined.providerWindow(window); + const partitions = { + definitely_in: [], + ambiguous: [], + definitely_out: [], + preexisting_open: [], + unusable: [], + invalidations: [], + }; + for (const record of relevant) { + if (!record.usable) { + partitions.unusable.push(record); + continue; + } + if (record.family !== "floor") { + if ( + record.interview_ms < rawWindow.low || + record.interview_ms > rawWindow.high + ) + continue; + // Auxiliary event offsets use the same anchor as this validated + // process/room/session; the producer does not include a clock pair there. + const at = joined.project( + record.interview_ms, + record.clock ? clockId(record) : joined.provider_clock_id, + ); + if ( + at.high >= window.low && + at.low <= window.high && + (record.family === "replacement" || + (record.family === "pressure" && + ["replacement", "terminal"].includes(record.stage)) || + (["latency", "gate"].includes(record.family) && + record.socket !== selected.socket) || + record.stage === "socket_replaced") + ) + partitions.invalidations.push(record); + continue; + } + const end = + record.kind === "overlap" ? record.activity_end_ms : record.resolved_ms; + if (record.opened_ms < rawWindow.low || record.opened_ms > rawWindow.high) { + partitions.definitely_out.push(record); + if ( + record.opened_ms < rawWindow.low && + (end === null || end >= rawWindow.low) + ) + partitions.preexisting_open.push(record); + continue; + } + const opening = joined.project(record.opened_ms, clockId(record)); + if ( + record.socket !== selected.socket && + opening.high >= window.low && + opening.low <= window.high + ) + partitions.invalidations.push(record); + const selectedRecord = { ...record, opening }; + if (opening.low <= window.low && (end === null || end >= rawWindow.low)) + partitions.preexisting_open.push(selectedRecord); + if (opening.high < window.low || opening.low > window.high) + partitions.definitely_out.push(selectedRecord); + else if (opening.low > window.low && opening.high < window.high) + partitions.definitely_in.push(selectedRecord); + else partitions.ambiguous.push(selectedRecord); + } + return { + ...partitions, + clock: { + clock_id: joined.clock_id, + provider_clock_id: joined.provider_clock_id, + uncertainty_ms: joined.uncertainty_ms, + }, + }; +} + +module.exports = { loadEvidence, partitionFloor, ReplayEvidenceError }; diff --git a/scripts/replay-fixture.cjs b/scripts/replay-fixture.cjs index 029aefa04..391114d7b 100644 --- a/scripts/replay-fixture.cjs +++ b/scripts/replay-fixture.cjs @@ -1,7 +1,7 @@ // Offline input validation shared by the observational replay transports. const fs = require("node:fs"); const path = require("node:path"); -const { TextDecoder } = require("node:util"); +const { readReplayFile, decodeReplayJson } = require("./replay-input.cjs"); const { parseWav, sha256 } = require("./long-interview-schedule.cjs"); const MANIFEST_BYTES = 16384; @@ -113,32 +113,6 @@ function validateManifest(manifest) { return manifest; } -// Read at most the cap plus one byte even if a file grows after open/fstat. -function readBounded(filename, limit) { - const fd = fs.openSync( - filename, - fs.constants.O_RDONLY | - (fs.constants.O_NOFOLLOW ?? 0) | - (fs.constants.O_NONBLOCK ?? 0), - ); - try { - const stat = fs.fstatSync(fd); - if (!stat.isFile() || stat.size > limit) - refuse("input is not a bounded regular file"); - const bytes = Buffer.alloc(limit + 1); - let size = 0; - while (size <= limit) { - const count = fs.readSync(fd, bytes, size, limit + 1 - size, null); - if (!count) break; - size += count; - } - if (size > limit) refuse("input exceeds byte limit"); - return bytes.subarray(0, size); - } finally { - fs.closeSync(fd); - } -} - function inspectAudio(audio, bytes) { if (sha256(bytes) !== audio.sha256) refuse("audio digest mismatch"); let frames; @@ -206,41 +180,15 @@ function inspectAudio(audio, bytes) { return { frames, duration_ms: durationMs }; } -function parseManifest(bytes) { - let text; - let manifest; - try { - text = new TextDecoder("utf-8", { fatal: true }).decode(bytes); - manifest = JSON.parse(text); - } catch { - refuse("manifest is not UTF-8 JSON"); - } - const tokens = /"(?:\\[\s\S]|[^"\\])*"|[{}\[\]]/g; - const stack = []; - for (const match of text.matchAll(tokens)) { - const token = match[0]; - if (token === "{") stack.push(new Set()); - else if (token === "[") stack.push(null); - else if (token === "}" || token === "]") stack.pop(); - else if ( - text - .slice(match.index + token.length) - .trimStart() - .startsWith(":") - ) { - const key = JSON.parse(token); - if (stack.at(-1).has(key)) refuse("manifest has a duplicate object key"); - stack.at(-1).add(key); - } - } - return manifest; -} - function loadFixture(filename, transport) { if (!["browser", "socket"].includes(transport)) refuse("transport must be browser or socket"); - const manifestBytes = readBounded(filename, MANIFEST_BYTES); - const manifest = parseManifest(manifestBytes); + const manifestBytes = readReplayFile( + filename, + MANIFEST_BYTES, + "replay fixture", + ); + const manifest = decodeReplayJson(manifestBytes, "replay fixture"); validateManifest(manifest); const expectedFormat = transport === "browser" ? "wav_pcm_s16le" : "pcm_s16le"; @@ -248,9 +196,10 @@ function loadFixture(filename, transport) { refuse("audio format does not match transport"); const directory = path.dirname(fs.realpathSync(filename)); const audioPath = path.join(directory, manifest.audio.file); - const bytes = readBounded( + const bytes = readReplayFile( audioPath, transport === "browser" ? WAV_BYTES : PCM_BYTES, + "replay fixture", ); const audio = inspectAudio(manifest.audio, bytes); return { diff --git a/scripts/replay-input.cjs b/scripts/replay-input.cjs new file mode 100644 index 000000000..8f64c2ae9 --- /dev/null +++ b/scripts/replay-input.cjs @@ -0,0 +1,88 @@ +const fs = require("node:fs"); +const { TextDecoder } = require("node:util"); + +class ReplayInputError extends Error {} + +function readReplayFile(filename, limit, label) { + const fail = (reason) => { + throw new ReplayInputError(`${label}: ${reason}`); + }; + let fd; + try { + fd = fs.openSync( + filename, + fs.constants.O_RDONLY | + (fs.constants.O_NOFOLLOW ?? 0) | + (fs.constants.O_NONBLOCK ?? 0), + ); + const before = fs.fstatSync(fd, { bigint: true }); + if (!before.isFile() || before.size > BigInt(limit)) + fail("input is not a bounded regular file"); + const bytes = Buffer.alloc(limit + 1); + let size = 0; + while (size <= limit) { + const count = fs.readSync(fd, bytes, size, limit + 1 - size, null); + if (!count) break; + size += count; + } + const after = fs.fstatSync(fd, { bigint: true }); + if (size > limit) fail("input exceeds byte limit"); + if ( + BigInt(size) !== BigInt(before.size) || + after.size !== before.size || + after.mtimeNs !== before.mtimeNs || + after.ctimeNs !== before.ctimeNs + ) + fail("input changed while reading"); + return bytes.subarray(0, size); + } catch (error) { + if (error instanceof ReplayInputError) throw error; + const failure = new ReplayInputError( + `${label}: ${error.code === "ELOOP" ? "input symlink refused" : "input is not a readable bounded regular file"}`, + ); + if ( + typeof error.code === "string" && + /^[A-Z][A-Z0-9_]{0,30}$/.test(error.code) + ) + failure.code = error.code; + throw failure; + } finally { + if (fd !== undefined) fs.closeSync(fd); + } +} + +function decodeReplayJson(bytes, label) { + let text; + let value; + try { + text = new TextDecoder("utf-8", { fatal: true, ignoreBOM: true }).decode( + bytes, + ); + value = JSON.parse(text); + } catch { + throw new Error(`${label}: input is not UTF-8 JSON`); + } + const stack = []; + for (const match of text.matchAll(/"(?:\\[\s\S]|[^"\\])*"|[{}\[\]]/g)) { + const token = match[0]; + if (token === "{") stack.push(new Set()); + else if (token === "[") stack.push(null); + else if (token === "}" || token === "]") stack.pop(); + else if ( + text + .slice(match.index + token.length) + .trimStart() + .startsWith(":") + ) { + const key = JSON.parse(token); + if (key === "__proto__") + throw new Error(`${label}: input has a forbidden object key`); + if (stack.at(-1).has(key)) + throw new Error(`${label}: input has a duplicate object key`); + stack.at(-1).add(key); + } + } + return value; +} + +module.exports = { readReplayFile, decodeReplayJson }; diff --git a/tests/browser/replay-clock.test.js b/tests/browser/replay-clock.test.js new file mode 100644 index 000000000..34a17f5e9 --- /dev/null +++ b/tests/browser/replay-clock.test.js @@ -0,0 +1,204 @@ +import assert from "node:assert/strict"; +import { test } from "node:test"; +import { createRequire } from "node:module"; +const require = createRequire(import.meta.url); +const { + createClockJoin, + ReplayClockError, +} = require("../../scripts/replay-clock.cjs"); +const local = (mono_ms, unix_ms = 100000 + mono_ms, uncertainty_ms = 1) => ({ + clock_id: "node:test", + mono_ms, + unix_ms, + uncertainty_ms, +}); +const remote = (emitted_ms, extra = {}) => ({ + clock_id: "producer:test", + start_unix_ms: 100000, + emitted_ms, + emitted_unix_ms: 100000 + emitted_ms, + clock_uncertainty_ms: 2, + ...extra, +}); +function inputs() { + return { + harness: [local(0), local(3000)], + provider: [remote(0), remote(2500)], + maxUncertaintyMs: 10, + }; +} +function rejects(args, reason) { + assert.throws( + () => createClockJoin(args), + (e) => e instanceof ReplayClockError && e.reason === reason, + ); +} +const project = (join, ms) => join.project(ms, "producer:test"); +test("joins the event clock independent of delayed emission, retaining millisecond quantization", () => { + const args = inputs(); + args.provider = [remote(2500), remote(0), remote(2000)]; + const join = createClockJoin(args); + assert.deepEqual(project(join, 1000), { low: 997, high: 1004 }); + assert.equal(join.uncertainty_ms, 7); +}); +test("same timestamp in another monotonic clock maps through independent wall samples", () => { + const args = inputs(); + args.harness = [local(500, 100000), local(3500, 103000)]; + assert.deepEqual(project(createClockJoin(args), 1000), { + low: 1497, + high: 1504, + }); +}); +test("detects local sampled drift and refuses mixed anchors without enforcing an old wall offset", () => { + let args = inputs(); + args.harness[1].unix_ms += 3; + rejects(args, "clock-drift"); + args = inputs(); + args.provider[1].emitted_unix_ms += 5; + rejects(args, "clock-drift"); + args = inputs(); + args.provider[1].start_unix_ms += 1; + rejects(args, "invalid-provider-sample"); + args = inputs(); + for (const sample of args.provider) sample.emitted_unix_ms += 100; + assert.deepEqual(project(createClockJoin(args), 1000), { + low: 1097, + high: 1104, + }); +}); +test("uses a conservative hull rather than false precision from intersecting samples", () => { + const args = inputs(); + args.harness[1].unix_ms += 2; + assert.deepEqual(project(createClockJoin(args), 1000), { + low: 995, + high: 1004, + }); + args.harness[1].unix_ms++; + rejects(args, "clock-drift"); +}); +test("full uncertainty width includes event quantization and is held to the configured limit", () => { + const args = inputs(); + args.maxUncertaintyMs = 7; + assert.equal(createClockJoin(args).uncertainty_ms, 7); + args.maxUncertaintyMs = 6; + rejects(args, "excessive-clock-uncertainty"); +}); +test("does not extrapolate beyond either sampled clock", () => { + const join = createClockJoin(inputs()); + assert.throws(() => project(join, 2501), /event-outside-provider-samples/); + assert.throws(() => project(join, 0), /event-outside-harness-samples/); + assert.throws(() => project(join, -1), /invalid-event-time/); + const args = inputs(); + args.provider = [remote(0), remote(4000)]; + assert.throws( + () => project(createClockJoin(args), 3000), + /event-outside-harness-samples/, + ); +}); +test("refuses absent, duplicate-only, excessive and unordered sampling", () => { + let args = inputs(); + args.harness = []; + rejects(args, "missing-or-excessive-samples"); + args = inputs(); + args.provider = [remote(0), remote(0)]; + rejects(args, "unbracketed-provider-clock"); + args = inputs(); + args.harness.reverse(); + rejects(args, "unordered-harness-samples"); + args = inputs(); + args.provider = Array.from({ length: 4097 }, (_, i) => remote(i)); + rejects(args, "missing-or-excessive-samples"); +}); +test("missing/null/coerced and unsafe numbers cannot become clock anchors", () => { + for (const value of [ + null, + undefined, + "100000", + NaN, + Infinity, + -1, + Number.MAX_SAFE_INTEGER + 1, + ]) { + let args = inputs(); + args.provider[0].start_unix_ms = value; + rejects(args, "missing-provider-anchor"); + args = inputs(); + args.harness[0].unix_ms = value; + rejects(args, "invalid-harness-sample"); + } + for (const value of [null, "1", NaN, Infinity, -1, 5001]) { + const args = inputs(); + args.maxUncertaintyMs = value; + rejects(args, "invalid-uncertainty-limit"); + } +}); +test("harness/page and producer identities cannot be mixed or omitted", () => { + let args = inputs(); + delete args.harness[0].clock_id; + rejects(args, "missing-clock-identity"); + args = inputs(); + args.harness[1].clock_id = "page:test"; + rejects(args, "invalid-harness-sample"); + args = inputs(); + args.provider[1].clock_id = "producer:other"; + rejects(args, "invalid-provider-sample"); + const join = createClockJoin(inputs()); + assert.throws(() => join.project(1000, "page:test"), /event-clock-mismatch/); + assert.throws(() => join.project(1000), /event-clock-mismatch/); +}); +test("a join snapshots its bracketing bounds rather than retaining mutable caller arrays", () => { + const args = inputs(); + const join = createClockJoin(args); + args.harness[0].mono_ms = 2000; + args.harness.at(-1).mono_ms = 100; + assert.deepEqual(project(join, 1000), { low: 997, high: 1004 }); +}); + +test("inverse windows include uncertainty margins at both harness bracket edges", () => { + const args = inputs(); + args.provider = [remote(0), remote(4000)]; + const join = createClockJoin(args); + assert.throws( + () => join.providerWindow({ clock_id: "node:test", low: 10, high: 2995 }), + /window-near-harness-boundary/, + ); + assert.throws( + () => join.providerWindow({ clock_id: "node:test", low: 6, high: 2000 }), + /window-near-harness-boundary/, + ); + const bounds = join.providerWindow({ + clock_id: "node:test", + low: 7, + high: 2993, + }); + assert.deepEqual(bounds, { low: 3, high: 2996 }); + assert.deepEqual(project(join, bounds.low), { low: 0, high: 7 }); + assert.deepEqual(project(join, bounds.high), { low: 2993, high: 3000 }); + assert.deepEqual( + join.providerWindow({ clock_id: "node:test", low: 1000.5, high: 2000.5 }), + { low: 996.5, high: 2003.5 }, + ); +}); + +test("inverse windows reject invalid bounds or a substituted clock domain", () => { + const join = createClockJoin(inputs()); + for (const window of [ + { clock_id: "page:test", low: 1000, high: 2000 }, + { clock_id: "node:test", low: -1, high: 2000 }, + { clock_id: "node:test", low: NaN, high: 2000 }, + { clock_id: "node:test", low: 2000, high: 1000 }, + { clock_id: "node:test", low: 1000, high: Infinity }, + ]) + assert.throws(() => join.providerWindow(window), /invalid-harness-window/); + const args = inputs(); + args.provider.forEach((sample) => { + sample.clock_id = "node:test"; + }); + rejects(args, "mixed-clock-domain"); + const missingRounding = inputs(); + missingRounding.harness[0].uncertainty_ms = 0; + rejects(missingRounding, "invalid-harness-sample"); + const missingProviderRounding = inputs(); + missingProviderRounding.provider[0].clock_uncertainty_ms = 1; + rejects(missingProviderRounding, "invalid-provider-sample"); +}); diff --git a/tests/browser/replay-evidence.test.js b/tests/browser/replay-evidence.test.js new file mode 100644 index 000000000..43effdc53 --- /dev/null +++ b/tests/browser/replay-evidence.test.js @@ -0,0 +1,372 @@ +import assert from "node:assert/strict"; +import { test } from "node:test"; +import { createRequire } from "node:module"; +import fs from "node:fs"; +import os from "node:os"; +import path from "node:path"; +const require = createRequire(import.meta.url); +const { + loadEvidence, + partitionFloor, +} = require("../../scripts/replay-evidence.cjs"); + +const selected = { pid: 42, room: "test-room", session: 7, socket: 1 }; +const clock = (emitted_ms) => ({ + start_unix_ms: 100000, + emitted_ms, + emitted_unix_ms: 100000 + emitted_ms, + clock_uncertainty_ms: 2, +}); +function gate(ms, extra = {}) { + return `codetrial replay_gate ${JSON.stringify({ ...selected, event: "gate_boundary", version: 1, turn: null, stage: "turn_complete", interview_ms: ms, clock: clock(ms), ...extra })}\n`; +} +function floor(extra = {}) { + const f = { + ...selected, + seq: 1, + kind: "pause", + outcome: "respond", + at: "0:02.500", + gap_ms: 400, + overlap_ms: "unknown", + playout_ahead_ms: "unknown", + suspect: "unknown", + opened_ms: 1100, + resolved_ms: 1500, + activity_end_ms: "unknown", + ...clock(2500), + ...extra, + }; + return `codetrial floor ${Object.entries(f) + .map(([k, v]) => `${k}=${v}`) + .join(" ")}\n`; +} +function artifacts(t, floorText = floor(), latencyText = gate(0) + gate(2500)) { + const dir = fs.mkdtempSync(path.join(os.tmpdir(), "replay-evidence-")); + t.after(() => fs.rmSync(dir, { recursive: true, force: true })); + const floorPath = path.join(dir, "floor.log"); + const latencyPath = path.join(dir, "latency.log"); + fs.writeFileSync(floorPath, floorText); + fs.writeFileSync(latencyPath, latencyText); + const input = { floorPath, latencyPath, finalized: true, drained: true }; + return { input, load: () => loadEvidence(input) }; +} +function partition(evidence, extra = {}) { + return partitionFloor({ + evidence, + selected, + harness: [ + { clock_id: "node:test", mono_ms: 0, unix_ms: 100000, uncertainty_ms: 1 }, + { + clock_id: "node:test", + mono_ms: 3000, + unix_ms: 103000, + uncertainty_ms: 1, + }, + ], + window: { clock_id: "node:test", low: 1000, high: 2000 }, + sampleSpan: { from_ms: 0, through_ms: 2500 }, + maxUncertaintyMs: 10, + ...extra, + }); +} + +test("joins actual floor fields by opening time even when resolution emits at teardown", (t) => { + const evidence = artifacts(t).load(); + const result = partition(evidence); + assert.equal(result.definitely_in.length, 1); + assert.deepEqual(result.definitely_in[0].opening, { low: 1097, high: 1104 }); + assert.equal(result.definitely_in[0].resolved_ms, 1500); + assert.equal(result.definitely_in[0].clock.emitted_ms, 2500); + assert.equal( + result.ambiguous.length + + result.unusable.length + + result.invalidations.length, + 0, + ); +}); +test("late preexisting emission cannot be selected as injected activity", (t) => { + const result = partition(artifacts(t, floor({ opened_ms: 100 })).load()); + assert.equal(result.definitely_in.length, 0); + assert.equal(result.definitely_out.length, 1); + assert.equal(result.preexisting_open.length, 1); +}); +test("all potentially matching records are returned without choosing a favorable outcome", (t) => { + const result = partition( + artifacts( + t, + floor() + + floor({ + seq: 2, + opened_ms: 1600, + resolved_ms: 1700, + outcome: "continue", + }), + ).load(), + ); + assert.equal(result.definitely_in.length, 2); + assert.deepEqual( + result.definitely_in.map((r) => r.outcome), + ["respond", "continue"], + ); +}); +test("endpoint touches and uncertainty are ambiguous", (t) => { + for (const opened_ms of [996, 1000, 1997, 2003]) { + const result = partition( + artifacts(t, floor({ opened_ms, resolved_ms: 2100 })).load(), + ); + assert.equal(result.definitely_in.length, 0); + assert.equal(result.ambiguous.length, 1); + } +}); +test("identities and generations never merge", (t) => { + const other = floor({ pid: 43, seq: 2 }); + const result = partition(artifacts(t, floor() + other).load()); + assert.equal(result.definitely_in.length, 1); + const mismatch = partition(artifacts(t, floor({ socket: 2 })).load()); + assert.equal(mismatch.invalidations.length, 1); + const swap = partition( + artifacts( + t, + floor(), + gate(0) + gate(1200, { stage: "socket_replaced" }) + gate(2500), + ).load(), + ); + assert.equal(swap.invalidations.length, 1); +}); +test("floor keys survive socket changes and duplicate keys cannot be concealed by them", (t) => { + assert.throws( + () => artifacts(t, floor() + floor({ socket: 2 })).load(), + /duplicate-evidence/, + ); + assert.throws( + () => artifacts(t, floor().replace("seq=1", "seq=1 seq=2")).load(), + /malformed-or-duplicate-field/, + ); +}); +test("missing numeric clocks are visible as unusable; malformed numbers and reversed times refuse", (t) => { + const result = partition( + artifacts(t, floor({ opened_ms: "unknown" })).load(), + ); + assert.equal(result.unusable.length, 1); + for (const [change, reason] of [ + [{ opened_ms: "1.2" }, "malformed-number"], + [{ resolved_ms: "unknown" }, "missing-floor-resolution"], + [{ opened_ms: 1600, resolved_ms: 1500 }, "reversed-floor-time"], + [{ resolved_ms: 2501 }, "floor-time-after-emission"], + [{ outcome: "unresolved" }, "unresolved-floor-has-resolution"], + [{ kind: "overlap", outcome: "respond" }, "invalid-floor-outcome"], + ]) + assert.throws( + () => artifacts(t, floor(change)).load(), + new RegExp(`replay evidence: ${reason}$`), + ); + assert.equal( + artifacts( + t, + floor({ outcome: "unresolved", resolved_ms: "unknown" }), + ).load().records[0].outcome, + "unresolved", + ); +}); +test("framing, capture gaps and encoding fail before unrelated-line classification", (t) => { + for (const text of [ + floor().trimEnd(), + `codetrial capture_incomplete family=future reason=future\n`, + "x".repeat(4096) + "\n", + "prefix " + floor(), + floor().replace("\n", "\r\n"), + ]) + assert.throws( + () => artifacts(t, text).load(), + /unterminated-stream|capture-incomplete|invalid-line-framing|unframed-diagnostic/, + ); + assert.throws( + () => artifacts(t, Buffer.from([0xff, 10])).load(), + /invalid-utf8/, + ); + assert.equal( + artifacts(t, "x".repeat(4095) + "\n") + .load() + .records.filter((r) => r.family === "floor").length, + 0, + ); +}); +test("JSON duplicate/escaped keys, mixed families and duplicated lines refuse", (t) => { + for (const text of [ + gate(0).replace('"pid":42', '"pid":42,"pid":43'), + gate(0).replace('"pid":42', '"pid":42,"p\\u0069d":43'), + gate(0).replace('"pid":42', '"__proto__":{},"pid":42'), + ]) + assert.throws( + () => artifacts(t, floor(), text).load(), + /duplicate object key|forbidden object key/, + ); + assert.throws(() => artifacts(t, gate(0)).load(), /mixed-diagnostic-family/); + assert.throws( + () => artifacts(t, floor(), gate(0) + gate(0)).load(), + /duplicate-evidence/, + ); +}); +test("finalization is explicit and missing files or symlinks cannot become evidence", (t) => { + const files = artifacts(t); + files.input.drained = false; + assert.throws(files.load, /evidence-not-finalized/); + files.input.drained = true; + const link = files.input.floorPath + ".link"; + fs.symlinkSync(files.input.floorPath, link); + files.input.floorPath = link; + assert.throws(files.load, /symlink/); + fs.unlinkSync(link); + assert.throws(files.load, /readable bounded regular file/); +}); + +function reply(ms, extra = {}) { + return `codetrial latency ${JSON.stringify({ ...selected, event: "reply_latency", version: 2, turn: 1, stage: "audio_accepted", origin_socket: 1, obligation_outcome: "open", interview_ms: ms, clock: clock(ms), ...extra })}\n`; +} + +test("normal reply, tool acknowledgements and pressure summaries share the latency stream", (t) => { + // Captured from the credential-free Rust recovery test; identity and event times are normalized. + const pressure = JSON.parse( + fs.readFileSync( + new URL( + "../fixtures/replay-evidence/socket-pressure.json", + import.meta.url, + ), + "utf8", + ), + ); + const terminal = { ...pressure[1], socket: 1 }; + const tool = (ms) => + reply(ms, { + stage: "tool_response", + sent: true, + hint_given: true, + accepted_tool_names: ["log_hint"], + tool_names: ["log_hint"], + tool_count: 1, + }); + const data = artifacts( + t, + floor(), + gate(0) + + tool(900) + + tool(901) + + reply(950) + + gate(2500) + + `codetrial latency ${JSON.stringify(terminal)}\n`, + ).load(); + assert.equal(data.records.filter((r) => r.family === "latency").length, 3); + assert.equal(data.records.filter((r) => r.family === "pressure").length, 1); + assert.equal(partition(data).definitely_in.length, 1); + assert.deepEqual( + data.records.find((r) => r.stage === "tool_response").accepted_tool_names, + ["log_hint"], + ); + assert.equal(partition(data).invalidations.length, 0); + const replacement = `codetrial latency ${JSON.stringify(pressure[0])}\n`; + assert.equal( + partition(artifacts(t, floor(), gate(0) + replacement + gate(2500)).load()) + .invalidations.length, + 1, + ); + const discarded = { ...pressure[0], socket: 999, end: "discarded" }; + assert.equal( + partition( + artifacts( + t, + floor(), + gate(0) + + `codetrial latency ${JSON.stringify(discarded)}\n` + + gate(2500), + ).load(), + ).invalidations.length, + 0, + ); +}); + +test("invalid auxiliary pressure records refuse instead of disappearing", (t) => { + const [base] = JSON.parse( + fs.readFileSync( + new URL( + "../fixtures/replay-evidence/socket-pressure.json", + import.meta.url, + ), + "utf8", + ), + ); + for (const change of [ + { version: 3 }, + { end: "future" }, + { reader_end: "future" }, + { received: "1" }, + { interview_ms: -1 }, + ]) { + const line = `codetrial latency ${JSON.stringify({ ...base, ...change })}\n`; + assert.throws( + () => artifacts(t, floor(), gate(0) + line).load(), + /invalid-pressure/, + ); + } +}); + +test("a leading UTF-8 BOM cannot hide physical bytes or create a framed diagnostic", (t) => { + const bare = floor().trimEnd(); + const exact = + bare + + " filler=" + + "x".repeat(4095 - Buffer.byteLength(bare + " filler=")) + + "\n"; + assert.equal(Buffer.byteLength(exact), 4096); + assert.equal( + artifacts(t, exact) + .load() + .records.filter((r) => r.family === "floor").length, + 1, + ); + assert.throws( + () => artifacts(t, "\ufeff" + exact).load(), + /invalid-line-framing/, + ); + assert.throws( + () => artifacts(t, "\ufeff" + floor()).load(), + /unframed-diagnostic/, + ); + assert.throws( + () => artifacts(t, "é".repeat(2048) + "\n").load(), + /invalid-line-framing/, + ); +}); + +test("JSON payload BOMs and conflicting per-socket pressure summaries refuse", (t) => { + assert.throws( + () => + artifacts( + t, + floor(), + gate(0).replace( + "codetrial replay_gate ", + "codetrial replay_gate \ufeff", + ), + ).load(), + /not UTF-8 JSON/, + ); + const [base] = JSON.parse( + fs.readFileSync( + new URL( + "../fixtures/replay-evidence/socket-pressure.json", + import.meta.url, + ), + "utf8", + ), + ); + assert.throws( + () => + artifacts( + t, + floor(), + `codetrial latency ${JSON.stringify(base)}\ncodetrial latency ${JSON.stringify({ ...base, end: "terminal" })}\n`, + ).load(), + /duplicate-evidence/, + ); +}); diff --git a/tests/browser/replay-input.test.js b/tests/browser/replay-input.test.js new file mode 100644 index 000000000..4c58ab880 --- /dev/null +++ b/tests/browser/replay-input.test.js @@ -0,0 +1,90 @@ +import assert from "node:assert/strict"; +import { test } from "node:test"; +import { createRequire } from "node:module"; +import fs from "node:fs"; +import os from "node:os"; +import path from "node:path"; +const require = createRequire(import.meta.url); +const { + readReplayFile, + decodeReplayJson, +} = require("../../scripts/replay-input.cjs"); +function file(t, bytes) { + const dir = fs.mkdtempSync(path.join(os.tmpdir(), "replay-input-")); + t.after(() => fs.rmSync(dir, { recursive: true, force: true })); + const name = path.join(dir, "input"); + fs.writeFileSync(name, bytes); + return name; +} +test("regular input accepts the exact byte cap and refuses one more byte", (t) => { + const name = file(t, Buffer.alloc(8, 1)); + assert.equal(readReplayFile(name, 8, "replay input").length, 8); + fs.appendFileSync(name, Buffer.from([1])); + assert.throws( + () => readReplayFile(name, 8, "replay input"), + /bounded regular/, + ); +}); +test("growth below the read cap is still detected by the final stat", (t) => { + const name = file(t, "abc"); + const stat = fs.fstatSync; + let grew = false; + t.mock.method(fs, "fstatSync", (fd, options) => { + const result = stat(fd, options); + if (!grew) { + grew = true; + fs.appendFileSync(name, "d"); + } + return result; + }); + assert.throws( + () => readReplayFile(name, 8, "replay input"), + /changed while reading/, + ); + assert.equal(grew, true); +}); +test("same-size rewrite with an observed metadata change refuses", (t) => { + const name = file(t, "abc"); + const stat = fs.fstatSync; + let changed = false; + t.mock.method(fs, "fstatSync", (fd, options) => { + const result = stat(fd, options); + if (!changed) { + changed = true; + fs.writeFileSync(name, "def"); + fs.utimesSync(name, 1, 1); + } + return result; + }); + assert.throws( + () => readReplayFile(name, 8, "replay input"), + /changed while reading/, + ); + assert.equal(changed, true); +}); +test("shared JSON decoding validates nested keys and encoding without coercion", () => { + assert.deepEqual( + decodeReplayJson(Buffer.from('{"a":[{"b":1},{"b":2}]}'), "input"), + { a: [{ b: 1 }, { b: 2 }] }, + ); + for (const json of [ + '{"a":{"b":1,"b":2}}', + '{"a":1,"\\u0061":2}', + '{"a":[{"__proto__":{}}]}', + ]) + assert.throws( + () => decodeReplayJson(Buffer.from(json), "input"), + /duplicate object key|forbidden object key/, + ); + assert.throws( + () => decodeReplayJson(Buffer.from([0xff]), "input"), + /not UTF-8 JSON/, + ); +}); + +test("JSON BOMs cannot be stripped into an accepted payload", () => { + assert.throws( + () => decodeReplayJson(Buffer.from('\ufeff{"a":1}'), "input"), + /not UTF-8 JSON/, + ); +}); diff --git a/tests/fixtures/replay-evidence/socket-pressure.json b/tests/fixtures/replay-evidence/socket-pressure.json new file mode 100644 index 000000000..d980a4e71 --- /dev/null +++ b/tests/fixtures/replay-evidence/socket-pressure.json @@ -0,0 +1,38 @@ +[ + { + "blocked_ms_max": 0, + "blocked_ms_total": 0, + "blocked_sends": 0, + "capacity": 256, + "consumed": 0, + "end": "replacement", + "event": "socket_pressure", + "interview_ms": 1200, + "occupancy_high_water": 1, + "pid": 42, + "reader_end": "stopped", + "received": 1, + "room": "test-room", + "session": 7, + "socket": 1, + "version": 2 + }, + { + "blocked_ms_max": 0, + "blocked_ms_total": 0, + "blocked_sends": 0, + "capacity": 256, + "consumed": 0, + "end": "terminal", + "event": "socket_pressure", + "interview_ms": 2500, + "occupancy_high_water": 0, + "pid": 42, + "reader_end": "stopped", + "received": 0, + "room": "test-room", + "session": 7, + "socket": 2, + "version": 2 + } +] From a47bc324440aeae6dfdf62ecdff1a04adc115765 Mon Sep 17 00:00:00 2001 From: Jim Huang Date: Tue, 3 Nov 2026 04:12:42 +0800 Subject: [PATCH 4/4] Select replay gates conservatively Injected audio can only be attributed to a tool or hint gate when the acknowledgement that opened it is still the newest context. Select a candidate from sampled event clocks, then verify it against finalized evidence: a newer boundary, a replacement, a discarded socket or a terminal state invalidates the gate, as does a stale age. Anything the clocks cannot order stays unknown rather than aligned. Record the closing state and the end of each event so these checks have the interval they need. A boundary also ends when it is handled, not when it arrived, so an interruption queued behind a tool send cannot sort before the acknowledgement it followed. Replies and gate boundaries carry whether the interview is closing, and a requested end is logged before the farewell. Keep read failures typed so an unexpected error still surfaces instead of reading as unknown evidence. Each observation line is written once, so a line cannot be split or cost a syscall per field. The helpers are not wired into a replay adapter yet. Change-Id: Ia87d1522947d41d793eeb100ff2d5d3313949e12 --- docs/observational-replay.md | 28 ++ docs/turn-timing.md | 19 +- scripts/floor-capture.cjs | 21 +- scripts/replay-clock.cjs | 14 +- scripts/replay-evidence.cjs | 191 ++++++---- scripts/replay-gates.cjs | 346 +++++++++++++++++ scripts/replay-input.cjs | 44 ++- scripts/rust-style-ceilings.json | 2 +- src/livekit/latency.rs | 45 ++- src/livekit/packets.rs | 9 + src/livekit/session.rs | 28 +- src/livekit/session/floor.rs | 7 +- src/livekit/session/observations.rs | 24 ++ tests/browser/replay-evidence.test.js | 15 + tests/browser/replay-fixture.test.js | 15 +- tests/browser/replay-gates.test.js | 419 +++++++++++++++++++++ tests/browser/replay-input.test.js | 63 +++- tests/unit/livekit/latency/gates.rs | 51 +++ tests/unit/livekit/packets.rs | 81 ++++ tests/unit/livekit/session/observations.rs | 134 ++++++- 20 files changed, 1399 insertions(+), 157 deletions(-) create mode 100644 scripts/replay-gates.cjs create mode 100644 tests/browser/replay-gates.test.js create mode 100644 tests/unit/livekit/packets.rs diff --git a/docs/observational-replay.md b/docs/observational-replay.md index d1c1d55eb..f804acf31 100644 --- a/docs/observational-replay.md +++ b/docs/observational-replay.md @@ -228,3 +228,31 @@ A floor record's socket identifies its emission context. Current room recovery flushes the floor tracker before advancing the socket; a consumer must still check replacement evidence rather than treating a matching socket as proof of an opening generation. No correlation result establishes physical audibility. + +## Provisional and finalized tool gates + +`scripts/replay-gates.cjs` selects an accepted-and-sent tool acknowledgement +from a snapshot of both diagnostic families. It pins the room actually joined +and a unique process/session (or a known agent child PID), then derives the +socket from the candidate. A hint also requires `hint_given`; every candidate +requires explicit `closing: false`. Missing legacy context remains unknown. +Same-turn batches are distinct by exact diagnostic-line digest, not turn ID. + +A live candidate and its wall-pair age estimate are provisional. Decode, +resume, budget admission and the final page-state check still belong to the +adapter. Only finalized, drained evidence can establish gate alignment: +any newer batch or authoritative boundary before injection expires the selected +acknowledgement, even if the line arrived late. An event overlapping injection +stays unknown. A normal completion strictly after injection is an outcome; +replacement, discarded or terminal state before the observation window ends +invalidates alignment across every socket of the pinned process/session. +A socket pressure summary is a best-effort record written once when a socket +is released, so it carries a drop time rather than an interval. A discarded +one comes from a standby socket that may never have carried the gate; it +still invalidates, which can only exclude a trial, never align one. + +Freshness uses one fixture maximum age in both phases. An age interval wholly +past that limit is stale; one straddling it is unknown. Closing transitions use +the complete producer reduction interval. These helpers do not supply a named +replay flow or a scenario verdict by themselves; actual adapter integration and +common judgment remain required. diff --git a/docs/turn-timing.md b/docs/turn-timing.md index cda186a96..69632b593 100644 --- a/docs/turn-timing.md +++ b/docs/turn-timing.md @@ -206,8 +206,9 @@ its own injection bracket and uncertainty, verify anchor identity and clock drift, and reject ambiguous or out-of-window attribution. Emission order and max emitted sequence remain insufficient for joining an injection to a record. -Tool-response latency records include allowlisted `accepted_tool_names` and -`hint_given`, separate from `sent`. Accepted means no tool error, not that a +Tool-response latency records include allowlisted `accepted_tool_names`, +`hint_given` and `closing`, separate from `sent`. `closing` observes the existing +end-requested or ended state after the batch; it does not end the session. Accepted means no tool error, not that a response was delivered. `hint_given` means this batch advanced an authored hint rung or recorded a volunteered hint; withheld/exhausted requests cannot supply hint context merely because their tool response has no error. It establishes @@ -215,7 +216,19 @@ server tool context, never the content or audibility of a generated phrase. `codetrial replay_gate` JSON lines carry `event=gate_boundary`, version 1, room/process/session/socket identity, optional turn, stage, event `interview_ms` -and an emission `clock` sample. Each invocation of the latency boundary handler +and an emission `clock` sample. `event_end_ms` is the upper bound of the +observed transition. For an ordinary provider boundary, `interview_ms` is when +the event arrived and `event_end_ms` is when the room loop handled it, so a +boundary queued behind a tool send spans that wait; only records without the +field have equal endpoints. A boundary may also appear as a latency record of +the same stage, and a consumer treats the pair as one event. +A `close_requested` observation brackets the tool call that first requests an +end, before any asynchronous response/board work. A `closing` observation +brackets the control reduction that first ends the session, before farewell or +report work. These observations leave reply traces intact. A consumer must +retain the interval rather than assigning a delayed transition to its emission +time. Missing interval fields on older ordinary boundaries mean their original +single event offset. Each invocation of the latency boundary handler emits one, even without an open reply trace: accepted turn completion or interruption, hold, and socket replacement cannot silently leave an old tool gate eligible. Provider events rejected by existing acceptance, hold or discard diff --git a/scripts/floor-capture.cjs b/scripts/floor-capture.cjs index 425a7f81f..0f60746f2 100644 --- a/scripts/floor-capture.cjs +++ b/scripts/floor-capture.cjs @@ -84,24 +84,24 @@ class DiagnosticCapture { else this.write(this.pending); } } finally { - this.pending = ""; - this.pendingBytes = 0; - this.tail = ""; - this.diagnostic = false; - this.discarding = false; + this.resetLine(); } } } + resetLine() { + this.pending = ""; + this.pendingBytes = 0; + this.tail = ""; + this.diagnostic = false; + this.discarding = false; + } + discontinuity(reason) { try { this.incomplete(reason); } finally { - this.pending = ""; - this.pendingBytes = 0; - this.tail = ""; - this.diagnostic = false; - this.discarding = false; + this.resetLine(); this.decoder = new StringDecoder("utf8"); } } @@ -224,6 +224,7 @@ function assertInterruptedOverlap(path, room) { } module.exports = { + PREFIXES, DiagnosticCapture, captureDiagnosticStream, drainDiagnosticStreams, diff --git a/scripts/replay-clock.cjs b/scripts/replay-clock.cjs index 9da61a05a..08e0edf8d 100644 --- a/scripts/replay-clock.cjs +++ b/scripts/replay-clock.cjs @@ -83,7 +83,7 @@ function createClockJoin({ harness, provider, maxUncertaintyMs }) { }); const start = provider[0]?.start_unix_ms; requireValue(whole(start), "missing-provider-anchor"); - const remote = provider.flatMap((sample) => { + const remote = provider.map((sample) => { requireValue( sample && sample.clock_id === providerId && @@ -95,12 +95,10 @@ function createClockJoin({ harness, provider, maxUncertaintyMs }) { sample.clock_uncertainty_ms <= maxUncertaintyMs, "invalid-provider-sample", ); - return [ - interval( - sample.emitted_unix_ms - sample.emitted_ms, - sample.clock_uncertainty_ms, - ), - ]; + return interval( + sample.emitted_unix_ms - sample.emitted_ms, + sample.clock_uncertainty_ms, + ); }); for (let i = 1; i < harness.length; i++) { requireValue( @@ -179,4 +177,4 @@ function createClockJoin({ harness, provider, maxUncertaintyMs }) { }; } -module.exports = { createClockJoin, ReplayClockError }; +module.exports = { createClockJoin, ReplayClockError, number, whole }; diff --git a/scripts/replay-evidence.cjs b/scripts/replay-evidence.cjs index 9c530d314..57397d3e5 100644 --- a/scripts/replay-evidence.cjs +++ b/scripts/replay-evidence.cjs @@ -1,17 +1,17 @@ // Complete diagnostic artifacts are evidence; arrival order is never event order. -const crypto = require("node:crypto"); +const { sha256 } = require("./long-interview-schedule.cjs"); const { TextDecoder } = require("node:util"); const { readReplayFile, decodeReplayJson } = require("./replay-input.cjs"); -const { createClockJoin } = require("./replay-clock.cjs"); +const { createClockJoin, whole: integer } = require("./replay-clock.cjs"); +const { PREFIXES: CAPTURE_PREFIXES } = require("./floor-capture.cjs"); const FILE_BYTES = 16 * 1024 * 1024; -const PREFIXES = [ - "codetrial floor ", - "codetrial latency ", - "codetrial replay_gate ", - "interview clock: ", - "replacement start: ", - "replacement end: ", +const PREFIXES = Object.values(CAPTURE_PREFIXES).flat(); +const CLOCK_KEYS = [ + "start_unix_ms", + "emitted_ms", + "emitted_unix_ms", + "clock_uncertainty_ms", ]; const TOOLS = new Set([ "read_editor", @@ -22,6 +22,10 @@ const TOOLS = new Set([ "end_interview", ]); +function knownReplayTool(name) { + return TOOLS.has(name); +} + class ReplayEvidenceError extends Error { constructor(reason) { super(`replay evidence: ${reason}`); @@ -31,30 +35,23 @@ class ReplayEvidenceError extends Error { function requireValue(condition, reason) { if (!condition) throw new ReplayEvidenceError(reason); } -function integer(n) { - return Number.isSafeInteger(n) && n >= 0; -} function room(n) { return typeof n === "string" && /^[a-zA-Z0-9_.:-]{1,128}$/.test(n); } function optional(n) { return n === null || integer(n); } -function scope(record) { - return JSON.stringify([record.pid, record.room, record.session]); -} +const sameScope = (a, b) => + a.pid === b.pid && a.room === b.room && a.session === b.session; function clockId(record) { - return `producer:${crypto - .createHash("sha256") - .update( - JSON.stringify([ - record.pid, - record.room, - record.session, - record.clock.start_unix_ms, - ]), - ) - .digest("hex")}`; + return `producer:${sha256( + JSON.stringify([ + record.pid, + record.room, + record.session, + record.clock.start_unix_ms, + ]), + )}`; } function tokens(text) { @@ -92,14 +89,9 @@ function clock(value) { value && typeof value === "object" && !Array.isArray(value), "invalid-clock", ); - const keys = [ - "start_unix_ms", - "emitted_ms", - "emitted_unix_ms", - "clock_uncertainty_ms", - ]; - for (const key of keys) requireValue(optional(value[key]), "invalid-clock"); - return Object.fromEntries(keys.map((key) => [key, value[key]])); + for (const key of CLOCK_KEYS) + requireValue(optional(value[key]), "invalid-clock"); + return Object.fromEntries(CLOCK_KEYS.map((key) => [key, value[key]])); } function floor(text) { const fields = tokens(text); @@ -134,12 +126,7 @@ function floor(text) { : []; requireValue(pairs.includes(record.outcome), "invalid-floor-outcome"); record.clock = Object.fromEntries( - [ - "start_unix_ms", - "emitted_ms", - "emitted_unix_ms", - "clock_uncertainty_ms", - ].map((key) => [key, numeric(fields[key])]), + CLOCK_KEYS.map((key) => [key, numeric(fields[key])]), ); // Older logs have no numeric opening clocks; they remain visible but unusable. record.usable = @@ -249,6 +236,20 @@ function jsonRecord(text, family) { record.interview_ms <= record.clock.emitted_ms, "event-after-emission", ); + if (family === "gate") { + record.event_end_ms = + value.event_end_ms === undefined + ? record.interview_ms + : value.event_end_ms; + requireValue(optional(record.event_end_ms), "invalid-event-interval"); + if (record.usable) + requireValue( + integer(record.event_end_ms) && + record.event_end_ms >= record.interview_ms && + record.event_end_ms <= record.clock.emitted_ms, + "invalid-event-interval", + ); + } if (family === "latency") { requireValue(integer(value.origin_socket), "invalid-origin-socket"); record.origin_socket = value.origin_socket; @@ -266,11 +267,16 @@ function jsonRecord(text, family) { typeof value.hint_given === "boolean" && Array.isArray(value.accepted_tool_names) && value.accepted_tool_names.length <= 64 && - value.accepted_tool_names.every((name) => TOOLS.has(name)), + value.accepted_tool_names.every(knownReplayTool), "invalid-tool-context", ); record.sent = value.sent; record.hint_given = value.hint_given; + requireValue( + value.closing === undefined || typeof value.closing === "boolean", + "invalid-closing-context", + ); + record.closing = value.closing ?? null; record.accepted_tool_names = [...value.accepted_tool_names]; } } @@ -362,16 +368,13 @@ function parseStream(bytes, family) { : line; requireValue(!seen.has(key), "duplicate-evidence"); seen.add(key); + record.evidence_sha256 = sha256(line + "\n"); records.push(record); } return records; } -function loadEvidence({ floorPath, latencyPath, finalized, drained }) { - requireValue( - finalized === true && drained === true, - "evidence-not-finalized", - ); +function readEvidenceSnapshot({ floorPath, latencyPath }) { const records = [ ...parseStream( readReplayFile(floorPath, FILE_BYTES, "replay evidence"), @@ -382,10 +385,22 @@ function loadEvidence({ floorPath, latencyPath, finalized, drained }) { "latency", ), ]; - return { finalized: true, drained: true, records }; + return { finalized: false, drained: false, records }; } -function partitionFloor({ +function loadEvidence({ floorPath, latencyPath, finalized, drained }) { + requireValue( + finalized === true && drained === true, + "evidence-not-finalized", + ); + return { + ...readEvidenceSnapshot({ floorPath, latencyPath }), + finalized: true, + drained: true, + }; +} + +function joinEvidenceClock({ evidence, selected, harness, @@ -399,12 +414,12 @@ function partitionFloor({ ); identity(selected); requireValue( - window && - Number.isFinite(window.low) && - Number.isFinite(window.high) && - window.low < window.high && - Array.isArray(harness) && - harness.every((sample) => sample.clock_id === window.clock_id), + !window || + (Number.isFinite(window.low) && + Number.isFinite(window.high) && + window.low < window.high && + Array.isArray(harness) && + harness.every((sample) => sample.clock_id === window.clock_id)), "invalid-trial-window", ); requireValue( @@ -416,7 +431,7 @@ function partitionFloor({ ); const relevant = evidence.records.filter( (record) => - scope(record) === scope(selected) || + sameScope(record, selected) || (record.family === "floor" && record.pid === null && record.room === selected.room), @@ -435,7 +450,43 @@ function partitionFloor({ provider: samples, maxUncertaintyMs, }); - const rawWindow = joined.providerWindow(window); + const rawWindow = window ? joined.providerWindow(window) : null; + return { + records: relevant, + clock: joined, + rawWindow, + project(record, at = record.interview_ms) { + requireValue(sameScope(record, selected), "event-scope-mismatch"); + return joined.project( + at, + record.clock ? clockId(record) : joined.provider_clock_id, + ); + }, + }; +} + +function partitionFloor({ + evidence, + selected, + harness, + window, + sampleSpan, + maxUncertaintyMs, +}) { + requireValue(window, "invalid-trial-window"); + const { + records: relevant, + clock: joined, + rawWindow, + project, + } = joinEvidenceClock({ + evidence, + selected, + harness, + window, + sampleSpan, + maxUncertaintyMs, + }); const partitions = { definitely_in: [], ambiguous: [], @@ -450,19 +501,17 @@ function partitionFloor({ continue; } if (record.family !== "floor") { - if ( - record.interview_ms < rawWindow.low || - record.interview_ms > rawWindow.high - ) + // A gate observation spans the time its boundary took effect, which can + // be later than the provider event that queued it. + const eventEnd = record.event_end_ms ?? record.interview_ms; + if (eventEnd < rawWindow.low || record.interview_ms > rawWindow.high) continue; // Auxiliary event offsets use the same anchor as this validated // process/room/session; the producer does not include a clock pair there. - const at = joined.project( - record.interview_ms, - record.clock ? clockId(record) : joined.provider_clock_id, - ); + const at = project(record); + const last = project(record, eventEnd); if ( - at.high >= window.low && + last.high >= window.low && at.low <= window.high && (record.family === "replacement" || (record.family === "pressure" && @@ -485,7 +534,7 @@ function partitionFloor({ partitions.preexisting_open.push(record); continue; } - const opening = joined.project(record.opened_ms, clockId(record)); + const opening = project(record, record.opened_ms); if ( record.socket !== selected.socket && opening.high >= window.low && @@ -511,4 +560,12 @@ function partitionFloor({ }; } -module.exports = { loadEvidence, partitionFloor, ReplayEvidenceError }; +module.exports = { + sameScope, + knownReplayTool, + readEvidenceSnapshot, + loadEvidence, + joinEvidenceClock, + partitionFloor, + ReplayEvidenceError, +}; diff --git a/scripts/replay-gates.cjs b/scripts/replay-gates.cjs new file mode 100644 index 000000000..d7b03d5d0 --- /dev/null +++ b/scripts/replay-gates.cjs @@ -0,0 +1,346 @@ +const { + joinEvidenceClock, + knownReplayTool, + sameScope, +} = require("./replay-evidence.cjs"); +const { number: finite, whole: integer } = require("./replay-clock.cjs"); + +const BOUNDARIES = new Set([ + "turn_complete", + "interrupted", + "held", + "socket_replaced", +]); +const GATE_STAGES = new Set([...BOUNDARIES, "closing", "close_requested"]); +const unknown = (reason) => ({ status: "unknown", reason }); +const excluded = (reason) => ({ status: "excluded", reason }); +const ack = (r) => r.family === "latency" && r.stage === "tool_response"; +const boundary = (r) => + r.family === "gate" || (r.family === "latency" && BOUNDARIES.has(r.stage)); +const replacement = (r) => + r.family === "replacement" || + r.stage === "socket_replaced" || + (r.family === "pressure" && + (r.stage === "replacement" || r.stage === "discarded")); +const terminal = (r) => + (r.family === "pressure" && r.stage === "terminal") || + (r.family === "gate" && r.stage === "closing"); +const supported = (g) => + g && + ["hint", "tool"].includes(g.state) && + knownReplayTool(g.tool) && + (g.state !== "hint" || g.tool === "log_hint"); +const eligible = (r, g) => + (r.obligation_outcome === null || r.obligation_outcome === "open") && + r.sent === true && + r.closing === false && + r.accepted_tool_names.includes(g.tool) && + (g.state !== "hint" || r.hint_given === true); +const invalidating = (r) => boundary(r) || replacement(r) || terminal(r); +const incomplete = (r) => + (ack(r) && ![null, "open"].includes(r.obligation_outcome)) || + !r.usable || + !known(r) || + (ack(r) && typeof r.closing !== "boolean"); +const known = (r) => + r.family === "replacement" || + r.family === "pressure" || + (r.family === "gate" && GATE_STAGES.has(r.stage)) || + (r.family === "latency" && + (BOUNDARIES.has(r.stage) || + ["tool_response", "audio_accepted"].includes(r.stage))); + +// The room came from the join token. A known child pid is stronger than picking +// a matching event from a shared server log; otherwise the context must be unique. +function pinGateSession({ evidence, roomName, expectedPid }) { + if ( + !evidence || + !Array.isArray(evidence.records) || + typeof roomName !== "string" || + (expectedPid !== undefined && !integer(expectedPid)) + ) + return unknown("invalid-context-selector"); + const contexts = new Map(); + for (const record of evidence.records) { + if ( + record.family === "floor" || + record.room !== roomName || + (expectedPid !== undefined && record.pid !== expectedPid) + ) + continue; + contexts.set(JSON.stringify([record.pid, record.session]), { + pid: record.pid, + room: record.room, + session: record.session, + }); + } + if (contexts.size !== 1) + return unknown(contexts.size ? "ambiguous-context" : "missing-context"); + return { status: "pinned", selected: [...contexts.values()][0] }; +} + +function selectToolGate({ evidence, roomName, expectedPid, gate }) { + if (!supported(gate)) + return { status: "unsupported_gate", reason: "unsupported-tool-context" }; + const pinned = pinGateSession({ evidence, roomName, expectedPid }); + if (pinned.status !== "pinned") return pinned; + const events = evidence.records.filter( + (r) => sameScope(r, pinned.selected) && r.family !== "floor", + ); + if ( + events.some( + (r) => + incomplete(r) || + !integer(r.interview_ms) || + (ack(r) && !/^[a-f0-9]{64}$/.test(r.evidence_sha256 ?? "")), + ) + ) + return unknown("incomplete-context-evidence"); + events.sort((a, b) => a.interview_ms - b.interview_ms); + let candidate; + let invalidUntil = -1; + let reason = "no-accepted-tool"; + for (let i = 0; i < events.length;) { + let until = i + 1; + while ( + until < events.length && + events[until].interview_ms === events[i].interview_ms + ) + until++; + const group = events.slice(i, until); + i = until; + const acks = group.filter(ack); + const invalidators = group.filter(invalidating); + const invalid = invalidators.length > 0; + if (invalid) + invalidUntil = Math.max( + invalidUntil, + ...invalidators.map((r) => r.event_end_ms ?? r.interview_ms), + ); + if (acks.length) { + if ( + acks.length !== 1 || + invalid || + acks[0].interview_ms <= invalidUntil + ) { + candidate = undefined; + reason = "ambiguous-context-order"; + continue; + } + candidate = eligible(acks[0], gate) ? acks[0] : undefined; + reason = acks[0].closing ? "closing-context" : "no-accepted-tool"; + } else if (invalid) { + candidate = undefined; + reason = "context-boundary"; + } + if ( + candidate && + group.some( + (r) => + r.family === "latency" && + r.stage === "audio_accepted" && + (r.turn !== candidate.turn || r.socket !== candidate.socket), + ) + ) { + candidate = undefined; + reason = "different-output-context"; + } + } + if (!candidate) return { status: "unavailable", reason }; + return { + status: "candidate", + selected: { ...pinned.selected, socket: candidate.socket }, + id: candidate.evidence_sha256, + gate: structuredClone(gate), + event: structuredClone(candidate), + }; +} + +function provisionalAge({ candidate, harnessSample }) { + const maxAgeMs = candidate?.gate?.max_age_ms; + if ( + candidate?.status !== "candidate" || + typeof candidate.id !== "string" || + candidate.event?.evidence_sha256 !== candidate.id + ) + return unknown("candidate-missing"); + const c = candidate.event.clock; + if ( + !c || + ![ + c.start_unix_ms, + c.emitted_ms, + c.emitted_unix_ms, + candidate.event.interview_ms, + ].every(integer) || + !integer(c.clock_uncertainty_ms) || + c.clock_uncertainty_ms < 2 || + c.clock_uncertainty_ms > 5000 || + candidate.event.interview_ms > c.emitted_ms || + !integer(harnessSample?.unix_ms) || + !finite(harnessSample?.mono_ms) || + harnessSample.mono_ms < 0 || + typeof harnessSample?.clock_id !== "string" || + !finite(harnessSample?.uncertainty_ms) || + harnessSample.uncertainty_ms < 1 || + harnessSample.uncertainty_ms > 5000 || + !integer(maxAgeMs) || + maxAgeMs < 1 || + maxAgeMs > 5000 + ) + return unknown("invalid-clock-sample"); + const base = c.emitted_unix_ms - c.emitted_ms + candidate.event.interview_ms; + const low = base - c.clock_uncertainty_ms; + const high = base + 1 + c.clock_uncertainty_ms; + const upper = harnessSample.unix_ms + harnessSample.uncertainty_ms - low; + const lower = harnessSample.unix_ms - harnessSample.uncertainty_ms - high; + if (![low, high, upper, lower].every(finite) || lower <= 0) + return unknown("ambiguous-clock-order"); + const age = { + provisional: true, + age_upper_ms: upper, + age_lower_ms: lower, + clock_id: harnessSample.clock_id, + }; + if (lower > maxAgeMs) + return { status: "expired", reason: "stale-gate", ...age }; + if (upper > maxAgeMs) + return { status: "unknown", reason: "ambiguous-gate-age", ...age }; + return { status: "candidate", ...age }; +} + +function verifyToolGate({ + evidence, + roomName, + expectedPid, + candidate, + gate, + harness, + sampleSpan, + injection, + observationEndMs, + maxUncertaintyMs, +}) { + if (!supported(gate)) + return { status: "unsupported_gate", reason: "unsupported-tool-context" }; + if (evidence?.finalized !== true || evidence?.drained !== true) + return unknown("evidence-not-finalized"); + const pinned = pinGateSession({ evidence, roomName, expectedPid }); + if (pinned.status !== "pinned") return pinned; + if ( + candidate?.status !== "candidate" || + !sameScope(candidate.selected, pinned.selected) + ) + return unknown("candidate-context-mismatch"); + if ( + ["state", "tool", "max_age_ms"].some( + (key) => candidate.gate?.[key] !== gate[key], + ) + ) + return unknown("candidate-gate-mismatch"); + const record = evidence.records.find( + (r) => r.evidence_sha256 === candidate.id && sameScope(r, pinned.selected), + ); + if ( + !record || + !ack(record) || + !eligible(record, gate) || + record.socket !== candidate.selected.socket + ) + return unknown("candidate-missing-or-changed"); + if ( + !injection || + !finite(injection.low) || + !finite(injection.high) || + injection.low > injection.high || + !finite(observationEndMs) || + observationEndMs <= injection.high || + !integer(gate.max_age_ms) || + gate.max_age_ms < 1 || + gate.max_age_ms > 5000 + ) + return unknown("invalid-injection-bracket"); + try { + const join = joinEvidenceClock({ + evidence, + selected: { ...candidate.selected }, + harness, + sampleSpan, + maxUncertaintyMs, + }); + if (injection.clock_id !== join.clock.clock_id) + return unknown("injection-clock-mismatch"); + const at = join.project(record); + if (at.high >= injection.low) return unknown("ambiguous-gate-time"); + const age = injection.high - at.low; + if (injection.low - at.high > gate.max_age_ms) + return excluded("stale-gate"); + if (age > gate.max_age_ms) return unknown("ambiguous-gate-age"); + const raw = join.clock.providerWindow({ + clock_id: injection.clock_id, + low: at.low, + high: observationEndMs, + }); + for (const event of join.records) { + if (event.family === "floor") continue; + if (incomplete(event)) return unknown("incomplete-context-evidence"); + const end = event.event_end_ms ?? event.interview_ms; + if ( + event.evidence_sha256 === candidate.id || + end < record.interview_ms || + event.interview_ms > raw.high + ) + continue; + if ( + event.interview_ms < record.interview_ms || + (event.interview_ms === record.interview_ms && + (ack(event) || invalidating(event))) + ) + return unknown("ambiguous-context-order"); + const first = join.project(event); + const last = join.project(event, end); + const when = { low: first.low, high: last.high }; + const sameOutput = + event.family === "latency" && + event.stage === "audio_accepted" && + event.turn === record.turn && + event.socket === record.socket; + const otherSocket = + ["latency", "gate"].includes(event.family) && + event.socket !== record.socket; + const invalidToEnd = replacement(event) || terminal(event) || otherSocket; + if (invalidToEnd) { + if (when.high < observationEndMs) + return excluded("transport-or-session-change"); + if (when.low <= observationEndMs) + return unknown("ambiguous-observation-boundary"); + } + const invalidAtInjection = + ack(event) || + boundary(event) || + (event.family === "latency" && !sameOutput); + if (invalidAtInjection) { + if (when.high < injection.low) return excluded("superseded-gate"); + if (when.low <= injection.high) + return unknown("ambiguous-injection-order"); + } + } + return { + status: "aligned", + candidate_id: candidate.id, + selected: { ...candidate.selected }, + age_upper_ms: age, + clock_id: injection.clock_id, + }; + } catch (error) { + // Evidence and clock errors carry a reason code; anything else is a bug. + if (typeof error?.reason !== "string") throw error; + return unknown(error.reason); + } +} +module.exports = { + pinGateSession, + selectToolGate, + provisionalAge, + verifyToolGate, +}; diff --git a/scripts/replay-input.cjs b/scripts/replay-input.cjs index 8f64c2ae9..ed3dc9b5c 100644 --- a/scripts/replay-input.cjs +++ b/scripts/replay-input.cjs @@ -1,11 +1,16 @@ const fs = require("node:fs"); const { TextDecoder } = require("node:util"); -class ReplayInputError extends Error {} +class ReplayInputError extends Error { + constructor(message, reason) { + super(message); + this.reason = reason; + } +} function readReplayFile(filename, limit, label) { - const fail = (reason) => { - throw new ReplayInputError(`${label}: ${reason}`); + const fail = (message, reason) => { + throw new ReplayInputError(`${label}: ${message}`, reason); }; let fd; try { @@ -16,29 +21,33 @@ function readReplayFile(filename, limit, label) { (fs.constants.O_NONBLOCK ?? 0), ); const before = fs.fstatSync(fd, { bigint: true }); - if (!before.isFile() || before.size > BigInt(limit)) - fail("input is not a bounded regular file"); - const bytes = Buffer.alloc(limit + 1); + if (!before.isFile()) + fail("input is not a bounded regular file", "invalid-input-file"); + if (before.size > BigInt(limit)) + fail("input exceeds byte limit", "input-limit"); + // One spare byte detects growth without zero-filling the whole limit. + const bytes = Buffer.alloc(Number(before.size) + 1); let size = 0; - while (size <= limit) { - const count = fs.readSync(fd, bytes, size, limit + 1 - size, null); + while (size < bytes.length) { + const count = fs.readSync(fd, bytes, size, bytes.length - size, null); if (!count) break; size += count; } const after = fs.fstatSync(fd, { bigint: true }); - if (size > limit) fail("input exceeds byte limit"); + if (size > limit) fail("input exceeds byte limit", "input-limit"); if ( BigInt(size) !== BigInt(before.size) || after.size !== before.size || after.mtimeNs !== before.mtimeNs || after.ctimeNs !== before.ctimeNs ) - fail("input changed while reading"); + fail("input changed while reading", "input-changed"); return bytes.subarray(0, size); } catch (error) { if (error instanceof ReplayInputError) throw error; const failure = new ReplayInputError( `${label}: ${error.code === "ELOOP" ? "input symlink refused" : "input is not a readable bounded regular file"}`, + error.code === "ENOENT" ? "file-missing" : "invalid-input-file", ); if ( typeof error.code === "string" && @@ -60,7 +69,10 @@ function decodeReplayJson(bytes, label) { ); value = JSON.parse(text); } catch { - throw new Error(`${label}: input is not UTF-8 JSON`); + throw new ReplayInputError( + `${label}: input is not UTF-8 JSON`, + "invalid-json", + ); } const stack = []; for (const match of text.matchAll(/"(?:\\[\s\S]|[^"\\])*"|[{}\[\]]/g)) { @@ -76,9 +88,15 @@ function decodeReplayJson(bytes, label) { ) { const key = JSON.parse(token); if (key === "__proto__") - throw new Error(`${label}: input has a forbidden object key`); + throw new ReplayInputError( + `${label}: input has a forbidden object key`, + "forbidden-key", + ); if (stack.at(-1).has(key)) - throw new Error(`${label}: input has a duplicate object key`); + throw new ReplayInputError( + `${label}: input has a duplicate object key`, + "duplicate-key", + ); stack.at(-1).add(key); } } diff --git a/scripts/rust-style-ceilings.json b/scripts/rust-style-ceilings.json index c5579e26c..9c5b87bba 100644 --- a/scripts/rust-style-ceilings.json +++ b/scripts/rust-style-ceilings.json @@ -6,7 +6,7 @@ "src/agent/report.rs": 1730, "src/gemini.rs": 2838, "src/livekit.rs": 3572, - "src/livekit/session.rs": 2956, + "src/livekit/session.rs": 2946, "src/livekit/turn.rs": 2333, "tests/agent/framework.rs": 4640, "tests/agent/prompts.rs": 2380, diff --git a/src/livekit/latency.rs b/src/livekit/latency.rs index 77da46415..3178181be 100644 --- a/src/livekit/latency.rs +++ b/src/livekit/latency.rs @@ -970,17 +970,48 @@ impl ReplyLatency { } /// Unlike a reply trace, gate invalidation exists even with no output. - fn gate_boundary(&self, boundary: Boundary, now: Instant) -> Value { + fn gate_observation(&self, stage: &str, started: Instant, finished: Instant) -> Value { json!({ "event": "gate_boundary", "version": 1, "pid": std::process::id(), "room": self.room, "session": self.session, "socket": self.socket, "turn": self.trace.as_ref().map(|trace| trace.turn), - "stage": boundary.label(), "interview_ms": self.interview_ms(now), + "stage": stage, "interview_ms": self.interview_ms(started), + "event_end_ms": self.interview_ms(finished), "clock": self.observation_clock(), }) } + /// Observations do not settle or replace the reply latency trace. + pub(super) fn closing(&self, started: Instant, finished: Instant) { + self.gate_observation_to("closing", started, finished, &mut std::io::stderr().lock()); + } + + pub(super) fn closing_requested(&self, started: Instant, finished: Instant) { + self.gate_observation_to( + "close_requested", + started, + finished, + &mut std::io::stderr().lock(), + ); + } + + fn gate_observation_to( + &self, + stage: &str, + started: Instant, + finished: Instant, + output: &mut impl std::io::Write, + ) { + let line = format!( + "codetrial replay_gate {}\n", + self.gate_observation(stage, started, finished) + ); + output + .write_all(line.as_bytes()) + .expect("failed to write replay gate observation"); + } + pub(super) fn boundary(&mut self, boundary: Boundary, now: Instant) -> Option { self.boundary_to(boundary, now, &mut std::io::stderr().lock()) } @@ -991,12 +1022,10 @@ impl ReplyLatency { now: Instant, output: &mut impl std::io::Write, ) -> Option { - writeln!( - output, - "codetrial replay_gate {}", - self.gate_boundary(boundary, now) - ) - .expect("failed to write replay gate boundary"); + // `now` is when the provider event arrived. A queued boundary can be + // handled after a later tool acknowledgement, so the observation also + // spans the time it took effect. + self.gate_observation_to(boundary.label(), now, Instant::now().max(now), output); if matches!(boundary, Boundary::Held) { self.voice_ended = false; self.voice_started = false; diff --git a/src/livekit/packets.rs b/src/livekit/packets.rs index 0a31b1d59..2f8e8f99f 100644 --- a/src/livekit/packets.rs +++ b/src/livekit/packets.rs @@ -328,6 +328,8 @@ pub(super) fn reduce_data_packet( received: bool, receipt_timestamp_ms: u64, ) -> crate::agent::DataEventResult { + let reduction_started = Instant::now(); + let was_ended = state.ended; let code_revision_before = state.evidence_ledger.code.revision; let test_runs_before = state.test_runs; let result = if received { @@ -347,6 +349,9 @@ pub(super) fn reduce_data_packet( receipt_timestamp_ms, ) }; + if !was_ended && state.ended { + activity.latency.closing(reduction_started, Instant::now()); + } activity.observe_candidate_work(state, code_revision_before, test_runs_before); result } @@ -679,3 +684,7 @@ pub(super) fn test_run_line<'a>( pub(super) fn owes_failed_reply(result: &crate::agent::DataEventResult) -> bool { result.carries_thinking_debt } + +#[cfg(test)] +#[path = "../../tests/unit/livekit/packets.rs"] +mod tests; diff --git a/src/livekit/session.rs b/src/livekit/session.rs index 3cf3a0e40..b7e4b3019 100644 --- a/src/livekit/session.rs +++ b/src/livekit/session.rs @@ -19,7 +19,7 @@ mod recovery; use floor::write_floor; pub(super) use floor::{observe_floor, reconcile_floor}; -use observations::{HintCounters, ToolTiming, known_tool_name}; +use observations::{HintCounters, ToolTiming, execute_timed_tool_batch, known_tool_name}; use recovery::log_socket_pressure; pub(super) use recovery::{ @@ -1879,21 +1879,6 @@ fn agent_state_attributes( attributes } -fn execute_timed_tool_batch( - state: &mut RuntimeState, - activity: &mut RuntimeActivity, - calls: Vec, - reviewed_revision: u64, - timed: bool, -) -> Vec<(GeminiFunctionCall, serde_json::Value)> { - execute_tool_batch_observed(state, calls, reviewed_revision, |started, finished| { - if timed { - activity.turn_timing.note_tool_request(started); - activity.turn_timing.note_tool_execution(started, finished); - } - }) -} - /// Public so the behaviour check in `tests/interview_behavior.rs` answers a /// text model's tool calls with this dispatch rather than a copy of it. pub fn execute_tool_call(state: &mut RuntimeState, call: &GeminiFunctionCall) -> serde_json::Value { @@ -1937,14 +1922,14 @@ pub(super) fn execute_tool_batch( calls: Vec, reviewed_revision: u64, ) -> Vec<(GeminiFunctionCall, serde_json::Value)> { - execute_tool_batch_observed(state, calls, reviewed_revision, |_, _| {}) + execute_tool_batch_observed(state, calls, reviewed_revision, |_, _, _| {}) } fn execute_tool_batch_observed( state: &mut RuntimeState, calls: Vec, reviewed_revision: u64, - mut observe: impl FnMut(Instant, Instant), + mut observe: impl FnMut(Instant, Instant, bool), ) -> Vec<(GeminiFunctionCall, serde_json::Value)> { let review_changed = editor_review_allowed(state) && state.code != state.code_shown @@ -1963,13 +1948,18 @@ fn execute_tool_batch_observed( .enumerate() .map(|(index, call)| { let started = Instant::now(); + let was_requested = state.end_requested; let response = execute_tool_call_with_continuity( state, &call, Some(index) == last_continuity, Some(index) == last_framework, ); - observe(started, Instant::now()); + observe( + started, + Instant::now(), + !was_requested && state.end_requested, + ); (call, response) }) .collect::>(); diff --git a/src/livekit/session/floor.rs b/src/livekit/session/floor.rs index 9b3ad62da..c63b1fc16 100644 --- a/src/livekit/session/floor.rs +++ b/src/livekit/session/floor.rs @@ -47,11 +47,12 @@ pub(super) fn write_floor( let sample = sample.get_or_insert_with(|| latency.observation_clock()); let number = |key: &str| value(sample[key].as_i64()); let event_time = |at: Option| value(at.and_then(|at| latency.interview_ms(at))); - writeln!(output, "{} opened_ms={} resolved_ms={} activity_end_ms={} emitted_ms={} emitted_unix_ms={} start_unix_ms={} clock_uncertainty_ms={} pid={}", + // One write, so the line cannot be split or cost a syscall per field. + let line = format!("{} opened_ms={} resolved_ms={} activity_end_ms={} emitted_ms={} emitted_unix_ms={} start_unix_ms={} clock_uncertainty_ms={} pid={}\n", record.log_line(room, session, socket, at), event_time(Some(record.opened_at)), event_time(record.resolved_at), event_time(record.activity_end_at), - number("emitted_ms"), number("emitted_unix_ms"), number("start_unix_ms"), number("clock_uncertainty_ms"), std::process::id()) - .expect("failed to write floor observation"); + number("emitted_ms"), number("emitted_unix_ms"), number("start_unix_ms"), number("clock_uncertainty_ms"), std::process::id()); + output.write_all(line.as_bytes()).expect("failed to write floor observation"); }); } diff --git a/src/livekit/session/observations.rs b/src/livekit/session/observations.rs index 51551a3b8..6dbffcd0f 100644 --- a/src/livekit/session/observations.rs +++ b/src/livekit/session/observations.rs @@ -26,6 +26,29 @@ pub(super) fn known_tool_name(name: &str) -> &'static str { .unwrap_or("unknown") } +pub(super) fn execute_timed_tool_batch( + state: &mut RuntimeState, + activity: &mut RuntimeActivity, + calls: Vec, + reviewed_revision: u64, + timed: bool, +) -> Vec<(GeminiFunctionCall, Value)> { + super::execute_tool_batch_observed( + state, + calls, + reviewed_revision, + |started, finished, closing| { + if timed { + activity.turn_timing.note_tool_request(started); + activity.turn_timing.note_tool_execution(started, finished); + } + if closing { + activity.latency.closing_requested(started, finished); + } + }, + ) +} + pub(super) struct HintCounters { rungs: usize, volunteered: u32, @@ -83,6 +106,7 @@ pub(super) fn tool_timing( (accepted.contains(&TOOL_LOG_HINT) && hints_before.advanced(state)).into(); record["accepted_tool_names"] = accepted.into(); record["sent"] = timing.sent.into(); + record["closing"] = (state.end_requested || state.ended).into(); record } diff --git a/tests/browser/replay-evidence.test.js b/tests/browser/replay-evidence.test.js index 43effdc53..2a4d35404 100644 --- a/tests/browser/replay-evidence.test.js +++ b/tests/browser/replay-evidence.test.js @@ -85,6 +85,21 @@ test("joins actual floor fields by opening time even when resolution emits at te 0, ); }); +test("a replacement that began before the window but took effect inside it invalidates", (t) => { + const replaced = (extra = {}) => + artifacts( + t, + floor(), + gate(0) + + gate(900, { stage: "socket_replaced", clock: clock(1200), ...extra }) + + gate(2500), + ).load(); + assert.equal(partition(replaced()).invalidations.length, 0); + assert.equal( + partition(replaced({ event_end_ms: 1200 })).invalidations.length, + 1, + ); +}); test("late preexisting emission cannot be selected as injected activity", (t) => { const result = partition(artifacts(t, floor({ opened_ms: 100 })).load()); assert.equal(result.definitely_in.length, 0); diff --git a/tests/browser/replay-fixture.test.js b/tests/browser/replay-fixture.test.js index 900fecda2..80a316383 100644 --- a/tests/browser/replay-fixture.test.js +++ b/tests/browser/replay-fixture.test.js @@ -276,17 +276,11 @@ test("caps are checked at the limit and one frame/byte past, without provider ac f.setBytes(audio("pcm_s16le", 30000)); assert.equal(loadFixture(f.filename, "socket").duration_ms, 30000); f.setBytes(Buffer.concat([audio("pcm_s16le", 30000), Buffer.alloc(2)])); - assert.throws( - () => loadFixture(f.filename, "socket"), - /bounded regular file/, - ); + assert.throws(() => loadFixture(f.filename, "socket"), /exceeds byte limit/); fs.writeFileSync(f.filename, " ".repeat(16384)); assert.throws(() => loadFixture(f.filename, "socket"), /UTF-8 JSON/); fs.appendFileSync(f.filename, " "); - assert.throws( - () => loadFixture(f.filename, "socket"), - /bounded regular file/, - ); + assert.throws(() => loadFixture(f.filename, "socket"), /exceeds byte limit/); }); test("CLI exits nonzero on invalid input and prints only offline fixture metadata", (t) => { @@ -436,10 +430,7 @@ test("WAV duration and file-byte ceilings accept exact boundaries and reject exc assert.equal(loadFixture(f.filename, "browser").bytes.length, 2945536); assert.equal(loadFixture(f.filename, "browser").frames, 4800); f.setBytes(Buffer.concat([atLimit, Buffer.alloc(1)])); - assert.throws( - () => loadFixture(f.filename, "browser"), - /bounded regular file/, - ); + assert.throws(() => loadFixture(f.filename, "browser"), /exceeds byte limit/); }); test("pause threshold is inclusive at +/-500 and bounds require a real internal interval", (t) => { diff --git a/tests/browser/replay-gates.test.js b/tests/browser/replay-gates.test.js new file mode 100644 index 000000000..014235d29 --- /dev/null +++ b/tests/browser/replay-gates.test.js @@ -0,0 +1,419 @@ +import assert from "node:assert/strict"; +import { createRequire } from "node:module"; +const require = createRequire(import.meta.url); +import { test } from "node:test"; +const fs = require("node:fs"); +const os = require("node:os"); +const path = require("node:path"); +const { + readEvidenceSnapshot, + loadEvidence, +} = require("../../scripts/replay-evidence.cjs"); +const { + pinGateSession, + selectToolGate, + provisionalAge, + verifyToolGate, +} = require("../../scripts/replay-gates.cjs"); +const identity = { pid: 42, room: "gate-test", session: 7, socket: 2 }; +const gate = { state: "hint", tool: "log_hint", max_age_ms: 250 }; +const clock = (ms) => ({ + start_unix_ms: 100000, + emitted_ms: ms, + emitted_unix_ms: 100000 + ms, + clock_uncertainty_ms: 2, +}); +function reply(ms, extra = {}) { + return `codetrial latency ${JSON.stringify({ ...identity, event: "reply_latency", version: 2, turn: 1, stage: "tool_response", origin_socket: 1, obligation_outcome: "open", interview_ms: ms, clock: clock(ms), sent: true, hint_given: true, accepted_tool_names: ["log_hint"], closing: false, ...extra })}\n`; +} +function boundary(ms, extra = {}) { + return `codetrial replay_gate ${JSON.stringify({ ...identity, event: "gate_boundary", version: 1, turn: null, stage: "turn_complete", interview_ms: ms, clock: clock(ms), ...extra })}\n`; +} +function trial(t, prefix = reply(1000)) { + const dir = fs.mkdtempSync(path.join(os.tmpdir(), "replay-gates-")); + t.after(() => fs.rmSync(dir, { recursive: true, force: true })); + const input = { + floorPath: path.join(dir, "floor.log"), + latencyPath: path.join(dir, "latency.log"), + }; + fs.writeFileSync(input.floorPath, ""); + fs.writeFileSync(input.latencyPath, boundary(0, { socket: 1 }) + prefix); + const live = () => readEvidenceSnapshot(input); + const choose = (extra = {}) => + selectToolGate({ + evidence: live(), + roomName: identity.room, + gate, + ...extra, + }); + const candidate = choose(); + const finish = (more = "") => { + fs.appendFileSync(input.latencyPath, more + boundary(3000)); + return loadEvidence({ ...input, finalized: true, drained: true }); + }; + const verify = (evidence, extra = {}) => + verifyToolGate({ + evidence, + roomName: identity.room, + candidate, + gate, + harness: [ + { + clock_id: "node:test", + mono_ms: 0, + unix_ms: 100000, + uncertainty_ms: 1, + }, + { + clock_id: "node:test", + mono_ms: 4000, + unix_ms: 104000, + uncertainty_ms: 1, + }, + ], + sampleSpan: { from_ms: 0, through_ms: 3000 }, + injection: { clock_id: "node:test", low: 1100, high: 1101 }, + observationEndMs: 2000, + maxUncertaintyMs: 20, + ...extra, + }); + return { input, live, choose, candidate, finish, verify }; +} +test("actual live-reader candidate remains provisional until finalized posthoc verification", (t) => { + const r = trial(t); + assert.equal(r.live().finalized, false); + assert.equal(r.candidate.status, "candidate"); + assert.equal(r.candidate.event.origin_socket, 1); + assert.equal(r.candidate.selected.socket, 2); + assert.equal(r.verify(r.live()).reason, "evidence-not-finalized"); + assert.equal(r.verify(r.finish()).status, "aligned"); + const age = provisionalAge({ + candidate: r.candidate, + harnessSample: { + clock_id: "node:test", + mono_ms: 1100, + unix_ms: 101100, + uncertainty_ms: 1, + }, + maxAgeMs: 250, + }); + assert.equal(age.status, "candidate"); + assert.equal(age.age_upper_ms, 103); + assert.equal(age.provisional, true); +}); +test("withheld/exhausted, unsent, closing and legacy unknown closing cannot open hint context", (t) => { + for (const change of [ + { hint_given: false }, + { sent: false }, + { accepted_tool_names: [] }, + { closing: true }, + { closing: undefined }, + ]) { + const r = trial(t, reply(1000, change)); + assert.notEqual(r.candidate.status, "candidate"); + } + const r = trial(t); + assert.equal( + r.choose({ gate: { state: "tool", tool: "future_tool" } }).status, + "unsupported_gate", + ); +}); +test("same-turn later accepted or failed batch supersedes the selected event before injection", (t) => { + for (const sent of [false, true]) { + const r = trial(t); + assert.equal( + r.verify(r.finish(reply(1050, { sent }))).reason, + "superseded-gate", + ); + } + const r = trial(t, reply(1000) + reply(1050)); + assert.equal(r.candidate.event.interview_ms, 1050); + assert.equal(r.verify(r.finish()).status, "aligned"); +}); +test("gate-only null-turn boundaries and their optional latency twin invalidate without arrival ordering", (t) => { + const r = trial(t); + const data = r.finish( + boundary(1050) + + reply(1050, { stage: "turn_complete", obligation_outcome: "answered" }), + ); + assert.equal(r.verify(data).reason, "superseded-gate"); + const only = trial(t); + assert.equal( + only.verify(only.finish(boundary(1050))).reason, + "superseded-gate", + ); + const equal = trial(t, reply(1000) + boundary(1000)); + assert.notEqual(equal.candidate.status, "candidate"); +}); +test("ordinary completion after injection is an outcome while interval overlap is unknown", (t) => { + const r = trial(t); + assert.equal(r.verify(r.finish(boundary(1500))).status, "aligned"); + const overlap = trial(t); + assert.equal( + overlap.verify(overlap.finish(boundary(1100))).reason, + "ambiguous-injection-order", + ); +}); +test("replacement under the old socket invalidates through observation end, but one before a fresh ack does not", (t) => { + const r = trial(t); + assert.equal( + r.verify(r.finish(boundary(1500, { socket: 1, stage: "socket_replaced" }))) + .reason, + "transport-or-session-change", + ); + const before = trial( + t, + boundary(500, { socket: 1, stage: "socket_replaced" }) + reply(1000), + ); + assert.equal(before.candidate.status, "candidate"); + assert.equal(before.verify(before.finish()).status, "aligned"); + const touch = trial(t); + assert.equal( + touch.verify( + touch.finish(boundary(2000, { socket: 1, stage: "socket_replaced" })), + ).reason, + "ambiguous-observation-boundary", + ); +}); +function pressure(ms, extra = {}) { + return `codetrial latency ${JSON.stringify({ ...identity, event: "socket_pressure", version: 2, interview_ms: ms, end: "discarded", reader_end: "stopped", capacity: 256, occupancy_high_water: 0, blocked_sends: 0, blocked_ms_total: 0, blocked_ms_max: 0, received: 0, consumed: 0, ...extra })}\n`; +} +test("a discarded socket invalidates through observation end like a replacement", (t) => { + const r = trial(t); + assert.equal( + r.verify(r.finish(pressure(1500, { socket: 1 }))).reason, + "transport-or-session-change", + ); +}); +test("a boundary received before the acknowledgement but handled after it expires the candidate", (t) => { + const r = trial( + t, + boundary(950, { + stage: "interrupted", + event_end_ms: 1050, + clock: clock(1050), + }) + reply(1000), + ); + assert.notEqual(r.candidate.status, "candidate"); + assert.equal(r.candidate.reason, "ambiguous-context-order"); +}); +test("same-turn audio is neutral; different-turn audio before injection expires context", (t) => { + const r = trial(t, reply(1000) + reply(1050, { stage: "audio_accepted" })); + assert.equal(r.candidate.status, "candidate"); + assert.equal(r.verify(r.finish()).status, "aligned"); + const other = trial(t); + assert.equal( + other.verify( + other.finish(reply(1050, { stage: "audio_accepted", turn: 2 })), + ).reason, + "superseded-gate", + ); +}); +test("equal-ms distinct acknowledgements stay ambiguous by exact record identity", (t) => { + const r = trial( + t, + reply(1000, { tool_batches: 1 }) + reply(1000, { tool_batches: 2 }), + ); + assert.notEqual(r.candidate.status, "candidate"); + const later = trial(t); + assert.equal( + later.verify(later.finish(reply(1000, { tool_batches: 2 }))).reason, + "ambiguous-context-order", + ); +}); +test("joined room and unique producer identity are pinned without choosing a favorable session", (t) => { + const r = trial(t, reply(1000) + reply(1001, { pid: 43 })); + assert.equal(r.candidate.reason, "ambiguous-context"); + assert.equal(r.choose({ expectedPid: 42 }).status, "candidate"); + assert.equal( + pinGateSession({ evidence: r.live(), roomName: "wrong-room" }).reason, + "missing-context", + ); + assert.equal(r.choose({ expectedPid: 99 }).reason, "missing-context"); +}); +test("posthoc refuses stale clocks, substituted domains and incomplete context", (t) => { + const r = trial(t); + const evidence = r.finish(); + assert.equal( + r.verify(evidence, { gate: { ...gate, max_age_ms: 100 } }).reason, + "candidate-gate-mismatch", + ); + assert.equal( + r.verify(evidence, { + injection: { clock_id: "page:other", low: 1100, high: 1101 }, + }).reason, + "injection-clock-mismatch", + ); + const unknown = trial(t); + assert.equal( + unknown.verify(unknown.finish(reply(1200, { stage: "future" }))).reason, + "incomplete-context-evidence", + ); +}); + +test("freshness limits distinguish fresh, definitely stale and age uncertainty", (t) => { + const r = trial(t); + const evidence = r.finish(); + assert.equal( + r.verify(evidence, { + injection: { clock_id: "node:test", low: 1247, high: 1247 }, + }).status, + "aligned", + ); + assert.equal( + r.verify(evidence, { + injection: { clock_id: "node:test", low: 1253, high: 1253 }, + }).reason, + "ambiguous-gate-age", + ); + assert.equal( + r.verify(evidence, { + injection: { clock_id: "node:test", low: 1260, high: 1261 }, + }).reason, + "stale-gate", + ); + for (const [unix_ms, status] of [ + [101247, "candidate"], + [101250, "unknown"], + [101260, "expired"], + ]) + assert.equal( + provisionalAge({ + candidate: r.candidate, + harnessSample: { + clock_id: "node:test", + mono_ms: unix_ms - 100000, + unix_ms, + uncertainty_ms: 1, + }, + }).status, + status, + ); + assert.equal( + r.verify(evidence, { gate: { ...gate, max_age_ms: 100 } }).reason, + "candidate-gate-mismatch", + ); +}); + +test("closing without another batch invalidates a selected gate and nonopen obligations never qualify", (t) => { + const r = trial(t); + assert.equal( + r.verify(r.finish(boundary(1050, { stage: "closing" }))).reason, + "transport-or-session-change", + ); + for (const obligation_outcome of ["answered", "superseded", "ended"]) { + const other = trial(t, reply(1000, { obligation_outcome })); + assert.notEqual(other.candidate.status, "candidate"); + } +}); + +test("a closing-request reduction interval cannot become an exact late boundary", (t) => { + const r = trial(t); + assert.equal( + r.verify( + r.finish( + boundary(1050, { + stage: "close_requested", + event_end_ms: 1150, + clock: clock(1150), + }), + ), + ).reason, + "ambiguous-injection-order", + ); + const early = trial(t); + assert.equal( + early.verify( + early.finish( + boundary(1040, { + stage: "close_requested", + event_end_ms: 1060, + clock: clock(1060), + }), + ), + ).reason, + "superseded-gate", + ); + const overlappingAck = trial( + t, + boundary(900, { + stage: "close_requested", + event_end_ms: 1050, + clock: clock(1050), + }) + reply(1000), + ); + assert.equal(overlappingAck.candidate.reason, "ambiguous-context-order"); +}); + +test("posthoc rejects other sockets, a changed anchor, missing pid and lost sample brackets", (t) => { + for (const stage of ["tool_response", "audio_accepted"]) { + const r = trial(t); + assert.equal( + r.verify(r.finish(reply(1500, { stage, socket: 3 }))).reason, + "transport-or-session-change", + ); + } + const changed = trial(t); + assert.equal( + changed.verify( + changed.finish( + boundary(1500, { + stage: "socket_replaced", + clock: { ...clock(1500), start_unix_ms: 100001 }, + }), + ), + ).reason, + "invalid-provider-sample", + ); + const missing = trial(t); + assert.equal( + missing.verify(missing.finish(), { expectedPid: 99 }).reason, + "missing-context", + ); + const bracket = trial(t); + assert.equal( + bracket.verify(bracket.finish(boundary(1500)), { + sampleSpan: { from_ms: 1200, through_ms: 3000 }, + }).reason, + "event-outside-provider-samples", + ); +}); + +test("legacy context anywhere in the pinned capture prevents a false freshness certificate", (t) => { + const r = trial(t); + assert.equal( + r.verify(r.finish(reply(100, { closing: undefined }))).reason, + "incomplete-context-evidence", + ); + const unknownTool = trial(t); + assert.throws( + () => + unknownTool.finish(reply(1200, { accepted_tool_names: ["future_tool"] })), + /invalid-tool-context/, + ); +}); + +test("posthoc does not discard a delayed interval starting before the selected acknowledgement", (t) => { + const r = trial(t); + const evidence = r.finish( + boundary(900, { + stage: "close_requested", + event_end_ms: 1150, + clock: clock(1150), + }), + ); + assert.equal(r.verify(evidence).reason, "ambiguous-context-order"); + const earlier = trial(t); + assert.equal( + earlier.verify( + earlier.finish( + boundary(980, { + stage: "closing", + event_end_ms: 1003, + clock: clock(1003), + }), + ), + ).reason, + "ambiguous-context-order", + ); +}); diff --git a/tests/browser/replay-input.test.js b/tests/browser/replay-input.test.js index 4c58ab880..6aee29605 100644 --- a/tests/browser/replay-input.test.js +++ b/tests/browser/replay-input.test.js @@ -20,10 +20,9 @@ test("regular input accepts the exact byte cap and refuses one more byte", (t) = const name = file(t, Buffer.alloc(8, 1)); assert.equal(readReplayFile(name, 8, "replay input").length, 8); fs.appendFileSync(name, Buffer.from([1])); - assert.throws( - () => readReplayFile(name, 8, "replay input"), - /bounded regular/, - ); + assert.throws(() => readReplayFile(name, 8, "replay input"), { + reason: "input-limit", + }); }); test("growth below the read cap is still detected by the final stat", (t) => { const name = file(t, "abc"); @@ -37,10 +36,9 @@ test("growth below the read cap is still detected by the final stat", (t) => { } return result; }); - assert.throws( - () => readReplayFile(name, 8, "replay input"), - /changed while reading/, - ); + assert.throws(() => readReplayFile(name, 8, "replay input"), { + reason: "input-changed", + }); assert.equal(grew, true); }); test("same-size rewrite with an observed metadata change refuses", (t) => { @@ -56,10 +54,9 @@ test("same-size rewrite with an observed metadata change refuses", (t) => { } return result; }); - assert.throws( - () => readReplayFile(name, 8, "replay input"), - /changed while reading/, - ); + assert.throws(() => readReplayFile(name, 8, "replay input"), { + reason: "input-changed", + }); assert.equal(changed, true); }); test("shared JSON decoding validates nested keys and encoding without coercion", () => { @@ -88,3 +85,45 @@ test("JSON BOMs cannot be stripped into an accepted payload", () => { /not UTF-8 JSON/, ); }); + +test("typed input reasons distinguish missing, invalid and malformed files", (t) => { + const name = file(t, "ok"); + assert.throws(() => readReplayFile(path.dirname(name), 8, "input"), { + reason: "invalid-input-file", + }); + assert.throws(() => readReplayFile(name + ".missing", 8, "input"), { + reason: "file-missing", + }); + const link = name + ".link"; + fs.symlinkSync(name, link); + assert.throws(() => readReplayFile(link, 8, "input"), { + reason: "invalid-input-file", + code: "ELOOP", + }); + for (const [text, reason] of [ + ["{", "invalid-json"], + ['{"a":1,"a":2}', "duplicate-key"], + ['{"__proto__":{}}', "forbidden-key"], + ]) + assert.throws(() => decodeReplayJson(Buffer.from(text), "input"), { + reason, + }); +}); + +test("file growth past the cap has the same input-limit reason as an initially oversized file", (t) => { + const name = file(t, "12345678"); + const stat = fs.fstatSync; + let grew = false; + t.mock.method(fs, "fstatSync", (fd, options) => { + const result = stat(fd, options); + if (!grew) { + grew = true; + fs.appendFileSync(name, "9"); + } + return result; + }); + assert.throws(() => readReplayFile(name, 8, "input"), { + reason: "input-limit", + }); + assert.equal(grew, true); +}); diff --git a/tests/unit/livekit/latency/gates.rs b/tests/unit/livekit/latency/gates.rs index 4a6939a68..ae5b66525 100644 --- a/tests/unit/livekit/latency/gates.rs +++ b/tests/unit/livekit/latency/gates.rs @@ -35,3 +35,54 @@ fn gate_invalidation_exists_without_a_trace_for_every_boundary() { assert!(event["clock"]["emitted_unix_ms"].as_u64().is_some()); } } + +#[test] +fn closing_observation_keeps_the_current_reply_trace_intact() { + let (start, mut trace) = traced(); + trace.anchor(start); + trace.tool_response(start, 1, true); + let before = trace.record("tool_response", start, Outcome::Open); + let mut output = Vec::new(); + trace.gate_observation_to("closing", ms(start, 40), ms(start, 50), &mut output); + let text = String::from_utf8(output).unwrap(); + let event: Value = serde_json::from_str( + text.trim_end() + .strip_prefix("codetrial replay_gate ") + .unwrap(), + ) + .unwrap(); + assert_eq!(event["stage"], "closing"); + assert_eq!(event["interview_ms"], 40); + assert_eq!(event["event_end_ms"], 50); + assert_eq!(event["turn"], before["turn"]); + assert!(trace.is_open()); + let after = trace.record("tool_response", start, Outcome::Open); + for key in [ + "turn", + "origin", + "tool_batches", + "last_tool_response_ms", + "obligation", + "obligation_outcome", + ] { + assert_eq!(before[key], after[key], "{key}"); + } +} + +#[test] +fn a_queued_boundary_ends_when_it_is_handled_not_when_it_arrived() { + let (start, mut trace) = traced(); + trace.anchor(start); + let mut output = Vec::new(); + std::thread::sleep(std::time::Duration::from_millis(20)); + let _ = trace.boundary_to(Boundary::Interrupted, start, &mut output); + let text = String::from_utf8(output).unwrap(); + let event: Value = serde_json::from_str( + text.trim_end() + .strip_prefix("codetrial replay_gate ") + .unwrap(), + ) + .unwrap(); + assert_eq!(event["interview_ms"], 0); + assert!(event["event_end_ms"].as_u64().unwrap() >= 20); +} diff --git a/tests/unit/livekit/packets.rs b/tests/unit/livekit/packets.rs new file mode 100644 index 000000000..7710049c0 --- /dev/null +++ b/tests/unit/livekit/packets.rs @@ -0,0 +1,81 @@ +use super::*; +use serde_json::Value; + +#[test] +fn closing_transition_is_logged_once_for_received_and_server_controls() { + const NAME: &str = "livekit::packets::tests::closing_transition_is_logged_once_for_received_and_server_controls"; + if let Ok(origin) = std::env::var("CODETRIAL_REPLAY_END_TEST") { + let received = origin == "received"; + let start = Instant::now(); + let mut state = RuntimeState::default(); + let mut activity = RuntimeActivity::for_interview(start, 0, 7); + activity.latency.bind("closing-test", 7, 1, 1500); + activity.latency.anchor(start); + let payload = serde_json::json!({"type":"end_interview", "reason":"synthetic-end"}); + let first = reduce_data_packet( + &mut state, + &mut activity, + TOPIC_CONTROL, + &payload, + received, + 1000, + ); + assert!(first.finish_interview.is_some()); + assert!(state.ended); + + // The record must precede this marker: logging only on a repeat would + // still leave one record in total. + eprintln!("step:first"); + let again = reduce_data_packet( + &mut state, + &mut activity, + TOPIC_CONTROL, + &payload, + received, + 1001, + ); + assert!(again.finish_interview.is_none()); + eprintln!("step:again"); + return; + } + for origin in ["received", "server"] { + let output = std::process::Command::new(std::env::current_exe().unwrap()) + .args(["--exact", NAME, "--nocapture"]) + .env("CODETRIAL_REPLAY_END_TEST", origin) + .output() + .unwrap(); + assert!( + output.status.success(), + "{}", + String::from_utf8_lossy(&output.stderr) + ); + let stderr = String::from_utf8_lossy(&output.stderr); + let order = stderr + .lines() + .filter_map(|line| { + if line.starts_with("codetrial replay_gate ") { + Some("record") + } else if line.starts_with("step:") { + Some(line) + } else { + None + } + }) + .collect::>(); + assert_eq!( + order, + ["record", "step:first", "step:again"], + "origin={origin}" + ); + let records = stderr + .lines() + .filter_map(|line| line.strip_prefix("codetrial replay_gate ")) + .map(|line| serde_json::from_str::(line).unwrap()) + .collect::>(); + assert_eq!(records[0]["stage"], "closing"); + assert_eq!(records[0]["session"], 7); + assert_eq!(records[0]["socket"], 1); + assert_eq!(records[0]["room"], "closing-test"); + assert!(records[0]["turn"].is_null()); + } +} diff --git a/tests/unit/livekit/session/observations.rs b/tests/unit/livekit/session/observations.rs index 487a20c00..cc3b80d46 100644 --- a/tests/unit/livekit/session/observations.rs +++ b/tests/unit/livekit/session/observations.rs @@ -1,5 +1,5 @@ use super::*; -use crate::livekit::session::execute_tool_call; +use crate::livekit::session::{execute_tool_batch_observed, execute_tool_call}; use serde_json::json; fn call(name: &str, requested: bool) -> GeminiFunctionCall { @@ -84,3 +84,135 @@ fn hint_context_distinguishes_released_volunteered_withheld_and_exhausted_calls( ); } } + +#[test] +fn closing_context_observes_pending_and_completed_end_without_changing_either() { + for (requested, ended, expected) in [ + (false, false, false), + (true, false, true), + (false, true, true), + ] { + let state = RuntimeState { + end_requested: requested, + ended, + ..RuntimeState::default() + }; + let mut activity = RuntimeActivity::for_interview(Instant::now(), 0, 4); + let record = tool_timing( + &mut activity, + &state, + &[(call(TOOL_READ_EDITOR, true), json!({"result":"synthetic"}))], + HintCounters::capture(&state), + timing(true), + ); + assert_eq!(record["closing"], expected); + assert_eq!(state.end_requested, requested); + assert_eq!(state.ended, ended); + } +} + +#[test] +fn accepted_close_request_is_observed_before_tool_batch_response_timing() { + const NAME: &str = "livekit::session::observations::tests::accepted_close_request_is_observed_before_tool_batch_response_timing"; + if let Ok(mode) = std::env::var("CODETRIAL_REPLAY_CLOSE_TEST") { + let refused = mode == "refused"; + let fresh_state = || { + let mut state = RuntimeState { + interview_loop: crate::agent::InterviewLoop::CodingBehavioral, + code: "def solve(nums):\n return sorted(nums)\n".into(), + language: "python".into(), + round_transition_seen: !refused, + ..RuntimeState::default() + }; + crate::livekit::tests::receive_test_run(&mut state); + for phase in ["test", "optimizations"] { + crate::agent::record_framework_evidence( + &mut state, + &json!({"phase":phase, "source":crate::livekit::tests::observed_source(phase), "kind":"observed", "confidence":90, "summary":"synthetic evidence"}), + ).unwrap(); + } + state + }; + let mut state = fresh_state(); + let start = Instant::now(); + let mut activity = RuntimeActivity::for_interview(start, 0, 7); + activity.latency.bind("closing-test", 7, 1, 1500); + activity.latency.anchor(start); + let answers = execute_timed_tool_batch( + &mut state, + &mut activity, + vec![ + call(TOOL_END_INTERVIEW, true), + call(TOOL_END_INTERVIEW, true), + ], + 0, + true, + ); + assert_eq!(answers.len(), 2); + assert!( + answers + .iter() + .all(|(_, value)| value.get("error").is_some() == refused) + ); + assert_eq!(state.end_requested, !refused); + assert!(!state.ended); + + // Which call newly requested the end, not only how many records there + // were: observing the repeat instead of the first would still give one. + let mut again = fresh_state(); + let mut flags = Vec::new(); + execute_tool_batch_observed( + &mut again, + vec![ + call(TOOL_END_INTERVIEW, true), + call(TOOL_END_INTERVIEW, true), + ], + 0, + |_, _, newly_requested| flags.push(newly_requested), + ); + eprintln!("close_flags={flags:?}"); + return; + } + for mode in ["accepted", "refused"] { + let output = std::process::Command::new(std::env::current_exe().unwrap()) + .args(["--exact", NAME, "--nocapture"]) + .env("CODETRIAL_REPLAY_CLOSE_TEST", mode) + .output() + .unwrap(); + assert!( + output.status.success(), + "{}", + String::from_utf8_lossy(&output.stderr) + ); + let records = String::from_utf8_lossy(&output.stderr) + .lines() + .filter_map(|line| line.strip_prefix("codetrial replay_gate ")) + .map(|line| serde_json::from_str::(line).unwrap()) + .collect::>(); + let flags = String::from_utf8_lossy(&output.stderr) + .lines() + .find_map(|line| line.strip_prefix("close_flags=").map(str::to_owned)) + .unwrap(); + assert_eq!( + flags, + if mode == "accepted" { + "[true, false]" + } else { + "[false, false]" + } + ); + assert_eq!(records.len(), usize::from(mode == "accepted")); + if records.is_empty() { + continue; + } + assert_eq!(records[0]["stage"], "close_requested"); + assert!( + records[0]["interview_ms"].as_i64().unwrap() + <= records[0]["event_end_ms"].as_i64().unwrap() + ); + assert!( + records[0]["event_end_ms"].as_i64().unwrap() + <= records[0]["clock"]["emitted_ms"].as_i64().unwrap() + ); + } +}