diff --git a/.github/workflows/test-drift.yml b/.github/workflows/test-drift.yml index 3123844c..fff11bec 100644 --- a/.github/workflows/test-drift.yml +++ b/.github/workflows/test-drift.yml @@ -285,6 +285,17 @@ jobs: elif [ "$EXIT_CODE" -eq 5 ]; then echo "::error::Drift collector quarantined unparseable output (exit 5) — manual triage required" exit "$EXIT_CODE" + elif [ "$EXIT_CODE" -eq 6 ]; then + # A live surface accepted the connection and then sent nothing, so its + # legs graded nothing. There is no collector fault to triage and no + # drift to attribute — failing the job here would say "the providers + # changed formats", which is not what happened. It is NOT swallowed + # either: each silent leg gets a named ::warning::, the report keeps + # its `timeouts[]`, and the `notify` job below alerts on exit 6 with + # its own wording. A day that graded nothing is never a clean day. + jq -r '.timeouts[]? | "::warning title=live-timeout::\(.testName) — \(if .serverClose then "session closed by the server (code \(.serverClose.code))" else "no messages in \(.timeoutMs)ms" end); nothing graded on this surface"' \ + drift-report.json || true + echo "::warning::Drift collector: $(jq -r '.timeouts | length' drift-report.json) live leg(s) observed nothing (exit 6) — the surface is silent, not drifting. Nothing was graded there." elif [ "$EXIT_CODE" -ne 0 ]; then echo "::error::Collector script crashed with exit code $EXIT_CODE" exit "$EXIT_CODE" @@ -348,6 +359,7 @@ jobs: AGUI_DRIFT=false INFRA_ERROR=false QUARANTINE=false + LIVE_TIMEOUT=false # Determine what happened in each job. An exit_code of 5 means the # collector QUARANTINED unparseable output — the drift job concludes @@ -355,8 +367,18 @@ jobs: # triage, not a "providers changed formats" alert. Classify it as # quarantine FIRST, before the generic failure→HTTP_DRIFT fallback, # so an exit-5 quarantine is never misreported as real drift. + # + # An exit_code of 6 means a live surface went SILENT — its legs observed + # nothing, so nothing was graded there. The drift job stays green (this + # is not a format change and not a collector fault), which is exactly why + # it must be alerted explicitly: without this branch a silent surface + # would fall through to the good→good "stay quiet" path and nobody would + # learn that a surface stopped being checked. Classified before the + # generic fallbacks so it is never reported as real drift. if [ "$DRIFT_EXIT_CODE" = "5" ]; then QUARANTINE=true + elif [ "$DRIFT_EXIT_CODE" = "6" ]; then + LIVE_TIMEOUT=true elif [ "$DRIFT_RESULT" = "failure" ]; then HTTP_DRIFT=true elif [ "$DRIFT_RESULT" != "success" ] && [ "$DRIFT_RESULT" != "skipped" ]; then @@ -400,6 +422,13 @@ jobs: if [ "$QUARANTINE" = "true" ]; then EMOJI="🔬" MSG="*Drift collector quarantined unparseable output* in aimock — manual triage required (not confirmed API drift).${DETAIL}${NL}${RUN_URL}" + # Live surface silent (collector exit 6): a live leg observed nothing at + # all, so that surface was NOT checked this run. Not drift, not a + # collector fault — but a surface that has stopped answering is worth + # knowing about, especially if it repeats day over day. + elif [ "$LIVE_TIMEOUT" = "true" ]; then + EMOJI="⏱️" + MSG="*Live drift surface went silent* in aimock — a live leg observed zero messages, so nothing was graded on that surface (not API drift, no collector triage needed). Repeats day over day mean the surface is rejecting or has retired the session, not a flake.${DETAIL}${NL}${RUN_URL}" # Both types of drift elif [ "$HTTP_DRIFT" = "true" ] && [ "$AGUI_DRIFT" = "true" ]; then EMOJI="🚨" @@ -668,8 +697,15 @@ jobs: # the step's `set -euo pipefail`: # exit 0 → clean, continue. # exit 2 → drift present, NON-FATAL (report feeds the delta gate). + # exit 6 → a live surface observed nothing on main — NON-FATAL. This + # is a property of the world, not of the PR's diff, and it + # is what used to block every drift PR: a silent surface was + # reported as unparseable output and hard-failed the base + # leg. The delta gate handles it correctly on its own — a + # surface that graded nothing contributes no keys to either + # side, so nothing is blamed on the diff. # exit 5 → quarantine (unparseable output) — genuine fault, FAIL. - # any other non-{0,2} → genuine collector fault, FAIL. + # any other non-{0,2,6} → genuine collector fault, FAIL. set +e npx tsx scripts/drift-report-collector.ts \ --out "$GITHUB_WORKSPACE/drift-report-base.json" @@ -680,7 +716,11 @@ jobs: echo "::error::Base collector quarantined unparseable output (exit 5) — manual triage required" exit "$BASE_EXIT" fi - if [ "$BASE_EXIT" -ne 0 ] && [ "$BASE_EXIT" -ne 2 ]; then + if [ "$BASE_EXIT" -eq 6 ]; then + jq -r '.timeouts[]? | "::warning title=live-timeout (base)::\(.testName) — \(if .serverClose then "session closed by the server (code \(.serverClose.code))" else "no messages in \(.timeoutMs)ms" end); this surface was not graded on main"' \ + drift-report-base.json || true + fi + if [ "$BASE_EXIT" -ne 0 ] && [ "$BASE_EXIT" -ne 2 ] && [ "$BASE_EXIT" -ne 6 ]; then echo "::error::Base collector faulted (exit $BASE_EXIT) — not a drift signal" exit "$BASE_EXIT" fi @@ -726,8 +766,12 @@ jobs: # with `set +e`/`set -e` and treat it as DATA: # exit 0 → clean, continue. # exit 2 → drift present, NON-FATAL (report feeds the delta gate). + # exit 6 → a live surface observed nothing — NON-FATAL, same rationale + # as the base leg: a silent provider is not something this + # diff did, and a surface that graded nothing contributes no + # delta keys, so the gate cannot blame the PR for it. # exit 5 → quarantine (unparseable output) — genuine fault, FAIL. - # any other non-{0,2} → genuine collector fault, FAIL. + # any other non-{0,2,6} → genuine collector fault, FAIL. set +e npx tsx scripts/drift-report-collector.ts --out drift-report-head.json HEAD_EXIT=$? @@ -736,11 +780,15 @@ jobs: echo "::error::Head collector quarantined unparseable output (exit 5) — manual triage required" exit "$HEAD_EXIT" fi - if [ "$HEAD_EXIT" -ne 0 ] && [ "$HEAD_EXIT" -ne 2 ]; then + if [ "$HEAD_EXIT" -eq 6 ]; then + jq -r '.timeouts[]? | "::warning title=live-timeout (head)::\(.testName) — \(if .serverClose then "session closed by the server (code \(.serverClose.code))" else "no messages in \(.timeoutMs)ms" end); this surface was not graded on the PR ref"' \ + drift-report-head.json || true + fi + if [ "$HEAD_EXIT" -ne 0 ] && [ "$HEAD_EXIT" -ne 2 ] && [ "$HEAD_EXIT" -ne 6 ]; then echo "::error::Head collector faulted (exit $HEAD_EXIT) — not a drift signal" exit "$HEAD_EXIT" fi - echo "head: collector exit $HEAD_EXIT (0 clean / 2 drift-present — both non-fatal here)" + echo "head: collector exit $HEAD_EXIT (0 clean / 2 drift-present / 6 live surface silent — all non-fatal here)" - name: Upload base drift report if: always() diff --git a/scripts/drift-report-collector.ts b/scripts/drift-report-collector.ts index ba20c989..f625f6c3 100644 --- a/scripts/drift-report-collector.ts +++ b/scripts/drift-report-collector.ts @@ -11,6 +11,9 @@ * 0 — no critical diffs found (or no drift at all) * 2 — at least one critical diff exists * 5 — at least one failure was quarantined (unparseable/untrusted — needs review) + * 6 — at least one live leg timed out having observed ZERO messages: the + * surface went silent, so nothing was graded there. Not drift, not a + * collector fault, and NOT a clean baseline. * 1 — AG-UI drift detection was skipped (infra), or an unhandled script error * * Usage: @@ -31,6 +34,7 @@ import type { DriftSeverity, ParsedDiff, QuarantineEntry, + TimeoutEntry, } from "./drift-types.js"; // --------------------------------------------------------------------------- @@ -131,8 +135,27 @@ export function parseDriftBlock(text: string): { context: string; diffs: ParsedD const diffs: ParsedDiff[] = []; // Match numbered entries: " 1. [severity] issue text\n Path:...\n SDK:...\n Real:...\n Mock:..." + // + // EVERY separator here is `[ \t]*` and every value is `(.*)`, NOT `\s*` and + // `(.+)`. `\s` matches newlines, and `compareShapes` sets `mock: ""` on every + // diff it produces, so `Mock:\s*(.+)` on an empty value used to run past the end + // of its own line: greedy `\s*` swallowed the trailing spaces, the newline and + // the blank separator line, and `(.+)` then matched the NEXT ENTRY'S header. + // That consumed the successor whole — `lastIndex` advanced past its `N. [sev]` + // line, so nothing could match it — and if that successor was the critical diff, + // `criticalCount` fell to 0 and the run reported `conclusion: "clean"`. + // + // The trigger is a single empty-`mock` entry that HAS a successor; it is not + // limited to consecutive empty values, and it does not need the block to be + // malformed. `fal-queue.drift.ts` and `video.drift.ts` both emit + // compareShapes-derived blocks, where the value is empty on 100% of diffs. + // + // A newline can no longer be crossed inside an entry, and an empty value is + // captured as empty instead of forcing the match to look for content elsewhere. + // `^` (with `m`) additionally requires the entry number to START a line, so a + // numbered list inside prose cannot be read as an entry. const entryPattern = - /\d+\.\s*\[(\w+)\]\s*(.+)\n\s*Path:\s*(.+)\n\s*SDK:\s*(.+)\n\s*Real:\s*(.+)\n\s*Mock:\s*(.+)/g; + /^[ \t]*\d+\.[ \t]*\[(\w+)\][ \t]*(.*)\n[ \t]*Path:[ \t]*(.*)\n[ \t]*SDK:[ \t]*(.*)\n[ \t]*Real:[ \t]*(.*)\n[ \t]*Mock:[ \t]*(.*)/gm; let match: RegExpExecArray | null; while ((match = entryPattern.exec(text)) !== null) { @@ -373,20 +396,55 @@ export function parseKnownModelsCanary(text: string): CanaryParseResult | null { // --------------------------------------------------------------------------- /** - * A parsed OpenAI-Realtime WS handshake failure. The socket UPGRADED (101) and - * the live API sent back an `error` event, but the expected session-lifecycle - * event never arrived, so the probe's `waitUntil(...)` timed out. That shape is - * a genuine, actionable protocol drift (e.g. a GA session-config field the - * probe/mock stopped sending) — NOT a benign network flake (a flake times out - * having collected ZERO messages and carries no `error` body). + * Which WS drift probe a failure came from, and therefore which surface owns it. + * + * The recognizer below used to test for a `ws-realtime.drift.ts` frame and then + * hardcode the `openai-realtime` surface, which made it useful for exactly one of + * the three WS surfaces this repo probes. A `gemini-live` handshake that the + * provider REJECTED with an error body — the surface most likely to hit this, + * since it is the one that actually goes quiet in production — resolved to no + * surface and fell through to the exit-5 quarantine, i.e. straight back into the + * hard human-triage stop this whole lane exists to avoid. + * + * Attribution is by the probe's own stack frame, and it is a CLOSED table on + * purpose. A frame that names no registered probe yields null and the failure + * stays quarantined — an unknown WS surface must not be guessed at, because a + * confident wrong owner routes remediation at the wrong file and fails OPEN. + */ +const WS_HANDSHAKE_PROBES: readonly { + /** The drift probe's filename as it appears in a stack frame. */ + file: string; + /** The registered surface whose failures that probe reports. */ + surface: keyof typeof SURFACE_REGISTRY; +}[] = [ + { file: "ws-realtime.drift.ts", surface: "openai-realtime" }, + { file: "ws-gemini-live.drift.ts", surface: "gemini-live" }, + { file: "ws-responses.drift.ts", surface: "openai-responses-ws" }, +]; + +/** The registered surface a WS failure's stack frames attribute it to, or null. */ +function resolveWSProbeSurface(text: string): keyof typeof SURFACE_REGISTRY | null { + return WS_HANDSHAKE_PROBES.find((p) => text.includes(p.file))?.surface ?? null; +} + +/** + * A parsed WS handshake failure. The socket UPGRADED (101) and the live API sent + * back an `error` event, but the expected session-lifecycle event never arrived, + * so the probe's `waitUntil(...)` timed out. That shape is a genuine, actionable + * protocol drift (e.g. a session-config field the probe/mock stopped sending) — + * NOT a benign network flake, and NOT the zero-observation timeout lane (a silent + * surface collects ZERO messages and carries no `error` body; see + * `parseLiveTimeout`, which this recognizer deliberately runs ahead of). * * Recognizing it here diverts it from the opaque exit-5 quarantine into a * parseable, attributed critical DriftEntry (exit 2), so the failing handshake * and its error payload are visible and route to a builder for remediation. - * Narrowly gated (realtime probe origin + a surfaced `error` event body) so it - * can never reclassify another provider's failure or a bare network timeout. + * Gated on a KNOWN probe origin plus a surfaced `error` event body, so it can + * neither reclassify an unrelated failure nor claim a bare network timeout. */ export interface WSHandshakeFailure { + /** The registered surface slug the failure is attributed to. */ + surface: keyof typeof SURFACE_REGISTRY; errorType: string; errorCode: string; errorMessage: string; @@ -394,20 +452,172 @@ export interface WSHandshakeFailure { export function parseWSHandshakeFailure(text: string): WSHandshakeFailure | null { // Gate 1: the probe timed out waiting for a lifecycle event (handshake never - // completed). Gate 2: it is the OpenAI Realtime WS probe (its stack frame is - // always present on a real failure; the surfaced `error` body comes from - // ws-providers' openaiRealtimeWS). Gate 3: an `error` event body was surfaced - // — this is the "connect succeeded but handshake didn't complete WITH a - // protocol error" case. A pure network flake (zero messages, no error body) - // fails Gate 3 and stays in the quarantine lane for human review. + // completed). Gate 2: the failure came from a KNOWN WS drift probe, which also + // resolves WHICH surface owns it (its stack frame is always present on a real + // failure; the surfaced `error` body comes from the ws-providers helper). + // Gate 3: an `error` event body was surfaced — this is the "connect succeeded + // but handshake didn't complete WITH a protocol error" case. A pure network + // flake or a silent surface carries no error body, fails Gate 3, and is left to + // the timeout/quarantine lanes. if (!/waitUntil timeout/.test(text)) return null; - if (!/ws-realtime\.drift\.ts/.test(text)) return null; + const surface = resolveWSProbeSurface(text); + if (surface === null) return null; if (!/"type"\s*:\s*"error"/.test(text)) return null; const errorType = text.match(/"error"\s*:\s*\{[^}]*?"type"\s*:\s*"([^"]+)"/)?.[1] ?? "unknown"; const errorCode = text.match(/"code"\s*:\s*"([^"]+)"/)?.[1] ?? "unknown"; const errorMessage = text.match(/"message"\s*:\s*"((?:[^"\\]|\\.)*)"/)?.[1] ?? "unknown"; - return { errorType, errorCode, errorMessage }; + return { surface, errorType, errorCode, errorMessage }; +} + +// --------------------------------------------------------------------------- +// Server-initiated CLOSE recognizer (provider refusal vs provider hang-up) +// --------------------------------------------------------------------------- + +/** + * A server-initiated WebSocket CLOSE observed while a probe was waiting. + * + * This is a THIRD failure channel, distinct from both lanes around it. The socket + * upgrades, and the provider then ends the session out-of-band with an RFC 6455 + * CLOSE frame instead of an in-band `error` event. Until the drift probe was + * taught to preserve the frame, the code and reason were dropped and this arrived + * as an ordinary zero-message timeout — byte-identical to a provider that simply + * said nothing. Now the frame states its own cause, and a stated cause is the most + * actionable signal this system can produce, so it must not be flattened back into + * either neighbouring lane. + */ +export interface WSServerClose { + /** RFC 6455 status code (1005 when the frame carried no code). */ + code: number; + /** The frame's reason text, decoded. Empty when the frame carried none. */ + reason: string; +} + +/** + * The RFC 6455 §7.4.1 close codes that mean "what this end sent was + * unacceptable" — the peer is describing OUR payload, protocol or policy. These + * are genuine, attributable drift. + * + * Enumerated rather than expressed as a range, because the numeric span is not + * semantically contiguous: 1004 is reserved, and 1005/1006 are codes that are + * NEVER sent on the wire (they are local placeholders for "no status received" + * and "closed abnormally"). A `1002..1010` range silently swept those three in + * and would have reported "the provider refused us" for a connection that + * dropped without any code at all. + */ +const WS_REFUSAL_CLOSE_CODES: ReadonlySet = new Set([ + 1002, // protocol error + 1003, // unsupported data + 1007, // invalid frame payload data + 1008, // policy violation + 1009, // message too big + 1010, // mandatory extension missing +]); + +/** + * Does this close code mean the provider REFUSED what this end sent? + * + * True for the §7.4.1 rejection codes above and for the 4000-4999 + * application-defined range, which is where a provider puts its own refusal + * semantics. + * + * False for everything else — the connection ending for the peer's or the + * transport's own reasons: 1000 normal, 1001 going away, 1004 reserved, 1005 no + * code, 1006 abnormal, 1011 internal error, 1012/1013 restarting / try again + * later, 1014/1015 gateway and TLS failures. Calling any of those "drift" would + * page the team about a provider's own hiccup and hand it to the auto-fixer, + * which is the false-drift alarm `drift-retry.ts` exists to suppress. They are + * real and worth seeing, but they are not findings about us. + */ +export function isRefusalCloseCode(code: number): boolean { + return WS_REFUSAL_CLOSE_CODES.has(code) || (code >= 4000 && code <= 4999); +} + +/** + * Recognize the drift probe's server-close failure message and recover the + * frame's code and reason. + * + * The reason is emitted `JSON.stringify`-quoted, so it is decoded with `JSON.parse` + * rather than by hand — a reason containing a quote, a backslash or a newline is + * exactly the input a hand-rolled unquoter gets wrong, and provider reason text is + * not under our control. + */ +export function parseWSServerClose(text: string): WSServerClose | null { + const match = text.match( + /WebSocket closed by server during waitUntil:\s*code=(\d+)\s*reason=("(?:[^"\\]|\\.)*")/, + ); + if (!match) return null; + let reason: string; + try { + // The pattern captures a COMPLETE JSON string literal — the surrounding + // quotes are part of the match — so a successful parse always yields a + // string. `String()` is an identity here; it types the result without a cast + // and without an unreachable `typeof` branch. (A branch for "parsed to a + // non-string" was here and could not be made to fail under mutation, which + // is the definition of coverage that does not exist, so it is gone.) + reason = String(JSON.parse(match[2])); + } catch { + // A reason we cannot decode is not a reason. Returning null leaves the + // failure to the quarantine lane rather than reporting a mangled cause — + // an undecodable payload must never become a confident diagnosis. + return null; + } + return { code: Number(match[1]), reason }; +} + +// --------------------------------------------------------------------------- +// Zero-observation live-timeout recognizer +// --------------------------------------------------------------------------- + +/** + * A live leg that hit its wait budget having observed NOTHING. + * + * This is the single most common way a live drift leg fails, and it has its own + * meaning, distinct from both lanes around it: + * + * - It is NOT a drift finding. Zero messages were observed, so there is no + * shape to compare and nothing to attribute to a builder file. (A timeout + * that DID observe messages including a provider `error` body is protocol + * drift, and `parseWSHandshakeFailure` — which runs first — claims it.) + * - It is NOT unparseable output. The message states exactly what happened: + * the wait budget, and that zero messages arrived. Routing it to the + * quarantine lane reported an unreachable live surface as "unparseable — + * manual triage required" (exit 5), which is both wrong and, because exit 5 + * hard-fails the base leg, a human-gated stop on every drift PR for as long + * as the surface stays silent. + * + * So it gets its own lane: recorded as a `TimeoutEntry`, reported as exit 6 / + * conclusion "live-timeout". + * + * DELIBERATELY NARROW. The recognizer requires the probe's own structured + * "Collected messages" tail with n === 0, and refuses any message carrying a + * drift marker. Anything else — a timeout with messages but no error body, a + * bare `AssertionError` with no timeout tail, truncated garbage — is unchanged + * and still quarantines. The failure mode to avoid here is the opposite of the + * one being fixed: a recognizer loose enough to swallow real output would trade + * a loud stop for a silent pass. + */ +export interface LiveTimeout { + /** The wait budget that expired, in milliseconds. */ + timeoutMs: number; +} + +/** A drift marker anywhere in the text disqualifies the timeout lane. */ +const DRIFT_MARKERS = [/API DRIFT DETECTED/i, /LLMOCK DRIFT/i]; + +export function parseLiveTimeout(text: string): LiveTimeout | null { + // Gate 1: the probe's own timeout tail, WITH its collected-message count. The + // count is what makes this classifiable rather than a guess — `Collected 0` + // is the probe stating, structurally, that it observed nothing. + const match = text.match(/waitUntil timeout after (\d+)ms\.\s*Collected (\d+) messages\s*:/); + if (!match) return null; + // Gate 2: ZERO observations. A timeout that collected messages saw SOMETHING; + // that output is evidence and must not be discarded as "surface was silent". + if (Number(match[2]) !== 0) return null; + // Gate 3: no drift marker. A message that carries a drift report is drift, + // whatever else it also says. + if (DRIFT_MARKERS.some((re) => re.test(text))) return null; + return { timeoutMs: Number(match[1]) }; } // --------------------------------------------------------------------------- @@ -701,6 +911,12 @@ export function classifyUnparseableAsInfra(unparseableMessages: string[]): boole export interface CollectResult { entries: DriftEntry[]; quarantine: QuarantineEntry[]; + /** + * Live legs that timed out having observed nothing (see `parseLiveTimeout`). + * A recognized outcome in its own right — neither a drift finding nor + * unparseable output. + */ + timeouts: TimeoutEntry[]; } /** @@ -729,6 +945,7 @@ export const TRUNCATED_DELTA_ID = "openai-realtime:unknown-models-truncated"; export function collectDriftEntries(results: VitestJsonResult): CollectResult { const entries: DriftEntry[] = []; const quarantine: QuarantineEntry[] = []; + const timeouts: TimeoutEntry[] = []; let unparseable = 0; for (const file of results.testResults) { @@ -858,9 +1075,13 @@ export function collectDriftEntries(results: VitestJsonResult): CollectResult { // timeout (no error body) still falls through to the quarantine lane. const wsFailure = parseWSHandshakeFailure(fullMessage); if (wsFailure !== null) { - const mapping = SURFACE_REGISTRY["openai-realtime"]; + // Attribution follows the probe that reported the failure, resolved in + // parseWSHandshakeFailure. Hardcoding openai-realtime here is what made + // a rejected gemini-live handshake quarantine instead of routing to + // src/ws-gemini-live.ts. + const mapping = SURFACE_REGISTRY[wsFailure.surface]; entries.push({ - provider: "OpenAI Realtime", + provider: mapping.provider, scenario: "WS handshake", builderFile: mapping.builderFile, builderFunctions: mapping.builderFunctions, @@ -870,12 +1091,14 @@ export function collectDriftEntries(results: VitestJsonResult): CollectResult { { severity: "critical" as const, issue: - "OpenAI Realtime WS handshake did not complete — the live API returned an " + + `${mapping.provider} WS handshake did not complete — the live API returned an ` + `error event (${wsFailure.errorType}/${wsFailure.errorCode}) and the expected ` + - "session lifecycle event never arrived. The realtime session config sent by the " + + "session lifecycle event never arrived. The session config sent by the " + `probe/mock likely drifted from the live protocol. Error: ${wsFailure.errorMessage}`, - path: `session.${wsFailure.errorCode}`, - expected: "(handshake completes: session.created/updated received)", + // Display only — the delta key is the explicit `id` below, so this + // string is free to be provider-neutral without moving any key. + path: `handshake.${wsFailure.errorCode}`, + expected: "(handshake completes: the session lifecycle event is received)", real: `error ${wsFailure.errorType}: ${wsFailure.errorMessage}`, mock: "", id: `ws-handshake:${wsFailure.errorCode}`, @@ -884,6 +1107,91 @@ export function collectDriftEntries(results: VitestJsonResult): CollectResult { }); continue; } + + // A session the provider ENDED. Split by what the CLOSE frame actually + // says, because the two halves are different evidence: + // - a REFUSAL code names something WE sent as unacceptable → genuine, + // attributable critical drift, exactly like an in-band error event; + // - any other code says only that the peer left → a hang-up, which is + // real and worth seeing but is not a finding about our payload. + // Neither half may fall through to the unparseable lane: this message + // states its own cause, and a stated cause routed to "manual triage" is + // the failure that blocked every drift PR in the first place. + const closed = parseWSServerClose(fullMessage); + if (closed !== null) { + const testName = `${assertion.ancestorTitles.join(" ")} > ${assertion.title}`; + const rawLocation = extractRawLocation(fullMessage); + const surface = resolveWSProbeSurface(fullMessage); + if (isRefusalCloseCode(closed.code)) { + if (surface === null) { + // A refusal we cannot attribute. Held for review rather than guessed + // at — the same rule the handshake lane follows, and the message says + // what is missing so the human is not left reading a stack trace. + quarantine.push({ + provider: "unknown", + testName, + rawLocation, + message: + `Provider REFUSED the WS session (close code ${closed.code}` + + `${closed.reason ? `: ${closed.reason}` : ""}) but the reporting probe is not ` + + `registered in WS_HANDSHAKE_PROBES, so the owning surface is unknown. ` + + `Add the probe to attribute this automatically.\n${fullMessage}`, + }); + continue; + } + const mapping = SURFACE_REGISTRY[surface]; + entries.push({ + provider: mapping.provider, + scenario: "WS session refused", + builderFile: mapping.builderFile, + builderFunctions: mapping.builderFunctions, + typesFile: mapping.typesFile ?? null, + sdkShapesFile: SDK_SHAPES_FILE, + diffs: [ + { + severity: "critical" as const, + issue: + `${mapping.provider} REFUSED the WS session — the provider closed the ` + + `connection with RFC 6455 code ${closed.code} instead of completing the ` + + `exchange. The stated reason is the diagnosis: ` + + `${closed.reason || "(the frame carried no reason text)"}`, + // Display only; the delta key is the explicit `id` below. + path: `ws-close.${closed.code}`, + expected: "(the session proceeds: the awaited message is received)", + real: `close ${closed.code}${closed.reason ? `: ${closed.reason}` : ""}`, + mock: "", + // Keyed by close CODE, not by the reason prose: providers reword + // reason text freely, and a key that moves on a reword would + // re-report the same refusal as new-in-head on every PR. + id: `ws-close:${closed.code}`, + }, + ], + }); + continue; + } + // Not a refusal — the peer hung up for its own reasons. Nothing was + // graded, so this shares the exit-6 lane: visible, alerted, and never a + // clean baseline, but not a finding and not a hard stop. + timeouts.push({ testName, rawLocation, message: fullMessage, serverClose: closed }); + continue; + } + + // A live leg that reached its wait budget having observed NOTHING. A + // recognized outcome with its own lane (exit 6) — see parseLiveTimeout + // for why it is neither drift nor unparseable. Checked AFTER the two + // recognizers above so a timeout that DID surface a provider error body + // stays the critical drift they classify it as. + const liveTimeout = parseLiveTimeout(fullMessage); + if (liveTimeout !== null) { + timeouts.push({ + testName: `${assertion.ancestorTitles.join(" ")} > ${assertion.title}`, + rawLocation: extractRawLocation(fullMessage), + timeoutMs: liveTimeout.timeoutMs, + message: fullMessage, + }); + continue; + } + unparseable++; continue; } @@ -982,6 +1290,12 @@ export function collectDriftEntries(results: VitestJsonResult): CollectResult { // entries) — only truly unparseable messages reach here. if (parseKnownModelsCanary(fullMessage) !== null) continue; if (parseWSHandshakeFailure(fullMessage) !== null) continue; + // Recognized zero-observation live timeouts were claimed by the + // timeout lane in the pass above; they are not unparseable. + if (parseLiveTimeout(fullMessage) !== null) continue; + // A recognized server close was claimed above too — either as an + // attributed refusal, an explicit quarantine entry, or the exit-6 lane. + if (parseWSServerClose(fullMessage) !== null) continue; unparseableFailures.push({ message: fullMessage, testName: `${assertion.ancestorTitles.join(" ")} > ${assertion.title}`, @@ -1037,7 +1351,32 @@ export function collectDriftEntries(results: VitestJsonResult): CollectResult { ); } - return { entries, quarantine }; + if (timeouts.length > 0) { + // Reported as what it is, with the one thing a reader needs to act on: the + // surface that went quiet. Explicitly NOT the quarantine wording — nothing + // here needs collector triage, so nobody should be sent looking for it. + console.warn( + `WARNING: ${timeouts.length} live drift leg(s) timed out having observed ZERO messages — ` + + `the live surface accepted the connection and then sent nothing. This is neither drift ` + + `nor unparseable output (exit 6, conclusion "live-timeout"): there is no collector fault ` + + `to triage. Check the surface below for an outage, a retired model, or a rejected session.`, + ); + for (const t of timeouts) { + const why = t.serverClose + ? `session closed by the server (code ${t.serverClose.code}` + + `${t.serverClose.reason ? `: ${t.serverClose.reason}` : ", no reason given"})` + : `no messages in ${t.timeoutMs}ms`; + console.warn(` - ${t.testName} — ${why} @ ${t.rawLocation || ""}`); + } + console.warn( + ` If this persists across runs it is not a flake. A leg that reports NO close code and no ` + + `messages was met with genuine silence; one that reports a close code was hung up on, and ` + + `the code names who ended it. A close code in the refusal range is reported separately, as ` + + `attributed critical drift, not here.`, + ); + } + + return { entries, quarantine, timeouts }; } // --------------------------------------------------------------------------- @@ -1249,10 +1588,17 @@ export function computeExitCode( criticalCount: number, quarantineCount: number, agUiSkipped: boolean, -): 0 | 1 | 2 | 5 { + timeoutCount: number = 0, +): 0 | 1 | 2 | 5 | 6 { if (criticalCount > 0) return 2; if (quarantineCount > 0) return 5; if (agUiSkipped) return 1; + // 6 — every leg that failed did so by observing nothing at all. Distinct from + // 5 so a silent live surface is never reported as a collector fault needing + // manual triage, and distinct from 0 so it is never a clean baseline: the legs + // that timed out graded NOTHING, and a run that graded nothing must not be + // able to certify that surface as drift-free. + if (timeoutCount > 0) return 6; return 0; } @@ -1262,7 +1608,7 @@ export function computeExitCode( * `report.conclusion` directly. Only exit 0 ("clean") is a reusable baseline; * "critical"/"quarantine" (and the exit-1 "skipped" case) are not. */ -export function conclusionForExitCode(exitCode: 0 | 1 | 2 | 5): string { +export function conclusionForExitCode(exitCode: 0 | 1 | 2 | 5 | 6): string { switch (exitCode) { case 0: return "clean"; @@ -1270,6 +1616,11 @@ export function conclusionForExitCode(exitCode: 0 | 1 | 2 | 5): string { return "critical"; case 5: return "quarantine"; + case 6: + // NOT in drift-delta's REUSABLE_CONCLUSIONS, deliberately: a run whose + // legs observed nothing cannot serve as a baseline that says they were + // clean. + return "live-timeout"; default: return "skipped"; } @@ -1307,16 +1658,18 @@ function main(): void { const entries = [...httpEntries, ...agUiEntries]; const quarantine = httpResult.quarantine; + const timeouts = httpResult.timeouts; const criticalCount = entries.reduce( (sum, e) => sum + e.diffs.filter((d) => d.severity === "critical").length, 0, ); const quarantineCount = quarantine.length; + const timeoutCount = timeouts.length; // Compute the exit code BEFORE writing so the report can carry the coarse // `conclusion` derived from it (base-report reuse contract). - const exitCode = computeExitCode(criticalCount, quarantineCount, agUiSkipped); + const exitCode = computeExitCode(criticalCount, quarantineCount, agUiSkipped, timeoutCount); const timestamp = new Date().toISOString(); const report: DriftReport = { @@ -1327,6 +1680,7 @@ function main(): void { conclusion: conclusionForExitCode(exitCode), entries, ...(quarantine.length > 0 ? { quarantine } : {}), + ...(timeouts.length > 0 ? { timeouts } : {}), }; try { @@ -1346,6 +1700,7 @@ function main(): void { console.log(` Total entries: ${entries.length}`); console.log(` Critical diffs: ${criticalCount}`); console.log(` Quarantined failures: ${quarantineCount}`); + console.log(` Live timeouts (zero observations): ${timeoutCount}`); switch (exitCode) { case 2: @@ -1356,6 +1711,13 @@ function main(): void { console.warn(`Exiting with code 5 (${quarantineCount} failure(s) quarantined for review).`); process.exit(5); // eslint-disable-next-line no-fallthrough + case 6: + console.warn( + `Exiting with code 6 (${timeoutCount} live leg(s) timed out with zero observations — ` + + `no drift graded on those surfaces; NOT a collector fault).`, + ); + process.exit(6); + // eslint-disable-next-line no-fallthrough case 1: console.warn("Exiting with code 1 (AG-UI drift detection was skipped — infra failure)."); process.exit(1); diff --git a/scripts/drift-retry.ts b/scripts/drift-retry.ts index 945bad5d..289d2cf5 100644 --- a/scripts/drift-retry.ts +++ b/scripts/drift-retry.ts @@ -51,6 +51,15 @@ import { fileURLToPath } from "node:url"; export const EXIT_CLEAN = 0; export const EXIT_CRITICAL_DRIFT = 2; export const EXIT_QUARANTINE = 5; +/** + * A live leg observed ZERO messages before its wait expired — the surface went + * silent, so nothing was graded there. Propagated unchanged (like every non-0/2 + * code) rather than retried: the wait already burned its full budget, and a + * surface that answered nothing for 30s is not going to be distinguished from a + * blip by spending another two waits on it. The caller decides what to do with + * it; `test-drift.yml` treats it as non-fatal and alerts on it distinctly. + */ +export const EXIT_LIVE_TIMEOUT = 6; // Defaults: keep the fleet of real-API calls small. 3 total attempts with a // ~45s backoff mirrors the observed transient window (the Fix Drift workflow diff --git a/scripts/drift-sync-check.ts b/scripts/drift-sync-check.ts index 344f2455..379e8556 100644 --- a/scripts/drift-sync-check.ts +++ b/scripts/drift-sync-check.ts @@ -30,6 +30,23 @@ * above is a plain data check. A sync that fails any of them is NOT resolved * and no PR opens (mirrors the predicate's fail-closed contract, spec §3). * + * WHAT GATE-3 IS AND IS NOT (run 31465219443, 2026-08-11). The re-collect runs + * in the same workspace as the fix, so it can FILTER a cheat but cannot PROVE + * correctness — that has always been its contract. What it also cannot do is + * answer a question about an edit it has no surface for: two consecutive runs of + * the identical changeset `74f6efa43753f7d0` (two gemini deprecations) got + * `gate-failed` and then `ok-applied`, because gate-3's input is a fresh LIVE + * observation of EVERY drift surface aimock has, and nothing about that is a + * function of the changeset. So gate-3 now: + * + * * is SKIPPED, with the reason recorded in the verdict, when the caller knows + * a re-collect cannot observe this run's edit (`skipRecollect`); + * * REFUSES on a positive critical finding and NAMES the diffs, so the next + * refusal is triageable from the log instead of being a bare count; + * * stops claiming "clean re-collect" for a zero it cannot believe — a + * quarantined or AG-UI-skipped report is reported as UNCONFIRMED, carried by + * gates 1 and 2 (see `reportTrustNote`). + * * C5 only ADDS this script + its test. Wiring it into `fix-drift.yml` in place * of the "Assert drift truly resolved" step, and deleting * `drift-success-predicate.ts`, is C3's job. @@ -145,12 +162,83 @@ export function runPinCheck( const DEFAULT_RECOLLECT_OUT = "drift-report.sync-check.json"; +/** One residual critical diff, identified well enough to triage without re-running anything. */ +export interface CriticalDiffRef { + provider: string; + scenario: string; + path: string; + id?: string; +} + +/** + * Every `severity === "critical"` diff in a report, IDENTIFIED. + * + * The gate used to carry only a COUNT into its verdict, and the re-collect report + * itself (`drift-report.sync-check.json`) is never uploaded by the workflow. So + * `gate-failed … still reports 1 critical diff(s)` was the entire record of run + * 31465219443 — which diff fired that morning is NOT recoverable from it. Naming + * the diffs is what makes the next one diagnosable from the log alone. + */ +export function listCriticalDiffs(report: DriftReport): CriticalDiffRef[] { + return report.entries.flatMap((entry) => + entry.diffs + .filter((d) => d.severity === "critical") + .map((d) => ({ + provider: entry.provider, + scenario: entry.scenario, + path: d.path, + ...(d.id !== undefined ? { id: d.id } : {}), + })), + ); +} + /** Count `severity === "critical"` diffs across every entry of a report. */ export function countCriticalDiffs(report: DriftReport): number { - return report.entries.reduce( - (sum, entry) => sum + entry.diffs.filter((d) => d.severity === "critical").length, - 0, - ); + return listCriticalDiffs(report).length; +} + +/** Render `listCriticalDiffs` output for a verdict detail line. */ +export function formatCriticalDiffs(diffs: readonly CriticalDiffRef[]): string { + return diffs.map((d) => `${d.provider}/${d.scenario}: ${d.id ?? d.path}`).join("; "); +} + +/** + * Can a ZERO critical count in this report be believed as "the live suite is + * clean", or did the collector fail to make a trustworthy, complete observation? + * + * The collector writes `conclusion` from its own exit code + * (`conclusionForExitCode`): "clean" (0), "critical" (2), "quarantine" (5 — a + * failure it could not parse into a trustworthy finding) or "skipped" (1 — the + * AG-UI drift leg could not run, so `entries` is missing that whole surface). + * Only "clean" and "critical" are positive determinations. + * + * This gate used to read `entries` alone, so a quarantined or AG-UI-skipped + * re-collect counted zero criticals and was reported as a "clean re-collect" — + * an UNKNOWN collapsing into the answer that passes. Both mornings of the + * 74f6efa43753f7d0 pair quarantined on the same live Gemini WS timeout, and the + * 08-12 log claims a clean re-collect for it. + * + * A zero that cannot be believed does not become a REFUSAL — a refusal would red + * an unattended cron on someone else's flaky live surface. It stops being a CLAIM: + * the verdict says the re-collect could not confirm the edit, and gate-1 and + * gate-2 carry it. A positive critical finding is still a refusal (see + * `evaluateSyncCheck`) — an UNKNOWN must not veto, but a POSITIVE finding must. + */ +export function reportTrustNote(report: DriftReport): string | null { + const quarantined = report.quarantine?.length ?? 0; + if (quarantined > 0) { + return `the collector quarantined ${quarantined} failure(s) it could not parse into a trustworthy finding`; + } + if (report.conclusion === undefined) { + return "the report carries no `conclusion`, so the collector's own verdict on it is unknown"; + } + if (report.conclusion === "skipped") { + return "the collector's AG-UI drift leg could not run, so the report is missing that surface entirely"; + } + if (report.conclusion !== "clean" && report.conclusion !== "critical") { + return `the collector reported conclusion="${report.conclusion}", which is not a positive determination`; + } + return null; } /** @@ -200,15 +288,19 @@ export interface SyncCheckDeps { export interface EvaluateSyncCheckOptions { /** * Run gate-1 (allowlist) + gate-2 (pin) but SKIP gate-3 (the live - * re-collect). Used by the sync core for a run that applied a mechanical - * registry edit but ALSO deferred a family to a human: a fresh collector run - * would still (correctly) report that deferred family as residual critical - * drift, so gate-3 is not a meaningful full-resolution check for such a run - * and — left on — would wrongly revert the valid mechanical edit. Gate-1 and - * gate-2 remain in force: the edit is still proven data-only with the frozen - * classification logic intact. + * re-collect), because for THIS run's edit a fresh collector run cannot + * answer the question gate-3 asks. Two such runs exist — see + * `gate3SkipReason` in drift-sync.ts for both, with their evidence. Gate-1 + * and gate-2 remain in force: the edit is still proven data-only with the + * frozen classification logic intact. */ skipRecollect?: boolean; + /** + * WHY gate-3 was skipped, quoted into the verdict detail. Required whenever + * `skipRecollect` is set: a skipped gate that does not say what it could not + * observe reads in the log exactly like a gate that ran and passed. + */ + skipRecollectReason?: string; } export interface SyncCheckVerdict { @@ -249,26 +341,55 @@ export function evaluateSyncCheck( }; } - // gate-3 (live re-collect) is skipped for a run that ALSO deferred a family - // to a human — see EvaluateSyncCheckOptions.skipRecollect. + // gate-3 (live re-collect) is skipped when it cannot observe THIS run's edit — + // see EvaluateSyncCheckOptions.skipRecollect. if (opts.skipRecollect) { + // A skip with no stated reason reads in the log exactly like a gate that ran + // and passed, so it is a CONFIG ERROR rather than a silent default: the + // caller that turns gate-3 off must say what it could not observe. + if (!opts.skipRecollectReason) { + throw new SyncCheckConfigError( + "skipRecollect was set with no skipRecollectReason — a gate that is turned off " + + "must record why, or its verdict is indistinguishable from a gate that ran", + ); + } return { ok: true, reason: SyncCheckReason.OK, detail: "drift-sync-check passed: changed files are data-only, classification pins intact " + - "(live re-collect skipped — this run also deferred a family to a human)", + `(live re-collect NOT RUN — ${opts.skipRecollectReason}; ` + + "this edit is carried by gate-1 + gate-2, not by a re-collect)", offendingFiles: [], }; } const report = deps.recollect(); - const criticalCount = countCriticalDiffs(report); - if (criticalCount > 0) { + const criticalDiffs = listCriticalDiffs(report); + if (criticalDiffs.length > 0) { + // A POSITIVE finding, so it refuses — and it names the diffs, because a bare + // count is not triageable after the fact (see `listCriticalDiffs`). return { ok: false, reason: SyncCheckReason.RESIDUAL_CRITICAL_DRIFT, - detail: `Clean re-collect after sync still reports ${criticalCount} critical diff(s) — sync did not resolve the drift`, + detail: + `Clean re-collect after sync still reports ${criticalDiffs.length} critical diff(s) — ` + + `sync did not resolve the drift: ${formatCriticalDiffs(criticalDiffs)}`, + offendingFiles: [], + }; + } + + // Zero criticals. Whether that zero is BELIEVABLE is a separate question — a + // quarantined or incomplete re-collect must not be reported as a clean one. + const trustNote = reportTrustNote(report); + if (trustNote !== null) { + return { + ok: true, + reason: SyncCheckReason.OK, + detail: + "drift-sync-check passed: changed files are data-only, classification pins intact " + + `(re-collect found no critical drift but could NOT CONFIRM the edit — ${trustNote}; ` + + "this edit is carried by gate-1 + gate-2)", offendingFiles: [], }; } diff --git a/scripts/drift-sync.ts b/scripts/drift-sync.ts index 8384a9c6..34e9f5ab 100644 --- a/scripts/drift-sync.ts +++ b/scripts/drift-sync.ts @@ -705,12 +705,15 @@ export interface SyncCoreDeps { writeProposalNote: (relPath: string, text: string) => void; /** * Run C5's drift-sync-check gate. `opts.skipRecollect` runs gate-1 - * (allowlist) + gate-2 (pin) but SKIPS gate-3 (the live re-collect) — used - * when this run applied a mechanical edit AND also deferred a family to a - * human, so a fresh collector run would still (correctly) see that deferred - * family as residual critical drift. + * (allowlist) + gate-2 (pin) but SKIPS gate-3 (the live re-collect), for the + * runs where a fresh collector pass cannot answer gate-3's question — see + * {@link gate3SkipReason} for the two cases and their evidence. + * `opts.skipRecollectReason` carries WHY into the verdict detail. */ - runSyncCheck: (opts?: { skipRecollect?: boolean }) => SyncCheckResultLike; + runSyncCheck: (opts?: { + skipRecollect?: boolean; + skipRecollectReason?: string; + }) => SyncCheckResultLike; /** Revert every file in `relPaths` (e.g. `git checkout -- `) after a failed gate. */ revertFiles: (relPaths: string[]) => void; now?: () => Date; @@ -738,6 +741,54 @@ export interface SyncCoreOutcome { skipped: { provider: Provider; reason: string }[]; } +/** + * WHY gate-3 (the live re-collect) cannot answer this run's question, or `null` + * when it can. The returned string is quoted verbatim into the gate's verdict. + * + * Gate-3 re-runs the WHOLE live drift suite and vetoes on its GLOBAL critical + * count. That is only a meaningful verdict on THIS run's edit when the suite has + * a surface that observes the edit. Two runs where it does not: + * + * 1. A MIXED RUN (a mechanical edit PLUS a family deferred to a human). A fresh + * collector pass still (correctly) reports the deferred family as residual + * critical drift, so gate-3 would revert the valid edit alongside it. This is + * the long-standing D-M1 case. + * + * 2. A DEPRECATION-ONLY RUN. The edit appends a family literal to + * `deprecatedFamilies`, and NOTHING in the collector's suite glob + * (`src/__tests__/drift/**\/*.drift.ts`, per vitest.config.drift.ts) reads + * `deprecatedFamilies`: the only LIVE model-family canary is the + * UNCLASSIFIED direction (`unclassifiedFamilies` — live minus classified), + * while the deprecation direction (`detectDeprecatedFamilies` — classified + * minus live) is exercised only OFFLINE against injected payloads. A recorded + * deprecation therefore cannot change a single collector output, so gate-3 + * can neither confirm nor refute it — it can only veto it on whatever + * unrelated drift the live suite happened to see that morning. It did exactly + * that: the identical changeset `74f6efa43753f7d0` was refused as + * `gate-failed` on 2026-08-11 (run 31465219443, "still reports 1 critical + * diff(s)") and applied as `ok-applied` on 2026-08-12 (run 31570802134, PR + * #370) — a daily cron reddening at random on a correct edit, and reporting + * it as "the mechanical edit was wrong". + * + * That premise is PINNED by `drift-sync-gate-determinism.test.ts`: if a live + * deprecation canary is ever added to a `*.drift.ts`, that test reds and + * sends whoever added it here. + * + * An `added` run is NOT on this list, and must not be: appending to + * `includeFamilies` makes the unclassified canary stop reporting the family, so + * gate-3 genuinely observes that edit — including an approved addition that + * landed in the wrong provider's array, which the canary still reports. + */ +export function gate3SkipReason(outcomes: readonly FamilyOutcome[]): string | null { + if (outcomes.some((o) => o.action.startsWith("needs-human-"))) { + return "this run also deferred a family to a human, which a fresh collector pass would still report as residual critical drift"; + } + if (!outcomes.some((o) => o.action === "added")) { + return "this run only RECORDED deprecations, and no live drift surface reads deprecatedFamilies — a re-collect cannot observe this edit"; + } + return null; +} + /** Read-or-create a dedup note (write only on first sighting — re-fire never spams a duplicate). */ function ensureProposalNote( deps: SyncCoreDeps, @@ -1006,14 +1057,16 @@ export function runDriftSyncCore( // A mechanical registry edit WAS applied — persist it and gate it. Gate-1 // (allowlist) and gate-2 (pin) always apply: they cheaply prove the edit // stayed on the data-only surface and left the frozen classification logic - // intact. Gate-3 (the live re-collect) only makes sense when this run CLAIMS - // to have fully resolved the drift — i.e. no family was simultaneously - // deferred to a human. In a mixed run (a valid registry edit PLUS a family - // routed to a human), the re-collect would (correctly) still see that deferred - // family as residual drift and would wrongly revert the valid edit (D-M1, - // mixed-run leg), so skip gate-3 and report NEEDS_HUMAN with the edit kept. + // intact. Gate-3 (the live re-collect) runs only when the live suite has a + // surface that can actually observe THIS run's edit — `gate3SkipReason` names + // the two runs where it does not, with the evidence. deps.writeRegistrySource(registrySource); - const verdict = deps.runSyncCheck({ skipRecollect: anyNeedsHuman }); + const skipReason = gate3SkipReason(outcomes); + const verdict = deps.runSyncCheck( + skipReason !== null + ? { skipRecollect: true, skipRecollectReason: skipReason } + : { skipRecollect: false }, + ); if (!verdict.ok) { deps.revertFiles([...touchedFiles]); return { @@ -1246,7 +1299,10 @@ const REAL_SYNC_CORE_DEPS: SyncCoreDeps = { runPinCheck: () => runPinCheck(), recollect: () => recollect(), }, - { skipRecollect: opts?.skipRecollect }, + { + skipRecollect: opts?.skipRecollect, + skipRecollectReason: opts?.skipRecollectReason, + }, ); return { ok: verdict.ok, reason: verdict.reason, detail: verdict.detail }; }, diff --git a/scripts/drift-types.ts b/scripts/drift-types.ts index 448663ab..aa282234 100644 --- a/scripts/drift-types.ts +++ b/scripts/drift-types.ts @@ -76,6 +76,47 @@ export interface QuarantineEntry { message: string; } +/** + * A live drift leg that reached its wait timeout having collected ZERO messages. + * + * This is a RECOGNIZED failure shape, not unparseable garbage: the probe opened + * the connection, sent its request, and the live surface then sent nothing back + * before the wait expired. There is no drift finding to attribute (nothing was + * observed to compare) and there is nothing about the collector to triage — so it + * belongs in neither the drift lane nor the quarantine lane. + * + * Recorded here so the outcome is REPORTED as what it is (exit 6, conclusion + * "live-timeout") instead of being funnelled into "unparseable output — manual + * triage required", which is what made an unreachable live surface a hard, + * human-gated stop on every drift PR. + */ +export interface TimeoutEntry { + /** The failing test's name (ancestor titles + title). */ + testName: string; + /** + * Raw `file:line` captured from the original stack frame BEFORE stack-frame + * stripping. Empty string when no frame was available. + */ + rawLocation: string; + /** + * The wait budget that expired, in milliseconds, as reported by the probe. + * Absent when the leg produced nothing because the server CLOSED the session + * rather than because a wait ran out — in that case `serverClose` explains it. + */ + timeoutMs?: number; + /** + * Set when the provider ended the session with an RFC 6455 CLOSE frame whose + * code does NOT indicate a refusal (see `isRefusalCloseCode`): 1000 normal, + * 1001 going away, 1011 internal error, 1012/1013 restarting, and so on. The + * peer stated that it left, not that anything we sent was wrong — so this is a + * hang-up, not a finding, and it shares the timeout lane's outcome. A REFUSAL + * code is not recorded here; it becomes an attributed critical drift entry. + */ + serverClose?: { code: number; reason: string }; + /** The full failure message, retained verbatim for the reader. */ + message: string; +} + export interface DriftEntry { provider: string; scenario: string; @@ -97,9 +138,9 @@ export interface DriftReport { generatedAt?: string; /** * Coarse run outcome derived from the collector exit code - * (0→"clean", 2→"critical", 5→"quarantine"), written so the reuse guard can - * read `report.conclusion` instead of relying solely on the CI run - * conclusion. Absent on legacy reports. + * (0→"clean", 2→"critical", 5→"quarantine", 6→"live-timeout"), written so the + * reuse guard can read `report.conclusion` instead of relying solely on the CI + * run conclusion. Absent on legacy reports. */ conclusion?: string; entries: DriftEntry[]; @@ -109,4 +150,10 @@ export interface DriftReport { * ignore this field are unaffected. */ quarantine?: QuarantineEntry[]; + /** + * Optional list of live legs that timed out having observed nothing (see + * TimeoutEntry). Absent/empty on a run where every leg produced output — + * legacy consumers that ignore this field are unaffected. + */ + timeouts?: TimeoutEntry[]; } diff --git a/src/__tests__/drift-collector.test.ts b/src/__tests__/drift-collector.test.ts index f47958f4..29d1919e 100644 --- a/src/__tests__/drift-collector.test.ts +++ b/src/__tests__/drift-collector.test.ts @@ -29,12 +29,20 @@ import { computeExitCode, conclusionForExitCode, classifyUnparseableAsInfra, + parseLiveTimeout, + parseWSServerClose, + isRefusalCloseCode, INFRA_INDICATOR_SOURCES, infraIndicatorSample, NO_GA_DELTA_ID, TRUNCATED_DELTA_ID, } from "../../scripts/drift-report-collector.js"; -import type { DriftEntry, QuarantineEntry, ParsedDiff } from "../../scripts/drift-types.js"; +import type { + DriftEntry, + QuarantineEntry, + TimeoutEntry, + ParsedDiff, +} from "../../scripts/drift-types.js"; import { SURFACE_REGISTRY, KNOWN_SURFACE_SLUGS, isKnownSurface } from "./drift/surface-registry.js"; import { existsSync, readFileSync, readdirSync } from "node:fs"; import { resolve } from "node:path"; @@ -55,14 +63,24 @@ function quarantineOf(result: VitestJsonResult): QuarantineEntry[] { return collectDriftEntries(result).quarantine; } -/** The exit code main() would emit for a given collect result (agUiSkipped=false). */ -function exitCodeOf(result: VitestJsonResult): 0 | 1 | 2 | 5 { - const { entries, quarantine } = collectDriftEntries(result); +function timeoutsOf(result: VitestJsonResult): TimeoutEntry[] { + return collectDriftEntries(result).timeouts; +} + +/** + * The exit code main() would emit for a given collect result (agUiSkipped=false). + * + * Forwards EVERY lane main() forwards, timeouts included. A helper that dropped + * a lane would report an exit code the collector never emits, and every taxonomy + * assertion routed through it would be measuring the helper. + */ +function exitCodeOf(result: VitestJsonResult): 0 | 1 | 2 | 5 | 6 { + const { entries, quarantine, timeouts } = collectDriftEntries(result); const criticalCount = entries.reduce( (sum, e) => sum + e.diffs.filter((d) => d.severity === "critical").length, 0, ); - return computeExitCode(criticalCount, quarantine.length, false); + return computeExitCode(criticalCount, quarantine.length, false, timeouts.length); } // --------------------------------------------------------------------------- @@ -482,10 +500,11 @@ describe("collectDriftEntries", () => { expect(exitCodeOf(result)).toBe(2); }); - it("does NOT recognize a bare WS network timeout (zero messages, no error body) as handshake drift → stays quarantined (exit 5)", () => { - // A genuine transient network flake times out having collected ZERO - // messages and carries no provider `error` body. It must NOT be reclassified - // as protocol drift — it stays in the quarantine lane for human review. + it("does NOT recognize a bare WS timeout (zero messages, no error body) as handshake drift → live-timeout lane (exit 6), NOT drift and NOT quarantine", () => { + // A zero-observation timeout carries no provider `error` body, so it must NOT + // be reclassified as protocol drift. Nor is it unparseable: the message states + // the wait budget and that zero messages arrived. It lands in the live-timeout + // lane (exit 6) — see parseLiveTimeout. const bareTimeout = "Error: waitUntil timeout after 30000ms. Collected 0 messages: []\n" + " at openaiRealtimeWS (/repo/src/__tests__/drift/ws-providers.ts:372:20)\n" + @@ -499,8 +518,9 @@ describe("collectDriftEntries", () => { }), ]); expect(entriesOf(result)).toEqual([]); - expect(quarantineOf(result)).toHaveLength(1); - expect(exitCodeOf(result)).toBe(5); + expect(quarantineOf(result)).toEqual([]); + expect(timeoutsOf(result)).toHaveLength(1); + expect(exitCodeOf(result)).toBe(6); }); it("returns valid entries and tolerates unparseable failures mixed in", () => { @@ -1059,6 +1079,699 @@ describe("collectDriftEntries", () => { }); }); +// --------------------------------------------------------------------------- +// An empty field value must not eat the next entry +// +// `compareShapes` sets `mock: ""` on every diff it produces, and the entry regex +// used `Mock:\s*(.+)`. `\s` matches newlines, so on an empty value the greedy +// `\s*` ran past the end of its own line and `(.+)` matched the NEXT ENTRY'S +// header, consuming it whole. When the swallowed entry was the critical one, +// `criticalCount` fell to 0 and the collector reported `conclusion: "clean"` — +// the failure state and the working state were observationally identical, which +// is the worst shape a defect can have here. +// +// SCOPE, measured rather than assumed: the trigger is ONE empty-`mock` entry that +// has a successor. It is NOT limited to consecutive empty values (a block whose +// only empty value sits in the middle loses its THIRD entry), and a trailing +// empty-`mock` entry survives (the capture falls back to the value's own trailing +// spaces). Two live surfaces emit compareShapes-derived blocks — +// `fal-queue.drift.ts` and `video.drift.ts` — where the value is empty on 100% of +// diffs, so a block of N entries lost floor(N/2) of them. +// +// The round-trip property below is the non-recurring part: it asserts through the +// REAL emitter and the REAL parser that what a block PRINTS is what the collector +// COLLECTS, across every empty/filled permutation. Any future separator that can +// cross a newline fails it without anyone having to think of this case again. +// --------------------------------------------------------------------------- + +describe("what a drift block prints is what the collector collects", () => { + const diff = ( + n: number, + mock: string, + severity: ShapeDiff["severity"] = "warning", + ): ShapeDiff => ({ + path: `field${n}`, + severity, + issue: `issue ${n}`, + expected: "e", + real: "r", + mock, + }); + const EMPTY = ""; + const FILLED = ""; + + // Every permutation of empty/filled `mock` up to 3 entries, plus the 4-entry + // all-empty case that shows the loss compounding. + const permutations: string[][] = [ + [EMPTY], + [FILLED], + [EMPTY, EMPTY], + [EMPTY, FILLED], + [FILLED, EMPTY], + [FILLED, FILLED], + [EMPTY, EMPTY, EMPTY], + [FILLED, EMPTY, FILLED], + [EMPTY, FILLED, EMPTY], + [EMPTY, EMPTY, EMPTY, EMPTY], + ]; + + it.each(permutations.map((m) => [m.map((x) => (x === EMPTY ? "empty" : "filled")).join("+"), m]))( + "round-trips every entry when the mock values are %s", + (_label, mocks) => { + const diffs = (mocks as string[]).map((m, i) => diff(i + 1, m)); + const parsed = parseDriftBlock(formatDriftReport("Round-trip probe", diffs)); + expect(parsed).not.toBeNull(); + // Path is the identity here, so a swallowed entry shows up as a missing path + // rather than as a count that happens to match for the wrong reason. + expect(parsed!.diffs.map((d) => d.path)).toEqual(diffs.map((d) => d.path)); + expect(parsed!.diffs.map((d) => d.mock)).toEqual(diffs.map((d) => d.mock)); + }, + ); + + it("a critical diff behind an empty-mock entry survives to the exit code", () => { + // The exact loss shape: two entries, both empty `mock` (what compareShapes + // emits), critical SECOND. Before the fix the critical was consumed by its + // predecessor and the collector exited 0 "clean". + const diffs = [diff(1, EMPTY, "warning"), diff(2, EMPTY, "critical")]; + const result = makeResult([ + makeAssertion({ + status: "failed", + ancestorTitles: ["OpenAI Chat Completions drift"], + title: "non-streaming text matches real API", + failureMessages: [formatDriftReport("OpenAI Chat (non-streaming text)", diffs)], + }), + ]); + const entries = entriesOf(result); + expect(entries).toHaveLength(1); + expect(entries[0].diffs.map((d) => d.severity)).toEqual(["warning", "critical"]); + // The whole point: a printed critical reaches the exit code. + expect(exitCodeOf(result)).toBe(2); + }); + + it("an empty value is captured as empty, never as the next entry's text", () => { + const diffs = [diff(1, EMPTY), diff(2, FILLED)]; + const parsed = parseDriftBlock(formatDriftReport("probe", diffs))!; + expect(parsed.diffs[0].mock).toBe(""); + expect(parsed.diffs[0].mock).not.toContain("issue 2"); + }); + + it("every labelled field tolerates an empty value, not just Mock", () => { + // The sibling separators had the identical hazard; an empty `real`/`expected` + // would have crossed a newline the same way. + const diffs: ShapeDiff[] = [ + { path: "p1", severity: "warning", issue: "i1", expected: "", real: "", mock: "" }, + { path: "p2", severity: "critical", issue: "i2", expected: "e", real: "r", mock: "m" }, + ]; + const parsed = parseDriftBlock(formatDriftReport("probe", diffs))!; + expect(parsed.diffs.map((d) => d.path)).toEqual(["p1", "p2"]); + expect(parsed.diffs[1].severity).toBe("critical"); + }); + + it("NEGATIVE CONTROL: a numbered list in prose is still not an entry", () => { + // `^` anchoring is what keeps the looser value captures from inventing entries + // out of ordinary text that happens to contain a numbered line mid-sentence. + const text = + "API DRIFT DETECTED: Prose probe\n" + + " the provider docs say 1. [critical] do not do this\n" + + " Path: nope\n" + + " SDK: nope\n" + + " Real: nope\n" + + " Mock: nope\n"; + expect(parseDriftBlock(text)!.diffs).toEqual([]); + }); +}); + +// --------------------------------------------------------------------------- +// Server-initiated CLOSE: refusal vs hang-up vs silence +// +// `fix/ws-preserve-close-code` taught the drift probe to preserve an RFC 6455 +// CLOSE frame instead of discarding it, which introduces a failure string no +// parser here had seen: +// +// WSClosedError: WebSocket closed by server during waitUntil: code=1008 +// reason="Requested model is not supported for BidiGenerateContent.". +// Collected 0 messages: [] bodies=[] +// +// Measured against this collector before the refusal lane existed, that string +// matched no infra indicator, no handshake recognizer and no timeout recognizer, +// and landed on `exit 5 — manual triage`. That is the same daily hard stop the +// timeout lane was built to remove, re-entering through a new input. +// +// So there are now THREE lanes and they must stay distinguishable, because +// telling them apart is the whole point: +// - REFUSAL — the frame names something WE sent as unacceptable → attributed +// critical drift (exit 2), with the code and reason carried into the report. +// - HANG-UP — the peer left for its own reasons (1011 internal error, 1012 +// restarting, 1000 normal) → nothing graded, exit 6. NOT a finding: calling a +// provider's own hiccup "drift" pages the team and hands it to the auto-fixer. +// - SILENCE / GARBAGE — unchanged: exit 6 and exit 5 respectively. +// --------------------------------------------------------------------------- + +/** The exact shape `fix/ws-preserve-close-code` emits, per its own source template. */ +function wsServerClose(code: number, reason: string, collected = 0): string { + return ( + `WSClosedError: WebSocket closed by server during waitUntil: code=${code} ` + + `reason=${JSON.stringify(reason)}. Collected ${collected} messages: [] bodies=[]\n` + + " at Timeout._onTimeout (/repo/src/__tests__/drift/ws-providers.ts:319:23)\n" + + " at /repo/src/__tests__/drift/ws-gemini-live.drift.ts:88:11" + ); +} + +function resultFor(message: string, ancestor = "Gemini Live WS drift"): VitestJsonResult { + return makeResult([ + makeAssertion({ + status: "failed", + ancestorTitles: [ancestor], + title: "WS text event sequence and shapes match", + failureMessages: [message], + }), + ]); +} + +describe("a provider that closes the session states its own cause", () => { + const GEMINI_REASON = "Requested model is not supported for BidiGenerateContent."; + + it("the production refusal (code 1008) becomes attributed critical drift, not triage", () => { + const result = resultFor(wsServerClose(1008, GEMINI_REASON)); + expect(quarantineOf(result)).toEqual([]); + expect(timeoutsOf(result)).toEqual([]); + const entries = entriesOf(result); + expect(entries).toHaveLength(1); + expect(entries[0].provider).toBe("Gemini Live"); + expect(entries[0].builderFile).toBe("src/ws-gemini-live.ts"); + expect(entries[0].scenario).toBe("WS session refused"); + expect(exitCodeOf(result)).toBe(2); + }); + + it("the close code AND the stated reason survive into the report", () => { + // The reason is the entire diagnosis; an entry that dropped it would be + // actionable in name only. + const diff = entriesOf(resultFor(wsServerClose(1008, GEMINI_REASON)))[0].diffs[0]; + expect(diff.severity).toBe("critical"); + expect(diff.issue).toContain("1008"); + expect(diff.issue).toContain(GEMINI_REASON); + expect(diff.real).toContain(GEMINI_REASON); + expect(diff.id).toBe("ws-close:1008"); + }); + + it("the delta key is the close CODE, so rewording the reason does not move it", () => { + // Providers reword reason prose freely. A key derived from it would re-report + // the same standing refusal as new-in-head on every PR. + const a = entriesOf(resultFor(wsServerClose(1008, "Requested model is not supported.")))[0]; + const b = entriesOf(resultFor(wsServerClose(1008, "totally different wording")))[0]; + expect(a.diffs[0].id).toBe(b.diffs[0].id); + }); + + it("a reason containing quotes, backslashes and newlines is decoded, not mangled", () => { + // The probe emits the reason JSON-quoted, so it is decoded with JSON.parse + // rather than by hand — provider text is not under our control. + const nasty = 'model "x\\y" is bad\nsecond line'; + const diff = entriesOf(resultFor(wsServerClose(1008, nasty)))[0].diffs[0]; + expect(diff.real).toContain(nasty); + }); + + it.each([ + [1002, "protocol error"], + [1003, "unsupported data"], + [1007, "invalid payload"], + [1008, "policy violation"], + [1009, "message too big"], + [1010, "mandatory extension missing"], + [4000, "provider-defined"], + [4999, "provider-defined upper bound"], + ])("close code %i (%s) is a refusal → exit 2", (code) => { + expect(isRefusalCloseCode(code as number)).toBe(true); + expect(exitCodeOf(resultFor(wsServerClose(code as number, "why")))).toBe(2); + }); + + it.each([ + [1000, "normal closure"], + [1001, "going away"], + [1004, "reserved, never assigned"], + [1005, "no status received — never sent on the wire"], + [1006, "abnormal closure — never sent on the wire"], + [1011, "server internal error"], + [1012, "service restarting"], + [1013, "try again later"], + [1015, "TLS handshake failure"], + [3999, "below the application range"], + [5000, "above the application range"], + ])("NEGATIVE CONTROL: close code %i (%s) is a hang-up, NOT drift → exit 6", (code) => { + // Treating a provider's own hiccup as drift pages the team and feeds the + // auto-fixer a phantom finding. It is surfaced, not swallowed and not blamed. + expect(isRefusalCloseCode(code as number)).toBe(false); + const result = resultFor(wsServerClose(code as number, "peer left")); + expect(entriesOf(result)).toEqual([]); + expect(quarantineOf(result)).toEqual([]); + const timeouts = timeoutsOf(result); + expect(timeouts).toHaveLength(1); + expect(timeouts[0].serverClose).toEqual({ code: code as number, reason: "peer left" }); + expect(exitCodeOf(result)).toBe(6); + }); + + it("a hang-up is distinguishable from silence in the record, not just in the exit code", () => { + // Both are exit 6, so the report is the only place a reader can tell "the peer + // hung up on us" from "nobody said anything". It has to carry that. + const hangUp = timeoutsOf(resultFor(wsServerClose(1011, "internal error")))[0]; + expect(hangUp.serverClose).toEqual({ code: 1011, reason: "internal error" }); + expect(hangUp.timeoutMs).toBeUndefined(); + + const silence = timeoutsOf(resultFor(CI_ZERO_OBSERVATION_TIMEOUT))[0]; + expect(silence.serverClose).toBeUndefined(); + expect(silence.timeoutMs).toBe(30000); + }); + + it("NEGATIVE CONTROL: silence is STILL exit 6 and garbage is STILL exit 5", () => { + // The two pre-existing lanes must be untouched by the third. + expect(exitCodeOf(resultFor(CI_ZERO_OBSERVATION_TIMEOUT))).toBe(6); + const garbage = resultFor( + "AssertionError: expected 'gpt-4o-realtime' to be one of\n at /repo/src/a.ts:1:1", + "Some unmapped suite", + ); + expect(quarantineOf(garbage)).toHaveLength(1); + expect(exitCodeOf(garbage)).toBe(5); + }); + + it("NEGATIVE CONTROL: a refusal from an UNREGISTERED probe quarantines, and says why", () => { + // An unattributable refusal must not be guessed at — but the quarantine + // message must name the refusal and the missing registration, not read as + // "unparseable". + const msg = wsServerClose(1008, GEMINI_REASON).replace( + "ws-gemini-live.drift.ts", + "ws-something-new.drift.ts", + ); + const result = resultFor(msg, "Some future WS drift"); + expect(entriesOf(result)).toEqual([]); + const q = quarantineOf(result); + expect(q).toHaveLength(1); + expect(q[0].message).toContain("REFUSED"); + expect(q[0].message).toContain("1008"); + expect(q[0].message).toContain("WS_HANDSHAKE_PROBES"); + expect(exitCodeOf(result)).toBe(5); + }); + + // An undecodable reason must never become a confident cause. Three inputs, + // because they fail at DIFFERENT points and an earlier one masks the later: + // an unquoted reason never matches the pattern at all, whereas an invalid JSON + // escape and a raw control character DO match it and then throw in the decoder. + // Testing only the unquoted form left the decoder's failure path unexercised — + // a mutation that swallowed the decode error and reported `reason: ""` survived + // until these two were added. + it.each([ + ["an unquoted reason (never matches the pattern)", "not-quoted"], + ["an invalid JSON escape (matches, then throws)", '"bad \\q escape"'], + ["a raw newline inside the quotes (matches, then throws)", '"line1\nline2"'], + ])("NEGATIVE CONTROL: %s is not a diagnosis → quarantine", (_label, rawReason) => { + const broken = + `WSClosedError: WebSocket closed by server during waitUntil: code=1008 reason=${rawReason}. ` + + "Collected 0 messages: []\n at /repo/src/__tests__/drift/ws-gemini-live.drift.ts:88:11"; + expect(parseWSServerClose(broken)).toBeNull(); + // Not drift, not the exit-6 lane — an unreadable cause is unreadable output. + expect(entriesOf(resultFor(broken))).toEqual([]); + expect(timeoutsOf(resultFor(broken))).toEqual([]); + expect(exitCodeOf(resultFor(broken))).toBe(5); + }); + + // The second classification pass re-scans every failed assertion, and it only + // runs when there is at least one unparseable failure AND no entries. So a + // recognized close is only at risk of being counted TWICE in a run that ALSO + // contains garbage — which is exactly the mixed run below. Without the skip in + // that pass, the hang-up is quarantined on top of being recorded, and the run + // reports two failures needing triage when only one does. + it("a hang-up alongside garbage is recorded ONCE, not also quarantined", () => { + const result = makeResult([ + makeAssertion({ + status: "failed", + ancestorTitles: ["Some unmapped suite"], + title: "something broke", + failureMessages: ["AssertionError: expected 'x' to be one of\n at /repo/src/a.ts:1:1"], + }), + makeAssertion({ + status: "failed", + ancestorTitles: ["Gemini Live WS drift"], + title: "WS text event sequence and shapes match", + failureMessages: [wsServerClose(1011, "internal error")], + }), + ]); + // Exactly the garbage is quarantined; the hang-up stays in its own lane. + expect(quarantineOf(result)).toHaveLength(1); + expect(quarantineOf(result)[0].testName).toContain("something broke"); + expect(timeoutsOf(result)).toHaveLength(1); + expect(exitCodeOf(result)).toBe(5); + }); + + it("an unattributable refusal alongside garbage is quarantined ONCE", () => { + const unowned = wsServerClose(1008, "nope").replace( + "ws-gemini-live.drift.ts", + "ws-something-new.drift.ts", + ); + const result = makeResult([ + makeAssertion({ + status: "failed", + ancestorTitles: ["Some unmapped suite"], + title: "something broke", + failureMessages: ["AssertionError: expected 'x' to be one of\n at /repo/src/a.ts:1:1"], + }), + makeAssertion({ + status: "failed", + ancestorTitles: ["Some future WS drift"], + title: "WS text event sequence and shapes match", + failureMessages: [unowned], + }), + ]); + expect(quarantineOf(result)).toHaveLength(2); + expect(quarantineOf(result).filter((q) => q.message.includes("REFUSED"))).toHaveLength(1); + }); + + it("a refusal that also carried messages is still a refusal", () => { + // The close frame is the terminal fact regardless of what arrived first. + const result = resultFor(wsServerClose(1008, GEMINI_REASON, 3)); + expect(entriesOf(result)).toHaveLength(1); + expect(exitCodeOf(result)).toBe(2); + }); +}); + +// --------------------------------------------------------------------------- +// Zero-observation live timeouts (exit 6) +// +// The failure that blocked every bot-opened drift PR: the Gemini Live WS legs +// reached their 30s wait having observed nothing, and the collector reported that +// as "unparseable output — manual triage required" (exit 5), which hard-fails the +// base leg of drift-live-pr. A timeout is the single most common failure a live +// harness will ever see; a collector that cannot name it is not classifying. +// +// The message below is VERBATIM from the run that failed (CopilotKit/aimock run +// 31571018005, PR #370) — lifted from that run's own `drift-report-base` artifact, +// not hand-authored to the recognizer. +// +// The negative controls are the load-bearing half. The trap on this fix is +// widening the lane until real output slips through quietly, so: unparseable +// output still quarantines, a timeout that OBSERVED something still quarantines, +// and a drift marker always wins. +// --------------------------------------------------------------------------- + +/** + * A timeout that DID surface a provider `error` body, reported from a given WS + * drift probe. The frame is the only thing that varies, because the frame is what + * attribution is supposed to key off. + */ +function wsErrorTimeoutFrom(driftFile: string): string { + return ( + "Error: waitUntil timeout after 30000ms. Collected 1 messages: [error] " + + 'bodies=[{"type":"error","error":{"type":"invalid_request_error",' + + '"code":"bad_setup","message":"nope"}}]\n' + + " at Timeout._onTimeout (/repo/src/__tests__/drift/ws-providers.ts:319:23)\n" + + ` at /repo/src/__tests__/drift/${driftFile}:88:11` + ); +} + +/** Verbatim CI failure message, run 31571018005 (PR #370), Gemini Live WS legs. */ +const CI_ZERO_OBSERVATION_TIMEOUT = + "Error: waitUntil timeout after 30000ms. Collected 0 messages: [] bodies=[]\n" + + " at Timeout._onTimeout (/home/runner/work/aimock/base-main/src/__tests__/drift/ws-providers.ts:319:23)\n" + + " at listOnTimeout (node:internal/timers:605:17)\n" + + " at processTimers (node:internal/timers:541:7)"; + +describe("zero-observation live timeouts are reported AS timeouts (exit 6)", () => { + function ciResult(): VitestJsonResult { + return makeResult([ + makeAssertion({ + status: "failed", + ancestorTitles: ["Gemini Live WS drift"], + title: "WS text event sequence and shapes match", + failureMessages: [CI_ZERO_OBSERVATION_TIMEOUT], + }), + makeAssertion({ + status: "failed", + ancestorTitles: ["Gemini Live WS drift"], + title: "WS tool call event sequence matches", + failureMessages: [CI_ZERO_OBSERVATION_TIMEOUT], + }), + ]); + } + + it("routes the REAL CI failure to the timeout lane, not quarantine", () => { + const result = ciResult(); + expect(quarantineOf(result)).toEqual([]); + expect(entriesOf(result)).toEqual([]); + const timeouts = timeoutsOf(result); + expect(timeouts).toHaveLength(2); + expect(exitCodeOf(result)).toBe(6); + }); + + it("carries the wait budget, the test name and a jumpable location", () => { + const [first] = timeoutsOf(ciResult()); + // The budget the probe reported, as a number the reader can act on. + expect(first.timeoutMs).toBe(30000); + expect(first.testName).toBe("Gemini Live WS drift > WS text event sequence and shapes match"); + // Captured BEFORE stack stripping, so it points at the probe's own frame. + expect(first.rawLocation).toBe( + "/home/runner/work/aimock/base-main/src/__tests__/drift/ws-providers.ts:319:23", + ); + expect(first.message).toBe(CI_ZERO_OBSERVATION_TIMEOUT); + }); + + it('reports the run as "live-timeout", which is NOT a reusable clean baseline', () => { + expect(conclusionForExitCode(6)).toBe("live-timeout"); + // The legs that timed out graded nothing, so the run must never be reused as + // a base that certifies those surfaces drift-free. + const report: DriftReport = { + timestamp: "2026-08-12T06:42:00.000Z", + generatedAt: "2026-08-12T06:42:00.000Z", + conclusion: conclusionForExitCode(6), + entries: [ + { + provider: "OpenAI", + scenario: "chat", + builderFile: "src/responses.ts", + builderFunctions: ["buildChat"], + typesFile: null, + sdkShapesFile: "src/__tests__/drift/sdk-shapes.ts", + diffs: [SAMPLE_DIFF], + }, + ], + }; + expect(isBaseReportReusable(report, "live-timeout", true)).toBe(false); + }); + + // ---- NEGATIVE CONTROLS -------------------------------------------------- + + it("NEGATIVE CONTROL: genuinely unparseable output STILL quarantines (exit 5)", () => { + // Truncated garbage with no drift block, no infra reason, and no timeout tail. + // If this stops quarantining, the lane has been widened into a silent pass. + const garbage = + "AssertionError: expected 'gpt-4o-realtime' to be one of\n" + + " at /repo/src/__tests__/drift/ws-realtime.drift.ts:64:11"; + const result = makeResult([ + makeAssertion({ + status: "failed", + ancestorTitles: ["Some unmapped suite"], + title: "something broke", + failureMessages: [garbage], + }), + ]); + expect(timeoutsOf(result)).toEqual([]); + expect(quarantineOf(result)).toHaveLength(1); + expect(exitCodeOf(result)).toBe(5); + }); + + it("NEGATIVE CONTROL: a timeout that OBSERVED messages is not a silent surface → still quarantines", () => { + // Non-zero collected count. The probe saw output; that output is evidence and + // must not be written off as "the surface sent nothing". (With a provider + // `error` body it would be handshake drift — asserted separately above.) + const observedTimeout = + "Error: waitUntil timeout after 30000ms. Collected 3 messages: [setup, chunk, chunk] " + + 'bodies=[{"type":"setup"}]\n' + + " at Timeout._onTimeout (/repo/src/__tests__/drift/ws-providers.ts:319:23)"; + expect(parseLiveTimeout(observedTimeout)).toBeNull(); + const result = makeResult([ + makeAssertion({ + status: "failed", + ancestorTitles: ["Gemini Live WS drift"], + title: "WS text event sequence and shapes match", + failureMessages: [observedTimeout], + }), + ]); + expect(timeoutsOf(result)).toEqual([]); + expect(quarantineOf(result)).toHaveLength(1); + expect(exitCodeOf(result)).toBe(5); + }); + + it("NEGATIVE CONTROL: a drift marker beats the timeout tail", () => { + // A message that carries a drift report is drift, whatever else it says. + const withMarker = + "Error: waitUntil timeout after 30000ms. Collected 0 messages: [] bodies=[]\n" + + "API DRIFT DETECTED: Gemini Live (WS text)\n"; + expect(parseLiveTimeout(withMarker)).toBeNull(); + }); + + it("NEGATIVE CONTROL: a bare timeout with no collected-message count still quarantines", () => { + // No structured count means the probe never stated what it observed, so + // "observed nothing" is an inference, not a reading. + const noCount = + "Error: waitUntil timeout after 30000ms\n" + + " at /repo/src/__tests__/drift/ws-providers.ts:319:23"; + expect(parseLiveTimeout(noCount)).toBeNull(); + const result = makeResult([ + makeAssertion({ + status: "failed", + ancestorTitles: ["Gemini Live WS drift"], + title: "WS text event sequence and shapes match", + failureMessages: [noCount], + }), + ]); + expect(quarantineOf(result)).toHaveLength(1); + expect(exitCodeOf(result)).toBe(5); + }); + + it("real drift on another leg still wins: exit 2, with the timeout recorded alongside", () => { + // A timed-out leg must not mask, or be masked by, a genuine finding — both + // are recorded and the actionable one drives the exit code. + const result = makeResult([ + makeAssertion({ + status: "failed", + ancestorTitles: ["OpenAI Chat Completions drift"], + title: "non-streaming text matches real API", + failureMessages: [formatDriftReport("OpenAI Chat (non-streaming text)", [SAMPLE_DIFF])], + }), + makeAssertion({ + status: "failed", + ancestorTitles: ["Gemini Live WS drift"], + title: "WS text event sequence and shapes match", + failureMessages: [CI_ZERO_OBSERVATION_TIMEOUT], + }), + ]); + expect(entriesOf(result)).toHaveLength(1); + expect(timeoutsOf(result)).toHaveLength(1); + expect(quarantineOf(result)).toEqual([]); + expect(exitCodeOf(result)).toBe(2); + }); + + it("a quarantined sibling still wins over a timeout: exit 5", () => { + // Quarantine outranks live-timeout — a collector fault needs a human even + // when another leg also went quiet. + const result = makeResult([ + makeAssertion({ + status: "failed", + ancestorTitles: ["Some unmapped suite"], + title: "something broke", + failureMessages: ["AssertionError: expected 'x' to be one of\n at /repo/src/a.ts:1:1"], + }), + makeAssertion({ + status: "failed", + ancestorTitles: ["Gemini Live WS drift"], + title: "WS text event sequence and shapes match", + failureMessages: [CI_ZERO_OBSERVATION_TIMEOUT], + }), + ]); + expect(quarantineOf(result)).toHaveLength(1); + expect(timeoutsOf(result)).toHaveLength(1); + expect(exitCodeOf(result)).toBe(5); + }); + + // The three-way split, pinned. A live WS leg can fail in three ways and they do + // NOT collapse, because the EVIDENCE differs: an error body is the provider + // stating why it rejected the session (drift, attributable, auto-fixable); + // silence is evidence of nothing (timeout); anything else is unreadable + // (quarantine). Pinned explicitly so the taxonomy is a measured fact rather + // than something a reader has to reconstruct from three recognizers. + // + // Attribution now follows the PROBE, for every registered WS surface. It used to + // test for a `ws-realtime.drift.ts` frame and hardcode openai-realtime, so a + // rejected `gemini-live` handshake — the surface that actually goes quiet in + // production — resolved to nothing and quarantined at exit 5, back into the hard + // stop this lane exists to avoid. Each row below asserts the surface the failure + // is routed to, not merely that it was routed somewhere: a lane that attributed + // every provider to OpenAI Realtime would satisfy a count-only assertion. + it.each([ + ["ws-realtime.drift.ts", "OpenAI Realtime", "src/ws-realtime.ts"], + ["ws-gemini-live.drift.ts", "Gemini Live", "src/ws-gemini-live.ts"], + ["ws-responses.drift.ts", "OpenAI Responses WS", "src/ws-responses.ts"], + ])( + "an error-carrying timeout from %s is critical drift owned by %s", + (frame, wantProvider, wantBuilderFile) => { + const result = makeResult([ + makeAssertion({ + status: "failed", + // The ancestor title deliberately says Gemini Live for every row: it must + // not be what decides the owner, or the frame-based attribution would be + // untested for the two rows whose title disagrees with their probe. + ancestorTitles: ["Gemini Live WS drift"], + title: "WS text event sequence and shapes match", + failureMessages: [wsErrorTimeoutFrom(frame)], + }), + ]); + expect(quarantineOf(result)).toEqual([]); + expect(timeoutsOf(result)).toEqual([]); + const entries = entriesOf(result); + expect(entries).toHaveLength(1); + expect(entries[0].provider).toBe(wantProvider); + expect(entries[0].builderFile).toBe(wantBuilderFile); + expect(entries[0].diffs[0].severity).toBe("critical"); + expect(entries[0].diffs[0].id).toBe("ws-handshake:bad_setup"); + expect(exitCodeOf(result)).toBe(2); + }, + ); + + it("NEGATIVE CONTROL: an error-carrying timeout from an UNREGISTERED probe still quarantines", () => { + // An unknown WS surface must not be guessed at. A confident wrong owner routes + // remediation at the wrong file and fails OPEN, which is worse than the stop. + const result = makeResult([ + makeAssertion({ + status: "failed", + ancestorTitles: ["Some future WS drift"], + title: "WS text event sequence and shapes match", + failureMessages: [wsErrorTimeoutFrom("ws-something-new.drift.ts")], + }), + ]); + expect(entriesOf(result)).toEqual([]); + expect(quarantineOf(result)).toHaveLength(1); + expect(exitCodeOf(result)).toBe(5); + }); + + it("NEGATIVE CONTROL: a registered probe with NO error body is a timeout, not drift", () => { + // Gate 3 still separates the lanes: silence from a known probe is exit 6, so + // widening attribution did not let the timeout lane be swallowed by the drift + // lane. + const silent = + "Error: waitUntil timeout after 30000ms. Collected 0 messages: [] bodies=[]\n" + + " at Timeout._onTimeout (/repo/src/__tests__/drift/ws-providers.ts:319:23)\n" + + " at /repo/src/__tests__/drift/ws-gemini-live.drift.ts:88:11"; + const result = makeResult([ + makeAssertion({ + status: "failed", + ancestorTitles: ["Gemini Live WS drift"], + title: "WS text event sequence and shapes match", + failureMessages: [silent], + }), + ]); + expect(entriesOf(result)).toEqual([]); + expect(quarantineOf(result)).toEqual([]); + expect(timeoutsOf(result)).toHaveLength(1); + expect(exitCodeOf(result)).toBe(6); + }); + + it("a WS handshake failure WITH an error body is still critical drift, not a timeout", () => { + // parseWSHandshakeFailure runs first and must keep its claim. + const handshake = + "Error: waitUntil timeout after 30000ms. Collected 1 messages: [error] " + + 'bodies=[{"type":"error","error":{"type":"invalid_request_error",' + + '"code":"missing_required_parameter","message":"Missing required parameter."}}]\n' + + " at /repo/src/__tests__/drift/ws-realtime.drift.ts:138:26"; + const result = makeResult([ + makeAssertion({ + status: "failed", + ancestorTitles: ["OpenAI Realtime API drift"], + title: "WS text event sequence and shapes match (GA)", + failureMessages: [handshake], + }), + ]); + expect(timeoutsOf(result)).toEqual([]); + expect(entriesOf(result)).toHaveLength(1); + expect(exitCodeOf(result)).toBe(2); + }); +}); + // --------------------------------------------------------------------------- // parseKnownModelsCanary // --------------------------------------------------------------------------- diff --git a/src/__tests__/drift-sync-check.test.ts b/src/__tests__/drift-sync-check.test.ts index ab0b7844..52223144 100644 --- a/src/__tests__/drift-sync-check.test.ts +++ b/src/__tests__/drift-sync-check.test.ts @@ -15,6 +15,9 @@ import { isAllowedSyncFile, checkChangedFileAllowlist, countCriticalDiffs, + listCriticalDiffs, + formatCriticalDiffs, + reportTrustNote, evaluateSyncCheck, runPinCheck, recollect, @@ -149,6 +152,66 @@ describe("countCriticalDiffs", () => { }); }); +describe("listCriticalDiffs / formatCriticalDiffs", () => { + it("IDENTIFIES each critical diff, not just a count", () => { + const refs = listCriticalDiffs(report([0, 2])); + expect(refs).toEqual([ + { provider: "provider-1", scenario: "scenario", path: "field-0" }, + { provider: "provider-1", scenario: "scenario", path: "field-1" }, + ]); + }); + + it("prefers a stable `id` over the prose-coupled `path` when one exists", () => { + const r = report([1]); + r.entries[0].diffs[0].id = "openai-realtime:no-ga-family"; + expect(formatCriticalDiffs(listCriticalDiffs(r))).toBe( + "provider-0/scenario: openai-realtime:no-ga-family", + ); + }); + + it("ignores non-critical diffs", () => { + const r = report([1]); + r.entries[0].diffs[0].severity = "warning"; + expect(listCriticalDiffs(r)).toEqual([]); + }); +}); + +describe("reportTrustNote — a zero that cannot be believed is not a clean re-collect", () => { + function withConclusion(conclusion: string | undefined, quarantine?: number): DriftReport { + const r = report([0]); + if (conclusion !== undefined) r.conclusion = conclusion; + if (quarantine !== undefined) { + r.quarantine = Array.from({ length: quarantine }, (_, i) => ({ + provider: "unknown", + testName: `t-${i}`, + rawLocation: "", + message: "waitUntil timeout after 30000ms", + })); + } + return r; + } + + it("trusts a positively-clean report", () => { + expect(reportTrustNote(withConclusion("clean"))).toBeNull(); + }); + + it("trusts a report whose criticals ARE the determination", () => { + expect(reportTrustNote(withConclusion("critical"))).toBeNull(); + }); + + it("does NOT trust a quarantined report (the 74f6efa43753f7d0 mornings' shape)", () => { + expect(reportTrustNote(withConclusion("quarantine", 2))).toContain("quarantined 2 failure(s)"); + }); + + it("does NOT trust a report whose AG-UI leg could not run (entries are incomplete)", () => { + expect(reportTrustNote(withConclusion("skipped"))).toContain("AG-UI"); + }); + + it("does NOT trust a report with no `conclusion` at all (UNKNOWN never passes as clean)", () => { + expect(reportTrustNote(withConclusion(undefined))).toContain("no `conclusion`"); + }); +}); + describe("recollect", () => { it("fails closed (SyncCheckConfigError) when the collector produced no report file", () => { const runner = vi.fn((): CommandResult => ({ status: 0, output: "" })); @@ -232,6 +295,60 @@ describe("evaluateSyncCheck — RED/GREEN value-test surface", () => { expect(verdict.reason).toBe(SyncCheckReason.RESIDUAL_CRITICAL_DRIFT); expect(verdict.detail).toContain("1 critical"); }); + + it("a refusal NAMES the residual diffs, so the log alone is triageable", () => { + const r = report([1]); + r.entries[0].diffs[0].id = "openai-realtime:no-ga-family"; + const verdict = evaluateSyncCheck(deps({ recollect: () => r })); + expect(verdict.reason).toBe(SyncCheckReason.RESIDUAL_CRITICAL_DRIFT); + expect(verdict.detail).toContain("provider-0/scenario: openai-realtime:no-ga-family"); + }); + + it("a SKIPPED gate-3 says in the verdict what it could not observe", () => { + const recollectFn = vi.fn(() => report([0])); + const verdict = evaluateSyncCheck(deps({ recollect: recollectFn }), { + skipRecollect: true, + skipRecollectReason: "no live drift surface reads deprecatedFamilies", + }); + expect(verdict.ok).toBe(true); + expect(recollectFn).not.toHaveBeenCalled(); + expect(verdict.detail).toContain("live re-collect NOT RUN"); + expect(verdict.detail).toContain("no live drift surface reads deprecatedFamilies"); + // …and never claims the thing it did not do. + expect(verdict.detail).not.toContain("clean re-collect"); + }); + + it("turning gate-3 OFF with no stated reason is a CONFIG ERROR, not a silent pass", () => { + expect(() => evaluateSyncCheck(deps({}), { skipRecollect: true })).toThrow( + SyncCheckConfigError, + ); + }); + + it("an UNTRUSTWORTHY zero passes but is reported UNCONFIRMED, never as a clean re-collect", () => { + const quarantined = report([0]); + quarantined.conclusion = "quarantine"; + quarantined.quarantine = [ + { + provider: "unknown", + testName: "Gemini Live WS drift", + rawLocation: "", + message: "timeout", + }, + ]; + const verdict = evaluateSyncCheck(deps({ recollect: () => quarantined })); + expect(verdict.ok).toBe(true); + expect(verdict.reason).toBe(SyncCheckReason.OK); + expect(verdict.detail).toContain("could NOT CONFIRM"); + expect(verdict.detail).not.toContain("clean re-collect"); + }); + + it("a positively-clean re-collect DOES claim a clean re-collect", () => { + const clean = report([0]); + clean.conclusion = "clean"; + const verdict = evaluateSyncCheck(deps({ recollect: () => clean })); + expect(verdict.ok).toBe(true); + expect(verdict.detail).toContain("clean re-collect"); + }); }); // --------------------------------------------------------------------------- diff --git a/src/__tests__/drift-sync-core.test.ts b/src/__tests__/drift-sync-core.test.ts index f6d9bc88..5335af63 100644 --- a/src/__tests__/drift-sync-core.test.ts +++ b/src/__tests__/drift-sync-core.test.ts @@ -621,10 +621,21 @@ describe("runDriftSyncCore", () => { // optional cleanup is safe — it no longer selects a different route. expect(registry.text).toContain("no remaining aimock reference"); - // A real registry edit was made, so the real gate DOES run — and with the - // live re-collect ON, because this run deferred nothing to a human. + // A real registry edit was made, so the real gate DOES run — gate-1 + // (allowlist) and gate-2 (pin), with gate-3's live re-collect OFF and the + // reason recorded. A recorded deprecation is invisible to every live drift + // surface (nothing in the collector's `*.drift.ts` glob reads + // `deprecatedFamilies`), so a re-collect can only veto this edit on + // unrelated drift — which is how the identical changeset 74f6efa43753f7d0 + // was refused on 2026-08-11 and applied on 2026-08-12. See + // `gate3SkipReason` and drift-sync-gate-determinism.test.ts. expect(runSyncCheck).toHaveBeenCalledTimes(1); - expect(runSyncCheck).toHaveBeenCalledWith({ skipRecollect: false }); + expect(runSyncCheck).toHaveBeenCalledWith({ + skipRecollect: true, + skipRecollectReason: expect.stringContaining( + "no live drift surface reads deprecatedFamilies", + ), + }); }); it("RED->GREEN (deprecation, STILL-REFERENCED): also recorded, and the mock is NOT removed", () => { @@ -924,9 +935,13 @@ describe("D-M1: recollect gate vs route-to-human invariant", () => { ); expect(revertFiles).not.toHaveBeenCalled(); // The gate ran (a registry edit WAS applied) but with the live re-collect - // skipped, because a family was simultaneously deferred to a human. + // skipped, because a family was simultaneously deferred to a human — and the + // verdict records that as the reason, not just the fact of the skip. expect(runSyncCheck).toHaveBeenCalledTimes(1); - expect(runSyncCheck).toHaveBeenCalledWith({ skipRecollect: true }); + expect(runSyncCheck).toHaveBeenCalledWith({ + skipRecollect: true, + skipRecollectReason: expect.stringContaining("deferred a family to a human"), + }); // The registry edit was persisted (writeRegistrySource ran with the addition). expect(registry.text).toContain('"gpt-live"'); }); diff --git a/src/__tests__/drift-sync-gate-determinism.test.ts b/src/__tests__/drift-sync-gate-determinism.test.ts new file mode 100644 index 00000000..b93ca12b --- /dev/null +++ b/src/__tests__/drift-sync-gate-determinism.test.ts @@ -0,0 +1,488 @@ +/** + * The drift-sync gate must return the SAME VERDICT for the SAME CHANGESET. + * + * OBSERVED FAILURE this file reconstructs — two consecutive scheduled `Fix Drift` + * runs produced the byte-identical changeset key `74f6efa43753f7d0` (the same two + * gemini deprecations, recorded the same way) and the gate accepted it only once: + * + * * 2026-08-11, run 31465219443 — `reason=gate-failed`: + * "drift-sync-check rejected the sync [residual-critical-drift]: Clean + * re-collect after sync still reports 1 critical diff(s) — sync did not + * resolve the drift — reverted" + * * 2026-08-12, run 31570802134 — `reason=ok-applied`, PR #370 opened, +2/-0. + * + * WHY IT COULD DIFFER — gate-3 re-runs the WHOLE live drift suite + * (`vitest --config vitest.config.drift.ts`, every provider and every surface) + * and vetoes on its GLOBAL critical count. Nothing about that count is a function + * of the changeset: the sync's own input is three `/models` listings, while + * gate-3's input is a fresh live observation of every drift surface aimock has, + * taken ~75s later. Two runs therefore share a changeset key while handing gate-3 + * different input. + * + * AND FOR A DEPRECATION RECORD GATE-3 CANNOT OBSERVE THE EDIT AT ALL. The edit + * appends a family literal to `deprecatedFamilies` in model-registry.ts, and NO + * file in the collector's suite glob (`src/__tests__/drift/**\/*.drift.ts`) reads + * `deprecatedFamilies` — the only live model-family canary is the UNCLASSIFIED + * direction (`unclassifiedFamilies`, live-minus-classified). The deprecation + * direction (`detectDeprecatedFamilies`, classified-minus-live) is exercised only + * OFFLINE with injected payloads. So a recorded deprecation provably cannot + * change any collector output: gate-3 can neither confirm nor refute it, yet it + * could still veto it on whatever unrelated drift the live suite happened to see + * that morning. `assertNoLiveDeprecationCanary` below pins that premise, so if a + * live deprecation canary is ever added this test reds and says to re-enable + * gate-3 for the deprecation lane. + * + * The two fixture re-collects below are the two mornings' observations: + * * `recollect0812` is VERBATIM from the 2026-08-12 drift-report artifact + * (9131032270): zero entries, two quarantined Gemini Live WS timeouts. + * * `recollect0811` is a FAITHFUL RECONSTRUCTION, not a capture. The 08-11 run + * recorded only the COUNT ("1 critical diff(s)") — the gate prints no diff + * identity and `drift-report.sync-check.json` is never uploaded — so which + * diff it was is NOT recoverable from that run. The fixture therefore uses a + * real collector-emitted critical shape (the OpenAI Realtime WS-handshake + * diff, drift-report-collector.ts) standing in for "one critical diff + * somewhere in the live suite, unrelated to the gemini deprecations". + */ +import { describe, it, expect } from "vitest"; +import { readdirSync, readFileSync } from "node:fs"; +import { join } from "node:path"; + +import { includeFamilies } from "./drift/model-registry.js"; +import { MIN_LISTING_SIZE } from "./drift/deprecation-detector.js"; +import { + runDriftSyncCore, + computeChangesetKey, + SyncCoreReason, + MODEL_REGISTRY_REL_PATH, + type SyncCoreDeps, + type SyncCoreOutcome, + type ProviderChurnInput, +} from "../../scripts/drift-sync.js"; +import { evaluateSyncCheck, SyncCheckReason } from "../../scripts/drift-sync-check.js"; +import type { DriftReport } from "../../scripts/drift-types.js"; + +// --------------------------------------------------------------------------- +// The premise gate-3's deprecation-lane skip rests on. +// --------------------------------------------------------------------------- + +const DRIFT_SUITE_DIR = "src/__tests__/drift"; + +/** + * The collector runs exactly `src/__tests__/drift/**\/*.drift.ts` + * (vitest.config.drift.ts). If none of those files reads `deprecatedFamilies`, + * then appending to that ledger cannot change a single collector output — which + * is precisely why gate-3 is skipped for a deprecation-only run. + * + * MUTATION-TESTABLE ON PURPOSE: add a live deprecation canary that imports + * `deprecatedFamilies` into any `*.drift.ts` and this reds, pointing at the + * `gate3CanObserveAppliedEdits` decision that must then change. + */ +function driftSuiteFilesReferencing(symbol: string): string[] { + return readdirSync(DRIFT_SUITE_DIR) + .filter((f) => f.endsWith(".drift.ts")) + .filter((f) => readFileSync(join(DRIFT_SUITE_DIR, f), "utf-8").includes(symbol)); +} + +describe("premise: the live drift suite cannot observe a recorded deprecation", () => { + it("no *.drift.ts in the collector's glob reads deprecatedFamilies", () => { + expect(driftSuiteFilesReferencing("deprecatedFamilies")).toEqual([]); + }); + + it("the collector's glob DOES read includeFamilies (so the guard above is not vacuous)", () => { + // Same read path, same glob, a symbol that IS present — proves the scan can + // find a reference at all, so the empty result above is a real absence. + expect(driftSuiteFilesReferencing("includeFamilies").length).toBeGreaterThan(0); + }); +}); + +// --------------------------------------------------------------------------- +// Fixtures — the 2026-08-11/12 changeset. +// --------------------------------------------------------------------------- + +/** + * The two families the real runs recorded. Asserted present-and-usable rather + * than assumed: `includeFamilies` and `deprecatedFamilies` both move under this + * repo's own automation, and a fixture that silently stops describing a real + * candidate would assert on an empty outcome list and pass vacuously. + */ +const RECORDED_PAIR = ["gemini-2.0-flash", "gemini-2.0-flash-lite"] as const; + +function geminiLiveListingWithoutRecordedPair(): string[] { + const missing = RECORDED_PAIR.filter((f) => !includeFamilies.gemini.has(f)); + if (missing.length > 0) { + throw new Error( + `this reconstruction needs ${RECORDED_PAIR.join(" + ")} to still be in ` + + `includeFamilies.gemini, but ${missing.join(", ")} is absent — the 2026-08-11 ` + + `changeset can no longer be reconstructed from the live registry. Re-derive the ` + + `pair from includeFamilies.gemini rather than deleting the assertions.`, + ); + } + const surviving = [...includeFamilies.gemini].filter( + (f) => !(RECORDED_PAIR as readonly string[]).includes(f), + ); + // Families plus a dated snapshot of each, so the listing clears the + // fail-closed floor (a short listing is skipped, never a removal signal). + const ids = [...surviving, ...surviving.map((f) => `${f}-2025-01-01`)]; + if (ids.length < MIN_LISTING_SIZE.gemini) { + throw new Error( + `fixture listing has ${ids.length} raw id(s), below gemini's fail-closed floor of ` + + `${MIN_LISTING_SIZE.gemini} — the detector would SKIP instead of reporting the pair.`, + ); + } + return ids; +} + +function fixtureRegistrySource(): string { + return [ + "export const includeFamilies = {", + ' gemini: set("gemini", [', + ...[...includeFamilies.gemini].map((f) => ` "${f}",`), + " ]),", + "};", + "export const deprecatedFamilies = {", + ' gemini: set("gemini", [', + " // drift-sync appends recorded deprecations here.", + " ]),", + "};", + ].join("\n"); +} + +/** The 2026-08-11/12 provider inputs: gemini checked, the other two not credentialed. */ +function churnInputs(): ProviderChurnInput[] { + return [{ provider: "gemini", liveModelIds: geminiLiveListingWithoutRecordedPair() }]; +} + +// --------------------------------------------------------------------------- +// The two mornings' live re-collect observations. +// --------------------------------------------------------------------------- + +/** + * 2026-08-11: one critical diff somewhere in the live suite. Reconstruction — + * see the file header for exactly what was and was not recoverable. + */ +function recollect0811(): DriftReport { + return { + timestamp: "2026-08-11T06:30:52.000Z", + generatedAt: "2026-08-11T06:30:52.000Z", + conclusion: "critical", + entries: [ + { + provider: "OpenAI Realtime", + scenario: "WS handshake", + builderFile: "src/responses.ts", + builderFunctions: [], + typesFile: null, + sdkShapesFile: "src/__tests__/drift/sdk-shapes.ts", + diffs: [ + { + severity: "critical", + issue: + "OpenAI Realtime WS handshake did not complete — the live API returned an " + + "error event (invalid_request_error/session_expired).", + path: "session.session_expired", + expected: "(handshake completes: session.created/updated received)", + real: "error invalid_request_error: session expired", + mock: "", + id: "ws-handshake:session_expired", + }, + ], + }, + ], + }; +} + +/** 2026-08-12: VERBATIM from drift-report artifact 9131032270 — zero entries, two quarantines. */ +function recollect0812(): DriftReport { + const wsTimeout = + "Error: waitUntil timeout after 30000ms. Collected 0 messages: [] bodies=[]\n" + + " at Timeout._onTimeout (/home/runner/work/aimock/aimock/src/__tests__/drift/ws-providers.ts:319:23)"; + return { + timestamp: "2026-08-12T06:31:23.604Z", + generatedAt: "2026-08-12T06:31:23.604Z", + conclusion: "quarantine", + entries: [], + quarantine: [ + { + provider: "unknown", + testName: "Gemini Live WS drift > WS text event sequence and shapes match", + rawLocation: "src/__tests__/drift/ws-providers.ts:319:23", + message: wsTimeout, + }, + { + provider: "unknown", + testName: "Gemini Live WS drift > WS tool call event sequence matches", + rawLocation: "src/__tests__/drift/ws-providers.ts:319:23", + message: wsTimeout, + }, + ], + }; +} + +// --------------------------------------------------------------------------- +// Driving the REAL sync core through the REAL gate. +// --------------------------------------------------------------------------- + +interface RunResult { + outcome: SyncCoreOutcome; + changesetKey: string; + registrySource: string; + reverted: string[]; + recollectCalls: number; +} + +/** + * Run the real `runDriftSyncCore` over the fixture changeset, with the real + * `evaluateSyncCheck` as the gate. Only the leaf observations are injected: the + * registry source text (in memory), the pin result, and the live re-collect + * report. Every decision under test — the churn diff, the mechanical edit, the + * gate composition, the skip decision, the revert — is real code. + */ +function runSync(recollect: () => DriftReport, inputs = churnInputs()): RunResult { + let registrySource = fixtureRegistrySource(); + const reverted: string[] = []; + let recollectCalls = 0; + + const deps: SyncCoreDeps = { + isReferenced: (family) => family === "gemini-2.0-flash", + isRecorded: () => false, + readRegistrySource: () => registrySource, + writeRegistrySource: (text) => { + registrySource = text; + }, + readProposalNote: () => null, + writeProposalNote: () => { + throw new Error("this changeset writes no proposal note"); + }, + runSyncCheck: (opts) => + evaluateSyncCheck( + { + getChangedFiles: () => [MODEL_REGISTRY_REL_PATH], + runPinCheck: () => ({ ok: true, output: "logic-pin.test.ts passed" }), + recollect: () => { + recollectCalls += 1; + return recollect(); + }, + }, + opts, + ), + revertFiles: (paths) => reverted.push(...paths), + now: () => new Date("2026-08-11T06:29:00.000Z"), + }; + + const outcome = runDriftSyncCore(inputs, deps); + return { + outcome, + changesetKey: computeChangesetKey(outcome), + registrySource, + reverted, + recollectCalls, + }; +} + +// --------------------------------------------------------------------------- +// RED: the same changeset, two verdicts. +// --------------------------------------------------------------------------- + +describe("the 2026-08-11/12 changeset key 74f6efa43753f7d0", () => { + it("both mornings really are the SAME changeset (identical key, identical edit)", () => { + const day1 = runSync(recollect0811); + const day2 = runSync(recollect0812); + + // The premise of the whole investigation: the key does not distinguish them. + expect(day1.changesetKey).toBe(day2.changesetKey); + expect(day1.changesetKey).not.toBe(""); + expect( + day1.outcome.outcomes.map((o) => `${o.action}:${o.provider}/${o.family}`).sort(), + ).toEqual([ + "deprecation-recorded:gemini/gemini-2.0-flash", + "deprecation-recorded:gemini/gemini-2.0-flash-lite", + ]); + }); + + it("the mechanical edit is CORRECT on both mornings (+2 recorded, nothing else touched)", () => { + for (const recollect of [recollect0811, recollect0812]) { + const { registrySource } = runSync(recollect); + for (const family of RECORDED_PAIR) { + expect(registrySource).toContain(`"${family}"`); + } + // The ledger grew and includeFamilies did NOT shrink — the mock keeps serving. + for (const family of includeFamilies.gemini) { + expect(registrySource).toContain(`"${family}"`); + } + } + }); + + it("the gate reaches the SAME verdict on both mornings", () => { + const day1 = runSync(recollect0811); + const day2 = runSync(recollect0812); + + expect(day1.outcome.reason).toBe(day2.outcome.reason); + expect(day1.outcome.ok).toBe(day2.outcome.ok); + }); + + it("neither morning reverts the correct edit", () => { + expect(runSync(recollect0811).reverted).toEqual([]); + expect(runSync(recollect0812).reverted).toEqual([]); + }); + + it("a deprecation-only run never pays for a live re-collect it cannot learn from", () => { + expect(runSync(recollect0811).recollectCalls).toBe(0); + expect(runSync(recollect0812).recollectCalls).toBe(0); + }); + + it("REPEAT-COUNT PROOF: 25 runs of each morning yield exactly ONE verdict", () => { + const verdicts = new Set(); + for (let i = 0; i < 25; i++) { + for (const recollect of [recollect0811, recollect0812]) { + const { outcome, changesetKey } = runSync(recollect); + verdicts.add(`${changesetKey}|${outcome.reason}|${outcome.ok}`); + } + } + expect([...verdicts]).toEqual([`74f6efa43753f7d0|${SyncCoreReason.OK_APPLIED}|true`]); + }); +}); + +// --------------------------------------------------------------------------- +// NEGATIVE CONTROLS — a genuinely wrong edit is still caught. +// --------------------------------------------------------------------------- + +/** + * An `added` run: a human approved a brand-new family, so the sync appends it to + * `includeFamilies`. THAT edit IS observable by the live suite — the unclassified + * canary stops reporting the family once it is classified — so gate-3 must run + * and must still veto a run whose re-collect proves the drift is unresolved. + */ +function approvedNewFamilyRun(recollect: () => DriftReport): RunResult { + let registrySource = fixtureRegistrySource(); + const reverted: string[] = []; + let recollectCalls = 0; + const deps: SyncCoreDeps = { + isReferenced: () => false, + isRecorded: () => false, + readRegistrySource: () => registrySource, + writeRegistrySource: (text) => { + registrySource = text; + }, + // An already-approved note for the new family — the sync applies it. + readProposalNote: () => "Decision: include\n", + writeProposalNote: () => { + throw new Error("the note already exists"); + }, + runSyncCheck: (opts) => + evaluateSyncCheck( + { + getChangedFiles: () => [MODEL_REGISTRY_REL_PATH], + runPinCheck: () => ({ ok: true, output: "logic-pin.test.ts passed" }), + recollect: () => { + recollectCalls += 1; + return recollect(); + }, + }, + opts, + ), + revertFiles: (paths) => reverted.push(...paths), + now: () => new Date("2026-08-11T06:29:00.000Z"), + }; + // A live listing that carries the whole classified set PLUS one genuinely new + // family, so the addition half fires and the deprecation half reports nothing. + const families = [...includeFamilies.gemini]; + const outcome = runDriftSyncCore( + [ + { + provider: "gemini", + liveModelIds: [ + ...families, + ...families.map((f) => `${f}-2025-01-01`), + "gemini-brand-new-family", + ], + }, + ], + deps, + ); + return { + outcome, + changesetKey: computeChangesetKey(outcome), + registrySource, + reverted, + recollectCalls, + }; +} + +function reportWithUnresolvedNewFamily(): DriftReport { + return { + timestamp: "2026-08-11T06:30:52.000Z", + generatedAt: "2026-08-11T06:30:52.000Z", + conclusion: "critical", + entries: [ + { + provider: "Google Gemini", + scenario: "live /models family canary", + builderFile: "src/responses.ts", + builderFunctions: [], + typesFile: null, + sdkShapesFile: "src/__tests__/drift/sdk-shapes.ts", + diffs: [ + { + severity: "critical", + issue: 'Unclassified model family "gemini-brand-new-family" in gemini /models', + path: "models/gemini-brand-new-family", + expected: "(family in includeFamilies ∪ excludeFamilies)", + real: "gemini-brand-new-family", + mock: "", + }, + ], + }, + ], + }; +} + +describe("negative controls — the gate still refuses a wrong edit", () => { + it("an `added` run IS gate-3-observable, so the re-collect really runs", () => { + const run = approvedNewFamilyRun(() => ({ + timestamp: "t", + conclusion: "clean", + entries: [], + })); + expect(run.outcome.outcomes.map((o) => o.action)).toContain("added"); + expect(run.recollectCalls).toBe(1); + expect(run.outcome.reason).toBe(SyncCoreReason.OK_APPLIED); + }); + + it("WRONG EDIT: an `added` run whose re-collect still reports the family -> reverted", () => { + const run = approvedNewFamilyRun(reportWithUnresolvedNewFamily); + expect(run.outcome.ok).toBe(false); + expect(run.outcome.reason).toBe(SyncCoreReason.GATE_FAILED); + expect(run.outcome.detail).toContain(SyncCheckReason.RESIDUAL_CRITICAL_DRIFT); + expect(run.reverted).toEqual([MODEL_REGISTRY_REL_PATH]); + }); + + it("WRONG EDIT: an off-allowlist file -> reverted, gate-1 never reaches the re-collect", () => { + const verdict = evaluateSyncCheck({ + getChangedFiles: () => [MODEL_REGISTRY_REL_PATH, "src/__tests__/drift/sdk-shapes.ts"], + runPinCheck: () => ({ ok: true, output: "" }), + recollect: () => { + throw new Error("gate-1 must refuse before any re-collect"); + }, + }); + expect(verdict.ok).toBe(false); + expect(verdict.reason).toBe(SyncCheckReason.OFF_ALLOWLIST_CHANGE); + }); + + it("WRONG EDIT: a moved classification pin -> refused even on the deprecation lane", () => { + const verdict = evaluateSyncCheck( + { + getChangedFiles: () => [MODEL_REGISTRY_REL_PATH], + runPinCheck: () => ({ + ok: false, + output: "FAIL logic-pin.test.ts > freezes PREVIEW_FAMILY", + }), + recollect: () => { + throw new Error("gate-2 must refuse before any re-collect"); + }, + }, + { skipRecollect: true, skipRecollectReason: "deprecation-record-only" }, + ); + expect(verdict.ok).toBe(false); + expect(verdict.reason).toBe(SyncCheckReason.PIN_CHECK_FAILED); + }); +}); diff --git a/src/__tests__/drift/ws-close-code.test.ts b/src/__tests__/drift/ws-close-code.test.ts new file mode 100644 index 00000000..f5734580 --- /dev/null +++ b/src/__tests__/drift/ws-close-code.test.ts @@ -0,0 +1,377 @@ +/** + * Regression + guard tests for the discarded WebSocket CLOSE code. + * + * The bug: the drift WS client handled an incoming CLOSE frame with a bare + * `socket.end()`, throwing away the frame's 2-byte status code and its reason + * string. A provider REFUSING a session therefore produced the exact same + * observation as a provider that accepted the socket and then said nothing — + * both surfaced only as + * + * Error: waitUntil timeout after 30000ms. Collected 0 messages: [] bodies=[] + * + * which is why a live Gemini Live failure of that shape could not be diagnosed. + * + * RED (pre-fix): `parseCloseFrame`/`WSClosedError` did not exist, and the + * refusal case below was byte-for-byte identical to the silence case. + * GREEN (post-fix): the refusal reports code + reason; the silence case still + * reports a plain timeout. + * + * These tests drive the REAL exported `connectTLSWebSocket` path against a + * local TLS server (no reimplementation of the client's framing) and use the + * real server-side `computeAcceptKey` for the upgrade, so the transport, + * handshake and frame parsing under test are the ones the live legs run. + */ +import { describe, it, expect, beforeAll, afterAll } from "vitest"; +import * as tls from "node:tls"; +import * as fs from "node:fs"; +import * as os from "node:os"; +import * as path from "node:path"; +import { execFileSync } from "node:child_process"; +import { computeAcceptKey } from "../../ws-framing.js"; +import { connectTLSWebSocket, parseCloseFrame, WSClosedError } from "./ws-providers.js"; + +// --------------------------------------------------------------------------- +// Local TLS WebSocket server +// --------------------------------------------------------------------------- + +let certDir: string; +let key: Buffer; +let cert: Buffer; + +beforeAll(() => { + certDir = fs.mkdtempSync(path.join(os.tmpdir(), "aimock-wsclose-")); + const keyPath = path.join(certDir, "key.pem"); + const certPath = path.join(certDir, "cert.pem"); + // A throwaway self-signed cert, generated per-run so no private key is ever + // committed. Node requires a subjectAltName (a CN alone is rejected). + execFileSync( + "openssl", + [ + "req", + "-x509", + "-newkey", + "rsa:2048", + "-nodes", + "-keyout", + keyPath, + "-out", + certPath, + "-days", + "1", + "-subj", + "/CN=localhost", + "-addext", + "subjectAltName=DNS:localhost,IP:127.0.0.1", + ], + { stdio: "ignore" }, + ); + key = fs.readFileSync(keyPath); + cert = fs.readFileSync(certPath); +}); + +afterAll(() => { + if (certDir) fs.rmSync(certDir, { recursive: true, force: true }); +}); + +/** An unmasked server-to-client CLOSE frame (RFC 6455 §5.5.1). */ +function serverCloseFrame(code?: number, reason = ""): Buffer { + let payload = Buffer.alloc(0); + if (code !== undefined) { + const reasonBuf = Buffer.from(reason, "utf-8"); + payload = Buffer.alloc(2 + reasonBuf.length); + payload.writeUInt16BE(code, 0); + reasonBuf.copy(payload, 2); + } + const header = Buffer.alloc(2); + header[0] = 0x88; // FIN + CLOSE + header[1] = payload.length; + return Buffer.concat([header, payload]); +} + +/** An unmasked server-to-client TEXT frame (payloads here are always < 126). */ +function serverTextFrame(text: string): Buffer { + const payload = Buffer.from(text, "utf-8"); + const header = Buffer.alloc(2); + header[0] = 0x81; // FIN + TEXT + header[1] = payload.length; + return Buffer.concat([header, payload]); +} + +interface LocalServer { + port: number; + stop: () => void; +} + +/** + * Stand up a TLS server that completes the WS upgrade and then hands the socket + * to `afterUpgrade`, which decides how the "provider" behaves. + */ +function startServer(afterUpgrade: (socket: tls.TLSSocket) => void): Promise { + return new Promise((resolve) => { + const live: tls.TLSSocket[] = []; + const server = tls.createServer({ key, cert }, (socket) => { + live.push(socket); + socket.once("data", (data: Buffer) => { + const wsKey = /sec-websocket-key:\s*(\S+)/i.exec(data.toString())?.[1] ?? ""; + socket.write( + "HTTP/1.1 101 Switching Protocols\r\n" + + "Upgrade: websocket\r\n" + + "Connection: Upgrade\r\n" + + `Sec-WebSocket-Accept: ${computeAcceptKey(wsKey)}\r\n\r\n`, + ); + afterUpgrade(socket); + }); + socket.on("error", () => { + /* the client tears sockets down mid-flight; not a test failure */ + }); + }); + server.listen(0, "127.0.0.1", () => { + const port = (server.address() as { port: number }).port; + resolve({ + port, + stop: () => { + for (const s of live) s.destroy(); + server.close(); + }, + }); + }); + }); +} + +/** Connect the real client to a local server, guaranteeing teardown. */ +async function withClient( + afterUpgrade: (socket: tls.TLSSocket) => void, + body: (ws: Awaited>) => Promise, +): Promise { + const server = await startServer(afterUpgrade); + try { + const ws = await connectTLSWebSocket("localhost", "/probe", undefined, { + port: server.port, + ca: cert, + }); + return await body(ws); + } finally { + server.stop(); + } +} + +/** The predicate `geminiLiveWS` step 2 waits on. */ +const isSetupComplete = (msg: unknown): boolean => + !!msg && typeof msg === "object" && "setupComplete" in msg; + +// --------------------------------------------------------------------------- +// parseCloseFrame +// --------------------------------------------------------------------------- + +describe("parseCloseFrame", () => { + it("extracts the status code and the UTF-8 reason", () => { + const reason = "Requested model is not supported for BidiGenerateContent."; + const payload = serverCloseFrame(1008, reason).subarray(2); + expect(parseCloseFrame(payload)).toEqual({ code: 1008, reason }); + }); + + it("returns an empty reason when the frame carries only a code", () => { + expect(parseCloseFrame(serverCloseFrame(1011).subarray(2))).toEqual({ + code: 1011, + reason: "", + }); + }); + + it("reports 1005 (no status received) for an absent payload", () => { + expect(parseCloseFrame(Buffer.alloc(0))).toEqual({ code: 1005, reason: "" }); + }); + + it("reports 1005 for a malformed 1-byte payload rather than misreading a code", () => { + // A status code is 2 bytes; one byte cannot be one. Must NOT be read as 0x03. + expect(parseCloseFrame(Buffer.from([0x03]))).toEqual({ code: 1005, reason: "" }); + }); + + it("preserves application-specific 4xxx codes", () => { + expect(parseCloseFrame(serverCloseFrame(4429, "slow down").subarray(2))).toEqual({ + code: 4429, + reason: "slow down", + }); + }); + + it("decodes a multi-byte UTF-8 reason without corrupting it", () => { + const reason = "quota dépassé — 上限"; + expect(parseCloseFrame(serverCloseFrame(1008, reason).subarray(2)).reason).toBe(reason); + }); +}); + +// --------------------------------------------------------------------------- +// The refusal-vs-silence distinction — the whole point of the fix +// --------------------------------------------------------------------------- + +describe("REGRESSION: a refused session reports WHY, a silent one still times out", () => { + const REASON = "Requested model is not supported for BidiGenerateContent."; + + it("surfaces the CLOSE code and reason when the server refuses the session", async () => { + const err = await withClient( + (socket) => setTimeout(() => socket.write(serverCloseFrame(1008, REASON)), 10), + async (ws) => { + ws.send(JSON.stringify({ setup: { model: "models/gemini-2.5-flash" } })); + return await ws.waitUntil(isSetupComplete, 2000).then( + () => null, + (e: unknown) => e, + ); + }, + ); + + expect(err).toBeInstanceOf(WSClosedError); + const closed = err as WSClosedError; + // Programmatically reachable, not just prose — a caller can classify on it. + expect(closed.code).toBe(1008); + expect(closed.reason).toBe(REASON); + // And readable by a human reading CI logs. + expect(closed.message).toContain("code=1008"); + expect(closed.message).toContain(REASON); + }); + + it("GUARD: a genuinely silent server is still reported as a timeout, never as a close", async () => { + // The server accepts the upgrade and sends nothing, ever. Collapsing this + // into a "close" would destroy the very distinction the fix exists for. + const err = await withClient( + () => { + /* silence */ + }, + async (ws) => { + ws.send(JSON.stringify({ setup: {} })); + return await ws.waitUntil(isSetupComplete, 300).then( + () => null, + (e: unknown) => e, + ); + }, + ); + + expect(err).toBeInstanceOf(Error); + expect(err).not.toBeInstanceOf(WSClosedError); + expect((err as Error).message).toContain("waitUntil timeout after 300ms"); + }); + + it("reports the close for a waitUntil that starts after the server already closed", async () => { + const err = await withClient( + (socket) => setTimeout(() => socket.write(serverCloseFrame(1011, "internal error")), 10), + async (ws) => { + // Let the close land before anyone waits on the socket. + await new Promise((r) => setTimeout(r, 150)); + return await ws.waitUntil(isSetupComplete, 2000).then( + () => null, + (e: unknown) => e, + ); + }, + ); + + expect(err).toBeInstanceOf(WSClosedError); + expect((err as WSClosedError).code).toBe(1011); + expect((err as WSClosedError).reason).toBe("internal error"); + }); +}); + +// --------------------------------------------------------------------------- +// Normal operation must be untouched +// --------------------------------------------------------------------------- + +describe("GUARD: normal operation is unchanged", () => { + it("resolves when the awaited message and the CLOSE frame arrive in one segment", async () => { + // The predicate must still win: a provider that answers and then hangs up + // is a SUCCESS, not a refusal. + const messages = await withClient( + (socket) => + setTimeout( + () => + socket.write( + Buffer.concat([ + serverTextFrame(JSON.stringify({ setupComplete: {} })), + serverCloseFrame(1000, "done"), + ]), + ), + 10, + ), + async (ws) => { + ws.send(JSON.stringify({ setup: {} })); + return await ws.waitUntil(isSetupComplete, 2000); + }, + ); + + expect(messages).toEqual([{ setupComplete: {} }]); + }); + + it("prefers a buffered satisfying message over an already-recorded close", async () => { + // A provider that answers and immediately hangs up. Both frames are already + // buffered and no waiter existed when they landed, so the FIRST thing the + // next waitUntil does decides the verdict: the answer must win over the + // close, or a successful turn would be misreported as a refusal. + const messages = await withClient( + (socket) => + setTimeout(() => { + socket.write(serverTextFrame(JSON.stringify({ setupComplete: {} }))); + socket.write(serverCloseFrame(1000, "done")); + }, 10), + async (ws) => { + ws.send(JSON.stringify({ setup: {} })); + await new Promise((r) => setTimeout(r, 150)); + return await ws.waitUntil(isSetupComplete, 2000); + }, + ); + + expect(messages).toEqual([{ setupComplete: {} }]); + }); + + it("a clean close after a satisfied predicate raises nothing", async () => { + const unhandled: unknown[] = []; + const onUnhandled = (e: unknown) => unhandled.push(e); + process.on("unhandledRejection", onUnhandled); + try { + const messages = await withClient( + (socket) => { + setTimeout( + () => socket.write(serverTextFrame(JSON.stringify({ setupComplete: {} }))), + 10, + ); + // Echo the client's CLOSE (and ONLY its CLOSE), as a well-behaved + // server would: opcode 0x8 with the client's mandatory mask bit. + socket.on("data", (frame: Buffer) => { + if (frame.length >= 1 && (frame[0] & 0x0f) === 0x8) { + socket.write(serverCloseFrame(1000)); + } + }); + }, + async (ws) => { + ws.send(JSON.stringify({ setup: {} })); + const collected = await ws.waitUntil(isSetupComplete, 2000); + ws.close(); + // Give the echoed CLOSE time to arrive and be recorded. + await new Promise((r) => setTimeout(r, 200)); + return collected; + }, + ); + + expect(messages).toEqual([{ setupComplete: {} }]); + expect(unhandled).toEqual([]); + } finally { + process.off("unhandledRejection", onUnhandled); + } + }); + + it("still collects a normal multi-message turn", async () => { + const messages = await withClient( + (socket) => + setTimeout(() => { + socket.write(serverTextFrame(JSON.stringify({ serverContent: { turnComplete: false } }))); + socket.write(serverTextFrame(JSON.stringify({ serverContent: { turnComplete: true } }))); + }, 10), + async (ws) => { + ws.send(JSON.stringify({ setup: {} })); + return await ws.waitUntil( + (m: unknown) => + (m as { serverContent?: { turnComplete?: boolean } })?.serverContent?.turnComplete === + true, + 2000, + ); + }, + ); + + expect(messages).toHaveLength(2); + }); +}); diff --git a/src/__tests__/drift/ws-providers.ts b/src/__tests__/drift/ws-providers.ts index f399e7b3..9b830aed 100644 --- a/src/__tests__/drift/ws-providers.ts +++ b/src/__tests__/drift/ws-providers.ts @@ -79,6 +79,61 @@ export class WSHandshakeError extends Error { } } +/** + * Raised by a pending {@link TLSWSClient.waitUntil} when the server closed the + * WebSocket before the awaited message arrived. + * + * This is the third failure channel, alongside the two above: the socket + * upgrades fine and the provider then REFUSES the session out-of-band, by + * sending an RFC 6455 CLOSE frame rather than an in-band error frame. The + * frame's status code and reason are the whole diagnosis — without them a + * refusal is byte-for-byte indistinguishable from a provider that accepted the + * socket and said nothing, since both end as a bare `waitUntil` timeout that + * collected zero messages. + */ +export class WSClosedError extends Error { + readonly code: number; + readonly reason: string; + + constructor(message: string, code: number, reason: string) { + super(message); + this.name = "WSClosedError"; + this.code = code; + this.reason = reason; + } +} + +/** + * Parse an RFC 6455 CLOSE frame payload into its status code and reason. + * + * Per §5.5.1 the payload is optional, and a code is 2 bytes — so an absent or + * 1-byte payload carries no code, which §7.4.1 represents as 1005 ("no status + * received"). The reason is the UTF-8 remainder, and is where a provider + * usually names the cause (e.g. an unsupported model). + */ +export function parseCloseFrame(payload: Buffer): { code: number; reason: string } { + const code = payload.length >= 2 ? payload.readUInt16BE(0) : 1005; + const reason = payload.length > 2 ? payload.subarray(2).toString("utf-8") : ""; + return { code, reason }; +} + +/** + * Render the messages a `waitUntil` had collected, for a failure message. + * Shared by the timeout and server-close paths so both report the same + * evidence: the bare type list plus (truncated) bodies, since an early `error` + * event's code/message is otherwise swallowed behind the type list. + */ +function describeCollected(collected: unknown[]): string { + const types = collected.map((m) => (m as { type?: string } | null)?.type ?? "unknown").join(", "); + let bodies = ""; + try { + bodies = ` bodies=${JSON.stringify(collected).slice(0, 800)}`; + } catch { + /* non-serializable payload; type list is enough */ + } + return `Collected ${collected.length} messages: [${types}]${bodies}`; +} + /** * Extract the numeric HTTP status code from a WS handshake's status line * (e.g. `"HTTP/1.1 401 Unauthorized"` -> `401`). Returns `null` when no @@ -206,13 +261,36 @@ function buildMaskedPongFrame(pingPayload: Buffer): Buffer { // TLS WebSocket client (RFC 6455 over TLS) // --------------------------------------------------------------------------- +/** + * Transport-level overrides for {@link connectTLSWebSocket}. + * + * Exists purely so a test can point this REAL client path at a local + * self-signed TLS server instead of a live provider. The live drift legs pass + * nothing and therefore keep the previous behaviour exactly: port 443 and the + * default system trust store. + */ +export interface TLSWSConnectOptions { + /** TLS port. Defaults to 443 — the only value the live legs use. */ + port?: number; + /** Extra trust anchors, so a local self-signed server can be verified. */ + ca?: string | Buffer | Array; +} + export function connectTLSWebSocket( host: string, path: string, headers?: Record, + options?: TLSWSConnectOptions, ): Promise { return new Promise((resolve, reject) => { - const socket = tls.connect({ host, port: 443, servername: host }, () => { + const connectOptions: tls.ConnectionOptions = { + host, + port: options?.port ?? 443, + servername: host, + }; + if (options?.ca) connectOptions.ca = options.ca; + + const socket = tls.connect(connectOptions, () => { const key = randomBytes(16).toString("base64"); const extraHeaders = headers ? Object.entries(headers) @@ -236,6 +314,10 @@ export function connectTLSWebSocket( const messages: unknown[] = []; const messageResolvers: Array<() => void> = []; let socketError: Error | null = null; + // The CLOSE frame the server sent, if any. Recorded rather than discarded + // along with the socket, so a pending (or subsequent) waitUntil can + // report WHY the provider ended the session instead of timing out. + let closeInfo: { code: number; reason: string } | null = null; // Connection-scoped cursor so successive waitUntil calls resume where the last left off let checkedUpTo = 0; @@ -290,12 +372,33 @@ export function connectTLSWebSocket( return false; }; + const rejectClosed = (info: { code: number; reason: string }) => { + reject( + new WSClosedError( + `WebSocket closed by server during waitUntil: code=${info.code} ` + + `reason=${JSON.stringify(info.reason)}. ${describeCollected(collected)}`, + info.code, + info.reason, + ), + ); + }; + // Check messages that arrived before waitUntil was called if (scanFromCursor()) { resolve(collected); return; } + // The server may already have closed before this waitUntil was + // called (e.g. a refusal that landed during the previous step). + // No further message can arrive, so report the stated reason + // now instead of waiting out the full timeout. + if (closeInfo) { + settled = true; + rejectClosed(closeInfo); + return; + } + const removeResolver = () => { const idx = messageResolvers.indexOf(check); if (idx !== -1) messageResolvers.splice(idx, 1); @@ -305,20 +408,9 @@ export function connectTLSWebSocket( if (!settled) { settled = true; removeResolver(); - const types = collected.map((m: any) => m?.type ?? "unknown").join(", "); - // Surface collected message bodies (truncated) so an early - // `error` event's code/message is visible in CI logs rather - // than swallowed behind the bare type list. - let bodies = ""; - try { - bodies = ` bodies=${JSON.stringify(collected).slice(0, 800)}`; - } catch { - /* non-serializable payload; type list is enough */ - } reject( new Error( - `waitUntil timeout after ${timeoutMs}ms. ` + - `Collected ${collected.length} messages: [${types}]${bodies}`, + `waitUntil timeout after ${timeoutMs}ms. ${describeCollected(collected)}`, ), ); } @@ -339,12 +431,40 @@ export function connectTLSWebSocket( ); return; } - // Scan all new messages since last check + // Scan all new messages since last check. + // + // The ORDER of this block relative to the close check below is + // inert here, not protective: the resolver wake sits inside the + // per-frame parse loop and fires on each TEXT frame, so an + // answer arriving in the same segment as a CLOSE has already + // settled this promise before the CLOSE frame is parsed. No + // reachable state in this function has BOTH an unscanned + // satisfying message and `closeInfo` set, so swapping the two + // blocks changes nothing observable — do not read this ordering + // as a guard. It is kept only to match the pre-check above, + // which is where the ordering IS load-bearing (a buffered + // answer plus an already-recorded close) and is covered by the + // "prefers a buffered satisfying message over an + // already-recorded close" test. + // + // The close check itself is NOT dead: a server that sends only + // a CLOSE frame leaves this scan empty, and deleting that + // branch reds the refusal regression test. if (scanFromCursor()) { settled = true; clearTimeout(timer); removeResolver(); resolve(collected); + return; + } + // A server-sent CLOSE ends the session, so the awaited message + // can never arrive. Report the code/reason rather than spin + // out the timeout and lose the diagnosis. + if (closeInfo) { + settled = true; + clearTimeout(timer); + removeResolver(); + rejectClosed(closeInfo); } }; @@ -397,8 +517,12 @@ export function connectTLSWebSocket( } for (const r of messageResolvers) r(); } else if (opcode === 0x8) { - // close frame + // close frame — keep the code/reason before ending the socket, then + // wake any pending waitUntil so it can report the stated reason. + // Socket lifecycle is deliberately unchanged: still a plain end(). + closeInfo = parseCloseFrame(framePayload); socket.end(); + for (const r of messageResolvers) r(); } else if (opcode === 0x9) { // ping — respond with pong per RFC 6455 socket.write(buildMaskedPongFrame(framePayload)); diff --git a/src/__tests__/test-drift-workflow.test.ts b/src/__tests__/test-drift-workflow.test.ts index c9ab5bf9..13616f65 100644 --- a/src/__tests__/test-drift-workflow.test.ts +++ b/src/__tests__/test-drift-workflow.test.ts @@ -371,3 +371,433 @@ describe("test-drift.yml — the drift job unpacks no bytes it has not pinned", ]); }); }); + +// --------------------------------------------------------------------------- +// A silent live surface must not read as a broken collector. +// +// The failure this guards (CopilotKit/aimock run 31571018005, PR #370): the +// Gemini Live WS legs observed nothing for 30s, the collector called that +// "unparseable output" and exited 5, and exit 5 hard-fails the base leg — so +// every bot-opened drift PR was blocked behind a manual-triage stop for a +// condition no human could triage in this repo. +// +// The collector side is fixed in scripts/drift-report-collector.ts (exit 6). What +// is asserted HERE is the half that decides whether a PR merges: the workflow's +// own routing of that exit code. Each case EXECUTES the step's real `run:` body +// with the collector stubbed to a chosen exit code, so the answer is the step's +// observed exit status, not a reading of its YAML. +// +// Both directions are pinned. Exit 6 must not fail a leg (the fix), and exit 5 +// must STILL fail it (the thing the fix must not trade away) — a routing that +// tolerates everything would turn the loud stop into a silent pass, which is the +// worse defect. +// --------------------------------------------------------------------------- + +interface LegRun { + stepExit: number; + stdio: string; + /** Whatever the step appended to GITHUB_OUTPUT. */ + output: string; +} + +/** + * EXECUTE one collector-running step's `run:` body with the collector stubbed. + * + * Only `npx` is stubbed: it writes the report the step's own `jq` then reads and + * exits with `collectorExit`. Every branch, comparison and exit in between is the + * workflow's code run as written. + */ +const observeCollectorLeg = ( + stepName: string, + job: string, + reportPath: string, + collectorExit: number, + timeouts: { + testName: string; + timeoutMs?: number; + serverClose?: { code: number; reason: string }; + }[] = [], +): LegRun => { + const dir = mkdtempSync(join(tmpdir(), "test-drift-leg-")); + try { + const bin = join(dir, "bin"); + mkdirSync(bin); + const report = JSON.stringify({ + timestamp: "2026-08-12T06:42:00.000Z", + entries: [], + ...(timeouts.length > 0 + ? { timeouts: timeouts.map((t) => ({ ...t, rawLocation: "", message: "" })) } + : {}), + }); + writeFileSync( + join(bin, "npx"), + [ + "#!/bin/sh", + `cat > ${JSON.stringify(join(dir, reportPath))} <<'REPORT'`, + report, + "REPORT", + `exit ${collectorExit}`, + ].join("\n"), + { mode: 0o755 }, + ); + const step = stepByName(stepName, job); + const script = join(dir, "step.sh"); + writeFileSync(script, step.run); + const outFile = join(dir, "gh-output"); + writeFileSync(outFile, ""); + const res = spawnSync("/bin/bash", [script], { + cwd: dir, + encoding: "utf-8", + env: { + ...process.env, + PATH: `${bin}:${process.env.PATH ?? ""}`, + GITHUB_WORKSPACE: dir, + GITHUB_OUTPUT: outFile, + LIVE_LEGS_RAN: "true", + }, + }); + return { + stepExit: res.status ?? -1, + stdio: `${res.stdout ?? ""}${res.stderr ?? ""}`, + output: readFileSync(outFile, "utf-8"), + }; + } finally { + rmSync(dir, { recursive: true, force: true }); + } +}; + +const HEAD_STEP = "Head drift report — run live on PR ref"; +const SCHEDULED_STEP = "Run drift tests"; + +describe("test-drift.yml — a silent live surface does not block a PR, and is still said out loud", () => { + it("EXECUTED: collector exit 6 does NOT fail the head leg", () => { + const run = observeCollectorLeg(HEAD_STEP, "drift-live-pr", "drift-report-head.json", 6, [ + { + testName: "Gemini Live WS drift > WS text event sequence and shapes match", + timeoutMs: 30000, + }, + ]); + expect(run.stepExit, `head leg failed on exit 6:\n${run.stdio}`).toBe(0); + }); + + it("EXECUTED: exit 6 names the surface that went silent, as a warning", () => { + const run = observeCollectorLeg(HEAD_STEP, "drift-live-pr", "drift-report-head.json", 6, [ + { testName: "Gemini Live WS drift > WS tool call event sequence matches", timeoutMs: 30000 }, + ]); + // Non-blocking is only acceptable if it is also not silent: the reader must + // learn WHICH surface stopped being graded, without opening the artifact. + expect(run.stdio).toContain("::warning title=live-timeout (head)::"); + expect(run.stdio).toContain("Gemini Live WS drift > WS tool call event sequence matches"); + expect(run.stdio).toContain("30000ms"); + }); + + it("EXECUTED NEGATIVE CONTROL: exit 5 STILL fails the head leg with the triage error", () => { + const run = observeCollectorLeg(HEAD_STEP, "drift-live-pr", "drift-report-head.json", 5); + expect(run.stepExit).toBe(5); + expect(run.stdio).toContain("quarantined unparseable output"); + }); + + it("EXECUTED NEGATIVE CONTROL: an unrecognized collector exit STILL fails the head leg", () => { + const run = observeCollectorLeg(HEAD_STEP, "drift-live-pr", "drift-report-head.json", 1); + expect(run.stepExit).toBe(1); + expect(run.stdio).toContain("Head collector faulted"); + }); + + it("EXECUTED POSITIVE CONTROL: exits 0 and 2 remain non-fatal (the routing is not 'always pass')", () => { + expect( + observeCollectorLeg(HEAD_STEP, "drift-live-pr", "drift-report-head.json", 0).stepExit, + ).toBe(0); + expect( + observeCollectorLeg(HEAD_STEP, "drift-live-pr", "drift-report-head.json", 2).stepExit, + ).toBe(0); + }); + + it("EXECUTED: the daily job survives exit 6, records it, and warns", () => { + const run = observeCollectorLeg(SCHEDULED_STEP, DRIFT_JOB, "drift-report.json", 6, [ + { + testName: "Gemini Live WS drift > WS text event sequence and shapes match", + timeoutMs: 30000, + }, + ]); + expect(run.stepExit, `daily drift step failed on exit 6:\n${run.stdio}`).toBe(0); + expect(run.stdio).toContain("::warning title=live-timeout::"); + // The exit code has to reach `notify` as job-output DATA, or the Slack branch + // that makes this loud can never fire. + expect(run.output).toContain("exit_code=6"); + }); + + it("EXECUTED NEGATIVE CONTROL: the daily job still fails on exit 5", () => { + const run = observeCollectorLeg(SCHEDULED_STEP, DRIFT_JOB, "drift-report.json", 5); + expect(run.stepExit).toBe(5); + expect(run.stdio).toContain("manual triage required"); + }); +}); + +/** + * EXECUTE the `Notify Slack` step with `curl` stubbed, and return the Slack text + * it would have posted (empty string when it posts nothing). + * + * This is the only place that answers "does a human find out". A silent surface + * that neither fails CI nor alerts is the fail-silent outcome this whole change + * has to avoid, and the exit-6 branch is the thing that prevents it — so it is + * asserted by observing the payload, not by reading the branch. + */ +const observeNotify = (env: Record): { posted: string; stepExit: number } => { + const dir = mkdtempSync(join(tmpdir(), "test-drift-notify-")); + try { + const bin = join(dir, "bin"); + mkdirSync(bin); + const postFile = join(dir, "posted"); + writeFileSync( + join(bin, "curl"), + [ + "#!/bin/sh", + 'body=""', + 'while [ $# -gt 0 ]; do case "$1" in -d) body="$2"; shift;; esac; shift; done', + `printf '%s' "$body" > ${JSON.stringify(postFile)}`, + ].join("\n"), + { mode: 0o755 }, + ); + const step = stepByName("Notify Slack", "notify"); + const script = join(dir, "step.sh"); + writeFileSync(script, step.run); + const res = spawnSync("/bin/bash", [script], { + cwd: dir, + encoding: "utf-8", + env: { + ...process.env, + PATH: `${bin}:${process.env.PATH ?? ""}`, + SLACK_WEBHOOK: "https://example.invalid/hook", + AGUI_RESULT: "success", + DRIFT_SUMMARY: "", + DRIFT_RUNS: "", + REPO: "CopilotKit/aimock", + RUN_ID: "31571018005", + ...env, + }, + }); + return { + posted: existsSync(postFile) ? readFileSync(postFile, "utf-8") : "", + stepExit: res.status ?? -1, + }; + } finally { + rmSync(dir, { recursive: true, force: true }); + } +}; + +describe("test-drift.yml — a surface that stopped being graded reaches a human", () => { + it("EXECUTED: exit 6 on a green drift job still posts to Slack", () => { + // The job PASSES on exit 6, which is precisely why the alert matters: without + // its own branch this run is good→good and the step exits without posting. + const { posted } = observeNotify({ + DRIFT_EXIT_CODE: "6", + DRIFT_RESULT: "success", + PREV: "success", + }); + expect(posted, "a silent live surface produced NO Slack message").not.toBe(""); + expect(posted).toContain("Live drift surface went silent"); + // Never as drift — nobody should go looking for a provider format change. + expect(posted).not.toContain("HTTP API drift detected"); + expect(posted).not.toContain("quarantined"); + }); + + it("EXECUTED NEGATIVE CONTROL: a genuinely quiet day still posts nothing", () => { + // If this posted, the branch above would be indistinguishable from "always + // alert", and the exit-6 assertion would prove nothing. + const { posted } = observeNotify({ + DRIFT_EXIT_CODE: "0", + DRIFT_RESULT: "success", + PREV: "success", + }); + expect(posted).toBe(""); + }); + + it("EXECUTED NEGATIVE CONTROL: exit 5 still alerts as a quarantine, not as a timeout", () => { + const { posted } = observeNotify({ + DRIFT_EXIT_CODE: "5", + DRIFT_RESULT: "failure", + PREV: "success", + }); + expect(posted).toContain("quarantined unparseable output"); + expect(posted).not.toContain("went silent"); + }); + + it("EXECUTED NEGATIVE CONTROL: real drift still alerts as real drift", () => { + const { posted } = observeNotify({ + DRIFT_EXIT_CODE: "2", + DRIFT_RESULT: "failure", + PREV: "success", + }); + expect(posted).toContain("HTTP API drift detected"); + expect(posted).not.toContain("went silent"); + }); +}); + +/** + * EXECUTE the BASE leg's own `run:` body on its fresh-live-base path. + * + * This is the step that actually failed (run 31571018005, step 7), so it gets its + * own execution rather than inheriting confidence from the head leg. Its reuse + * lookup, worktree checkout and install are stubbed; the exit-code routing is the + * workflow's code run as written. + * + * The reuse path is deliberately made to MISS, because that is the live + * situation: reuse requires a same-UTC-day `main` report with non-empty entries, + * and while main's own scheduled run is failing there is no such report — which is + * exactly why every PR ends up running a fresh live base and meeting this routing. + */ +const observeBaseLeg = ( + collectorExit: number, + timeoutTestName?: string, + serverClose?: { code: number; reason: string }, +): LegRun => { + const parent = mkdtempSync(join(tmpdir(), "test-drift-base-")); + try { + const ws = join(parent, "workspace"); + mkdirSync(ws); + const bin = join(parent, "bin"); + mkdirSync(bin); + const report = JSON.stringify({ + timestamp: "2026-08-12T06:42:00.000Z", + entries: [], + ...(timeoutTestName || serverClose + ? { + timeouts: [ + { + testName: timeoutTestName ?? "Gemini Live WS drift > WS text event sequence", + rawLocation: "", + message: "", + ...(serverClose ? { serverClose } : { timeoutMs: 30000 }), + }, + ], + } + : {}), + }); + // No same-UTC-day main report exists → empty run id → reuse is skipped. + writeFileSync(join(bin, "gh"), "#!/bin/sh\nexit 0\n", { mode: 0o755 }); + writeFileSync(join(bin, "git"), '#!/bin/sh\nmkdir -p "$3"\nexit 0\n', { mode: 0o755 }); + writeFileSync(join(bin, "pnpm"), "#!/bin/sh\nexit 0\n", { mode: 0o755 }); + writeFileSync( + join(bin, "npx"), + [ + "#!/bin/sh", + `cat > ${JSON.stringify(join(ws, "drift-report-base.json"))} <<'REPORT'`, + report, + "REPORT", + `exit ${collectorExit}`, + ].join("\n"), + { mode: 0o755 }, + ); + const step = stepByName( + "Base drift report — reuse same-UTC-day main run, else run live", + "drift-live-pr", + ); + const script = join(parent, "step.sh"); + writeFileSync(script, step.run); + const outFile = join(parent, "gh-output"); + writeFileSync(outFile, ""); + const res = spawnSync("/bin/bash", [script], { + cwd: ws, + encoding: "utf-8", + env: { + ...process.env, + PATH: `${bin}:${process.env.PATH ?? ""}`, + GITHUB_WORKSPACE: ws, + GITHUB_OUTPUT: outFile, + LIVE_LEGS_RAN: "true", + REPO: "CopilotKit/aimock", + GH_TOKEN: "stub", + }, + }); + return { + stepExit: res.status ?? -1, + stdio: `${res.stdout ?? ""}${res.stderr ?? ""}`, + output: readFileSync(outFile, "utf-8"), + }; + } finally { + rmSync(parent, { recursive: true, force: true }); + } +}; + +describe("test-drift.yml — the base leg that blocked every drift PR", () => { + it("EXECUTED RED→GREEN: a silent live surface on main no longer fails the base leg", () => { + // Before the fix this exact condition arrived as exit 5 and the step died on + // "Base collector quarantined unparseable output — manual triage required". + const run = observeBaseLeg(6, "Gemini Live WS drift > WS text event sequence and shapes match"); + expect(run.stepExit, `base leg failed on exit 6:\n${run.stdio}`).toBe(0); + expect(run.stdio).toContain("::warning title=live-timeout (base)::"); + expect(run.stdio).toContain("Gemini Live WS drift > WS text event sequence and shapes match"); + // The leg still reports how the base was obtained, so the delta step is wired. + expect(run.output).toContain("reused=false"); + }); + + it("EXECUTED NEGATIVE CONTROL: genuinely unparseable base output STILL stops the leg", () => { + const run = observeBaseLeg(5); + expect(run.stepExit).toBe(5); + expect(run.stdio).toContain("manual triage required"); + }); + + it("EXECUTED NEGATIVE CONTROL: an unrecognized base exit STILL stops the leg", () => { + const run = observeBaseLeg(1); + expect(run.stepExit).toBe(1); + expect(run.stdio).toContain("Base collector faulted"); + }); + + it("EXECUTED POSITIVE CONTROL: base exits 0 and 2 stay non-fatal", () => { + expect(observeBaseLeg(0).stepExit).toBe(0); + expect(observeBaseLeg(2).stepExit).toBe(0); + }); +}); + +// --------------------------------------------------------------------------- +// A hang-up and a silence are both exit 6, so the ANNOTATION is the only place a +// reader can tell them apart. `fix/ws-preserve-close-code` makes a server close +// report its code, and a run that says "no messages in nullms" would be worse +// than the silence it replaced — so the rendering is executed, not read. +// --------------------------------------------------------------------------- + +describe("test-drift.yml — a hang-up is annotated as a close, not as a timeout", () => { + it("EXECUTED: a serverClose entry names the close code, and never renders null", () => { + const run = observeCollectorLeg(HEAD_STEP, "drift-live-pr", "drift-report-head.json", 6, [ + { + testName: "Gemini Live WS drift > WS text event sequence and shapes match", + serverClose: { code: 1011, reason: "internal error" }, + }, + ]); + expect(run.stepExit, `head leg failed on a hang-up:\n${run.stdio}`).toBe(0); + expect(run.stdio).toContain("session closed by the server (code 1011)"); + // The failure mode of a naive template: `\(.timeoutMs)` on an absent field. + expect(run.stdio).not.toContain("nullms"); + expect(run.stdio).not.toContain("no messages in null"); + }); + + it("EXECUTED: a silence entry still renders its wait budget", () => { + // The other branch of the same template must not regress. + const run = observeCollectorLeg(HEAD_STEP, "drift-live-pr", "drift-report-head.json", 6, [ + { testName: "Gemini Live WS drift > WS tool call event sequence matches", timeoutMs: 30000 }, + ]); + expect(run.stepExit).toBe(0); + expect(run.stdio).toContain("no messages in 30000ms"); + expect(run.stdio).not.toContain("session closed by the server"); + }); + + it("EXECUTED: the daily job renders a hang-up the same way", () => { + const run = observeCollectorLeg(SCHEDULED_STEP, DRIFT_JOB, "drift-report.json", 6, [ + { + testName: "Gemini Live WS drift > WS text event sequence and shapes match", + serverClose: { code: 1012, reason: "restarting" }, + }, + ]); + expect(run.stepExit).toBe(0); + expect(run.stdio).toContain("session closed by the server (code 1012)"); + expect(run.stdio).not.toContain("nullms"); + expect(run.output).toContain("exit_code=6"); + }); + + it("EXECUTED: the base leg renders a hang-up the same way", () => { + const run = observeBaseLeg(6, undefined, { code: 1011, reason: "internal error" }); + expect(run.stepExit, `base leg failed on a hang-up:\n${run.stdio}`).toBe(0); + expect(run.stdio).toContain("session closed by the server (code 1011)"); + expect(run.stdio).not.toContain("nullms"); + }); +});