diff --git a/packages/opencode/src/commands.ts b/packages/opencode/src/commands.ts index ed09000..426d1f6 100644 --- a/packages/opencode/src/commands.ts +++ b/packages/opencode/src/commands.ts @@ -153,9 +153,7 @@ async function executeQuotaCommand( if (failures.length > 0) { lines.push('') for (const f of failures) { - lines.push( - `⚠ ${f.account}: could not fetch (${f.error ?? 'unknown error'})`, - ) + lines.push(`- ${f.account}: fetch failed — Refresh to retry`) } } } diff --git a/packages/opencode/src/core/backoff.ts b/packages/opencode/src/core/backoff.ts index 2fc0d0c..0a63380 100644 --- a/packages/opencode/src/core/backoff.ts +++ b/packages/opencode/src/core/backoff.ts @@ -19,6 +19,8 @@ export function isTransientRefreshError(error: unknown) { } if (!(error instanceof Error)) return false return ( + error.name === 'AbortError' || + error.name === 'TimeoutError' || error.message.includes('fetch failed') || ('code' in error && (error.code === 'ECONNRESET' || @@ -37,6 +39,8 @@ export function isTransientQuotaError(error: unknown) { if (!(error instanceof Error)) return false const code = (error as Error & { code?: unknown }).code return ( + error.name === 'AbortError' || + error.name === 'TimeoutError' || message.includes('fetch failed') || code === 'ECONNRESET' || code === 'ECONNREFUSED' || diff --git a/packages/opencode/src/core/provider.ts b/packages/opencode/src/core/provider.ts index a71b493..3877b3e 100644 --- a/packages/opencode/src/core/provider.ts +++ b/packages/opencode/src/core/provider.ts @@ -6,9 +6,14 @@ * directly. */ +import { createLogger } from '../logger.ts' +import { errorMessage } from '../util/error.ts' import type { OAuthQuotaSnapshot } from './accounts.ts' import { parseRetryAfter } from './backoff.ts' +const log = createLogger('quota') +type QuotaLogger = Pick + // --------------------------------------------------------------------------- // Window names are widen-able strings (not an enum) so multi-family // rate-limit windows (additional_rate_limits / metered_limit_name) can be @@ -92,6 +97,7 @@ export async function codexRefreshFn(input: { }> { const response = await input.fetchImpl(`${CODEX_ISSUER}/oauth/token`, { method: 'POST', + signal: AbortSignal.timeout(15_000), headers: { 'Content-Type': 'application/x-www-form-urlencoded' }, body: new URLSearchParams({ grant_type: 'refresh_token', @@ -140,23 +146,51 @@ export async function whamUsageFn(input: { fetchImpl: typeof fetch now: () => number accountId?: string + accountKey?: string + logger?: QuotaLogger }): Promise { - const res = await input.fetchImpl(WHAM_USAGE_URL, { - headers: { - authorization: `Bearer ${input.accessToken}`, - 'chatgpt-account-id': input.accountId ?? '', - 'oai-client-platform': 'web', - 'oai-client-version': '0', - 'x-openai-target-path': '/backend-api/wham/usage', - }, - }) - if (!res.ok) { - const retryAfter = parseRetryAfter(res.headers.get('retry-after')) - throw Object.assign(new Error(`wham usage check failed: ${res.status}`), { + const logger = input.logger ?? log + const accountId = input.accountKey ?? 'unknown' + const startedAt = Date.now() + logger.debug('wham usage fetch started', { pid: process.pid, accountId }) + try { + const res = await input.fetchImpl(WHAM_USAGE_URL, { + signal: AbortSignal.timeout(15_000), + headers: { + authorization: `Bearer ${input.accessToken}`, + 'chatgpt-account-id': input.accountId ?? '', + 'oai-client-platform': 'web', + 'oai-client-version': '0', + 'x-openai-target-path': '/backend-api/wham/usage', + }, + }) + if (!res.ok) { + const retryAfter = parseRetryAfter(res.headers.get('retry-after')) + throw Object.assign(new Error(`wham usage check failed: ${res.status}`), { + status: res.status, + retryAfter, + }) as ProviderHttpError + } + const { normalizeWham } = await import('../quota-normalize.ts') + const snapshot = normalizeWham(await res.json()) + logger.debug('wham usage fetch succeeded', { + pid: process.pid, + accountId, status: res.status, - retryAfter, - }) as ProviderHttpError + elapsedMs: Date.now() - startedAt, + }) + return snapshot + } catch (error) { + logger.warn('wham usage fetch failed', { + pid: process.pid, + accountId, + status: + typeof (error as { status?: unknown } | null)?.status === 'number' + ? (error as { status: number }).status + : 'error', + elapsedMs: Date.now() - startedAt, + error: errorMessage(error), + }) + throw error } - const { normalizeWham } = await import('../quota-normalize.ts') - return normalizeWham(await res.json()) } diff --git a/packages/opencode/src/core/refresh-all-quota.ts b/packages/opencode/src/core/refresh-all-quota.ts index 6604927..c483dd7 100644 --- a/packages/opencode/src/core/refresh-all-quota.ts +++ b/packages/opencode/src/core/refresh-all-quota.ts @@ -1,3 +1,5 @@ +import { createLogger } from '../logger' +import { errorMessage } from '../util/error' import type { FallbackAccountManager, isOAuthAccount, @@ -7,6 +9,9 @@ import type { import type { whamUsageFn } from './provider' import type { QuotaManager } from './quota-manager' +const log = createLogger('quota') +type QuotaLogger = Pick + export interface RefreshAllQuotaDeps { getAuth: () => Promise<{ type: string @@ -50,6 +55,7 @@ export interface RefreshAllQuotaDeps { isOAuthAccountFn: typeof isOAuthAccount whamFn?: typeof whamUsageFn respectBackoff?: boolean + logger?: QuotaLogger } export interface RefreshAllQuotaResult { @@ -65,6 +71,18 @@ export async function refreshAllQuota( if (!whamFn) throw new Error('whamFn is required for refreshAllQuota') const results: RefreshAllQuotaResult[] = [] + const logger = deps.logger ?? log + const recordOutcome = (result: RefreshAllQuotaResult) => { + results.push(result) + const payload = { + pid: process.pid, + accountId: result.account, + status: result.ok ? 'ok' : 'error', + ...(result.error ? { error: result.error } : {}), + } + if (result.ok) logger.debug('quota refresh succeeded', payload) + else logger.warn('quota refresh failed', payload) + } // --- MAIN --- try { @@ -90,13 +108,14 @@ export async function refreshAllQuota( if (auth.access) { if (deps.respectBackoff && deps.quotaManager.isBackedOff()) { - results.push({ account: 'main', ok: true }) + recordOutcome({ account: 'main', ok: true }) } else { const snap = await whamFn({ accessToken: auth.access, fetchImpl: deps.fetchImpl, now: deps.now, accountId: deps.storageMainAccountId, + accountKey: 'main', }) deps.quotaManager.setMain( auth.access, @@ -108,23 +127,27 @@ export async function refreshAllQuota( undefined, true, ) - results.push({ account: 'main', ok: true }) + recordOutcome({ account: 'main', ok: true }) } } else { - results.push({ account: 'main', ok: false, error: 'no access token' }) + recordOutcome({ + account: 'main', + ok: false, + error: 'no access token', + }) } } else { - results.push({ + recordOutcome({ account: 'main', ok: false, error: 'auth type is not oauth', }) } } catch (e) { - results.push({ + recordOutcome({ account: 'main', ok: false, - error: (e as Error)?.message ?? String(e), + error: errorMessage(e), }) } @@ -142,7 +165,7 @@ export async function refreshAllQuota( (acct as OAuthAccount).access, ) ) { - results.push({ account: acct.id, ok: true }) + recordOutcome({ account: acct.id, ok: true }) continue } @@ -154,7 +177,7 @@ export async function refreshAllQuota( } if (!refreshed.access) { - results.push({ + recordOutcome({ account: acct.id, ok: false, error: 'no access token', @@ -167,6 +190,7 @@ export async function refreshAllQuota( fetchImpl: deps.fetchImpl, now: deps.now, accountId: refreshed.accountId, + accountKey: acct.id, }) deps.quotaManager.setFallback( acct.id, @@ -178,12 +202,12 @@ export async function refreshAllQuota( refreshed.access, true, ) - results.push({ account: acct.id, ok: true }) + recordOutcome({ account: acct.id, ok: true }) } catch (e) { - results.push({ + recordOutcome({ account: acct.id, ok: false, - error: (e as Error)?.message ?? String(e), + error: errorMessage(e), }) } } diff --git a/packages/opencode/src/index.ts b/packages/opencode/src/index.ts index a8e0590..a206a57 100644 --- a/packages/opencode/src/index.ts +++ b/packages/opencode/src/index.ts @@ -106,6 +106,7 @@ import { setSidebarMachineState, upsertSidebarActiveRouting, } from './sidebar-state' +import { errorMessage } from './util/error' import { isRecord } from './util/record' import { stableStringify } from './util/stable-json' import { uuidV7 } from './util/uuid-v7' @@ -1971,7 +1972,12 @@ export async function CodexAuthPlugin( isOAuthAccountFn: isOAuthAccount, whamFn: whamUsageFn, respectBackoff: true, - }).catch(() => {}) + }).catch((error) => + logQ.warn('boot quota seed failed', { + pid: process.pid, + error: errorMessage(error), + }), + ) } // ------------------------------------------------------------------- diff --git a/packages/opencode/src/tests/commands.test.ts b/packages/opencode/src/tests/commands.test.ts index a4c9077..949767b 100644 --- a/packages/opencode/src/tests/commands.test.ts +++ b/packages/opencode/src/tests/commands.test.ts @@ -849,7 +849,7 @@ describe('commands', () => { expect(fb2Section).not.toContain('resets:') }) - test('refreshAllQuota with one failure → ⚠ line for failing account', async () => { + test('refreshAllQuota with one failure → short retry state for failing account', async () => { const qm = new QuotaManager({ storage: { version: 1 as const, accounts: [] }, }) @@ -884,10 +884,8 @@ describe('commands', () => { expect(payload.text).toContain('10% used') expect(payload.text).toContain('50% used') - // Failure line - expect(payload.text).toContain( - '⚠ fb-2: could not fetch (wham usage check failed: 401)', - ) + expect(payload.text).toContain('- fb-2: fetch failed — Refresh to retry') + expect(payload.text).not.toContain('wham usage check failed: 401') }) test('refreshAllQuota undefined → falls back to cached display', async () => { diff --git a/packages/opencode/src/tests/provider-backoff.test.ts b/packages/opencode/src/tests/provider-backoff.test.ts index 7fbbfa5..e918bea 100644 --- a/packages/opencode/src/tests/provider-backoff.test.ts +++ b/packages/opencode/src/tests/provider-backoff.test.ts @@ -1,6 +1,31 @@ -import { describe, expect, it, mock } from 'bun:test' -import { buildQuotaOperationError } from '../core/backoff.ts' -import { codexRefreshFn, type ProviderHttpError } from '../core/provider.ts' +import { describe, expect, it, jest, mock } from 'bun:test' +import { + buildQuotaOperationError, + isTransientQuotaError, + isTransientRefreshError, +} from '../core/backoff.ts' +import { + codexRefreshFn, + type ProviderHttpError, + whamUsageFn, +} from '../core/provider.ts' + +function fetchUntilAborted() { + const fetchMock = mock( + (_input: RequestInfo | URL, init?: RequestInit) => + new Promise((_resolve, reject) => { + const signal = init?.signal + if (!signal) { + reject(new Error('missing timeout signal')) + return + } + signal.addEventListener('abort', () => reject(signal.reason), { + once: true, + }) + }), + ) + return fetchMock as unknown as typeof fetch & typeof fetchMock +} describe('buildQuotaOperationError retryAfter threading', () => { it('honors positive retryAfter on quota error', () => { @@ -142,3 +167,80 @@ describe('codexRefreshFn token validation', () => { expect(thrown?.isRefreshError).toBe(true) }) }) + +describe('provider fetch timeouts', () => { + it('bounds a stalled quota fetch and classifies the timeout as transient', async () => { + jest.useFakeTimers() + try { + const fetchImpl = fetchUntilAborted() + const pending = whamUsageFn({ + accessToken: 'access-token', + fetchImpl, + now: () => 1_000_000, + accountId: 'account-1', + }) + + expect(fetchImpl.mock.calls[0]?.[1]?.signal).toBeInstanceOf(AbortSignal) + jest.advanceTimersByTime(15_000) + + const error = await pending.catch((caught) => caught) + expect(error).toBeInstanceOf(Error) + expect((error as Error).name).toBe('TimeoutError') + expect(isTransientQuotaError(error)).toBe(true) + } finally { + jest.useRealTimers() + } + }) + + it('bounds a stalled token refresh and classifies the timeout as transient', async () => { + jest.useFakeTimers() + try { + const fetchImpl = fetchUntilAborted() + const pending = codexRefreshFn({ + refreshToken: 'refresh-token', + fetchImpl, + now: () => 1_000_000, + }) + + expect(fetchImpl.mock.calls[0]?.[1]?.signal).toBeInstanceOf(AbortSignal) + jest.advanceTimersByTime(15_000) + + const error = await pending.catch((caught) => caught) + expect(error).toBeInstanceOf(Error) + expect((error as Error).name).toBe('TimeoutError') + expect(isTransientRefreshError(error)).toBe(true) + } finally { + jest.useRealTimers() + } + }) +}) + +describe('quota fetch logging', () => { + it('warns with account context when the usage fetch rejects', async () => { + const logger = { + debug: mock(() => {}), + warn: mock(() => {}), + } + const failure = new Error('upstream unavailable') + const input = { + accessToken: 'access-token', + fetchImpl: mock(async () => { + throw failure + }) as unknown as typeof fetch, + now: () => 1_000_000, + accountId: 'account-1', + accountKey: 'account-1', + logger, + } + + const caught = await whamUsageFn(input).catch((error) => error) + expect(caught).toBe(failure) + expect(logger.warn).toHaveBeenCalledWith( + 'wham usage fetch failed', + expect.objectContaining({ + accountId: 'account-1', + error: 'upstream unavailable', + }), + ) + }) +}) diff --git a/packages/opencode/src/tests/refresh-all-quota.test.ts b/packages/opencode/src/tests/refresh-all-quota.test.ts index 682918d..ca550b3 100644 --- a/packages/opencode/src/tests/refresh-all-quota.test.ts +++ b/packages/opencode/src/tests/refresh-all-quota.test.ts @@ -150,6 +150,40 @@ describe('refreshAllQuota', () => { expect(whamCalls).toEqual(['access-main', 'access-fb1', 'access-fb2']) }) + test('logs each account outcome without exposing credentials', async () => { + const logger = { + debug: mock(() => {}), + warn: mock(() => {}), + } + const whamFn = mock(async (input: { accessToken: string }) => { + if (input.accessToken === 'access-fb2') { + throw new Error('upstream unavailable') + } + return makeQuotaSnapshot(10) + }) + const deps = makeDeps({ whamFn, logger } as MakeDepsOptions) + + await refreshAllQuota(deps) + + expect(logger.debug).toHaveBeenCalledWith('quota refresh succeeded', { + pid: process.pid, + accountId: 'main', + status: 'ok', + }) + expect(logger.warn).toHaveBeenCalledWith('quota refresh failed', { + pid: process.pid, + accountId: 'fb-2', + status: 'error', + error: 'upstream unavailable', + }) + const serialized = JSON.stringify([ + ...logger.debug.mock.calls, + ...logger.warn.mock.calls, + ]) + expect(serialized).not.toContain('access-main') + expect(serialized).not.toContain('access-fb2') + }) + test('expired main token → codexRefreshFn called before wham', async () => { const deps = makeDeps({ getAuth: mock(async () => ({