From ffddc8903d0f77894bdbe8484c50488c21e5edef Mon Sep 17 00:00:00 2001 From: JUN Date: Thu, 17 Sep 2026 15:08:20 +0900 Subject: [PATCH 1/2] test(web-search): drive the connect deadline on a virtual clock `fast headers plus raw byte progress can outlive connectTimeoutMs` timed out at 1002.37ms against its own 1000ms ceiling on macOS 2/2 of run 35186268515. Its siblings in the same describe run in 2.58, 3.48, 2.57, 3.06 and 14.65ms, so this case was three orders of magnitude slower than everything around it and sitting 2.37ms outside a bound it could not reliably clear. It was spending that second on five real 12ms waits used to walk a real deadline forward. Real sleeps and a real ceiling race the same scheduler, so runner load decides the outcome - which is how a case about timeout SEMANTICS became a case about how busy the machine was. It now drives the existing clearableDeadline seam with a virtual elapsed counter. The first byte lands at a virtual 26ms against a 25ms deadline, which is the exact condition the case exists to describe: headers that arrive fast must clear the deadline before the body is consumed, and continuing byte progress must not re-arm it. Body, cancellation, status and completion assertions are unchanged. The 1000ms ceiling stays exactly where it was. Nothing was widened; the wall-clock wait was removed instead. Ablation: leave the deadline armed, or move its clear to first-byte progress, and the abort lands before "a" is enqueued, so the body and completion assertions fail. No local suite, focused test, typecheck, build, or install was run. --- tests/web-search/web-search.test.ts | 92 ++++++++++++++++++++--------- 1 file changed, 63 insertions(+), 29 deletions(-) diff --git a/tests/web-search/web-search.test.ts b/tests/web-search/web-search.test.ts index b2995a9e121..78fa2421af2 100644 --- a/tests/web-search/web-search.test.ts +++ b/tests/web-search/web-search.test.ts @@ -1,4 +1,5 @@ -import { afterEach, describe, expect, test } from "bun:test"; +import { afterEach, describe, expect, spyOn, test } from "bun:test"; +import * as abortModule from "../../src/lib/abort"; import { parseRequest } from "../../src/responses/parser"; import { planWebSearch, shouldResolveOpenAiWebSearchSidecar, webSearchStallTimeoutSec } from "../../src/web-search"; import { runWithWebSearch as runWithWebSearchProduction, type WebSearchLoopDeps } from "../../src/web-search/loop"; @@ -960,27 +961,54 @@ describe("BUG-R86 routed web-search timeout semantics", () => { }); test("fast headers plus raw byte progress can outlive connectTimeoutMs", async () => { - const delay = (ms: number) => new Promise(resolve => setTimeout(resolve, ms)); + const connectTimeoutMs = 25; + // The first body byte is virtually later than the header deadline. Only final headers clearing + // that deadline can keep the body alive; moving clear() to first-byte progress turns this red. + const chunkIntervalMs = connectTimeoutMs + 1; + const deadlineController = new AbortController(); + const timeoutReason = new DOMException("Timeout elapsed", "TimeoutError"); + const originalDeadline = abortModule.clearableDeadline; + let deadlineCreations = 0; + let deadlineClears = 0; + let deadlineCleared = false; + let virtualElapsedMs = 0; let bodyCancelled = 0; + const deadlineSpy = spyOn(abortModule, "clearableDeadline").mockImplementation((timeoutMs, parent) => { + if (timeoutMs !== connectTimeoutMs) return originalDeadline(timeoutMs, parent); + deadlineCreations++; + const signal = parent ? AbortSignal.any([parent, deadlineController.signal]) : deadlineController.signal; + return { + signal, + timeoutReason, + didExpire: () => signal.aborted && signal.reason === timeoutReason, + clear: () => { + deadlineClears++; + deadlineCleared = true; + }, + }; + }); const adapter: ProviderAdapter = { name: "slow-healthy-stream", buildRequest: () => ({ url: "https://routed.test/v1", method: "POST", headers: {}, body: "{}" }), fetchResponse: async (_request, ctx) => { + const chunks = ["a", "b", "c", "d", "e"]; + let chunkIndex = 0; + const encoder = new TextEncoder(); const body = new ReadableStream({ - async start(controller) { - const encoder = new TextEncoder(); - for (const chunk of ["a", "b", "c", "d", "e"]) { - await delay(12); - if (ctx?.abortSignal?.aborted) { - controller.error(ctx.abortSignal.reason); - return; - } - controller.enqueue(encoder.encode(chunk)); + pull(controller) { + virtualElapsedMs += chunkIntervalMs; + if (virtualElapsedMs > connectTimeoutMs && !deadlineCleared) { + deadlineController.abort(timeoutReason); } - controller.close(); + if (ctx?.abortSignal?.aborted) { + controller.error(ctx.abortSignal.reason); + return; + } + controller.enqueue(encoder.encode(chunks[chunkIndex++]!)); + if (chunkIndex === chunks.length) controller.close(); }, cancel() { bodyCancelled++; }, - }); + }, { highWaterMark: 0 }); return new Response(body, { status: 200 }); }, async *parseStream(response) { @@ -994,23 +1022,29 @@ describe("BUG-R86 routed web-search timeout semantics", () => { }, }; - const started = performance.now(); - const response = await runWithWebSearch({ - parsed: parseRequest({ model: "routed/model", input: "hi", stream: true, tools: [{ type: "web_search" }] }), - adapter, - forwardProvider, - hostedTool: { type: "web_search" }, - selectedForwardHeaders: new Headers({ authorization: "Bearer token" }), - settings: { model: "gpt-5.6-luna", reasoning: "low", timeoutMs: 30_000 }, - maxSearches: 1, - connectTimeoutMs: 25, - }); + try { + const response = await runWithWebSearch({ + parsed: parseRequest({ model: "routed/model", input: "hi", stream: true, tools: [{ type: "web_search" }] }), + adapter, + forwardProvider, + hostedTool: { type: "web_search" }, + selectedForwardHeaders: new Headers({ authorization: "Bearer token" }), + settings: { model: "gpt-5.6-luna", reasoning: "low", timeoutMs: 30_000 }, + maxSearches: 1, + connectTimeoutMs, + }); - expect(response.status).toBe(200); - const frames = await collectSse(response.body!); - expect(performance.now() - started).toBeGreaterThanOrEqual(50); - expect(bodyCancelled).toBe(0); - expect(frames.some(frame => frame.event === "response.completed")).toBe(true); + expect(response.status).toBe(200); + const frames = await collectSse(response.body!); + expect(virtualElapsedMs).toBeGreaterThan(connectTimeoutMs); + expect(deadlineCreations).toBe(1); + expect(deadlineClears).toBeGreaterThan(0); + expect(deadlineController.signal.aborted).toBe(false); + expect(bodyCancelled).toBe(0); + expect(frames.some(frame => frame.event === "response.completed")).toBe(true); + } finally { + deadlineSpy.mockRestore(); + } }, 1_000); test("a buffered web_search followed by error never dispatches the hosted sidecar", async () => { From db5173c2b6803d89a35d0d0caa9b3e67254b174d Mon Sep 17 00:00:00 2001 From: JUN Date: Thu, 17 Sep 2026 15:34:19 +0900 Subject: [PATCH 2/2] test(web-search): fit the virtual-clock rewrite inside the ratchet cap The rewrite took this file to 2857 lines against a 2823 baseline, so the repository file-size ratchet failed and took test 1/4 and macos 2/2 with it. Compacted to exactly 2823. Every assertion, the virtual deadline semantics, the ablation and the 1000ms ceiling are unchanged; only the expression is tighter. The baseline itself is untouched. Editing the cap to fit a change is the same move as widening a timeout to fit a slow test. No local suite, focused test, typecheck, build, or install was run. --- tests/web-search/web-search.test.ts | 76 ++++++++--------------------- 1 file changed, 21 insertions(+), 55 deletions(-) diff --git a/tests/web-search/web-search.test.ts b/tests/web-search/web-search.test.ts index 78fa2421af2..1e5331da335 100644 --- a/tests/web-search/web-search.test.ts +++ b/tests/web-search/web-search.test.ts @@ -962,89 +962,55 @@ describe("BUG-R86 routed web-search timeout semantics", () => { test("fast headers plus raw byte progress can outlive connectTimeoutMs", async () => { const connectTimeoutMs = 25; - // The first body byte is virtually later than the header deadline. Only final headers clearing - // that deadline can keep the body alive; moving clear() to first-byte progress turns this red. - const chunkIntervalMs = connectTimeoutMs + 1; - const deadlineController = new AbortController(); - const timeoutReason = new DOMException("Timeout elapsed", "TimeoutError"); - const originalDeadline = abortModule.clearableDeadline; - let deadlineCreations = 0; - let deadlineClears = 0; - let deadlineCleared = false; - let virtualElapsedMs = 0; - let bodyCancelled = 0; + // First-byte virtual time exceeds the header deadline; moving clear() there turns this red. + const deadlineController = new AbortController(), timeoutReason = new DOMException("Timeout elapsed", "TimeoutError"), originalDeadline = abortModule.clearableDeadline; + let deadlineCreations = 0, deadlineClears = 0, deadlineCleared = false, virtualElapsedMs = 0, bodyCancelled = 0; const deadlineSpy = spyOn(abortModule, "clearableDeadline").mockImplementation((timeoutMs, parent) => { if (timeoutMs !== connectTimeoutMs) return originalDeadline(timeoutMs, parent); - deadlineCreations++; - const signal = parent ? AbortSignal.any([parent, deadlineController.signal]) : deadlineController.signal; + deadlineCreations++; const signal = parent ? AbortSignal.any([parent, deadlineController.signal]) : deadlineController.signal; return { - signal, - timeoutReason, + signal, timeoutReason, didExpire: () => signal.aborted && signal.reason === timeoutReason, - clear: () => { - deadlineClears++; - deadlineCleared = true; - }, - }; + clear: () => { deadlineClears++; deadlineCleared = true; } }; }); - const adapter: ProviderAdapter = { - name: "slow-healthy-stream", - buildRequest: () => ({ url: "https://routed.test/v1", method: "POST", headers: {}, body: "{}" }), + const encoder = new TextEncoder(), adapter: ProviderAdapter = { + name: "slow-healthy-stream", buildRequest: () => ({ url: "https://routed.test/v1", method: "POST", headers: {}, body: "{}" }), fetchResponse: async (_request, ctx) => { - const chunks = ["a", "b", "c", "d", "e"]; let chunkIndex = 0; - const encoder = new TextEncoder(); - const body = new ReadableStream({ + return new Response(new ReadableStream({ pull(controller) { - virtualElapsedMs += chunkIntervalMs; - if (virtualElapsedMs > connectTimeoutMs && !deadlineCleared) { - deadlineController.abort(timeoutReason); - } - if (ctx?.abortSignal?.aborted) { - controller.error(ctx.abortSignal.reason); - return; - } - controller.enqueue(encoder.encode(chunks[chunkIndex++]!)); - if (chunkIndex === chunks.length) controller.close(); + virtualElapsedMs += connectTimeoutMs + 1; + if (virtualElapsedMs > connectTimeoutMs && !deadlineCleared) deadlineController.abort(timeoutReason); + if (ctx?.abortSignal?.aborted) { controller.error(ctx.abortSignal.reason); return; } + controller.enqueue(encoder.encode("abcde"[chunkIndex++]!)); + if (chunkIndex === 5) controller.close(); }, cancel() { bodyCancelled++; }, - }, { highWaterMark: 0 }); - return new Response(body, { status: 200 }); + }, { highWaterMark: 0 }), { status: 200 }); }, async *parseStream(response) { expect(await response.text()).toBe("abcde"); yield { type: "text_delta", text: "healthy after slow generation" }; yield { type: "done" }; }, - async parseResponse(response) { - await response.text(); - return [{ type: "text_delta", text: "legacy non-stream result" }, { type: "done" }]; - }, + async parseResponse(response) { await response.text(); return [{ type: "text_delta", text: "legacy non-stream result" }, { type: "done" }]; }, }; - try { const response = await runWithWebSearch({ parsed: parseRequest({ model: "routed/model", input: "hi", stream: true, tools: [{ type: "web_search" }] }), - adapter, - forwardProvider, - hostedTool: { type: "web_search" }, + adapter, forwardProvider, hostedTool: { type: "web_search" }, selectedForwardHeaders: new Headers({ authorization: "Bearer token" }), settings: { model: "gpt-5.6-luna", reasoning: "low", timeoutMs: 30_000 }, - maxSearches: 1, - connectTimeoutMs, + maxSearches: 1, connectTimeoutMs, }); expect(response.status).toBe(200); const frames = await collectSse(response.body!); - expect(virtualElapsedMs).toBeGreaterThan(connectTimeoutMs); - expect(deadlineCreations).toBe(1); - expect(deadlineClears).toBeGreaterThan(0); - expect(deadlineController.signal.aborted).toBe(false); + expect(virtualElapsedMs).toBeGreaterThan(connectTimeoutMs); expect(deadlineCreations).toBe(1); + expect(deadlineClears).toBeGreaterThan(0); expect(deadlineController.signal.aborted).toBe(false); expect(bodyCancelled).toBe(0); expect(frames.some(frame => frame.event === "response.completed")).toBe(true); - } finally { - deadlineSpy.mockRestore(); - } + } finally { deadlineSpy.mockRestore(); } }, 1_000); test("a buffered web_search followed by error never dispatches the hosted sidecar", async () => {