diff --git a/src/providers/key-failover.ts b/src/providers/key-failover.ts index d5ccd759e3e..701540b8d1d 100644 --- a/src/providers/key-failover.ts +++ b/src/providers/key-failover.ts @@ -29,6 +29,153 @@ interface KeyCooldown { const DEFAULT_COOLDOWN_MS = 60_000; const MAX_COOLDOWN_MS = 10 * 60_000; // cap at 10 min for api-key rotation +/** + * Cap for a cooldown the upstream itself dated, as opposed to one we inferred. + * + * `MAX_COOLDOWN_MS` is deliberately short because an undated 429 is a guess: ten + * minutes bounds how long a transient limit can park a working key. A free-tier + * quota is not a guess — OpenRouter replies `Weekly/Monthly Limit Exhausted ... + * will reset at `, and until that date the key cannot serve anything. Held + * for ten minutes instead, it comes back, takes a 429, and rotates again, every + * ten minutes for the rest of the week (#4024). + * + * 32 days rather than unbounded. The wording this parses is + * `Weekly/Monthly Limit Exhausted`, so the cap has to clear a monthly window — + * 31 days plus a day of slack for timezone and month length. An earlier 8-day + * cap looked generous against the weekly case in the issue and silently clamped + * every monthly reset to ~23 days early, which puts the key back into exactly + * the 429 loop this exists to stop. Caught by the cap's own test. + * + * Bounded at all because the date is upstream-controlled input: a malformed or + * hostile `reset at 2999-01-01` must not park a working key past any horizon an + * operator would think to look at. + */ +const MAX_QUOTA_COOLDOWN_MS = 32 * 24 * 60 * 60_000; + +/** + * Read a bounded prefix of a 429 body and pull the upstream's declared reset instant. + * + * Clones first: the caller still cancels the original body to release the socket, + * and a rotation storm must not be gated on reading N full error payloads. Any + * failure — no body, already consumed, slow, malformed — returns undefined and + * leaves the `Retry-After` path exactly as it was. + */ +export async function readQuotaResetAt( + response: Response, + now = Date.now(), +): Promise<{ at: number | undefined; response: Response }> { + if (!response.body) return { at: undefined, response }; + try { + const reader = response.body.getReader(); + const decoder = new TextDecoder(); + const chunks: Uint8Array[] = []; + let seen = 0; + let text = ""; + while (seen < QUOTA_RESET_SCAN_BYTES) { + const { done, value } = await reader.read(); + if (done) break; + chunks.push(value); + seen += value.byteLength; + text += decoder.decode(value, { stream: true }); + } + // Hand back a Response carrying the bytes already pulled followed by whatever + // is left, so the caller can still read or cancel it. `response.clone()` is + // NOT usable here: it tees, and with the original branch undrained the tee + // stalls once its buffer fills — a 5MB error body hangs the rotation path, + // which is worse than the unbounded read this replaced. + const rest = new ReadableStream({ + start(controller) { + for (const c of chunks) controller.enqueue(c); + }, + async pull(controller) { + const { done, value } = await reader.read(); + if (done) { + controller.close(); + return; + } + controller.enqueue(value); + }, + cancel(reason) { + return reader.cancel(reason); + }, + }); + const rebuilt = new Response(rest, { + status: response.status, + statusText: response.statusText, + headers: response.headers, + }); + return { at: parseQuotaResetAt(text, now), response: rebuilt }; + } catch { + return { at: undefined, response }; + } +} + +/** + * How much of a 429 body is read and scanned for the reset instant. + * + * Bounds the READ, not just the parse: this runs on the rotation path, once per + * rotated key under a rate-limit storm, and the body is upstream-controlled. + * OpenRouter's rate_limit_error JSON is a few hundred bytes. + */ +const QUOTA_RESET_SCAN_BYTES = 4_096; + +/** + * Reset instant an upstream declared in a 429 *body*, in epoch ms. + * + * Only the body carries this: OpenRouter sends no `Retry-After` for a quota + * exhaustion, so the header path (`parseRetryAfterMs`) sees nothing and falls + * back to `DEFAULT_COOLDOWN_MS`. Returns undefined for anything it cannot read + * as a date, so an unparsable body keeps today's behaviour exactly. + */ +/** + * Whether `YYYY-MM-DD…` names a day that exists. + * + * `Date.parse` does NOT reject an out-of-range day: measured on Bun, + * `2026-02-30T00:00:00Z` yields March 2 and `2026-04-31T00:00:00Z` yields + * May 1, so a malformed upstream body would park a key past the instant it + * actually named. Only the month is rejected outright (`2026-13-01` is NaN). + * + * Checked on the date text alone rather than by round-tripping the parsed + * instant, because a value carrying an explicit offset (`…T23:00+05:30`) + * legitimately lands on a different UTC day than the one written. + */ +function isRealCalendarDate(value: string): boolean { + const [year, month, day] = value.slice(0, 10).split("-").map(Number); + if (month < 1 || month > 12 || day < 1) return false; + const leap = (year % 4 === 0 && year % 100 !== 0) || year % 400 === 0; + const lengths = [31, leap ? 29 : 28, 31, 30, 31, 30, 31, 31, 30, 31, 30, 31]; + return day <= lengths[month - 1]!; +} + +export function parseQuotaResetAt(body: string | null | undefined, now = Date.now()): number | undefined { + const text = body?.slice(0, QUOTA_RESET_SCAN_BYTES); + if (!text) return undefined; + // `will reset at 2026-09-09 03:30:06` / `... at 2026-09-09T03:30:06Z` / `resets at ` + const match = /reset[s]?\s+at\s+([0-9]{4}-[0-9]{2}-[0-9]{2}(?:[T ][0-9]{2}:[0-9]{2}(?::[0-9]{2})?(?:\.[0-9]+)?(?:Z|[+-][0-9]{2}:?[0-9]{2})?)?)/i.exec(text); + if (!match) return undefined; + // Pin a bare `YYYY-MM-DD hh:mm:ss` to UTC explicitly. + // + // ECMA-262 says a date-TIME form with no offset is LOCAL time, and Node follows + // that: `Date.parse("2026-09-09 03:30:06")` differs from the UTC reading by the + // host offset (7h on a PDT box, measured). Bun currently returns the UTC value + // for the same string, so on this runtime the normalisation is a no-op today — + // which is exactly why it is written out rather than relied upon. If Bun ever + // conforms, an un-normalised parse would silently shift every park-until by the + // operator's offset, and the early direction resumes the 429 loop. + // + // A consequence worth knowing: no Bun test can observe this branch being + // removed. The explicit-zone case below is the part the suite can pin. + const raw = match[1].includes("T") || /(?:Z|[+-][0-9]{2}:?[0-9]{2})$/.test(match[1]) + ? match[1] + : `${match[1].replace(" ", "T")}Z`; + if (!isRealCalendarDate(match[1])) return undefined; + const at = Date.parse(raw); + if (!Number.isFinite(at)) return undefined; + // Already past, or beyond the cap: not usable as a park-until instant. + if (at <= now) return undefined; + return Math.min(at, now + MAX_QUOTA_COOLDOWN_MS); +} + /** * Default same-target 429 retry policy used when a provider opts in via a bare * `retryOn429: {}` (presence = opt-in with these defaults). @@ -363,6 +510,7 @@ function rotateKeyAfterFailure( now = Date.now(), attemptedKey?: string, attemptedSelection?: ProviderApiKeySelection, + quotaResetAt?: number, ): OcxProviderConfig | null { const provider = config.providers[providerName]; if (!provider) return null; @@ -421,7 +569,12 @@ function rotateKeyAfterFailure( // full cap instead of the 429 default so a dead key is not re-tried once a minute. const cooldownMs = failureStatus === 401 ? MAX_COOLDOWN_MS - : parseRetryAfterMs(retryAfterHeader, now) ?? DEFAULT_COOLDOWN_MS; + // A reset instant the upstream dated outranks both the header and the + // default: it is the only one of the three that knows when the quota + // actually returns (#4024). + : quotaResetAt !== undefined + ? Math.max(quotaResetAt - now, 1) + : parseRetryAfterMs(retryAfterHeader, now) ?? DEFAULT_COOLDOWN_MS; keyCooldowns.set(cooldownKey(providerName, outcome.value.failedId), { cooldownUntil: now + cooldownMs }); sweepExpiredOnWrite(now); } @@ -448,8 +601,9 @@ export function rotateKeyOn429( now = Date.now(), attemptedKey?: string, attemptedSelection?: ProviderApiKeySelection, + quotaResetAt?: number, ): OcxProviderConfig | null { - return rotateKeyAfterFailure(config, providerName, 429, retryAfterHeader, now, attemptedKey, attemptedSelection); + return rotateKeyAfterFailure(config, providerName, 429, retryAfterHeader, now, attemptedKey, attemptedSelection, quotaResetAt); } /** @@ -482,6 +636,8 @@ export function sweepExpiredApiKeyCooldowns(now = Date.now()): number { interface RotateProviderTransportOptions { retryAfter?: string | null; + /** Epoch ms from `parseQuotaResetAt`, when the upstream dated the reset in its body. */ + quotaResetAt?: number; now?: number; attemptedKey?: string; attemptedSelection?: ProviderApiKeySelection; @@ -507,6 +663,7 @@ export function rotateProviderTransportOn429( options.now, options.attemptedKey, options.attemptedSelection ?? routedProvider._apiKeyAttempt, + options.quotaResetAt, ); if (!rotated) return null; return applyRotatedTransport(providerName, routedProvider, rotated, options.promptCacheKey); diff --git a/src/server/responses/adapter-dispatch.ts b/src/server/responses/adapter-dispatch.ts index c26b77b19b8..b1f161c84eb 100644 --- a/src/server/responses/adapter-dispatch.ts +++ b/src/server/responses/adapter-dispatch.ts @@ -25,6 +25,7 @@ import { hasKeyPoolFailover, rotateProviderTransportOn401, rateLimitRetryDelayMs, + readQuotaResetAt, rotateProviderTransportOn429, } from "../../providers/key-failover"; import { @@ -667,11 +668,20 @@ export async function prepareAdapterExchange( // SAME request once per remaining key. OAuth/forward providers and single-key pools // return null immediately, so this stays a no-op for them (src/providers/key-failover.ts). while (upstreamResponse.status === 429 && hasKeyPoolFailover(route.provider)) { + // A quota exhaustion is dated in the BODY, not in `Retry-After` — OpenRouter + // sends no header for it (#4024). Read a bounded prefix before the socket is + // released below; a failed or slow read just leaves the header path in charge. + // Peeks a bounded prefix and hands back a Response still carrying the whole + // body, so the cancel below still releases the socket. + const peeked = await readQuotaResetAt(upstreamResponse); + upstreamResponse = peeked.response; + const quotaResetAt = peeked.at; const rotated = rotateProviderTransportOn429(config, route.providerName, route.provider, { retryAfter: upstreamResponse.headers.get("retry-after"), now: Date.now(), attemptedKey: route.provider.apiKey, promptCacheKey: parsed.options.promptCacheKey, + quotaResetAt, }); if (!rotated) break; // Release the failed response's socket before retrying; unread bodies otherwise linger diff --git a/tests/providers/openrouter-quota-reset-cooldown-4024.test.ts b/tests/providers/openrouter-quota-reset-cooldown-4024.test.ts new file mode 100644 index 00000000000..d806bed1df0 --- /dev/null +++ b/tests/providers/openrouter-quota-reset-cooldown-4024.test.ts @@ -0,0 +1,154 @@ +import { describe, expect, test } from "bun:test"; +import { parseQuotaResetAt, readQuotaResetAt } from "../../src/providers/key-failover"; + +/** + * #4024 — a free-tier quota exhaustion is dated by the upstream, and OpenRouter + * sends it in the 429 body rather than in `Retry-After`. Without reading it the + * key is parked for the undated-429 cap (10 min), comes back, takes another 429, + * and repeats for the rest of the quota window. + */ +describe("parseQuotaResetAt", () => { + const now = Date.parse("2026-09-01T00:00:00Z"); + + test("reads the OpenRouter wording, treating a bare timestamp as UTC", () => { + const body = JSON.stringify({ + error: { code: "rate_limit_error", message: "Weekly Limit Exhausted. Your limit will reset at 2026-09-09 03:30:06" }, + }); + expect(parseQuotaResetAt(body, now)).toBe(Date.parse("2026-09-09T03:30:06Z")); + }); + + test("honours an explicit zone rather than re-stamping it as UTC", () => { + const at = parseQuotaResetAt("limit will reset at 2026-09-09T03:30:06+05:30", now); + expect(at).toBe(Date.parse("2026-09-09T03:30:06+05:30")); + expect(at).not.toBe(Date.parse("2026-09-09T03:30:06Z")); + }); + + test("accepts the 'resets at' spelling and a date with no clock time", () => { + expect(parseQuotaResetAt("quota resets at 2026-09-09", now)).toBe(Date.parse("2026-09-09T00:00:00Z")); + }); + + test("a body it cannot read yields undefined, so today's behaviour is unchanged", () => { + for (const body of [ + null, + undefined, + "", + "429 Too Many Requests", + JSON.stringify({ error: { message: "rate limited, try later" } }), + "will reset at soon", + "will reset at 2026-13-45 99:99:99", + ]) { + expect(parseQuotaResetAt(body as string | null | undefined, now)).toBeUndefined(); + } + }); + + test("a reset already in the past is not a park-until instant", () => { + expect(parseQuotaResetAt("will reset at 2026-08-01 00:00:00", now)).toBeUndefined(); + }); + + test("a monthly window is honoured in full, not clamped", () => { + // `Weekly/Monthly Limit Exhausted` is the wording upstream sends, so a reset + // up to ~31 days out is legitimate. Clamping it would resume the 429 loop + // weeks early — the failure this feature exists to prevent. + const monthly = "will reset at 2026-10-01 00:00:00"; + expect(parseQuotaResetAt(monthly, now)).toBe(Date.parse("2026-10-01T00:00:00Z")); + }); + + test("an absurd or hostile date is capped rather than parking the key forever", () => { + const at = parseQuotaResetAt("will reset at 2999-01-01 00:00:00", now); + expect(at).toBe(now + 32 * 24 * 60 * 60_000); + }); + + test("a day the calendar does not have is refused, not rolled forward", () => { + // `Date.parse` does not reject an out-of-range DAY — measured on Bun, + // `2026-02-30T00:00:00Z` yields March 2 — so without this the key parks + // past the instant the upstream actually named. Only the month is caught + // by the parser itself. + const feb = Date.parse("2026-02-25T00:00:00Z"); + expect(parseQuotaResetAt("resets at 2026-02-30T00:00:00Z", feb)).toBeUndefined(); + expect(parseQuotaResetAt("resets at 2026-02-29T00:00:00Z", feb)).toBeUndefined(); + expect(parseQuotaResetAt("resets at 2026-04-31T00:00:00Z", Date.parse("2026-04-25T00:00:00Z"))).toBeUndefined(); + expect(parseQuotaResetAt("resets at 2026-13-01T00:00:00Z", feb)).toBeUndefined(); + }); + + test("real leap days still park the key, including the century rule", () => { + // The guard above must not cost a legitimate Feb 29. 2024 is a leap year, + // 2000 is one (divisible by 400) and 2100 is not (divisible by 100). + expect(parseQuotaResetAt("resets at 2024-02-29T00:00:00Z", Date.parse("2024-02-25T00:00:00Z"))) + .toBe(Date.parse("2024-02-29T00:00:00Z")); + expect(parseQuotaResetAt("resets at 2000-02-29T00:00:00Z", Date.parse("2000-02-25T00:00:00Z"))) + .toBe(Date.parse("2000-02-29T00:00:00Z")); + expect(parseQuotaResetAt("resets at 2100-02-29T00:00:00Z", Date.parse("2100-02-25T00:00:00Z"))) + .toBeUndefined(); + }); + + test("only the first 4KB is scanned, so a huge body cannot stall the rotation path", () => { + const padded = "x".repeat(8_000) + " will reset at 2026-09-09 03:30:06"; + expect(parseQuotaResetAt(padded, now)).toBeUndefined(); + }); +}); + +describe("readQuotaResetAt", () => { + const now = Date.parse("2026-09-01T00:00:00Z"); + + test("returns the reset AND a response whose body is still fully readable", async () => { + // The caller still needs this response: on a failed rotation adapter-dispatch + // breaks out of the loop with it, and on a successful one it cancels the body + // to release the socket. Peeking must not cost it either. + const body = JSON.stringify({ + error: { code: "rate_limit_error", message: "Weekly Limit Exhausted. Your limit will reset at 2026-09-05 12:00:00" }, + }); + const { at, response } = await readQuotaResetAt(new Response(body, { status: 429 }), now); + + expect(at).toBe(Date.parse("2026-09-05T12:00:00Z")); + expect(response.status).toBe(429); + // The bytes already pulled are replayed ahead of the remainder. + expect(await response.text()).toBe(body); + }); + + test("the returned response can be cancelled instead of read", async () => { + const { response } = await readQuotaResetAt(new Response("x".repeat(10_000), { status: 429 }), now); + await response.body?.cancel(); + expect(response.bodyUsed).toBe(true); + }); + + test("a bodyless or unreadable response leaves the Retry-After path in charge", async () => { + expect((await readQuotaResetAt(new Response(null, { status: 429 }), now)).at).toBeUndefined(); + const consumed = new Response("x", { status: 429 }); + await consumed.text(); + expect((await readQuotaResetAt(consumed, now)).at).toBeUndefined(); + }); +}); + +describe("readQuotaResetAt — the read is bounded, not just the parse", () => { + const now = Date.parse("2026-09-01T00:00:00Z"); + + test("stops pulling after the cap instead of buffering the whole body", async () => { + // A chatty upstream must not make the rotation path read megabytes. This counts + // what the reader actually PULLED, not what the parser looked at — the two were + // different before this was fixed (`.text()` read it all, then sliced 4KB). + let pulled = 0; + const chunk = new TextEncoder().encode("x".repeat(64 * 1_024)); + const total = 5 * 1_024 * 1_024; + const body = new ReadableStream({ + pull(controller) { + if (pulled >= total) { + controller.close(); + return; + } + pulled += chunk.byteLength; + controller.enqueue(chunk); + }, + }); + + const { at } = await readQuotaResetAt(new Response(body, { status: 429 }), now); + + expect(at).toBeUndefined(); + expect(pulled).toBeLessThan(total / 4); + }); + + test("still finds a reset that sits inside the cap", async () => { + const body = `{"error":{"message":"Weekly Limit Exhausted. Your limit will reset at 2026-09-05 12:00:00"}}`; + expect((await readQuotaResetAt(new Response(body, { status: 429 }), now)).at) + .toBe(Date.parse("2026-09-05T12:00:00Z")); + }); +}); diff --git a/tests/server/server-key-failover-e2e.test.ts b/tests/server/server-key-failover-e2e.test.ts index 4bf924c2492..9fe34cb8f40 100644 --- a/tests/server/server-key-failover-e2e.test.ts +++ b/tests/server/server-key-failover-e2e.test.ts @@ -5,7 +5,7 @@ import { join } from "node:path"; import { apiKeyAccountLogLabel } from "../../src/codex/account-label"; import { readUsageEntries, resetUsageReadCacheForTests } from "../../src/usage/log"; import { loadConfig, saveConfig } from "../../src/config"; -import { clearKeyCooldowns, rotateKeyOn429 } from "../../src/providers/key-failover"; +import { clearKeyCooldowns, getKeyCooldownUntil, rotateKeyOn429 } from "../../src/providers/key-failover"; import { deriveXaiConvId } from "../../src/providers/xai-transport"; import { clearReasoningReplayCacheForTests } from "../../src/responses/reasoning-replay-cache"; import { startServer } from "../../src/server"; @@ -496,6 +496,69 @@ describe("server 429 key failover (end-to-end)", () => { }); } + test("a 429 dated in the body parks the failed key until that instant, outranking Retry-After", async () => { + // #4024 regression, through the real dispatch path. The unit tests cover + // parseQuotaResetAt/readQuotaResetAt in isolation; nothing exercised + // adapter-dispatch actually READING the body and handing quotaResetAt to + // rotateProviderTransportOn429. Dropping it there would leave every unit + // test green while the key came back after the header's 30s and took the + // same 429 again — which is the bug. + const resetAt = new Date(Date.now() + 6 * 60 * 60_000); + const stamp = resetAt.toISOString().replace("T", " ").slice(0, 19); // bare form, read as UTC + const seenAuth: string[] = []; + upstream = Bun.serve({ + hostname: "127.0.0.1", port: 0, + fetch(req) { + seenAuth.push(req.headers.get("authorization") ?? ""); + if (seenAuth.length === 1) { + return new Response(JSON.stringify({ + error: { code: "rate_limit_error", message: `Weekly Limit Exhausted. Your limit will reset at ${stamp}` }, + }), { status: 429, headers: { "retry-after": "30", "content-type": "application/json" } }); + } + return new Response(JSON.stringify({ + id: "chatcmpl-dated", object: "chat.completion", + choices: [{ index: 0, message: { role: "assistant", content: "ok after dated rotate" }, finish_reason: "stop" }], + }), { headers: { "content-type": "application/json" } }); + }, + }); + const config: OcxConfig = { + port: 0, hostname: "127.0.0.1", defaultProvider: "dated", + providers: { + dated: { + adapter: "openai-chat", + baseUrl: `http://127.0.0.1:${upstream.port}/v1`, + allowPrivateNetwork: true, + apiKey: "key-dated-000111222333", + apiKeyPool: [ + { id: "d1", key: "key-dated-000111222333", addedAt: 1 }, + { id: "d2", key: "key-dated-444555666777", addedAt: 2 }, + ], + }, + }, + } as OcxConfig; + saveConfig(config); + const server = startServer(0); + try { + const res = await fetch(new URL("/v1/responses", server.url), { + method: "POST", + headers: { "content-type": "application/json" }, + body: JSON.stringify({ model: "dated/some-model", input: "hello", stream: false }), + }); + expect(res.status).toBe(200); + await res.json(); + expect(seenAuth[1]).toBe("Bearer key-dated-444555666777"); + + const cooldownUntil = getKeyCooldownUntil("dated", "d1"); + expect(cooldownUntil).not.toBeNull(); + // The body's instant, not the header's 30s. Compared with a wide window + // because the cooldown is anchored to the server's Date.now(), not ours. + expect(cooldownUntil!).toBeGreaterThan(Date.now() + 5 * 60 * 60_000); + expect(cooldownUntil!).toBeLessThanOrEqual(resetAt.getTime() + 60_000); + } finally { + await server.stop(true); + } + }); + test("reasoning replay misses after a 429 rotates to a different physical key", async () => { const model = "reasoning-model"; const callId = "call_key_rotation";