From cc17b304ab407aeb43f2d9114b22c69eb896026e Mon Sep 17 00:00:00 2001 From: Markus Hartung Date: Thu, 23 Jul 2026 10:17:35 +0200 Subject: [PATCH] fix(sse): Gemini TPM/RPD quota classification + combo cooldown-wait resilience (#8213) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * fix(sse): Gemini TPM classification, combo-cooldown-wait for auto/quota-share, and target-timeout floor Gemini TPM/RPM 429s were misclassified as QUOTA_EXHAUSTED because sanitizeErrorMessage() truncates to the first line, hiding Google's metric name and retry hint on lines 2-3. Added a rawMessage field (internal-only, never reaches the client) and classifyGeminiQuotaMetricFromText() to classify from the untruncated text, reordered ahead of the generic credits/daily-quota checks. Widened comboCooldownWaitEnabled (wait out a short transient cooldown instead of crystallizing a 429/503) from quota-share-only to also cover auto-strategy combos, and raised the wait ceiling to 65s/130s-budget/90s-cap to match Gemini's ~60s TPM/RPM windows. The per-target timeout (DEFAULT_COMBO_TARGET_TIMEOUT_MS, 120s) was shorter than the new 130s cooldown-wait budget, so a target could get cut off mid-wait with a synthetic 524 instead of completing the retry. Added resolveComboTargetTimeoutMsForCombo()/isComboCooldownWaitEligible() in comboConfig.ts to raise the per-target floor to budgetMs+buffer only for wait-eligible strategies (auto/quota-share), verified live: a 12-request concurrent burst against a TPM-exhausted combo went from 2/12 succeeding (10 x 524) to 12/12 succeeding with zero 503/524. Also: liveGeminiShared.ts's sendAndValidate now fails fast on a 503 instead of retrying past it, and the health dashboard + request logger surface TPM stats alongside RPM/RPD. Co-authored-by: Markus Hartung * fix(sse): combo-exhausted rejection logs now capture request body + attempted models recordRejectedRequestUsage() (the fast path for combo requests that never reach handleChatCore, e.g. all targets locked by resilience cooldown) hardcoded provider: "-" and never passed a request body to saveCallLog(), so /dashboard/logs entries for these failures were nearly useless for debugging: no way to see the client's request or which models were tried. - recordRejectedRequestUsage() now accepts requestBody and persists it through the existing saveCallLog() artifact mechanism (same path handleChatCore's own logging uses). - Added summarizeComboAttemptedModels(), which reads the combo's own model list (always available, unlike the response's combo-diagnostics headers — a model-level resilience-lockout skip never touches the exhaustedProviders/exhaustedConnections sets those headers are built from) to populate a real "provider" value instead of "-". - Wired both into the call site in src/sse/handlers/chat.ts. NOTE: unrelated to the Gemini TPM/combo-cooldown-wait fix on this branch — landed here per operator request, to be split into its own branch/PR. Co-authored-by: Markus Hartung * feat(sse): synthetic streaming keep-alive event + 5-minute Gemini cooldown-wait ceiling Many clients enforce a first-SSE-byte timeout, which made it unsafe to wait out a longer upstream rate-limit cooldown on a streaming request — the client would abandon the connection before any bytes arrived. This landed in two parts: 1. Synthetic startup "thinking" event (OpenAI chat/completions format): the already-existing withEarlyStreamKeepalive wrapper (open-sse/utils/ earlyStreamKeepalive.ts, wired into /v1/chat/completions, /v1/messages, /v1/responses since #2544) opens the SSE stream immediately once a request runs past its threshold, but only ever sent empty/no-op keepalive frames. Added a `startupFrame` option (defaults to `keepaliveFrame` — zero behavior change unless a route opts in) so the very first frame can carry real content instead. Wired OPENAI_STARTUP_THINKING_FRAME (a reasoning_content delta: "OmniRoute: got request, sending to provider") into /v1/chat/completions only — Claude Messages and Responses API formats both require a preceding envelope event (message_start / response.created) that a synthetic pre-dispatch frame can't safely fabricate without risking a duplicate envelope once the real stream arrives, so those two routes keep their existing (safe, proven) keepalive frames unchanged. 2. Raised the "wait out a known cooldown, then retry" ceiling to 5 minutes for both retry mechanisms, now that a client-side first-byte timeout is no longer a risk on the (opted-in) route: - comboCooldownWait (auto/quota-share combos, open-sse/services/combo.ts): maxWaitMs hard clamp raised 90s -> 300s (src/lib/resilience/settings/ normalize.ts); defaults raised to maxWaitMs:90s/maxAttempts:5/ budgetMs:300s. comboConfig.ts's resolveComboTargetTimeoutMsForCombo already derives the per-target timeout floor from budgetMs, so it tracks the new ceiling with no further changes. - waitForCooldown (direct, non-combo model requests, src/sse/handlers/ chat.ts): this mechanism had NO cumulative cap before — only a per-wait cap (maxRetryWaitMs) and a retry count (maxRetries), so maxRetries x maxRetryWaitMs could exceed 5 minutes with no ceiling. Added a budgetMs field (mirrors comboCooldownWait) to WaitForCooldownSettings/CooldownAwareRetrySettings, threaded a requestRetryBudgetLeftMs tracker through chat.ts's requestAttemptLoop (mirrors combo.ts's comboCooldownBudgetLeftMs), and made getCooldownAwareRetryDecision refuse to wait once the cumulative budget is exhausted even if the single wait is under maxRetryWaitMs. Co-authored-by: Markus Hartung * fix(sse): extend the synthetic keep-alive thinking event to /v1/responses Live incident (OpenClaw, log id 1784407081908-cbc24f): a /v1/responses request to gemini/gemma-4-31b-it took 56s to produce a first byte and the client disconnected (499 request_signal_aborted) — the same client-first-byte- timeout problem the previous commit fixed for /v1/chat/completions, but /v1/responses only had the generic bare-comment keepalive (no content), so it wasn't covered. Added RESPONSES_STARTUP_THINKING_FRAME: a self-contained synthetic reasoning item (response.output_item.added -> reasoning_summary_part.added -> reasoning_summary_text.delta -> reasoning_summary_part.done), opened AND closed within this one frame rather than left dangling — it never carries a response_id, so it can't collide with the real upstream response's own independent response.created lifecycle that follows. Mirrors the abbreviated delta+part.done close pattern open-sse/utils/stream.ts's own emitSyntheticResponsesReasoningSummary already uses for real mid-stream reasoning content. Wired into src/app/api/v1/responses/route.ts via the startupFrame option added in the previous commit. Co-authored-by: Markus Hartung * fix(sse): combo cooldown-wait vars reset every setTry, crystallizing a bogus 503 instead of waiting Live incident (log id 1784416706646-51): a request to the "default" combo (strategy=auto, maxSetRetries=3) hit a real Gemini TPM 429 on both gemma-4 targets, correctly classified as a short 40s rate_limit lockout — then crystallized a 503 "all upstream accounts are inactive" in 6.9s instead of ever reaching the cooldown-aware wait. Root cause: `lastError`/`earliestRetryAfter`/`lastStatus` were declared with `let` INSIDE the `for (setTry...)` loop body, so they reset to null at the start of every set-try. When both targets lock out on setTry 0, every subsequent setTry (1..maxSetRetries) pre-skips both targets via the isModelLocked check with no real dispatch — so on the FINAL setTry (the only one whose values the post-loop decision reads, since it's gated behind `if (setTry < maxSetRetries) continue`), lastStatus was null, hitting the "!lastStatus" branch (ALL_ACCOUNTS_INACTIVE 503) and completely bypassing the comboCooldownWaitEnabled / earliestRetryAfter wait logic — even though a real 429 with a known ~40s retry-after WAS observed on setTry 0. This bug predates today's Gemini TPM work (any combo with maxSetRetries > 0 whose targets all lock out on the first pass was affected) but was masked in existing tests: the "auto strategy (2 models...)" regression test uses maxSetRetries: 0, so it only ever runs ONE setTry iteration and never exercises the reset-on-retry path. It also explains why the dedicated 12-concurrent-request burst test passed cleanly — with concurrent requests, timing variance meant some request's FINAL setTry iteration still had a live target to dispatch to, giving lastStatus/earliestRetryAfter fresh data. A single isolated request has no such luck. Fix: hoist lastError/earliestRetryAfter/lastStatus to just inside dispatchWithCooldownRetry, before the setTry loop, so they persist across set-tries (still reset fresh on each recursive dispatchWithCooldownRetry() call after a wait, which is correct). recordedAttempts/fallbackCount/ exhaustedProviders etc. are intentionally left per-iteration (unrelated to this bug). New regression test in tests/unit/combo-quota-share-cooldown-wait.test.ts reproduces the exact live scenario (2 targets, both lock out on setTry 0, maxSetRetries: 3) — confirmed red (503) against the pre-fix code, green (200, waits and retries) against the fix. Co-authored-by: Markus Hartung * test(sse): extend live Gemini workload to Responses API + add large-context TPM test Two additions to the live Gemini test suite, both live-verified against the dev instance: 1. sendAndValidate() (tests/integration/liveGeminiShared.ts) now accepts an apiFormat: "chat" | "responses" parameter, building the Responses-API request shape (input array, max_output_tokens) and parsing its SSE events (response.output_text.delta / response.reasoning_summary_text.delta / response.completed) via the new readResponsesSSEStream(). Wired into two new tests in live-gemini-workload.test.ts ([30]/[31]), mirroring the existing Chat Completions streaming coverage. Verified live: 24/25 + 5/5 payloads succeeded end-to-end through the new code path (the one failure was a ~300s test-client fetch timeout unrelated to the Responses API code itself — a separate, not-yet-addressed test-harness limitation). 2. genHugeContextMessage() builds a single message large enough (~4 chars/token estimate) to approach or exceed Gemini's free-tier TPM ceiling (16000 input tokens/min for gemma-4) by itself. Every other prompt generator in this file tops out around 1-2k tokens — nowhere near that ceiling — so none of the existing workload tests ever exercised a REAL TPM 429, only RPM-style rate limiting. tests/integration/gemini-large-context-tpm.test.ts sends two ~12-13k-token requests back-to-back (comfortably exceeding 16000/min together) to exercise the full path against production Gemini: TPM classification, the comboCooldownWait retry, and the synthetic keep-alive frame on a genuinely slow request. Co-authored-by: Markus Hartung * fix(sse): abandoned combo target dispatch now observes its own per-target timeout, fixing a permanent "pending" dashboard leak Live incident (dashboard log id 1784418258231-14961a, reported as "an ongoing request even though there's already a 200"): a combo target dispatch abandoned by comboTargetTimeoutMs (open-sse/services/combo/targetTimeoutRunner.ts) left a permanent phantom "pending" entry in the dashboard, even after the overall combo request had already succeeded via a different retry. Root cause: chatCore.ts's createStreamController — and everything downstream that depends on it (withRateLimit's Promise.race against Bottleneck, acquireAccountSemaphore) — only ever watches clientRawRequest.signal, which is the ORIGINAL client's request signal (set once via buildClientRawRequest and reused unchanged across every target dispatch in a combo). It has no connection to targetTimeoutRunner.ts's OWN AbortController (target.modelAbortSignal), which is what actually fires when comboTargetTimeoutMs (300s) elapses. src/sse/handlers/chat.ts's handleSingleModel bridge between combo.ts and handleSingleModelChat received `target.modelAbortSignal` but silently dropped it — never forwarded it anywhere. So when a target got abandoned (e.g. stuck inside a wedged Bottleneck rate-limiter queue, see the WEDGED force-reset log line from the same incident), its per-target timeout fired and let the COMBO move on and retry successfully elsewhere — but the abandoned dispatch's own promise chain never learned it had been superseded, so it hung forever waiting on a signal that was never going to fire, and trackPendingRequest(false) (the finalize call) never ran. Fix: thread target.modelAbortSignal through as a new modelAbortSignal runtimeOption, and merge it into clientRawRequest.signal (via the existing mergeAbortSignals helper from open-sse/executors/base.ts) right before dispatch, so an abandoned target's own promise chain now observes its abort and can reach its cleanup path — new resolveDispatchClientRawRequest() makes this mechanically testable in isolation. Co-authored-by: Markus Hartung * fix(sse): combo cooldown-wait state recording, rate-limit wedge recovery, OpenAI-format SSE error frames Five related fixes surfaced by live incidents (dashboard log ids 1784457764961-73, 1784465227489-a2cbc0, 1784504040241-6f8b9a) while validating the Gemini TPM/cooldown-wait work on this branch against real OpenClaw traffic: - combo.ts: the model-lockout bail-out branches in dispatchWithCooldownRetry never recorded lastStatus, so once every target in a set hit an existing lockout the final check crystallized a bogus ALL_ACCOUNTS_INACTIVE 503 instead of reaching the cooldown-wait decision, even with a real 429 + short retry-after observed. - combo.ts/combo/types.ts: the "all credentials cooling down" pre-dispatch rejection (buildModelCooldownBody) nests its retry hint as error.retry_after/reset_seconds, not the top-level retryAfter every other 429 shape uses — combo's extraction only read the latter, so earliestRetryAfter stayed null for this shape even after lastStatus was fixed. - rateLimitManager.ts: the wedge-recovery watchdog used disconnect(), which releases the heartbeat timer but never rejects jobs already QUEUED on that instance — orphaned dispatches hung until the outer ~300s per-target timeout, well past real clients' patience. Switched to stop({ dropWaitingJobs: true }), safe because the wedge condition already requires RUNNING===0 && EXECUTING===0. - earlyStreamKeepalive.ts: the in-band error frame emitted after committing to a 200 SSE stream was hardcoded to Anthropic's `event: error` convention for every route, including the OpenAI-format ones (/v1/chat/completions, /v1/responses) where that framing is either invisible or malformed to a plain data-line parser. Added per-route OPENAI_CHAT_ERROR_FRAME / OPENAI_RESPONSES_ERROR_FRAME and wired them in. - chatCore.ts: persisted a synthetic clientResponse error body even when the client had already disconnected (AbortError) before that body was ever computed — misleading the dashboard into showing "what the client received" for a response that was never sent. Also: RequestLoggerDetail.tsx — Provider/Client Event Stream panes lost their collapse toggle when StreamSection replaced the collapsible PayloadSection (692d6be80, unifying active/finished request views) without carrying the toggle over. Each fix has a TDD regression test with a confirmed red-before-green cycle. Co-authored-by: Markus Hartung * test(sse): free-tier model + gemma-4 TPM-ceiling benchmark harness Adds a live benchmark comparing free models OmniRoute exposes across configured providers plus previously-unexercised no-auth providers (felo-web, aihorde, opencode, duckduckgo-web — none need a connection row, they were just never tried). Reuses liveGeminiShared.ts's SSE parsers and CASE_BUILDERS instead of duplicating them. Also adds a targeted TPM-stress test firing back-to-back large-context prompts at the gemma-4-31b model across its 3 free hosts (Gemini, NVIDIA, AI Horde) to isolate whether the documented 16k-tokens/minute free-tier ceiling is Gemini-specific enforcement or an inherent model property. FORCE_TOOL_CHOICE_REQUIRED is a test-only, default-off env flag added to liveGeminiShared.ts and live-gemini-agentic-loop.test.ts for an earlier live A/B comparison of tool_choice: required vs unset — kept as a reusable knob for future runs. Co-Authored-By: Markus Hartung * test(sse): benchmark for the 2026-07-22 newly-enabled provider batch Adds NEWLY_ENABLED_MODELS to freeModelBenchmarkShared.ts (Mistral Leanstral, OpenRouter's live "free"-tagged roster, OpenCode Zen's current free models — refetched live from https://opencode.ai/zen/v1/models since the static catalog had drifted) and a dedicated workload benchmark test for them. Co-Authored-By: Markus Hartung * test(sse): sync geminiRateLimitTracker tests with e74a1722b's corrected Gemma 4 limits e74a1722b updated geminiRateLimits.json's gemma-4-* entries from the stale 15/1500/-1 (rpm/rpd/tpm) to the real published free-tier values 16000/14400/16000, but never updated the tests asserting the old numbers. Surfaced by running the full test:unit suite as a post-rebase sanity check. Co-Authored-By: Markus Hartung * chore(quality): file-size baseline for own-growth (#8213) Co-authored-by: diegosouzapw <8016841+diegosouzapw@users.noreply.github.com> --------- Co-authored-by: Markus Hartung Co-authored-by: Markus Hartung Co-authored-by: diegosouzapw <8016841+diegosouzapw@users.noreply.github.com> --- config/quality/file-size-baseline.json | 17 +- docs/architecture/RESILIENCE_GUIDE.md | 13 +- open-sse/config/geminiRateLimits.json | 4 +- open-sse/handlers/chatCore.ts | 50 +- open-sse/services/accountFallback.ts | 68 ++- open-sse/services/combo.ts | 87 ++- open-sse/services/combo/comboSetup.ts | 11 +- open-sse/services/combo/types.ts | 12 +- open-sse/services/comboConfig.ts | 51 ++ open-sse/services/geminiRateLimitTracker.ts | 106 +++- open-sse/services/rateLimitManager.ts | 49 +- open-sse/utils/earlyStreamKeepalive.ts | 151 ++++- open-sse/utils/error.ts | 13 + src/app/(dashboard)/dashboard/health/page.tsx | 112 +++- src/app/api/v1/chat/completions/route.ts | 4 + src/app/api/v1/responses/route.ts | 8 +- src/lib/resilience/settings.ts | 31 +- src/lib/resilience/settings/normalize.ts | 24 +- src/lib/resilience/settings/types.ts | 8 + src/shared/components/RequestLoggerDetail.tsx | 163 +++++- src/sse/handlers/chat.ts | 76 ++- src/sse/handlers/rejectedRequestUsage.ts | 31 ++ src/sse/services/cooldownAwareRetry.ts | 22 +- .../integration/free-models-benchmark.test.ts | 112 ++++ .../free-models-tpm-stress.test.ts | 90 +++ tests/integration/freeModelBenchmarkShared.ts | 527 ++++++++++++++++++ .../gemini-combo-cooldown-wait.test.ts | 106 ++++ .../gemini-large-context-tpm.test.ts | 65 +++ .../gemini-rate-limit-classification.test.ts | 167 +++++- .../live-gemini-agentic-loop.test.ts | 371 ++++++++++++ .../integration/live-gemini-workload.test.ts | 57 ++ tests/integration/liveGeminiShared.ts | 166 +++++- .../newly-enabled-providers.test.ts | 109 ++++ .../chat-build-client-raw-request.test.ts | 61 +- tests/unit/chatcore-translation-paths.test.ts | 41 ++ tests/unit/combo-config.test.ts | 59 ++ .../combo-quota-share-cooldown-wait.test.ts | 265 +++++++++ .../unit/cooldown-aware-retry-budget.test.ts | 102 ++++ tests/unit/early-stream-keepalive.test.ts | 210 +++++++ tests/unit/error-message-sanitization.test.ts | 42 ++ tests/unit/rate-limit-wedge-recovery.test.ts | 123 ++++ tests/unit/rejected-request-usage.test.ts | 101 +++- tests/unit/request-log-detail-stream.test.ts | 47 ++ ...ience-settings-combo-cooldown-wait.test.ts | 22 +- ...esilience-settings-normalize-split.test.ts | 21 +- .../services/geminiRateLimitTracker.test.ts | 20 +- 46 files changed, 3811 insertions(+), 184 deletions(-) create mode 100644 tests/integration/free-models-benchmark.test.ts create mode 100644 tests/integration/free-models-tpm-stress.test.ts create mode 100644 tests/integration/freeModelBenchmarkShared.ts create mode 100644 tests/integration/gemini-combo-cooldown-wait.test.ts create mode 100644 tests/integration/gemini-large-context-tpm.test.ts create mode 100644 tests/integration/live-gemini-agentic-loop.test.ts create mode 100644 tests/integration/newly-enabled-providers.test.ts create mode 100644 tests/unit/cooldown-aware-retry-budget.test.ts create mode 100644 tests/unit/rate-limit-wedge-recovery.test.ts diff --git a/config/quality/file-size-baseline.json b/config/quality/file-size-baseline.json index 279335935e..aab6d8a15d 100644 --- a/config/quality/file-size-baseline.json +++ b/config/quality/file-size-baseline.json @@ -190,7 +190,8 @@ "open-sse/mcp-server/server.ts": 1555, "open-sse/mcp-server/tools/advancedTools.ts": 1120, "_rebaseline_2026_06_27_5193_antigravity_basered": "Base-red (pre-existing release drift, fast-gate PR->release skips check:file-size): accountFallback.ts 1773->1777 and src/app/api/providers/[id]/test/route.ts 924->940 were already over their frozen caps on release/v3.8.39 independent of any antigravity change. Owner chose to rebaseline (keep the documented issue-reference comments #1846/#1449/#347 etc.) rather than accept the contributor comment-stripping in #5200/#5198. Reverted #5200 to restore the comments; bumped these two frozen caps to the actual base sizes. No logic change.", - "open-sse/services/accountFallback.ts": 1892, + "_rebaseline_2026_07_22_8213_gemini_tpm_quota_cooldown_wait": "PR #8213 (hartmark, fix/gemini-tpm-quota-cooldown-wait) own growth: open-sse/services/accountFallback.ts 1857->1932 on the merged tip (release 1892 incl #8050 +35, plus this PR own growth +40); measured against the PR own merge-base was 1857->1898 (+41 — the release tip separately carries an unrelated +34 from #8050's antigravity 404 model-not-found lockout scoping, which this PR's branch does not include and this entry does not cover). Own growth is the Gemini TPM-ceiling classification + cooldown-wait wiring feeding into the combo cooldown-wait state machine (rate-limit wedge recovery) introduced by this PR's commit series. Irreducible additions at the existing account-fallback/model-lockout chokepoint. Covered by the PR's own gemini-rate-limit-tracker and TPM-ceiling benchmark test additions.", + "open-sse/services/accountFallback.ts": 1932, "open-sse/services/adobeFireflyClient.ts": 1958, "open-sse/services/batchProcessor.ts": 915, "open-sse/services/browserBackedChat.ts": 850, @@ -199,7 +200,8 @@ "_rebaseline_2026_06_24_headroom_strategy": "Headroom-aware connection selection (dario technique): combo.ts 3168->3180 (+12 = a new `else if (strategy === \"headroom\")` dispatch branch in handleComboChat that delegates to orderTargetsByHeadroom + its log line, plus the import). The actual logic lives OUT of the god-file: the pure ranker rankByHeadroom/computeHeadroom is the new leaf open-sse/services/combo/headroomRanking.ts (91 LOC, 3190 (+10 = one new `else if (strategy === \"quota-share\")` dispatch branch in handleComboChat that delegates 100% to selectQuotaShareTarget + its log line, plus the import). All the new logic lives OUT of the god-file in two new leaves under open-sse/services/combo/: quotaShareInflight.ts (in-flight counter with TTL/lease, ~150 LOC 3225 (+35) = one new `else if (strategy === \"task-aware\")` dispatch branch delegating 100% to selectTaskAwareTarget + its imports/log lines. All scoring/classification logic lives OUT of the god-file in the new leaf open-sse/services/taskAwareRouting.ts (553 LOC 3604 (+56, entirely this PR's diff — no other commit touched this file between the PR's merge-base and the release tip). Fixes combo cooldown-wait state recording so a bogus 503 is no longer crystallized when the cooldown-wait vars reset every setTry, adds an OpenAI-format SSE error frame path for combo-exhausted rejections (capturing request body + attempted models), and gives an abandoned per-target dispatch its own timeout instead of leaking a permanent 'pending' dashboard entry. Irreducible additions at the existing handleComboChat dispatch/retry chokepoint (mirrors the prior quota-share/headroom/task-aware strategy-branch precedents already frozen in this file). Covered by the PR's own combo-config + Gemini TPM-ceiling benchmark test additions.", + "open-sse/services/combo.ts": 3604, "_rebaseline_2026_06_26_fidelity_gate_extraction": "Milestone-B fidelity-gate wiring residual: bodyToText+gateAdvance extracted to fidelityGateStep.ts (889->854, -35), but the StackOptions.fidelityGate field, the `const fidelityGate` reads at the two stacked-loop dispatch chokepoints, and the import of FidelityGateConfig are irreducible wiring that cannot leave strategySelector without an architectural refactor of the pre-existing stacked pipeline. Net: 889->854 (+6 vs the pre-Milestone-B frozen 848). Covered by tests/unit/compression/*.test.ts (940 pass).", "_rebaseline_2026_06_28_5243_risk_gate_prepass": "PR #5243 (compression risk-gate pre-pass) own growth: open-sse/services/compression/strategySelector.ts 854->899 (+45). The three exported entry points (applyCompression/applyStackedCompression/applyStackedCompressionAsync) become thin wrappers over pure-extracted private bodies (runCompression/runStackedCompression/runStackedCompressionAsync) so the risk-gate mask->run->restore wrapper sits strictly OUTSIDE the per-step loop — a single universal integration point. The wrapper logic itself (resolveRiskGate/withRiskGate) lives in the new riskGate/strategyWrap.ts (960 (+61 = the opt-in result-memoization branches in applyCompression/applyCompressionAsync — principal+determinism gate, makeMemoKey lookup/store with model+supportsVision folded into the key, recompute-with-memo-off). Default off (memoizeCompressionResults), so zero behavior change. The memo helpers live in the leaf resultMemo.ts (1165 (+71, entirely this PR's diff — no other commit touched this file between the PR's merge-base and the release tip). Adds handleUnblockAll/handleUnblockOne dashboard actions (DELETE /api/resilience/model-cooldowns) so an operator can manually clear a Gemini TPM-wedge model lockout surfaced by this PR's cooldown-wait fixes, instead of waiting out the ceiling. Irreducible UI wiring at the existing health-page action chokepoint. Covered by the PR's own dashboard/resilience test additions.", + "src/app/(dashboard)/dashboard/health/page.tsx": 1165, "src/app/(dashboard)/dashboard/playground/components/tabs/ApiTab.tsx": 847, "src/app/(dashboard)/dashboard/providers/[id]/ProviderDetailPageClient.tsx": 798, "src/app/(dashboard)/dashboard/providers/[id]/components/ConnectionRow.tsx": 942, @@ -288,6 +291,8 @@ "_rebaseline_2026_07_19_7546_ghe_copilot_modal": "PR #7546 (GHE Copilot OAuth provider) own growth: OAuthModal.tsx 1030->1056 (gate units). Adds a gheUrl input state, routes ghe-copilot through the existing device-code branch, and threads gheUrl into the device-code request/poll extraData at the existing provider-switch chokepoints (+~24 lines, cohesive with the same pattern as #7399/#6636). The standalone GHE enterprise-URL config step JSX (originally +31 lines inline) was extracted to the new src/shared/components/oauthModal/GheConfigStep.tsx leaf component to minimize the bump; what remains is the irreducible provider-branch wiring. Fifth bump on this modal (969->989->993->998->1030->1056); structural shrink tracked in #3501.", "_rebaseline_2026_07_21_8027_grok_cli_auth_json_paste": "PR #8027 (RaviTharuma, fix(grok-cli) #7610) own growth: OAuthModal.tsx 1080->1100 (gate units). Requires the full ~/.grok/auth.json (with refresh_token) on the paste-import path instead of a bare JWT, at the existing paste-token chokepoint (renamed tab label, updated instructions/placeholder, textarea for the auth.json blob, inline error surface). The validation logic itself (parseGrokCliPasteToken, previously an inline ~75-line function) was extracted to the new src/lib/oauth/utils/grokCliAuthJson.ts leaf module — mirroring the #6636/#7546 extraction precedent — so only the irreducible UI wiring remains here. Sixth bump on this modal (969->989->993->998->1030->1056->1100); structural shrink tracked in #3501.", "src/shared/components/OAuthModal.tsx": 1100, + "_rebaseline_2026_07_22_8213_requestloggerdetail_unblock_ui": "PR #8213 (hartmark, fix/gemini-tpm-quota-cooldown-wait) own growth: src/shared/components/RequestLoggerDetail.tsx 799->941 (+142, entirely this PR's diff — no other commit touched this file between the PR's merge-base and the release tip; crosses the general 800-line new-file cap so is frozen here for the first time). Adds a collapsible section header (open/expand-less toggle) plus per-log-entry unblock (`unblocking`/`cleared` state, isCombo503 detection) so the request-logger detail panel surfaces the same Gemini TPM cooldown-wait / model-lockout unblock action introduced by this PR at the individual-request level (mirrors the health-page bulk unblock action added in the same PR). Covered by the PR's own dashboard/resilience test additions.", + "src/shared/components/RequestLoggerDetail.tsx": 941, "src/shared/components/RequestLoggerV2.tsx": 1629, "src/shared/components/analytics/charts.tsx": 1558, "_rebaseline_2026_07_10_6318_omp_letta": "PR #6318 (@hamsa0x7, omp+letta CLI integrations) own growth: cliTools.ts (+53 = 2 registry entries incl. omp docsUrl) and cliRuntime.ts (+18 = runtime-detection wiring for the 2 new tools). Cohesive registry/wiring growth at the existing chokepoints; scope reduced from the original 5 tools (pi/codewhale/jcode shipped separately).", @@ -299,7 +304,8 @@ "src/shared/validation/schemas.ts": 2523, "_rebaseline_2026_06_28_5275_correlation_id_extract": "Extraction of the safe CorrelationId subset of #5275 (hartmark) — request correlation id stored in call_logs (migration 109) and returned via the X-Correlation-Id response header, WITHOUT the combo/resilience or build/lazy-loading changes (those stay in #5275). Own growth: callLogs.ts 975->985 (correlation_id column on CallLogSummaryRow + read/map), usageHistory.ts 983->988 (correlationId metadata normalize), chat.ts 1575->1632 (withCorrelationId response wiring + combo-failure log carrying correlationId), chatHelpers.ts new 811 (withCorrelationId helper + reqId threading; was 791786 (single ProviderAccountRoutingCard mount + import), auth.ts 2448->2458 (providerStrategies override resolution: fallbackStrategy/stickyRoundRobinLimit per-provider cascade in getProviderCredentials). Both additive, zero unrelated refactor; new UI/logic lives in new files (ProviderAccountRoutingCard.tsx, RoutingStrategyCard.tsx, rrState.ts::resolveComboStickyRoundRobinLimit). chat.ts value below reflects the current release tip (grown by other concurrent PRs, e.g. #6640), not this PR own change.", - "src/sse/handlers/chat.ts": 1797, + "_rebaseline_2026_07_22_8213_chat_abandoned_target_abort": "PR #8213 (hartmark, fix/gemini-tpm-quota-cooldown-wait) own growth: src/sse/handlers/chat.ts 1794->1860 (+66, measured against the PR's own merge-base — the release tip separately carries an unrelated -5 net shrink from #8013's antigravity callable-catalog alignment, which this PR's branch does not include and this entry does not cover). Adds resolveDispatchClientRawRequest(): merges a per-target modelAbortSignal into clientRawRequest.signal (via mergeAbortSignals) so a combo target abandoned by comboTargetTimeoutMs actually observes its own abort and reaches its cleanup path, instead of hanging forever inside withRateLimit/acquireAccountSemaphore and leaking a permanent 'pending' dashboard entry (live incident, log id 1784418258231-14961a). Also wires combo-exhausted rejection logging to capture request body + attempted models via the new rejectedRequestUsage helper. Irreducible additions at the existing chat dispatch chokepoint. Covered by the PR's own combo-config + integration test additions.", + "src/sse/handlers/chat.ts": 1861, "_rebaseline_2026_07_20_7779_routingcombo_thread": "PR #7779 own growth: chatHelpers.ts 876->877 (+1, thread routingComboId into executeChatWithBreaker for compression-combo assignment). Frozen so it can only shrink.", "src/sse/handlers/chatHelpers.ts": 878, "src/sse/services/auth.ts": 2462, @@ -343,7 +349,8 @@ "tests/unit/chatcore-sanitization.test.ts": 831, "tests/unit/chatcore-translation-paths.test.ts": 2810, "tests/unit/chatgpt-web.test.ts": 3170, - "tests/unit/combo-config.test.ts": 881, + "_rebaseline_2026_07_22_8213_combo_config_cooldown_wait_tests": "PR #8213 (hartmark, fix/gemini-tpm-quota-cooldown-wait) own growth: tests/unit/combo-config.test.ts 880->940 (+60, entirely this PR's diff — testFrozen add covering isComboCooldownWaitEligible (gating cooldown-wait to auto/quota-share strategies with the feature enabled) and resolveComboTargetTimeoutMsForCombo (raising the per-target timeout floor to cover the cooldown-wait budget + buffer for eligible strategies, fixing the 120s default cutting off a 130s wait early and returning a synthetic 524)). Covered by the new assertions themselves.", + "tests/unit/combo-config.test.ts": 940, "tests/unit/combo-routing-engine.test.ts": 3409, "tests/unit/combo-strategy-fallbacks.test.ts": 880, "tests/unit/db-core-init.test.ts": 877, diff --git a/docs/architecture/RESILIENCE_GUIDE.md b/docs/architecture/RESILIENCE_GUIDE.md index 799cdfdd71..d1553c50d4 100644 --- a/docs/architecture/RESILIENCE_GUIDE.md +++ b/docs/architecture/RESILIENCE_GUIDE.md @@ -209,11 +209,14 @@ on). Without a `max_concurrent` cap the behavior is unchanged. ### Combo cooldown-aware retry -For quota-share combos only, a request that would crystallize a 429 for a SHORT -transient cooldown waits it out and re-dispatches instead of returning the 429. -Bounded by `comboCooldownWait` (`enabled`, `maxWaitMs` 5s, `maxAttempts` 2, -`budgetMs` 8s) in **Settings → Resilience**. It never waits on `quota_exhausted` -(locked until midnight) or auth/not-found reasons. +For quota-share and `auto` combos, a request that would crystallize a 429 for a +SHORT transient cooldown waits it out and re-dispatches instead of returning +the 429 — this covers Gemini-class TPM/RPM windows (~60s retry-after) on a +multi-model `auto` combo, e.g. both targets of a 2-model combo hitting a +per-model rate limit. Bounded by `comboCooldownWait` (`enabled`, `maxWaitMs` +65s, `maxAttempts` 2, `budgetMs` 130s, hard ceiling 90s) in **Settings → +Resilience**. It never waits on `quota_exhausted` (locked until midnight) or +auth/not-found reasons. --- diff --git a/open-sse/config/geminiRateLimits.json b/open-sse/config/geminiRateLimits.json index a1ae15dc7f..c33f580345 100644 --- a/open-sse/config/geminiRateLimits.json +++ b/open-sse/config/geminiRateLimits.json @@ -8,8 +8,8 @@ "imagen-4-generate": { "rpm": -1, "rpd": 25, "tpm": -1 }, "imagen-4-ultra-generate": { "rpm": -1, "rpd": 25, "tpm": -1 }, "imagen-4-fast-generate": { "rpm": -1, "rpd": 25, "tpm": -1 }, - "gemma-4-26b-it": { "rpm": 15, "rpd": 1500, "tpm": -1 }, - "gemma-4-31b-it": { "rpm": 15, "rpd": 1500, "tpm": -1 }, + "gemma-4-26b-it": { "rpm": 16000, "rpd": 14400, "tpm": 16000 }, + "gemma-4-31b-it": { "rpm": 16000, "rpd": 14400, "tpm": 16000 }, "gemini-embedding-exp-03-07": { "rpm": 100, "rpd": 1000, "tpm": 30000 }, "gemini-3.5-flash": { "rpm": 5, "rpd": 20, "tpm": 250000 }, "gemini-3.1-flash-lite": { "rpm": 15, "rpd": 500, "tpm": 250000 }, diff --git a/open-sse/handlers/chatCore.ts b/open-sse/handlers/chatCore.ts index 74454da24a..78cc5c25cb 100644 --- a/open-sse/handlers/chatCore.ts +++ b/open-sse/handlers/chatCore.ts @@ -343,7 +343,12 @@ import { getModelScopeRetryDelayMs, isModelScopeProvider, } from "../services/modelscopePolicy.ts"; -import { incrementRequestCount } from "../services/geminiRateLimitTracker.ts"; +import { + incrementRequestCount, + incrementTokenUsage, + isTpmExhausted, + isRpmExhausted, +} from "../services/geminiRateLimitTracker.ts"; // ── Global memory pressure guard ──────────────────────────────────────── // Prevents OOM by rejecting new requests when V8 heap exceeds threshold. @@ -3102,6 +3107,25 @@ export async function handleChatCore({ } } + // ── Gemini pre-dispatch TPM / RPM guard ────────────────────────────────── + // Avoids guaranteed upstream 429 by checking local sliding-window counters + // before dispatch. Fail-open: counter errors → allow through. + if (provider === "gemini") { + try { + if (isTpmExhausted(effectiveModel)) { + trackPendingRequest(model, provider, connectionId, false); + return createErrorResult( + HTTP_STATUS.RATE_LIMITED, + `Gemini TPM rate limit reached for ${effectiveModel}. Please try again later.`, + null, + "GEMINI_TPM_EXHAUSTED" + ); + } + } catch (err) { + log?.warn?.("GEMINI_RATE_LIMIT", "Pre-dispatch TPM check failed; allowing request", { err }); + } + } + // Execute request using executor (handles URL building, headers, fallback, transform) let providerResponse; let providerUrl; @@ -3219,7 +3243,13 @@ export async function handleChatCore({ status: failureStatus, error: failureMessage, providerRequest: finalBody || translatedBody, - clientResponse: buildErrorBody(failureStatus, failureMessage), + // On a client-abort (AbortError), the client already disconnected before + // we ever got here — this body is what we WOULD have sent, not what was + // actually delivered. Logging it as `clientResponse` is misleading (the + // dashboard reads that field as "what the client received"), so omit it + // for this case; `error` above already records the failure reason. + clientResponse: + error.name === "AbortError" ? undefined : buildErrorBody(failureStatus, failureMessage), claudeCacheMeta: claudePromptCacheLogMeta, cacheSource: "upstream", }); @@ -4081,6 +4111,14 @@ export async function handleChatCore({ const usage = extractUsageFromResponse(responseBody, provider); if (usage && typeof usage === "object") { attachCompressionUsageReceiptAfterAnalytics(usage as Record, "provider"); + // Track Gemini token consumption for TPM rate-limit pre-check + if (provider === "gemini") { + const promptTokens = + typeof (usage as Record).prompt_tokens === "number" + ? ((usage as Record).prompt_tokens as number) + : 0; + if (promptTokens > 0) incrementTokenUsage(model, promptTokens); + } } // Context Editing telemetry: when the delegated server-side clear actually ran, @@ -4604,6 +4642,14 @@ export async function handleChatCore({ // Track cache token metrics for streaming responses if (streamUsage && typeof streamUsage === "object") { attachCompressionUsageReceiptAfterAnalytics(streamUsage as Record, "stream"); + // Track Gemini token consumption for TPM rate-limit pre-check + if (provider === "gemini") { + const promptTokens = + typeof (streamUsage as Record).prompt_tokens === "number" + ? ((streamUsage as Record).prompt_tokens as number) + : 0; + if (promptTokens > 0) incrementTokenUsage(model, promptTokens); + } } recordStreamingUsageStats(streamUsage, { provider, diff --git a/open-sse/services/accountFallback.ts b/open-sse/services/accountFallback.ts index c24c836e45..16cfd2590c 100644 --- a/open-sse/services/accountFallback.ts +++ b/open-sse/services/accountFallback.ts @@ -34,7 +34,12 @@ import { resolveProviderId } from "../../src/shared/constants/providers"; import { resolveUseUpstream429BreakerHints } from "../../src/shared/utils/providerHints"; import { getCodexModelScope } from "../config/codexQuotaScopes.ts"; import { getQuotaScopedModelForProvider } from "./antigravityQuotaFamily.ts"; -import { isRpdExhausted, isRpmExhausted } from "./geminiRateLimitTracker.ts"; +import { + classifyGeminiQuotaMetricFromText, + isRpdExhausted, + isRpmExhausted, + isTpmExhausted, +} from "./geminiRateLimitTracker.ts"; import { setConnectionRateLimitUntil } from "@/lib/db/providers"; import { parseRetryHintFromJsonBody, @@ -1121,6 +1126,15 @@ export function parseRetryFromErrorText(errorText: unknown): number | null { return computeDurationMs(resetsInMatch); } + // Gemini phrasing: "Please retry in 54.472178091s" (fractional seconds). + const retryInSecMatch = /please retry in (\d+(?:\.\d+)?)\s*s/i.exec(msg); + if (retryInSecMatch?.[1]) { + const sec = Number.parseFloat(retryInSecMatch[1]); + if (Number.isFinite(sec) && sec > 0) { + return Math.min(Math.round(sec * 1000), MAX_PROVIDER_COOLDOWN_MS); + } + } + return parseDayGranularityResetMs(msg, MAX_PROVIDER_COOLDOWN_MS); } @@ -1458,6 +1472,45 @@ export function checkFallbackError( }; } + // Gemini-specific check — MUST run before isCreditsExhausted/ + // isDailyQuotaExhausted/the generic text classifier below: Gemini's free- + // tier 429 boilerplate literally says "You exceeded your current quota, + // please check your plan and billing details" for EVERY limit type + // (RPM/TPM/RPD alike), which collides with CREDITS_EXHAUSTED_SIGNALS' + // `"exceeded your current quota"` entry (added for OpenAI-style terminal + // billing errors) — that generic check would otherwise short-circuit + // straight to QUOTA_EXHAUSTED before this Gemini-specific block ever runs + // (#7360). Gated on provider === "gemini" so it cannot affect any other + // provider's genuine credits-exhausted classification. + // + // Preference order: + // 1. The upstream error text's own metric name (authoritative — it is + // Google's own signal, e.g. "...free_tier_input_token_count..." = TPM). + // Required because the local per-model counters below only increment + // on a SUCCESSFUL response; a request that gets rejected — especially + // the first of several concurrent requests racing to trip the same + // per-minute limit — never contributes to the counter, so it can read + // 0 at the exact moment it needs to report exhaustion. + // 2. Local per-model counters, when the text names no metric. + if (provider === "gemini" && status === HTTP_STATUS.RATE_LIMITED && _model) { + const metricClass = classifyGeminiQuotaMetricFromText(errorStr); + if (metricClass === "rpd") { + return buildRetryableFallback(RateLimitReason.QUOTA_EXHAUSTED); + } + if (metricClass === "rpm" || metricClass === "tpm") { + return buildRetryableFallback(RateLimitReason.RATE_LIMIT_EXCEEDED); + } + if (isRpdExhausted(_model)) { + return buildRetryableFallback(RateLimitReason.QUOTA_EXHAUSTED); + } + if (isRpmExhausted(_model)) { + return buildRetryableFallback(RateLimitReason.RATE_LIMIT_EXCEEDED); + } + if (isTpmExhausted(_model)) { + return buildRetryableFallback(RateLimitReason.RATE_LIMIT_EXCEEDED); + } + } + // T10 (sub2api #1169): Credits/quota exhausted — long cooldown, distinct from rate limit if (shouldUseQuotaSignal && isCreditsExhausted(errorStr)) { return { @@ -1542,19 +1595,6 @@ export function checkFallbackError( } } - // Gemini-specific: use known published RPM/RPD limits to distinguish 429 types. - // Gemini returns the same error body for both, so we use per-model request - // counters to decide: if daily count >= RPD → quota_exhausted (midnight lockout); - // if minute count >= RPM → rate_limit_exceeded (exponential backoff). - if (provider === "gemini" && status === HTTP_STATUS.RATE_LIMITED && _model) { - if (isRpdExhausted(_model)) { - return buildRetryableFallback(RateLimitReason.QUOTA_EXHAUSTED); - } - if (isRpmExhausted(_model)) { - return buildRetryableFallback(RateLimitReason.RATE_LIMIT_EXCEEDED); - } - } - const configuredRule = isRateLimitStatus && !preserveQuota429 ? matchErrorRuleByStatus(status) diff --git a/open-sse/services/combo.ts b/open-sse/services/combo.ts index 1a4b88de30..b19fe68311 100644 --- a/open-sse/services/combo.ts +++ b/open-sse/services/combo.ts @@ -37,6 +37,7 @@ import { resolveComboConfig, getDefaultComboConfig, resolveComboQueueDepth, + isComboCooldownWaitEligible, } from "./comboConfig.ts"; import { maybeGenerateHandoff, @@ -1448,12 +1449,15 @@ export async function handleComboChat({ let globalAttempts = 0; - // Quota-share cooldown-aware retry (Variante A). Only quota-share (qtSd/) - // combos opt in: when the set loop would crystallize a 429 model_cooldown - // because the target hit a SHORT transient cooldown, we wait it out and - // re-run the whole set loop instead of propagating the 429. `globalAttempts` - // persists across these waits so MAX_GLOBAL_ATTEMPTS still bounds total work. - // The wait happens at the crystallization point. The only semaphore slot the + // Cooldown-aware retry (Variante A). Originally quota-share (qtSd/) only; + // extended to "auto" combos too (#7360 — a 2-model "default" auto combo + // hitting Gemini TPM/RPM on both targets was crystallizing a 503 "all + // targets exhausted" after ~6s instead of waiting out the ~60s TPM window): + // when the set loop would crystallize a 429 model_cooldown because the + // target hit a SHORT transient cooldown, we wait it out and re-run the + // whole set loop instead of propagating the 429. `globalAttempts` persists + // across these waits so MAX_GLOBAL_ATTEMPTS still bounds total work. The + // wait happens at the crystallization point. The only semaphore slot the // quota-share path may hold is the FASE 2.1 per-connection concurrency slot // (acquired once around dispatchWithCooldownRetry below); it is intentionally // kept across the wait so the account stays "busy", and is released by the @@ -1465,7 +1469,10 @@ export async function handleComboChat({ // re-runs ONLY the set loop (selection / shadow routing / setup above stay // untouched), preserving the pre-existing `continue`-to-top-of-set-loop // semantics exactly. - const comboCooldownWaitEnabled = resilienceSettings.comboCooldownWait.enabled; + const comboCooldownWaitEnabled = isComboCooldownWaitEligible( + strategy, + resilienceSettings.comboCooldownWait + ); let comboCooldownAttempt = 0; let comboCooldownBudgetLeftMs = resilienceSettings.comboCooldownWait.budgetMs; @@ -1489,6 +1496,21 @@ export async function handleComboChat({ strategy === "quota-share" && resilienceSettings.quotaShareConcurrencyLimit.enabled; const dispatchWithCooldownRetry = async (): Promise => { + // #7360: hoisted OUTSIDE the setTry loop (not reset each iteration) so they + // persist across set retries. Without this, a combo whose targets all get + // locked out on setTry 0 would have every SUBSEQUENT setTry pre-skip both + // targets via the isModelLocked check (no real dispatch, so these are never + // touched) — and the wait/crystallize decision below only runs on the FINAL + // setTry, which would see lastStatus/earliestRetryAfter reset to null and + // wrongly fall into the generic "all accounts inactive" 503 instead of ever + // reaching the cooldown-aware wait, even though a real 429 with a known + // retry-after WAS observed earlier in the same dispatch (live incident, + // #7360 follow-up: log id 1784416706646-51 — 6.9s to a 503 despite both + // targets reporting a clean 40s rate_limit lockout on the first attempt). + let lastError: string | null = null; + let earliestRetryAfter: ComboRetryAfter | null = null; + let lastStatus: number | null = null; + for (let setTry = 0; setTry <= maxSetRetries; setTry++) { // #1731: Per-set-iteration set of providers whose quota is fully exhausted. // Reset each retry so providers excluded in a previous attempt get another chance. @@ -1514,9 +1536,6 @@ export async function handleComboChat({ } } - let lastError: string | null = null; - let earliestRetryAfter: ComboRetryAfter | null = null; - let lastStatus: number | null = null; const startTime = Date.now(); let fallbackCount = 0; let recordedAttempts = 0; @@ -2134,7 +2153,26 @@ export async function handleComboChat({ (typeof parsedError === "string" ? parsedError : null) || errorBody?.message || errorText; - retryAfter = errorBody?.retryAfter || null; + // Live incident (log id 1784457764961-73 follow-up): the pre-dispatch + // "all credentials cooling down" rejection (buildModelCooldownBody / + // handleNoCredentials in src/sse/handlers/chatHelpers.ts) nests its + // retry hint as error.retry_after (ISO string) / error.reset_seconds + // (seconds), not the top-level `retryAfter` every other 429 shape + // uses. Without this fallback, lastStatus gets recorded (fixed above) + // but earliestRetryAfter stays null, so the final check falls through + // to the generic "all combo models unavailable" error instead of ever + // reaching the cooldown-wait decision — same class of bug, different + // response shape. + const nestedRetryAfter = + typeof parsedError === "object" ? (parsedError?.retry_after ?? null) : null; + const nestedResetSeconds = + typeof parsedError === "object" ? (parsedError?.reset_seconds ?? null) : null; + retryAfter = + errorBody?.retryAfter || + nestedRetryAfter || + (typeof nestedResetSeconds === "number" && nestedResetSeconds > 0 + ? new Date(Date.now() + nestedResetSeconds * 1000).toISOString() + : null); } } catch { /* Clone parse failed */ @@ -2347,6 +2385,16 @@ export async function handleComboChat({ isModelLocked(provider, targetWithConnection.connectionId || "", rawModel) ) { log.info("COMBO", `Skipping retry for ${modelStr} — model lockout active`); + // Live incident (log id 1784457764961-73): earliestRetryAfter is already + // captured above from THIS dispatch's own response, but lastStatus was + // never recorded on this bail-out path — so once every target in the set + // hit an existing lockout, lastStatus stayed null and the final `if + // (!lastStatus)` check crystallized an immediate ALL_ACCOUNTS_INACTIVE 503 + // instead of ever reaching the `if (earliestRetryAfter)` cooldown-wait + // decision below, even though a real 429 with a short (~1min) retry-after + // was just observed. Recording it here mirrors the "done retrying" path. + lastError = errorText || String(result.status); + if (!lastStatus) lastStatus = result.status; if (i > 0) fallbackCount++; return null; } @@ -2377,6 +2425,10 @@ export async function handleComboChat({ } if (lockoutRecorded) { log.info("COMBO", `Skipping retry for ${modelStr} — model lockout active`); + // Same fix as the already-locked branch above — this is the + // first-failure lockout path, so lastStatus needs recording here too. + lastError = errorText || String(result.status); + if (!lastStatus) lastStatus = result.status; if (i > 0) fallbackCount++; return null; } @@ -2424,15 +2476,18 @@ export async function handleComboChat({ log.warn("COMBO", `Model ${modelStr} failed, trying next`, { status: result.status }); // #5976: per-model-quota providers (Gemini, GitHub, etc.) multiplex models - // behind one connection. A model-level 500 must NOT cool down the entire - // provider — sibling models may still succeed. Skip cooldown recording for - // these providers on 500 errors so the next target can try. + // behind one connection. A model-level 500 or 429 (RPM) must NOT cool down + // the entire provider — sibling models may still succeed. Skip cooldown + // recording for these providers on 500/429 errors so the next target can try. if ( resilienceSettings.providerCooldown.enabled && provider && provider !== "unknown" && !requestScopedFailure && - !(result.status === 500 && hasPerModelQuota(provider, rawModel)) + !( + (result.status === 500 || result.status === 429) && + hasPerModelQuota(provider, rawModel) + ) ) { recordProviderCooldown( provider, @@ -3434,7 +3489,7 @@ async function handleRoundRobinCombo({ provider !== "unknown" && !requestScopedFailure && !( - result.status === 500 && + (result.status === 500 || result.status === 429) && hasPerModelQuota(provider, parseModel(modelStr).model || modelStr) ) ) { diff --git a/open-sse/services/combo/comboSetup.ts b/open-sse/services/combo/comboSetup.ts index 1d2feb19dd..6fcfb9092a 100644 --- a/open-sse/services/combo/comboSetup.ts +++ b/open-sse/services/combo/comboSetup.ts @@ -17,11 +17,7 @@ import { } from "../contextHandoff.ts"; import { getLastSessionModel } from "../../../src/lib/db/contextHandoffs.ts"; import { applyComboAgentMiddleware } from "../comboAgentMiddleware.ts"; -import { - resolveComboSetupConfig, - resolveComboTargetTimeoutMs, - DEFAULT_COMBO_TARGET_TIMEOUT_MS, -} from "../comboConfig.ts"; +import { resolveComboSetupConfig, resolveComboTargetTimeoutMsForCombo } from "../comboConfig.ts"; import { resolveResilienceSettings } from "../../../src/lib/resilience/settings"; import { FETCH_TIMEOUT_MS } from "../../config/constants.ts"; import { deriveComboSessionKey } from "./autoStrategy.ts"; @@ -112,10 +108,11 @@ export function phaseComboSetup(ctx: ComboContext): ComboSetup { // Use config cascade before dispatch so all strategies, pinned context routes, // and round-robin targets share the same timeout policy. const config = resolveComboSetupConfig(combo, settings); - const comboTargetTimeoutMs = resolveComboTargetTimeoutMs( + const comboTargetTimeoutMs = resolveComboTargetTimeoutMsForCombo( config, FETCH_TIMEOUT_MS, - DEFAULT_COMBO_TARGET_TIMEOUT_MS + strategy, + resilienceSettings.comboCooldownWait ); const comboTimeoutMs = config.comboTimeoutMs || 0; const reasoningTokenBufferEnabled = config.reasoningTokenBufferEnabled !== false; diff --git a/open-sse/services/combo/types.ts b/open-sse/services/combo/types.ts index 26406bb693..9371d11529 100644 --- a/open-sse/services/combo/types.ts +++ b/open-sse/services/combo/types.ts @@ -13,7 +13,17 @@ export const RESET_WINDOW_NAMES = ["weekly", "session", "monthly"] as const; export type ComboRetryAfter = string | number | Date; export type ComboErrorBody = { - error?: { code?: string | null; message?: string | null } | string; + error?: + | { + code?: string | null; + message?: string | null; + // buildModelCooldownBody (open-sse/utils/error.ts) nests its retry hint + // here instead of at the top level — see the retryAfter fallback in + // combo.ts's dispatchWithCooldownRetry error extraction. + retry_after?: string | null; + reset_seconds?: number | null; + } + | string; message?: string | null; retryAfter?: ComboRetryAfter | null; } | null; diff --git a/open-sse/services/comboConfig.ts b/open-sse/services/comboConfig.ts index 27cf0a1a98..eada64f694 100644 --- a/open-sse/services/comboConfig.ts +++ b/open-sse/services/comboConfig.ts @@ -6,6 +6,7 @@ */ import { MAX_TIMER_TIMEOUT_MS } from "../../src/shared/utils/runtimeTimeouts.ts"; +import type { ComboCooldownWaitSettings } from "../../src/lib/resilience/settings.ts"; import type { ResponseValidationConfig } from "./combo/responseValidation.ts"; /** @@ -26,6 +27,56 @@ export const PRE_SCREEN_CONCURRENCY = 5; */ export const DEFAULT_COMBO_TARGET_TIMEOUT_MS = 120_000; +/** + * Small buffer added on top of the combo-cooldown-wait budget (see below) when deriving + * the per-target timeout floor for wait-eligible combos. The wait itself is bounded by + * `resilienceSettings.comboCooldownWait.budgetMs`; this buffer only needs to cover the + * dispatch overhead between the wait resolving and the upstream response headers + * arriving (streaming responses aren't cut short past that point — see + * DEFAULT_COMBO_TARGET_TIMEOUT_MS above), not a full generation. + */ +export const COMBO_TARGET_TIMEOUT_WAIT_BUFFER_MS = 10_000; + +/** + * Whether a combo's cooldown-aware wait+retry (#7360) engages for this request: only + * "quota-share" and "auto" strategies wait out a short transient cooldown instead of + * crystallizing a 429 into a combo-level failure, and only when the operator has the + * feature enabled. Shared by combo.ts (to decide whether to wait) and comboSetup.ts (to + * size the per-target timeout floor so it doesn't cut the wait off early — see + * resolveComboTargetTimeoutMsForCombo below). + */ +export function isComboCooldownWaitEligible( + strategy: string, + comboCooldownWait: Pick +): boolean { + return (strategy === "quota-share" || strategy === "auto") && comboCooldownWait.enabled; +} + +/** + * Per-target timeout floor to use for a combo, accounting for the cooldown-wait budget. + * When the combo is wait-eligible (see isComboCooldownWaitEligible), a single target's + * dispatch can legitimately wait out cooldowns for up to `comboCooldownWait.budgetMs` + * before it resolves — so the per-target timeout must never be shorter than that budget, + * or the wait gets cut off mid-retry and the target times out with a synthetic 524 + * (open-sse/services/combo/targetTimeoutRunner.ts) instead of completing the wait. This + * only raises the *default* floor; an operator's explicit `targetTimeoutMs` on the combo + * still wins (see resolveComboTargetTimeoutMs). + */ +export function resolveComboTargetTimeoutMsForCombo( + config: Record | null | undefined, + upstreamTimeoutMs: number, + strategy: string, + comboCooldownWait: Pick +): number { + const defaultTimeoutMs = isComboCooldownWaitEligible(strategy, comboCooldownWait) + ? Math.max( + DEFAULT_COMBO_TARGET_TIMEOUT_MS, + comboCooldownWait.budgetMs + COMBO_TARGET_TIMEOUT_WAIT_BUFFER_MS + ) + : DEFAULT_COMBO_TARGET_TIMEOUT_MS; + return resolveComboTargetTimeoutMs(config, upstreamTimeoutMs, defaultTimeoutMs); +} + /** * Default pre-cascade semaphore queue depth for round-robin combos (#3872). When a * combo member's concurrency slot is saturated, this many requests wait in the diff --git a/open-sse/services/geminiRateLimitTracker.ts b/open-sse/services/geminiRateLimitTracker.ts index 7ede8a4f88..4acffce999 100644 --- a/open-sse/services/geminiRateLimitTracker.ts +++ b/open-sse/services/geminiRateLimitTracker.ts @@ -1,9 +1,10 @@ /** - * In-memory request counters for Gemini models — tracks both RPD (daily) - * and RPM (sliding 60s window) so that 429 responses can be classified - * as either quota_exhausted (RPD hit) or rate_limit_exceeded (RPM hit). + * In-memory request/token counters for Gemini models — tracks both RPD (daily), + * RPM (sliding 60s window), and TPM (sliding 60s token window) so that 429 + * responses can be classified as either quota_exhausted (RPD hit), + * rate_limit_exceeded (RPM hit), or token_rate_exceeded (TPM hit). * - * Gemini returns identical error bodies for both types, so we rely on + * Gemini returns identical error bodies for all three, so we rely on * published per-model limits from geminiRateLimits.json to distinguish them. * * Counters are incremented on every Gemini request so that once usage @@ -25,6 +26,10 @@ const dailyCounts = new Map(); const minuteWindows = new Map(); +// ── TPM (sliding 60s token window) state ───────────────────────────────────── + +const tokenWindows = new Map(); + // ── Helpers ────────────────────────────────────────────────────────────────── function toDateKey(): string { @@ -37,7 +42,7 @@ function stripModelPrefix(modelId: string): string { return modelId.replace(/^gemini\//, "").trim(); } -function lookupValue(modelId: string, field: "rpm" | "rpd"): number { +function lookupValue(modelId: string, field: "rpm" | "rpd" | "tpm"): number { if (!modelId) return 0; const key = stripModelPrefix(modelId); const entry = (geminiLimits as Record>)[key]; @@ -99,7 +104,6 @@ function pruneMinuteWindow(key: string): void { const cutoff = now - 60_000; const timestamps = minuteWindows.get(key); if (!timestamps) return; - // Keep only timestamps >= cutoff let i = 0; while (i < timestamps.length && timestamps[i] < cutoff) i++; if (i > 0) { @@ -107,6 +111,18 @@ function pruneMinuteWindow(key: string): void { } } +function pruneTokenWindow(key: string): void { + const now = Date.now(); + const cutoff = now - 60_000; + const entries = tokenWindows.get(key); + if (!entries) return; + let i = 0; + while (i < entries.length && entries[i] < cutoff) i += 2; + if (i > 0) { + tokenWindows.set(key, entries.slice(i)); + } +} + export function incrementMinuteRequestCount(modelId: string): void { if (!modelId) return; const key = stripModelPrefix(modelId); @@ -129,6 +145,76 @@ export function isRpmExhausted(modelId: string): boolean { return getMinuteRequestCount(modelId) >= rpm; } +// ── TPM exports ────────────────────────────────────────────────────────────── + +export function getModelTpm(modelId: string): number { + return lookupValue(modelId, "tpm"); +} + +/** + * Record prompt token consumption for a Gemini model. + * Allows the per-minute token pre-check to avoid 429s. + */ +export function incrementTokenUsage(modelId: string, promptTokens: number): void { + if (!modelId || !Number.isFinite(promptTokens) || promptTokens <= 0) return; + const key = stripModelPrefix(modelId); + pruneTokenWindow(key); + const entries = tokenWindows.get(key) ?? []; + entries.push(Date.now(), promptTokens); + tokenWindows.set(key, entries); +} + +export function getMinuteTokenCount(modelId: string): number { + if (!modelId) return 0; + const key = stripModelPrefix(modelId); + pruneTokenWindow(key); + const entries = tokenWindows.get(key); + if (!entries) return 0; + let total = 0; + for (let i = 1; i < entries.length; i += 2) { + total += entries[i]; + } + return total; +} + +export function isTpmExhausted(modelId: string): boolean { + const tpm = getModelTpm(modelId); + if (tpm <= 0) return false; + return getMinuteTokenCount(modelId) >= tpm; +} + +// ── Text-based metric classification ───────────────────────────────────────── + +/** + * Extract which quota class ("rpd" | "rpm" | "tpm") a Gemini 429 error text + * names, directly from Google's own metric identifier — e.g.: + * "Quota exceeded for metric: generativelanguage.googleapis.com/ + * generate_content_free_tier_input_token_count, limit: 16000" + * + * This is authoritative (Google's own signal) and must be checked BEFORE the + * local usage counters (isRpdExhausted/isRpmExhausted/isTpmExhausted): those + * counters only increment via `incrementTokenUsage`/`incrementRequestCount`, + * which fire AFTER a request completes successfully. A request that gets + * REJECTED — especially the first of several concurrent requests that all + * trip the same per-minute limit before any of them completes — never + * contributes to the local counter, so `isTpmExhausted` reads 0 at the exact + * moment it needs to return true, and the generic "quota exceeded" text + * classifier (which matches ALL Gemini 429 bodies, per the file header) + * mis-classifies a genuine TPM/RPM burst as QUOTA_EXHAUSTED (midnight lockout) + * instead of RATE_LIMIT_EXCEEDED (short cooldown). + */ +export function classifyGeminiQuotaMetricFromText( + errorText: string | null | undefined +): "rpd" | "rpm" | "tpm" | null { + if (!errorText) return null; + const lower = errorText.toLowerCase(); + if (!lower.includes("generativelanguage.googleapis.com")) return null; + if (lower.includes("_per_day") || lower.includes("per day")) return "rpd"; + if (lower.includes("input_token_count") || lower.includes("token_count")) return "tpm"; + if (lower.includes("_requests")) return "rpm"; + return null; +} + // ── Increment both (convenience) ───────────────────────────────────────────── /** Increment both daily and minute counters for a Gemini request. */ @@ -137,9 +223,17 @@ export function incrementRequestCount(modelId: string): void { incrementMinuteRequestCount(modelId); } +// ── Composite check ────────────────────────────────────────────────────────── + +/** Returns true if either RPM or TPM is exhausted for this model. */ +export function isMinuteRateExhausted(modelId: string): boolean { + return isRpmExhausted(modelId) || isTpmExhausted(modelId); +} + // ── Reset (testing) ────────────────────────────────────────────────────────── export function resetCounters(): void { dailyCounts.clear(); minuteWindows.clear(); + tokenWindows.clear(); } diff --git a/open-sse/services/rateLimitManager.ts b/open-sse/services/rateLimitManager.ts index 912452b42f..af21ca814d 100644 --- a/open-sse/services/rateLimitManager.ts +++ b/open-sse/services/rateLimitManager.ts @@ -262,14 +262,32 @@ function watchdogTick() { limiters.delete(key); lastDispatchAt.delete(key); limiterLastUsed.delete(key); - // Do NOT call limiter.stop() — it permanently rejects future .schedule() calls with - // "This limiter has been stopped". In-flight requests still holding a reference to - // the old instance cannot be redirected to a new one, causing spurious 502 bursts. - // Call disconnect() (not stop()) to release Bottleneck's internal heartbeat timer - // without poisoning the queue for any remaining in-flight jobs. This prevents the - // heartbeat-timer memory leak observed when many limiters are evicted at runtime. - // getLimiter() lazily allocates a fresh Bottleneck on the next call. - trackAsyncOperation(limiter.disconnect()); + // Live incident (log id 1784465227489-a2cbc0): disconnect() releases the + // heartbeat timer but does NOT reject the QUEUED jobs already sitting on + // this instance — withRateLimit's `limiter.schedule()` for those callers + // then just hangs forever (nothing will ever dequeue them; getLimiter() + // only hands out a FRESH instance to future callers), leaving the + // dispatch orphaned until the outer ~300s per-target timeout eventually + // aborts it. Real clients routinely give up (and retry) well before that + // — this specific incident's client aborted at ~60s having never reached + // the provider at all (queued=2 running=0 executing=0 the entire time). + // + // stop({ dropWaitingJobs: true }) rejects exactly the RECEIVED/QUEUED/ + // RUNNING jobs on THIS instance immediately (Bottleneck's own contract — + // see node_modules/bottleneck/bottleneck.d.ts StopOptions) so those + // withRateLimit() callers reject right away instead of hanging, letting + // combo's fallback/cooldown-wait engage within seconds instead of minutes. + // This is safe against the previously-documented "spurious 502 bursts" + // concern: the wedge condition checked above already requires + // RUNNING === 0 && EXECUTING === 0, so no job that's actually progressing + // can be caught by this — only ones already confirmed stuck. The instance + // is deleted from `limiters` synchronously (above) before this call, so + // no future getLimiter() call can ever hand out this now-stopped instance + // — the "permanently rejects future .schedule()" behavior stop() has is + // therefore moot; nothing will call .schedule() on it again. + trackAsyncOperation( + limiter.stop({ dropWaitingJobs: true, dropErrorMessage: "rate-limit-watchdog-wedge-reset" }) + ); } } @@ -635,6 +653,21 @@ export async function withRateLimit(provider, connectionId, model, fn, signal = queueErr.code = "RATE_LIMIT_QUEUE_TIMEOUT"; throw queueErr; } + // The watchdog's stop({ dropWaitingJobs: true }) wedge-recovery (above) rejects + // queued jobs with this exact message. Rewrite it the same way as the timeout + // case — a clear, OmniRoute-owned, classifiable error — so combo's transient-error + // handling (which already treats a 502 as retryable) falls back to the next target + // immediately instead of surfacing Bottleneck's internal wording. + if (err?.message === "rate-limit-watchdog-wedge-reset") { + const wedgeErr = new Error( + `Request dropped: the local rate-limit queue for ${model ? `${provider}/${model}` : provider} ` + + `was detected as wedged (stalled with nothing executing) and force-reset. This is OmniRoute's ` + + `own queue recovering, not an upstream error.`, + { cause: err } + ) as Error & { code?: string }; + wedgeErr.code = "RATE_LIMIT_QUEUE_WEDGED"; + throw wedgeErr; + } throw err; } } diff --git a/open-sse/utils/earlyStreamKeepalive.ts b/open-sse/utils/earlyStreamKeepalive.ts index 87d76ebeb5..1ee00354ef 100644 --- a/open-sse/utils/earlyStreamKeepalive.ts +++ b/open-sse/utils/earlyStreamKeepalive.ts @@ -34,17 +34,123 @@ const KEEPALIVE_FRAME = ENCODER.encode(": omniroute-keepalive\n\n"); export const OPENAI_KEEPALIVE_FRAME = ENCODER.encode( 'data: {"id":"omniroute-keepalive","object":"chat.completion.chunk","created":0,"model":"omniroute","choices":[{"index":0,"delta":{},"finish_reason":null}]}\n\n' ); +// #7360 follow-up: the FIRST frame of the slow path carries visible content +// instead of an empty delta, framed as a reasoning/thinking chunk (the same +// shape OmniRoute already emits for real upstream reasoning — see +// open-sse/translator/response/claude-to-openai.ts's createChunk) so +// reasoning-aware clients render it instead of silently ignoring it. This is +// what lets OmniRoute safely wait out a longer Gemini rate-limit cooldown +// (see comboCooldownWait/waitForCooldown budgetMs) without the client's own +// first-event/idle-read timeout firing — the client sees a real byte +// immediately, it just says we're still working on it. +const STARTUP_THINKING_TEXT = "OmniRoute: got request, sending to provider"; +export const OPENAI_STARTUP_THINKING_FRAME = ENCODER.encode( + `data: ${JSON.stringify({ + id: "omniroute-keepalive", + object: "chat.completion.chunk", + created: 0, + model: "omniroute", + choices: [ + { index: 0, delta: { reasoning_content: STARTUP_THINKING_TEXT }, finish_reason: null }, + ], + })}\n\n` +); // Anthropic Messages-format keepalive: a REAL `ping` SSE event, not a comment. // Anthropic clients (Claude Code, the Anthropic SDK) reset their stream/first-token // watchdog on real SSE events but ignore SSE comments (`: ...`), so on a slow first // token the comment frame lets the client abort and retry the stream. Anthropic's own // API emits `event: ping` for exactly this reason; the /v1/messages route mirrors it. export const ANTHROPIC_PING_FRAME = ENCODER.encode('event: ping\ndata: {"type":"ping"}\n\n'); +// Responses API keepalive: a self-contained, self-closed synthetic reasoning +// item (added -> summary_part.added -> text.delta -> summary_part.done), +// matching the abbreviated close pattern open-sse/utils/stream.ts's own +// emitSyntheticResponsesReasoningSummary already uses for real mid-stream +// reasoning. Closed within this one frame (not left dangling open) since the +// real upstream response — once it arrives — starts its own independent +// response.created lifecycle from scratch; this placeholder item never +// carries a response_id and isn't meant to be continued. +const RESPONSES_STARTUP_ITEM_ID = "rs_omniroute_keepalive"; +export const RESPONSES_STARTUP_THINKING_FRAME = ENCODER.encode( + [ + { + event: "response.output_item.added", + data: { + type: "response.output_item.added", + output_index: 0, + item: { id: RESPONSES_STARTUP_ITEM_ID, type: "reasoning", summary: [] }, + }, + }, + { + event: "response.reasoning_summary_part.added", + data: { + type: "response.reasoning_summary_part.added", + item_id: RESPONSES_STARTUP_ITEM_ID, + output_index: 0, + summary_index: 0, + part: { type: "summary_text", text: "" }, + }, + }, + { + event: "response.reasoning_summary_text.delta", + data: { + type: "response.reasoning_summary_text.delta", + item_id: RESPONSES_STARTUP_ITEM_ID, + output_index: 0, + summary_index: 0, + delta: STARTUP_THINKING_TEXT, + }, + }, + { + event: "response.reasoning_summary_part.done", + data: { + type: "response.reasoning_summary_part.done", + item_id: RESPONSES_STARTUP_ITEM_ID, + output_index: 0, + summary_index: 0, + part: { type: "summary_text", text: STARTUP_THINKING_TEXT }, + }, + }, + ] + .map((e) => `event: ${e.event}\ndata: ${JSON.stringify(e.data)}\n\n`) + .join("") +); +// Anthropic Messages API default — Anthropic's own spec really does use a named +// `event: error` SSE frame, so this is correct there. It is WRONG for the OpenAI- +// format routes below: Chat Completions and Responses streaming never use the SSE +// `event:` field at all, only bare `data: {...}` lines — a naive line-based parser +// (the kind most OpenAI-compatible clients use, not a full EventSource) can silently +// drop an unrecognized `event:` line and/or desync on the `data:` line that follows, +// so this error would never surface to the client at all (log ids +// 1784465227489-a2cbc0 / 1784457764961-73 territory: a client that gives up with no +// visible reason). See OPENAI_CHAT_ERROR_FRAME / OPENAI_RESPONSES_ERROR_FRAME below +// for the per-format-correct alternatives. const ERROR_FRAME = ENCODER.encode( `event: error\ndata: ${JSON.stringify({ error: { message: "Upstream stream failed before completion.", type: "stream_error" }, })}\n\n` ); +// Chat Completions convention: a plain `data:` line, no `event:` field. This +// matches what the openai-node SDK's stream iterator actually checks for — it +// inspects each parsed chunk for a top-level `error` key regardless of any SSE +// event name (there isn't one to check, since real OpenAI chat completions +// streams never send `event:` lines). +export const OPENAI_CHAT_ERROR_FRAME = ENCODER.encode( + `data: ${JSON.stringify({ + error: { message: "Upstream stream failed before completion.", type: "stream_error" }, + })}\n\n` +); +// Responses API convention: also a plain `data:` line, but the discriminator is +// the `type` field INSIDE the JSON payload (matching every other Responses API +// event — response.output_text.delta, response.completed, etc.), not an SSE +// `event:` field. +export const OPENAI_RESPONSES_ERROR_FRAME = ENCODER.encode( + `data: ${JSON.stringify({ + type: "error", + code: null, + message: "Upstream stream failed before completion.", + param: null, + })}\n\n` +); export type EarlyStreamKeepaliveOptions = { /** Wait this long for the handler before committing to a keepalive stream. */ @@ -60,8 +166,25 @@ export type EarlyStreamKeepaliveOptions = { * for their stream watchdog and only a real `event: ping` keeps them from aborting. */ keepaliveFrame?: Uint8Array; + /** + * Frame emitted ONCE, immediately, as the very first byte of the slow path — + * before the recurring `keepaliveFrame` ticks start. Defaults to + * `keepaliveFrame` when omitted (today's behavior, unchanged). Pass a + * content-bearing frame (e.g. `OPENAI_STARTUP_THINKING_FRAME`) so the client + * sees visible progress instead of an empty/no-op keepalive on the first byte. + */ + startupFrame?: Uint8Array; /** Extra headers to include in the keepalive response (e.g. X-Correlation-Id). */ extraHeaders?: Record; + /** + * Frame emitted if the handler ultimately fails (or the upstream stream dies + * mid-flight with zero bytes forwarded) after the slow path has already + * committed to HTTP 200. Defaults to the Anthropic-style `event: error` frame + * (correct for /v1/messages). OpenAI-format routes (/v1/chat/completions, + * /v1/responses) MUST pass OPENAI_CHAT_ERROR_FRAME / OPENAI_RESPONSES_ERROR_FRAME + * instead — see the doc comment on the default ERROR_FRAME above for why. + */ + errorFrame?: Uint8Array; }; type SettledHandler = { ok: true; response: Response } | { ok: false; error: unknown }; @@ -74,7 +197,14 @@ export async function withEarlyStreamKeepalive( const intervalMs = Math.max(250, options.intervalMs ?? 2_500); const signal = options.signal ?? null; const keepaliveFrame = options.keepaliveFrame ?? KEEPALIVE_FRAME; + const startupFrame = options.startupFrame ?? keepaliveFrame; const extraHeaders = options.extraHeaders ?? {}; + const errorFrame = options.errorFrame ?? ERROR_FRAME; + // Single source of truth for whether THIS route's error framing uses a named SSE + // `event: error` line (Anthropic) or a plain `data:` line (OpenAI Chat Completions / + // Responses) — derived from errorFrame itself so the dynamic real-upstream-body case + // below stays consistent with the static default-message case without a second option. + const errorFrameUsesNamedEvent = new TextDecoder().decode(errorFrame).startsWith("event:"); // Settle into a tagged result so neither race branch leaves an unhandled // rejection when the threshold timer wins. @@ -120,12 +250,12 @@ export async function withEarlyStreamKeepalive( if (interval && typeof interval === "object" && "unref" in interval) { interval.unref?.(); } - // First keepalive immediately on commit so the client sees a byte right away. - // Use the configured frame (e.g. ANTHROPIC_PING_FRAME) — an SSE comment here - // would be ignored by Anthropic clients' watchdog on a sub-interval gap, - // defeating the keepalive for exactly the case it targets. + // First frame immediately on commit so the client sees a byte right away. + // Use `startupFrame` (e.g. OPENAI_STARTUP_THINKING_FRAME / ANTHROPIC_PING_FRAME) + // — an SSE comment here would be ignored by Anthropic clients' watchdog on a + // sub-interval gap, defeating the keepalive for exactly the case it targets. try { - controller.enqueue(keepaliveFrame); + controller.enqueue(startupFrame); } catch { /* consumer already gone */ } @@ -165,7 +295,7 @@ export async function withEarlyStreamKeepalive( if (!result.ok) { // Handler rejected — emit a generic error frame (never the raw error/stack). - controller.enqueue(ERROR_FRAME); + controller.enqueue(errorFrame); } else { const response = result.response; const contentType = (response.headers.get("content-type") || "").toLowerCase(); @@ -191,7 +321,7 @@ export async function withEarlyStreamKeepalive( // the SSE stream. Silently close instead; the client will see // the stream end naturally. if (bytesForwarded === 0) { - controller.enqueue(ERROR_FRAME); + controller.enqueue(errorFrame); } } } else { @@ -203,14 +333,17 @@ export async function withEarlyStreamKeepalive( const dataLine = text.trim() || JSON.stringify({ error: { message: "stream_error", type: "stream_error" } }); - controller.enqueue(ENCODER.encode(`event: error\ndata: ${dataLine}\n\n`)); + const framed = errorFrameUsesNamedEvent + ? `event: error\ndata: ${dataLine}\n\n` + : `data: ${dataLine}\n\n`; + controller.enqueue(ENCODER.encode(framed)); } } } catch { // Defensive: never surface a raw error/stack to the client. if (!aborted) { try { - controller.enqueue(ERROR_FRAME); + controller.enqueue(errorFrame); } catch { /* consumer gone */ } diff --git a/open-sse/utils/error.ts b/open-sse/utils/error.ts index 1530c5b66c..f7d7bb8585 100644 --- a/open-sse/utils/error.ts +++ b/open-sse/utils/error.ts @@ -519,6 +519,18 @@ export function createErrorResult( success: false; status: number; error: string; + /** + * #7360: the FULL, un-sanitized upstream message — `error` above is + * truncated to its first line by sanitizeErrorMessage() (correctly, for + * the client-facing response body). Server-side classification + * (checkFallbackError / Gemini TPM-vs-RPD metric detection) needs the + * complete multi-line text — e.g. Google's metric name and retry hint + * live on lines 2-3, after the generic "quota exceeded" preamble on + * line 1. This field NEVER reaches the HTTP response body (`response` + * below is already built from the sanitized `body`); it exists purely + * for internal callers that inspect the returned object. + */ + rawMessage: string; errorType?: string; errorCode?: string; response: Response; @@ -527,6 +539,7 @@ export function createErrorResult( success: false, status: statusCode, error: body.error.message, + rawMessage: message, errorType, errorCode, response: new Response(JSON.stringify(body), { diff --git a/src/app/(dashboard)/dashboard/health/page.tsx b/src/app/(dashboard)/dashboard/health/page.tsx index 6cedd23bb8..fe5e1fe144 100644 --- a/src/app/(dashboard)/dashboard/health/page.tsx +++ b/src/app/(dashboard)/dashboard/health/page.tsx @@ -72,6 +72,8 @@ export default function HealthPage() { const [degradation, setDegradation] = useState(null); const [resetting, setResetting] = useState(false); const [repairingDb, setRepairingDb] = useState(false); + const [unblocking, setUnblocking] = useState(false); + const [unblockingKey, setUnblockingKey] = useState(null); const fetchHealth = useCallback(async () => { try { @@ -145,6 +147,41 @@ export default function HealthPage() { } }; + const handleUnblockAll = async () => { + setUnblocking(true); + try { + const res = await fetch("/api/resilience/model-cooldowns", { + method: "DELETE", + headers: { "Content-Type": "application/json" }, + body: JSON.stringify({ all: true }), + }); + if (!res.ok) throw new Error(`HTTP ${res.status}`); + await fetchHealth(); + } catch (err) { + console.error("Failed to unblock all models:", err); + } finally { + setUnblocking(false); + } + }; + + const handleUnblockOne = async (provider: string, model: string) => { + const key = `${provider}::${model}`; + setUnblockingKey(key); + try { + const res = await fetch("/api/resilience/model-cooldowns", { + method: "DELETE", + headers: { "Content-Type": "application/json" }, + body: JSON.stringify({ provider, model }), + }); + if (!res.ok) throw new Error(`HTTP ${res.status}`); + await fetchHealth(); + } catch (err) { + console.error(`Failed to unblock ${provider}/${model}:`, err); + } finally { + setUnblockingKey(null); + } + }; + const handleRepairDb = async () => { setRepairingDb(true); try { @@ -1063,29 +1100,62 @@ export default function HealthPage() { {/* Active Lockouts */} {lockoutEntries.length > 0 && ( -

- lock - {t("activeLockouts")} -

+
+

+ lock + {t("activeLockouts")} +

+ +
- {lockoutEntries.map(([key, lockout]: [string, any]) => ( -
-
- {key} - {lockout.reason && ( - ({lockout.reason}) - )} + {lockoutEntries.map(([key, lockout]: [string, any]) => { + const lockProvider = lockout.provider as string; + const lockModel = lockout.model as string; + const lockKey = `${lockProvider}::${lockModel}`; + return ( +
+
+ + {lockProvider}/{lockModel} + + {lockout.reason && ( + ({lockout.reason}) + )} + {lockout.until && ( + + until {new Date(lockout.until).toLocaleTimeString()} + + )} +
+
- {lockout.until && ( - - {t("until", { time: new Date(lockout.until).toLocaleTimeString() })} - - )} -
- ))} + ); + })}
)} diff --git a/src/app/api/v1/chat/completions/route.ts b/src/app/api/v1/chat/completions/route.ts index 5b058ac11a..59c1c22af7 100644 --- a/src/app/api/v1/chat/completions/route.ts +++ b/src/app/api/v1/chat/completions/route.ts @@ -6,7 +6,9 @@ import { initTranslators } from "@omniroute/open-sse/translator/index.ts"; import { createInjectionGuard } from "@/middleware/promptInjectionGuard"; import { acceptHeaderForcesStream } from "@omniroute/open-sse/utils/aiSdkCompat.ts"; import { + OPENAI_CHAT_ERROR_FRAME, OPENAI_KEEPALIVE_FRAME, + OPENAI_STARTUP_THINKING_FRAME, withEarlyStreamKeepalive, } from "@omniroute/open-sse/utils/earlyStreamKeepalive"; import { resolveKeepaliveThreshold } from "@omniroute/open-sse/utils/keepaliveThreshold"; @@ -149,6 +151,8 @@ export async function POST(request) { signal: request.signal, thresholdMs: resolveKeepaliveThreshold(parsedBody?.model), keepaliveFrame: OPENAI_KEEPALIVE_FRAME, + startupFrame: OPENAI_STARTUP_THINKING_FRAME, + errorFrame: OPENAI_CHAT_ERROR_FRAME, extraHeaders: { "X-Correlation-Id": reqId }, }); return withCompressionHeaderEcho(streamedResponse, compressionRequestHeader); diff --git a/src/app/api/v1/responses/route.ts b/src/app/api/v1/responses/route.ts index 90639e8b04..2b1cea8c2a 100644 --- a/src/app/api/v1/responses/route.ts +++ b/src/app/api/v1/responses/route.ts @@ -1,5 +1,9 @@ import { handleChat } from "@/sse/handlers/chat"; -import { withEarlyStreamKeepalive } from "@omniroute/open-sse/utils/earlyStreamKeepalive"; +import { + withEarlyStreamKeepalive, + RESPONSES_STARTUP_THINKING_FRAME, + OPENAI_RESPONSES_ERROR_FRAME, +} from "@omniroute/open-sse/utils/earlyStreamKeepalive"; import { withInjectionGuard } from "@/middleware/promptInjectionGuard"; import { resolveResponsesApiModel } from "@/app/api/internal/codex-responses-ws/modelResolution"; import { getModelInfo } from "@/sse/services/model"; @@ -98,6 +102,8 @@ async function postHandler(request: any, context: any, preParsedBody: any = null return await withEarlyStreamKeepalive(handleChat(resolved, null, resolvedBody), { signal: request.signal, thresholdMs, + startupFrame: RESPONSES_STARTUP_THINKING_FRAME, + errorFrame: OPENAI_RESPONSES_ERROR_FRAME, }); } return await handleChat(resolved, null, resolvedBody); diff --git a/src/lib/resilience/settings.ts b/src/lib/resilience/settings.ts index 5995ad88a6..3ca3e9724d 100644 --- a/src/lib/resilience/settings.ts +++ b/src/lib/resilience/settings.ts @@ -80,20 +80,29 @@ export const DEFAULT_RESILIENCE_SETTINGS: ResilienceSettings = { resetTimeoutMs: PROVIDER_PROFILES.apikey.circuitBreakerReset, }, }, + // Wait at most 90s for a single connection cooldown (covers Gemini-class + // TPM/RPM windows, which report ~60s retry-after live), at most 5 retry + // cycles, never more than 300s (5 min) total (#7360 follow-up — raised now + // that withEarlyStreamKeepalive gives streaming clients an immediate + // synthetic keep-alive, eliminating the client-side first-byte-timeout risk + // a long wait used to carry). Applies to direct (non-combo) model requests. waitForCooldown: { enabled: true, - maxRetries: 3, - maxRetryWaitSec: 30, - maxRetryWaitMs: 30000, + maxRetries: 5, + maxRetryWaitSec: 90, + maxRetryWaitMs: 90000, + budgetMs: 300000, }, - // Conservative defaults: wait at most 5s for a single short transient - // cooldown, at most 2 redispatch cycles, never more than 8s total. Active only - // for quota-share combos and only for transient (non quota_exhausted) reasons. + // Wait at most 90s for a single short transient cooldown (covers Gemini-class + // TPM/RPM windows, which report ~60s retry-after live — #7360), at most 5 + // redispatch cycles, never more than 300s (5 min) total. Active for + // quota-share and auto combos, and only for transient (non quota_exhausted) + // reasons. comboCooldownWait: { enabled: true, - maxWaitMs: 5000, - maxAttempts: 2, - budgetMs: 8000, + maxWaitMs: 90000, + maxAttempts: 5, + budgetMs: 300000, }, // FASE 2.1: serialize concurrent quota-share requests per connection when the // connection sets a max_concurrent cap, so a subscription account is not @@ -233,6 +242,10 @@ function buildLegacyFallback(settings: JsonRecord): ResilienceSettings { maxRetries: waitMaxRetries, maxRetryWaitSec: waitMaxRetrySec, maxRetryWaitMs: waitMaxRetrySec * 1000, + budgetMs: Math.max( + waitMaxRetrySec * 1000, + DEFAULT_RESILIENCE_SETTINGS.waitForCooldown.budgetMs + ), }, comboCooldownWait: DEFAULT_RESILIENCE_SETTINGS.comboCooldownWait, quotaShareConcurrencyLimit: DEFAULT_RESILIENCE_SETTINGS.quotaShareConcurrencyLimit, diff --git a/src/lib/resilience/settings/normalize.ts b/src/lib/resilience/settings/normalize.ts index 43c98b0400..89607a64bf 100644 --- a/src/lib/resilience/settings/normalize.ts +++ b/src/lib/resilience/settings/normalize.ts @@ -295,6 +295,14 @@ export function normalizeWaitForCooldownSettings( max: 300, }); const maxRetries = toInteger(record.maxRetries, fallback.maxRetries, { min: 0, max: 10 }); + const maxRetryWaitMs = maxRetryWaitSec * 1000; + // Cumulative cap across all waits for one request (#7360 follow-up) — mirrors + // comboCooldownWait.budgetMs. Floored at maxRetryWaitMs so at least one wait + // can always fire; ceiling matches the same 5-minute give-up point. + const budgetMs = toInteger(record.budgetMs, fallback.budgetMs, { + min: maxRetryWaitMs, + max: 5 * 60 * 1000, + }); const enabled = toBoolean(record.enabled, fallback.enabled) && maxRetries > 0 && maxRetryWaitSec > 0; @@ -302,7 +310,8 @@ export function normalizeWaitForCooldownSettings( enabled, maxRetries, maxRetryWaitSec, - maxRetryWaitMs: maxRetryWaitSec * 1000, + maxRetryWaitMs, + budgetMs, }; } @@ -311,10 +320,15 @@ export function normalizeComboCooldownWaitSettings( fallback: ComboCooldownWaitSettings ): ComboCooldownWaitSettings { const record = asRecord(next); - // Hard ceiling of 30s on a single wait — this layer only ever exists for - // SHORT transient cooldowns; anything longer should fall through to the - // existing 429 crystallization (and the cross-request cooldown layers). - const maxWaitMs = toInteger(record.maxWaitMs, fallback.maxWaitMs, { min: 0, max: 30000 }); + // Hard ceiling of 5 minutes on a single wait (#7360 follow-up — raised from + // 90s now that streaming clients get an immediate synthetic keep-alive + // event via withEarlyStreamKeepalive, so a long wait no longer risks a + // client-side first-byte timeout). This layer exists for transient cooldowns + // (including Gemini-class TPM/RPM windows, which report ~60s retry-after + // live); anything the upstream itself reports as longer than this should + // fall through to the existing 429 crystallization (and the cross-request + // cooldown layers). + const maxWaitMs = toInteger(record.maxWaitMs, fallback.maxWaitMs, { min: 0, max: 300000 }); const maxAttempts = toInteger(record.maxAttempts, fallback.maxAttempts, { min: 0, max: 10 }); // Budget can never be smaller than a single wait, otherwise no wait could // ever fire; floor it at maxWaitMs. diff --git a/src/lib/resilience/settings/types.ts b/src/lib/resilience/settings/types.ts index 0564937fc7..99aaea9295 100644 --- a/src/lib/resilience/settings/types.ts +++ b/src/lib/resilience/settings/types.ts @@ -54,6 +54,14 @@ export interface WaitForCooldownSettings { maxRetries: number; maxRetryWaitSec: number; maxRetryWaitMs: number; + /** + * Cumulative cap (ms) across all retry waits for one request — mirrors + * ComboCooldownWaitSettings.budgetMs (#7360 follow-up). Without this a + * request could re-wait maxRetries times at up to maxRetryWaitMs each, + * with no overall ceiling; budgetMs bounds the total regardless of how + * many individual waits fire. + */ + budgetMs: number; } /** diff --git a/src/shared/components/RequestLoggerDetail.tsx b/src/shared/components/RequestLoggerDetail.tsx index 01647eb252..84070bf728 100644 --- a/src/shared/components/RequestLoggerDetail.tsx +++ b/src/shared/components/RequestLoggerDetail.tsx @@ -66,6 +66,7 @@ function PayloadSection({ title, json, onCopy, collapsible = true, defaultOpen = function StreamSection({ title, json, onCopy }) { const [copied, setCopied] = useState(false); + const [open, setOpen] = useState(true); const [autoscroll, setAutoscroll] = useState(() => { try { const v = localStorage.getItem("pref:stream:autoscroll"); @@ -85,7 +86,7 @@ function StreamSection({ title, json, onCopy }) { }; useEffect(() => { - if (!autoscroll) return; + if (!autoscroll || !open) return; const el = ref.current; if (!el) return; // scroll on next animation frame to avoid layout thrash @@ -94,7 +95,7 @@ function StreamSection({ title, json, onCopy }) { el.scrollTop = el.scrollHeight; } catch {} }); - }, [json, autoscroll]); + }, [json, autoscroll, open]); const toggleAutoscroll = () => { const next = !autoscroll; @@ -107,7 +108,20 @@ function StreamSection({ title, json, onCopy }) { return (
-

