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 <noreply@anthropic.com>
This commit is contained in:
Codex
2026-06-20 20:55:35 +09:00
parent f9b1e74838
commit 2be6c8db8d
5 changed files with 304 additions and 30 deletions

View File

@@ -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<typeof import('./utils.js')>('./utils.js');
return { ...actual, readJsonFile: readJsonFileMock, writeJsonFile: vi.fn() };
});
afterEach(() => {
vi.resetModules();
vi.clearAllMocks();
vi.unstubAllGlobals();
vi.useRealTimers();
});
function makeResponse(
status: number,
headers: Record<string, string> = {},
): 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);
});
});

View File

@@ -55,6 +55,30 @@ interface UsageCacheEntry {
fetchedAt: number; fetchedAt: number;
/** Timestamp of last API *attempt* including failures (use for throttling). */ /** Timestamp of last API *attempt* including failures (use for throttling). */
lastAttemptAt?: number; 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<string, UsageCacheEntry> = {}; let usageDiskCache: Record<string, UsageCacheEntry> = {};
@@ -117,11 +141,35 @@ export function getUsageCacheReadKeys(
// resolution — at worst the gate fires ~60s after a window crosses 95%. // resolution — at worst the gate fires ~60s after a window crosses 95%.
const MIN_FETCH_INTERVAL_MS = 60_000; 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( async function fetchUsageForToken(
token: string, token: string,
accountIndex?: number, accountIndex?: number,
refreshAttempted = false, refreshAttempted = false,
): Promise<ClaudeUsageData | null> { ): Promise<UsageFetchResult> {
loadUsageDiskCache(); loadUsageDiskCache();
// Return cached data if attempted recently (avoid API rate-limit) // Return cached data if attempted recently (avoid API rate-limit)
@@ -150,13 +198,51 @@ async function fetchUsageForToken(
cached = usageDiskCache[writeKey]; cached = usageDiskCache[writeKey];
saveUsageDiskCache(); 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; const lastAttempt = cached?.lastAttemptAt ?? cached?.fetchedAt ?? 0;
if ( if (
!refreshAttempted && !refreshAttempted &&
cached && cached &&
Date.now() - lastAttempt < MIN_FETCH_INTERVAL_MS 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 controller = new AbortController();
const timer = setTimeout(() => controller.abort(), FETCH_TIMEOUT_MS); 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: token expired or invalid (401)'
: 'Claude usage API: forbidden — token missing required scope (403)', : 'Claude usage API: forbidden — token missing required scope (403)',
); );
if (cached) { recordAttempt(res.status);
cached.lastAttemptAt = Date.now(); return { usage: cached?.usage ?? null, rateLimited: false };
saveUsageDiskCache();
}
return cached?.usage ?? null;
} }
if (res.status === 429) { if (res.status === 429) {
const staleMs = cached ? Date.now() - cached.fetchedAt : 0; 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( logger.warn(
{ {
account: accountIndex != null ? accountIndex + 1 : '?', account: accountIndex != null ? accountIndex + 1 : '?',
tokenKey: legacyTokenCacheKey(token), tokenKey: legacyTokenCacheKey(token),
cacheKey: writeKey, cacheKey: writeKey,
staleMinutes: Math.round(staleMs / 60_000), 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 // Back off until the server-provided Retry-After window closes (plus a
if (cached) { // margin) so we stop re-tripping the limit. Surfaces a 429 indicator and
cached.lastAttemptAt = Date.now(); // does NOT serve the stale value.
saveUsageDiskCache(); recordAttempt(429, cooldownUntil);
} return { usage: null, rateLimited: true };
return cached?.usage ?? null;
} }
if (!res.ok) { if (!res.ok) {
logger.warn( logger.warn(
@@ -242,11 +329,8 @@ async function fetchUsageForToken(
}, },
`Claude usage API: unexpected status ${res.status}`, `Claude usage API: unexpected status ${res.status}`,
); );
if (cached) { recordAttempt(res.status);
cached.lastAttemptAt = Date.now(); return { usage: cached?.usage ?? null, rateLimited: false };
saveUsageDiskCache();
}
return cached?.usage ?? null;
} }
const data = (await res.json()) as UsageApiResponse; const data = (await res.json()) as UsageApiResponse;
@@ -258,12 +342,14 @@ async function fetchUsageForToken(
seven_day_opus: mapWindow(data.seven_day_opus), 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(); const now = Date.now();
usageDiskCache[writeKey] = { usageDiskCache[writeKey] = {
usage: result, usage: result,
fetchedAt: now, fetchedAt: now,
lastAttemptAt: now, lastAttemptAt: now,
lastErrorStatus: undefined,
}; };
saveUsageDiskCache(); saveUsageDiskCache();
@@ -278,7 +364,7 @@ async function fetchUsageForToken(
'Claude usage API: fetched successfully', 'Claude usage API: fetched successfully',
); );
return result; return { usage: result, rateLimited: false };
} catch (err) { } catch (err) {
if ((err as Error).name === 'AbortError') { if ((err as Error).name === 'AbortError') {
logger.warn( logger.warn(
@@ -301,11 +387,8 @@ async function fetchUsageForToken(
); );
} }
// Record attempt time so we back off on persistent failures // Record attempt time so we back off on persistent failures
if (cached) { recordAttempt();
cached.lastAttemptAt = Date.now(); return { usage: cached?.usage ?? null, rateLimited: false };
saveUsageDiskCache();
}
return cached?.usage ?? null;
} finally { } finally {
clearTimeout(timer); clearTimeout(timer);
} }
@@ -329,7 +412,7 @@ export async function fetchClaudeUsage(): Promise<ClaudeUsageData | null> {
logger.debug('No Claude OAuth token available for usage check'); logger.debug('No Claude OAuth token available for usage check');
return null; return null;
} }
return fetchUsageForToken(token, undefined); return (await fetchUsageForToken(token, undefined)).usage;
} }
export interface ClaudeAccountProfile { export interface ClaudeAccountProfile {
@@ -471,6 +554,11 @@ export interface ClaudeAccountUsage {
isActive: boolean; isActive: boolean;
isRateLimited: boolean; isRateLimited: boolean;
usage: ClaudeUsageData | null; 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<ClaudeAccountUsage[]> {
const credsToken = readCredentialsAccessToken(0); const credsToken = readCredentialsAccessToken(0);
const token = credsToken || getConfiguredClaudeTokens()[0]; const token = credsToken || getConfiguredClaudeTokens()[0];
if (!token) return []; if (!token) return [];
const usage = await fetchUsageForToken(token, 0); const { usage, rateLimited } = await fetchUsageForToken(token, 0);
return [ return [
{ {
index: 0, index: 0,
@@ -492,6 +580,7 @@ export async function fetchAllClaudeUsage(): Promise<ClaudeAccountUsage[]> {
isActive: true, isActive: true,
isRateLimited: false, isRateLimited: false,
usage, usage,
usageRateLimited: rateLimited,
}, },
]; ];
} }
@@ -505,13 +594,17 @@ export async function fetchAllClaudeUsage(): Promise<ClaudeAccountUsage[]> {
// by token-refresh.ts, so it always carries the full scope set. // by token-refresh.ts, so it always carries the full scope set.
const credsToken = readCredentialsAccessToken(t.index); const credsToken = readCredentialsAccessToken(t.index);
const tokenForFetch = credsToken || t.token; const tokenForFetch = credsToken || t.token;
const usage = await fetchUsageForToken(tokenForFetch, t.index); const { usage, rateLimited } = await fetchUsageForToken(
tokenForFetch,
t.index,
);
results.push({ results.push({
index: t.index, index: t.index,
masked: t.masked, masked: t.masked,
isActive: t.isActive, isActive: t.isActive,
isRateLimited: t.isRateLimited, isRateLimited: t.isRateLimited,
usage, usage,
usageRateLimited: rateLimited,
}); });
} }
return results; return results;

View File

@@ -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', () => { it('preserves the last successful usage per account instead of collapsing to one cache entry', () => {
const cachedAccounts: ClaudeAccountUsage[] = [ const cachedAccounts: ClaudeAccountUsage[] = [
{ {

View File

@@ -7,6 +7,8 @@ export type UsageRow = {
h5reset: string; h5reset: string;
d7pct: number; d7pct: number;
d7reset: string; 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 { export function formatResetRemaining(value: string | number): string {
@@ -42,7 +44,11 @@ export function mergeClaudeDashboardAccounts(
return liveAccounts.map((account) => ({ return liveAccounts.map((account) => ({
...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) : Math.round(d7.utilization * 100)
: -1, : -1,
d7reset: d7 ? formatResetRemaining(d7.resets_at) : '', d7reset: d7 ? formatResetRemaining(d7.resets_at) : '',
error: account.usageRateLimited ? '429' : undefined,
}; };
}); });
} }

View File

@@ -480,6 +480,13 @@ export function renderUsageTable(
const renderRows = (rows: UsageRow[]) => { const renderRows = (rows: UsageRow[]) => {
for (const row of rows) { 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 = const h5 =
row.h5pct >= 0 row.h5pct >= 0
? `${bar(row.h5pct)}${String(row.h5pct).padStart(3)}%` ? `${bar(row.h5pct)}${String(row.h5pct).padStart(3)}%`