From d70f43d4b4e828bae09120b5e4145a5a5d8645c6 Mon Sep 17 00:00:00 2001 From: initguru Date: Thu, 17 Sep 2026 14:30:15 +0900 Subject: [PATCH] fix(sse): retry empty_response 502 + reasoning-aware direct response-start timeout (#12906) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * fix(sse): retry 0-byte empty_response 502 like STREAM_EARLY_EOF to stop autocompact 502 A genuine 0-byte upstream empty response (GLM-5.2 on a huge autocompact context returns ONLY reasoning_content or nothing, then closes) reaches stream.ts::emitClaudeEmptyStreamErrorAndAbort which emits a 502 with code "empty_response" via the onFailure callback AND propagates the failure down the pipeline as controller.error(new Error(msg)). The plain Error carries no .code, so getUpstreamErrorIdentifier (reads only error.code) returns undefined, result.errorCode/result.errorType become undefined, and the single-model retry guard (chat.ts) only matches errorType === "stream_early_eof" / errorCode === "STREAM_EARLY_EOF". The 502 surfaces to the client with no re-attempt (call logs 1788132529140-96ef4a / 1788142914004-062cf6, ~48s, tokens out=0). This is the same class of transient upstream glitch STREAM_EARLY_EOF was built for (HTTP 200 then zero useful frames — #3758), but empty_response was never wired into the retry path. Fix (three chokepoints, all required for consistency): - stream.ts: emitClaudeEmptyStreamErrorAndAbort now propagates an Error carrying code="empty_response" so a downstream classifier can identify it (plain new Error(msg) dropped it). - chatHelpers.ts: shouldRetryStreamEarlyEof now treats "empty_response" the same as "STREAM_EARLY_EOF" via RETRYABLE_STREAM_EMPTY_CODES Set — ONE bounded same-connection re-attempt, never a loop (STREAM_EARLY_EOF_MAX_RETRIES=1 unchanged). - chat.ts: the single-model retry guard now also enters on errorCode === "empty_response". The bounded retry never marks the account unavailable (an empty response is a transient upstream glitch, not a bad key), mirroring #3758. Tests: 5/5 (stream-empty-response-retry-96ef4a). Existing 3758 regression guard stays green (5/5). typecheck:core clean. * fix(sse): make direct response-start timeout reasoning-aware to stop 504 on high-effort TTFB Reasoning models (GLM-5.2/5.3 reasoning.effort=high/max, codex-gpt-5.x-high, third-party Claude-format replicas) warm up with a ~78s+ TTFB before emitting the first byte. The stream-readiness layer (streamReadinessPolicy) already budgets 180s for this class, but the fetch-layer guard (resolveDirectHeadersTimeoutMs) was a flat 30s — it pre-empted a warm reasoning response the readiness layer would have permitted, surfacing a 504 (regression introduced by 142ae9349). Fix: resolveDirectHeadersTimeoutMs now accepts the request body and, when hasHighReasoningEffort(body) matches a quoted "reasoning_effort" or nested "effort" field with value high/max, raises the budget to REASONING_READINESS_CEILING_MS (180_000) — aligning to the same ceiling the readiness layer uses. The operator env override (OMNIROUTE_DIRECT_HEADERS TIMEOUT_MS) is treated as a FLOOR: reasoning awareness only raises the budget, never lowers it; an override above the ceiling (e.g. 240s) is preserved. proxyFetch.ts passes the request body (when it is a string) to resolveDirectHeadersTimeoutMs so the budget is per-request. The HIGH_REASONING_EFFORT_PATTERN is a bounded, non-overlapping regex (no variable-length quantifier overlap) — no ReDoS surface (PII rule #1). Tests: 7/7 (direct-response-start-timeout-reasoning-504 — flat default, env override, high/max ceiling bump, floor semantics, non-reasoning pass-through). typecheck:core clean. * docs(changelog): add fragments for empty_response 502 retry + reasoning-aware timeout Co-authored-by: diegosouzapw <8016841+diegosouzapw@users.noreply.github.com> --------- Co-authored-by: Jihyun Son Co-authored-by: diegosouzapw <8016841+diegosouzapw@users.noreply.github.com> --- .../12906-direct-timeout-reasoning-aware.md | 1 + .../fixes/12906-empty-response-502-retry.md | 1 + open-sse/utils/directResponseStartTimeout.ts | 42 +++++-- open-sse/utils/proxyFetch.ts | 3 +- open-sse/utils/stream.ts | 10 +- src/sse/handlers/chat.ts | 4 +- src/sse/handlers/chatHelpers.ts | 16 ++- ...sponse-start-timeout-reasoning-504.test.ts | 89 ++++++++++++++ ...stream-empty-response-retry-96ef4a.test.ts | 109 ++++++++++++++++++ 9 files changed, 263 insertions(+), 12 deletions(-) create mode 100644 changelog.d/fixes/12906-direct-timeout-reasoning-aware.md create mode 100644 changelog.d/fixes/12906-empty-response-502-retry.md create mode 100644 tests/unit/direct-response-start-timeout-reasoning-504.test.ts create mode 100644 tests/unit/stream-empty-response-retry-96ef4a.test.ts diff --git a/changelog.d/fixes/12906-direct-timeout-reasoning-aware.md b/changelog.d/fixes/12906-direct-timeout-reasoning-aware.md new file mode 100644 index 0000000000..90cdb9f4e9 --- /dev/null +++ b/changelog.d/fixes/12906-direct-timeout-reasoning-aware.md @@ -0,0 +1 @@ +- **fix(sse):** make the direct response-start timeout reasoning-aware — detect reasoning_effort high/max in the body and raise the ceiling to 180s to stop 504 on high-effort TTFB ([#12906](https://github.com/diegosouzapw/OmniRoute/pull/12906)) diff --git a/changelog.d/fixes/12906-empty-response-502-retry.md b/changelog.d/fixes/12906-empty-response-502-retry.md new file mode 100644 index 0000000000..d3b1d9eb3a --- /dev/null +++ b/changelog.d/fixes/12906-empty-response-502-retry.md @@ -0,0 +1 @@ +- **fix(sse):** retry 0-byte empty_response 502 like STREAM_EARLY_EOF to stop autocompact 502 — RETRYABLE_STREAM_EMPTY_CODES + shouldRetryStreamEarlyEof wiring ([#12906](https://github.com/diegosouzapw/OmniRoute/pull/12906)) diff --git a/open-sse/utils/directResponseStartTimeout.ts b/open-sse/utils/directResponseStartTimeout.ts index 90e7b6a04a..c1cf40e408 100644 --- a/open-sse/utils/directResponseStartTimeout.ts +++ b/open-sse/utils/directResponseStartTimeout.ts @@ -1,19 +1,45 @@ type DirectFetchOptions = RequestInit & { dispatcher?: unknown }; -type DirectFetch = ( - input: RequestInfo | URL, - options: DirectFetchOptions -) => Promise; +type DirectFetch = (input: RequestInfo | URL, options: DirectFetchOptions) => Promise; const DEFAULT_DIRECT_HEADERS_TIMEOUT_MS = 30_000; const DIRECT_RESPONSE_START_TIMEOUT_CODE = "DIRECT_RESPONSE_START_TIMEOUT"; +// Reasoning models (GLM-5.2/5.3 reasoning.effort=high/max, codex-gpt-5.x-high, +// third-party Claude-format replicas) warm up with a ~78s+ TTFB before emitting +// the first byte. The stream-readiness layer (streamReadinessPolicy.ts) already +// budgets 180s for this class (claude_format_heavy_reasoning / +// codex_gpt_5_5_high_reasoning +30s bumps over an 80s base). This fetch-layer +// guard must align to the SAME ceiling so it does not pre-empt a warm reasoning +// response that the readiness layer would have permitted — that mismatch is the +// 504 regression introduced by 142ae9349 (flat 30s cut a 78s+ reasoning TTFB). +const REASONING_READINESS_CEILING_MS = 180_000; +// Bounded, non-overlapping pattern: a quoted "reasoning_effort" or nested +// "effort" field whose value is high or max. No variable-length quantifier +// overlap → no ReDoS surface (project PII rule #1). +const HIGH_REASONING_EFFORT_PATTERN = /"(?:reasoning_effort|effort)"\s*:\s*"(?:high|max)"/i; + +function hasHighReasoningEffort(body?: string | null): boolean { + if (!body || typeof body !== "string") return false; + return HIGH_REASONING_EFFORT_PATTERN.test(body); +} + export function resolveDirectHeadersTimeoutMs( - env: Record = process.env + env: Record = process.env, + body?: string | null ): number { const raw = env.OMNIROUTE_DIRECT_HEADERS_TIMEOUT_MS; - if (raw == null || raw.trim() === "") return DEFAULT_DIRECT_HEADERS_TIMEOUT_MS; - const parsed = Number(raw); - return Number.isFinite(parsed) && parsed > 0 ? Math.floor(parsed) : 0; + const base = + raw == null || raw.trim() === "" + ? DEFAULT_DIRECT_HEADERS_TIMEOUT_MS + : Number.isFinite(Number(raw)) && Number(raw) > 0 + ? Math.floor(Number(raw)) + : 0; + // Operator override is a FLOOR: reasoning awareness only raises the budget, + // never lowers it. An override above the ceiling (e.g. 240s) is preserved. + if (hasHighReasoningEffort(body)) { + return Math.max(base, REASONING_READINESS_CEILING_MS); + } + return base; } function createDirectResponseStartTimeout(timeoutMs: number): Error & { code: string } { diff --git a/open-sse/utils/proxyFetch.ts b/open-sse/utils/proxyFetch.ts index f060573f98..f5aafed3c7 100644 --- a/open-sse/utils/proxyFetch.ts +++ b/open-sse/utils/proxyFetch.ts @@ -848,7 +848,8 @@ async function patchedFetchUnrecorded( const _nativeFallback = (deps.nativeFetch as FetchWithDispatcher | undefined) ?? originalFetchWithDispatcher; let lastDispatcherError: unknown = null; - const directHeadersTimeoutMs = resolveDirectHeadersTimeoutMs(); + const directBodyForTimeout = typeof options.body === "string" ? options.body : null; + const directHeadersTimeoutMs = resolveDirectHeadersTimeoutMs(undefined, directBodyForTimeout); let targetHostForLogs = ""; try { targetHostForLogs = new URL(targetUrl).host; diff --git a/open-sse/utils/stream.ts b/open-sse/utils/stream.ts index 68929bba13..119386dd17 100644 --- a/open-sse/utils/stream.ts +++ b/open-sse/utils/stream.ts @@ -1043,7 +1043,15 @@ export function createSSEStream(options: StreamOptions = {}) { if (decrementPendingRequest && !failureHandled) { clearPendingRequestFromStream(); } - controller.error(markPendingRequestCleared(new Error(msg))); + // Preserve the `empty_response` code on the propagated Error so the + // single-model retry classifier (chatHelpers::shouldRetryStreamEarlyEof via + // chat.ts) can identify this as a retryable transient upstream glitch and + // attempt one bounded re-attempt — a plain `new Error(msg)` drops the code, + // getUpstreamErrorIdentifier (streamErrorResult.ts) reads only `error.code`, + // and the 502 surfaces with no retry (call logs 96ef4a / 062cf6). + const emptyStreamError = new Error(msg) as Error & { code?: string }; + emptyStreamError.code = "empty_response"; + controller.error(markPendingRequestCleared(emptyStreamError)); }; const emitTranslatedClientItem = ( diff --git a/src/sse/handlers/chat.ts b/src/sse/handlers/chat.ts index 81d4006a51..f8aaddf162 100644 --- a/src/sse/handlers/chat.ts +++ b/src/sse/handlers/chat.ts @@ -2069,7 +2069,9 @@ async function handleSingleModelChat( result.errorType === "stream_early_eof"); if ( - (result.errorType === "stream_timeout" || result.errorType === "stream_early_eof") && + (result.errorType === "stream_timeout" || + result.errorType === "stream_early_eof" || + result.errorCode === "empty_response") && !isAntigravityStreamReadinessFailure ) { // Bug #3758: flaky OpenAI-compatible upstreams (e.g. NVIDIA NIM) sometimes diff --git a/src/sse/handlers/chatHelpers.ts b/src/sse/handlers/chatHelpers.ts index b47c0037ac..d86e3fc242 100644 --- a/src/sse/handlers/chatHelpers.ts +++ b/src/sse/handlers/chatHelpers.ts @@ -937,11 +937,25 @@ export function handleNoCredentials( */ export const STREAM_EARLY_EOF_MAX_RETRIES = 1; +// A genuine 0-byte upstream empty response (emitClaudeEmptyStreamErrorAndAbort, +// code "empty_response" — call logs 1788132529140-96ef4a / 1788142914004-062cf6) +// is the same class of transient upstream glitch as STREAM_EARLY_EOF: the +// upstream sent HTTP 200 then closed with zero useful frames. Treat it the +// same — ONE bounded same-connection re-attempt, never a loop. +const RETRYABLE_STREAM_EMPTY_CODES: ReadonlySet = new Set([ + "STREAM_EARLY_EOF", + "empty_response", +]); + export function shouldRetryStreamEarlyEof( errorCode: string | null | undefined, attempt: number ): boolean { - return errorCode === "STREAM_EARLY_EOF" && attempt < STREAM_EARLY_EOF_MAX_RETRIES; + return ( + typeof errorCode === "string" && + RETRYABLE_STREAM_EMPTY_CODES.has(errorCode) && + attempt < STREAM_EARLY_EOF_MAX_RETRIES + ); } // The sibling hop widens the terminal/failover boundary, so it ships off diff --git a/tests/unit/direct-response-start-timeout-reasoning-504.test.ts b/tests/unit/direct-response-start-timeout-reasoning-504.test.ts new file mode 100644 index 0000000000..c7488e2ee0 --- /dev/null +++ b/tests/unit/direct-response-start-timeout-reasoning-504.test.ts @@ -0,0 +1,89 @@ +// Regression guard for the 504 regression introduced by 142ae9349 +// "fix(network): bound direct-path response-start timeout". +// +// Root cause: directResponseStartTimeout resolved a FLAT timeout +// (OMNIROUTE_DIRECT_HEADERS_TIMEOUT_MS or 30s default) with zero +// awareness of reasoning effort. GLM-5.2 reasoning.effort=max has ~78s +// TTFB; the stream-readiness layer already allows 180s for reasoning +// models (streamReadinessPolicy claude_format_heavy_reasoning / +// codex_gpt_5_5_high_reasoning bumps), but the fetch layer below it +// cut the request at 30s (×2 = 60s 504) — and even 90s was still short. +// +// The fix: resolveDirectHeadersTimeoutMs inspects the serialized +// request body for a high/max reasoning effort selector and raises the +// per-attempt TTFB budget to align with the stream-readiness ceiling +// (180s) so the fetch layer no longer pre-empts a warm reasoning +// response that the readiness layer would have permitted. +import { test } from "node:test"; +import assert from "node:assert/strict"; +import { resolveDirectHeadersTimeoutMs } from "../../open-sse/utils/directResponseStartTimeout.ts"; + +const REASONING_HIGH_BODY = JSON.stringify({ + model: "glm-5.2", + reasoning_effort: "high", + messages: [{ role: "user", content: "hi" }], +}); +const REASONING_MAX_BODY = JSON.stringify({ + model: "glm-5.3", + reasoning: { effort: "max" }, + messages: [{ role: "user", content: "hi" }], +}); +const NON_REASONING_BODY = JSON.stringify({ + model: "gpt-4o-mini", + messages: [{ role: "user", content: "hi" }], +}); + +test("flat default is 30s when no body and no env override", () => { + assert.equal( + resolveDirectHeadersTimeoutMs({ OMNIROUTE_DIRECT_HEADERS_TIMEOUT_MS: undefined }), + 30_000 + ); +}); + +test("env override is honored when no reasoning body is present", () => { + assert.equal( + resolveDirectHeadersTimeoutMs({ OMNIROUTE_DIRECT_HEADERS_TIMEOUT_MS: "90000" }), + 90_000 + ); +}); + +test("reasoning_effort=high body raises TTFB budget to the readiness ceiling (180s)", () => { + const got = resolveDirectHeadersTimeoutMs( + { OMNIROUTE_DIRECT_HEADERS_TIMEOUT_MS: undefined }, + REASONING_HIGH_BODY + ); + assert.equal(got, 180_000, "high reasoning must align with the 180s readiness ceiling"); +}); + +test("reasoning.effort=max nested body raises TTFB budget to the readiness ceiling (180s)", () => { + const got = resolveDirectHeadersTimeoutMs( + { OMNIROUTE_DIRECT_HEADERS_TIMEOUT_MS: undefined }, + REASONING_MAX_BODY + ); + assert.equal(got, 180_000, "max reasoning must align with the 180s readiness ceiling"); +}); + +test("reasoning body never yields a budget BELOW an explicit env override above the ceiling", () => { + // Operator override is a floor; reasoning awareness only raises, never lowers. + const got = resolveDirectHeadersTimeoutMs( + { OMNIROUTE_DIRECT_HEADERS_TIMEOUT_MS: "240000" }, + REASONING_HIGH_BODY + ); + assert.equal(got, 240_000, "explicit override above ceiling is preserved"); +}); + +test("non-reasoning body keeps the flat default (zombie-socket detection preserved)", () => { + const got = resolveDirectHeadersTimeoutMs( + { OMNIROUTE_DIRECT_HEADERS_TIMEOUT_MS: undefined }, + NON_REASONING_BODY + ); + assert.equal(got, 30_000, "non-reasoning requests keep 30s to detect zombie sockets"); +}); + +test("non-reasoning body keeps the env override (no reasoning bump applied)", () => { + const got = resolveDirectHeadersTimeoutMs( + { OMNIROUTE_DIRECT_HEADERS_TIMEOUT_MS: "90000" }, + NON_REASONING_BODY + ); + assert.equal(got, 90_000); +}); diff --git a/tests/unit/stream-empty-response-retry-96ef4a.test.ts b/tests/unit/stream-empty-response-retry-96ef4a.test.ts new file mode 100644 index 0000000000..8983c5e180 --- /dev/null +++ b/tests/unit/stream-empty-response-retry-96ef4a.test.ts @@ -0,0 +1,109 @@ +import test from "node:test"; +import assert from "node:assert/strict"; + +// Regression: 502 "Empty Claude stream at flush" on a genuine 0-byte upstream +// empty response (call logs 1788132529140-96ef4a / 1788142914004-062cf6). +// +// Root cause (retry gap): emitClaudeEmptyStreamErrorAndAbort (stream.ts:1017) +// sends `{ status: 502, code: "empty_response" }` to the onFailure callback AND +// propagates the failure down the pipeline as `controller.error(new Error(msg))` +// (stream.ts:1025). The plain `new Error(msg)` carries NO `.code`, so +// getUpstreamErrorIdentifier (streamErrorResult.ts:56 — reads only `error.code`) +// returns undefined → result.errorCode/result.errorType become undefined → +// the single-model retry block (chat.ts:1931-1936) only matches +// `errorCode === "STREAM_EARLY_EOF"` / `errorType === "stream_early_eof"` and so +// NEVER enters the retry branch for an empty_response 502. The 502 surfaces to +// the client with no re-attempt, even though the failure is the same class of +// transient upstream glitch as STREAM_EARLY_EOF (HTTP 200 then zero useful +// frames) and the bounded same-connection retry was designed exactly for it. +// +// Fix contract (two chokepoints, both required for consistency): +// 1. stream.ts: when emitClaudeEmptyStreamErrorAndAbort propagates the error +// down the pipeline, preserve the `empty_response` code on the Error so a +// downstream classifier can identify it (plain `new Error(msg)` drops it). +// 2. shouldRetryStreamEarlyEof / the chat.ts:1931-1936 retry guard must treat +// `empty_response` as retryable exactly like `STREAM_EARLY_EOF` (one +// bounded same-connection re-attempt, never a loop). + +const { shouldRetryStreamEarlyEof } = await import("../../src/sse/handlers/chatHelpers.ts"); + +// --- Chokepoint 2: the retry classifier must recognize empty_response -------- + +test("shouldRetryStreamEarlyEof: retries once on the first empty_response (attempt 0)", () => { + // A 0-byte upstream empty response (GLM-5.2 autocompact) is the same class of + // transient upstream glitch as STREAM_EARLY_EOF (HTTP 200 then zero useful + // frames) and must get the same ONE bounded re-attempt. + assert.equal(shouldRetryStreamEarlyEof("empty_response", 0), true); +}); + +test("shouldRetryStreamEarlyEof: does NOT retry a second consecutive empty_response (bounded)", () => { + // Bounded: exactly one retry, never a loop — mirrors the STREAM_EARLY_EOF cap. + assert.equal(shouldRetryStreamEarlyEof("empty_response", 1), false); + assert.equal(shouldRetryStreamEarlyEof("empty_response", 2), false); + assert.equal(shouldRetryStreamEarlyEof("empty_response", 99), false); +}); + +test("shouldRetryStreamEarlyEof: still retries STREAM_EARLY_EOF (regression guard)", () => { + // The existing #3758 behavior must be preserved. + assert.equal(shouldRetryStreamEarlyEof("STREAM_EARLY_EOF", 0), true); + assert.equal(shouldRetryStreamEarlyEof("STREAM_EARLY_EOF", 1), false); +}); + +test("shouldRetryStreamEarlyEof: still ignores unrelated/empty codes (regression guard)", () => { + assert.equal(shouldRetryStreamEarlyEof("", 0), false); + assert.equal(shouldRetryStreamEarlyEof(null, 0), false); + assert.equal(shouldRetryStreamEarlyEof(undefined, 0), false); + assert.equal(shouldRetryStreamEarlyEof("UPSTREAM_4XX", 0), false); + assert.equal(shouldRetryStreamEarlyEof("STREAM_READINESS_TIMEOUT", 0), false); + assert.equal(shouldRetryStreamEarlyEof("stream_timeout", 0), false); +}); + +// --- End-to-end decision wiring (mirrors chat.ts around the retry guard) ------- + +test("single-model empty_response: retries once then succeeds; double empty surfaces 502; no markAccountUnavailable", () => { + function simulate(results: Array<{ errorCode: string; success?: boolean }>) { + let earlyEofAttempts = 0; + let markAccountUnavailableCalls = 0; + let i = 0; + + while (true) { + const result = results[Math.min(i, results.length - 1)]; + if (result.success) { + return { outcome: "success", earlyEofAttempts, markAccountUnavailableCalls }; + } + + // empty_response is a transient upstream glitch — never marks the account + // unavailable (same as STREAM_EARLY_EOF). + if (shouldRetryStreamEarlyEof(result.errorCode, earlyEofAttempts)) { + earlyEofAttempts += 1; + i += 1; + continue; + } + + return { outcome: "502", earlyEofAttempts, markAccountUnavailableCalls }; + } + } + + // attempt 1: empty_response → retry; attempt 2: success + const recovered = simulate([ + { errorCode: "empty_response" }, + { errorCode: "empty_response", success: true }, + ]); + assert.equal(recovered.outcome, "success"); + assert.equal(recovered.earlyEofAttempts, 1, "exactly one retry before success"); + assert.equal( + recovered.markAccountUnavailableCalls, + 0, + "empty_response must not mark account unavailable" + ); + + // attempt 1 + attempt 2 both empty → surfaces the 502 (bounded, no loop) + const exhausted = simulate([ + { errorCode: "empty_response" }, + { errorCode: "empty_response" }, + { errorCode: "empty_response" }, + ]); + assert.equal(exhausted.outcome, "502"); + assert.equal(exhausted.earlyEofAttempts, 1, "only one retry attempted before surfacing 502"); + assert.equal(exhausted.markAccountUnavailableCalls, 0); +});