Files
OmniRoute/tests/unit/rejected-request-usage.test.ts
Markus Hartung cc17b304ab fix(sse): Gemini TPM/RPD quota classification + combo cooldown-wait resilience (#8213)
* 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 <markus.hartung@gmail.com>

* 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 <markus.hartung@gmail.com>

* 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 <markus.hartung@gmail.com>

* 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 <markus.hartung@gmail.com>

* 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 <markus.hartung@gmail.com>

* 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 <markus.hartung@gmail.com>

* 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 <markus.hartung@gmail.com>

* 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 <markus.hartung@gmail.com>

* 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 <markus.hartung@gmail.com>

* 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 <markus.hartung@gmail.com>

* 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 <markus.hartream@gmail.com>

* chore(quality): file-size baseline for own-growth (#8213)

Co-authored-by: diegosouzapw <8016841+diegosouzapw@users.noreply.github.com>

---------

Co-authored-by: Markus Hartung <markus.hartung@gmail.com>
Co-authored-by: Markus Hartung <markus.hartream@gmail.com>
Co-authored-by: diegosouzapw <8016841+diegosouzapw@users.noreply.github.com>
2026-07-23 05:17:35 -03:00

178 lines
7.0 KiB
TypeScript

// Regression guard — support-mesh escalation (2026-07-08, whatsbrasil):
// an OmniRoute API key ("opencode-mac") showed "zero requisições" even though
// it received traffic. Root cause: requests rejected *before* handleChatCore
// (pipeline-gate / provider circuit breaker OPEN, or a combo with every target
// exhausted) short-circuit in src/sse/handlers/chat.ts and only wrote a
// call_logs row via saveCallLog — they never reached persistFailureUsage, so
// no usage_history row was created and the per-api-key usage counter
// (getApiKeyUsageRows, which reads usage_history) never incremented.
//
// The fix routes those rejections through recordRejectedRequestUsage(), which
// writes BOTH the call_logs row (dashboard/logs visibility, preserved) AND a
// usage_history row attributed to the api key with success:false — so the
// rejected traffic is counted per key.
import test from "node:test";
import assert from "node:assert/strict";
import fs from "node:fs";
import os from "node:os";
import path from "node:path";
const TEST_DATA_DIR = fs.mkdtempSync(path.join(os.tmpdir(), "omniroute-rejected-usage-"));
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, summarizeComboAttemptedModels } =
await import("../../src/sse/handlers/rejectedRequestUsage.ts");
test.beforeEach(() => {
core.resetDbInstance();
fs.rmSync(TEST_DATA_DIR, { recursive: true, force: true });
fs.mkdirSync(TEST_DATA_DIR, { recursive: true });
usageHistory.clearPendingRequests();
});
test.after(() => {
core.resetDbInstance();
fs.rmSync(TEST_DATA_DIR, { recursive: true, force: true });
});
test("gate-rejected request is attributed to the api key in usage_history", async () => {
await recordRejectedRequestUsage({
status: 503,
model: "claude-sonnet-5",
requestedModel: "claude-sonnet-5",
provider: "anthropic",
endpoint: "/v1/chat/completions",
error: "[503] Pipeline gate rejected",
apiKeyId: "key-opencode-mac",
apiKeyName: "opencode-mac",
startTime: Date.now() - 5,
});
// 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"
);
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"
);
assert.ok(rejected && rejected.length >= 1, "expected a call_logs row for the rejected request");
});
test("combo-exhausted rejection is also counted per api key", async () => {
await recordRejectedRequestUsage({
status: 502,
model: "gpt-5",
requestedModel: "gpt-5",
provider: "-",
endpoint: "/v1/chat/completions",
error: '[502] Combo "prod" failed — all targets exhausted',
comboName: "prod",
apiKeyId: "key-opencode-mac",
apiKeyName: "opencode-mac",
startTime: Date.now() - 3,
});
const rows = (await usageHistory.getUsageDb()).data.history;
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" }]), "-");
});