diff --git a/devlog/_plan/260906_release_244_followups/033_web_search_deadline_fixture.md b/devlog/_plan/260906_release_244_followups/033_web_search_deadline_fixture.md new file mode 100644 index 0000000000..d67cca89f6 --- /dev/null +++ b/devlog/_plan/260906_release_244_followups/033_web_search_deadline_fixture.md @@ -0,0 +1,24 @@ +# Check-phase cumulative deadline fixture repair + +CI34016017020 passed Kiro checks but macOS1 failed an unrelated elapsed <500ms +assertion (644ms) in web-search-timeout-contract.test.ts. The contract uses a +45ms response-header deadline; the wall measurement also includes preparation +and host scheduling. Source still starts one deadline before the rotation loop +and does not await the first response body's cancellation promise. + +Modify only that test file. For this one cancellation/rotation case, spy on the +existing clearableDeadline export and provide a controlled original deadline. +Hold the body-cancel promise until fixture cleanup; queue controlled expiry at the +next timer task when cancellation is requested. The immediate rotated fetch must +record that cancellation is still pending and that the same signal is unexpired. +This catches an added timer wait as well as awaiting the broken cancellation. +Assert one deadline factory call, +one real rotated fetch, cancellation/rotation/expiry ordering, cleanup and the +same exact504 response. Keep the existing1000ms test timeout unchanged. + +The real-timer header-timeout and abort-library tests stay unchanged. The fixture +tests deadline ownership and nonblocking cancellation rather than a loaded host's +wall time. Restore the spy and release/abort controlled resources in both finally +and afterEach, including a failing or timed-out test. No production timeout, +retry, skip or local suite is introduced. Verify by independent review and fresh +hosted CI in a separate prerequisite test-only PR beneath Kiro. diff --git a/tests/web-search/web-search-timeout-contract.test.ts b/tests/web-search/web-search-timeout-contract.test.ts index d1ab2c8f67..83d1c63f5f 100644 --- a/tests/web-search/web-search-timeout-contract.test.ts +++ b/tests/web-search/web-search-timeout-contract.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 type { AdapterFetchContext, ProviderAdapter } from "../../src/adapters/base"; import { parseRequest } from "../../src/responses/parser"; import { responseWithDeferredRequestLog, type RequestLogEntry } from "../../src/server"; @@ -19,8 +20,11 @@ function runWithWebSearch( } const originalFetch = globalThis.fetch; +let cleanupDeadlineFixture: (() => void) | undefined; afterEach(() => { + cleanupDeadlineFixture?.(); + cleanupDeadlineFixture = undefined; globalThis.fetch = originalFetch; }); @@ -362,6 +366,47 @@ describe("web-search timeout runtime contracts", () => { let firstSignal: AbortSignal | undefined; let cancelCalls = 0; let rotations = 0; + let rotatedFetches = 0; + let deadlineCreations = 0; + let deadlineClears = 0; + let cancelSettled = false; + let releaseCancel!: () => void; + const cancelGate = new Promise(resolve => { releaseCancel = resolve; }) + .then(() => { cancelSettled = true; }); + const events: string[] = []; + const deadlineController = new AbortController(); + const timeoutReason = new DOMException("Timeout elapsed", "TimeoutError"); + let expiryTimer: ReturnType | undefined; + let deadlineCleared = false; + const originalDeadline = abortModule.clearableDeadline; + 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; + events.push("deadline-cleared"); + if (expiryTimer !== undefined) clearTimeout(expiryTimer); + expiryTimer = undefined; + }, + }; + }); + let cleaned = false; + const cleanup = () => { + if (cleaned) return; + cleaned = true; + if (expiryTimer !== undefined) clearTimeout(expiryTimer); + expiryTimer = undefined; + releaseCancel(); + deadlineController.abort(timeoutReason); + deadlineSpy.mockRestore(); + }; + cleanupDeadlineFixture = cleanup; const firstAdapter: ProviderAdapter = { name: "rate-limited-never-cancelled", buildRequest: () => ({ url: "https://routed.test/v1", method: "POST", headers: {}, body: "{}" }), @@ -370,7 +415,15 @@ describe("web-search timeout runtime contracts", () => { return new Response(new ReadableStream({ cancel() { cancelCalls++; - return new Promise(() => {}); + events.push("cancel-requested"); + // Expire on the next timer task, after immediate rotation microtasks. + // An added timer wait or an awaited cancel cannot get a fresh budget. + if (!deadlineCleared) expiryTimer = setTimeout(() => { + expiryTimer = undefined; + events.push("deadline-expired"); + deadlineController.abort(timeoutReason); + }, 0); + return cancelGate; }, }), { status: 429 }); }, @@ -381,32 +434,47 @@ describe("web-search timeout runtime contracts", () => { name: "rotated-header-hang", buildRequest: () => ({ url: "https://routed.test/v1", method: "POST", headers: {}, body: "{}" }), fetchResponse: (_request, ctx) => { + rotatedFetches++; + expect(firstSignal).toBeDefined(); expect(ctx?.abortSignal).toBe(firstSignal); + expect(ctx?.abortSignal?.aborted).toBe(false); + expect(cancelCalls).toBe(1); + expect(cancelSettled).toBe(false); + events.push("rotated-fetch"); return hangingFetch(ctx); }, async *parseStream() { yield { type: "done" }; }, async parseResponse() { return [{ type: "done" }]; }, }; - const started = performance.now(); - const response = await runWithWebSearch(deps(firstAdapter, { - connectTimeoutMs, - on429: () => { - rotations++; - return rotatedAdapter; - }, - })); - - expect(performance.now() - started).toBeLessThan(500); - expect(cancelCalls).toBe(1); - expect(rotations).toBe(1); - expect(response.status).toBe(504); - expect(await response.json()).toEqual({ - error: { - message: `Provider response-header timeout after ${connectTimeoutMs}ms during web-search`, - type: "upstream_error", - code: null, - }, - }); + try { + const response = await runWithWebSearch(deps(firstAdapter, { + connectTimeoutMs, + on429: () => { + rotations++; + return rotatedAdapter; + }, + })); + + expect(cancelCalls).toBe(1); + expect(cancelSettled).toBe(false); + expect(rotations).toBe(1); + expect(rotatedFetches).toBe(1); + expect(deadlineCreations).toBe(1); + expect(deadlineClears).toBe(1); + expect(firstSignal?.reason).toBe(timeoutReason); + expect(events).toEqual(["cancel-requested", "rotated-fetch", "deadline-expired", "deadline-cleared"]); + expect(response.status).toBe(504); + expect(await response.json()).toEqual({ + error: { + message: `Provider response-header timeout after ${connectTimeoutMs}ms during web-search`, + type: "upstream_error", + code: null, + }, + }); + } finally { + cleanup(); + if (cleanupDeadlineFixture === cleanup) cleanupDeadlineFixture = undefined; + } }, 1_000); });