diff --git a/.env.example b/.env.example index 8cd6ad6669..2057468364 100644 --- a/.env.example +++ b/.env.example @@ -1664,6 +1664,7 @@ CURSOR_USER_AGENT="Cursor/3.4" # ── TLS client (wreq-js fingerprint proxy) ── # TLS_CLIENT_TIMEOUT_MS=600000 # Inherits from FETCH_TIMEOUT_MS by default +# TLS_FIRST_BYTE_WATCHDOG_MS=10000 # #12656: bounds time-to-first-byte on the wreq body (0 disables) # ── API Bridge (/v1 proxy server) ── # API_BRIDGE_PROXY_TIMEOUT_MS=600000 # Proxy hop timeout (default: 10min) diff --git a/changelog.d/fixes/12656-tls-wreq-first-byte-watchdog.md b/changelog.d/fixes/12656-tls-wreq-first-byte-watchdog.md new file mode 100644 index 0000000000..6adb30b64f --- /dev/null +++ b/changelog.d/fixes/12656-tls-wreq-first-byte-watchdog.md @@ -0,0 +1 @@ +- fix(sse): add first-byte watchdog to the TLS-fingerprint transport so a stalled wreq body falls back instead of hanging for minutes (#12656) diff --git a/docs/reference/ENVIRONMENT.md b/docs/reference/ENVIRONMENT.md index 02894977d0..f65fc824d9 100644 --- a/docs/reference/ENVIRONMENT.md +++ b/docs/reference/ENVIRONMENT.md @@ -735,6 +735,7 @@ REQUEST_TIMEOUT_MS (global override) │ ├─→ FETCH_HEADERS_TIMEOUT_MS (inherits from FETCH_TIMEOUT_MS) │ ├─→ FETCH_BODY_TIMEOUT_MS (inherits from FETCH_TIMEOUT_MS) │ ├─→ TLS_CLIENT_TIMEOUT_MS (inherits from FETCH_TIMEOUT_MS) +│ │ └── TLS_FIRST_BYTE_WATCHDOG_MS (independent, default: 10000) │ ├── FETCH_CONNECT_TIMEOUT_MS (independent, default: 30000) │ └── FETCH_KEEPALIVE_TIMEOUT_MS (independent, default: 4000) ├─→ STREAM_IDLE_TIMEOUT_MS (inherits from REQUEST_TIMEOUT_MS, default: 600000) @@ -772,6 +773,7 @@ REQUEST_TIMEOUT_MS (global override) | `FETCH_CONNECT_TIMEOUT_MS` | `30000` | TCP connection establishment timeout. | | `FETCH_KEEPALIVE_TIMEOUT_MS` | `4000` | Keep-alive socket idle timeout. | | `TLS_CLIENT_TIMEOUT_MS` | = `FETCH_TIMEOUT_MS` | TLS fingerprint proxy (wreq-js) timeout. | +| `TLS_FIRST_BYTE_WATCHDOG_MS` | `10000` | Bounds time-to-first-byte on the wreq-js TLS-fingerprint transport's body specifically; `TLS_CLIENT_TIMEOUT_MS` alone cannot catch a stalled body since it resolves as soon as headers arrive (#12656). A timeout cancels the wreq reader and falls back to the direct/proxy dispatcher; `0` disables the watchdog. | | `API_BRIDGE_PROXY_TIMEOUT_MS` | `30000` | Proxy hop timeout for `/v1` bridge requests. | | `FIRECRAWL_BASE_URL` | `https://api.firecrawl.dev` | Point the Firecrawl web-fetch executor at a self-hosted instance (API key optional off-cloud). | | `FIRECRAWL_TIMEOUT_MS` | `30000` | Per-request timeout for the Firecrawl web-fetch executor. | diff --git a/docs/security/STEALTH_GUIDE.md b/docs/security/STEALTH_GUIDE.md index 767eb90a0b..78284ff37f 100644 --- a/docs/security/STEALTH_GUIDE.md +++ b/docs/security/STEALTH_GUIDE.md @@ -31,6 +31,13 @@ unavailable; a caller may explicitly select a fallback outside this wrapper. - Proxy resolution (priority): `HTTPS_PROXY` → `HTTP_PROXY` → `ALL_PROXY` (also lower-case) - Timeout: `TLS_CLIENT_TIMEOUT_MS` (inherits from `FETCH_TIMEOUT_MS`, default 600000) - `wreq-js` Response is fetch-compatible (`headers`, `text()`, `json()`, `clone()`, `body`). +- First-byte watchdog (`open-sse/utils/tlsFirstByteWatchdog.ts`, #12656): `TlsClient.fetch()` + resolves as soon as upstream headers arrive, so `TLS_CLIENT_TIMEOUT_MS` alone cannot bound a + body that never yields a first byte. `guardTlsFirstByte()` races the body's first `read()` + against `TLS_FIRST_BYTE_WATCHDOG_MS` (default `10000`, `0` disables it); a healthy body is + unaffected, while a stalled body cancels the wreq reader and lets `proxyFetch`'s existing + TLS-fallback logic fall through to the direct/proxy dispatcher (a non-replay-safe request, e.g. + a POST with a body, still throws instead of being silently retried). ### Web-cookie provider transport — wreq-js 3.2.0 diff --git a/open-sse/utils/proxyFetch.ts b/open-sse/utils/proxyFetch.ts index 8dd5d013e8..349bb71a2d 100644 --- a/open-sse/utils/proxyFetch.ts +++ b/open-sse/utils/proxyFetch.ts @@ -13,7 +13,7 @@ import { proxyConfigToUrl, proxyUrlForLogs, } from "./proxyDispatcher.ts"; -import tlsClient, { type TlsFetchOptions } from "./tlsClient.ts"; +import tlsClient, { type TlsFetchOptions, guardTlsFirstByte } from "./tlsClient.ts"; import { isProxyReachable } from "@/lib/proxyHealth"; import { isControlPlaneProxyDirectFallbackEnabled, @@ -807,7 +807,7 @@ async function patchedFetch( ...tlsProfileForProvider(tlsStore?.provider), }); if (tlsStore) tlsStore.used = true; - return response; + return await guardTlsFirstByte(response); } catch (error) { if (isCallerAbort(error, getEffectiveSignal(input, options))) throw error; const sessionHadCookies = @@ -1100,7 +1100,7 @@ async function patchedFetch( ...tlsProfileForProvider(tlsStore?.provider), }); if (tlsStore) tlsStore.used = true; - return response; + return await guardTlsFirstByte(response); } catch (error) { if (isCallerAbort(error, getEffectiveSignal(input, options))) throw error; const sessionHadCookies = diff --git a/open-sse/utils/tlsClient.ts b/open-sse/utils/tlsClient.ts index 25c3e81aee..e0767d1b64 100644 --- a/open-sse/utils/tlsClient.ts +++ b/open-sse/utils/tlsClient.ts @@ -1,6 +1,9 @@ import { createHash } from "node:crypto"; import * as nodeModule from "node:module"; import { getTlsClientTimeoutConfig } from "@/shared/utils/runtimeTimeouts"; +// #12656 — re-exported so proxyFetch.ts (frozen at its file-size cap) can +// import the first-byte watchdog alongside TlsClient without adding a line. +export { guardTlsFirstByte } from "./tlsFirstByteWatchdog.ts"; const runtimeRequire = nodeModule.createRequire(import.meta.url); diff --git a/open-sse/utils/tlsFirstByteWatchdog.ts b/open-sse/utils/tlsFirstByteWatchdog.ts new file mode 100644 index 0000000000..4976457129 --- /dev/null +++ b/open-sse/utils/tlsFirstByteWatchdog.ts @@ -0,0 +1,115 @@ +import { getTlsFirstByteWatchdogMs } from "@/shared/utils/runtimeTimeouts"; + +// #12656 — the wreq-js TLS-fingerprint transport resolves the Response as +// soon as upstream headers arrive, with zero protection around how long the +// caller then waits for the body's first byte. The only timing guard on that +// path, TlsClient's flat `timeout`, defaults to 600_000ms — matching the +// reported 90-600s stall window exactly. This module races the body's first +// `read()` against a short, env-overridable watchdog: a healthy body is +// completely unaffected (bytes already buffered are replayed through a +// passthrough stream, nothing is dropped), while a body that never yields +// within the deadline cancels the wreq reader and throws so the caller +// (proxyFetch's existing TLS-fallback catch blocks) can fall back to the +// direct/proxy dispatcher instead of hanging for minutes. + +export const TLS_FIRST_BYTE_WATCHDOG_TIMEOUT_CODE = "TLS_FIRST_BYTE_WATCHDOG_TIMEOUT"; + +type BodyReader = ReadableStreamDefaultReader; +type FirstReadResult = ReadableStreamReadResult; + +function createWatchdogTimeoutError(timeoutMs: number): Error & { code: string } { + const err = new Error( + `TLS fingerprint transport produced no first byte within ${timeoutMs}ms` + ) as Error & { code: string }; + err.name = "TimeoutError"; + err.code = TLS_FIRST_BYTE_WATCHDOG_TIMEOUT_CODE; + return err; +} + +export function isTlsFirstByteWatchdogTimeout(err: unknown): boolean { + return ( + !!err && + typeof err === "object" && + "code" in err && + (err as { code?: unknown }).code === TLS_FIRST_BYTE_WATCHDOG_TIMEOUT_CODE + ); +} + +async function raceFirstChunk(reader: BodyReader, timeoutMs: number): Promise { + let timer: ReturnType | undefined; + const timeoutPromise = new Promise((_, reject) => { + timer = setTimeout(() => reject(createWatchdogTimeoutError(timeoutMs)), timeoutMs); + timer.unref?.(); + }); + try { + return await Promise.race([reader.read(), timeoutPromise]); + } finally { + clearTimeout(timer); + } +} + +async function pumpRemainingChunks( + reader: BodyReader, + controller: ReadableStreamDefaultController +): Promise { + try { + for (;;) { + const { done, value } = await reader.read(); + if (done) { + controller.close(); + return; + } + if (value) controller.enqueue(value); + } + } catch (error) { + controller.error(error); + } +} + +function buildPassthroughStream( + reader: BodyReader, + firstChunk: FirstReadResult +): ReadableStream { + return new ReadableStream({ + start(controller) { + if (firstChunk.value) controller.enqueue(firstChunk.value); + if (firstChunk.done) { + controller.close(); + return; + } + void pumpRemainingChunks(reader, controller); + }, + cancel(reason) { + void reader.cancel(reason).catch(() => {}); + }, + }); +} + +/** + * Guard a TLS-fingerprint Response's first body byte with a short watchdog. + * Resolves with an equivalent Response (status/headers preserved) whose body + * has already produced at least one byte, or throws + * TLS_FIRST_BYTE_WATCHDOG_TIMEOUT after cancelling the reader so the caller + * can fall back to another transport. + */ +export async function guardTlsFirstByte( + response: Response, + timeoutMs: number = getTlsFirstByteWatchdogMs() +): Promise { + if (!timeoutMs || timeoutMs <= 0 || !response.body) return response; + + const reader = response.body.getReader(); + let firstChunk: FirstReadResult; + try { + firstChunk = await raceFirstChunk(reader, timeoutMs); + } catch (error) { + await reader.cancel(error).catch(() => {}); + throw error; + } + + return new Response(buildPassthroughStream(reader, firstChunk), { + status: response.status, + statusText: response.statusText, + headers: response.headers, + }); +} diff --git a/src/shared/utils/runtimeTimeouts.ts b/src/shared/utils/runtimeTimeouts.ts index 667fa82b64..f80219aa7a 100644 --- a/src/shared/utils/runtimeTimeouts.ts +++ b/src/shared/utils/runtimeTimeouts.ts @@ -35,6 +35,14 @@ export const DEFAULT_MAIN_SERVER_HEADERS_TIMEOUT_MS = 66_000; // failure, wait this long for the real completion to land. Set to 0 to // disable and restore the old immediate-fail behavior. export const DEFAULT_STREAM_DISCONNECT_GRACE_PERIOD_MS = 10_000; +// #12656 — the wreq-js TLS-fingerprint transport resolves the Response as +// soon as upstream headers arrive; the only timing guard on the body itself +// was TlsClient's flat `timeout` (defaults to DEFAULT_FETCH_TIMEOUT_MS = +// 600_000ms), matching the reporter's observed 90-600s stall range exactly. +// This bounds time-to-first-byte specifically for that transport so a wedged +// wreq body falls back fast instead of riding the 10-minute ceiling. Set to +// 0 to disable the watchdog entirely. +export const DEFAULT_TLS_FIRST_BYTE_WATCHDOG_MS = 10_000; function hasEnvValue(env: EnvSource, name: string): boolean { const raw = env[name]; @@ -212,6 +220,16 @@ export function getTlsClientTimeoutConfig( }; } +export function getTlsFirstByteWatchdogMs( + env: EnvSource = process.env, + logger?: TimeoutLogger +): number { + return readTimeoutMs(env, "TLS_FIRST_BYTE_WATCHDOG_MS", DEFAULT_TLS_FIRST_BYTE_WATCHDOG_MS, { + allowZero: true, + logger, + }); +} + export function getApiBridgeTimeoutConfig( env: EnvSource = process.env, logger?: TimeoutLogger diff --git a/tests/unit/tls-first-byte-watchdog-12656.test.ts b/tests/unit/tls-first-byte-watchdog-12656.test.ts new file mode 100644 index 0000000000..26551cbca4 --- /dev/null +++ b/tests/unit/tls-first-byte-watchdog-12656.test.ts @@ -0,0 +1,150 @@ +import assert from "node:assert/strict"; +import test from "node:test"; + +import { + proxyFetch, + runWithTlsTracking, + setTlsClientForTest, +} from "../../open-sse/utils/proxyFetch.ts"; +import type { TlsFetchOptions } from "../../open-sse/utils/tlsClient.ts"; + +// #12656 — when ENABLE_TLS_FINGERPRINT=true, the wreq-js TLS-fingerprint +// transport used to return the Response as soon as headers resolved, with no +// guard on how long the caller then waited for the body's first byte (the +// only timing control, TlsClient's flat `timeout`, defaults to 600_000ms). +// These tests promote the RED probe from the #12656 plan-file into a +// permanent regression suite for the first-byte watchdog added in +// open-sse/utils/tlsFirstByteWatchdog.ts. + +type EnvState = Record; + +const ENV_KEYS = [ + "ENABLE_TLS_FINGERPRINT", + "TLS_FINGERPRINT_PROVIDERS", + "TLS_FIRST_BYTE_WATCHDOG_MS", +] as const; + +async function withEnv(env: EnvState, fn: () => Promise | void): Promise { + const prior = Object.fromEntries(ENV_KEYS.map((key) => [key, process.env[key]])); + for (const key of ENV_KEYS) { + if (env[key] === undefined) delete process.env[key]; + else process.env[key] = env[key]; + } + try { + await fn(); + } finally { + for (const key of ENV_KEYS) { + if (prior[key] === undefined) delete process.env[key]; + else process.env[key] = prior[key]; + } + setTlsClientForTest(null); + } +} + +function fakeTlsClient(fetch: (url: string, options?: TlsFetchOptions) => Promise) { + return { available: true, fetch }; +} + +function neverYieldingBody(): ReadableStream { + return new ReadableStream({ + pull() { + // Never enqueue, never close — simulates the reported wreq stall. + }, + }); +} + +test("#12656 (a) a stalled wreq body falls back to the direct dispatcher within the watchdog window", async () => { + await withEnv({ ENABLE_TLS_FINGERPRINT: "true", TLS_FIRST_BYTE_WATCHDOG_MS: "80" }, async () => { + setTlsClientForTest( + fakeTlsClient( + async () => + new Response(neverYieldingBody(), { + status: 200, + headers: { "content-type": "text/event-stream" }, + }) + ) + ); + + let dispatcherCalls = 0; + const startedAt = Date.now(); + const tracked = await runWithTlsTracking("openai", () => + proxyFetch( + "https://example-provider.test/v1/chat/completions", + { method: "GET" }, + { + undiciFetch: async () => { + dispatcherCalls++; + return new Response("fallback-body", { status: 200 }); + }, + } + ) + ); + const elapsedMs = Date.now() - startedAt; + + assert.equal(dispatcherCalls, 1); + assert.equal(await tracked.result.text(), "fallback-body"); + // Well under the OLD 600_000ms flat TlsClient timeout — proves the + // watchdog fired instead of riding the default request timeout. + assert.ok(elapsedMs < 5_000, `expected fast fallback, took ${elapsedMs}ms`); + // tlsStore.used is flipped back to false on the fallback path in + // proxyFetch's existing catch block, same as any other TLS failure. + assert.equal(tracked.tlsFingerprintUsed, false); + }); +}); + +test("#12656 (b) a healthy/fast wreq body is unaffected by the watchdog", async () => { + await withEnv({ ENABLE_TLS_FINGERPRINT: "true", TLS_FIRST_BYTE_WATCHDOG_MS: "80" }, async () => { + setTlsClientForTest(fakeTlsClient(async () => new Response("healthy-body", { status: 200 }))); + + let dispatcherCalls = 0; + const tracked = await runWithTlsTracking("openai", () => + proxyFetch( + "https://example-provider.test/v1/chat/completions", + { method: "GET" }, + { + undiciFetch: async () => { + dispatcherCalls++; + return new Response("fallback-body", { status: 200 }); + }, + } + ) + ); + + assert.equal(dispatcherCalls, 0); + assert.equal(await tracked.result.text(), "healthy-body"); + assert.equal(tracked.tlsFingerprintUsed, true); + }); +}); + +test("#12656 (c) a non-replay-safe POST throws on watchdog timeout instead of silently retrying", async () => { + await withEnv({ ENABLE_TLS_FINGERPRINT: "true", TLS_FIRST_BYTE_WATCHDOG_MS: "80" }, async () => { + setTlsClientForTest( + fakeTlsClient( + async () => + new Response(neverYieldingBody(), { + status: 200, + headers: { "content-type": "text/event-stream" }, + }) + ) + ); + + let dispatcherCalls = 0; + await assert.rejects( + runWithTlsTracking("openai", () => + proxyFetch( + "https://example-provider.test/v1/chat/completions", + { method: "POST", body: "{}" }, + { + undiciFetch: async () => { + dispatcherCalls++; + return new Response("unexpected", { status: 200 }); + }, + } + ) + ), + (error: Error) => + error.message === "TLS fingerprint request failed; request is not safe to replay" + ); + assert.equal(dispatcherCalls, 0); + }); +});