From 2be6c8db8d1ed82daa44c2a51edc13e886439060 Mon Sep 17 00:00:00 2001 From: Codex Date: Sat, 20 Jun 2026 20:55:35 +0900 Subject: [PATCH] fix(usage): honor 429 Retry-After to stop self-sustaining rate-limit loop The Claude usage poller retried /api/oauth/usage every 60s, but the endpoint returns 429 with a longer Retry-After window (~93s). Retrying mid-cooldown re-tripped the limit so the 429s never cleared and usage data never populated. Record a cooldownUntil from the 429 Retry-After header (5min fallback when absent) and skip the API until it closes; cleared on success. Dashboard now shows a "429" indicator instead of a stale value when rate-limited. Adds regression tests proving the cooldown outlasts the 60s throttle and releases once the window passes. Co-Authored-By: Claude Opus 4.7 --- src/claude-usage-backoff.test.ts | 135 +++++++++++++++++++++++++++ src/claude-usage.ts | 151 +++++++++++++++++++++++++------ src/dashboard-usage-rows.test.ts | 32 +++++++ src/dashboard-usage-rows.ts | 9 +- src/unified-dashboard.ts | 7 ++ 5 files changed, 304 insertions(+), 30 deletions(-) create mode 100644 src/claude-usage-backoff.test.ts diff --git a/src/claude-usage-backoff.test.ts b/src/claude-usage-backoff.test.ts new file mode 100644 index 0000000..bc5f260 --- /dev/null +++ b/src/claude-usage-backoff.test.ts @@ -0,0 +1,135 @@ +/** + * Regression tests for the Claude usage-API 429 `Retry-After` backoff. + * + * Root cause this guards against: the usage poller used to retry every + * MIN_FETCH_INTERVAL_MS (60s), but the endpoint hands back a longer rate-limit + * window (e.g. `retry-after: 93`). Retrying mid-cooldown re-trips the limit, so + * the 429s never clear. The fix records a `cooldownUntil` from the header and + * refuses to call the API until that window closes. + */ +import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest'; + +vi.mock('./logger.js', () => ({ + logger: { info: vi.fn(), warn: vi.fn(), error: vi.fn(), debug: vi.fn() }, +})); + +vi.mock('./config.js', () => ({ DATA_DIR: '/tmp/ejclaw-usage-backoff-data' })); + +const { getAllTokensMock } = vi.hoisted(() => ({ getAllTokensMock: vi.fn() })); +vi.mock('./token-rotation.js', () => ({ + getAllTokens: getAllTokensMock, + getCurrentToken: () => null, + getConfiguredClaudeTokens: () => [], +})); + +const { readJsonFileMock } = vi.hoisted(() => ({ readJsonFileMock: vi.fn() })); +vi.mock('./utils.js', async () => { + const actual = + await vi.importActual('./utils.js'); + return { ...actual, readJsonFile: readJsonFileMock, writeJsonFile: vi.fn() }; +}); + +afterEach(() => { + vi.resetModules(); + vi.clearAllMocks(); + vi.unstubAllGlobals(); + vi.useRealTimers(); +}); + +function makeResponse( + status: number, + headers: Record = {}, +): Response { + return { + status, + ok: status >= 200 && status < 300, + headers: { get: (k: string) => headers[k.toLowerCase()] ?? null }, + json: async () => ({}), + } as unknown as Response; +} + +describe('parseRetryAfterMs', () => { + it('parses delta-seconds', async () => { + const { parseRetryAfterMs } = await import('./claude-usage.js'); + expect(parseRetryAfterMs('93')).toBe(93_000); + expect(parseRetryAfterMs('0')).toBe(0); + }); + + it('parses an HTTP-date relative to now', async () => { + vi.useFakeTimers(); + vi.setSystemTime(new Date('2026-06-20T00:00:00Z')); + const { parseRetryAfterMs } = await import('./claude-usage.js'); + expect(parseRetryAfterMs('Sat, 20 Jun 2026 00:00:30 GMT')).toBe(30_000); + }); + + it('returns null for missing or junk values', async () => { + const { parseRetryAfterMs } = await import('./claude-usage.js'); + expect(parseRetryAfterMs(null)).toBeNull(); + expect(parseRetryAfterMs('soon')).toBeNull(); + }); +}); + +describe('Claude usage 429 Retry-After backoff', () => { + beforeEach(() => { + readJsonFileMock.mockReturnValue({}); // start from an empty disk cache + getAllTokensMock.mockReturnValue([ + { + index: 0, + token: 'sk-ant-oat01-testTokenAAAAAAAA', + masked: 'sk-ant-oat01-test...AAAA', + isActive: true, + isRateLimited: false, + }, + ]); + }); + + it('records a cooldown on 429 and skips the next fetch within the window', async () => { + const fetchMock = vi.fn(async () => + makeResponse(429, { 'retry-after': '93' }), + ); + vi.stubGlobal('fetch', fetchMock); + + const { fetchAllClaudeUsage } = await import('./claude-usage.js'); + + const first = await fetchAllClaudeUsage(); + expect(fetchMock).toHaveBeenCalledTimes(1); + expect(first[0].usageRateLimited).toBe(true); + expect(first[0].usage).toBeNull(); + + // Immediate re-call: cooldown gate must hold, no second network call. + const second = await fetchAllClaudeUsage(); + expect(fetchMock).toHaveBeenCalledTimes(1); + expect(second[0].usageRateLimited).toBe(true); + }); + + it('keeps backing off after the 60s throttle elapses but before the cooldown closes', async () => { + // This is the core regression: a 93s Retry-After must outlast the 60s + // MIN_FETCH_INTERVAL throttle. Without the cooldown the poller would refetch + // at ~60s — mid rate-limit window — and re-trip the 429 forever. + vi.useFakeTimers(); + vi.setSystemTime(new Date('2026-06-20T00:00:00Z')); + + const fetchMock = vi + .fn() + .mockResolvedValueOnce(makeResponse(429, { 'retry-after': '93' })) + .mockResolvedValueOnce(makeResponse(200)); + vi.stubGlobal('fetch', fetchMock); + + const { fetchAllClaudeUsage } = await import('./claude-usage.js'); + + await fetchAllClaudeUsage(); + expect(fetchMock).toHaveBeenCalledTimes(1); + + // +70s: past the 60s throttle, still inside the ~98s cooldown → no refetch. + vi.setSystemTime(Date.now() + 70_000); + const held = await fetchAllClaudeUsage(); + expect(fetchMock).toHaveBeenCalledTimes(1); + expect(held[0].usageRateLimited).toBe(true); + + // +100s total: cooldown window closed → poller is allowed to fetch again. + vi.setSystemTime(Date.now() + 30_000); + const resumed = await fetchAllClaudeUsage(); + expect(fetchMock).toHaveBeenCalledTimes(2); + expect(resumed[0].usageRateLimited).toBe(false); + }); +}); diff --git a/src/claude-usage.ts b/src/claude-usage.ts index 9ff2815..13b81ee 100644 --- a/src/claude-usage.ts +++ b/src/claude-usage.ts @@ -55,6 +55,30 @@ interface UsageCacheEntry { fetchedAt: number; /** Timestamp of last API *attempt* including failures (use for throttling). */ lastAttemptAt?: number; + /** + * HTTP status of the most recent *failed* attempt (e.g. 429), cleared on a + * successful fetch. Used so the dashboard can render a live error indicator + * instead of a stale value. + */ + lastErrorStatus?: number; + /** + * Epoch-ms before which we MUST NOT retry, derived from a 429 `Retry-After` + * header (or a default backoff when the header is absent). Cleared on a + * successful fetch. Without this we re-poll every MIN_FETCH_INTERVAL_MS (60s) + * even though the endpoint's rate-limit window is longer (~90s+), so the + * cooldown never clears and the 429s become self-sustaining. + */ + cooldownUntil?: number; +} + +/** + * Outcome of a usage fetch. `rateLimited` is true when the most recent attempt + * hit a 429 — callers use it to surface an error in the UI rather than the + * last cached value. + */ +export interface UsageFetchResult { + usage: ClaudeUsageData | null; + rateLimited: boolean; } let usageDiskCache: Record = {}; @@ -117,11 +141,35 @@ export function getUsageCacheReadKeys( // resolution — at worst the gate fires ~60s after a window crosses 95%. const MIN_FETCH_INTERVAL_MS = 60_000; +// Small margin added on top of a server-provided Retry-After so we wait until +// just *after* the cooldown window closes rather than racing its edge. +const RATE_LIMIT_MARGIN_MS = 5_000; +// Fallback cooldown when a 429 carries no usable Retry-After header. +const DEFAULT_RATE_LIMIT_COOLDOWN_MS = 5 * 60_000; + +/** + * Parse an HTTP `Retry-After` header into milliseconds from now. + * Accepts either a delta-seconds integer ("93") or an HTTP-date. + * Returns null when the header is missing or unparseable. + */ +export function parseRetryAfterMs(header: string | null): number | null { + if (!header) return null; + const trimmed = header.trim(); + if (/^\d+$/.test(trimmed)) { + return Number(trimmed) * 1000; + } + const dateMs = Date.parse(trimmed); + if (Number.isFinite(dateMs)) { + return Math.max(0, dateMs - Date.now()); + } + return null; +} + async function fetchUsageForToken( token: string, accountIndex?: number, refreshAttempted = false, -): Promise { +): Promise { loadUsageDiskCache(); // Return cached data if attempted recently (avoid API rate-limit) @@ -150,13 +198,51 @@ async function fetchUsageForToken( cached = usageDiskCache[writeKey]; saveUsageDiskCache(); } + + /** + * Record this attempt's timestamp (and error status) at the write key, + * creating the entry if it does not exist yet. Recording even when there is + * no prior cached usage is what makes the MIN_FETCH_INTERVAL_MS throttle + * apply to *failures* too — without it an empty cache means every dashboard + * refresh hits the API, which itself sustains the very 429s we then report. + */ + const recordAttempt = (errorStatus?: number, cooldownUntil?: number): void => { + const now = Date.now(); + const entry: UsageCacheEntry = usageDiskCache[writeKey] ?? { + usage: {}, + fetchedAt: 0, + }; + entry.lastAttemptAt = now; + entry.lastErrorStatus = errorStatus; + entry.cooldownUntil = cooldownUntil; + usageDiskCache[writeKey] = entry; + saveUsageDiskCache(); + }; + + // Honour an active rate-limit cooldown from a prior 429's Retry-After. This + // is what actually breaks the self-sustaining 429 loop: the endpoint hands + // back a ~90s+ window, so retrying on the 60s MIN_FETCH_INTERVAL would keep + // hitting it mid-cooldown and never recover. + if ( + !refreshAttempted && + cached?.cooldownUntil && + Date.now() < cached.cooldownUntil + ) { + return { usage: null, rateLimited: true }; + } + const lastAttempt = cached?.lastAttemptAt ?? cached?.fetchedAt ?? 0; if ( !refreshAttempted && cached && Date.now() - lastAttempt < MIN_FETCH_INTERVAL_MS ) { - return cached.usage; + // Within the throttle window: replay the last outcome without an API call. + // On a 429 we report rateLimited and DO NOT serve the stale value. + if (cached.lastErrorStatus === 429) { + return { usage: null, rateLimited: true }; + } + return { usage: cached.usage ?? null, rateLimited: false }; } const controller = new AbortController(); const timer = setTimeout(() => controller.abort(), FETCH_TIMEOUT_MS); @@ -208,29 +294,30 @@ async function fetchUsageForToken( ? 'Claude usage API: token expired or invalid (401)' : 'Claude usage API: forbidden — token missing required scope (403)', ); - if (cached) { - cached.lastAttemptAt = Date.now(); - saveUsageDiskCache(); - } - return cached?.usage ?? null; + recordAttempt(res.status); + return { usage: cached?.usage ?? null, rateLimited: false }; } if (res.status === 429) { const staleMs = cached ? Date.now() - cached.fetchedAt : 0; + const retryAfterMs = parseRetryAfterMs(res.headers.get('retry-after')); + const cooldownMs = retryAfterMs ?? DEFAULT_RATE_LIMIT_COOLDOWN_MS; + const cooldownUntil = Date.now() + cooldownMs + RATE_LIMIT_MARGIN_MS; logger.warn( { account: accountIndex != null ? accountIndex + 1 : '?', tokenKey: legacyTokenCacheKey(token), cacheKey: writeKey, staleMinutes: Math.round(staleMs / 60_000), + retryAfterSec: retryAfterMs != null ? Math.round(retryAfterMs / 1000) : null, + cooldownSec: Math.round(cooldownMs / 1000), }, - 'Claude usage API: rate limited (429), returning cached data', + 'Claude usage API: rate limited (429)', ); - // Record attempt time so we don't retry for MIN_FETCH_INTERVAL_MS - if (cached) { - cached.lastAttemptAt = Date.now(); - saveUsageDiskCache(); - } - return cached?.usage ?? null; + // Back off until the server-provided Retry-After window closes (plus a + // margin) so we stop re-tripping the limit. Surfaces a 429 indicator and + // does NOT serve the stale value. + recordAttempt(429, cooldownUntil); + return { usage: null, rateLimited: true }; } if (!res.ok) { logger.warn( @@ -242,11 +329,8 @@ async function fetchUsageForToken( }, `Claude usage API: unexpected status ${res.status}`, ); - if (cached) { - cached.lastAttemptAt = Date.now(); - saveUsageDiskCache(); - } - return cached?.usage ?? null; + recordAttempt(res.status); + return { usage: cached?.usage ?? null, rateLimited: false }; } const data = (await res.json()) as UsageApiResponse; @@ -258,12 +342,14 @@ async function fetchUsageForToken( seven_day_opus: mapWindow(data.seven_day_opus), }; - // Persist to disk cache — success: update both fetchedAt and lastAttemptAt + // Persist to disk cache — success: update fetchedAt + lastAttemptAt and + // clear any prior error status. const now = Date.now(); usageDiskCache[writeKey] = { usage: result, fetchedAt: now, lastAttemptAt: now, + lastErrorStatus: undefined, }; saveUsageDiskCache(); @@ -278,7 +364,7 @@ async function fetchUsageForToken( 'Claude usage API: fetched successfully', ); - return result; + return { usage: result, rateLimited: false }; } catch (err) { if ((err as Error).name === 'AbortError') { logger.warn( @@ -301,11 +387,8 @@ async function fetchUsageForToken( ); } // Record attempt time so we back off on persistent failures - if (cached) { - cached.lastAttemptAt = Date.now(); - saveUsageDiskCache(); - } - return cached?.usage ?? null; + recordAttempt(); + return { usage: cached?.usage ?? null, rateLimited: false }; } finally { clearTimeout(timer); } @@ -329,7 +412,7 @@ export async function fetchClaudeUsage(): Promise { logger.debug('No Claude OAuth token available for usage check'); return null; } - return fetchUsageForToken(token, undefined); + return (await fetchUsageForToken(token, undefined)).usage; } export interface ClaudeAccountProfile { @@ -471,6 +554,11 @@ export interface ClaudeAccountUsage { isActive: boolean; isRateLimited: boolean; usage: ClaudeUsageData | null; + /** + * True when the most recent usage-API attempt for this account hit a 429. + * The dashboard renders a "429" indicator instead of a stale value. + */ + usageRateLimited?: boolean; } /** @@ -484,7 +572,7 @@ export async function fetchAllClaudeUsage(): Promise { const credsToken = readCredentialsAccessToken(0); const token = credsToken || getConfiguredClaudeTokens()[0]; if (!token) return []; - const usage = await fetchUsageForToken(token, 0); + const { usage, rateLimited } = await fetchUsageForToken(token, 0); return [ { index: 0, @@ -492,6 +580,7 @@ export async function fetchAllClaudeUsage(): Promise { isActive: true, isRateLimited: false, usage, + usageRateLimited: rateLimited, }, ]; } @@ -505,13 +594,17 @@ export async function fetchAllClaudeUsage(): Promise { // by token-refresh.ts, so it always carries the full scope set. const credsToken = readCredentialsAccessToken(t.index); const tokenForFetch = credsToken || t.token; - const usage = await fetchUsageForToken(tokenForFetch, t.index); + const { usage, rateLimited } = await fetchUsageForToken( + tokenForFetch, + t.index, + ); results.push({ index: t.index, masked: t.masked, isActive: t.isActive, isRateLimited: t.isRateLimited, usage, + usageRateLimited: rateLimited, }); } return results; diff --git a/src/dashboard-usage-rows.test.ts b/src/dashboard-usage-rows.test.ts index a1b1c02..ca07467 100644 --- a/src/dashboard-usage-rows.test.ts +++ b/src/dashboard-usage-rows.test.ts @@ -133,6 +133,38 @@ describe('dashboard Claude usage rows', () => { }); }); + it('marks a rate-limited account with a 429 error and does not fall back to a cached value', () => { + const cachedAccounts: ClaudeAccountUsage[] = [ + { + index: 0, + masked: 'tok-a', + isActive: true, + isRateLimited: false, + usage: { + five_hour: { utilization: 0.4, resets_at: '2026-03-24T04:00:00+09:00' }, + seven_day: { utilization: 0.7, resets_at: '2026-03-29T04:00:00+09:00' }, + }, + }, + ]; + const liveAccounts: ClaudeAccountUsage[] = [ + { + index: 0, + masked: 'tok-a', + isActive: true, + isRateLimited: false, + usage: null, + usageRateLimited: true, + }, + ]; + + const merged = mergeClaudeDashboardAccounts(liveAccounts, cachedAccounts); + // The 429 must win over the cached value — no stale fallback. + expect(merged[0].usage).toBeNull(); + + const rows = buildClaudeUsageRows(merged); + expect(rows[0]).toMatchObject({ h5pct: -1, d7pct: -1, error: '429' }); + }); + it('preserves the last successful usage per account instead of collapsing to one cache entry', () => { const cachedAccounts: ClaudeAccountUsage[] = [ { diff --git a/src/dashboard-usage-rows.ts b/src/dashboard-usage-rows.ts index 31c8dff..259384f 100644 --- a/src/dashboard-usage-rows.ts +++ b/src/dashboard-usage-rows.ts @@ -7,6 +7,8 @@ export type UsageRow = { h5reset: string; d7pct: number; d7reset: string; + /** When set, the renderer shows this text (e.g. "429") in place of the bars. */ + error?: string; }; export function formatResetRemaining(value: string | number): string { @@ -42,7 +44,11 @@ export function mergeClaudeDashboardAccounts( return liveAccounts.map((account) => ({ ...account, - usage: account.usage || cachedByIndex.get(account.index)?.usage || null, + // On a 429 we deliberately do NOT fall back to the last cached value — + // the dashboard surfaces a "429" indicator instead. + usage: account.usageRateLimited + ? null + : account.usage || cachedByIndex.get(account.index)?.usage || null, })); } @@ -75,6 +81,7 @@ export function buildClaudeUsageRows( : Math.round(d7.utilization * 100) : -1, d7reset: d7 ? formatResetRemaining(d7.resets_at) : '', + error: account.usageRateLimited ? '429' : undefined, }; }); } diff --git a/src/unified-dashboard.ts b/src/unified-dashboard.ts index 17c56b2..bf5dbd4 100644 --- a/src/unified-dashboard.ts +++ b/src/unified-dashboard.ts @@ -480,6 +480,13 @@ export function renderUsageTable( const renderRows = (rows: UsageRow[]) => { for (const row of rows) { + if (row.error) { + // Live error (e.g. 429) — show the indicator in both columns instead + // of a bar or a stale value. + const cell = row.error.padEnd(6); + lines.push(`${padName(row.name)}${cell} ${cell}`); + continue; + } const h5 = row.h5pct >= 0 ? `${bar(row.h5pct)}${String(row.h5pct).padStart(3)}%`