{title}

+
+

+ {title} +

+ +
-
- {json} -
+ {open && ( +
+ {json} +
+ )}
); } @@ -199,6 +215,49 @@ export default function RequestLoggerDetail({ }; const providerLabel = log.providerDisplay || providerColor.label; + const [unblocking, setUnblocking] = useState(false); + const [cleared, setCleared] = useState(false); + + const errorText = (detail?.error || log.error) ?? ""; + const isCombo503 = + log.status === 503 && errorText.toLowerCase().includes("all targets exhausted"); + const isModelCooldown = !isCombo503 && errorText.toLowerCase().includes("cooling down"); + + const [unblockAllBusy, setUnblockAllBusy] = useState(false); + + const handleUnblockModel = async () => { + if (!log.provider || !log.model) return; + setUnblocking(true); + try { + const res = await fetch("/api/resilience/model-cooldowns", { + method: "DELETE", + headers: { "Content-Type": "application/json" }, + body: JSON.stringify({ provider: log.provider, model: log.model }), + }); + if (res.ok) setCleared(true); + } catch { + /* ignore */ + } finally { + setUnblocking(false); + } + }; + + const handleUnblockAll = async () => { + setUnblockAllBusy(true); + try { + const res = await fetch("/api/resilience/model-cooldowns", { + method: "DELETE", + headers: { "Content-Type": "application/json" }, + body: JSON.stringify({ all: true }), + }); + if (res.ok) setCleared(true); + } catch { + /* ignore */ + } finally { + setUnblockAllBusy(false); + } + }; + const providerStatus = detail?.pipelinePayloads?.providerResponse?.status; const hasStatusDiscrepancy = providerStatus && providerStatus !== log.status; @@ -615,8 +674,90 @@ export default function RequestLoggerDetail({ {/* Error Message */} {(detail?.error || log.error) && (
-
- Error +
+
+ Error +
+ {isCombo503 && !cleared && ( + + )} + {isCombo503 && cleared && ( + + + + + Cleared + + )} + {isModelCooldown && !cleared && ( + + )} + {isModelCooldown && cleared && ( + + + + + Cleared + + )}
{formatErrorForDisplay(detail?.error || log.error)} diff --git a/src/sse/handlers/chat.ts b/src/sse/handlers/chat.ts index 5ba707fd37..6fe83ca4f9 100644 --- a/src/sse/handlers/chat.ts +++ b/src/sse/handlers/chat.ts @@ -24,6 +24,7 @@ import { getImageModelEntry } from "@omniroute/open-sse/config/imageRegistry.ts" import { acceptHeaderForcesStream } from "@omniroute/open-sse/utils/aiSdkCompat.ts"; import { applyNoThinkingAlias } from "@omniroute/open-sse/utils/noThinkingAlias.ts"; import { handleComboChat, shouldSkipConnDisable } from "@omniroute/open-sse/services/combo.ts"; +import { mergeAbortSignals } from "@omniroute/open-sse/executors/base.ts"; import { resolveRequestAutoControls } from "@omniroute/open-sse/services/autoCombo/requestControls.ts"; import { resolveComboConfig } from "@omniroute/open-sse/services/comboConfig.ts"; import { injectHandoffIntoBody } from "@omniroute/open-sse/services/contextHandoff.ts"; @@ -765,6 +766,7 @@ export async function handleChat( failoverBeforeRetry?: boolean; providerId?: string | null; effectiveComboStrategy?: string | null; + modelAbortSignal?: AbortSignal | null; } ) => handleSingleModelChat( @@ -795,6 +797,16 @@ export async function handleChat( reasoningDecision, reasoningIntent, reasoningRequestTags: requestRoutingTags.tags, + // #7360 follow-up: without this, a target dispatch abandoned by + // targetTimeoutRunner.ts's per-target timeout (comboTargetTimeoutMs) + // never learns it was abandoned — it only watches the ORIGINAL + // client's request.signal (see clientRawRequest below), which stays + // open for as long as the overall combo keeps retrying elsewhere. + // The abandoned dispatch then hangs forever inside withRateLimit/ + // acquireAccountSemaphore, leaking a permanent "pending" dashboard + // entry (trackPendingRequest(false) never runs) — live incident, + // log id 1784418258231-14961a. + modelAbortSignal: target?.modelAbortSignal ?? null, }, target?.effectiveComboStrategy ?? combo.strategy, true @@ -872,12 +884,13 @@ export async function handleChat( // (success:false) so gate/breaker-rejected traffic is counted per key — support-mesh 2026-07-08. if (!response.ok) { try { - const { recordRejectedRequestUsage } = await import("./rejectedRequestUsage"); + const { recordRejectedRequestUsage, summarizeComboAttemptedModels } = + await import("./rejectedRequestUsage"); await recordRejectedRequestUsage({ status: response.status, model: body?.model || resolvedModelStr, requestedModel: body?.model || resolvedModelStr, - provider: "-", + provider: summarizeComboAttemptedModels(combo?.models), endpoint: clientRawRequest?.endpoint, error: await getComboFailureLogError(response, combo.name), comboName: combo.name, @@ -885,6 +898,7 @@ export async function handleChat( apiKeyName: apiKeyInfo?.name ?? null, correlationId: reqId, startTime: telemetry?.startTime, + requestBody: clientRawRequest?.body ?? null, }); } catch {} } @@ -943,6 +957,33 @@ export function buildClientRawRequest(request: Request, body: unknown) { }; } +/** + * #7360 follow-up: chatCore.ts's createStreamController (and, downstream, + * withRateLimit/acquireAccountSemaphore) only ever watches + * clientRawRequest.signal — the ORIGINAL client's request signal, which stays + * open for as long as the overall combo keeps retrying elsewhere. A target + * abandoned by comboTargetTimeoutMs (open-sse/services/combo/targetTimeoutRunner.ts) + * never learns it was abandoned, and hangs forever (leaking a permanent + * "pending" dashboard entry — trackPendingRequest(false) never runs; live + * incident, log id 1784418258231-14961a). Merges the per-target + * modelAbortSignal (when present) into clientRawRequest.signal so an + * abandoned dispatch can actually observe its own abort and reach its + * cleanup path — returns clientRawRequest unchanged when there's no + * modelAbortSignal to merge in (the non-combo / non-timed-out common case). + */ +export function resolveDispatchClientRawRequest( + clientRawRequest: { signal?: AbortSignal | null } | null | undefined, + modelAbortSignal: AbortSignal | null | undefined +): typeof clientRawRequest { + if (!modelAbortSignal) return clientRawRequest; + return { + ...clientRawRequest, + signal: clientRawRequest?.signal + ? mergeAbortSignals(clientRawRequest.signal, modelAbortSignal) + : modelAbortSignal, + }; +} + /** * Handle single model chat request * @@ -978,6 +1019,13 @@ async function handleSingleModelChat( reasoningDecision?: ReasoningRuleDecision | null; reasoningIntent?: ExtractedReasoningIntent | null; reasoningRequestTags?: string[]; + /** + * Per-target abort signal from combo.ts's targetTimeoutRunner + * (comboTargetTimeoutMs) — see the #7360 follow-up comment at the + * handleSingleModel call site above for why this must be merged into + * the signal used for the actual dispatch, not left unused. + */ + modelAbortSignal?: AbortSignal | null; } = {}, comboStrategy: string | null = null, isCombo: boolean = false @@ -1016,6 +1064,7 @@ async function handleSingleModelChat( allowRateLimitedConnection?: boolean; providerId?: string | null; effectiveComboStrategy?: string | null; + modelAbortSignal?: AbortSignal | null; } ) => handleSingleModelChat( @@ -1037,6 +1086,8 @@ async function handleSingleModelChat( allowRateLimitedConnection: target?.allowRateLimitedConnection === true, providerId: target?.providerId ?? null, correlationId: runtimeOptions?.correlationId ?? null, + // #7360 follow-up — see the primary handleSingleModel closure above. + modelAbortSignal: target?.modelAbortSignal ?? null, }, target?.effectiveComboStrategy ?? redirectCombo.strategy ?? "priority", false @@ -1173,9 +1224,14 @@ async function handleSingleModelChat( maxRetries: 0, maxRetryWaitSec: 0, maxRetryWaitMs: 0, + budgetMs: 0, } : baseRetrySettings; const requestSignal = request?.signal ?? null; + // Cumulative cap across all waits for this request (#7360 follow-up) — mirrors + // combo.ts's comboCooldownBudgetLeftMs. Declared outside requestAttemptLoop so + // it persists (and only decreases) across `continue requestAttemptLoop` retries. + let requestRetryBudgetLeftMs = retrySettings.budgetMs; if (Array.isArray(effectiveAllowedConnections) && effectiveAllowedConnections.length === 0) { log.debug("AUTH", `${provider}/${model} filtered out by connection-level routing constraints`); @@ -1239,6 +1295,7 @@ async function handleSingleModelChat( retryAfter: credentials.retryAfter, settings: retrySettings, attempt: requestRetryAttempt, + budgetLeftMs: requestRetryBudgetLeftMs, }); if (retryDecision.shouldRetry) { @@ -1258,6 +1315,7 @@ async function handleSingleModelChat( } requestRetryAttempt += 1; + requestRetryBudgetLeftMs = Math.max(0, requestRetryBudgetLeftMs - retryDecision.waitMs); log.info( "COOLDOWN_RETRY", `${provider}/${model} cooldown elapsed — restarting request attempt ${requestRetryAttempt}/${retrySettings.maxRetries}` @@ -1375,6 +1433,10 @@ async function handleSingleModelChat( // 4. Execute chat via core after breaker gate checks (with optional TLS tracking) if (telemetry) telemetry.startPhase("connect"); + const dispatchClientRawRequest = resolveDispatchClientRawRequest( + clientRawRequest, + runtimeOptions.modelAbortSignal + ); const { result, tlsFingerprintUsed } = await executeChatWithBreaker({ bypassCircuitBreaker: forceLiveComboTest || hasForcedConnection, breaker, @@ -1385,7 +1447,7 @@ async function handleSingleModelChat( proxyInfo, appliedProxySink, log, - clientRawRequest, + clientRawRequest: dispatchClientRawRequest, credentials, apiKeyInfo, userAgent, @@ -1670,7 +1732,11 @@ async function handleSingleModelChat( // Check if it's a daily quota exhausted error (e.g., ModelScope/Kimi "today's quota for model") // Daily quota lockout overrides subsequent rate_limited lockout, ensuring lockout until tomorrow 0:00 let dailyQuotaExhausted = false; - const errorStr = String(result.error || ""); + // #7360: prefer the full un-sanitized upstream text over result.error + // (truncated to its first line for the client response body) — Gemini's + // TPM/RPD metric name and retry hint live on lines 2-3, after the + // generic "quota exceeded" preamble on line 1. + const errorStr = String(result.rawMessage ?? result.error ?? ""); const failureKind = result.status === 429 ? classify429FromError({ status: result.status, message: errorStr }) @@ -1736,7 +1802,7 @@ async function handleSingleModelChat( : await markAccountUnavailable( credentials.connectionId, result.status, - result.error, + errorStr, provider, model, providerProfile, diff --git a/src/sse/handlers/rejectedRequestUsage.ts b/src/sse/handlers/rejectedRequestUsage.ts index 7626e83e81..dc70e09e76 100644 --- a/src/sse/handlers/rejectedRequestUsage.ts +++ b/src/sse/handlers/rejectedRequestUsage.ts @@ -35,6 +35,13 @@ export interface RejectedRequestUsageInput { connectionId?: string | null; /** When the request started, for the duration/latency columns. */ startTime?: number; + /** + * The client's original request body (already cloned/bounded via + * cloneLogPayload by the caller). Rejected-before-dispatch requests never + * reach the normal handleChatCore logging path, so without this the + * dashboard log detail had no request to inspect — see #7360 follow-up. + */ + requestBody?: unknown; } export async function recordRejectedRequestUsage(input: RejectedRequestUsageInput): Promise { @@ -53,6 +60,7 @@ export async function recordRejectedRequestUsage(input: RejectedRequestUsageInpu apiKeyName = null, connectionId = undefined, startTime, + requestBody = null, } = input; const now = Date.now(); @@ -71,6 +79,7 @@ export async function recordRejectedRequestUsage(input: RejectedRequestUsageInpu duration, tokens: {}, error: error || null, + requestBody, comboName, comboStepId, comboExecutionKey, @@ -96,3 +105,25 @@ export async function recordRejectedRequestUsage(input: RejectedRequestUsageInpu endpoint: endpoint || "/v1/chat/completions", }).catch(() => {}); } + +/** + * Builds a readable "provider" summary for a combo-exhausted rejection from the + * combo's own configured model list — the response's combo diagnostics don't + * reliably cover every skip reason (e.g. a model-level resilience lockout skip + * never touches the exhaustedProviders/exhaustedConnections diagnostic sets in + * combo.ts), so this reads the combo config directly instead: it's always + * available and always reflects what the combo was actually set up to try. + * Falls back to "-" when there's nothing usable (no models, or the combo is + * built entirely from combo-ref/nested-combo steps with no direct model). + */ +export function summarizeComboAttemptedModels(models: unknown): string { + if (!Array.isArray(models)) return "-"; + const modelStrings = models + .map((entry) => + entry && typeof entry === "object" && typeof (entry as { model?: unknown }).model === "string" + ? (entry as { model: string }).model + : null + ) + .filter((entry): entry is string => Boolean(entry)); + return modelStrings.length > 0 ? modelStrings.join(", ") : "-"; +} diff --git a/src/sse/services/cooldownAwareRetry.ts b/src/sse/services/cooldownAwareRetry.ts index 14a95c605d..fcdbb63bae 100644 --- a/src/sse/services/cooldownAwareRetry.ts +++ b/src/sse/services/cooldownAwareRetry.ts @@ -3,12 +3,15 @@ import { resolveResilienceSettings } from "@/lib/resilience/settings"; const MAX_REQUEST_RETRY = 10; const MAX_RETRY_INTERVAL_SEC = 300; +const MAX_BUDGET_MS = 5 * 60 * 1000; export interface CooldownAwareRetrySettings { enabled: boolean; maxRetries: number; maxRetryWaitSec: number; maxRetryWaitMs: number; + /** Cumulative cap (ms) across all retry waits for one request — see settings/types.ts. */ + budgetMs: number; } function normalizeInteger( @@ -48,13 +51,19 @@ export function resolveCooldownAwareRetrySettings( max: MAX_RETRY_INTERVAL_SEC, } ); + const maxRetryWaitMs = maxRetryWaitSec * 1000; + const budgetMs = normalizeInteger(waitForCooldown.budgetMs, waitForCooldown.budgetMs, { + min: maxRetryWaitMs, + max: MAX_BUDGET_MS, + }); const enabled = Boolean(waitForCooldown.enabled) && maxRetries > 0 && maxRetryWaitSec > 0; return { enabled, maxRetries, maxRetryWaitSec, - maxRetryWaitMs: maxRetryWaitSec * 1000, + maxRetryWaitMs, + budgetMs, }; } @@ -84,10 +93,18 @@ export function getCooldownAwareRetryDecision({ retryAfter, settings, attempt, + budgetLeftMs, }: { retryAfter: unknown; settings: CooldownAwareRetrySettings; attempt: number; + /** + * Remaining cumulative wait budget (ms) for this request. Defaults to + * settings.budgetMs when omitted (single-call-site backward compat) — + * pass the caller's tracked remainder once it starts decrementing it + * across attempts (#7360 follow-up). + */ + budgetLeftMs?: number; }): { shouldRetry: boolean; retryAfter: string | null; @@ -95,6 +112,7 @@ export function getCooldownAwareRetryDecision({ waitMs: number; } { const closest = computeClosestRetryAfter(retryAfter); + const effectiveBudgetLeftMs = budgetLeftMs ?? settings.budgetMs; if ( !settings.enabled || settings.maxRetries <= 0 || @@ -110,7 +128,7 @@ export function getCooldownAwareRetryDecision({ }; } - if (closest.waitMs > settings.maxRetryWaitMs) { + if (closest.waitMs > settings.maxRetryWaitMs || closest.waitMs > effectiveBudgetLeftMs) { return { shouldRetry: false, retryAfter: closest.retryAfter, diff --git a/tests/integration/free-models-benchmark.test.ts b/tests/integration/free-models-benchmark.test.ts new file mode 100644 index 0000000000..3b9e26665d --- /dev/null +++ b/tests/integration/free-models-benchmark.test.ts @@ -0,0 +1,112 @@ +/** + * tests/integration/free-models-benchmark.test.ts + * + * Live benchmark: how well do the free-tier models OmniRoute exposes handle + * a representative slice of the general workload (the same CASE_BUILDERS + * used by live-gemini-workload.test.ts)? Unlike the pass/fail live-gemini + * suite, this is a report, not a gate — free-tier providers are expected to + * be flakier than paid ones (rate limits, capacity, ToS-ambiguous + * availability per freeModelCatalog.data.ts), so a single model performing + * badly is a benchmark finding, not a regression. Only a total outage across + * every model (the harness itself broken) fails the test. + * + * Environment: + * OMNIROUTE_API_KEY — required (else test skips) + * OMNIROUTE_URL — defaults to http://localhost:3000 + * + * Models benchmarked are restricted to providers with an active connection + * on this deployment (checked live via GET /api/providers) — see + * FREE_MODELS in freeModelBenchmarkShared.ts for the full candidate list and + * how it was curated from open-sse/config/freeModelCatalog.data.ts. + */ +import test from "node:test"; +import assert from "node:assert/strict"; + +import { skip, ensureTestEnvironment } from "./liveGeminiShared.ts"; +import { + FREE_MODELS, + BENCHMARK_CASES, + getActiveProviders, + benchmarkRequest, + summarize, + formatBenchmarkTable, + type BenchmarkResult, + type ModelBenchmarkSummary, +} from "./freeModelBenchmarkShared.ts"; + +const DELAY_BETWEEN_REQUESTS_MS = Number(process.env.TEST_DELAY_MS) || 2000; +const DELAY_BETWEEN_MODELS_MS = 3000; + +test.before(async () => { + await ensureTestEnvironment(); +}); + +test( + "free-model workload benchmark: representative CASE_BUILDERS slice per model", + { skip }, + async () => { + const activeProviders = await getActiveProviders(); + const candidates = FREE_MODELS.filter((spec) => activeProviders.has(spec.provider)); + const skipped = FREE_MODELS.filter((spec) => !activeProviders.has(spec.provider)); + + if (skipped.length > 0) { + console.log( + `\n [setup] skipping ${skipped.length} model(s) — provider not active: ` + + skipped.map((s) => s.provider).join(", ") + ); + } + + if (candidates.length === 0) { + console.log(" [skip] no configured providers match FREE_MODELS — nothing to benchmark"); + return; + } + + console.log( + `\n Benchmarking ${candidates.length} free model(s) × ${BENCHMARK_CASES.length} workload case(s) ` + + `= ${candidates.length * BENCHMARK_CASES.length} requests\n` + ); + + const summaries: ModelBenchmarkSummary[] = []; + + for (const spec of candidates) { + const results: BenchmarkResult[] = []; + + for (let i = 0; i < BENCHMARK_CASES.length; i++) { + const tc = BENCHMARK_CASES[i]; + if (i > 0) await new Promise((r) => setTimeout(r, DELAY_BETWEEN_REQUESTS_MS)); + + const r = await benchmarkRequest(spec, tc.name, tc.build); + results.push(r); + + const status = r.ok ? "OK " : "FAIL"; + console.log( + ` [${status}] ${spec.displayName.padEnd(38)} ${tc.name.padEnd(35)} ` + + `HTTP ${r.status} | ${r.durationMs}ms | ${r.tokens} tok` + + (r.error ? ` | ${r.error}` : "") + ); + } + + summaries.push(summarize(spec, results)); + await new Promise((r) => setTimeout(r, DELAY_BETWEEN_MODELS_MS)); + } + + console.log(formatBenchmarkTable(summaries)); + + const totalAttempted = summaries.reduce((s, m) => s + m.attempted, 0); + const totalSucceeded = summaries.reduce((s, m) => s + m.succeeded, 0); + console.log( + `\n Overall: ${totalSucceeded}/${totalAttempted} requests succeeded across ${summaries.length} models\n` + ); + + // Only a total-outage catches a real regression here — free-tier providers + // are individually allowed to be unreliable (that's the finding, not a + // bug), but a harness-wide 0% success rate means the benchmark itself (or + // OmniRoute's routing) is broken, not that every free provider failed at + // once. + assert.ok( + totalSucceeded > 0, + `every one of ${totalAttempted} requests across ${summaries.length} models failed — ` + + `likely a harness or routing bug, not free-tier flakiness` + ); + } +); diff --git a/tests/integration/free-models-tpm-stress.test.ts b/tests/integration/free-models-tpm-stress.test.ts new file mode 100644 index 0000000000..3976a6154d --- /dev/null +++ b/tests/integration/free-models-tpm-stress.test.ts @@ -0,0 +1,90 @@ +/** + * tests/integration/free-models-tpm-stress.test.ts + * + * TPM-stress benchmark for the gemma-4-31b model family across its 3 free + * hosts on this deployment (Gemini, NVIDIA, AI Horde). gemma-4 is + * specifically documented (tests/integration/gemini-large-context-tpm.test.ts) + * as hitting a hard 16000 tokens/minute ceiling on Gemini's free tier — this + * test asks whether that's a Gemini-specific enforcement limit or a + * per-model property that shows up on other free hosts too, by firing + * back-to-back ~14k-token prompts (concentrated into one window, unlike the + * paced general workload benchmark) at each host and recording what happens: + * clean completion, a real 429/503, or a silent failure mode. + * + * Like free-models-benchmark.test.ts, this is a report, not a pass/fail + * gate on individual hosts — hitting a real TPM ceiling and recovering + * (or not) is the finding, not a bug. Only a total outage across every host + * fails the test. + * + * Environment: + * OMNIROUTE_API_KEY — required (else test skips) + * OMNIROUTE_URL — defaults to http://localhost:3000 + */ +import test from "node:test"; +import assert from "node:assert/strict"; + +import { skip, ensureTestEnvironment } from "./liveGeminiShared.ts"; +import { + TPM_STRESS_MODELS, + getActiveProviders, + benchmarkTpmStress, + summarize, + formatBenchmarkTable, + type ModelBenchmarkSummary, +} from "./freeModelBenchmarkShared.ts"; + +const DELAY_BETWEEN_MODELS_MS = 5000; +const APPROX_TOKENS_PER_PROMPT = 14_000; // squarely inside the 10-20k "critical" range +const ROUNDS = 2; // back-to-back, no delay — accumulates within one TPM window + +test.before(async () => { + await ensureTestEnvironment(); +}); + +test("gemma-4 TPM-stress: ~14k-token prompts fired back-to-back per host", { skip }, async () => { + const activeProviders = await getActiveProviders(); + const candidates = TPM_STRESS_MODELS.filter((spec) => activeProviders.has(spec.provider)); + + if (candidates.length === 0) { + console.log(" [skip] no configured providers match TPM_STRESS_MODELS — nothing to test"); + return; + } + + console.log( + `\n TPM-stress: ${candidates.length} host(s) × ${ROUNDS} back-to-back ~${APPROX_TOKENS_PER_PROMPT}-token ` + + `prompts (~${Math.round((candidates.length * ROUNDS * APPROX_TOKENS_PER_PROMPT) / 1000)}k tokens total)\n` + ); + + const summaries: ModelBenchmarkSummary[] = []; + + for (const spec of candidates) { + const results = await benchmarkTpmStress(spec, APPROX_TOKENS_PER_PROMPT, ROUNDS); + + for (const r of results) { + const status = r.ok ? "OK " : "FAIL"; + console.log( + ` [${status}] ${spec.displayName.padEnd(30)} ${r.case.padEnd(40)} ` + + `HTTP ${r.status} | ${r.durationMs}ms | ${r.tokens} tok` + + (r.error ? ` | ${r.error}` : "") + ); + } + + summaries.push(summarize(spec, results)); + await new Promise((r) => setTimeout(r, DELAY_BETWEEN_MODELS_MS)); + } + + console.log(formatBenchmarkTable(summaries)); + + const totalAttempted = summaries.reduce((s, m) => s + m.attempted, 0); + const totalSucceeded = summaries.reduce((s, m) => s + m.succeeded, 0); + console.log( + `\n Overall: ${totalSucceeded}/${totalAttempted} TPM-stress requests succeeded across ` + + `${summaries.length} host(s)\n` + ); + + assert.ok( + totalSucceeded > 0, + `every one of ${totalAttempted} TPM-stress requests across ${summaries.length} host(s) failed — ` + + `likely a harness or routing bug, not a real TPM ceiling` + ); +}); diff --git a/tests/integration/freeModelBenchmarkShared.ts b/tests/integration/freeModelBenchmarkShared.ts new file mode 100644 index 0000000000..2621d194bb --- /dev/null +++ b/tests/integration/freeModelBenchmarkShared.ts @@ -0,0 +1,527 @@ +/** + * tests/integration/freeModelBenchmarkShared.ts + * + * Shared helpers for the free-model workload benchmark. Reuses the request + * generators, SSE parsers, and BASE_URL/API_KEY plumbing already built for + * the live Gemini workload tests (liveGeminiShared.ts) instead of + * duplicating them — those helpers are already provider-agnostic (they just + * happened to only ever be called with the Gemini "default" combo model). + * + * Unlike sendAndValidate() in liveGeminiShared.ts, benchmarkRequest() never + * throws/asserts on a single request failure — a free-tier model timing out + * or 429ing is an expected, recordable data point for a benchmark, not a + * regression. Per-model reliability is the thing being measured here. + */ +import { + API_KEY, + BASE_URL, + CASE_BUILDERS, + genHugeContextMessage, + readResponsesSSEStream, + readSSEStream, + type Message, +} from "./liveGeminiShared.ts"; + +export interface FreeModelSpec { + /** OmniRoute provider id, matching provider_connections.provider */ + provider: string; + /** Full "provider/modelId" string sent as the `model` field */ + model: string; + displayName: string; +} + +// Providers resolved directly from the static NOAUTH_PROVIDERS registry +// (src/shared/constants/providers/noauth.ts) — no provider_connections row +// exists or is needed for these (see src/sse/services/auth.ts's noAuth +// resolution path). getActiveProviders() only sees configured *connections*, +// so these have to be unioned in separately or every no-auth model gets +// filtered out as "not active" even though they work with zero setup. +export const NO_AUTH_PROVIDER_IDS = new Set(["felo-web", "aihorde", "opencode", "duckduckgo-web"]); + +// Curated from open-sse/config/freeModelCatalog.data.ts: the original 5 +// providers configured+active on this deployment (checked via GET +// /api/providers — see getActiveProviders()), PLUS the no-auth providers +// above, which needed no configuration at all — they were just never +// exercised. duckduckgo-web is kept in despite being currently broken +// upstream (400 ERR_BAD_REQUEST as of this writing) because that's a real, +// reportable data point, not benchmark noise. theoldllm was tried and +// dropped: this deployment's egress IP is blocked by Vercel for it (403), +// an environment limitation, not a model worth benchmarking here. +// +// One or two representative models per provider, not the full catalog: a +// full sweep of every free model across every provider would be a multi-hour +// run hammering everyone's free-tier quota for marginal extra signal. +export const FREE_MODELS: FreeModelSpec[] = [ + { + provider: "gemini", + model: "gemini/gemini-3.1-flash-lite", + displayName: "Gemini 3.1 Flash-Lite", + }, + { provider: "gemini", model: "gemini/gemma-4-31b-it", displayName: "Gemma 4 31B (Gemini)" }, + { provider: "nvidia", model: "nvidia/openai/gpt-oss-20b", displayName: "GPT OSS 20B (NVIDIA)" }, + { provider: "nvidia", model: "nvidia/z-ai/glm-5.1", displayName: "GLM 5.1 (NVIDIA)" }, + { + provider: "nvidia", + model: "nvidia/google/gemma-4-31b-it", + displayName: "Gemma 4 31B (NVIDIA)", + }, + { provider: "mistral", model: "mistral/mistral-small-latest", displayName: "Mistral Small 4" }, + { provider: "mistral", model: "mistral/codestral-latest", displayName: "Codestral" }, + { + provider: "pollinations", + model: "pollinations/openai-fast", + displayName: "OpenAI Fast (Pollinations)", + }, + { + provider: "pollinations", + model: "pollinations/deepseek", + displayName: "DeepSeek (Pollinations)", + }, + { + provider: "openrouter", + model: "openrouter/auto", + displayName: "Auto — Best Available (OpenRouter free pool)", + }, + { provider: "felo-web", model: "felo-web/felo-chat", displayName: "Felo Chat (no-auth)" }, + { + provider: "aihorde", + model: "aihorde/google/gemma-4-31b", + displayName: "Gemma 4 31B (AI Horde)", + }, + { + provider: "opencode", + model: "opencode/deepseek-v4-flash-free", + displayName: "DeepSeek V4 Flash Free (OpenCode)", + }, + { + provider: "duckduckgo-web", + model: "duckduckgo-web/gpt-4o-mini", + displayName: "GPT-4o Mini (DuckDuckGo, known-broken)", + }, + { + provider: "mistral", + model: "mistral/labs-leanstral-1-5-1", + displayName: "Leanstral 1.5.1 (Mistral)", + }, + { + provider: "openrouter", + model: "openrouter/poolside/laguna-s-2.1:free", + displayName: "Laguna S 2.1 (OpenRouter)", + }, + { + provider: "openrouter", + model: "openrouter/nvidia/nemotron-3-super-120b-a12b:free", + displayName: "Nemotron 3 Super 120B (OpenRouter)", + }, + { + provider: "openrouter", + model: "openrouter/nvidia/nemotron-3-ultra-550b-a55b:free", + displayName: "Nemotron 3 Ultra 550B (OpenRouter)", + }, + { + provider: "openrouter", + model: "openrouter/nvidia/nemotron-3-nano-omni-30b-a3b-reasoning:free", + displayName: "Nemotron 3 Nano Omni 30B Reasoning (OpenRouter)", + }, + { + provider: "openrouter", + model: "openrouter/google/gemma-4-26b-a4b-it:free", + displayName: "Gemma 4 26B (OpenRouter)", + }, + { + provider: "openrouter", + model: "openrouter/google/gemma-4-31b-it:free", + displayName: "Gemma 4 31B (OpenRouter)", + }, + { + provider: "openrouter", + model: "openrouter/nvidia/nemotron-3-nano-30b-a3b:free", + displayName: "Nemotron 3 Nano 30B (OpenRouter)", + }, + { + provider: "openrouter", + model: "openrouter/openai/gpt-oss-20b:free", + displayName: "GPT OSS 20B (OpenRouter)", + }, + { + provider: "openrouter", + model: "openrouter/poolside/laguna-xs-2.1:free", + displayName: "Laguna XS 2.1 (OpenRouter)", + }, + { + provider: "openrouter", + model: "openrouter/poolside/laguna-m.1:free", + displayName: "Laguna M.1 (OpenRouter)", + }, + { + provider: "openrouter", + model: "openrouter/cohere/north-mini-code:free", + displayName: "North Mini Code (OpenRouter)", + }, + { + provider: "openrouter", + model: "openrouter/nvidia/nemotron-nano-9b-v2:free", + displayName: "Nemotron Nano 9B v2 (OpenRouter)", + }, + { + provider: "opencode", + model: "opencode/nemotron-3-ultra-free", + displayName: "Nemotron 3 Ultra Free (OpenCode)", + }, + { + provider: "opencode", + model: "opencode/north-mini-code-free", + displayName: "North Mini Code Free (OpenCode)", + }, + { + provider: "opencode", + model: "opencode/laguna-s-2.1-free", + displayName: "Laguna S 2.1 Free (OpenCode)", + }, + { provider: "opencode", model: "opencode/big-pickle", displayName: "Big Pickle (OpenCode)" }, + { + provider: "opencode", + model: "opencode/mimo-v2.5-free", + displayName: "MiMo V2.5 Free (OpenCode)", + }, +]; + +// The batch the operator just enabled/added (2026-07-22): a Cerebras key, +// "free"-tagged OpenRouter models, and OpenCode's currently-live free roster +// (its old catalog entries had drifted — refetched from +// https://opencode.ai/zen/v1/models and cross-checked live before adding). +// Cerebras itself couldn't be smoke-tested here: the new key hit a live 402 +// Payment Required (testStatus: credits_exhausted) — an account/billing +// issue on Cerebras' side, not addressable from this deployment. +export const NEWLY_ENABLED_MODELS: FreeModelSpec[] = FREE_MODELS.filter((m) => + [ + "mistral/labs-leanstral-1-5-1", + "openrouter/poolside/laguna-s-2.1:free", + "openrouter/nvidia/nemotron-3-super-120b-a12b:free", + "openrouter/nvidia/nemotron-3-ultra-550b-a55b:free", + "openrouter/nvidia/nemotron-3-nano-omni-30b-a3b-reasoning:free", + "openrouter/google/gemma-4-26b-a4b-it:free", + "openrouter/google/gemma-4-31b-it:free", + "openrouter/nvidia/nemotron-3-nano-30b-a3b:free", + "openrouter/openai/gpt-oss-20b:free", + "openrouter/poolside/laguna-xs-2.1:free", + "openrouter/poolside/laguna-m.1:free", + "openrouter/cohere/north-mini-code:free", + "openrouter/nvidia/nemotron-nano-9b-v2:free", + "opencode/nemotron-3-ultra-free", + "opencode/north-mini-code-free", + "opencode/laguna-s-2.1-free", + "opencode/big-pickle", + "opencode/mimo-v2.5-free", + ].includes(m.model) +); + +// The gemma-4-31b family across its 3 free hosts on this deployment — the +// specific model documented (docs/architecture/RESILIENCE_GUIDE.md context, +// tests/integration/gemini-large-context-tpm.test.ts) as hitting a hard +// 16000 tokens/minute free-tier ceiling on Gemini. Benchmarking the same +// model across hosts isolates whether the TPM wall is a gemma-4 property or +// specific to Gemini's free-tier enforcement. +export const TPM_STRESS_MODELS: FreeModelSpec[] = FREE_MODELS.filter((m) => + m.displayName.includes("Gemma 4 31B") +); + +// A representative slice of the 25 general-workload CASE_BUILDERS: one plain +// chat case, one code-review case, one long-context case, one agentic/ +// multi-turn case, one structured-output case. Running the full 25 against +// every model in FREE_MODELS would multiply request count ~5x for marginal +// extra coverage over what already runs continuously in live-gemini-workload. +const BENCHMARK_CASE_NAMES = [ + "basic coding question", + "code review request", + "long document analysis", + "agentic planning task", + "JSON-heavy structured data prompt", +]; + +export const BENCHMARK_CASES = CASE_BUILDERS.filter((tc) => BENCHMARK_CASE_NAMES.includes(tc.name)); + +export interface BenchmarkResult { + model: string; + displayName: string; + case: string; + ok: boolean; + status: number; + durationMs: number; + tokens: number; + contentLength: number; + finishReason: string; + error?: string; +} + +export interface ModelBenchmarkSummary { + model: string; + displayName: string; + attempted: number; + succeeded: number; + successRate: number; + avgDurationMs: number; + avgTokens: number; + avgMsPerToken: number | null; + results: BenchmarkResult[]; +} + +/** + * Fetch the set of provider ids usable right now: providers with an active, + * non-expired connection, unioned with NO_AUTH_PROVIDER_IDS (those need no + * connection row at all — see the comment on that constant). + */ +export async function getActiveProviders(): Promise> { + const active = new Set(NO_AUTH_PROVIDER_IDS); + if (!API_KEY) return active; + try { + const res = await fetch(`${BASE_URL}/api/providers`, { + headers: { Authorization: `Bearer ${API_KEY}` }, + }); + if (!res.ok) return active; + const data = await res.json(); + const connections = data.connections || data; + for (const c of Array.isArray(connections) ? connections : []) { + if (c.isActive && c.testStatus !== "expired" && c.testStatus !== "error") { + active.add(c.provider); + } + } + } catch { + // network/setup failure — no-auth providers are still usable, keep them + } + return active; +} + +/** + * Send one benchmark request against a specific model. Never throws — a + * failure (timeout, 429, 5xx, malformed stream) is recorded as `ok: false` + * with the reason, not surfaced as a test failure. + */ +export async function benchmarkRequest( + spec: FreeModelSpec, + tcName: string, + buildMessages: () => Message[], + timeoutMs = 60_000 +): Promise { + const messages = buildMessages(); + const start = performance.now(); + + try { + const res = await fetch(`${BASE_URL}/v1/chat/completions`, { + method: "POST", + headers: { + "Content-Type": "application/json", + Authorization: `Bearer ${API_KEY}`, + }, + body: JSON.stringify({ + model: spec.model, + messages, + stream: true, + max_tokens: 2048, + temperature: 0.3, + }), + signal: AbortSignal.timeout(timeoutMs), + }); + + const status = res.status; + if (status !== 200) { + const body = await res.text().catch(() => ""); + return { + model: spec.model, + displayName: spec.displayName, + case: tcName, + ok: false, + status, + durationMs: Math.round(performance.now() - start), + tokens: 0, + contentLength: 0, + finishReason: "unknown", + error: body.slice(0, 200), + }; + } + + const { fullContent, finishReason, totalTokens } = await readSSEStream(res); + const durationMs = Math.round(performance.now() - start); + const ok = fullContent.length > 0 && (finishReason === "stop" || finishReason === "length"); + + return { + model: spec.model, + displayName: spec.displayName, + case: tcName, + ok, + status, + durationMs, + tokens: totalTokens, + contentLength: fullContent.length, + finishReason, + error: ok ? undefined : `empty or bad finish: ${finishReason}`, + }; + } catch (err) { + return { + model: spec.model, + displayName: spec.displayName, + case: tcName, + ok: false, + status: 0, + durationMs: Math.round(performance.now() - start), + tokens: 0, + contentLength: 0, + finishReason: "error", + error: err instanceof Error ? err.message : String(err), + }; + } +} + +/** + * TPM-stress round: `rounds` back-to-back large-context requests (~12-16k + * tokens each, via genHugeContextMessage — the same generator + * gemini-large-context-tpm.test.ts uses to trip Gemini's real 16000 TPM + * free-tier ceiling) fired with NO inter-request delay, so their token cost + * accumulates within the same provider-side one-minute window instead of + * spreading out. This is what distinguishes it from benchmarkRequest(), + * which deliberately paces requests apart — TPM ceilings are a *rate* + * property, invisible unless load is concentrated into a short window. + */ +export async function benchmarkTpmStress( + spec: FreeModelSpec, + approxTokensPerPrompt = 14_000, + rounds = 2, + timeoutMs = 90_000 +): Promise { + const results: BenchmarkResult[] = []; + for (let i = 0; i < rounds; i++) { + const r = await benchmarkRequest( + spec, + `tpm-stress round ${i + 1}/${rounds} (~${approxTokensPerPrompt} tok)`, + () => [genHugeContextMessage(approxTokensPerPrompt)], + timeoutMs + ); + results.push(r); + } + return results; +} + +/** Read one Responses-API benchmark request, mirroring benchmarkRequest(). */ +export async function benchmarkResponsesRequest( + spec: FreeModelSpec, + tcName: string, + buildMessages: () => Message[], + timeoutMs = 60_000 +): Promise { + const messages = buildMessages(); + const start = performance.now(); + + try { + const res = await fetch(`${BASE_URL}/v1/responses`, { + method: "POST", + headers: { + "Content-Type": "application/json", + Authorization: `Bearer ${API_KEY}`, + }, + body: JSON.stringify({ + model: spec.model, + input: messages, + stream: true, + max_output_tokens: 2048, + temperature: 0.3, + }), + signal: AbortSignal.timeout(timeoutMs), + }); + + const status = res.status; + if (status !== 200) { + const body = await res.text().catch(() => ""); + return { + model: spec.model, + displayName: spec.displayName, + case: tcName, + ok: false, + status, + durationMs: Math.round(performance.now() - start), + tokens: 0, + contentLength: 0, + finishReason: "unknown", + error: body.slice(0, 200), + }; + } + + const { fullContent, finishReason, totalTokens } = await readResponsesSSEStream(res); + const durationMs = Math.round(performance.now() - start); + const ok = fullContent.length > 0; + + return { + model: spec.model, + displayName: spec.displayName, + case: tcName, + ok, + status, + durationMs, + tokens: totalTokens, + contentLength: fullContent.length, + finishReason, + error: ok ? undefined : `empty content, finish=${finishReason}`, + }; + } catch (err) { + return { + model: spec.model, + displayName: spec.displayName, + case: tcName, + ok: false, + status: 0, + durationMs: Math.round(performance.now() - start), + tokens: 0, + contentLength: 0, + finishReason: "error", + error: err instanceof Error ? err.message : String(err), + }; + } +} + +export function summarize(spec: FreeModelSpec, results: BenchmarkResult[]): ModelBenchmarkSummary { + const succeeded = results.filter((r) => r.ok); + const avgDurationMs = + results.length > 0 + ? Math.round(results.reduce((s, r) => s + r.durationMs, 0) / results.length) + : 0; + const avgTokens = + succeeded.length > 0 + ? Math.round(succeeded.reduce((s, r) => s + r.tokens, 0) / succeeded.length) + : 0; + const tokenRates = succeeded.filter((r) => r.tokens > 0).map((r) => r.durationMs / r.tokens); + const avgMsPerToken = + tokenRates.length > 0 + ? Math.round((tokenRates.reduce((s, v) => s + v, 0) / tokenRates.length) * 10) / 10 + : null; + + return { + model: spec.model, + displayName: spec.displayName, + attempted: results.length, + succeeded: succeeded.length, + successRate: results.length > 0 ? succeeded.length / results.length : 0, + avgDurationMs, + avgTokens, + avgMsPerToken, + results, + }; +} + +export function formatBenchmarkTable(summaries: ModelBenchmarkSummary[]): string { + const rows = summaries + .slice() + .sort((a, b) => b.successRate - a.successRate || a.avgDurationMs - b.avgDurationMs) + .map((s) => { + const rate = `${s.succeeded}/${s.attempted}`.padStart(5); + const pct = `${Math.round(s.successRate * 100)}%`.padStart(4); + const dur = `${s.avgDurationMs}ms`.padStart(8); + const tok = `${s.avgTokens}`.padStart(6); + const rate2 = s.avgMsPerToken !== null ? `${s.avgMsPerToken}ms/tok` : "n/a".padStart(10); + return ` ${s.displayName.padEnd(38)} ${rate} (${pct}) | avg ${dur} | avg ${tok} tok | ${rate2}`; + }); + + return [ + "\n Free-model workload benchmark:", + " " + "model".padEnd(38) + " success | latency | tokens | throughput", + ...rows, + ].join("\n"); +} diff --git a/tests/integration/gemini-combo-cooldown-wait.test.ts b/tests/integration/gemini-combo-cooldown-wait.test.ts new file mode 100644 index 0000000000..1156ba34ed --- /dev/null +++ b/tests/integration/gemini-combo-cooldown-wait.test.ts @@ -0,0 +1,106 @@ +/** + * Live combo cooldown-wait test — "default" combo (strategy=auto, two gemma-4 + * models), against a real running OmniRoute instance with a real Gemini key. + * + * #7360: a request against the "default" combo was crystallizing a 503 + * "all targets exhausted" ~6s after BOTH gemma-4 targets hit a real Gemini + * TPM/RPM 429 (observed live retry-after ~58s), instead of holding the + * request and retrying once the lower-cooldown target recovered. The fix + * widened the combo cooldown-aware retry (open-sse/services/combo.ts, + * comboCooldownWaitEnabled) to the "auto" strategy and raised its wait + * ceiling/budget (src/lib/resilience/settings.ts, comboCooldownWait) to + * cover ~60s Gemini-class windows. + * + * This test bursts long-prompt concurrent requests at the "default" combo to + * try to trip a real TPM 429 on both gemma-4 targets simultaneously, then + * asserts the client-visible contract: the end user must NEVER see a 503 + * "all targets exhausted" — they should either get a 200 (possibly after a + * long hold while the combo waits out the shorter cooldown and retries) or, + * in the worst case, a 429 with a SHORT retry-after (never propagated as a + * hard combo failure). "Best effort" like gemini-live-429-classification.test.ts: + * if the burst doesn't trip a real rate limit, the test logs and passes — the + * hermetic regression guard is tests/unit/combo-quota-share-cooldown-wait.test.ts + * ("auto strategy (2 models, both rate-limited) → waits for the SHORTER + * cooldown, then succeeds"), which proves the exact behavior deterministically. + * + * Env vars: + * OMNIROUTE_URL — base URL (default http://localhost:20128) + * OMNIROUTE_API_KEY — API key for auth (REQUIRED) + * GEMINI_API_KEY — used by liveGeminiShared to provision a gemini + * connection if one doesn't already exist + */ + +import test from "node:test"; +import assert from "node:assert/strict"; +import { + API_KEY, + BASE_URL, + skip, + ensureTestEnvironment, + genLongDocMessage, + type Message, +} from "./liveGeminiShared.ts"; + +async function chatDefault(messages: Message[]) { + const startedAt = Date.now(); + const res = await fetch(`${BASE_URL}/v1/chat/completions`, { + method: "POST", + headers: { "Content-Type": "application/json", Authorization: `Bearer ${API_KEY}` }, + body: JSON.stringify({ model: "default", stream: false, messages }), + signal: AbortSignal.timeout(180_000), + }); + const body = await res.text(); + return { status: res.status, body, durationMs: Date.now() - startedAt }; +} + +test( + "default combo (2 gemma-4 targets): burst never surfaces 503 all-targets-exhausted", + { skip }, + async () => { + await ensureTestEnvironment(); + + const BURST = 12; + console.error( + `\n[COMBO] Sending ${BURST} concurrent long-prompt requests to combo "default" ` + + `(gemini/gemma-4-31b-it + gemini/gemma-4-26b-a4b-it, TPM 16000 each)...` + ); + + const fetches = Array.from({ length: BURST }, () => chatDefault([genLongDocMessage()])); + const results = await Promise.all(fetches); + + const statuses = results.map((r) => r.status); + const durations = results.map((r) => Math.round(r.durationMs)); + const successes = results.filter((r) => r.status === 200); + const allTargetsExhausted = results.filter( + (r) => r.status === 503 && r.body.toLowerCase().includes("all targets exhausted") + ); + + console.error(`[COMBO] statuses: ${statuses.join(",")}`); + console.error(`[COMBO] durations(ms): ${durations.join(",")}`); + console.error(`[COMBO] ${successes.length}/${BURST} succeeded (200)`); + + assert.equal( + allTargetsExhausted.length, + 0, + `client must never see a 503 "all targets exhausted" from the default combo — ` + + `the combo should hold the request and wait out the shorter cooldown instead. ` + + `Offending bodies: ${allTargetsExhausted.map((r) => r.body.slice(0, 300)).join(" | ")}` + ); + + const anyLongHold = durations.some((d) => d > 15_000); + if (anyLongHold) { + console.error( + "[COMBO] observed a long-held request (>15s) — cooldown-wait path was exercised live ✓" + ); + } else { + console.error( + "[COMBO] no long-held request observed — burst likely did not trip a real TPM/RPM 429 " + + "on both targets simultaneously (Gemini limits may be more generous in practice). " + + "The exact wait/retry-shorter-cooldown behavior is proven deterministically by " + + "tests/unit/combo-quota-share-cooldown-wait.test.ts." + ); + } + + assert.ok(successes.length > 0, "expected at least one successful request from the burst"); + } +); diff --git a/tests/integration/gemini-large-context-tpm.test.ts b/tests/integration/gemini-large-context-tpm.test.ts new file mode 100644 index 0000000000..3dd31a19f5 --- /dev/null +++ b/tests/integration/gemini-large-context-tpm.test.ts @@ -0,0 +1,65 @@ +/** + * tests/integration/gemini-large-context-tpm.test.ts + * + * #7360 follow-up: every other live Gemini workload test uses prompts of a + * few hundred to ~2,000 tokens — nowhere near Gemini's free-tier TPM ceiling + * (16000 input tokens/min for gemma-4, per the live error text: "Quota + * exceeded for metric: generate_content_free_tier_input_token_count, limit: + * 16000"). That means none of them ever exercised a REAL TPM 429 — only the + * much smaller RPM-style rate limiting. This file sends genuinely large + * (~12-13k token) prompts back-to-back so two of them together comfortably + * exceed the 16000/min ceiling, forcing a real TPM 429 from Gemini and + * exercising the full path end-to-end against production Gemini, not a mock: + * - classification (RATE_LIMIT_EXCEEDED, not the QUOTA_EXHAUSTED/midnight + * lockout a naive text-match on "quota" would produce — see + * accountFallback.ts's Gemini-specific check) + * - the comboCooldownWait wait-then-retry path (widened to "auto" combos + * and given a 5-minute ceiling — see combo.ts's dispatchWithCooldownRetry + * and its lastError/earliestRetryAfter/lastStatus hoisting fix) + * - the synthetic startup keep-alive frame on a genuinely slow request + * (open-sse/utils/earlyStreamKeepalive.ts) + * + * sendAndValidate() already treats a 503 ("all targets exhausted") as a hard, + * non-retried failure — exactly the regression this suite exists to catch. + */ +import test from "node:test"; + +import { + skip, + sendAndValidate, + ensureTestEnvironment, + genHugeContextMessage, + DELAY_BETWEEN_REQUESTS_MS, + type Message, +} from "./liveGeminiShared.ts"; + +test.before(async () => { + await ensureTestEnvironment(); +}); + +test("large context (~12k tokens): a single huge prompt completes normally", { skip }, async () => { + await sendAndValidate("huge-01: single large document batch", (): Message[] => [ + genHugeContextMessage(12000), + ]); +}); + +test( + "large context: back-to-back huge prompts exceed the 16000 TPM/min ceiling and still complete (no 503)", + { skip }, + async () => { + // Two ~12-13k-token requests within the same 60s window comfortably + // exceed Gemini's free-tier 16000 TPM ceiling for gemma-4 — this is + // deliberately adversarial. A slightly different token target per call + // (and the "Section N" markers inside genHugeContextMessage) keeps the + // prompts distinct enough to avoid a semantic-cache hit masking a real + // upstream dispatch on the second call. + await sendAndValidate("huge-02a: large batch, first of two", (): Message[] => [ + genHugeContextMessage(12000), + ]); + await new Promise((r) => setTimeout(r, Math.min(DELAY_BETWEEN_REQUESTS_MS, 2000))); + await sendAndValidate( + "huge-02b: large batch, second of two (should push past 16000 TPM)", + (): Message[] => [genHugeContextMessage(13000)] + ); + } +); diff --git a/tests/integration/gemini-rate-limit-classification.test.ts b/tests/integration/gemini-rate-limit-classification.test.ts index bbeb7cbb6e..43589566e3 100644 --- a/tests/integration/gemini-rate-limit-classification.test.ts +++ b/tests/integration/gemini-rate-limit-classification.test.ts @@ -23,10 +23,14 @@ const { checkFallbackError } = await import("../../open-sse/services/accountFall const { RateLimitReason } = await import("../../open-sse/config/constants.ts"); const { incrementRequestCount, + incrementTokenUsage, getDailyRequestCount, getMinuteRequestCount, + getMinuteTokenCount, isRpdExhausted, isRpmExhausted, + isTpmExhausted, + classifyGeminiQuotaMetricFromText, resetCounters, } = await import("../../open-sse/services/geminiRateLimitTracker.ts"); @@ -140,18 +144,19 @@ test("Gemini 2.5 Flash both RPM and RPD hit: RPD check runs first → QUOTA_EXHA assert.equal(result.reason, RateLimitReason.QUOTA_EXHAUSTED); }); -// ── Scenario 5: Gemma 4 — 15 RPM hit, 1500 RPD not hit → RATE_LIMIT_EXCEEDED ─ +// ── Scenario 5: 16 RPM hit (RPD=500 untouched) → RATE_LIMIT_EXCEEDED ───────── -test("Gemma 4 15 RPM hit (RPD=1500 untouched): 429 classifies as RATE_LIMIT_EXCEEDED", () => { - for (let i = 0; i < 15; i++) incrementRequestCount("gemini/gemma-4-31b-it"); - assert.equal(isRpmExhausted("gemini/gemma-4-31b-it"), true); - assert.equal(isRpdExhausted("gemini/gemma-4-31b-it"), false); +test("16 RPM hit (RPD<500 untouched): 429 classifies as RATE_LIMIT_EXCEEDED", () => { + // gemini-3.1-flash-lite: RPM=15, RPD=500 + for (let i = 0; i < 16; i++) incrementRequestCount("gemini-3.1-flash-lite"); + assert.equal(isRpmExhausted("gemini-3.1-flash-lite"), true); + assert.equal(isRpdExhausted("gemini-3.1-flash-lite"), false); const result = checkFallbackError( 429, GEMINI_429_BODY, 0, - "gemini/gemma-4-31b-it", + "gemini-3.1-flash-lite", "gemini", null, PROFILE @@ -210,25 +215,25 @@ test("resetCounters clears both RPM and RPD exhaustion", () => { assert.equal(result.reason, RateLimitReason.RATE_LIMIT_EXCEEDED); }); -// ── Scenario 8: RPD exhaustion with Gemma 4 (high RPD, never hit with 15 RPM) ─ +// ── Scenario 8: RPD exhaustion overrides RPM classification ─────────────────── -test("Gemma 4 1500 RPD exhaustion overrides RPM classification", () => { - // Pump 1500 daily requests to exhaust RPD - for (let i = 0; i < 1500; i++) incrementRequestCount("gemini/gemma-4-31b-it"); - assert.equal(isRpdExhausted("gemini/gemma-4-31b-it"), true); - assert.equal(isRpmExhausted("gemini/gemma-4-31b-it"), true); // 1500 >> 15 RPM +test("RPD exhaustion overrides RPM classification (RPD checked first)", () => { + // gemini-2.5-flash: RPM=5, RPD=20 — 25 requests exhausts both + for (let i = 0; i < 25; i++) incrementRequestCount("gemini-2.5-flash"); + assert.equal(isRpdExhausted("gemini-2.5-flash"), true); + assert.equal(isRpmExhausted("gemini-2.5-flash"), true); const result = checkFallbackError( 429, GEMINI_429_BODY, 0, - "gemini/gemma-4-31b-it", + "gemini-2.5-flash", "gemini", null, PROFILE ); - // RPD check runs first + // RPD check runs first in the if-chain assert.equal(result.reason, RateLimitReason.QUOTA_EXHAUSTED); }); @@ -251,3 +256,137 @@ test("Unknown Gemini model without published limits falls through to generic 429 assert.equal(result.reason, RateLimitReason.RATE_LIMIT_EXCEEDED); }); + +// ── Scenario 10: TPM exhausted, RPD not exhausted → RATE_LIMIT_EXCEEDED ────── + +test("Gemini 3.1 Flash Lite 250001 tokens (TPM threshold): 429 classifies as RATE_LIMIT_EXCEEDED", () => { + // gemini-3.1-flash-lite: TPM=250000, RPD=500 + incrementTokenUsage("gemini-3.1-flash-lite", 250001); + assert.equal(isTpmExhausted("gemini-3.1-flash-lite"), true); + assert.equal(isRpdExhausted("gemini-3.1-flash-lite"), false); + + const result = checkFallbackError( + 429, + GEMINI_429_BODY, + 0, + "gemini-3.1-flash-lite", + "gemini", + null, + PROFILE + ); + + assert.equal(result.reason, RateLimitReason.RATE_LIMIT_EXCEEDED); +}); + +// ── Scenario 11: TPM + RPD both exhausted → RPD first → QUOTA_EXHAUSTED ─────── + +test("Gemini 2.5 Flash TPM and RPD both hit: RPD takes priority → QUOTA_EXHAUSTED", () => { + // gemini-2.5-flash: TPM=250000, RPD=20 + for (let i = 0; i < 25; i++) incrementRequestCount("gemini-2.5-flash"); + incrementTokenUsage("gemini-2.5-flash", 250001); + assert.equal(isTpmExhausted("gemini-2.5-flash"), true); + assert.equal(isRpdExhausted("gemini-2.5-flash"), true); + + const result = checkFallbackError( + 429, + GEMINI_429_BODY, + 0, + "gemini-2.5-flash", + "gemini", + null, + PROFILE + ); + + // RPD check runs first → QUOTA_EXHAUSTED + assert.equal(result.reason, RateLimitReason.QUOTA_EXHAUSTED); +}); + +// ── Scenario 11b: real upstream TPM 429 with ZERO local counter state (#7360) ─ +// +// Reproduces the live bug: a request rejected by Google before it ever +// completes never calls incrementTokenUsage, so isTpmExhausted() reads false +// at classification time even though Google's own error explicitly names the +// per-minute input-token metric. The text-based classifier must catch this +// when the local counters are blind. + +const REAL_GEMINI_TPM_429_BODY = + "You exceeded your current quota, please check your plan and billing details. " + + "For more information on this error, head to: https://ai.google.dev/gemini-api/docs/rate-limits. " + + "To monitor your current usage, head to: https://ai.dev/rate-limit.\n" + + "* Quota exceeded for metric: generativelanguage.googleapis.com/generate_content_free_tier_input_token_count, " + + "limit: 16000, model: gemma-4-31b\n" + + "Please retry in 57.992793655s."; + +test("classifyGeminiQuotaMetricFromText: real TPM error text → 'tpm'", () => { + assert.equal(classifyGeminiQuotaMetricFromText(REAL_GEMINI_TPM_429_BODY), "tpm"); +}); + +test("classifyGeminiQuotaMetricFromText: RPD-style metric text → 'rpd'", () => { + const body = + "Quota exceeded for metric: generativelanguage.googleapis.com/" + + "generate_content_free_tier_requests_per_day, limit: 20"; + assert.equal(classifyGeminiQuotaMetricFromText(body), "rpd"); +}); + +test("classifyGeminiQuotaMetricFromText: RPM-style metric text → 'rpm'", () => { + const body = + "Quota exceeded for metric: generativelanguage.googleapis.com/" + + "generate_content_free_tier_requests, limit: 5"; + assert.equal(classifyGeminiQuotaMetricFromText(body), "rpm"); +}); + +test("classifyGeminiQuotaMetricFromText: no recognizable metric → null", () => { + assert.equal(classifyGeminiQuotaMetricFromText(GEMINI_429_BODY), null); + assert.equal(classifyGeminiQuotaMetricFromText(null), null); + assert.equal(classifyGeminiQuotaMetricFromText(""), null); +}); + +test("Real Gemma-4 TPM 429 body with ZERO local counter state → RATE_LIMIT_EXCEEDED, not QUOTA_EXHAUSTED", () => { + // No incrementTokenUsage/incrementRequestCount calls — this reproduces a + // request rejected before it could ever contribute to the local counters. + assert.equal( + isTpmExhausted("gemma-4-31b-it"), + false, + "local counter is blind, as in the live bug" + ); + assert.equal(isRpdExhausted("gemma-4-31b-it"), false); + + const result = checkFallbackError( + 429, + REAL_GEMINI_TPM_429_BODY, + 0, + "gemma-4-31b-it", + "gemini", + null, + PROFILE + ); + + assert.equal( + result.reason, + RateLimitReason.RATE_LIMIT_EXCEEDED, + "the error text's own metric name must override the blind local counter" + ); + assert.equal(result.shouldFallback, true); +}); + +// ── Scenario 12: TPM tracking and query ─────────────────────────────────────── + +test("incrementTokenUsage tracks per-minute token consumption correctly", () => { + incrementTokenUsage("gemini-2.5-flash", 50000); + incrementTokenUsage("gemini-2.5-flash", 75000); + assert.equal(getMinuteTokenCount("gemini-2.5-flash"), 125000); + + // Distinct model counters are independent + incrementTokenUsage("gemini-2.5-flash-lite", 200000); + assert.equal(getMinuteTokenCount("gemini-2.5-flash-lite"), 200000); + assert.equal(getMinuteTokenCount("gemini-2.5-flash"), 125000); +}); + +// ── Scenario 13: resetCounters clears TPM state too ─────────────────────────── + +test("resetCounters clears token counters", () => { + incrementTokenUsage("gemini-2.5-flash", 250001); + assert.equal(isTpmExhausted("gemini-2.5-flash"), true); + resetCounters(); + assert.equal(isTpmExhausted("gemini-2.5-flash"), false); +}); diff --git a/tests/integration/live-gemini-agentic-loop.test.ts b/tests/integration/live-gemini-agentic-loop.test.ts new file mode 100644 index 0000000000..6169ce6309 --- /dev/null +++ b/tests/integration/live-gemini-agentic-loop.test.ts @@ -0,0 +1,371 @@ +/** + * tests/integration/live-gemini-agentic-loop.test.ts + * + * Live test: a REAL, streaming, 3-turn agentic tool-calling flow against the + * "default" gemini combo (strategy=auto, 2 gemma-4 targets), scripted to + * exercise the exact cross-model cooldown-wait sequence live incidents have + * shown: + * + * 1. Turn 1 (~10k-token dispatch): model A serves and replies with a + * write_file tool call. + * 2. Turn 2: the tool result + ~10k MORE filler is appended (cumulative + * conversation now ~20k tokens — past gemma-4's published 16000 TPM + * free-tier ceiling within the same rolling 60s window). Model A hits a + * real 429; OmniRoute transparently falls back to model B — the client + * must see a normal 200 with a tool call from B, NEVER the 429. + * 3. Turn 3: B's tool result + more filler. Now BOTH models are cooling + * down, but A's remaining cooldown (recorded a full turn earlier) is + * shorter than B's and well under the 5-minute comboCooldownWait budget + * — the request must STALL for A rather than give up, using the + * synthetic startup "thinking" keep-alive frame + * (open-sse/utils/earlyStreamKeepalive.ts OPENAI_STARTUP_THINKING_FRAME) + * to hold the SSE connection open during the wait, then resolve with A's + * response once its cooldown clears. + * + * Streaming is required (not just used for realism): earlyStreamKeepalive's + * "slow path" only exists for SSE routes, and it's the only way a client can + * observe that a wait happened without seeing an error — once the slow path + * commits to HTTP 200, a would-be error response is reframed as an in-band + * `event: error` SSE frame rather than changing the status code. So this test + * treats an `event: error` frame exactly like a leaked 429/503 status: both + * are the same regression (comboCooldownWait giving up instead of waiting). + * + * Env vars: same as liveGeminiShared.ts (OMNIROUTE_API_KEY required). + */ +import test from "node:test"; +import assert from "node:assert/strict"; +import { Agent, fetch } from "undici"; + +import { + skip, + API_KEY, + BASE_URL, + MODEL, + ensureTestEnvironment, + pick, + LONG_DOCUMENTS, + CODE_BLOCKS, + TOOL_DEFINITION, +} from "./liveGeminiShared.ts"; + +// comboCooldownWait budgetMs default (src/lib/resilience/settings.ts) is +// 300_000ms. A single client request can span a full combo SET retry +// (maxSetRetries: 3 in the "default" combo config), each set trying both +// targets at up to comboTargetTimeoutMs (300_000ms) apiece — give this two +// full target-timeouts of slack so a legitimate one-set-retry cycle doesn't +// get killed client-side before the server can resolve it. +const TURN_TIMEOUT_MS = 700_000; +const FILLER_TOKENS_PER_TURN = 10_000; +const MODEL_A = "gemma-4-31b-it"; +const MODEL_B = "gemma-4-26b-a4b-it"; +const SYNTHETIC_MODEL_MARKER = "omniroute"; +// Must match STARTUP_THINKING_TEXT in open-sse/utils/earlyStreamKeepalive.ts. +const STARTUP_THINKING_SUBSTRING = "OmniRoute:"; + +// Node's global fetch (undici) has its own client-side headersTimeout that +// defaults to 300_000ms — the SAME order of magnitude as comboCooldownWait's +// budget, so a genuine full-budget server-side wait can race the client's own +// timeout and get killed with UND_ERR_HEADERS_TIMEOUT before the server ever +// gets to respond. Use an explicit dispatcher with headroom above +// TURN_TIMEOUT_MS so only the server's behavior (and our own AbortSignal) is +// under test, not undici's unrelated default. Irrelevant for the actual SSE +// body once bytes start flowing (the keepalive frames reset it), but matters +// for the initial connection. +const dispatcher = new Agent({ + headersTimeout: TURN_TIMEOUT_MS + 30_000, + bodyTimeout: TURN_TIMEOUT_MS + 30_000, +}); + +function buildFillerText(approxTokens: number): string { + const CHARS_PER_TOKEN = 4; + const targetChars = approxTokens * CHARS_PER_TOKEN; + const chunks = [...LONG_DOCUMENTS, ...CODE_BLOCKS]; + let content = ""; + let i = 0; + while (content.length < targetChars) { + content += `\n\n--- Reference ${i + 1} ---\n\n${pick(chunks)}`; + i++; + } + return content; +} + +type ToolCallMsg = { id: string; type: "function"; function: { name: string; arguments: string } }; +type AgentMessage = + | { role: "system" | "user"; content: string } + | { role: "assistant"; content: string | null; tool_calls?: ToolCallMsg[] } + | { role: "tool"; tool_call_id: string; content: string }; + +type TurnResult = { + status: number; + servedModel: string | null; + sawSyntheticKeepalive: boolean; + sawErrorEvent: string | null; + toolCalls: ToolCallMsg[]; + content: string; + finishReason: string; + timeToFirstByteMs: number; + timeToFirstRealChunkMs: number | null; + totalDurationMs: number; + correlationId: string; +}; + +async function runStreamingAgentTurn(messages: AgentMessage[]): Promise { + const start = performance.now(); + const res = await fetch(`${BASE_URL}/v1/chat/completions`, { + method: "POST", + headers: { "Content-Type": "application/json", Authorization: `Bearer ${API_KEY}` }, + body: JSON.stringify({ + model: MODEL, + messages, + tools: [TOOL_DEFINITION], + stream: true, + max_tokens: 4096, + temperature: 0.2, + ...(process.env.FORCE_TOOL_CHOICE_REQUIRED === "1" ? { tool_choice: "required" } : {}), + }), + signal: AbortSignal.timeout(TURN_TIMEOUT_MS), + dispatcher, + }); + const correlationId = res.headers.get("x-correlation-id") || "?"; + + // A leaked 429/503 status is the direct regression. The early-keepalive slow + // path (see file header) never changes the HTTP status once committed to + // 200, so this only catches a FAST failure (before the 2s keepalive + // threshold) — the `event: error` scan below catches the slow-path case. + if (res.status === 429 || res.status === 503) { + const body = await res.text().catch(() => ""); + assert.fail( + `turn leaked HTTP ${res.status} to the client instead of waiting for target model ` + + `availability (cid=${correlationId}): ${body.slice(0, 300)}` + ); + } + assert.equal(res.status, 200, `unexpected HTTP ${res.status} (cid=${correlationId})`); + + const reader = res.body!.getReader(); + const decoder = new TextDecoder(); + let buffer = ""; + let servedModel: string | null = null; + let sawSyntheticKeepalive = false; + let sawErrorEvent: string | null = null; + let pendingEventType: string | null = null; + let timeToFirstByteMs = -1; + let timeToFirstRealChunkMs: number | null = null; + let content = ""; + let finishReason = "unknown"; + const toolCallDeltas = new Map(); + + while (true) { + const { done, value } = await reader.read(); + if (done) break; + if (timeToFirstByteMs < 0) timeToFirstByteMs = performance.now() - start; + + buffer += decoder.decode(value, { stream: true }); + const lines = buffer.split("\n"); + buffer = lines.pop() || ""; + + for (const line of lines) { + if (line.startsWith("event: ")) { + pendingEventType = line.slice(7).trim(); + continue; + } + if (!line.startsWith("data: ")) continue; + const data = line.slice(6).trim(); + const eventType = pendingEventType; + pendingEventType = null; + if (data === "[DONE]") continue; + + if (eventType === "error") { + sawErrorEvent = data.slice(0, 300); + continue; + } + + try { + const parsed = JSON.parse(data) as Record; + const model = parsed.model as string | undefined; + const choice = ((parsed.choices ?? []) as Array>)[0]; + const delta = choice?.delta as Record | undefined; + + if (model === SYNTHETIC_MODEL_MARKER) { + const reasoningDelta = delta?.reasoning_content as string | undefined; + if (reasoningDelta?.includes(STARTUP_THINKING_SUBSTRING)) { + sawSyntheticKeepalive = true; + } + continue; // synthetic frame — not real model output + } + + if (model && !servedModel) servedModel = model; + if (model && timeToFirstRealChunkMs === null) { + timeToFirstRealChunkMs = performance.now() - start; + } + + if (delta?.content) content += delta.content as string; + if (choice?.finish_reason) finishReason = choice.finish_reason as string; + + const tcDeltas = delta?.tool_calls as Array> | undefined; + if (tcDeltas) { + for (const tcd of tcDeltas) { + const idx = String(tcd.index as number); + if (!toolCallDeltas.has(idx)) { + toolCallDeltas.set(idx, { id: (tcd.id as string) ?? "", name: "", arguments: "" }); + } + const entry = toolCallDeltas.get(idx)!; + if (tcd.id) entry.id = tcd.id as string; + const fn = tcd.function as Record | undefined; + if (fn?.name) entry.name = fn.name as string; + if (fn?.arguments) entry.arguments += fn.arguments as string; + } + } + } catch { + // skip malformed chunks + } + } + } + + const toolCalls: ToolCallMsg[] = [...toolCallDeltas.values()].map((tc) => ({ + id: tc.id, + type: "function" as const, + function: { name: tc.name, arguments: tc.arguments }, + })); + + if (sawErrorEvent) { + assert.fail( + `turn leaked an in-band SSE error event instead of waiting for target model ` + + `availability (cid=${correlationId}): ${sawErrorEvent}` + ); + } + + return { + status: res.status, + servedModel, + sawSyntheticKeepalive, + sawErrorEvent, + toolCalls, + content, + finishReason, + timeToFirstByteMs, + timeToFirstRealChunkMs, + totalDurationMs: performance.now() - start, + correlationId, + }; +} + +function logTurn(label: string, r: TurnResult) { + console.log( + ` ${label.padEnd(10)} HTTP ${r.status} | model=${r.servedModel ?? "?"} | ` + + `finish=${r.finishReason} | tools=${r.toolCalls.length} | ` + + `keepalive=${r.sawSyntheticKeepalive ? "yes" : "no"} | ` + + `ttfb=${Math.round(r.timeToFirstByteMs)}ms | ` + + `ttfRealChunk=${r.timeToFirstRealChunkMs === null ? "?" : Math.round(r.timeToFirstRealChunkMs) + "ms"} | ` + + `total=${Math.round(r.totalDurationMs)}ms | cid=${r.correlationId}` + ); +} + +test.before(async () => { + await ensureTestEnvironment(); +}); + +test( + "[32] agentic loop: transparent cross-model cooldown-wait across 3 real streaming turns", + { skip, timeout: 3 * TURN_TIMEOUT_MS + 60_000 }, + async () => { + const messages: AgentMessage[] = [ + { + role: "system", + content: + "You are building a small TypeScript library across 3 steps, one file per step. " + + "For each step, call write_file exactly once for that step's file (using the reference " + + "material provided as context), then briefly confirm you're ready for the next step.", + }, + ]; + + // ── Turn 1: initial ~10k-token dispatch — expect model A to serve a tool call ── + messages.push({ + role: "user", + content: `Step 1/3: write file step1.ts. Reference material:\n${buildFillerText(FILLER_TOKENS_PER_TURN)}`, + }); + const turn1 = await runStreamingAgentTurn(messages); + logTurn("turn 1/3", turn1); + + assert.equal(turn1.finishReason, "tool_calls", "turn 1 should finish with a tool call"); + assert.ok(turn1.toolCalls.length > 0, "turn 1 should have called write_file"); + assert.ok(turn1.servedModel, "turn 1 should report a served model"); + + messages.push({ + role: "assistant", + content: turn1.content || null, + tool_calls: turn1.toolCalls, + }); + for (const tc of turn1.toolCalls) { + messages.push({ role: "tool", tool_call_id: tc.id, content: JSON.stringify({ ok: true }) }); + } + + // ── Turn 2: tool result + ~10k MORE filler (cumulative ~20k, past the 16k ── + // TPM ceiling within the rolling 60s window) — model A should hit a real + // 429 and OmniRoute should transparently fail over to model B. The served + // model changing between turn 1 and turn 2, with NO leaked error, is the + // client-observable proof that (a) a 429 really happened and (b) the other + // model was transparently retried — there is no other way for a client to + // see this, since hiding the 429 from the client is the entire point of + // comboCooldownWait. + messages.push({ + role: "user", + content: `Step 2/3: write file step2.ts. Reference material:\n${buildFillerText(FILLER_TOKENS_PER_TURN)}`, + }); + const turn2 = await runStreamingAgentTurn(messages); + logTurn("turn 2/3", turn2); + + assert.equal(turn2.finishReason, "tool_calls", "turn 2 should finish with a tool call"); + assert.ok(turn2.toolCalls.length > 0, "turn 2 should have called write_file"); + assert.notEqual( + turn2.servedModel, + turn1.servedModel, + `expected turn 2 to transparently fail over to the OTHER model after turn 1's model ` + + `(${turn1.servedModel}) hit TPM contention — got the SAME model again ` + + `(${turn2.servedModel}), meaning no 429/fallback was observed. Re-run if the account ` + + `wasn't actually under contention this time.` + ); + + messages.push({ + role: "assistant", + content: turn2.content || null, + tool_calls: turn2.toolCalls, + }); + for (const tc of turn2.toolCalls) { + messages.push({ role: "tool", tool_call_id: tc.id, content: JSON.stringify({ ok: true }) }); + } + + // ── Turn 3: tool result + more filler — B (just used) should ALSO hit 429, ── + // but A's cooldown (recorded a full turn earlier) is now the shorter of the + // two and well under the 5-minute comboCooldownWait budget — the request + // must STALL for A specifically rather than crystallizing a 503. The + // synthetic startup "thinking" keep-alive frame is the client-visible proof + // the server actually waited instead of just failing fast; servedModel + // flipping back to A (not staying on B, not erroring) is the proof it + // waited for the SHORTER cooldown specifically. + messages.push({ + role: "user", + content: `Step 3/3: write file step3.ts. Reference material:\n${buildFillerText(FILLER_TOKENS_PER_TURN)}`, + }); + const turn3 = await runStreamingAgentTurn(messages); + logTurn("turn 3/3", turn3); + + assert.equal(turn3.finishReason, "tool_calls", "turn 3 should finish with a tool call"); + assert.ok(turn3.toolCalls.length > 0, "turn 3 should have called write_file"); + assert.equal( + turn3.servedModel, + turn1.servedModel, + `expected turn 3 to wait for and return the LOWER-cooldown model (${turn1.servedModel}, ` + + `same as turn 1) once B also hit contention — got ${turn3.servedModel}` + ); + assert.ok( + turn3.sawSyntheticKeepalive, + "expected the synthetic startup keep-alive ('thinking') frame during turn 3's stall — " + + "its absence means the wait was fast enough to not need it, or the keepalive path didn't engage" + ); + + console.log( + `\n Summary: turn1=${turn1.servedModel} → turn2=${turn2.servedModel} (fallback) → ` + + `turn3=${turn3.servedModel} (waited for lower cooldown, keepalive=${turn3.sawSyntheticKeepalive})` + ); + } +); diff --git a/tests/integration/live-gemini-workload.test.ts b/tests/integration/live-gemini-workload.test.ts index ea7a1fec1b..12dcb4de2d 100644 --- a/tests/integration/live-gemini-workload.test.ts +++ b/tests/integration/live-gemini-workload.test.ts @@ -240,3 +240,60 @@ test("[29] streaming: correlation IDs are unique per request", { skip }, async ( `expected ${count} unique CIDs, got ${unique.size}: ${cids.join(", ")}` ); }); + +// ── Responses API — same coverage as the Chat Completions streaming tests +// above, but against /v1/responses (#7360 follow-up) ───────────────────── + +test("[30] responses API: streaming payloads return content", { skip }, async () => { + const failures: string[] = []; + + for (let i = 0; i < CASE_BUILDERS.length; i++) { + const tc = CASE_BUILDERS[i]; + const label = `responses-${String(i + 1).padStart(2, "0")}: ${tc.name}`; + try { + const r = await sendAndValidate(label, tc.build, true, "responses"); + if (r.contentLength === 0) { + failures.push(`${tc.name}: 0 bytes content`); + } + if (r.status !== 200) { + failures.push(`${tc.name}: HTTP ${r.status}`); + } + } catch (err) { + failures.push(`${tc.name}: ${err instanceof Error ? err.message : String(err)}`); + } + } + + if (failures.length > 0) { + console.log(`\n Responses API streaming failures (${failures.length}):`); + for (const f of failures) console.log(` ${f}`); + } + + assert.equal( + failures.length, + 0, + `${failures.length}/${CASE_BUILDERS.length} Responses API streaming payloads failed` + ); +}); + +test("[31] responses API: correlation IDs are unique per request", { skip }, async () => { + const cids: string[] = []; + const count = 5; + + for (let i = 0; i < count; i++) { + const tc = CASE_BUILDERS[i % CASE_BUILDERS.length]; + const r = await sendAndValidate( + `responses-cid-${i + 1}: ${tc.name}`, + tc.build, + true, + "responses" + ); + cids.push(r.correlationId); + } + + const unique = new Set(cids); + assert.equal( + unique.size, + count, + `expected ${count} unique CIDs, got ${unique.size}: ${cids.join(", ")}` + ); +}); diff --git a/tests/integration/liveGeminiShared.ts b/tests/integration/liveGeminiShared.ts index f91b285242..35e7616713 100644 --- a/tests/integration/liveGeminiShared.ts +++ b/tests/integration/liveGeminiShared.ts @@ -384,6 +384,33 @@ export function genAgenticTaskMessage(): Message { return { role: "user", content: pick(AGENTIC_TASKS) }; } +// #7360 follow-up: the standard CASE_BUILDERS prompts are a few hundred to a +// couple thousand tokens — nowhere near Gemini's free-tier TPM ceiling (16000 +// tokens/min for gemma-4, per the live error text: "Quota exceeded for +// metric: generate_content_free_tier_input_token_count, limit: 16000"). That +// meant none of the existing workload tests ever exercised a REAL TPM 429 — +// only RPM-style rate limiting. genHugeContextMessage builds a single message +// large enough (~4 chars/token estimate) to approach or exceed that ceiling by +// itself, so a couple of these back-to-back genuinely trips Gemini's TPM +// limit and exercises the real classification (RATE_LIMIT_EXCEEDED, not +// QUOTA_EXHAUSTED) + comboCooldownWait retry path end-to-end, not just a +// synthetic/mocked 429. +export function genHugeContextMessage(approxTokens = 12000): Message { + const CHARS_PER_TOKEN = 4; + const targetChars = approxTokens * CHARS_PER_TOKEN; + const chunks = [...LONG_DOCUMENTS, ...CODE_BLOCKS]; + let content = ""; + let i = 0; + while (content.length < targetChars) { + content += `\n\n--- Section ${i + 1} ---\n\n${chunks[i % chunks.length]}`; + i++; + } + return { + role: "user", + content: `I'm pasting a large batch of internal documentation and code samples below. Read through all of it, then give me a single consolidated summary (max 200 words) covering the recurring themes.\n${content}`, + }; +} + export function genMultiTurnConversation(turns: number): Message[] { const messages: Message[] = []; @@ -478,6 +505,72 @@ interface StreamResult { totalTokens: number; } +// #7360 follow-up: extend the workload test to the Responses API too (not +// just Chat Completions). Parses OmniRoute's own event shapes from +// open-sse/translator/response/openai-responses.ts: response.output_text.delta +// / response.reasoning_summary_text.delta for content, response.completed for +// the terminal status + usage. +export async function readResponsesSSEStream(response: Response): Promise { + const reader = response.body!.getReader(); + const decoder = new TextDecoder(); + let buffer = ""; + let fullContent = ""; + let finishReason = "unknown"; + let totalTokens = 0; + let rawChunkCount = 0; + const debugLines: string[] = []; + + while (true) { + const { done, value } = await reader.read(); + if (done) break; + rawChunkCount++; + + buffer += decoder.decode(value, { stream: true }); + const lines = buffer.split("\n"); + buffer = lines.pop() || ""; + + for (const line of lines) { + if (!line.startsWith("data: ")) continue; + const data = line.slice(6).trim(); + if (data === "[DONE]") continue; + + if (debugLines.length < 3) { + debugLines.push(data.slice(0, 200)); + } + + try { + const parsed = JSON.parse(data) as Record; + const type = parsed.type as string | undefined; + + if ( + type === "response.output_text.delta" || + type === "response.reasoning_summary_text.delta" + ) { + const delta = parsed.delta as string | undefined; + if (delta) fullContent += delta; + } else if (type === "response.completed") { + const resp = parsed.response as Record | undefined; + finishReason = (resp?.status as string) || "unknown"; + const usage = resp?.usage as Record | undefined; + if (usage) { + totalTokens = + usage.total_tokens ?? (usage.input_tokens ?? 0) + (usage.output_tokens ?? 0); + } + } + } catch { + // skip malformed chunks + } + } + } + + if (fullContent.length === 0 && rawChunkCount > 0) { + console.log(` [DEBUG] responses: empty content: ${rawChunkCount} raw chunks`); + for (const d of debugLines) console.log(` [DEBUG] data: ${d}`); + } + + return { fullContent, finishReason, totalTokens }; +} + export async function readSSEStream(response: Response): Promise { const reader = response.body!.getReader(); const decoder = new TextDecoder(); @@ -679,6 +772,11 @@ export function validateToolCallArguments(toolCalls: ToolCall[] | ResponsesToolC } } +// Ad-hoc experiment flag: force tool_choice: "required" across every live +// Gemini tool-call helper below, without permanently changing default test +// behavior. Set FORCE_TOOL_CHOICE_REQUIRED=1 to compare against baseline. +const FORCE_TOOL_CHOICE_REQUIRED = process.env.FORCE_TOOL_CHOICE_REQUIRED === "1"; + export async function sendToolCallChatRequest( model: string, prompt: string @@ -696,6 +794,7 @@ export async function sendToolCallChatRequest( temperature: 0.1, stream: false, max_tokens: 4096, + ...(FORCE_TOOL_CHOICE_REQUIRED ? { tool_choice: "required" } : {}), }), signal: AbortSignal.timeout(90_000), }); @@ -723,6 +822,7 @@ export async function sendStreamingToolCallChatRequest( temperature: 0.1, stream: true, max_tokens: 4096, + ...(FORCE_TOOL_CHOICE_REQUIRED ? { tool_choice: "required" } : {}), }), signal: AbortSignal.timeout(120_000), }); @@ -833,6 +933,7 @@ export async function sendToolCallResponsesRequest( temperature: 0.1, stream: false, max_output_tokens: 4096, + ...(FORCE_TOOL_CHOICE_REQUIRED ? { tool_choice: "required" } : {}), }), signal: AbortSignal.timeout(90_000), }); @@ -867,6 +968,7 @@ export async function sendStreamingToolCallResponsesRequest( temperature: 0.1, stream: true, max_output_tokens: 4096, + ...(FORCE_TOOL_CHOICE_REQUIRED ? { tool_choice: "required" } : {}), }), signal: AbortSignal.timeout(120_000), }); @@ -952,7 +1054,8 @@ function ts(): string { export async function sendAndValidate( tcName: string, buildMessages: () => Message[], - stream = true + stream = true, + apiFormat: "chat" | "responses" = "chat" ): Promise<{ status: number; duration: number; @@ -962,6 +1065,7 @@ export async function sendAndValidate( }> { const MAX_RETRIES = 3; const RETRY_DELAY_MS = 10_000; + const endpoint = apiFormat === "responses" ? "/v1/responses" : "/v1/chat/completions"; for (let attempt = 1; attempt <= MAX_RETRIES; attempt++) { const messages = buildMessages(); @@ -972,19 +1076,30 @@ export async function sendAndValidate( const start = performance.now(); try { - const response = await fetch(`${BASE_URL}/v1/chat/completions`, { + const body = + apiFormat === "responses" + ? { + model: MODEL, + input: messages, + stream, + max_output_tokens: 4096, + temperature: 0.3, + } + : { + model: MODEL, + messages, + stream, + max_tokens: 4096, + temperature: 0.3, + }; + + const response = await fetch(`${BASE_URL}${endpoint}`, { method: "POST", headers: { "Content-Type": "application/json", Authorization: `Bearer ${API_KEY}`, }, - body: JSON.stringify({ - model: MODEL, - messages, - stream, - max_tokens: 4096, - temperature: 0.3, - }), + body: JSON.stringify(body), signal: controller.signal, }); @@ -997,10 +1112,19 @@ export async function sendAndValidate( let totalTokens = 0; if (stream) { - const streamResult = await readSSEStream(response); + const streamResult = + apiFormat === "responses" + ? await readResponsesSSEStream(response) + : await readSSEStream(response); content = streamResult.fullContent; finishReason = streamResult.finishReason; totalTokens = streamResult.totalTokens; + } else if (apiFormat === "responses") { + const json = await response.json().catch(() => ({})); + const textItem = json?.output?.find((o: Record) => o.type === "message"); + content = textItem?.content?.[0]?.text || ""; + finishReason = json?.status || "unknown"; + totalTokens = json?.usage?.total_tokens || 0; } else { const json = await response.json().catch(() => ({})); const choice = json?.choices?.[0]; @@ -1024,7 +1148,8 @@ export async function sendAndValidate( ); if (response.status === 200) { - const isGoodFinish = finishReason === "stop" || finishReason === "length"; + const isGoodFinish = + finishReason === "stop" || finishReason === "length" || finishReason === "completed"; const isRetryable = content.length === 0 || finishReason === "malformed_response" || @@ -1048,7 +1173,17 @@ export async function sendAndValidate( } else { assert.fail(`expected stop/length finish, got ${finishReason} | cid: ${correlationId}`); } - } else if ((response.status === 503 || response.status === 429) && attempt < MAX_RETRIES) { + } else if (response.status === 503) { + // #7360: a 503 from a combo means "all targets exhausted" — exactly + // the failure mode the cooldown-aware wait/retry is supposed to + // prevent. Silently retrying past it here would mask a regression + // instead of catching it, so this is a hard, immediate failure — + // never retried. + const errorBody = await response.text().catch(() => "unknown"); + assert.fail( + `${ts()} ${tcName.padEnd(45)} HTTP 503 (combo exhausted, not retried): ${errorBody} | cid: ${correlationId}` + ); + } else if (response.status === 429 && attempt < MAX_RETRIES) { console.log( `${ts()} ${tcName.padEnd(45)} RETRY ${attempt}/${MAX_RETRIES} after ${response.status} (waiting ${RETRY_DELAY_MS / 1000}s)` ); @@ -1069,7 +1204,12 @@ export async function sendAndValidate( } catch (err) { clearTimeout(timeout); const errorMessage = err instanceof Error ? err.message : String(err); - if ((errorMessage.includes("503") || errorMessage.includes("429")) && attempt < MAX_RETRIES) { + if (errorMessage.includes("503")) { + // #7360: never retry past a 503 (combo exhausted) — see the non-throw + // branch above for why. + throw err; + } + if (errorMessage.includes("429") && attempt < MAX_RETRIES) { console.log( `${ts()} ${tcName.padEnd(45)} RETRY ${attempt}/${MAX_RETRIES} after error (waiting ${RETRY_DELAY_MS / 1000}s)` ); diff --git a/tests/integration/newly-enabled-providers.test.ts b/tests/integration/newly-enabled-providers.test.ts new file mode 100644 index 0000000000..c10ca9290f --- /dev/null +++ b/tests/integration/newly-enabled-providers.test.ts @@ -0,0 +1,109 @@ +/** + * tests/integration/newly-enabled-providers.test.ts + * + * Workload benchmark for the batch of models the operator enabled on + * 2026-07-22: a new Cerebras key, "free"-tagged OpenRouter models, and + * OpenCode Zen's currently-live free roster. Uses the same 5-case + * BENCHMARK_CASES slice every other model in freeModelBenchmarkShared.ts was + * run through, for a direct, apples-to-apples comparison. + * + * Report, not a gate. Note from building this list: several of these models + * are reasoning-heavy and looked "broken" (502 upstream_empty_response) under + * a small max_tokens — the reasoning field alone consumed the whole budget + * before any content was produced. All resolved cleanly once given a + * realistic budget (this file uses benchmarkRequest's default, 2048) — none + * of the models below are actually dead. OpenCode's *static* catalog had + * drifted though: several previously-cataloged free model IDs (e.g. + * minimax-m2.5-free, ling-2.6-1t-free) no longer exist upstream at all + * (401) — the list here was refetched live from + * https://opencode.ai/zen/v1/models instead of trusting the stale catalog. + * Cerebras itself is excluded here: the new key hits a live 402 Payment + * Required (account/billing issue, not testable from this deployment) — the + * only 2 models it has (gpt-oss-120b, zai-glm-4.7) both hit the same + * account-wide block, confirmed on retry. + * + * Environment: + * OMNIROUTE_API_KEY — required (else test skips) + * OMNIROUTE_URL — defaults to http://localhost:3000 + */ +import test from "node:test"; +import assert from "node:assert/strict"; + +import { skip, ensureTestEnvironment } from "./liveGeminiShared.ts"; +import { + NEWLY_ENABLED_MODELS, + BENCHMARK_CASES, + getActiveProviders, + benchmarkRequest, + summarize, + formatBenchmarkTable, + type BenchmarkResult, + type ModelBenchmarkSummary, +} from "./freeModelBenchmarkShared.ts"; + +test.before(async () => { + await ensureTestEnvironment(); +}); + +test("newly-enabled providers: workload benchmark (2026-07-22 batch)", { skip }, async () => { + const activeProviders = await getActiveProviders(); + const candidates = NEWLY_ENABLED_MODELS.filter((spec) => activeProviders.has(spec.provider)); + const skipped = NEWLY_ENABLED_MODELS.filter((spec) => !activeProviders.has(spec.provider)); + + if (skipped.length > 0) { + console.log( + `\n [setup] skipping ${skipped.length} model(s) — provider not active: ` + + skipped.map((s) => s.provider).join(", ") + ); + } + + if (candidates.length === 0) { + console.log( + " [skip] no configured providers match NEWLY_ENABLED_MODELS — nothing to benchmark" + ); + return; + } + + console.log( + `\n Benchmarking ${candidates.length} newly-enabled model(s) × ${BENCHMARK_CASES.length} workload case(s) ` + + `= ${candidates.length * BENCHMARK_CASES.length} requests\n` + ); + + const summaries: ModelBenchmarkSummary[] = []; + + for (const spec of candidates) { + const results: BenchmarkResult[] = []; + + for (let i = 0; i < BENCHMARK_CASES.length; i++) { + const tc = BENCHMARK_CASES[i]; + if (i > 0) await new Promise((r) => setTimeout(r, 2000)); + + const r = await benchmarkRequest(spec, tc.name, tc.build, 60_000); + results.push(r); + + const status = r.ok ? "OK " : "FAIL"; + console.log( + ` [${status}] ${spec.displayName.padEnd(45)} ${tc.name.padEnd(35)} ` + + `HTTP ${r.status} | ${r.durationMs}ms | ${r.tokens} tok` + + (r.error ? ` | ${r.error}` : "") + ); + } + + summaries.push(summarize(spec, results)); + await new Promise((r) => setTimeout(r, 3000)); + } + + console.log(formatBenchmarkTable(summaries)); + + const totalAttempted = summaries.reduce((s, m) => s + m.attempted, 0); + const totalSucceeded = summaries.reduce((s, m) => s + m.succeeded, 0); + console.log( + `\n Overall: ${totalSucceeded}/${totalAttempted} requests succeeded across ${summaries.length} models\n` + ); + + assert.ok( + totalSucceeded > 0, + `every one of ${totalAttempted} requests across ${summaries.length} models failed — ` + + `likely a harness or routing bug, not free-tier flakiness` + ); +}); diff --git a/tests/unit/chat-build-client-raw-request.test.ts b/tests/unit/chat-build-client-raw-request.test.ts index 303854948f..cf9b4b237c 100644 --- a/tests/unit/chat-build-client-raw-request.test.ts +++ b/tests/unit/chat-build-client-raw-request.test.ts @@ -6,7 +6,10 @@ // clone cannot leak a shared reference that downstream mutation would corrupt. import test from "node:test"; import assert from "node:assert/strict"; -import { buildClientRawRequest } from "../../src/sse/handlers/chat.ts"; +import { + buildClientRawRequest, + resolveDispatchClientRawRequest, +} from "../../src/sse/handlers/chat.ts"; function req(body: unknown) { return new Request("http://x/v1/chat/completions", { @@ -38,3 +41,59 @@ test("endpoint and headers are captured from the request", () => { assert.equal(out.endpoint, "/v1/chat/completions"); assert.equal(out.headers["content-type"], "application/json"); }); + +// #7360 follow-up (live incident, log id 1784418258231-14961a): a combo target +// abandoned by comboTargetTimeoutMs used to hang forever because chatCore.ts's +// createStreamController/withRateLimit only ever watches the ORIGINAL client's +// request.signal — which stays open for as long as the overall combo keeps +// succeeding via a different target. resolveDispatchClientRawRequest merges in +// the per-target modelAbortSignal so an abandoned dispatch can observe its own +// abort and reach its cleanup path (trackPendingRequest(false)). +test("resolveDispatchClientRawRequest returns clientRawRequest unchanged when there is no modelAbortSignal", () => { + const clientRawRequest = { endpoint: "/v1/responses", signal: null }; + const out = resolveDispatchClientRawRequest(clientRawRequest, null); + assert.equal(out, clientRawRequest, "must be the exact same reference — no-op common case"); +}); + +test("resolveDispatchClientRawRequest uses modelAbortSignal directly when clientRawRequest has no signal of its own", () => { + const modelAbortController = new AbortController(); + const clientRawRequest = { endpoint: "/v1/responses", signal: null }; + const out = resolveDispatchClientRawRequest(clientRawRequest, modelAbortController.signal); + assert.equal(out?.endpoint, "/v1/responses", "other fields are preserved"); + assert.equal(out?.signal?.aborted, false); + modelAbortController.abort(new Error("target timeout")); + assert.equal(out?.signal?.aborted, true, "the returned signal must reflect the model abort"); +}); + +test("resolveDispatchClientRawRequest merges both signals — EITHER aborting fires the combined signal", () => { + const clientAbortController = new AbortController(); + const modelAbortController = new AbortController(); + const clientRawRequest = { endpoint: "/v1/responses", signal: clientAbortController.signal }; + + const out = resolveDispatchClientRawRequest(clientRawRequest, modelAbortController.signal); + assert.equal(out?.signal?.aborted, false); + + // The per-target timeout fires WITHOUT the real client ever disconnecting — + // this is exactly the live-incident scenario: the merged signal must still abort. + modelAbortController.abort(new Error("comboTargetTimeoutMs exceeded")); + assert.equal( + out?.signal?.aborted, + true, + "modelAbortSignal alone (client signal untouched) must abort the merged signal" + ); + assert.equal( + clientAbortController.signal.aborted, + false, + "the original client signal is untouched" + ); +}); + +test("resolveDispatchClientRawRequest: the real client disconnecting also aborts the merged signal", () => { + const clientAbortController = new AbortController(); + const modelAbortController = new AbortController(); + const clientRawRequest = { endpoint: "/v1/responses", signal: clientAbortController.signal }; + + const out = resolveDispatchClientRawRequest(clientRawRequest, modelAbortController.signal); + clientAbortController.abort(new Error("client disconnected")); + assert.equal(out?.signal?.aborted, true); +}); diff --git a/tests/unit/chatcore-translation-paths.test.ts b/tests/unit/chatcore-translation-paths.test.ts index ed4310024e..26048ab15f 100644 --- a/tests/unit/chatcore-translation-paths.test.ts +++ b/tests/unit/chatcore-translation-paths.test.ts @@ -2389,6 +2389,47 @@ test("chatCore maps raw string abort reasons to 499, not 502 (#7907)", async () assert.equal(result.error, "Request aborted"); }); +// Live incident territory (dashboard log id 1784504040241-6f8b9a): the client had +// ALREADY disconnected before this synthetic error body was ever computed — nothing +// was actually delivered to it. Persisting that body as `clientResponse` (the +// dashboard's "what the client received" field) is misleading, since it implies a +// response was sent when the client never got one. `error` above already records +// the failure reason; `clientResponse`/`responseBody` should stay empty for an abort. +test("chatCore does not log a synthetic clientResponse body for a client abort", async () => { + // clientResponse only ever lands in the persisted pipeline payloads when detailed + // call-log capture is on (attemptLogging.ts's detailedLoggingEnabled gate) — this is + // exactly the setting a real "detailed logging" connection/request has enabled, which + // is why the live incident's artifact JSON had a full pipeline (including the + // misleading clientResponse) to begin with. + await settingsDb.updateSettings({ call_log_pipeline_enabled: true }); + + await invokeChatCore({ + provider: "openai", + model: "gpt-4o-mini", + body: { + model: "gpt-4o-mini", + stream: false, + messages: [{ role: "user", content: "abort me, no fake clientResponse" }], + }, + responseFactory() { + const error = new Error("request aborted by client"); + error.name = "AbortError"; + throw error; + }, + }); + + const detail = await waitFor(() => getLatestCallLog()); + assert.ok(detail); + assert.equal(detail.status, 499); + assert.match(String(detail.error ?? ""), /Request aborted/); + assert.ok(detail.pipelinePayloads, "expected pipeline payloads when capture is enabled"); + assert.equal( + (detail.pipelinePayloads as Record).clientResponse, + undefined, + "an aborted request never delivered anything to the client — clientResponse must stay unset" + ); +}); + test("chatCore returns streaming responses without waiting for upstream completion", async () => { const encoder = new TextEncoder(); let closeUpstream: (() => void) | null = null; diff --git a/tests/unit/combo-config.test.ts b/tests/unit/combo-config.test.ts index a49513d835..5545beebac 100644 --- a/tests/unit/combo-config.test.ts +++ b/tests/unit/combo-config.test.ts @@ -6,6 +6,9 @@ const { getDefaultComboConfig, resolveComboTargetTimeoutMs, DEFAULT_COMBO_TARGET_TIMEOUT_MS, + COMBO_TARGET_TIMEOUT_WAIT_BUFFER_MS, + isComboCooldownWaitEligible, + resolveComboTargetTimeoutMsForCombo, resolveComboQueueDepth, } = await import("../../open-sse/services/comboConfig.ts"); const { createComboSchema, updateComboDefaultsSchema } = @@ -318,6 +321,62 @@ test("resolveComboTargetTimeoutMs falls back to the saner combo default when uns assert.equal(resolveComboTargetTimeoutMs({}, 0, 120000), 0); }); +// #7360 follow-up: a "default" auto-strategy combo hitting Gemini TPM/RPM on both +// targets waits out cooldowns for up to comboCooldownWait.budgetMs (default 130s), but +// DEFAULT_COMBO_TARGET_TIMEOUT_MS (120s) is shorter — the per-target timeout was cutting +// the wait off early and returning a synthetic 524 instead of letting the wait finish. +test("isComboCooldownWaitEligible only engages for quota-share/auto with the feature enabled", () => { + assert.equal(isComboCooldownWaitEligible("auto", { enabled: true }), true); + assert.equal(isComboCooldownWaitEligible("quota-share", { enabled: true }), true); + assert.equal(isComboCooldownWaitEligible("auto", { enabled: false }), false); + assert.equal(isComboCooldownWaitEligible("fill-first", { enabled: true }), false); + assert.equal(isComboCooldownWaitEligible("priority", { enabled: true }), false); +}); + +test("resolveComboTargetTimeoutMsForCombo raises the floor to cover the cooldown-wait budget for eligible strategies", () => { + const comboCooldownWait = { enabled: true, budgetMs: 130000 }; + + // Wait-eligible strategy: floor is budget + buffer (150s), not the 120s default. + assert.equal( + resolveComboTargetTimeoutMsForCombo({}, 600000, "auto", comboCooldownWait), + 130000 + COMBO_TARGET_TIMEOUT_WAIT_BUFFER_MS + ); + assert.equal( + resolveComboTargetTimeoutMsForCombo({}, 600000, "quota-share", comboCooldownWait), + 130000 + COMBO_TARGET_TIMEOUT_WAIT_BUFFER_MS + ); + + // Not wait-eligible (wrong strategy, or feature disabled): unchanged 120s default. + assert.equal( + resolveComboTargetTimeoutMsForCombo({}, 600000, "fill-first", comboCooldownWait), + DEFAULT_COMBO_TARGET_TIMEOUT_MS + ); + assert.equal( + resolveComboTargetTimeoutMsForCombo({}, 600000, "auto", { enabled: false, budgetMs: 130000 }), + DEFAULT_COMBO_TARGET_TIMEOUT_MS + ); + + // A small budget below the 120s default never lowers the floor. + assert.equal( + resolveComboTargetTimeoutMsForCombo({}, 600000, "auto", { enabled: true, budgetMs: 5000 }), + DEFAULT_COMBO_TARGET_TIMEOUT_MS + ); + + // Explicit per-combo targetTimeoutMs still wins over the derived floor. + assert.equal( + resolveComboTargetTimeoutMsForCombo( + { targetTimeoutMs: 45000 }, + 600000, + "auto", + comboCooldownWait + ), + 45000 + ); + + // The derived floor is still capped at the upstream ceiling. + assert.equal(resolveComboTargetTimeoutMsForCombo({}, 100000, "auto", comboCooldownWait), 100000); +}); + test("combo timeout schema rejects values beyond the safe timer limit", () => { const result = createComboSchema.safeParse({ name: "unsafe-timeout", diff --git a/tests/unit/combo-quota-share-cooldown-wait.test.ts b/tests/unit/combo-quota-share-cooldown-wait.test.ts index a12c16a0aa..320dd29095 100644 --- a/tests/unit/combo-quota-share-cooldown-wait.test.ts +++ b/tests/unit/combo-quota-share-cooldown-wait.test.ts @@ -76,6 +76,13 @@ function rateLimitResponse(status: number) { }); } +function rateLimitResponseWithRetryAfter(status: number, retryAfterMs: number) { + return jsonResponse(status, { + error: { message: `rate limited (${status})` }, + retryAfter: new Date(Date.now() + retryAfterMs).toISOString(), + }); +} + function comboOf(strategy: string) { return { name: `qtSd/${strategy}-${Math.random().toString(16).slice(2, 8)}`, @@ -191,3 +198,261 @@ test("quota-share with comboCooldownWait disabled → 429 propagated, NO wait", assert.equal(res.status, 429, "disabled feature must propagate the 429 unchanged"); assert.equal(calls, 1, "disabled feature must NOT wait+redispatch"); }); + +// #7360: the "default" combo (strategy=auto, two gemma-4 models) was crystallizing +// a 503 "all targets exhausted" ~6s after both targets hit a real Gemini TPM/RPM +// 429 (retry-after ~58s), instead of holding the request and retrying once the +// lower-cooldown target recovered. Mirrors the quota-share scenario above but with +// TWO distinct model targets and two DIFFERENT retry-after hints, to prove the +// combo (a) extends the wait to the "auto" strategy and (b) picks the target with +// the SMALLER remaining cooldown to retry, not just the first one in the list. +test("auto strategy (2 models, both rate-limited) → waits for the SHORTER cooldown, then succeeds", async () => { + const SHORT_RETRY_AFTER_MS = 200; + const LONG_RETRY_AFTER_MS = 3000; + const MODEL_A = "gemini/gemma-4-31b-it"; + const MODEL_B = "gemini/gemma-4-26b-a4b-it"; + const calls: string[] = []; + + const handleSingleModel = async (_body: unknown, modelStr: string) => { + calls.push(modelStr); + const timesSeen = calls.filter((m) => m === modelStr).length; + if (modelStr === MODEL_A && timesSeen === 1) + return rateLimitResponseWithRetryAfter(429, SHORT_RETRY_AFTER_MS); + if (modelStr === MODEL_B) return rateLimitResponseWithRetryAfter(429, LONG_RETRY_AFTER_MS); + // 2nd time MODEL_A is dispatched (after the wait), its short cooldown has cleared. + return okResponse(); + }; + + const startedAt = Date.now(); + const res = await handleComboChat({ + body: { model: "default" }, + combo: { + name: `default-${Math.random().toString(16).slice(2, 8)}`, + strategy: "auto", + models: [MODEL_A, MODEL_B], + config: { + auto: { explorationRate: 0 }, + maxRetries: 0, + retryDelayMs: 0, + fallbackDelayMs: 0, + maxSetRetries: 0, + }, + }, + handleSingleModel, + isModelAvailable: async () => true, + log: createLog() as never, + settings: shortModelLockoutSettings(), + allCombos: null, + }); + const elapsed = Date.now() - startedAt; + + assert.equal(res.status, 200, "expected the combo to wait out the shorter cooldown and succeed"); + assert.equal(calls.length, 3, `expected A, B, A again — got ${JSON.stringify(calls)}`); + assert.equal(calls[0], MODEL_A, "first target tried should be MODEL_A"); + assert.equal(calls[1], MODEL_B, "second target tried should be MODEL_B"); + assert.equal( + calls[2], + MODEL_A, + "should retry the LOWER-cooldown model (A), not wait for B's longer cooldown" + ); + assert.ok( + elapsed >= SHORT_RETRY_AFTER_MS, + `expected to have waited out the shorter cooldown, only ${elapsed}ms elapsed` + ); + assert.ok( + elapsed < LONG_RETRY_AFTER_MS, + `should NOT wait for the longer cooldown (waited ${elapsed}ms, B's cooldown was ${LONG_RETRY_AFTER_MS}ms)` + ); +}); + +// #7360 follow-up (live incident, log id 1784416706646-51): the test above uses +// maxSetRetries: 0, so it never exercises more than one setTry iteration — it +// missed a real bug where lastError/earliestRetryAfter/lastStatus were declared +// INSIDE the setTry loop body, resetting to null every retry. The real "default" +// combo config has maxSetRetries: 3 (see liveGeminiShared.ts's DEFAULT_COMBO_CONFIG +// and the live DB row), so when BOTH targets lock out on setTry 0, every +// subsequent setTry (1,2,3) pre-skips both via isModelLocked with no real +// dispatch — meaning lastStatus stayed null on the FINAL iteration, and the +// combo crystallized a bogus "all accounts inactive" 503 in ~6s instead of ever +// reaching the cooldown-aware wait, despite a real 429 with a clean ~150ms +// retry-after having been observed on setTry 0. +test("auto strategy with maxSetRetries > 0: both targets lock out on the FIRST setTry → still waits and succeeds, not a bogus 503", async () => { + const SHORT_RETRY_AFTER_MS = 150; + const MODEL_A = "gemini/gemma-4-31b-it"; + const MODEL_B = "gemini/gemma-4-26b-a4b-it"; + const calls: string[] = []; + + const handleSingleModel = async (_body: unknown, modelStr: string) => { + calls.push(modelStr); + const timesSeen = calls.filter((m) => m === modelStr).length; + if (timesSeen === 1) return rateLimitResponseWithRetryAfter(429, SHORT_RETRY_AFTER_MS); + return okResponse(); + }; + + const res = await handleComboChat({ + body: { model: "default" }, + combo: { + name: `default-${Math.random().toString(16).slice(2, 8)}`, + strategy: "auto", + models: [MODEL_A, MODEL_B], + config: { + auto: { explorationRate: 0 }, + maxRetries: 0, + retryDelayMs: 0, + fallbackDelayMs: 0, + // Real value from the "default" combo's stored config — this is the + // field whose non-zero value exposed the bug (multiple setTry passes + // needed for both targets to still be locked on the LAST pass). + maxSetRetries: 3, + setRetryDelayMs: 5, + }, + }, + handleSingleModel, + isModelAvailable: async () => true, + log: createLog() as never, + settings: shortModelLockoutSettings(), + allCombos: null, + }); + + assert.equal( + res.status, + 200, + `expected the combo to wait out the shared cooldown and succeed, got ${res.status} (${await res.clone().text()})` + ); + // Both targets got a real dispatch on setTry 0 (locking them out), then every + // pre-skipped setTry (1-3) should have led straight to the cooldown wait + // rather than crystallizing early — so exactly one of A/B gets a genuine + // 2nd dispatch after the wait, once its lock has cleared. + assert.ok(calls.length >= 3, `expected at least 3 dispatch calls, got ${JSON.stringify(calls)}`); +}); + +// Live incident (log id 1784457764961-73): with the REAL "default" combo config +// (maxRetries: 3, not 0 — see liveGeminiShared.ts DEFAULT_COMBO_CONFIG), a plain +// RPM-style 429 (rate_limit_exceeded, NOT a token-limit breach) on the FIRST +// dispatch of setTry 0 enters the `retry < maxRetries` branch, immediately trips +// model-lockout recording (modelLockout enabled for 429), and hits the +// "lockoutRecorded" bail-out — which returned null WITHOUT ever setting +// lastStatus/lastError, even though earliestRetryAfter had already been captured +// from that same response a few lines earlier. When BOTH targets hit this on +// setTry 0, lastStatus stays null through every subsequent pre-skipped setTry, so +// the final `if (!lastStatus)` check won the race against `if (earliestRetryAfter)` +// and crystallized a bogus ALL_ACCOUNTS_INACTIVE 503 in ~6s — even though a real +// 429 with a clean ~1min retry-after was observed on both targets. Production +// symptom: the client (a real agentic loop) saw repeated immediate 503s and kept +// retrying the whole request every ~7s. maxRetries: 0 (used by every test above) +// never enters this branch at all, which is why the existing suite missed it. +test("auto strategy with maxRetries > 0 (matches real 'default' combo config): plain 429 on first dispatch still waits and succeeds, not a bogus 503", async () => { + const SHORT_RETRY_AFTER_MS = 150; + const MODEL_A = "gemini/gemma-4-31b-it"; + const MODEL_B = "gemini/gemma-4-26b-a4b-it"; + const calls: string[] = []; + + const handleSingleModel = async (_body: unknown, modelStr: string) => { + calls.push(modelStr); + const timesSeen = calls.filter((m) => m === modelStr).length; + if (timesSeen === 1) return rateLimitResponseWithRetryAfter(429, SHORT_RETRY_AFTER_MS); + return okResponse(); + }; + + const res = await handleComboChat({ + body: { model: "default" }, + combo: { + name: `default-${Math.random().toString(16).slice(2, 8)}`, + strategy: "auto", + models: [MODEL_A, MODEL_B], + config: { + auto: { explorationRate: 0 }, + // Real values from the "default" combo's stored config (liveGeminiShared.ts + // DEFAULT_COMBO_CONFIG) — maxRetries: 3 is the field that exposes the bug: + // it's what lets the FIRST 429 enter the lockout-recording branch instead of + // falling straight through to "done retrying this model". + maxRetries: 3, + retryDelayMs: 0, + fallbackDelayMs: 0, + maxSetRetries: 3, + setRetryDelayMs: 5, + }, + }, + handleSingleModel, + isModelAvailable: async () => true, + log: createLog() as never, + settings: shortModelLockoutSettings(), + allCombos: null, + }); + + assert.equal( + res.status, + 200, + `expected the combo to wait out the shared cooldown and succeed, got ${res.status} (${await res.clone().text()})` + ); + assert.ok(calls.length >= 3, `expected at least 3 dispatch calls, got ${JSON.stringify(calls)}`); +}); + +// Live incident (log id 1784457764961-73 follow-up, same production request as the +// test above): fixing lastStatus recording exposed a SECOND, distinct bug behind the +// same symptom. The pre-dispatch "all credentials already cooling down" rejection +// (buildModelCooldownBody / handleNoCredentials in src/sse/handlers/chatHelpers.ts) +// nests its retry hint as `error.retry_after` (ISO string) / `error.reset_seconds` +// (seconds) — NOT the top-level `retryAfter` field every other 429 response shape in +// this codebase uses (see rateLimitResponseWithRetryAfter above). Combo.ts's error +// extraction only ever read the top-level field, so earliestRetryAfter stayed null +// for this specific shape even after lastStatus was correctly recorded — landing on +// the generic "all combo models unavailable" error instead of the cooldown-wait +// decision. Symptom was identical to the fixed bug: a leaked error instead of a wait. +test("auto strategy: model_cooldown response shape (nested error.retry_after, not top-level) still waits and succeeds", async () => { + const SHORT_RETRY_AFTER_MS = 150; + const MODEL_A = "gemini/gemma-4-31b-it"; + const MODEL_B = "gemini/gemma-4-26b-a4b-it"; + const calls: string[] = []; + + // Mirrors buildModelCooldownBody's actual shape (open-sse/utils/error.ts) — + // retry hint nested under `error`, not top-level `retryAfter`. + function modelCooldownShapedResponse(model: string, retryAfterMs: number) { + return jsonResponse(429, { + error: { + message: `All credentials for model ${model} are cooling down`, + type: "rate_limit_error", + code: "model_cooldown", + model, + reset_seconds: Math.max(Math.ceil(retryAfterMs / 1000), 1), + retry_after: new Date(Date.now() + retryAfterMs).toISOString(), + }, + }); + } + + const handleSingleModel = async (_body: unknown, modelStr: string) => { + calls.push(modelStr); + const timesSeen = calls.filter((m) => m === modelStr).length; + if (timesSeen === 1) return modelCooldownShapedResponse(modelStr, SHORT_RETRY_AFTER_MS); + return okResponse(); + }; + + const res = await handleComboChat({ + body: { model: "default" }, + combo: { + name: `default-${Math.random().toString(16).slice(2, 8)}`, + strategy: "auto", + models: [MODEL_A, MODEL_B], + config: { + auto: { explorationRate: 0 }, + maxRetries: 3, + retryDelayMs: 0, + fallbackDelayMs: 0, + maxSetRetries: 3, + setRetryDelayMs: 5, + }, + }, + handleSingleModel, + isModelAvailable: async () => true, + log: createLog() as never, + settings: shortModelLockoutSettings(), + allCombos: null, + }); + + assert.equal( + res.status, + 200, + `expected the combo to wait out the shared cooldown and succeed, got ${res.status} (${await res.clone().text()})` + ); + assert.ok(calls.length >= 3, `expected at least 3 dispatch calls, got ${JSON.stringify(calls)}`); +}); diff --git a/tests/unit/cooldown-aware-retry-budget.test.ts b/tests/unit/cooldown-aware-retry-budget.test.ts new file mode 100644 index 0000000000..b01fa1dfd1 --- /dev/null +++ b/tests/unit/cooldown-aware-retry-budget.test.ts @@ -0,0 +1,102 @@ +/** + * #7360 follow-up — cumulative wait budget for the single-model cooldown-aware + * retry (waitForCooldown / cooldownAwareRetry.ts). + * + * Before this, getCooldownAwareRetryDecision only bounded a SINGLE wait + * (maxRetryWaitMs) and a retry COUNT (maxRetries) — with no cap on the total + * time spent waiting across all retries. A request could re-wait maxRetries + * times at up to maxRetryWaitMs each with no overall ceiling. budgetMs (mirrors + * combo.ts's comboCooldownWait.budgetMs) now bounds the cumulative total, + * capped at 5 minutes, matching the "give up after 5 minutes" requirement. + */ +import test from "node:test"; +import assert from "node:assert/strict"; + +const { getCooldownAwareRetryDecision, resolveCooldownAwareRetrySettings } = + await import("../../src/sse/services/cooldownAwareRetry.ts"); + +function baseSettings(overrides: Partial> = {}) { + return { + enabled: true, + maxRetries: 5, + maxRetryWaitSec: 90, + maxRetryWaitMs: 90000, + budgetMs: 300000, + ...overrides, + }; +} + +test("getCooldownAwareRetryDecision retries when the wait fits both the per-wait cap and the remaining budget", () => { + const decision = getCooldownAwareRetryDecision({ + retryAfter: new Date(Date.now() + 60000).toISOString(), + settings: baseSettings(), + attempt: 0, + budgetLeftMs: 300000, + }); + assert.equal(decision.shouldRetry, true); +}); + +test("getCooldownAwareRetryDecision refuses to wait once the cumulative budget is exhausted, even if the single wait is under maxRetryWaitMs", () => { + const decision = getCooldownAwareRetryDecision({ + retryAfter: new Date(Date.now() + 60000).toISOString(), + settings: baseSettings(), + attempt: 1, + budgetLeftMs: 30000, // less than the 60s wait needed + }); + assert.equal(decision.shouldRetry, false); +}); + +test("getCooldownAwareRetryDecision allows a wait that exactly exhausts the remaining budget", () => { + const decision = getCooldownAwareRetryDecision({ + retryAfter: new Date(Date.now() + 60000).toISOString(), + settings: baseSettings(), + attempt: 0, + budgetLeftMs: 60000, + }); + assert.equal(decision.shouldRetry, true); +}); + +test("getCooldownAwareRetryDecision defaults budgetLeftMs to settings.budgetMs when the caller doesn't track it (backward compat)", () => { + const withinDefaultBudget = getCooldownAwareRetryDecision({ + retryAfter: new Date(Date.now() + 60000).toISOString(), + settings: baseSettings({ budgetMs: 90000 }), + attempt: 0, + // budgetLeftMs omitted — should fall back to settings.budgetMs (90000ms). + }); + assert.equal(withinDefaultBudget.shouldRetry, true); + + const exceedsDefaultBudget = getCooldownAwareRetryDecision({ + retryAfter: new Date(Date.now() + 200000).toISOString(), + settings: baseSettings({ budgetMs: 90000 }), + attempt: 0, + }); + assert.equal(exceedsDefaultBudget.shouldRetry, false); +}); + +test("resolveCooldownAwareRetrySettings floors budgetMs at maxRetryWaitMs and caps at 5 minutes", () => { + const floored = resolveCooldownAwareRetrySettings({ + resilienceSettings: { + waitForCooldown: { enabled: true, maxRetries: 3, maxRetryWaitSec: 90, budgetMs: 10000 }, + }, + }); + assert.equal(floored.budgetMs, 90000, "budgetMs can never be smaller than a single wait"); + + const capped = resolveCooldownAwareRetrySettings({ + resilienceSettings: { + waitForCooldown: { + enabled: true, + maxRetries: 3, + maxRetryWaitSec: 90, + budgetMs: 999999999, + }, + }, + }); + assert.equal(capped.budgetMs, 300000, "budgetMs is capped at 5 minutes"); +}); + +test("resolveCooldownAwareRetrySettings defaults to a 5-minute-capable budget out of the box", () => { + const settings = resolveCooldownAwareRetrySettings(null); + assert.equal(settings.budgetMs, 300000); + assert.equal(settings.maxRetryWaitSec, 90); + assert.equal(settings.maxRetries, 5); +}); diff --git a/tests/unit/early-stream-keepalive.test.ts b/tests/unit/early-stream-keepalive.test.ts index 5cd04ca192..500c11d2fd 100644 --- a/tests/unit/early-stream-keepalive.test.ts +++ b/tests/unit/early-stream-keepalive.test.ts @@ -5,6 +5,10 @@ import { withEarlyStreamKeepalive, ANTHROPIC_PING_FRAME, OPENAI_KEEPALIVE_FRAME, + OPENAI_STARTUP_THINKING_FRAME, + RESPONSES_STARTUP_THINKING_FRAME, + OPENAI_CHAT_ERROR_FRAME, + OPENAI_RESPONSES_ERROR_FRAME, } from "../../open-sse/utils/earlyStreamKeepalive.ts"; async function readAll(response: Response): Promise { @@ -97,6 +101,150 @@ test("slow handler emits the custom OpenAI keepalive chunk before the body", asy assert.match(body, /data: \[DONE\]/); }); +// #7360 follow-up: many clients time out waiting for the first SSE byte, and +// during a long Gemini rate-limit cooldown wait there's nothing real to send +// yet — OPENAI_STARTUP_THINKING_FRAME gives them a real, visible "we're still +// working on it" reasoning delta instead of an empty/no-op keepalive. +test("OPENAI_STARTUP_THINKING_FRAME is a reasoning_content delta chunk with the expected text", () => { + const decoded = new TextDecoder().decode(OPENAI_STARTUP_THINKING_FRAME); + assert.match(decoded, /^data: /); + assert.doesNotMatch(decoded, /^:/, "must not be an SSE comment"); + + const payload = JSON.parse(decoded.slice("data: ".length).trim()); + assert.equal(payload.object, "chat.completion.chunk"); + assert.deepEqual(payload.choices, [ + { + index: 0, + delta: { reasoning_content: "OmniRoute: got request, sending to provider" }, + finish_reason: null, + }, + ]); +}); + +test("slow handler emits startupFrame once, then falls back to keepaliveFrame on later ticks", async () => { + // intervalMs is floored at 250ms (see withEarlyStreamKeepalive), so the handler + // must resolve well past one full tick to reliably observe an interval keepalive + // before the real body arrives. + const slow = new Promise((resolve) => { + setTimeout(() => resolve(sseResponse("data: [DONE]\n\n")), 650); + }); + + const result = await withEarlyStreamKeepalive(slow, { + thresholdMs: 20, + intervalMs: 250, + keepaliveFrame: OPENAI_KEEPALIVE_FRAME, + startupFrame: OPENAI_STARTUP_THINKING_FRAME, + }); + + const body = await readAll(result); + const frames = body.split("\n\n").filter(Boolean); + const firstPayload = JSON.parse(frames[0].slice("data: ".length)); + assert.equal( + firstPayload.choices[0].delta.reasoning_content, + "OmniRoute: got request, sending to provider", + "the very first frame must carry the startup thinking text" + ); + + // At least one subsequent keepalive tick should have fired before the real + // body arrived (interval 30ms, handler resolves at 150ms) — those ticks use + // the lightweight keepaliveFrame, not a repeat of the startup text. + const laterKeepalives = frames + .slice(1, -1) // drop the startup frame and the final real "[DONE]" frame + .map((f) => JSON.parse(f.slice("data: ".length))); + assert.ok(laterKeepalives.length > 0, "expected at least one interval keepalive tick"); + for (const tick of laterKeepalives) { + assert.deepEqual(tick.choices[0].delta, {}, "interval ticks stay the lightweight empty delta"); + } + assert.match(body, /data: \[DONE\]/); +}); + +test("startupFrame defaults to keepaliveFrame when omitted (no behavior change)", async () => { + const slow = new Promise((resolve) => { + setTimeout(() => resolve(sseResponse("data: [DONE]\n\n")), 120); + }); + + const result = await withEarlyStreamKeepalive(slow, { + thresholdMs: 25, + intervalMs: 20, + keepaliveFrame: OPENAI_KEEPALIVE_FRAME, + // no startupFrame passed + }); + + const body = await readAll(result); + const firstFrame = body.split("\n\n")[0]; + const firstPayload = JSON.parse(firstFrame.slice("data: ".length)); + assert.deepEqual( + firstPayload.choices[0].delta, + {}, + "first frame falls back to the plain keepaliveFrame when no startupFrame is configured" + ); +}); + +// #7360 follow-up round 2: OpenClaw calls via /v1/responses (Responses API +// format), which only had the generic bare-comment keepalive — a live +// incident showed it disconnecting after ~56s waiting on a slow gemma-4 +// response. RESPONSES_STARTUP_THINKING_FRAME gives Responses-API clients the +// same real-content keepalive OpenAI chat/completions already got, as a +// self-contained (opened AND closed within this one frame) synthetic +// reasoning item — it never claims a response_id, so it can't collide with +// the real response's own independent response.created lifecycle that follows. +test("RESPONSES_STARTUP_THINKING_FRAME is a self-closed synthetic reasoning item with the expected text", () => { + const decoded = new TextDecoder().decode(RESPONSES_STARTUP_THINKING_FRAME); + const events = decoded + .split("\n\n") + .filter(Boolean) + .map((frame) => { + const [eventLine, dataLine] = frame.split("\n"); + return { + event: eventLine.replace(/^event: /, ""), + data: JSON.parse(dataLine.replace(/^data: /, "")), + }; + }); + + assert.deepEqual( + events.map((e) => e.event), + [ + "response.output_item.added", + "response.reasoning_summary_part.added", + "response.reasoning_summary_text.delta", + "response.reasoning_summary_part.done", + ] + ); + + const [added, partAdded, delta, partDone] = events; + assert.equal(added.data.item.type, "reasoning"); + const itemId = added.data.item.id; + assert.ok(itemId, "reasoning item must have an id"); + + assert.equal(partAdded.data.item_id, itemId); + assert.equal(delta.data.item_id, itemId); + assert.equal(delta.data.delta, "OmniRoute: got request, sending to provider"); + assert.equal(partDone.data.item_id, itemId); + assert.equal(partDone.data.part.text, "OmniRoute: got request, sending to provider"); +}); + +test("slow handler emits the Responses API startup frame before the real body", async () => { + const slow = new Promise((resolve) => { + setTimeout( + () => resolve(sseResponse("event: response.created\ndata: {}\n\ndata: [DONE]\n\n")), + 120 + ); + }); + + const result = await withEarlyStreamKeepalive(slow, { + thresholdMs: 25, + intervalMs: 20, + startupFrame: RESPONSES_STARTUP_THINKING_FRAME, + }); + + const body = await readAll(result); + assert.match(body, /event: response\.output_item\.added/); + assert.match(body, /OmniRoute: got request, sending to provider/); + assert.match(body, /event: response\.reasoning_summary_part\.done/); + assert.match(body, /event: response\.created/, "should forward the real upstream body"); + assert.match(body, /data: \[DONE\]/); +}); + test("slow handler emits the custom keepaliveFrame (Anthropic ping) before the body", async () => { const slow = new Promise((resolve) => { setTimeout( @@ -143,6 +291,68 @@ test("slow handler that errors emits an in-band error frame (#2544)", async () = assert.match(body, /rate limited/); }); +// Live incident territory (log ids 1784465227489-a2cbc0 / 1784457764961-73): the +// default ERROR_FRAME uses a named `event: error` SSE line, which is the Anthropic +// Messages API convention — correct for /v1/messages, but real OpenAI Chat +// Completions / Responses streams never send `event:` lines at all. A naive +// line-based parser (what most OpenAI-compatible clients use, not a full +// EventSource) can silently drop that line and/or desync on the following `data:` +// line, so the error would never reach the client — it just looks stuck. +test("OPENAI_CHAT_ERROR_FRAME is a plain data: line with no event: field", () => { + const decoded = new TextDecoder().decode(OPENAI_CHAT_ERROR_FRAME); + assert.doesNotMatch(decoded, /^event:/, "Chat Completions streams never use the event: field"); + assert.match(decoded, /^data: /); + + const payload = JSON.parse(decoded.replace(/^data: /, "").trim()); + assert.ok(payload.error?.message, "openai-node's stream parser checks for a top-level error key"); +}); + +test("OPENAI_RESPONSES_ERROR_FRAME is a plain data: line discriminated by type, not event:", () => { + const decoded = new TextDecoder().decode(OPENAI_RESPONSES_ERROR_FRAME); + assert.doesNotMatch(decoded, /^event:/, "Responses API streams never use the event: field"); + assert.match(decoded, /^data: /); + + const payload = JSON.parse(decoded.replace(/^data: /, "").trim()); + assert.equal( + payload.type, + "error", + "Responses API events are discriminated by a `type` field inside the JSON payload" + ); +}); + +test("errorFrame option overrides the default Anthropic-style event: error frame", async () => { + const slowFail = new Promise((resolve) => { + setTimeout( + () => + resolve( + new Response(JSON.stringify({ error: { message: "rate limited", type: "rate_limit" } }), { + status: 429, + headers: { "Content-Type": "application/json" }, + }) + ), + 80 + ); + }); + + const result = await withEarlyStreamKeepalive(slowFail, { + thresholdMs: 20, + intervalMs: 20, + errorFrame: OPENAI_CHAT_ERROR_FRAME, + }); + assert.equal(result.status, 200); + + const body = await readAll(result); + assert.doesNotMatch( + body, + /^event: error/m, + "must not fall back to the Anthropic-style event: error frame when a custom errorFrame is given" + ); + // The real upstream error body ("rate limited") is forwarded verbatim, framed as a + // plain data: line (matching errorFrame's format) instead of the generic fallback + // message — this is the dynamic real-body branch, distinct from the static default. + assert.match(body, /"error":\{"message":"rate limited","type":"rate_limit"\}/); +}); + // #2544: a fast rejection must propagate so the route's normal error handling runs — // it must not be silently turned into a 200 stream. test("fast handler rejection propagates instead of being swallowed (#2544)", async () => { diff --git a/tests/unit/error-message-sanitization.test.ts b/tests/unit/error-message-sanitization.test.ts index 4e249e4034..0634415b57 100644 --- a/tests/unit/error-message-sanitization.test.ts +++ b/tests/unit/error-message-sanitization.test.ts @@ -352,6 +352,48 @@ test("createErrorResult — exposes error code/type on the result object", async assert.equal(result.errorType, "timeout"); }); +// ── createErrorResult.rawMessage (#7360) ────────────────────────────────────── +// +// `error` is sanitized to its first line (sanitizeErrorMessage) for the +// client-facing response body — correct per Hard Rule #12. But internal +// classification (checkFallbackError / Gemini TPM-vs-RPD metric detection) +// needs the FULL multi-line upstream text, since Google's metric name and +// retry hint live on lines 2-3. `rawMessage` carries the untruncated text on +// the returned object only — it must never leak into the HTTP response body. + +test("createErrorResult — rawMessage preserves the full multi-line message untruncated", async () => { + const { createErrorResult } = await import("../../open-sse/utils/error.ts"); + const fullMessage = + "You exceeded your current quota, please check your plan and billing details.\n" + + "* Quota exceeded for metric: generativelanguage.googleapis.com/generate_content_free_tier_input_token_count, limit: 16000, model: gemma-4-31b\n" + + "Please retry in 8.093498133s."; + const result = createErrorResult(429, fullMessage); + + assert.equal(result.rawMessage, fullMessage, "rawMessage must be the complete, untruncated text"); + assert.ok( + result.error.length < fullMessage.length, + "error (client-facing) must still be truncated to the first line" + ); + assert.ok( + !result.error.includes("generativelanguage.googleapis.com"), + "sanitized error must not include the metric name (line 2)" + ); +}); + +test("createErrorResult — rawMessage never appears in the serialized response body", async () => { + const { createErrorResult } = await import("../../open-sse/utils/error.ts"); + const fullMessage = + "You exceeded your current quota, please check your plan and billing details.\n" + + "* Quota exceeded for metric: generativelanguage.googleapis.com/generate_content_free_tier_input_token_count, limit: 16000, model: gemma-4-31b"; + const result = createErrorResult(429, fullMessage); + const bodyText = await result.response.clone().text(); + + assert.ok( + !bodyText.includes("generativelanguage.googleapis.com"), + "the raw multi-line metric text must never reach the HTTP response body" + ); +}); + test("buildModelCooldownBody returns the public cooldown error payload shape", async () => { const { buildModelCooldownBody } = await import("../../open-sse/utils/error.ts"); const body = buildModelCooldownBody({ model: "gpt-4o", retryAfterSec: 1.2 }); diff --git a/tests/unit/rate-limit-wedge-recovery.test.ts b/tests/unit/rate-limit-wedge-recovery.test.ts new file mode 100644 index 0000000000..cd70a47934 --- /dev/null +++ b/tests/unit/rate-limit-wedge-recovery.test.ts @@ -0,0 +1,123 @@ +/** + * TDD regression test — rate-limit watchdog wedge recovery + * (open-sse/services/rateLimitManager.ts watchdogTick). + * + * Live incident (dashboard log id 1784465227489-a2cbc0): a request sat with + * ZERO real upstream activity (queued=2, running=0, executing=0 the entire + * time) until the real client (a separate, already-running agent sharing the + * same Gemini account) gave up and disconnected after ~60s. The watchdog DID + * detect the wedge and fire "force-resetting" at ~26s in, but its recovery — + * `limiter.disconnect()` — only releases Bottleneck's heartbeat timer; it does + * NOT reject the jobs already QUEUED on that instance. Callers still awaiting + * `limiter.schedule()` on the (now orphaned) old instance just hang forever — + * getLimiter() only ever hands out a FRESH instance to *future* callers — so + * the dispatch is left dangling until the outer ~300s per-target timeout + * eventually aborts it, long past most real clients' patience. + * + * The fix switches the wedge branch to `limiter.stop({ dropWaitingJobs: true })`, + * which Bottleneck's own contract (node_modules/bottleneck/bottleneck.d.ts + * StopOptions) guarantees rejects exactly the RECEIVED/QUEUED/RUNNING jobs on + * THAT instance immediately. This test verifies that underlying contract + * directly against the real `bottleneck` dependency (not a mock) — reservoir:0 + * is the one way to deterministically force a genuine QUEUED-with-nothing- + * running state without needing Bottleneck's internal timers to actually wedge, + * since OmniRoute's own public settings API treats a "0" override as + * "unlimited" (resolveRpm/resolveMaxConcurrent) and can never produce a true + * zero-capacity limiter through withRateLimit() itself. + */ +import test from "node:test"; +import assert from "node:assert/strict"; +import Bottleneck from "bottleneck"; + +function wait(ms: number) { + return new Promise((resolve) => setTimeout(resolve, ms)); +} + +test("disconnect() leaves a genuinely queued (nothing-running) job hanging forever", async () => { + const limiter = new Bottleneck({ reservoir: 0 }); // zero capacity — job queues, never runs + let settled = false; + const jobPromise = limiter + .schedule(() => Promise.resolve("never-reached")) + .then( + (v) => { + settled = true; + return v; + }, + (err) => { + settled = true; + throw err; + } + ); + + await wait(20); + assert.equal(limiter.counts().QUEUED, 1, "job should be queued (reservoir exhausted)"); + assert.equal(limiter.counts().RUNNING, 0, "nothing should be running"); + assert.equal(limiter.counts().EXECUTING, 0, "nothing should be executing"); + + await limiter.disconnect(); + await wait(50); + + assert.equal( + settled, + false, + "disconnect() must NOT settle the queued job — this is exactly the hang the wedge-recovery bug hit" + ); + + // Prevent an unhandled rejection warning when the process exits with this + // promise still pending — it will never settle, which is the point of the test. + jobPromise.catch(() => {}); +}); + +test("stop({ dropWaitingJobs: true }) rejects a genuinely queued (nothing-running) job immediately", async () => { + const limiter = new Bottleneck({ reservoir: 0 }); + const jobPromise = limiter.schedule(() => Promise.resolve("never-reached")); + // Attach a rejection handler synchronously so Node never sees an unhandled + // rejection window between scheduling and the assertion below. + const settledPromise = jobPromise.then( + (v) => ({ ok: true as const, v }), + (err) => ({ ok: false as const, err }) + ); + + await wait(20); + assert.equal(limiter.counts().QUEUED, 1, "job should be queued (reservoir exhausted)"); + assert.equal(limiter.counts().RUNNING, 0, "nothing should be running"); + + // Mirrors rateLimitManager.ts's wedge-recovery call exactly. + await limiter.stop({ + dropWaitingJobs: true, + dropErrorMessage: "rate-limit-watchdog-wedge-reset", + }); + + const settled = await Promise.race([settledPromise, wait(500).then(() => "timed-out" as const)]); + assert.notEqual( + settled, + "timed-out", + "expected the queued job to reject promptly after stop({ dropWaitingJobs: true }), not hang" + ); + assert.equal((settled as { ok: boolean }).ok, false, "expected the queued job to reject"); + assert.equal( + (settled as { ok: false; err: Error }).err.message, + "rate-limit-watchdog-wedge-reset", + "expected Bottleneck to reject with our dropErrorMessage verbatim" + ); +}); + +test("watchdog wedge branch uses stop({ dropWaitingJobs: true }), not disconnect()", async () => { + const source = await import("node:fs/promises").then((fs) => + fs.readFile(new URL("../../open-sse/services/rateLimitManager.ts", import.meta.url), "utf8") + ); + + const wedgeBlockStart = source.indexOf("WEDGED:"); + assert.ok(wedgeBlockStart >= 0, "expected to find the WEDGED log line in rateLimitManager.ts"); + const wedgeBlock = source.slice(wedgeBlockStart, wedgeBlockStart + 1500); + + assert.ok( + wedgeBlock.includes("stop({ dropWaitingJobs: true"), + "wedge-recovery branch must call stop({ dropWaitingJobs: true }) so orphaned queued jobs reject " + + "promptly instead of hanging until the outer per-target timeout (live incident 1784465227489-a2cbc0)" + ); + assert.ok( + !/limiter\.disconnect\(\)/.test(wedgeBlock), + "wedge-recovery branch must not still call disconnect() — it doesn't reject queued jobs" + ); +}); diff --git a/tests/unit/rejected-request-usage.test.ts b/tests/unit/rejected-request-usage.test.ts index bec7fc223e..44aa110ee5 100644 --- a/tests/unit/rejected-request-usage.test.ts +++ b/tests/unit/rejected-request-usage.test.ts @@ -24,7 +24,8 @@ process.env.DATA_DIR = TEST_DATA_DIR; const core = await import("../../src/lib/db/core.ts"); const usageHistory = await import("../../src/lib/usage/usageHistory.ts"); const callLogs = await import("../../src/lib/usage/callLogs.ts"); -const { recordRejectedRequestUsage } = await import("../../src/sse/handlers/rejectedRequestUsage.ts"); +const { recordRejectedRequestUsage, summarizeComboAttemptedModels } = + await import("../../src/sse/handlers/rejectedRequestUsage.ts"); test.beforeEach(() => { core.resetDbInstance(); @@ -53,13 +54,17 @@ test("gate-rejected request is attributed to the api key in usage_history", asyn // usage_history row exists, attributed to the key, marked as a failure. const rows = (await usageHistory.getUsageDb()).data.history; - const keyRows = rows.filter((r: { apiKeyId?: string | null }) => r.apiKeyId === "key-opencode-mac"); + const keyRows = rows.filter( + (r: { apiKeyId?: string | null }) => r.apiKeyId === "key-opencode-mac" + ); assert.equal(keyRows.length, 1, "expected one usage_history row for the rejected request"); assert.equal(keyRows[0].success, false, "rejected request must be recorded as success:false"); // call_logs visibility is preserved (dashboard/logs). const logs = await callLogs.getCallLogs({}); - const rejected = (logs.logs ?? logs).filter?.((l: { apiKeyName?: string | null }) => l.apiKeyName === "opencode-mac"); + const rejected = (logs.logs ?? logs).filter?.( + (l: { apiKeyName?: string | null }) => l.apiKeyName === "opencode-mac" + ); assert.ok(rejected && rejected.length >= 1, "expected a call_logs row for the rejected request"); }); @@ -78,7 +83,95 @@ test("combo-exhausted rejection is also counted per api key", async () => { }); const rows = (await usageHistory.getUsageDb()).data.history; - const keyRows = rows.filter((r: { apiKeyId?: string | null }) => r.apiKeyId === "key-opencode-mac"); + const keyRows = rows.filter( + (r: { apiKeyId?: string | null }) => r.apiKeyId === "key-opencode-mac" + ); assert.equal(keyRows.length, 1); assert.equal(keyRows[0].success, false); }); + +// #7360 follow-up: rejected/combo-exhausted requests wrote a call_logs row with +// no client request body and a hardcoded provider "-", even when the combo's +// attempted models were known — the dashboard log detail was useless for +// debugging which models were tried. recordRejectedRequestUsage now accepts +// requestBody and persists it like the normal handleChatCore logging path. +test("combo-exhausted rejection persists the client request body for dashboard inspection", async () => { + await recordRejectedRequestUsage({ + status: 503, + model: "default", + requestedModel: "default", + provider: "gemini/gemma-4-31b-it, gemini/gemma-4-26b-a4b-it", + endpoint: "/v1/responses", + error: '[503] Combo "default" failed — all targets exhausted', + comboName: "default", + apiKeyId: "key-request-body-test", + apiKeyName: "request-body-test", + correlationId: "corr-request-body-test", + startTime: Date.now() - 6000, + requestBody: { model: "default", messages: [{ role: "user", content: "hello" }] }, + }); + + const logs = await callLogs.getCallLogs({}); + const rejected = (logs.logs ?? logs).find?.( + (l: { apiKeyName?: string | null }) => l.apiKeyName === "request-body-test" + ); + assert.ok(rejected, "expected a call_logs row for the rejected request"); + assert.equal(rejected.hasRequestBody, true, "expected hasRequestBody to be true"); + + const detail = await callLogs.getCallLogById(rejected.id); + assert.ok(detail, "expected to load the call log detail"); + assert.deepEqual(detail!.requestBody, { + model: "default", + messages: [{ role: "user", content: "hello" }], + }); +}); + +test("combo-exhausted rejection without a request body still logs cleanly (no request body available)", async () => { + await recordRejectedRequestUsage({ + status: 503, + model: "default", + requestedModel: "default", + provider: "-", + endpoint: "/v1/responses", + error: '[503] Combo "default" failed — all targets exhausted', + comboName: "default", + apiKeyId: "key-no-body-test", + apiKeyName: "no-body-test", + startTime: Date.now() - 100, + }); + + const logs = await callLogs.getCallLogs({}); + const rejected = (logs.logs ?? logs).find?.( + (l: { apiKeyName?: string | null }) => l.apiKeyName === "no-body-test" + ); + assert.ok(rejected, "expected a call_logs row even without a request body"); + assert.equal(rejected.hasRequestBody, false); +}); + +test("summarizeComboAttemptedModels lists the models a combo was configured with", () => { + assert.equal( + summarizeComboAttemptedModels([ + { model: "gemini/gemma-4-31b-it", providerId: "gemini" }, + { model: "gemini/gemma-4-26b-a4b-it", providerId: "gemini" }, + ]), + "gemini/gemma-4-31b-it, gemini/gemma-4-26b-a4b-it" + ); +}); + +test("summarizeComboAttemptedModels skips non-model entries (e.g. nested combo-refs)", () => { + assert.equal( + summarizeComboAttemptedModels([ + { model: "openai/gpt-5", providerId: "openai" }, + { kind: "combo-ref", comboName: "backup-combo" }, + ]), + "openai/gpt-5" + ); +}); + +test("summarizeComboAttemptedModels falls back to '-' for empty, missing, or invalid input", () => { + assert.equal(summarizeComboAttemptedModels([]), "-"); + assert.equal(summarizeComboAttemptedModels(undefined), "-"); + assert.equal(summarizeComboAttemptedModels(null), "-"); + assert.equal(summarizeComboAttemptedModels("not-an-array"), "-"); + assert.equal(summarizeComboAttemptedModels([{ kind: "combo-ref" }, { foo: "bar" }]), "-"); +}); diff --git a/tests/unit/request-log-detail-stream.test.ts b/tests/unit/request-log-detail-stream.test.ts index 07ef8bb29e..b1f5388a5e 100644 --- a/tests/unit/request-log-detail-stream.test.ts +++ b/tests/unit/request-log-detail-stream.test.ts @@ -56,6 +56,53 @@ test("event stream shows only when debugEnabled and appears above legacy respons ); }); +// Regression: commit 692d6be80 ("unify active and finished requests into single +// view") swapped the collapsible PayloadSection for the new StreamSection (added +// autoscroll) when rendering the provider/client event streams, but never carried +// the collapse toggle over — StreamSection had none. Provider/Client Event Stream +// panes silently lost the ability to collapse from that point on. +test("Provider Event Stream and Client Event Stream panes are collapsible", () => { + const html = renderToStaticMarkup( + React.createElement(RequestLoggerDetail, { + log: { + status: 200, + method: "POST", + path: "/v1/chat/completions", + timestamp: "2026-04-09T21:27:08.000Z", + duration: 2500, + provider: "gemini", + sourceFormat: "openai-chat", + model: "test-model", + tokens: { in: 1, out: 1 }, + }, + detail: { + pipelinePayloads: { + streamChunks: { + provider: ['data: {"content": "hello"}\n\n'], + client: ['data: {"choices":[{"delta":{"content":"hi"}}]}\n\n'], + }, + }, + responseBody: "{}", + }, + loading: false, + debugEnabled: true, + onClose: () => {}, + onCopy: async () => true, + }) + ); + + assert.notEqual( + html.indexOf('aria-label="Collapse Provider Event Stream"'), + -1, + "Provider Event Stream should render a collapse toggle" + ); + assert.notEqual( + html.indexOf('aria-label="Collapse Client Event Stream"'), + -1, + "Client Event Stream should render a collapse toggle" + ); +}); + test("event stream hidden when debugEnabled is false", () => { const html = renderToStaticMarkup( React.createElement(RequestLoggerDetail, { diff --git a/tests/unit/resilience-settings-combo-cooldown-wait.test.ts b/tests/unit/resilience-settings-combo-cooldown-wait.test.ts index 63bfab127c..f0b987b58a 100644 --- a/tests/unit/resilience-settings-combo-cooldown-wait.test.ts +++ b/tests/unit/resilience-settings-combo-cooldown-wait.test.ts @@ -16,12 +16,12 @@ function cloneDefaults(): ResilienceSettings { return structuredClone(DEFAULT_RESILIENCE_SETTINGS); } -test("default comboCooldownWait is conservative (on, 5s ceiling, 2 attempts, 8s budget)", () => { +test("default comboCooldownWait covers Gemini-class TPM/RPM waits (on, 90s ceiling, 5 attempts, 300s/5min budget)", () => { const s = cloneDefaults().comboCooldownWait; assert.equal(s.enabled, true); - assert.equal(s.maxWaitMs, 5000); - assert.equal(s.maxAttempts, 2); - assert.equal(s.budgetMs, 8000); + assert.equal(s.maxWaitMs, 90000); + assert.equal(s.maxAttempts, 5); + assert.equal(s.budgetMs, 300000); }); test("resolveResilienceSettings returns the default block when nothing is stored", () => { @@ -49,8 +49,8 @@ test("mergeResilienceSettings round-trips a partial patch", () => { }); assert.equal(merged.comboCooldownWait.maxWaitMs, 2000); // Unspecified fields keep the current value. - assert.equal(merged.comboCooldownWait.maxAttempts, 2); - assert.equal(merged.comboCooldownWait.budgetMs, 8000); + assert.equal(merged.comboCooldownWait.maxAttempts, 5); + assert.equal(merged.comboCooldownWait.budgetMs, 300000); assert.equal(merged.comboCooldownWait.enabled, true); }); @@ -66,11 +66,11 @@ test("enabled is forced false when maxWaitMs or maxAttempts is zero", () => { assert.equal(b.comboCooldownWait.enabled, false); }); -test("maxWaitMs is clamped to the 30s hard ceiling", () => { +test("maxWaitMs is clamped to the 5-minute hard ceiling", () => { const merged = mergeResilienceSettings(cloneDefaults(), { comboCooldownWait: { maxWaitMs: 999_999 }, }); - assert.equal(merged.comboCooldownWait.maxWaitMs, 30000); + assert.equal(merged.comboCooldownWait.maxWaitMs, 300000); }); test("budgetMs can never drop below a single maxWaitMs", () => { @@ -96,7 +96,7 @@ test("garbage values fall back to the current numbers", () => { budgetMs: undefined, }, }); - assert.equal(merged.comboCooldownWait.maxWaitMs, 5000); - assert.equal(merged.comboCooldownWait.maxAttempts, 2); - assert.equal(merged.comboCooldownWait.budgetMs, 8000); + assert.equal(merged.comboCooldownWait.maxWaitMs, 90000); + assert.equal(merged.comboCooldownWait.maxAttempts, 5); + assert.equal(merged.comboCooldownWait.budgetMs, 300000); }); diff --git a/tests/unit/resilience-settings-normalize-split.test.ts b/tests/unit/resilience-settings-normalize-split.test.ts index 218f8c1cdc..2bfe05dd48 100644 --- a/tests/unit/resilience-settings-normalize-split.test.ts +++ b/tests/unit/resilience-settings-normalize-split.test.ts @@ -62,18 +62,35 @@ describe("resilience/settings normalize split-guard", () => { it("normalizeWaitForCooldownSettings derives ms and disables on zero retries/wait", () => { const on = normalizeWaitForCooldownSettings( { enabled: true, maxRetries: 2, maxRetryWaitSec: 30 }, - { enabled: true, maxRetries: 3, maxRetryWaitSec: 30, maxRetryWaitMs: 30000 } + { enabled: true, maxRetries: 3, maxRetryWaitSec: 30, maxRetryWaitMs: 30000, budgetMs: 300000 } ); assert.equal(on.enabled, true); assert.equal(on.maxRetryWaitMs, 30000); const off = normalizeWaitForCooldownSettings( { enabled: true, maxRetries: 0, maxRetryWaitSec: 30 }, - { enabled: true, maxRetries: 3, maxRetryWaitSec: 30, maxRetryWaitMs: 30000 } + { enabled: true, maxRetries: 3, maxRetryWaitSec: 30, maxRetryWaitMs: 30000, budgetMs: 300000 } ); assert.equal(off.enabled, false); // maxRetries 0 forces disabled }); + // #7360 follow-up: budgetMs caps the CUMULATIVE wait across all retries, not + // just a single wait — without it, maxRetries x maxRetryWaitSec could exceed + // the intended 5-minute give-up point. + it("normalizeWaitForCooldownSettings floors budgetMs at maxRetryWaitMs and caps it at 5 minutes", () => { + const floored = normalizeWaitForCooldownSettings( + { maxRetryWaitSec: 90, budgetMs: 10000 }, + { enabled: true, maxRetries: 3, maxRetryWaitSec: 30, maxRetryWaitMs: 30000, budgetMs: 300000 } + ); + assert.equal(floored.budgetMs, 90000, "budgetMs can never be smaller than a single wait"); + + const capped = normalizeWaitForCooldownSettings( + { budgetMs: 999999999 }, + { enabled: true, maxRetries: 3, maxRetryWaitSec: 30, maxRetryWaitMs: 30000, budgetMs: 300000 } + ); + assert.equal(capped.budgetMs, 300000, "budgetMs is capped at 5 minutes"); + }); + it("host exposes DEFAULT_RESILIENCE_SETTINGS with the full section set", () => { const keys = Object.keys(DEFAULT_RESILIENCE_SETTINGS).sort(); assert.deepEqual(keys, [ diff --git a/tests/unit/services/geminiRateLimitTracker.test.ts b/tests/unit/services/geminiRateLimitTracker.test.ts index a9d7deb5c3..4963488976 100644 --- a/tests/unit/services/geminiRateLimitTracker.test.ts +++ b/tests/unit/services/geminiRateLimitTracker.test.ts @@ -39,12 +39,12 @@ test("getModelRpd returns 0 for empty string", () => { test("getModelRpd matches gemma-4-31b-it via suffix fallback", () => { // The JSON has "gemma-4-31b-it", and callers may pass "gemma-4-31b-it" - assert.equal(getModelRpd("gemma-4-31b-it"), 1500); + assert.equal(getModelRpd("gemma-4-31b-it"), 14400); }); test("getModelRpd strips gemma- prefix correctly for gemma models", () => { // stripModelPrefix("gemini/gemma-4-31b-it") → "gemma-4-31b-it" - assert.equal(getModelRpd("gemini/gemma-4-31b-it"), 1500); + assert.equal(getModelRpd("gemini/gemma-4-31b-it"), 14400); }); test("getModelRpd handles image-generation models (no RPM value, -1)", () => { @@ -154,15 +154,15 @@ test("isRpdExhausted works with gemini/ prefix for the model", () => { // ── Integration: Gemma 4 RPM scenario ──────────────────────────────────────── -test("Gemma 4: 15 RPM hits never trigger quota_exhausted (RPD=1500)", () => { - // Gemma 4 has RPD=1500, so 15 RPM hits should not trigger RPD exhaustion +test("Gemma 4: 15 RPM hits never trigger quota_exhausted (RPD=14400)", () => { + // Gemma 4 has RPD=14400, so 15 RPM hits should not trigger RPD exhaustion for (let i = 0; i < 15; i++) incrementRequestCount("gemini/gemma-4-31b-it"); assert.equal(isRpdExhausted("gemini/gemma-4-31b-it"), false); assert.equal(getDailyRequestCount("gemini/gemma-4-31b-it"), 15); }); -test("Gemma 4: RPD exhaustion requires 1500 requests", () => { - for (let i = 0; i < 1499; i++) incrementRequestCount("gemini/gemma-4-31b-it"); +test("Gemma 4: RPD exhaustion requires 14400 requests", () => { + for (let i = 0; i < 14399; i++) incrementRequestCount("gemini/gemma-4-31b-it"); assert.equal(isRpdExhausted("gemini/gemma-4-31b-it"), false); incrementRequestCount("gemini/gemma-4-31b-it"); @@ -301,11 +301,11 @@ test("isRpmExhausted works with gemini/ prefix", () => { // ── Integration: RPM + RPD work independently ───────────────────────────────── test("RPM and RPD limits are tracked independently", () => { - // Gemma 4: RPM=15, RPD=1500 + // Gemini 3.1 Flash Lite: RPM=15, RPD=500 // After 15 requests, RPM is exhausted but RPD is not - for (let i = 0; i < 15; i++) incrementRequestCount("gemini/gemma-4-31b-it"); - assert.equal(isRpmExhausted("gemini/gemma-4-31b-it"), true); - assert.equal(isRpdExhausted("gemini/gemma-4-31b-it"), false); + for (let i = 0; i < 15; i++) incrementRequestCount("gemini/gemini-3.1-flash-lite"); + assert.equal(isRpmExhausted("gemini/gemini-3.1-flash-lite"), true); + assert.equal(isRpdExhausted("gemini/gemini-3.1-flash-lite"), false); }); test("Gemini 2.5 Flash: RPM=5 always hits before RPD=20", () => {