From f351961173310e75d26535a6c4e2e529a66c5540 Mon Sep 17 00:00:00 2001 From: Kevin Lin Date: Tue, 28 Apr 2026 11:36:10 -0700 Subject: [PATCH] fix: log fetch timeout aborts (#73692) * fix: log fetch timeout aborts * fix: redact relative timeout urls --- src/infra/net/fetch-guard.ts | 2 + src/utils/fetch-timeout.test.ts | 81 +++++++++++++++++++++++++++++++++ src/utils/fetch-timeout.ts | 77 ++++++++++++++++++++++++++++++- 3 files changed, 158 insertions(+), 2 deletions(-) create mode 100644 src/utils/fetch-timeout.test.ts diff --git a/src/infra/net/fetch-guard.ts b/src/infra/net/fetch-guard.ts index fd2ddb6a150..9851b62d18b 100644 --- a/src/infra/net/fetch-guard.ts +++ b/src/infra/net/fetch-guard.ts @@ -318,6 +318,8 @@ export async function fetchWithSsrFGuard(params: GuardedFetchOptions): Promise vi.fn()); + +vi.mock("../logging/subsystem.js", () => ({ + createSubsystemLogger: vi.fn(() => ({ + warn, + })), +})); + +import { buildTimeoutAbortSignal } from "./fetch-timeout.js"; + +describe("buildTimeoutAbortSignal", () => { + beforeEach(() => { + warn.mockClear(); + vi.useFakeTimers(); + }); + + afterEach(() => { + vi.useRealTimers(); + }); + + it("logs when its own timeout aborts the signal", async () => { + const { signal, cleanup } = buildTimeoutAbortSignal({ + timeoutMs: 25, + operation: "unit-test", + url: "https://user:pass@example.com/v1/responses?api-key=secret#fragment", + }); + + await vi.advanceTimersByTimeAsync(25); + + expect(signal?.aborted).toBe(true); + expect(warn).toHaveBeenCalledTimes(1); + expect(warn).toHaveBeenCalledWith( + "fetch timeout reached; aborting operation", + expect.objectContaining({ + timeoutMs: 25, + operation: "unit-test", + url: "https://example.com/v1/responses", + }), + ); + + cleanup(); + }); + + it("strips query strings and hashes from relative timeout URL logs", async () => { + const { cleanup } = buildTimeoutAbortSignal({ + timeoutMs: 25, + operation: "unit-test", + url: "/api/responses?api-key=secret#fragment", + }); + + await vi.advanceTimersByTimeAsync(25); + + expect(warn).toHaveBeenCalledWith( + "fetch timeout reached; aborting operation", + expect.objectContaining({ + url: "/api/responses", + }), + ); + + cleanup(); + }); + + it("does not log when a parent signal aborts first", async () => { + const parent = new AbortController(); + const { signal, cleanup } = buildTimeoutAbortSignal({ + timeoutMs: 25, + signal: parent.signal, + operation: "unit-test", + }); + + parent.abort(); + await vi.advanceTimersByTimeAsync(25); + + expect(signal?.aborted).toBe(true); + expect(warn).not.toHaveBeenCalled(); + + cleanup(); + }); +}); diff --git a/src/utils/fetch-timeout.ts b/src/utils/fetch-timeout.ts index d0ddc01d4b2..16d5f30d916 100644 --- a/src/utils/fetch-timeout.ts +++ b/src/utils/fetch-timeout.ts @@ -1,3 +1,16 @@ +import { createSubsystemLogger } from "../logging/subsystem.js"; + +const log = createSubsystemLogger("fetch-timeout"); +const LOG_URL_MAX_CHARS = 500; +const URL_SECRET_SUFFIX_PATTERN = /[?#]/; + +type TimeoutAbortSignalParams = { + timeoutMs?: number; + signal?: AbortSignal; + operation?: string; + url?: string; +}; + /** * Relay abort without forwarding the Event argument as the abort reason. * Using .bind() avoids closure scope capture (memory leak prevention). @@ -11,7 +24,56 @@ export function bindAbortRelay(controller: AbortController): () => void { return relayAbort.bind(controller); } -export function buildTimeoutAbortSignal(params: { timeoutMs?: number; signal?: AbortSignal }): { +function sanitizeTimeoutLogUrl(rawUrl: string | undefined): string | undefined { + const trimmed = rawUrl?.trim(); + if (!trimmed) { + return undefined; + } + try { + const parsed = new URL(trimmed); + parsed.username = ""; + parsed.password = ""; + parsed.search = ""; + parsed.hash = ""; + const value = parsed.toString(); + return value.length > LOG_URL_MAX_CHARS ? `${value.slice(0, LOG_URL_MAX_CHARS)}...` : value; + } catch { + const withoutQueryOrHash = trimmed.split(URL_SECRET_SUFFIX_PATTERN, 1)[0] ?? ""; + const cleaned = withoutQueryOrHash + .replace(/[\r\n\u2028\u2029]+/g, " ") + .replace(/\p{Cc}+/gu, " ") + .replace(/\s+/g, " ") + .trim(); + if (!cleaned) { + return undefined; + } + return cleaned.length > LOG_URL_MAX_CHARS + ? `${cleaned.slice(0, LOG_URL_MAX_CHARS)}...` + : cleaned; + } +} + +function abortDueToTimeout( + controller: AbortController, + timeoutMs: number, + startedAtMs: number, + operation?: string, + url?: string, +) { + if (controller.signal.aborted) { + return; + } + const sanitizedUrl = sanitizeTimeoutLogUrl(url); + log.warn("fetch timeout reached; aborting operation", { + timeoutMs, + elapsedMs: Math.max(0, Date.now() - startedAtMs), + ...(operation ? { operation } : {}), + ...(sanitizedUrl ? { url: sanitizedUrl } : {}), + }); + controller.abort(); +} + +export function buildTimeoutAbortSignal(params: TimeoutAbortSignalParams): { signal?: AbortSignal; cleanup: () => void; } { @@ -24,7 +86,16 @@ export function buildTimeoutAbortSignal(params: { timeoutMs?: number; signal?: A } const controller = new AbortController(); - const timeoutId = setTimeout(controller.abort.bind(controller), timeoutMs); + const normalizedTimeoutMs = Math.max(1, Math.floor(timeoutMs)); + const timeoutId = setTimeout( + abortDueToTimeout, + normalizedTimeoutMs, + controller, + normalizedTimeoutMs, + Date.now(), + params.operation, + params.url, + ); const onAbort = bindAbortRelay(controller); if (signal) { if (signal.aborted) { @@ -63,6 +134,8 @@ export async function fetchWithTimeout( ): Promise { const { signal, cleanup } = buildTimeoutAbortSignal({ timeoutMs: Math.max(1, timeoutMs), + operation: "fetchWithTimeout", + url, }); try { return await fetchFn(url, { ...init, signal });