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/observational-replay.md b/docs/observational-replay.md new file mode 100644 index 000000000..f804acf31 --- /dev/null +++ b/docs/observational-replay.md @@ -0,0 +1,258 @@ +# 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. + +## 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. + +## 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 fd733db5e..69632b593 100644 --- a/docs/turn-timing.md +++ b/docs/turn-timing.md @@ -186,26 +186,90 @@ 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`, +`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 +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. `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 +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 @@ -220,6 +284,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/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..0f60746f2 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.resetLine(); } - this.pending = ""; - this.discarding = false; + } + } + + resetLine() { + this.pending = ""; + this.pendingBytes = 0; + this.tail = ""; + this.diagnostic = false; + this.discarding = false; + } + + discontinuity(reason) { + try { + this.incomplete(reason); + } finally { + this.resetLine(); + 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,56 @@ function assertInterruptedOverlap(path, room) { } } -module.exports = { FloorCapture, assertInterruptedOverlap, readFloorRecords }; +module.exports = { + PREFIXES, + 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 +280,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/replay-clock.cjs b/scripts/replay-clock.cjs new file mode 100644 index 000000000..08e0edf8d --- /dev/null +++ b/scripts/replay-clock.cjs @@ -0,0 +1,180 @@ +// 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.map((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, number, whole }; diff --git a/scripts/replay-evidence.cjs b/scripts/replay-evidence.cjs new file mode 100644 index 000000000..57397d3e5 --- /dev/null +++ b/scripts/replay-evidence.cjs @@ -0,0 +1,571 @@ +// Complete diagnostic artifacts are evidence; arrival order is never event order. +const { sha256 } = require("./long-interview-schedule.cjs"); +const { TextDecoder } = require("node:util"); +const { readReplayFile, decodeReplayJson } = require("./replay-input.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 = 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", + "read_board", + "read_conversation", + "log_hint", + "record_framework_evidence", + "end_interview", +]); + +function knownReplayTool(name) { + return TOOLS.has(name); +} + +class ReplayEvidenceError extends Error { + constructor(reason) { + super(`replay evidence: ${reason}`); + this.reason = reason; + } +} +function requireValue(condition, reason) { + if (!condition) throw new ReplayEvidenceError(reason); +} +function room(n) { + return typeof n === "string" && /^[a-zA-Z0-9_.:-]{1,128}$/.test(n); +} +function optional(n) { + return n === null || integer(n); +} +const sameScope = (a, b) => + a.pid === b.pid && a.room === b.room && a.session === b.session; +function clockId(record) { + return `producer:${sha256( + JSON.stringify([ + record.pid, + record.room, + record.session, + record.clock.start_unix_ms, + ]), + )}`; +} + +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", + ); + 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); + 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( + CLOCK_KEYS.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 === "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; + 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(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]; + } + } + 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); + record.evidence_sha256 = sha256(line + "\n"); + records.push(record); + } + return records; +} + +function readEvidenceSnapshot({ floorPath, latencyPath }) { + const records = [ + ...parseStream( + readReplayFile(floorPath, FILE_BYTES, "replay evidence"), + "floor", + ), + ...parseStream( + readReplayFile(latencyPath, FILE_BYTES, "replay evidence"), + "latency", + ), + ]; + return { finalized: false, drained: false, records }; +} + +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, + 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) => + sameScope(record, 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 = 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: [], + definitely_out: [], + preexisting_open: [], + unusable: [], + invalidations: [], + }; + for (const record of relevant) { + if (!record.usable) { + partitions.unusable.push(record); + continue; + } + if (record.family !== "floor") { + // 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 = project(record); + const last = project(record, eventEnd); + if ( + last.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 = project(record, record.opened_ms); + 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 = { + sameScope, + knownReplayTool, + readEvidenceSnapshot, + loadEvidence, + joinEvidenceClock, + partitionFloor, + ReplayEvidenceError, +}; diff --git a/scripts/replay-fixture.cjs b/scripts/replay-fixture.cjs new file mode 100644 index 000000000..391114d7b --- /dev/null +++ b/scripts/replay-fixture.cjs @@ -0,0 +1,227 @@ +// Offline input validation shared by the observational replay transports. +const fs = require("node:fs"); +const path = require("node:path"); +const { readReplayFile, decodeReplayJson } = require("./replay-input.cjs"); +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; +} + +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 loadFixture(filename, transport) { + if (!["browser", "socket"].includes(transport)) + refuse("transport must be browser or socket"); + 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"; + 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 = readReplayFile( + audioPath, + transport === "browser" ? WAV_BYTES : PCM_BYTES, + "replay fixture", + ); + 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/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 new file mode 100644 index 000000000..ed3dc9b5c --- /dev/null +++ b/scripts/replay-input.cjs @@ -0,0 +1,106 @@ +const fs = require("node:fs"); +const { TextDecoder } = require("node:util"); + +class ReplayInputError extends Error { + constructor(message, reason) { + super(message); + this.reason = reason; + } +} + +function readReplayFile(filename, limit, label) { + const fail = (message, reason) => { + throw new ReplayInputError(`${label}: ${message}`, 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()) + 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 < 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", "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", "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" && + /^[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 ReplayInputError( + `${label}: input is not UTF-8 JSON`, + "invalid-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 ReplayInputError( + `${label}: input has a forbidden object key`, + "forbidden-key", + ); + if (stack.at(-1).has(key)) + throw new ReplayInputError( + `${label}: input has a duplicate object key`, + "duplicate-key", + ); + stack.at(-1).add(key); + } + } + return value; +} + +module.exports = { readReplayFile, decodeReplayJson }; diff --git a/scripts/rust-style-ceilings.json b/scripts/rust-style-ceilings.json index 339d0c964..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": 3026, + "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/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..3178181be 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,63 @@ impl ReplyLatency { Some(self.record("audio_accepted", now, Outcome::Open)) } + /// Unlike a reply trace, gate invalidation exists even with no output. + 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": 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()) + } + + fn boundary_to( + &mut self, + boundary: Boundary, + now: Instant, + output: &mut impl std::io::Write, + ) -> Option { + // `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; @@ -1036,6 +1123,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/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 2b5b4d2bc..b7e4b3019 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, execute_timed_tool_batch, 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<'_>, @@ -1949,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 { @@ -2007,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 @@ -2033,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 new file mode 100644 index 000000000..c63b1fc16 --- /dev/null +++ b/src/livekit/session/floor.rs @@ -0,0 +1,76 @@ +//! 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))); + // 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()); + output.write_all(line.as_bytes()).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..6dbffcd0f --- /dev/null +++ b/src/livekit/session/observations.rs @@ -0,0 +1,115 @@ +//! 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) 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, +} + +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["closing"] = (state.end_requested || state.ended).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/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..2a4d35404 --- /dev/null +++ b/tests/browser/replay-evidence.test.js @@ -0,0 +1,387 @@ +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("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); + 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-fixture.test.js b/tests/browser/replay-fixture.test.js new file mode 100644 index 000000000..80a316383 --- /dev/null +++ b/tests/browser/replay-fixture.test.js @@ -0,0 +1,461 @@ +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"), /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"), /exceeds byte limit/); +}); + +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"), /exceeds byte limit/); +}); + +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/); + } +}); 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 new file mode 100644 index 000000000..6aee29605 --- /dev/null +++ b/tests/browser/replay-input.test.js @@ -0,0 +1,129 @@ +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"), { + reason: "input-limit", + }); +}); +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"), { + reason: "input-changed", + }); + 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"), { + reason: "input-changed", + }); + 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/, + ); +}); + +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/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 + } +] 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..ae5b66525 --- /dev/null +++ b/tests/unit/livekit/latency/gates.rs @@ -0,0 +1,88 @@ +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()); + } +} + +#[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/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..cc3b80d46 --- /dev/null +++ b/tests/unit/livekit/session/observations.rs @@ -0,0 +1,218 @@ +use super::*; +use crate::livekit::session::{execute_tool_batch_observed, 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() + ); + } +} + +#[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() + ); + } +}