From 06a3b55af3bcd343017636f34a0a2e3d9124d9ff Mon Sep 17 00:00:00 2001 From: thisisjun786 <259586770+thisisjun786@users.noreply.github.com> Date: Tue, 15 Sep 2026 21:03:50 +0900 Subject: [PATCH 1/9] fix(usage): attribute retries to the dispatched API-key account --- .../content/docs/reference/management-api.md | 16 ++ src/adapters/command-code.ts | 2 +- src/codex/account-label.ts | 17 ++- src/providers/label.ts | 20 ++- src/server/chat-native.ts | 22 ++- src/server/request-log.ts | 116 ++++++++++++++- src/server/responses/adapter-continuation.ts | 7 +- src/server/responses/adapter-delivery.ts | 14 +- src/server/responses/adapter-dispatch.ts | 10 +- src/server/responses/collaboration.ts | 1 - src/server/responses/compact.ts | 1 - src/server/responses/core-codex-account.ts | 4 +- src/server/responses/core-combo.ts | 9 +- src/server/responses/encrypted-payload.ts | 1 - src/server/responses/passthrough-dispatch.ts | 12 +- src/server/responses/request-send-budget.ts | 2 +- src/server/responses/request-transport.ts | 65 ++++++++- src/server/responses/run-turn-execution.ts | 18 +-- src/server/responses/sidecar-execution.ts | 20 +-- src/usage/log.ts | 2 +- structure/adapters/registry.md | 2 +- structure/catalog.md | 2 +- structure/clients/claude-desktop.md | 2 +- structure/codex-home.md | 2 + structure/config.md | 2 +- structure/data-planes/images.md | 2 +- structure/data-planes/inbound-compat.md | 2 +- structure/gui-and-management-api.md | 20 +++ structure/ops/docs-and-release.md | 2 +- structure/ops/service-and-sidecars.md | 2 +- structure/providers/chat-compat.md | 2 + structure/providers/cursor.md | 2 + structure/providers/openai-tiers.md | 2 + structure/providers/xai-grok.md | 2 +- structure/runtime.md | 7 + structure/subagents.md | 2 +- structure/transports/byte-accounting.md | 2 + structure/transports/inventory.md | 2 +- structure/transports/responses.md | 9 ++ structure/transports/streaming-health.md | 2 +- .../codex-account-label.test.ts | 18 +++ tests/providers/rate-limit-retry.test.ts | 8 +- .../chat-completions-endpoint.test.ts | 69 ++++++++- tests/responses/empty-completion-core.test.ts | 12 +- .../server/server-combo-failover-e2e.test.ts | 18 ++- tests/server/server-key-failover-e2e.test.ts | 137 ++++++++++++++++-- .../server-xai-oauth-401-replay.test.ts | 8 +- tests/usage/request-log.test.ts | 112 ++++++++++++++ 48 files changed, 694 insertions(+), 117 deletions(-) diff --git a/docs-site/src/content/docs/reference/management-api.md b/docs-site/src/content/docs/reference/management-api.md index b973add5d9..d03a78f5f4 100644 --- a/docs-site/src/content/docs/reference/management-api.md +++ b/docs-site/src/content/docs/reference/management-api.md @@ -246,6 +246,22 @@ final provider. Custom destinations and historic rows omit the field; consumers infer subscription usage from the current configuration, model name, or inbound API key. The log reports usage, not subscription invoice amounts. +API-key attempts also record `accountLogLabel` as `k` followed by 32 lowercase hex digits. +The label is the first 128 bits of SHA-256 over +`JSON.stringify(["ocx-key-account-v1", providerName, entryId ?? null, reference])`. +The reference is the configured key value captured for the physical request, before environment +or keychain resolution. Raw keys, references, and pool IDs are not written to the label field. +A consumer can derive the same label from its local configuration without resolving secrets. +Changing a literal key or reference changes the label; replacing the secret behind an unchanged +reference keeps the same logical account. Older unlabeled records cannot be attributed reliably. + +Key selection is recorded after queued requests have been rebuilt for the current selection. +When a retry changes keys, `attempts` retains a separate record for the preceding key, including +reported usage from failed responses. Missing usage remains unreported. Routed adapter terminals +are observed before image/search loops or continuation guards combine their usage. Consumers +sum the flat attempts by provider/account and do not add the parent combo total again. These +records identify usage; provider quota percentages remain separate upstream observations. + `GET /api/usage` reads `~/.opencodex/usage.jsonl` from the beginning through the current ledger snapshot on a cold start. It processes fixed 1 MiB chunks and retains compact aggregate state rather than every normalized request row. Later refreshes validate the previous line boundary and fold only diff --git a/src/adapters/command-code.ts b/src/adapters/command-code.ts index 4b7c707d7e..3c466829e2 100644 --- a/src/adapters/command-code.ts +++ b/src/adapters/command-code.ts @@ -469,7 +469,7 @@ async function fetchCommandCode(request: AdapterRequest, ctx: AdapterFetchContex const timer = setTimeout(() => timeout.abort(new DOMException("Timeout elapsed", "TimeoutError")), ctx?.timeoutMs ?? 200_000); const callerSignal = ctx?.abortSignal ?? new AbortController().signal; try { - return await executor(request.url, { + return await (ctx?.executor ?? executor)(request.url, { method: request.method, headers: request.headers, body: request.body, diff --git a/src/codex/account-label.ts b/src/codex/account-label.ts index b0a4ab7602..046462670b 100644 --- a/src/codex/account-label.ts +++ b/src/codex/account-label.ts @@ -1,17 +1,19 @@ import { createHash, randomBytes } from "node:crypto"; import type { CodexAccount, OcxConfig } from "../types"; import type { CodexAuthContext } from "./auth-context"; +import type { ProviderApiKeySelection } from "../types/provider"; import { MAIN_CODEX_ACCOUNT_ID } from "./main-account"; export const CODEX_ACCOUNT_LOG_LABEL_RE = /^p[a-f0-9]{6}$/; /** - * Account log labels come in two families (#2699): + * Account log labels come in three families: * * - `p` (plus the literal `main`) — a Codex pool account. * - `o` — a non-Codex OAuth provider account (xai, cursor, and siblings). + * - `k` — a request-owned API-key selection, scoped to provider and reference. * - * Both are sha256-derived digests, never an email and never a raw provider account id. That is + * Labels never contain an email, raw key/reference, or raw provider account id. That is * a privacy requirement, not a formatting preference: these labels are written to the usage log * and served over the management API. * @@ -20,7 +22,16 @@ export const CODEX_ACCOUNT_LOG_LABEL_RE = /^p[a-f0-9]{6}$/; * accepted cost of keeping the existing `p` format byte-compatible. */ export const OAUTH_ACCOUNT_LOG_LABEL_RE = /^o[a-f0-9]{6}$/; -export const ACCOUNT_LOG_LABEL_RE = /^(?:main|[po][a-f0-9]{6})$/; +export const KEY_ACCOUNT_LOG_LABEL_RE = /^k[a-f0-9]{32}$/; +export const ACCOUNT_LOG_LABEL_RE = /^(?:main|[po][a-f0-9]{6}|k[a-f0-9]{32})$/; + +/** Digest the request-owned configured selection, never serialize its key/reference. */ +export function apiKeyAccountLogLabel(provider: string, selection: ProviderApiKeySelection | undefined): `k${string}` | undefined { + if (!selection || typeof selection.reference !== "string" || !selection.reference.length) return undefined; + return `k${createHash("sha256").update(JSON.stringify([ + "ocx-key-account-v1", provider, selection.entryId ?? null, selection.reference, + ])).digest("hex").slice(0, 32)}`; +} export function oauthAccountLogLabel(accountId: string, provider = ""): string { return `o${createHash("sha256").update(`${provider}\0${accountId}`).digest("hex").slice(0, 6)}`; diff --git a/src/providers/label.ts b/src/providers/label.ts index 099bf04870..38b472a1a0 100644 --- a/src/providers/label.ts +++ b/src/providers/label.ts @@ -1,10 +1,28 @@ -import { CODEX_ACCOUNT_LOG_LABEL_RE, oauthAccountLogLabel } from "../codex/account-label"; +import { CODEX_ACCOUNT_LOG_LABEL_RE, KEY_ACCOUNT_LOG_LABEL_RE, apiKeyAccountLogLabel, oauthAccountLogLabel } from "../codex/account-label"; import type { OcxProviderConfig } from "../types"; export function canonicalUsageProviderLabel(provider: string): string { return provider === "chatgpt" || provider === "openai-multi" ? "openai" : provider; } +export function usesApiKeyAccount(provider: Pick): boolean { + return provider.authMode === "key" + || (provider.authMode === undefined && !!provider._apiKeyAttempt?.reference); +} + +/** Key identity comes from the captured selection, before env/keychain resolution. */ +export function stampApiKeyAccountLabel( + logCtx: { accountLogLabel?: string }, + providerName: string, + provider: Pick, +): void { + if (usesApiKeyAccount(provider)) { + logCtx.accountLogLabel = apiKeyAccountLogLabel(providerName, provider._apiKeyAttempt); + } else if (KEY_ACCOUNT_LOG_LABEL_RE.test(logCtx.accountLogLabel ?? "")) { + delete logCtx.accountLogLabel; + } +} + export function baseProviderLabel(provider: string): string { const canonical = canonicalUsageProviderLabel(provider); if (canonical !== provider) return canonical; diff --git a/src/server/chat-native.ts b/src/server/chat-native.ts index b122467103..791c687bd0 100644 --- a/src/server/chat-native.ts +++ b/src/server/chat-native.ts @@ -51,7 +51,9 @@ import { linkAbortSignal } from "./responses"; import { addFinalRequestLog, beginRequestAttempt, - noteAttemptSend, + noteProviderAttemptSend, + recordKeyAttemptFailure, + recordKeyWireAttemptUsage, recordFirstOutput, recordAttemptCredentialSource, sealRequestAttemptIdentity, @@ -344,10 +346,12 @@ export async function handleNativeChatCompletions(options: HandleNativeChatOptio const encoding = new Headers(init.headers).get("accept-encoding"); if (!headers.has("accept-encoding") && encoding) headers.set("accept-encoding", encoding); if (init.signal?.aborted) throw init.signal.reason; - noteAttemptSend(attempt, logCtx.usageLogInputTokens, transportRecovery ?? recovery); - return ((activeProvider as OcxProviderTransport).fetch ?? execute)(request.url, applyUpstreamRecoveryInit({ + noteProviderAttemptSend(logCtx, route.providerName, activeProvider, logCtx.usageLogInputTokens, transportRecovery ?? recovery); + const dispatched = await ((activeProvider as OcxProviderTransport).fetch ?? execute)(request.url, applyUpstreamRecoveryInit({ ...init, method: request.method, headers, body: request.body, }, transportRecovery)); + if (!dispatched.ok) await recordKeyAttemptFailure(logCtx, dispatched, init.signal ?? upstream.signal); + return dispatched; }, }), ); @@ -509,8 +513,10 @@ export async function handleNativeChatCompletions(options: HandleNativeChatOptio stallTimeoutSec: config.stallTimeoutSec, onFirstOutput: logIds ? () => recordFirstOutput(logCtx, logIds.start) : undefined, onUsage: usage => { - logCtx.usage = usage; - attempt.usage = usage; + if (!recordKeyWireAttemptUsage(logCtx, usage)) { + logCtx.usage = usage; + attempt.usage = usage; + } }, onTerminal: (status: number, message?: string) => { terminalStatus = status; @@ -600,8 +606,10 @@ export async function handleNativeChatCompletions(options: HandleNativeChatOptio if (!completion) return fail(502, "upstream response contained no choices", "upstream_error"); const usage = usageFromChat(completion.usage); if (usage) { - logCtx.usage = usage; - attempt.usage = usage; + if (!recordKeyWireAttemptUsage(logCtx, usage)) { + logCtx.usage = usage; + attempt.usage = usage; + } } if (logIds) recordFirstOutput(logCtx, logIds.start); try { diff --git a/src/server/request-log.ts b/src/server/request-log.ts index d9cf83361f..2c09fb9b80 100644 --- a/src/server/request-log.ts +++ b/src/server/request-log.ts @@ -1,5 +1,8 @@ import { existsSync, readFileSync } from "node:fs"; import { randomBytes } from "node:crypto"; +import { stampApiKeyAccountLabel, usesApiKeyAccount } from "../providers/label"; +import { KEY_ACCOUNT_LOG_LABEL_RE } from "../codex/account-label"; +import { readBoundedResponseBody } from "../lib/bounded-body"; import type { ResponsesTerminalStatus } from "../bridge"; import { classifyError, @@ -782,8 +785,10 @@ export function applyResponseLogMetadata(logCtx: RequestLogContext, payload: unk } const usage = usageFromResponsesPayload((source as { usage?: unknown }).usage); if (usage && !logCtx.usageFromBridge) { - logCtx.usage = usage; - if (logCtx.activeAttempt) logCtx.activeAttempt.usage = usage; + if (!recordKeyWireAttemptUsage(logCtx, usage)) { + logCtx.usage = usage; + if (logCtx.activeAttempt) logCtx.activeAttempt.usage = usage; + } // Counts taken off a wire, not reported raw. The zero-default token-detail objects strict // clients require are indistinguishable here from a measured zero, so the cache detail these // counts carry is recorded as synthesized rather than as an observed miss. @@ -1216,6 +1221,31 @@ export function recordNoAccountAffinityFailure( logCtx.errorCode ??= "codex_no_account"; return resolved; } +// Attempt identity can change in place while a combo parent retains an older context copy. +// These objects own their usage even after a rotation to an unknown key identity. +const keyUsageOwners = new WeakSet(); +const keyWireUsageBaselines = new WeakMap(); + +function cloneKeyUsage(usage: OcxUsage | undefined): OcxUsage | undefined { + return usage ? { ...usage } : undefined; +} + +/** Replace this physical send's wire snapshot against the pre-send baseline; repeats do not sum. */ +export function recordKeyWireAttemptUsage(logCtx: RequestLogContext, usage: OcxUsage | undefined): boolean { + if (!usage) return false; + const attempt = logCtx.activeAttempt; + if (!attempt || !keyUsageOwners.has(attempt) || !keyWireUsageBaselines.has(attempt)) return false; + const baseline = keyWireUsageBaselines.get(attempt); + const current = { ...usage }; + attempt.usage = baseline + ? aggregateAttemptUsage([ + { ...attempt, usage: baseline, usageStatus: baseline.estimated ? "estimated" : "reported" }, + { ...attempt, usage: current, usageStatus: current.estimated ? "estimated" : "reported" }, + ]).usage + : current; + logCtx.usage = attempt.usage; + return true; +} export function addFinalRequestLog( requestId: string, @@ -1247,7 +1277,9 @@ export function addFinalRequestLog( logCtx.activeAttempt, effectiveStatus, Date.now() - (logCtx.activeAttemptStartedAt ?? start), - logCtx.usage, + keyUsageOwners.has(logCtx.activeAttempt) + ? logCtx.activeAttempt.usage + : logCtx.usage, ); // The final row and its active physical attempt describe the same terminal. Preserve the // semantic code on both so detailed attempt telemetry cannot regress to a generic status code. @@ -1542,6 +1574,84 @@ export function sealRequestAttemptIdentity( attempt.provider = provider; attempt.adapter = adapter; if (isCodexUsageAccountLogLabel(accountLogLabel)) attempt.accountLogLabel = accountLogLabel; + else delete attempt.accountLogLabel; +} + +/** Preserve metered JSON failures before key recovery consumes/cancels their body. */ +export async function recordKeyAttemptFailure(logCtx: RequestLogContext, response: Response, signal?: AbortSignal): Promise { + const attempt = logCtx.activeAttempt; + if (!attempt || !KEY_ACCOUNT_LOG_LABEL_RE.test(attempt.accountLogLabel ?? "")) return; + attempt.status = response.status; + const cancelOriginal = (): void => { try { void response.body?.cancel().catch(() => {}); } catch { /* closed */ } }; + signal?.addEventListener("abort", cancelOriginal, { once: true }); + try { + if (signal?.aborted) { cancelOriginal(); return; } + const body = await readBoundedResponseBody(response.clone(), { signal, totalTimeoutMs: 1000, inactivityTimeoutMs: 1000 }); + if (body.truncated || body.oversized) return; + const value = JSON.parse(body.text); + const usage = usageFromResponsesPayload(value?.usage ?? value?.response?.usage); + if (usage) recordKeyWireAttemptUsage(logCtx, usage); + } catch { /* Absent/malformed usage remains unknown; recovery still owns the response. */ } + finally { signal?.removeEventListener("abort", cancelOriginal); } +} + +/** Add raw per-response usage before a bridge combines multiple rounds for the client. */ +export function recordKeyAttemptUsage(logCtx: RequestLogContext, usage: OcxUsage | undefined): void { + const attempt = logCtx.activeAttempt; + if (!attempt || !usage) return; + attempt.usage = attempt.usage + ? aggregateAttemptUsage([{ ...attempt, usageStatus: attempt.usage.estimated ? "estimated" : "reported" }, + { ...attempt, usage, usageStatus: usage.estimated ? "estimated" : "reported" }]).usage + : { ...usage }; + logCtx.usage = attempt.usage; +} + +/** A stable active object lets combo/stream callbacks keep pointing at the final attempt. + * Earlier key segments are immutable, flat snapshots inserted before that active object. */ +export function noteProviderAttemptSend( + logCtx: RequestLogContext, + providerName: string, + provider: OcxProviderConfig, + inputTokenEstimate: number | undefined, + recovery?: AttemptRecoveryKind, +): void { + const attempt = logCtx.activeAttempt; + const previous = attempt?.accountLogLabel; + stampApiKeyAccountLabel(logCtx, providerName, provider); + const next = logCtx.accountLogLabel; + if (attempt && usesApiKeyAccount(provider)) keyUsageOwners.add(attempt); + if (attempt && attempt.sendCount > 0 && previous !== next + && (KEY_ACCOUNT_LOG_LABEL_RE.test(previous ?? "") || KEY_ACCOUNT_LOG_LABEL_RE.test(next ?? ""))) { + // An input estimate is not evidence that a failed send used that many tokens. + delete attempt.inputTokenEstimate; + finishRequestAttempt(attempt, attempt.status >= 100 ? attempt.status + : recovery === "key-401" ? 401 : recovery?.includes("429") ? 429 : 502, + Date.now() - (logCtx.activeAttemptStartedAt ?? Date.now()), attempt.usage); + const completed = { ...attempt, recoveryKinds: [...attempt.recoveryKinds], + ...(attempt.usage ? { usage: { ...attempt.usage } } : {}), + ...(attempt.tierOutcome ? { tierOutcome: { ...attempt.tierOutcome } } : {}) }; + const attempts = logCtx.attempts ??= [attempt]; + const index = attempts.indexOf(attempt); + if (index >= 0) attempts.splice(index, 0, completed); + else attempts.push(completed, attempt); + const fresh = beginRequestAttempt(completed.ordinal + 1, providerName, completed.model, completed.adapter); + // Effort/tier metadata describes the request and is captured before the physical send. + for (const key of ["requestedEffort", "effectiveEffort", "reasoningWireField", "reasoningWireValue", "tierOutcome"] as const) { + if (completed[key] !== undefined) Object.assign(fresh, { [key]: completed[key] }); + } + for (const key of Object.keys(attempt)) delete (attempt as unknown as Record)[key]; + Object.assign(attempt, fresh); + delete logCtx.usage; + logCtx.activeAttemptStartedAt = Date.now(); + } + if (attempt) { + sealRequestAttemptIdentity(attempt, logCtx.provider, attempt.adapter, next); + recordAttemptCredentialSource(attempt, providerName, provider, attempt.adapter); + } + noteAttemptSend(attempt, inputTokenEstimate, recovery); + if (attempt && keyUsageOwners.has(attempt)) { + keyWireUsageBaselines.set(attempt, cloneKeyUsage(attempt.usage)); + } } /** Capture only the resolved upstream route; inbound auth and today's config cannot label old usage. */ diff --git a/src/server/responses/adapter-continuation.ts b/src/server/responses/adapter-continuation.ts index 325833c20a..6d4ffcfb43 100644 --- a/src/server/responses/adapter-continuation.ts +++ b/src/server/responses/adapter-continuation.ts @@ -10,7 +10,6 @@ import type { AdapterRequest } from "../../adapters/base"; import { recordAdapterReasoning, recordAdapterTier, - noteAttemptSend, sealRequestAttemptIdentity, recordAttemptCredentialSource, } from "../request-log"; @@ -78,6 +77,7 @@ export function createAdapterContinuations( | "genericFailoverAccountId" | "genericFailovers" | "applyFailoverSnapshot" + | "noteRoutedAttemptSend" >, sidecarState: Pick, sendBudgetState: Pick< @@ -185,7 +185,7 @@ export function createAdapterContinuations( const replayKind: AttemptRecoveryKind | undefined = recoveryKind; try { if (transportState.activeAdapter.fetchResponse) { - noteAttemptSend(logCtx.activeAttempt, continuationEstimate, replayKind); + transportState.noteRoutedAttemptSend(continuationEstimate, replayKind); await waitForProviderRequestSlot(route.providerName, route.provider, nextParsed.modelId, upstream.signal); return await transportState.activeAdapter.fetchResponse(builtContinuationRequest, { abortSignal: upstream.signal, @@ -194,6 +194,7 @@ export function createAdapterContinuations( onPhysicalSend: send => noteAdapterPhysicalSend(continuationEstimate, send), stream: nextParsed.stream, executor: providerFetch(route.provider, options.codexWsRuntimeIdentity, { + pacingSlotAcquired: true, dispatchOverride: oauthDispatch(builtContinuationRequest, nextParsed), providerName: route.providerName, modelId: nextParsed.modelId, @@ -208,7 +209,7 @@ export function createAdapterContinuations( : fetchWithResetRetry; return await fetchContinuationWithRetryPolicy( recovery => { - noteAttemptSend(logCtx.activeAttempt, continuationEstimate, recovery ?? replayKind); + transportState.noteRoutedAttemptSend(continuationEstimate, recovery ?? replayKind); return fetchWithHeaderTimeout( builtContinuationRequest.url, applyUpstreamRecoveryInit({ diff --git a/src/server/responses/adapter-delivery.ts b/src/server/responses/adapter-delivery.ts index a46d1faf8b..3f6330b6c4 100644 --- a/src/server/responses/adapter-delivery.ts +++ b/src/server/responses/adapter-delivery.ts @@ -26,7 +26,7 @@ export async function deliverAdapterResponse( | "rememberKiroDeliveredFinalAnswer" | "responseStateOptions" >, - transportState: Pick, + transportState: Pick, sidecarState: Pick, responseEffects: Pick< ResponsesEffects, @@ -106,11 +106,7 @@ export async function deliverAdapterResponse( ...(logCtx.surface === "grok" ? { heartbeatStyle: "comment" as const } : {}), onUsage: usage => { // Raw adapter usage, pre wire-normalization (see the runTurn branch above). - logCtx.usageFromBridge = true; - if (usage) { - logCtx.usage = usage; - if (logCtx.activeAttempt) logCtx.activeAttempt.usage = usage; - } + transportState.bindKeyUsageFromBridge(usage); }, onCompletedResponse: (response: Record, providerState?: OcxProviderContinuationState) => { commitReasoningReplayServingRoute(); @@ -184,11 +180,7 @@ export async function deliverAdapterResponse( ...(routedCompaction ? { compaction: true } : {}), onProviderState: state => { providerState = state; }, onUsage: usage => { - logCtx.usageFromBridge = true; - if (usage) { - logCtx.usage = usage; - if (logCtx.activeAttempt) logCtx.activeAttempt.usage = usage; - } + transportState.bindKeyUsageFromBridge(usage); }, }); // See the streaming branch: compaction turns skip the continuation cache. diff --git a/src/server/responses/adapter-dispatch.ts b/src/server/responses/adapter-dispatch.ts index 99a0683439..33135cf75a 100644 --- a/src/server/responses/adapter-dispatch.ts +++ b/src/server/responses/adapter-dispatch.ts @@ -11,7 +11,6 @@ import { trackStreamLifetime } from "../lifecycle"; import { recordAdapterReasoning, recordAdapterTier, - noteAttemptSend, sealRequestAttemptIdentity, recordAttemptCredentialSource, } from "../request-log"; @@ -120,6 +119,7 @@ export async function prepareAdapterExchange( | "genericFailoverAccountId" | "genericFailovers" | "applyFailoverSnapshot" + | "noteRoutedAttemptSend" >, responseEffects: Pick, sendBudgetState: Pick< @@ -278,7 +278,7 @@ export async function prepareAdapterExchange( let upstreamResponse: Response; try { if (transportState.activeAdapter.fetchResponse) { - noteAttemptSend(logCtx.activeAttempt, inputTokenEstimate); + transportState.noteRoutedAttemptSend(inputTokenEstimate); await waitForProviderRequestSlot(route.providerName, route.provider, route.modelId, upstream.signal); upstreamResponse = await transportState.activeAdapter.fetchResponse(builtInitialRequest, { abortSignal: upstream.signal, @@ -287,6 +287,7 @@ export async function prepareAdapterExchange( onPhysicalSend: send => noteAdapterPhysicalSend(inputTokenEstimate, send), stream: parsed.stream, executor: providerFetch(route.provider, options.codexWsRuntimeIdentity, { + pacingSlotAcquired: true, dispatchOverride: oauthDispatch(builtInitialRequest), providerName: route.providerName, modelId: route.modelId, @@ -306,7 +307,7 @@ export async function prepareAdapterExchange( : fetchWithResetRetry; upstreamResponse = await fetchWithRetryPolicy( recovery => { - noteAttemptSend(logCtx.activeAttempt, inputTokenEstimate, recovery); + transportState.noteRoutedAttemptSend(inputTokenEstimate, recovery); return fetchWithHeaderTimeout(builtInitialRequest.url, applyUpstreamRecoveryInit({ method: builtInitialRequest.method, headers: builtInitialRequest.headers, @@ -425,7 +426,7 @@ export async function prepareAdapterExchange( logCtx.providerAdapter = transportState.activeAdapter.name; sealRequestAttemptIdentity(logCtx.activeAttempt, logCtx.provider, transportState.activeAdapter.name, logCtx.accountLogLabel); recordAttemptCredentialSource(logCtx.activeAttempt, route.providerName, route.provider, transportState.activeAdapter.name); - noteAttemptSend(logCtx.activeAttempt, retryEstimate, recovery); + transportState.noteRoutedAttemptSend(retryEstimate, recovery); try { try { if (transportState.activeAdapter.fetchResponse) { @@ -442,6 +443,7 @@ export async function prepareAdapterExchange( onPhysicalSend: send => noteAdapterPhysicalSend(retryEstimate, send), stream: parsed.stream, executor: providerFetch(route.provider, options.codexWsRuntimeIdentity, { + pacingSlotAcquired: true, dispatchOverride: oauthDispatch(retryRequest), providerName: route.providerName, modelId: route.modelId, diff --git a/src/server/responses/collaboration.ts b/src/server/responses/collaboration.ts index ab6a9b55c9..60b6661936 100644 --- a/src/server/responses/collaboration.ts +++ b/src/server/responses/collaboration.ts @@ -83,7 +83,6 @@ import { catalogModelSupportsServiceTier, finishRequestAttempt, inspectResponseLogJson, - noteAttemptSend, readConfiguredCodexServiceTier, requestLogSpeedLabel, sealRequestAttemptIdentity, diff --git a/src/server/responses/compact.ts b/src/server/responses/compact.ts index 6b5b979d37..77082bfe00 100644 --- a/src/server/responses/compact.ts +++ b/src/server/responses/compact.ts @@ -140,7 +140,6 @@ import { catalogModelSupportsServiceTier, finishRequestAttempt, inspectResponseLogJson, - noteAttemptSend, readConfiguredCodexServiceTier, requestLogSpeedLabel, sealRequestAttemptIdentity, diff --git a/src/server/responses/core-codex-account.ts b/src/server/responses/core-codex-account.ts index 5d0fc50109..f84f83db68 100644 --- a/src/server/responses/core-codex-account.ts +++ b/src/server/responses/core-codex-account.ts @@ -66,7 +66,7 @@ import { recordAdapterTier, sealRequestAttemptIdentity, recordAttemptCredentialSource, - noteAttemptSend, + noteProviderAttemptSend, } from "../request-log"; import { codexAuthContextLogLabel } from "../../codex/account-label"; import { chargeWorkflowSends } from "../../lib/workflow-budget"; @@ -702,7 +702,7 @@ export async function retryCodexPoolOnAlternateAccount( // The move is a physical send like any other, so the root workflow is charged too. chargeWorkflowSends(args.options.workflowRootId, 1); } - noteAttemptSend(logCtx.activeAttempt, passthroughEstimate); + noteProviderAttemptSend(logCtx, route.providerName, route.provider, passthroughEstimate); try { upstreamResponse = await fetchWithHeaderTimeout( request.url, diff --git a/src/server/responses/core-combo.ts b/src/server/responses/core-combo.ts index 1db4b9d0bf..6a573e4907 100644 --- a/src/server/responses/core-combo.ts +++ b/src/server/responses/core-combo.ts @@ -452,6 +452,9 @@ export async function executeComboResponses( childLog.requestedEffort = originalRequestedEffort; recordAttemptRequestedEffort(childLog); } + childLog.activeAttemptStartedAt = started; + childLog.attempts = logCtx.attempts ??= []; + childLog.attempts.push(attempt); let attemptRetained = false; const retainCancelledAttempt = (): void => { if (attemptRetained) return; @@ -462,7 +465,6 @@ export async function executeComboResponses( childLog.accountLogLabel, ); finishRequestAttempt(attempt, 499, Date.now() - started, childLog.usage); - (logCtx.attempts ??= []).push(attempt); attemptRetained = true; }; const completedTarget = { provider: pick.target.provider, model: pick.target.model }; @@ -533,6 +535,7 @@ export async function executeComboResponses( retainCancelledAttempt(); return clientCancelledResponse(); } + finishRequestAttempt(attempt, 502, Date.now() - started, childLog.usage); throw error; } @@ -554,6 +557,7 @@ export async function executeComboResponses( retainCancelledAttempt(); return clientCancelledResponse(); } + finishRequestAttempt(attempt, 502, Date.now() - started, childLog.usage); throw error; } if (preflight.kind === "failed") { @@ -574,7 +578,6 @@ export async function executeComboResponses( childLog.providerAdapter ?? attempt.adapter, childLog.accountLogLabel, ); - (logCtx.attempts ??= []).push(attempt); attemptRetained = true; noteComboSuccess(comboId, combo, pick.target, pick.writerGeneration); Object.assign(logCtx, childLog, { @@ -608,6 +611,7 @@ export async function executeComboResponses( retainCancelledAttempt(); return clientCancelledResponse(); } + finishRequestAttempt(attempt, 502, Date.now() - started, childLog.usage); throw error; } if (options.abortSignal?.aborted) { @@ -626,7 +630,6 @@ export async function executeComboResponses( Date.now() - started, failure.usage, ); - (logCtx.attempts ??= []).push(attempt); attemptRetained = true; lastFailure = failure.response; lastFailedChildLog = childLog; diff --git a/src/server/responses/encrypted-payload.ts b/src/server/responses/encrypted-payload.ts index 066bb9b522..0e9efddf99 100644 --- a/src/server/responses/encrypted-payload.ts +++ b/src/server/responses/encrypted-payload.ts @@ -78,7 +78,6 @@ import { catalogModelSupportsServiceTier, finishRequestAttempt, inspectResponseLogJson, - noteAttemptSend, readConfiguredCodexServiceTier, requestLogSpeedLabel, sealRequestAttemptIdentity, diff --git a/src/server/responses/passthrough-dispatch.ts b/src/server/responses/passthrough-dispatch.ts index f5c5b94694..0292f1d77a 100644 --- a/src/server/responses/passthrough-dispatch.ts +++ b/src/server/responses/passthrough-dispatch.ts @@ -60,7 +60,6 @@ import { restorePlaintextV2AgentMessageCalls } from "../../responses/plaintext-v import { recordAdapterReasoning, recordAdapterTier, - noteAttemptSend, sealRequestAttemptIdentity, recordAttemptCredentialSource, } from "../request-log"; @@ -171,6 +170,7 @@ export async function preparePassthroughExchange( | "replayOAuthCredentialSnapshot" | "genericFailovers" | "applyFailoverSnapshot" + | "noteRoutedAttemptSend" >, responseEffects: Pick< ResponsesEffects, @@ -752,7 +752,7 @@ export async function preparePassthroughExchange( // Body is a replayable string; nothing has streamed to the client yet. upstreamResponse = await fetchWithTransientRetry( recovery => { - noteAttemptSend(logCtx.activeAttempt, passthroughEstimate, recovery); + transportState.noteRoutedAttemptSend(passthroughEstimate, recovery); return fetchWithHeaderTimeout(request.url, applyUpstreamRecoveryInit({ method: request.method, headers: request.headers, @@ -848,7 +848,7 @@ export async function preparePassthroughExchange( if (allowance.permit && !allowance.permit.use()) { throw new SendBudgetExhaustedError(safeHostLabel(request.url)); } - noteAttemptSend(logCtx.activeAttempt, passthroughEstimate, innerRecovery ?? recovery); + transportState.noteRoutedAttemptSend(passthroughEstimate, innerRecovery ?? recovery); return fetchWithHeaderTimeout(request.url, applyUpstreamRecoveryInit({ method: request.method, headers: request.headers, @@ -946,7 +946,7 @@ export async function preparePassthroughExchange( // every other build site; a replay is exactly when a grown payload reappears. const replayBodyRefusal = refuseOversizedOutboundBody(request); if (replayBodyRefusal) return replayBodyRefusal; - noteAttemptSend(logCtx.activeAttempt, passthroughEstimate, "oauth-401"); + transportState.noteRoutedAttemptSend(passthroughEstimate, "oauth-401"); upstreamResponse = await fetchWithHeaderTimeout( request.url, { method: request.method, headers: request.headers, body: request.body }, @@ -1075,7 +1075,7 @@ export async function preparePassthroughExchange( try { upstreamResponse = await fetchWithTransientRetry( recovery => { - noteAttemptSend(logCtx.activeAttempt, passthroughEstimate, recovery ?? "oauth-401"); + transportState.noteRoutedAttemptSend(passthroughEstimate, recovery ?? "oauth-401"); return fetchWithHeaderTimeout(request.url, applyUpstreamRecoveryInit({ method: request.method, headers: request.headers, @@ -1192,7 +1192,7 @@ export async function preparePassthroughExchange( recovery => { // The first send of every replay is itself a rate-limit retry; inner transient-5xx // recoveries keep their own label (recovery is provided for those). - noteAttemptSend(logCtx.activeAttempt, passthroughEstimate, recovery ?? "rate-limit-429"); + transportState.noteRoutedAttemptSend(passthroughEstimate, recovery ?? "rate-limit-429"); return fetchWithHeaderTimeout(request.url, applyUpstreamRecoveryInit({ method: request.method, headers: request.headers, diff --git a/src/server/responses/request-send-budget.ts b/src/server/responses/request-send-budget.ts index 41bf5d64d6..897f87f9fe 100644 --- a/src/server/responses/request-send-budget.ts +++ b/src/server/responses/request-send-budget.ts @@ -58,7 +58,7 @@ export function createResponsesSendBudget( /** * Records an adapter's OWN inner retries against this attempt. * - * Ordinal 1 is the send each call site already recorded through `noteAttemptSend`, so only + * Ordinal 1 is the send each call site already recorded through `noteRoutedAttemptSend`, so only * the extra physical sends are added here and an adapter that does not retry internally * leaves its log byte-for-byte as it was. Kiro reaches roughly eighteen sends per call and * Cursor re-sends a whole turn, and both reported one; a count that cannot be observed diff --git a/src/server/responses/request-transport.ts b/src/server/responses/request-transport.ts index c80f242121..c5b92a177d 100644 --- a/src/server/responses/request-transport.ts +++ b/src/server/responses/request-transport.ts @@ -8,7 +8,7 @@ import { credentialGeneration, } from "../../oauth/store"; import type { ProviderAdapter, AdapterRequest } from "../../adapters/base"; -import type { OcxParsedRequest, OcxProviderConfig } from "../../types"; +import type { AdapterEvent, OcxParsedRequest, OcxProviderConfig, OcxUsage } from "../../types"; import type { AnthropicAccountSelectionReason } from "../../oauth/anthropic-routing"; import { isAnthropicAccountPoolEnabled, @@ -33,7 +33,7 @@ import { preferredInitialAccount, noteGenericPoolSelection, } from "../../oauth/generic-account-failover"; -import { stampOAuthAccountLabel } from "../../providers/label"; +import { stampOAuthAccountLabel, usesApiKeyAccount } from "../../providers/label"; import { resolveProviderTransport } from "../../providers/xai-transport"; import { resolveCopilotApiBaseUrl } from "../../oauth/github-copilot"; import { @@ -59,7 +59,11 @@ import { sealRequestAttemptIdentity, recordAttemptCredentialSource, recordAdapterTierMetadata, + noteProviderAttemptSend, + recordKeyAttemptFailure, + recordKeyAttemptUsage, } from "../request-log"; +import type { AttemptRecoveryKind } from "../../usage/log"; import { resolvePassiveRouteSubjectId } from "../passive-route-linker"; /** Owns live credential selection and adapter bindings for one request. */ @@ -241,6 +245,30 @@ export async function prepareResponsesTransport( replayOAuthCredentialSnapshot = { accountId: snapshot.accountId, generation: snapshot.generation }; return true; }; + // Key sends may be rebuilt while queued. Keep metadata pending until the guarded + // physical dispatch binds it to the selection that actually reaches the upstream. + let pendingKeySend: { estimate: number | undefined; recovery?: AttemptRecoveryKind } | undefined; + const noteRoutedAttemptSend = (estimate: number | undefined, recovery?: AttemptRecoveryKind): void => { + if (usesApiKeyAccount(route.provider)) pendingKeySend = { estimate, recovery }; + else noteProviderAttemptSend(logCtx, route.providerName, route.provider, estimate, recovery); + }; + const commitKeyAttemptSend = (): void => { + if (!usesApiKeyAccount(route.provider)) return; + noteProviderAttemptSend(logCtx, route.providerName, route.provider, + pendingKeySend?.estimate ?? logCtx.usageLogInputTokens, pendingKeySend?.recovery); + pendingKeySend = undefined; + }; + const bindKeyUsageFromBridge = (usage: OcxUsage | undefined): void => { + logCtx.usageFromBridge = true; + if (usesApiKeyAccount(route.provider)) { + logCtx.usage = logCtx.activeAttempt?.usage; + return; + } + if (usage) { + logCtx.usage = usage; + if (logCtx.activeAttempt) logCtx.activeAttempt.usage = usage; + } + }; const selectionIsCurrent = (binding: DispatchBinding | undefined): boolean => { if (route.provider.authMode === "forward") return true; if (!binding) return false; @@ -260,6 +288,27 @@ export async function prepareResponsesTransport( : undefined : { kind: "api-key", provider: { ...route.provider } }; if (binding) adapterBindings.set(resolved, binding); + // Observe terminals before search/image loops or continuation guards hide earlier rounds. + // Each adapter parser is called once per physical response; bridge totals are client-only. + const observedResponses = new WeakSet(); + const observeUsage = (event: AdapterEvent, response: object): void => { + if (usesApiKeyAccount(provider) && "usage" in event && event.usage && !observedResponses.has(response)) { + observedResponses.add(response); + recordKeyAttemptUsage(logCtx, event.usage); + } + }; + const parseStream = resolved.parseStream.bind(resolved); + resolved.parseStream = async function* (...args) { + for await (const event of parseStream(...args)) { observeUsage(event, args[0]); yield event; } + }; + if (resolved.parseResponse) { + const parseResponse = resolved.parseResponse.bind(resolved); + resolved.parseResponse = async (...args) => { + const events = await parseResponse(...args); + events.forEach(event => observeUsage(event, args[0])); + return events; + }; + } const build = resolved.buildRequest.bind(resolved); resolved.buildRequest = async (requestParsed, incoming) => { const request = await build(requestParsed, incoming); @@ -268,7 +317,11 @@ export async function prepareResponsesTransport( return request; }; if (resolved.runTurn) { - rawRunTurns.set(resolved, resolved.runTurn.bind(resolved)); + const runTurn = resolved.runTurn.bind(resolved); + rawRunTurns.set(resolved, (requestParsed, incoming, emit) => { + const response = {}; + return runTurn(requestParsed, incoming, event => { observeUsage(event, response); emit(event); }); + }); resolved.runTurn = (requestParsed, incoming, emit) => runSelectedTurn(resolved, requestParsed, incoming, emit); } return resolved; @@ -319,6 +372,7 @@ export async function prepareResponsesTransport( refused = true; throw new Error("Account selection changed before the first turn dispatch"); } + commitKeyAttemptSend(); sent = true; }, }); @@ -351,7 +405,9 @@ export async function prepareResponsesTransport( && sentHeaders?.get("authorization") === `Bearer ${snapshot.accessToken}` && !sentHeaders?.has("x-api-key"); // Reselection can choose a provider override instead of the supplied executor. + commitKeyAttemptSend(); const response = await fetchImpl(destination, { ...dispatchInit, redirect: "manual" }); + if (!response.ok) await recordKeyAttemptFailure(logCtx, response, dispatchInit.signal ?? options.abortSignal); // Observe each physical response before retries replace it. The binding belongs to // this dispatch, so a manual switch cannot file A's headers against B. Header // overrides and credential replacement make ownership unprovable: skip those writes. @@ -736,6 +792,9 @@ export async function prepareResponsesTransport( resolveSelectionAdapter, refreshRunTurnAdapter, oauthDispatch, + noteRoutedAttemptSend, + commitKeyAttemptSend, + bindKeyUsageFromBridge, anthropicSessionKey, isPassthrough, }; diff --git a/src/server/responses/run-turn-execution.ts b/src/server/responses/run-turn-execution.ts index 1bd962e628..20524edd3a 100644 --- a/src/server/responses/run-turn-execution.ts +++ b/src/server/responses/run-turn-execution.ts @@ -12,7 +12,7 @@ import { adapterNeedsForcedContinuation, adapterResponseReachedServingTerminal, } from "./core-replay"; -import { sealRequestAttemptIdentity, noteAttemptSend, recordAttemptCredentialSource } from "../request-log"; +import { sealRequestAttemptIdentity, recordAttemptCredentialSource } from "../request-log"; import { waitForProviderRequestSlot, RequestPacingQueueOverloadError } from "../../providers/request-pacing"; import type { AdapterEventQueue } from "../../adapters/run-turn-queue"; import type { AttemptRecoveryKind } from "../../usage/log"; @@ -66,6 +66,8 @@ export async function executeResponsesRunTurn( | "applyFailoverSnapshot" | "resolveSelectionAdapter" | "adapter" + | "noteRoutedAttemptSend" + | "bindKeyUsageFromBridge" >, sidecarState: Pick, responseEffects: Pick< @@ -144,7 +146,7 @@ export async function executeResponsesRunTurn( await waitForProviderRequestSlot(route.providerName, route.provider, route.modelId, runTurnAbort.signal); } await refreshRunTurnSelection(); - noteAttemptSend(logCtx.activeAttempt, logCtx.usageLogInputTokens, recovery); + transportState.noteRoutedAttemptSend(logCtx.usageLogInputTokens, recovery); const runTurnProviderFetch = providerFetch( route.provider, options.codexWsRuntimeIdentity, @@ -381,11 +383,7 @@ export async function executeResponsesRunTurn( onUsage: usage => { // Raw adapter usage, pre wire-normalization: the bridged SSE now always carries // zero-default detail objects, so provenance must come from here (cache_detail_missing). - logCtx.usageFromBridge = true; - if (usage) { - logCtx.usage = usage; - if (logCtx.activeAttempt) logCtx.activeAttempt.usage = usage; - } + transportState.bindKeyUsageFromBridge(usage); }, onCompletedResponse: (response: Record, providerState?: OcxProviderContinuationState) => { commitReasoningReplayServingRoute(); @@ -452,11 +450,7 @@ export async function executeResponsesRunTurn( ...(routedCompaction ? { compaction: true } : {}), onProviderState: state => { providerState = state; }, onUsage: usage => { - logCtx.usageFromBridge = true; - if (usage) { - logCtx.usage = usage; - if (logCtx.activeAttempt) logCtx.activeAttempt.usage = usage; - } + transportState.bindKeyUsageFromBridge(usage); }, }); if (!routedCompaction) { diff --git a/src/server/responses/sidecar-execution.ts b/src/server/responses/sidecar-execution.ts index 7987d5ca93..7aeb9d452d 100644 --- a/src/server/responses/sidecar-execution.ts +++ b/src/server/responses/sidecar-execution.ts @@ -35,7 +35,7 @@ import { bindRouteReasoningReplayScope, adapterNeedsForcedContinuation } from ". import { namespacedToolName } from "../../types"; import { providerFetch } from "./fetch-helpers"; import type { AttemptRecoveryKind } from "../../usage/log"; -import { noteAttemptSend, recordAdapterReasoning, recordAdapterTier } from "../request-log"; +import { recordAdapterReasoning, recordAdapterTier } from "../request-log"; import { normalizeLogConversationId } from "../request-log-conversation"; import { rememberResponseState } from "../../responses/state"; import { trackStreamLifetime } from "../lifecycle"; @@ -65,6 +65,8 @@ export async function executeResponsesSidecars( | "commitResolvedOAuthSelection" | "resolveSelectionAdapter" | "oauthDispatch" + | "noteRoutedAttemptSend" + | "bindKeyUsageFromBridge" >, sidecarState: Pick, responseEffects: Pick< @@ -322,7 +324,7 @@ export async function executeResponsesSidecars( ...(vidPlan ? { videoPlan: vidPlan } : {}), forwardHeaders: requestState.selectedForwardHeaders, onAttemptSend: (recovery?: AttemptRecoveryKind) => - noteAttemptSend(logCtx.activeAttempt, logCtx.usageLogInputTokens, recovery), + transportState.noteRoutedAttemptSend(logCtx.usageLogInputTokens, recovery), abortSignal: options.abortSignal, maxRounds: imgPlan && vidPlan ? clampImageMaxRounds(Math.min(config.images?.maxRounds ?? 3, config.images?.videoMaxRounds ?? 2)) @@ -352,11 +354,7 @@ export async function executeResponsesSidecars( if (!logCtx.conversationId && parsed._cursorConversationId) { logCtx.conversationId = normalizeLogConversationId(parsed._cursorConversationId); } - logCtx.usageFromBridge = true; - if (usage) { - logCtx.usage = usage; - if (logCtx.activeAttempt) logCtx.activeAttempt.usage = usage; - } + transportState.bindKeyUsageFromBridge(usage); }, on429: rotateSidecarProviderOn429, retryOn429Policy: rateLimitRetryPolicyFor(route.provider), @@ -432,13 +430,9 @@ export async function executeResponsesSidecars( recordAdapterTier(logCtx, request); }, onAttemptSend: (recovery?: AttemptRecoveryKind) => - noteAttemptSend(logCtx.activeAttempt, logCtx.usageLogInputTokens, recovery), + transportState.noteRoutedAttemptSend(logCtx.usageLogInputTokens, recovery), onUsage: usage => { - logCtx.usageFromBridge = true; - if (usage) { - logCtx.usage = usage; - if (logCtx.activeAttempt) logCtx.activeAttempt.usage = usage; - } + transportState.bindKeyUsageFromBridge(usage); }, recordSidecarOutcome: wsPlan.forwardSidecar?.recordOutcome, connectTimeoutMs: config.connectTimeoutMs ?? 200_000, diff --git a/src/usage/log.ts b/src/usage/log.ts index de03cbf752..aadeb1648b 100644 --- a/src/usage/log.ts +++ b/src/usage/log.ts @@ -38,7 +38,7 @@ export type UsageStatus = "reported" | "unreported" | "unsupported" | "estimated * The old name `CodexUsageAccountLogLabel` is kept as an alias because it is exported and used * across modules; the two predicates below are what callers should choose between. */ -export type UsageAccountLogLabel = "main" | `p${string}` | `o${string}`; +export type UsageAccountLogLabel = "main" | `p${string}` | `o${string}` | `k${string}`; export type CodexUsageAccountLogLabel = UsageAccountLogLabel; /** diff --git a/structure/adapters/registry.md b/structure/adapters/registry.md index 83e8f4f466..6714c77665 100644 --- a/structure/adapters/registry.md +++ b/structure/adapters/registry.md @@ -99,7 +99,7 @@ so the schema is not something a user can fix from configuration (issue #2673). > Decision record: [ADR-0093](../decisions/ADR-0093-moonshot-ref-with-siblings-normalization.md) -Usage consumers preserve positive incomplete-history metadata as specified in [usage accounting](../gui-and-management-api.md#usage-accounting); readable totals are not represented as a complete ledger. +Usage consumers preserve positive incomplete-history metadata as specified in [usage accounting](../gui-and-management-api.md#usage-accounting); readable totals are not represented as a complete ledger. Upstream API-key usage follows the [physical-attempt account attribution contract](../gui-and-management-api.md#upstream-key-account-attribution), independently of subscription quota observations. Connected CLI usage follows the [client-scoped hub usage contract](../gui-and-management-api.md#usage-accounting); local management and account data remain separate. diff --git a/structure/catalog.md b/structure/catalog.md index bf9d6e3751..2167718056 100644 --- a/structure/catalog.md +++ b/structure/catalog.md @@ -345,7 +345,7 @@ spelling; the V1 and compaction cap exemptions are preserved. Codex display-cache expiry, retained main-policy evidence, and reset history follow the [quota cache contract](providers/openai-tiers.md#quota-cache-and-short-window-history). -Usage consumers preserve positive incomplete-history metadata as specified in [usage accounting](gui-and-management-api.md#usage-accounting); readable totals are not represented as a complete ledger. +Usage consumers preserve positive incomplete-history metadata as specified in [usage accounting](gui-and-management-api.md#usage-accounting); readable totals are not represented as a complete ledger. Upstream API-key usage follows the [physical-attempt account attribution contract](gui-and-management-api.md#upstream-key-account-attribution), independently of subscription quota observations. Connected CLI usage follows the [client-scoped hub usage contract](gui-and-management-api.md#usage-accounting); local management and account data remain separate. diff --git a/structure/clients/claude-desktop.md b/structure/clients/claude-desktop.md index 01a583c182..11e62f4e17 100644 --- a/structure/clients/claude-desktop.md +++ b/structure/clients/claude-desktop.md @@ -101,7 +101,7 @@ testable on any host: stubbing `process.platform` does not propagate to `os.plat > Decision record: [ADR-0046](../decisions/ADR-0046-claude-desktop-config-library-resolution.md) -Usage consumers preserve positive incomplete-history metadata as specified in [usage accounting](../gui-and-management-api.md#usage-accounting); readable totals are not represented as a complete ledger. +Usage consumers preserve positive incomplete-history metadata as specified in [usage accounting](../gui-and-management-api.md#usage-accounting); readable totals are not represented as a complete ledger. Upstream API-key usage follows the [physical-attempt account attribution contract](../gui-and-management-api.md#upstream-key-account-attribution), independently of subscription quota observations. Connected CLI usage follows the [client-scoped hub usage contract](../gui-and-management-api.md#usage-accounting); local management and account data remain separate. diff --git a/structure/codex-home.md b/structure/codex-home.md index 339358ea9b..bdacb4ed9c 100644 --- a/structure/codex-home.md +++ b/structure/codex-home.md @@ -275,3 +275,5 @@ Pool quota producers and account commands follow the [bounded raw-observation co The account history response can include a [low-confidence effective capacity estimate](providers/openai-tiers.md#observed-effective-token-capacity); usage normalization retains local-answer provenance so local responses cannot supply samples. Codex pool settings and their consumers follow the [reset-first ordering contract](providers/openai-tiers.md#reset-first-account-ordering), including independent-quota fallback and preserved affinity. + +Upstream API-key usage follows the [physical-attempt account attribution contract](gui-and-management-api.md#upstream-key-account-attribution), independently of subscription quota observations. diff --git a/structure/config.md b/structure/config.md index d00b36b06b..41515893d7 100644 --- a/structure/config.md +++ b/structure/config.md @@ -269,7 +269,7 @@ The unregistered executor CLI module stores Remote Workspace state separately fr Remote Workspace uses a separate, explicitly enabled server surface with structural WebSocket callbacks and awaited per-server cleanup; [its contract](remote-workspace.md) owns that integration. -Usage consumers preserve positive incomplete-history metadata as specified in [usage accounting](gui-and-management-api.md#usage-accounting); readable totals are not represented as a complete ledger. +Usage consumers preserve positive incomplete-history metadata as specified in [usage accounting](gui-and-management-api.md#usage-accounting); readable totals are not represented as a complete ledger. Upstream API-key usage follows the [physical-attempt account attribution contract](gui-and-management-api.md#upstream-key-account-attribution), independently of subscription quota observations. `dropCodexSafetyBuffering` is an optional boolean, default false. Invalid API candidates reject; malformed persisted values stay disabled. It controls only the allowlisted client-output hints diff --git a/structure/data-planes/images.md b/structure/data-planes/images.md index a7420072bf..a73fcc6f07 100644 --- a/structure/data-planes/images.md +++ b/structure/data-planes/images.md @@ -84,7 +84,7 @@ conflicts with `modelSupportsReasoningSummaries: false` for the same model. > Decision record: [ADR-0045](../decisions/ADR-0045-standalone-images.md) -Usage consumers preserve positive incomplete-history metadata as specified in [usage accounting](../gui-and-management-api.md#usage-accounting); readable totals are not represented as a complete ledger. +Usage consumers preserve positive incomplete-history metadata as specified in [usage accounting](../gui-and-management-api.md#usage-accounting); readable totals are not represented as a complete ledger. Upstream API-key usage follows the [physical-attempt account attribution contract](../gui-and-management-api.md#upstream-key-account-attribution), independently of subscription quota observations. Connected CLI usage follows the [client-scoped hub usage contract](../gui-and-management-api.md#usage-accounting); local management and account data remain separate. diff --git a/structure/data-planes/inbound-compat.md b/structure/data-planes/inbound-compat.md index 33ca8c76b0..0e1a030e94 100644 --- a/structure/data-planes/inbound-compat.md +++ b/structure/data-planes/inbound-compat.md @@ -183,7 +183,7 @@ reasoning ladder into `thinking.effortOptions`. Missing capabilities stay absent falling back to OpenCodex guesses, and the integration does not write the removed `thinking.effort` / `defaultEffort` fields because MCode owns the active effort per session. -Usage consumers preserve positive incomplete-history metadata as specified in [usage accounting](../gui-and-management-api.md#usage-accounting); readable totals are not represented as a complete ledger. +Usage consumers preserve positive incomplete-history metadata as specified in [usage accounting](../gui-and-management-api.md#usage-accounting); readable totals are not represented as a complete ledger. Upstream API-key usage follows the [physical-attempt account attribution contract](../gui-and-management-api.md#upstream-key-account-attribution), independently of subscription quota observations. Connected CLI usage follows the [client-scoped hub usage contract](../gui-and-management-api.md#usage-accounting); local management and account data remain separate. diff --git a/structure/gui-and-management-api.md b/structure/gui-and-management-api.md index 4628ca5e50..5f01edbc8d 100644 --- a/structure/gui-and-management-api.md +++ b/structure/gui-and-management-api.md @@ -367,6 +367,26 @@ keeps the saved state and renders fixed `ocx sync` guidance without server/accou ## Usage accounting +### Upstream key account attribution + +API-key attempts in `src/usage/log.ts` carry `accountLogLabel` as `k` plus 32 lowercase +hex digits. `src/codex/account-label.ts` derives it from the first 128 bits of SHA-256 over +`JSON.stringify(["ocx-key-account-v1", providerName, entryId ?? null, reference])`. +`reference` is the configured value captured for the physical send, before environment or +keychain resolution. The log contains the digest, not raw keys, references, or pool IDs. +Existing Codex and OAuth label formats remain valid. Replacing a literal or reference changes +identity; rotating the secret behind the same reference preserves the logical account. + +`src/providers/label.ts` stamps only key authentication, including implicit custom-provider +keys. `src/server/request-log.ts` commits identity at dispatch after queued selection changes, +retains separate flat records when retries change keys, and isolates each record's raw usage +from parent combo totals and adapter-loop aggregation. Reported failure usage is retained; +missing usage and historical identities remain unknown. Native wire snapshots replace only the +current physical response contribution, preserving prior sends on the same key without counting +repeated inspections twice. Consumers sum the flat attempts once and keep subscription quota +observations separate from token or API-equivalent cost totals. + + `src/server/hub-usage.ts` serves `GET /v1/usage` on hubs for an explicit configured data key. The authenticated key selects the aggregate; query parameters cannot select an API-key identity. Unscoped environment/admin credentials and loopback bypass are not admitted. The response projects only this client's numeric totals, provider/model/day rows and incomplete-history metadata through `src/remote/hub-usage.ts`; accounts, raw records and key IDs are omitted. Unknown fields are stripped at every object boundary and the serialized body is capped at 1 MiB. Custom usage windows are immutable bounds on the streaming accumulator, applied to each diff --git a/structure/ops/docs-and-release.md b/structure/ops/docs-and-release.md index 0c0ffe38d0..9a2f6f27d3 100644 --- a/structure/ops/docs-and-release.md +++ b/structure/ops/docs-and-release.md @@ -336,7 +336,7 @@ The shared atomic replacement publisher also identifies explicit Remote Workspac Remote Workspace uses a separate, explicitly enabled server surface with structural WebSocket callbacks and awaited per-server cleanup; [its contract](../remote-workspace.md) owns that integration. -Usage consumers preserve positive incomplete-history metadata as specified in [usage accounting](../gui-and-management-api.md#usage-accounting); readable totals are not represented as a complete ledger. +Usage consumers preserve positive incomplete-history metadata as specified in [usage accounting](../gui-and-management-api.md#usage-accounting); readable totals are not represented as a complete ledger. Upstream API-key usage follows the [physical-attempt account attribution contract](../gui-and-management-api.md#upstream-key-account-attribution), independently of subscription quota observations. Listener startup diagnostics follow [the runtime lifecycle contract](../runtime.md#lifecycle); malformed optional listener blocks follow [config loading](../config.md#config-surface). The Combo guides describe the distinction between display quota and single-credential inference evidence used by routing. See [scoped provider quota](../runtime.md#scoped-provider-quota-for-combo-selection). diff --git a/structure/ops/service-and-sidecars.md b/structure/ops/service-and-sidecars.md index e28575b432..db1a8653a1 100644 --- a/structure/ops/service-and-sidecars.md +++ b/structure/ops/service-and-sidecars.md @@ -145,7 +145,7 @@ so the flag does not identify the peer responsible for corruption. Existing diag not rewritten. Audio devices, WebRTC media negotiation, captions and spoken handoff delivery remain client responsibilities. -Usage consumers preserve positive incomplete-history metadata as specified in [usage accounting](../gui-and-management-api.md#usage-accounting); readable totals are not represented as a complete ledger. +Usage consumers preserve positive incomplete-history metadata as specified in [usage accounting](../gui-and-management-api.md#usage-accounting); readable totals are not represented as a complete ledger. Upstream API-key usage follows the [physical-attempt account attribution contract](../gui-and-management-api.md#upstream-key-account-attribution), independently of subscription quota observations. Connected CLI usage follows the [client-scoped hub usage contract](../gui-and-management-api.md#usage-accounting); local management and account data remain separate. diff --git a/structure/providers/chat-compat.md b/structure/providers/chat-compat.md index 5ee17ed807..08cdc58288 100644 --- a/structure/providers/chat-compat.md +++ b/structure/providers/chat-compat.md @@ -339,3 +339,5 @@ prose the model reads beside them. Vendor tool execution stays disabled on both adapters, and Qoder's explicit refusal of original images is unchanged. Canonical Responses identity sanitation and narrowly scoped pre-output combo recovery follow [request-local target compatibility](../runtime.md#request-local-target-compatibility); other adapter contracts remain unchanged. + +Upstream API-key usage follows the [physical-attempt account attribution contract](../gui-and-management-api.md#upstream-key-account-attribution), independently of subscription quota observations. diff --git a/structure/providers/cursor.md b/structure/providers/cursor.md index 5ae38028d8..39f06c3915 100644 --- a/structure/providers/cursor.md +++ b/structure/providers/cursor.md @@ -130,3 +130,5 @@ Translated Chat request construction uses the [inline-image budget](../transport Translated audio/file admission follows the [final-adapter input contract](../adapters/registry.md#untranslated-input-media); native raw passthrough remains separate. Canonical Responses identity sanitation and narrowly scoped pre-output combo recovery follow [request-local target compatibility](../runtime.md#request-local-target-compatibility); other adapter contracts remain unchanged. + +Upstream API-key usage follows the [physical-attempt account attribution contract](../gui-and-management-api.md#upstream-key-account-attribution), independently of subscription quota observations. diff --git a/structure/providers/openai-tiers.md b/structure/providers/openai-tiers.md index ab7511c3b0..fd25e83c46 100644 --- a/structure/providers/openai-tiers.md +++ b/structure/providers/openai-tiers.md @@ -567,3 +567,5 @@ Two call sites need the rule — the live path in `reevaluateAffinityQuota` and `previewReusableAffinityAccount` that subagent fallback reads — and they share one helper rather than restating it, because the suite asserts the two answer identically and a preview that disagreed would hand fallback a different account than the request actually uses. + +Upstream API-key usage follows the [physical-attempt account attribution contract](../gui-and-management-api.md#upstream-key-account-attribution), independently of subscription quota observations. diff --git a/structure/providers/xai-grok.md b/structure/providers/xai-grok.md index dc982c5639..114dbd9f80 100644 --- a/structure/providers/xai-grok.md +++ b/structure/providers/xai-grok.md @@ -68,7 +68,7 @@ malformed, gapped, oversized, contradictory, failed, or incomplete streams stay - **Safety & Idempotency:** Managed via `src/grok/reset-coupon-ledger.ts` using UUIDv4 operation tracking before upstream dispatch to prevent duplicate consumption during network flakes. - **Surfaces:** `ocx account grok-reset-coupons` in the terminal, and the dashboard at Providers > xAI Grok > Accounts, where each OAuth row carries a ticket badge with its remaining count and opens a redemption dialog (`gui/src/hooks/useGrokResetCoupons.ts`, `gui/src/components/provider-workspace/GrokResetCoupons.tsx`). The dashboard reads one `GET /api/grok/reset-coupons` per account with at most three in flight, always sends an explicit `tokenId` and a client-minted `operationId`, and treats redemption truth as the settled `code` rather than HTTP 200 — a replayed *failure* returns 200 with `replayed: true`. After a request times out it issues no further consume call, because a redemption whose ledger record is still `open` re-executes. -Usage consumers preserve positive incomplete-history metadata as specified in [usage accounting](../gui-and-management-api.md#usage-accounting); readable totals are not represented as a complete ledger. +Usage consumers preserve positive incomplete-history metadata as specified in [usage accounting](../gui-and-management-api.md#usage-accounting); readable totals are not represented as a complete ledger. Upstream API-key usage follows the [physical-attempt account attribution contract](../gui-and-management-api.md#upstream-key-account-attribution), independently of subscription quota observations. Connected CLI usage follows the [client-scoped hub usage contract](../gui-and-management-api.md#usage-accounting); local management and account data remain separate. diff --git a/structure/runtime.md b/structure/runtime.md index 248c3011c6..2a5a3b82cf 100644 --- a/structure/runtime.md +++ b/structure/runtime.md @@ -442,3 +442,10 @@ change target selection. `src/server/responses/core-combo.ts` applies the policy and preserves the original requested effort separately from effective wire telemetry. `src/server/chat-completions.ts` routes combos through that same child pipeline while retaining the current config-aware native-Chat eligibility check for non-combo routes. +## Upstream key usage identity + +`src/codex/account-label.ts` owns the provider/selection digest and `src/providers/label.ts` +stamps the configured key selected for the physical request. `src/server/request-log.ts` +retains per-key attempt usage, and `src/usage/log.ts` validates and persists labels. The +[account attribution contract](gui-and-management-api.md#upstream-key-account-attribution) +defines identity, unknown records, and aggregation boundaries. diff --git a/structure/subagents.md b/structure/subagents.md index c0c92891f7..1edc9e2e34 100644 --- a/structure/subagents.md +++ b/structure/subagents.md @@ -321,7 +321,7 @@ Native Codex advertisements still follow display priority; private guidance rank Codex display-cache expiry, retained main-policy evidence, and reset history follow the [quota cache contract](providers/openai-tiers.md#quota-cache-and-short-window-history). -Usage consumers preserve positive incomplete-history metadata as specified in [usage accounting](gui-and-management-api.md#usage-accounting); readable totals are not represented as a complete ledger. +Usage consumers preserve positive incomplete-history metadata as specified in [usage accounting](gui-and-management-api.md#usage-accounting); readable totals are not represented as a complete ledger. Upstream API-key usage follows the [physical-attempt account attribution contract](gui-and-management-api.md#upstream-key-account-attribution), independently of subscription quota observations. Connected CLI usage follows the [client-scoped hub usage contract](gui-and-management-api.md#usage-accounting); local management and account data remain separate. diff --git a/structure/transports/byte-accounting.md b/structure/transports/byte-accounting.md index 7f01dee197..239529ad96 100644 --- a/structure/transports/byte-accounting.md +++ b/structure/transports/byte-accounting.md @@ -39,3 +39,5 @@ These optimizations do not add request queues, retry policies, or RSS-based admi Translated audio/file admission follows the [final-adapter input contract](../adapters/registry.md#untranslated-input-media); native raw passthrough remains separate. Canonical Responses identity sanitation and narrowly scoped pre-output combo recovery follow [request-local target compatibility](../runtime.md#request-local-target-compatibility); other adapter contracts remain unchanged. + +Upstream API-key usage follows the [physical-attempt account attribution contract](../gui-and-management-api.md#upstream-key-account-attribution), independently of subscription quota observations. diff --git a/structure/transports/inventory.md b/structure/transports/inventory.md index ca80373a8e..53122d96ea 100644 --- a/structure/transports/inventory.md +++ b/structure/transports/inventory.md @@ -96,7 +96,7 @@ Caller-owned `provider.fetch` executors are also deferred: they receive literal/ redirect blocking, but cannot inherit DNS classification or peer pinning without a verified-peer executor contract. Main-request migration must not treat that branch as fixed-transport equivalent. -Usage consumers preserve positive incomplete-history metadata as specified in [usage accounting](../gui-and-management-api.md#usage-accounting); readable totals are not represented as a complete ledger. +Usage consumers preserve positive incomplete-history metadata as specified in [usage accounting](../gui-and-management-api.md#usage-accounting); readable totals are not represented as a complete ledger. Upstream API-key usage follows the [physical-attempt account attribution contract](../gui-and-management-api.md#upstream-key-account-attribution), independently of subscription quota observations. Connected CLI usage follows the [client-scoped hub usage contract](../gui-and-management-api.md#usage-accounting); local management and account data remain separate. diff --git a/structure/transports/responses.md b/structure/transports/responses.md index aa66104165..b2de98cec8 100644 --- a/structure/transports/responses.md +++ b/structure/transports/responses.md @@ -573,6 +573,15 @@ change target order or attempt accounting; provider-400 decisions follow the [re The shared Responses path follows the [bounded multipart recovery contract](../subagents.md#multipart-encrypted-task-recovery); credential admission and retry policy remain unchanged. +## Upstream key attempt accounting + +Key identity is sealed at the guarded physical dispatch after queued selections are rebuilt. +Raw adapter terminal usage is recorded before continuation, search, or image loops merge it; +repeated parsing of one physical response does not count it twice. Key changes preserve the +previous attempt while retaining the active attempt object shared by streaming/combo callbacks. +Bounded failure-body observation retains reported usage and releases cloned readers on abort. +Identity and consumer aggregation follow the [account attribution contract](../gui-and-management-api.md#upstream-key-account-attribution). + ## Combo streaming commit boundary An HTTP 200 does not by itself commit a streaming combo child. The combo parent runs the child's diff --git a/structure/transports/streaming-health.md b/structure/transports/streaming-health.md index 682fbb2ca2..06783ad651 100644 --- a/structure/transports/streaming-health.md +++ b/structure/transports/streaming-health.md @@ -211,7 +211,7 @@ WebSocket clients observe the same canonical lifecycle. frame rather than always emitting `response.completed`. If the response status is `failed`, a `response.failed` frame is sent; otherwise `response.completed` carries through the original status. -Usage consumers preserve positive incomplete-history metadata as specified in [usage accounting](../gui-and-management-api.md#usage-accounting); readable totals are not represented as a complete ledger. +Usage consumers preserve positive incomplete-history metadata as specified in [usage accounting](../gui-and-management-api.md#usage-accounting); readable totals are not represented as a complete ledger. Upstream API-key usage follows the [physical-attempt account attribution contract](../gui-and-management-api.md#upstream-key-account-attribution), independently of subscription quota observations. Connected CLI usage follows the [client-scoped hub usage contract](../gui-and-management-api.md#usage-accounting); local management and account data remain separate. diff --git a/tests/codex-integration/codex-account-label.test.ts b/tests/codex-integration/codex-account-label.test.ts index 9680e3f8b9..5053d1fc78 100644 --- a/tests/codex-integration/codex-account-label.test.ts +++ b/tests/codex-integration/codex-account-label.test.ts @@ -1,6 +1,8 @@ import { describe, expect, test } from "bun:test"; import { CODEX_ACCOUNT_LOG_LABEL_RE, + ACCOUNT_LOG_LABEL_RE, + apiKeyAccountLogLabel, codexAccountLogLabel, createCodexAccountLogLabel, fallbackCodexAccountLogLabel, @@ -8,6 +10,22 @@ import { } from "../../src/codex/account-label"; describe("codex account privacy labels", () => { + test("key labels follow the shared consumer contract and isolate provider, slot and reference", () => { + expect(apiKeyAccountLogLabel("test-provider", { entryId: "slot-a", reference: "test-key-a" })) + .toBe("k35f7c109222440212853c90de03e7df5"); + expect(apiKeyAccountLogLabel("test-provider", { entryId: "slot-b", reference: "test-key-b" })) + .toBe("kae34539c9f0b302367a033166800ae47"); + expect(apiKeyAccountLogLabel("test-provider", { reference: "test-key-a" })) + .toBe("ke4869182d193d18777b6ce175baaa41a"); + expect(apiKeyAccountLogLabel("other-provider", { entryId: "slot-a", reference: "test-key-a" })) + .toBe("k98c6a69a98c5537c6acd344f116e7579"); + expect(apiKeyAccountLogLabel("test-provider", undefined)).toBeUndefined(); + expect(apiKeyAccountLogLabel("test-provider", { reference: "" })).toBeUndefined(); + expect(apiKeyAccountLogLabel("test-provider", { reference: "env:MISSING_SYNTHETIC_KEY" })) + .toMatch(ACCOUNT_LOG_LABEL_RE); + expect(ACCOUNT_LOG_LABEL_RE.test("kabc123")).toBe(false); + expect(ACCOUNT_LOG_LABEL_RE.test("k" + "a".repeat(33))).toBe(false); + }); test("generates non-PII log labels", () => { expect(createCodexAccountLogLabel()).toMatch(CODEX_ACCOUNT_LOG_LABEL_RE); }); diff --git a/tests/providers/rate-limit-retry.test.ts b/tests/providers/rate-limit-retry.test.ts index 709ccdae12..b351057055 100644 --- a/tests/providers/rate-limit-retry.test.ts +++ b/tests/providers/rate-limit-retry.test.ts @@ -121,14 +121,16 @@ describe("retry loop client-abort handling", () => { test("abort during the wait interrupts the sleep, cancels the 429 body, and returns 499 without replaying", async () => { let sends = 0; let upstreamBodyCancelled = false; + let upstreamBodyDrained = false; globalThis.fetch = (async (input, init) => { const url = input instanceof Request ? input.url : String(input); if (url === "https://llmapi.blsc.cn/chat/completions") { sends += 1; return new Response(new ReadableStream({ - start(controller) { + pull(controller) { controller.enqueue(new TextEncoder().encode(JSON.stringify({ error: { message: "rate limited" } }))); controller.close(); + upstreamBodyDrained = true; }, cancel() { upstreamBodyCancelled = true; @@ -167,7 +169,7 @@ describe("retry loop client-abort handling", () => { const response = await pending; expect(response.status).toBe(499); expect(sends).toBe(1); - expect(upstreamBodyCancelled).toBe(true); + expect(upstreamBodyCancelled || upstreamBodyDrained).toBe(true); const body = await response.json() as { error?: { code?: string } }; expect(body.error?.code).toBe("client_cancelled"); }); @@ -182,7 +184,7 @@ describe("retry loop client-abort handling", () => { return new Response(new ReadableStream({ start(controller) { controller.enqueue(new TextEncoder().encode(JSON.stringify({ error: { message: "rate limited" } }))); - controller.close(); + // Keep the source open so abort must cancel both accounting tee branches. }, cancel() { cancelInitiated = true; diff --git a/tests/responses/chat-completions-endpoint.test.ts b/tests/responses/chat-completions-endpoint.test.ts index 82317d89bd..c88a247674 100644 --- a/tests/responses/chat-completions-endpoint.test.ts +++ b/tests/responses/chat-completions-endpoint.test.ts @@ -1649,7 +1649,74 @@ test("chat-native preserves same-key retry, key rotation, usage, and request log const entry = getRequestLogEntries().at(-1); expect(entry?.status).toBe(200); expect(entry?.usage).toMatchObject({ inputTokens: 4, outputTokens: 2 }); - expect(entry?.attempts?.[0]?.recoveryKinds).toEqual(["rate-limit-429", "key-429"]); + expect(entry?.attempts).toHaveLength(2); + expect(entry?.attempts?.[0]?.recoveryKinds).toEqual(["rate-limit-429"]); + expect(entry?.attempts?.[0]?.sendCount).toBe(2); + expect(entry?.attempts?.[1]?.recoveryKinds).toEqual(["key-429"]); + expect(entry?.attempts?.[1]?.sendCount).toBe(1); + } finally { + await server.stop(true); + upstream.stop(true); + clearKeyCooldowns("mock"); + } +}); + +test.each([false, true])("chat-native attributes same-key 429 usage then the rotated key (stream=%s)", async (streaming) => { + const { clearRequestLogsForTests, getRequestLogEntries } = await import("../../src/server/request-log"); + const { clearKeyCooldowns } = await import("../../src/providers/key-failover"); + clearRequestLogsForTests(); + clearKeyCooldowns("mock"); + const authorizations: Array = []; + const upstream = Bun.serve({ + port: 0, + fetch(req) { + authorizations.push(req.headers.get("authorization")); + if (authorizations.length === 1) { + return Response.json({ error: { message: "rate limited" }, usage: { prompt_tokens: 10, completion_tokens: 1 } }, { + status: 429, headers: { "retry-after": "0", "content-type": "application/json" }, + }); + } + if (authorizations.length === 2) { + return Response.json({ error: { message: "rate limited" }, usage: { prompt_tokens: 7, completion_tokens: 0 } }, { + status: 429, headers: { "retry-after": "0", "content-type": "application/json" }, + }); + } + if (streaming) { + const chunks = [ + { id: "chatcmpl-1", choices: [{ index: 0, delta: { role: "assistant", content: "ok" }, finish_reason: null }] }, + { id: "chatcmpl-1", choices: [{ index: 0, delta: {}, finish_reason: "stop" }], usage: { prompt_tokens: 3, completion_tokens: 2 } }, + ]; + return new Response(chunks.map(chunk => `data: ${JSON.stringify(chunk)}\n\n`).join("") + "data: [DONE]\n\n", { + headers: { "content-type": "text/event-stream" }, + }); + } + return Response.json({ + id: "chatcmpl-1", object: "chat.completion", + choices: [{ index: 0, message: { role: "assistant", content: "ok" }, finish_reason: "stop" }], + usage: { prompt_tokens: 3, completion_tokens: 2 }, + }); + }, + }); + saveConfig(mockConfig(`${upstream.url.toString().replace(/\/$/, "")}/v1`, { + authMode: "key", + apiKey: "key-one", + apiKeyPool: [{ id: "one", key: "key-one" }, { id: "two", key: "key-two" }], + retryOn429: { attempts: 1, intervalMs: 100, maxIntervalMs: 100, respectRetryAfter: false }, + })); + const server = startServer(0); + try { + const response = await fetch(new URL("/v1/chat/completions", server.url), { + method: "POST", + headers: { "content-type": "application/json" }, + body: JSON.stringify({ model: "mock/test-model", stream: streaming, messages: [{ role: "user", content: "hi" }] }), + }); + expect(response.status).toBe(200); + expect(await response.text()).toContain("ok"); + expect(authorizations).toEqual(["Bearer key-one", "Bearer key-one", "Bearer key-two"]); + const entry = getRequestLogEntries().at(-1); + expect(entry?.attempts).toHaveLength(2); + expect(entry?.attempts?.[0]).toMatchObject({ sendCount: 2, usage: { inputTokens: 17, outputTokens: 1 } }); + expect(entry?.attempts?.[1]).toMatchObject({ sendCount: 1, usage: { inputTokens: 3, outputTokens: 2 } }); } finally { await server.stop(true); upstream.stop(true); diff --git a/tests/responses/empty-completion-core.test.ts b/tests/responses/empty-completion-core.test.ts index d8d4d73325..6ec5541f12 100644 --- a/tests/responses/empty-completion-core.test.ts +++ b/tests/responses/empty-completion-core.test.ts @@ -60,10 +60,8 @@ function fixtureAdapter(provider: OcxProviderConfig): ProviderAdapter & { passth } : {}), }; }, - async fetchResponse() { - const index = httpCalls; - httpCalls += 1; - return new Response("", { headers: { "x-fixture-attempt": String(index) } }); + async fetchResponse(request, context) { + return context!.executor!(request.url, { method: request.method, headers: request.headers, body: request.body }); }, async *parseStream(response) { const index = Number(response.headers.get("x-fixture-attempt")); @@ -79,6 +77,7 @@ function fixtureAdapter(provider: OcxProviderConfig): ProviderAdapter & { passth await customRunTurn(parsed, _incoming as never, emit); return; } + await (_incoming as { providerFetch: typeof fetch }).providerFetch(provider.baseUrl, { method: "POST" }); const index = runTurnCalls; runTurnCalls += 1; parsedAttempts.push(parsed); @@ -123,6 +122,11 @@ function config( }, ...extra, } as OcxConfig; + (result.providers.fixture as OcxProviderConfig & { fetch?: typeof globalThis.fetch }).fetch = async () => { + const index = httpCalls; + if (adapter === "test-http") httpCalls += 1; + return new Response("", { headers: { "x-fixture-attempt": String(index) } }); + }; if (adapter === "test-passthrough") { (result.providers.fixture as OcxProviderConfig & { fetch?: typeof globalThis.fetch }).fetch = async () => { passthroughFetchCalls += 1; diff --git a/tests/server/server-combo-failover-e2e.test.ts b/tests/server/server-combo-failover-e2e.test.ts index bea04074a4..9c31a260a0 100644 --- a/tests/server/server-combo-failover-e2e.test.ts +++ b/tests/server/server-combo-failover-e2e.test.ts @@ -103,7 +103,8 @@ mock.module("../../src/server/adapter-resolve", () => ({ }, async fetchResponse(request, context) { if (!customFetchResponse) throw new Error("custom fetchResponse not installed"); - return customFetchResponse(request, context); + return context!.executor!(request.url, { method: request.method, headers: request.headers, + body: request.body, signal: context?.abortSignal }); }, }; } @@ -264,6 +265,12 @@ function provider( allowPrivateNetwork: url.includes("127.0.0.1"), authMode: "key", apiKey, + ...(adapter === "test-response" ? { fetch: (async (input, init) => { + if (!customFetchResponse) throw new Error("custom fetchResponse not installed"); + return customFetchResponse({ url: String(input), method: init?.method ?? "POST", + headers: Object.fromEntries(new Headers(init?.headers)), body: String(init?.body ?? "") }, + { abortSignal: init?.signal ?? undefined }); + }) as typeof globalThis.fetch } : {}), ...extra, }; } @@ -1835,7 +1842,7 @@ describe("server combo failover 030 activation matrix", () => { .toEqual({ inputTokens: 17, outputTokens: 3, totalTokens: 20 }); }); - test("provider-local retry keeps one attempt, two sends, recovery kind, and latest estimate", async () => { + test("provider-local key retry keeps separate attempts and the latest estimate on the selected key", async () => { const estimates = [10, 25]; customUsageEstimate = () => estimates.shift(); let calls = 0; @@ -1856,11 +1863,14 @@ describe("server combo failover 030 activation matrix", () => { const response = await postLogged(config); expect(response.status).toBe(200); await response.text(); - const attempt = (await latestAttemptReceipts(config)).usage.attempts?.[0]; + const attempts = (await latestAttemptReceipts(config)).usage.attempts; + expect(attempts).toHaveLength(2); + expect(attempts?.[0]).toMatchObject({ sendCount: 1, usageStatus: "unreported" }); + const attempt = attempts?.[1]; expect(attempt).toMatchObject({ provider: "a", model: "m1", - sendCount: 2, + sendCount: 1, inputTokenEstimate: 25, recoveryKinds: ["key-429"], }); diff --git a/tests/server/server-key-failover-e2e.test.ts b/tests/server/server-key-failover-e2e.test.ts index 418ef993ca..39c125ddd3 100644 --- a/tests/server/server-key-failover-e2e.test.ts +++ b/tests/server/server-key-failover-e2e.test.ts @@ -1,7 +1,9 @@ import { afterEach, beforeEach, describe, expect, test } from "bun:test"; -import { mkdtempSync} from "node:fs"; +import { mkdtempSync, readFileSync} from "node:fs"; import { tmpdir } from "node:os"; 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 { deriveXaiConvId } from "../../src/providers/xai-transport"; @@ -81,7 +83,8 @@ describe("server 429 key failover (end-to-end)", () => { expect(providerApiKeySelectionIsCurrent(config, "current", current)).toBe(true); }); - test("native Chat rebuilds a queued request after a manual key selection during pacing", async () => { + test.each(["responses", "chat/completions"])("%s logs only the key selected after pacing", async surface => { + resetUsageReadCacheForTests(); let now = 0; let resumePacing: (() => void) | undefined; const queued = Promise.withResolvers(); @@ -113,9 +116,10 @@ describe("server 429 key failover (end-to-end)", () => { const abort = new AbortController(); try { await waitForProviderRequestSlot("paced", config.providers.paced); - const pending = fetch(new URL("/v1/chat/completions", server.url), { + const pending = fetch(new URL(`/v1/${surface}`, server.url), { method: "POST", headers: { "content-type": "application/json" }, signal: abort.signal, - body: JSON.stringify({ model: "paced/test", stream: false, messages: [{ role: "user", content: "hello" }] }), + body: JSON.stringify({ model: "paced/test", stream: false, + ...(surface === "responses" ? { input: "hello" } : { messages: [{ role: "user", content: "hello" }] }) }), }); await queued.promise; expect(seen).toHaveLength(0); @@ -131,6 +135,11 @@ describe("server 429 key failover (end-to-end)", () => { expect(await response.text()).toContain("current selection"); expect(seen.map(headers => headers.get("authorization"))).toEqual(["Bearer synthetic-second"]); expect(seen[0]!.get("x-static-test")).toBe("retained"); + const rows = readUsageEntries(); + expect(rows).toHaveLength(1); + expect(rows[0].attempts).toHaveLength(1); + expect(rows[0].attempts?.[0]).toMatchObject({ sendCount: 1, + accountLogLabel: apiKeyAccountLogLabel("paced", { entryId: "second", reference: "synthetic-second" }) }); } finally { abort.abort(); await server.stop(true); @@ -333,17 +342,29 @@ describe("server 429 key failover (end-to-end)", () => { } }); - test("routed 429 rotates to the pool's next key and succeeds", async () => { + for (const surface of ["combo", "responses", "chat", "image"] as const) for (const meteredFailure of [false, true]) for (const streaming of [false, true]) { + if (surface === "image" && !streaming) continue; + test(`${surface} key rotation attributes each send (failed usage reported: ${meteredFailure}, streaming: ${streaming})`, async () => { + resetUsageReadCacheForTests(); const seenAuth: string[] = []; upstream = Bun.serve({ hostname: "127.0.0.1", port: 0, - fetch(req) { + async fetch(req) { + const body = await req.json() as { stream?: boolean }; seenAuth.push(req.headers.get("authorization") ?? ""); if (seenAuth.length === 1) { - return new Response(JSON.stringify({ error: { message: "rate limited" } }), { + return new Response(JSON.stringify({ error: { message: "rate limited" }, ...(meteredFailure ? { usage: { prompt_tokens: 10, completion_tokens: 4 } } : {}) }), { status: 429, headers: { "retry-after": "30", "content-type": "application/json" }, }); } + if (body.stream) { + const chunks = [ + { id: "chatcmpl-1", choices: [{ index: 0, delta: { role: "assistant", content: "ok after rotate" }, finish_reason: null }] }, + { id: "chatcmpl-1", choices: [{ index: 0, delta: {}, finish_reason: "stop" }], usage: { prompt_tokens: 3, completion_tokens: 2 } }, + ]; + return new Response(chunks.map(chunk => `data: ${JSON.stringify(chunk)}\n\n`).join("") + "data: [DONE]\n\n", + { headers: { "content-type": "text/event-stream" } }); + } return new Response(JSON.stringify({ id: "chatcmpl-1", object: "chat.completion", choices: [{ index: 0, message: { role: "assistant", content: "ok after rotate" }, finish_reason: "stop" }], @@ -353,9 +374,12 @@ describe("server 429 key failover (end-to-end)", () => { }); const config: OcxConfig = { port: 0, hostname: "127.0.0.1", defaultProvider: "pooled", + combos: { fixture: { strategy: "failover", targets: [{ provider: "pooled", model: "some-model" }] } }, + images: { bridgeEnabled: surface === "image" }, providers: { + xai: { adapter: "openai-chat", baseUrl: "https://api.x.ai/v1", authMode: "key", apiKey: "synthetic-unused-image-key" }, pooled: { - adapter: "openai-chat", + adapter: "openai-chat", ...(meteredFailure ? { authMode: "key" as const } : {}), baseUrl: `http://127.0.0.1:${upstream.port}/v1`, allowPrivateNetwork: true, apiKey: "key-alpha-000111222333", @@ -369,21 +393,108 @@ describe("server 429 key failover (end-to-end)", () => { saveConfig(config); const server = startServer(0); try { - const res = await fetch(new URL("/v1/responses", server.url), { + const res = await fetch(new URL(surface === "chat" ? "/v1/chat/completions" : "/v1/responses", server.url), { method: "POST", headers: { "content-type": "application/json" }, - body: JSON.stringify({ model: "pooled/some-model", input: "hello", stream: false }), + body: JSON.stringify(surface === "chat" + ? { model: "pooled/some-model", messages: [{ role: "user", content: "hello" }], stream: streaming } + : { model: surface === "combo" ? "combo/fixture" : "pooled/some-model", input: "hello", stream: streaming, + ...(surface === "image" ? { tools: [{ type: "image_generation" }] } : {}) }), }); expect(res.status).toBe(200); - const json = await res.json() as { output?: { type: string; content?: { text?: string }[] }[] }; - const message = json.output?.find(o => o.type === "message"); - expect(message?.content?.[0]?.text).toBe("ok after rotate"); + expect(await res.text()).toContain("ok after rotate"); expect(seenAuth[0]).toBe("Bearer key-alpha-000111222333"); expect(seenAuth[1]).toBe("Bearer key-beta-444555666777"); + expect(seenAuth).toHaveLength(2); + const rows = readUsageEntries(); + expect(rows).toHaveLength(1); + const attempts = rows[0].attempts!; + expect(attempts).toHaveLength(2); + expect(attempts[0]).toMatchObject({ ordinal: 1, provider: "pooled", model: "some-model", status: 429, + accountLogLabel: apiKeyAccountLogLabel("pooled", { entryId: "k1", reference: "key-alpha-000111222333" }), + usageStatus: meteredFailure ? "reported" : "unreported" }); + if (meteredFailure) expect(attempts[0].usage).toMatchObject({ inputTokens: 10, outputTokens: 4 }); + else expect(attempts[0].usage).toBeUndefined(); + expect(attempts[1]).toMatchObject({ ordinal: 2, provider: "pooled", model: "some-model", status: 200, + accountLogLabel: apiKeyAccountLogLabel("pooled", { entryId: "k2", reference: "key-beta-444555666777" }), + usage: { inputTokens: 3, outputTokens: 2 } }); + const raw = readFileSync(join(testDir, "usage.jsonl"), "utf8"); + expect(raw).not.toContain("key-alpha-000111222333"); + expect(raw).not.toContain("key-beta-444555666777"); } finally { await server.stop(true); } }); + } + + + test("Responses continuation keeps hidden successful A usage when a later 429 rotates to B", async () => { + resetUsageReadCacheForTests(); + const seen: string[] = []; + upstream = Bun.serve({ hostname: "127.0.0.1", port: 0, fetch(req) { + seen.push(req.headers.get("authorization") ?? ""); + if (seen.length === 2) return Response.json({ error: { message: "rate limited" }, + usage: { prompt_tokens: 7, completion_tokens: 1 } }, { status: 429 }); + return Response.json({ id: "chatcmpl-hidden", object: "chat.completion", + choices: [{ index: 0, message: { role: "assistant", content: seen.length === 1 ? "" : "recovered" }, finish_reason: "stop" }], + usage: { prompt_tokens: seen.length === 1 ? 100 : 200, completion_tokens: seen.length === 1 ? 10 : 20 } }); + } }); + saveConfig({ port: 0, hostname: "127.0.0.1", defaultProvider: "pooled", emptyCompletionRetry: true, + combos: { hidden: { strategy: "failover", targets: [{ provider: "pooled", model: "test" }] } }, + providers: { pooled: { adapter: "openai-chat", authMode: "key", + baseUrl: `http://127.0.0.1:${upstream.port}/v1`, allowPrivateNetwork: true, + apiKey: "synthetic-first", apiKeyPool: [{ id: "first", key: "synthetic-first" }, { id: "second", key: "synthetic-second" }] } }, + } as OcxConfig); + const server = startServer(0); + try { + const response = await fetch(new URL("/v1/responses", server.url), { method: "POST", + headers: { "content-type": "application/json" }, + body: JSON.stringify({ model: "pooled/test", input: "hello", stream: false }) }); + expect(response.status).toBe(200); + expect(await response.text()).toContain("recovered"); + expect(seen).toEqual(["Bearer synthetic-first", "Bearer synthetic-first", "Bearer synthetic-second"]); + const rows = readUsageEntries(); + expect(rows).toHaveLength(1); + expect(rows[0].attempts).toHaveLength(2); + expect(rows[0].attempts?.[0]).toMatchObject({ sendCount: 2, usage: { inputTokens: 107, outputTokens: 11 }, + accountLogLabel: apiKeyAccountLogLabel("pooled", { entryId: "first", reference: "synthetic-first" }) }); + expect(rows[0].attempts?.[1]).toMatchObject({ sendCount: 1, usage: { inputTokens: 200, outputTokens: 20 }, + accountLogLabel: apiKeyAccountLogLabel("pooled", { entryId: "second", reference: "synthetic-second" }) }); + expect(rows[0].attempts?.reduce((sum, attempt) => sum + (attempt.usage?.inputTokens ?? 0), 0)).toBe(307); + } finally { await server.stop(true); } + }); + + for (const adapter of ["command-code", "openai-chat"] as const) for (const error of [false, true]) { + test(`${adapter} records one usage observation for a nested parser or HTTP-200 error (${error})`, async () => { + resetUsageReadCacheForTests(); + upstream = Bun.serve({ hostname: "127.0.0.1", port: 0, fetch() { + if (adapter === "command-code") return new Response([ + { type: "text-delta", text: "synthetic answer" }, + { type: "finish", finishReason: error ? "error" : "stop", totalUsage: { inputTokens: 100, outputTokens: 20 } }, + ].map(row => JSON.stringify(row) + "\n").join(""), { headers: { "content-type": "application/x-ndjson" } }); + return Response.json({ id: "chatcmpl-error", object: "chat.completion", + ...(error ? { error: { message: "synthetic failure", type: "server_error" } } + : { choices: [{ index: 0, message: { role: "assistant", content: "synthetic answer" }, finish_reason: "stop" }] }), + usage: { prompt_tokens: 100, completion_tokens: 20 } }); + } }); + saveConfig({ port: 0, hostname: "127.0.0.1", defaultProvider: "metered", providers: { + metered: { adapter, authMode: "key", apiKey: "synthetic-key", allowPrivateNetwork: true, + baseUrl: `http://127.0.0.1:${upstream.port}` }, + } } as OcxConfig); + const server = startServer(0); + try { + const response = await fetch(new URL("/v1/responses", server.url), { method: "POST", + headers: { "content-type": "application/json" }, + body: JSON.stringify({ model: "metered/test", input: "hello", stream: false }) }); + await response.text(); + const rows = readUsageEntries(); + expect(rows).toHaveLength(1); + expect(rows[0].attempts).toHaveLength(1); + expect(rows[0].attempts?.[0]).toMatchObject({ usage: { inputTokens: 100, outputTokens: 20 }, + accountLogLabel: apiKeyAccountLogLabel("metered", { reference: "synthetic-key" }) }); + } finally { await server.stop(true); } + }); + } test("reasoning replay misses after a 429 rotates to a different physical key", async () => { const model = "reasoning-model"; diff --git a/tests/server/server-xai-oauth-401-replay.test.ts b/tests/server/server-xai-oauth-401-replay.test.ts index aab488ccb5..887415af39 100644 --- a/tests/server/server-xai-oauth-401-replay.test.ts +++ b/tests/server/server-xai-oauth-401-replay.test.ts @@ -317,11 +317,13 @@ describe("xAI OAuth Responses opt-in upstream 401 replay", () => { expect(seenAuth).toEqual([`Bearer ${firstKey}`, `Bearer ${secondKey}`]); const entries = readUsageEntries(); expect(entries).toHaveLength(1); - const attempt = entries[0]?.attempts?.[0]; - expect(entries[0]?.attempts).toHaveLength(1); + const attempts = entries[0]?.attempts; + expect(attempts).toHaveLength(2); + for (const attempt of attempts ?? []) { expect(attempt?.credentialSource).toBe("xai-api-key"); - expect(attempt?.sendCount).toBe(2); + expect(attempt?.sendCount).toBe(1); expect(attempt?.adapter).toBe("openai-chat"); + } const persisted = readFileSync(usageLogPath(), "utf8"); expect(persisted).not.toContain(firstKey); expect(persisted).not.toContain(secondKey); diff --git a/tests/usage/request-log.test.ts b/tests/usage/request-log.test.ts index f27426480a..8aed16d053 100644 --- a/tests/usage/request-log.test.ts +++ b/tests/usage/request-log.test.ts @@ -18,6 +18,9 @@ import { getRequestLogEntries, hydrateRequestLogsFromDisk, noteAttemptSend, + noteProviderAttemptSend, + recordKeyAttemptFailure, + recordKeyAttemptUsage, recordAdapterReasoning, recordFirstOutput, requestLogEntryFromPersistedUsage, @@ -25,6 +28,7 @@ import { recordAttemptCredentialSource, inspectResponseLogSsePayload, httpStatusForRequestLogTerminal, + applyResponseLogMetadata, type RequestLogContext, } from "../../src/server/request-log"; import { handleResponses } from "../../src/server/responses"; @@ -2073,3 +2077,111 @@ describe("request log snapshot cursor", () => { expect(selectRequestLogPoll(rows, query, stale, epoch)).toMatchObject({ logs: rows, reset: true }); }); }); + +describe("key attempt accounting", () => { + test("a combo parent copied before streaming rotation cannot overwrite the final key's usage", () => { + const active = beginRequestAttempt(1, "test", "model", "openai-chat"); + const child: RequestLogContext = { provider: "test", model: "model", comboId: "stream", + activeAttempt: active, attempts: [active] }; + const key = (reference: string) => ({ adapter: "openai-chat" as const, authMode: "key" as const, + baseUrl: "https://example.test", _apiKeyAttempt: { reference } }); + noteProviderAttemptSend(child, "test", key("synthetic-a"), undefined); + recordKeyAttemptUsage(child, { inputTokens: 100, outputTokens: 10 }); + const parent = { ...child }; + noteProviderAttemptSend(child, "test", key("synthetic-b"), undefined, "key-429"); + recordKeyAttemptUsage(child, { inputTokens: 200, outputTokens: 20 }); + const rows: RequestLogEntry[] = []; + addFinalRequestLog("stream-key-switch", Date.now(), parent, 200, undefined, row => rows.push(row)); + expect(rows[0].attempts?.map(attempt => attempt.usage?.inputTokens)).toEqual([100, 200]); + expect(rows[0].usage).toMatchObject({ inputTokens: 300, outputTokens: 30 }); + }); + test("adding reported usage cannot upgrade an earlier estimate to a measurement", () => { + const active = beginRequestAttempt(1, "test", "model", "openai-chat"); + const ctx: RequestLogContext = { provider: "test", model: "model", activeAttempt: active }; + recordKeyAttemptUsage(ctx, { inputTokens: 100, outputTokens: 0, estimated: true }); + recordKeyAttemptUsage(ctx, { inputTokens: 10, outputTokens: 2 }); + finishRequestAttempt(active, 429, 1); + expect(active).toMatchObject({ usageStatus: "estimated", usage: { inputTokens: 110, outputTokens: 2, estimated: true } }); + }); + test.each(["synthetic-a", undefined])("a late unreported segment (%s) cannot reuse a stale parent total", reference => { + const active = beginRequestAttempt(1, "test", "model", "openai-chat"); + const child: RequestLogContext = { provider: "test", model: "model", comboId: "stream", + activeAttempt: active, attempts: [active] }; + const key = (value?: string) => ({ adapter: "openai-chat" as const, authMode: "key" as const, + baseUrl: "https://example.test", _apiKeyAttempt: value ? { reference: value } : undefined }); + noteProviderAttemptSend(child, "test", key("synthetic-a"), undefined); + recordKeyAttemptUsage(child, { inputTokens: 100, outputTokens: 10 }); + const parent = { ...child }; + noteProviderAttemptSend(child, "test", key("synthetic-b"), undefined, "key-429"); + noteProviderAttemptSend(child, "test", key(reference), undefined, "key-429"); + const rows: RequestLogEntry[] = []; + addFinalRequestLog("stale-parent", Date.now(), parent, 499, undefined, row => rows.push(row)); + expect(rows[0].attempts?.map(attempt => attempt.usage?.inputTokens)).toEqual([100, undefined, undefined]); + expect(rows[0].attempts?.[2].usageStatus).toBe("unreported"); + }); + test("rotation preserves reported failure usage and the stable active object; unknown stays unreported", async () => { + const provider = (reference?: string) => ({ adapter: "openai-chat" as const, authMode: "key" as const, + baseUrl: "https://example.test/v1", _apiKeyAttempt: reference ? { reference } : undefined }); + const active = beginRequestAttempt(1, "test-provider", "test-model", "openai-chat"); + const ctx: RequestLogContext = { provider: "test-provider", model: "test-model", comboId: "fixture", + activeAttempt: active, activeAttemptStartedAt: Date.now(), attempts: [active] }; + noteProviderAttemptSend(ctx, "test-provider", provider("test-key-a"), 99999); + const labelA = active.accountLogLabel; + const failed = Response.json({ usage: { prompt_tokens: 100, completion_tokens: 20 } }, { status: 429 }); + await recordKeyAttemptFailure(ctx, failed); + expect(await failed.json()).toEqual({ usage: { prompt_tokens: 100, completion_tokens: 20 } }); + noteProviderAttemptSend(ctx, "test-provider", provider("test-key-b"), 200, "rate-limit-429"); + expect(ctx.activeAttempt).toBe(active); + expect(ctx.attempts).toHaveLength(2); + expect(ctx.attempts?.[0]).toMatchObject({ accountLogLabel: labelA, status: 429, ordinal: 1, + usageStatus: "reported", usage: { inputTokens: 100, outputTokens: 20 }, sendCount: 1 }); + expect(active.accountLogLabel).not.toBe(labelA); + expect(active.usage).toBeUndefined(); + // The next failure reports no usage. It must not inherit the preceding account's usage or an estimate. + await recordKeyAttemptFailure(ctx, Response.json({ error: "synthetic" }, { status: 401 })); + noteProviderAttemptSend(ctx, "test-provider", provider(), 300, "key-401"); + expect(ctx.attempts?.[1]).toMatchObject({ status: 401, ordinal: 2, usageStatus: "unreported" }); + expect(ctx.attempts?.[1].usage).toBeUndefined(); + expect(active.accountLogLabel).toBeUndefined(); + recordKeyAttemptUsage(ctx, { inputTokens: 300, outputTokens: 40 }); + const rows: RequestLogEntry[] = []; + addFinalRequestLog("key-rotation", Date.now(), ctx, 200, undefined, row => rows.push(row)); + const roundTrip = normalizeUsageEntryForTest(JSON.parse(JSON.stringify(rows[0])))!; + expect(roundTrip.attempts).toHaveLength(3); + expect(roundTrip.attempts?.map(a => a.ordinal)).toEqual([1, 2, 3]); + expect(roundTrip.attempts?.[0].accountLogLabel).toBe(labelA); + expect(roundTrip.attempts?.[2].usage).toMatchObject({ inputTokens: 300, outputTokens: 40 }); + expect(roundTrip.usage).toMatchObject({ inputTokens: 400, outputTokens: 60 }); + expect(JSON.stringify(roundTrip)).not.toContain("test-key-"); + }); + test("wire snapshots replace the current send against a pre-send baseline", () => { + const active = beginRequestAttempt(1, "test", "model", "openai-chat"); + const ctx: RequestLogContext = { provider: "test", model: "model", activeAttempt: active, attempts: [active] }; + const key = { adapter: "openai-chat" as const, authMode: "key" as const, baseUrl: "https://example.test", _apiKeyAttempt: { reference: "synthetic-a" } }; + noteProviderAttemptSend(ctx, "test", key, undefined); + applyResponseLogMetadata(ctx, { usage: { prompt_tokens: 10, completion_tokens: 1 } }); + inspectResponseLogSsePayload(ctx, JSON.stringify({ usage: { prompt_tokens: 10, completion_tokens: 1 } })); + noteProviderAttemptSend(ctx, "test", key, undefined); + applyResponseLogMetadata(ctx, { usage: { prompt_tokens: 3, completion_tokens: 2 } }); + applyResponseLogMetadata(ctx, { usage: { prompt_tokens: 3, completion_tokens: 2 } }); + finishRequestAttempt(active, 200, 1); + expect(active.usage).toMatchObject({ inputTokens: 13, outputTokens: 3 }); + expect(active.usage?.estimated).toBeUndefined(); + }); + test("an estimated baseline plus repeated and progressive wire snapshots stay one current send", () => { + const active = beginRequestAttempt(1, "test", "model", "openai-chat"); + const ctx: RequestLogContext = { provider: "test", model: "model", activeAttempt: active, attempts: [active] }; + const key = { adapter: "openai-chat" as const, authMode: "key" as const, baseUrl: "https://example.test", _apiKeyAttempt: { reference: "synthetic-a" } }; + noteProviderAttemptSend(ctx, "test", key, undefined); + recordKeyAttemptUsage(ctx, { inputTokens: 10, outputTokens: 0, estimated: true }); + noteProviderAttemptSend(ctx, "test", key, undefined); + applyResponseLogMetadata(ctx, { usage: { prompt_tokens: 3, completion_tokens: 2 } }); + applyResponseLogMetadata(ctx, { usage: { prompt_tokens: 3, completion_tokens: 2 } }); + applyResponseLogMetadata(ctx, { usage: { prompt_tokens: 4, completion_tokens: 2 } }); + finishRequestAttempt(active, 200, 1); + expect(active).toMatchObject({ + usageStatus: "estimated", + usage: { inputTokens: 14, outputTokens: 2, estimated: true }, + }); + }); +}); From d3ca5522db6d6094dd5d9e2e5d8e440eb93586b1 Mon Sep 17 00:00:00 2001 From: thisisjun786 <259586770+thisisjun786@users.noreply.github.com> Date: Tue, 15 Sep 2026 21:13:13 +0900 Subject: [PATCH 2/9] test(usage): isolate key accounting regressions within size limits --- scripts/test-layout/layout.json | 1 + tests/fixtures/test-layout-expected.json | 1 + tests/helpers/combo-provider.ts | 30 +++++ .../chat-completions-endpoint.test.ts | 118 ----------------- .../server/server-combo-failover-e2e.test.ts | 24 +--- tests/server/server-key-failover-e2e.test.ts | 122 ++++++++++++++++++ tests/usage/key-attribution.test.ts | 115 +++++++++++++++++ tests/usage/request-log.test.ts | 112 ---------------- 8 files changed, 271 insertions(+), 252 deletions(-) create mode 100644 tests/helpers/combo-provider.ts create mode 100644 tests/usage/key-attribution.test.ts diff --git a/scripts/test-layout/layout.json b/scripts/test-layout/layout.json index b4a1c1b0cf..1a1234c068 100644 --- a/scripts/test-layout/layout.json +++ b/scripts/test-layout/layout.json @@ -167,6 +167,7 @@ } }, "explicit": { + "key-attribution.test.ts": "usage", "responses-core-modules.test.ts": "responses", "responses-spend-ledger-wiring.test.ts": "responses", "responses-send-budget-errors.test.ts": "responses", diff --git a/tests/fixtures/test-layout-expected.json b/tests/fixtures/test-layout-expected.json index fb9acec3a7..5d6ede1f23 100644 --- a/tests/fixtures/test-layout-expected.json +++ b/tests/fixtures/test-layout-expected.json @@ -1,4 +1,5 @@ { + "key-attribution.test.ts": "usage", "responses-core-modules.test.ts": "responses", "responses-spend-ledger-wiring.test.ts": "responses", "responses-send-budget-errors.test.ts": "responses", diff --git a/tests/helpers/combo-provider.ts b/tests/helpers/combo-provider.ts new file mode 100644 index 0000000000..4221adbe4c --- /dev/null +++ b/tests/helpers/combo-provider.ts @@ -0,0 +1,30 @@ +import type { ProviderAdapter } from "../../src/adapters/base"; +import type { OcxProviderConfig } from "../../src/types"; + +/** Keep the fixture upstream behind the same executor used by real provider sends. */ +export function comboProviderFactory( + getFetchResponse: () => ProviderAdapter["fetchResponse"], +) { + return function provider( + adapter: string, + url: string, + apiKey: string, + extra: Partial = {}, + ): OcxProviderConfig { + return { + adapter, + baseUrl: url, + allowPrivateNetwork: url.includes("127.0.0.1"), + authMode: "key", + apiKey, + ...(adapter === "test-response" ? { fetch: (async (input, init) => { + const customFetchResponse = getFetchResponse(); + if (!customFetchResponse) throw new Error("custom fetchResponse not installed"); + return customFetchResponse({ url: String(input), method: init?.method ?? "POST", + headers: Object.fromEntries(new Headers(init?.headers)), body: String(init?.body ?? "") }, + { abortSignal: init?.signal ?? undefined }); + }) as typeof globalThis.fetch } : {}), + ...extra, + }; + }; +} diff --git a/tests/responses/chat-completions-endpoint.test.ts b/tests/responses/chat-completions-endpoint.test.ts index c88a247674..5eee77907c 100644 --- a/tests/responses/chat-completions-endpoint.test.ts +++ b/tests/responses/chat-completions-endpoint.test.ts @@ -1606,124 +1606,6 @@ test("chat-native records terminal key cooldown after the send budget is exhaust } }); -test("chat-native preserves same-key retry, key rotation, usage, and request logging", async () => { - const { clearRequestLogsForTests, getRequestLogEntries } = await import("../../src/server/request-log"); - const { clearKeyCooldowns } = await import("../../src/providers/key-failover"); - clearRequestLogsForTests(); - clearKeyCooldowns("mock"); - const authorizations: Array = []; - const upstream = Bun.serve({ - port: 0, - fetch(req) { - authorizations.push(req.headers.get("authorization")); - if (authorizations.length < 3) { - return Response.json({ error: { message: "rate limited", type: "rate_limit_error" } }, { - status: 429, - headers: { "retry-after": "0" }, - }); - } - return Response.json({ - id: "chatcmpl_retry", - object: "chat.completion", - choices: [{ index: 0, message: { role: "assistant", content: "ok" }, finish_reason: "stop" }], - usage: { prompt_tokens: 4, completion_tokens: 2 }, - }); - }, - }); - saveConfig(mockConfig(`${upstream.url.toString().replace(/\/$/, "")}/v1`, { - authMode: "key", - apiKey: "key-one", - apiKeyPool: [{ id: "one", key: "key-one" }, { id: "two", key: "key-two" }], - retryOn429: { attempts: 1, intervalMs: 100, maxIntervalMs: 100, respectRetryAfter: false }, - })); - const server = startServer(0); - try { - const response = await fetch(new URL("/v1/chat/completions", server.url), { - method: "POST", - headers: { "content-type": "application/json" }, - body: JSON.stringify({ model: "mock/test-model", stream: false, messages: [{ role: "user", content: "hi" }] }), - }); - expect(response.status).toBe(200); - await response.text(); - expect(authorizations).toEqual(["Bearer key-one", "Bearer key-one", "Bearer key-two"]); - const entry = getRequestLogEntries().at(-1); - expect(entry?.status).toBe(200); - expect(entry?.usage).toMatchObject({ inputTokens: 4, outputTokens: 2 }); - expect(entry?.attempts).toHaveLength(2); - expect(entry?.attempts?.[0]?.recoveryKinds).toEqual(["rate-limit-429"]); - expect(entry?.attempts?.[0]?.sendCount).toBe(2); - expect(entry?.attempts?.[1]?.recoveryKinds).toEqual(["key-429"]); - expect(entry?.attempts?.[1]?.sendCount).toBe(1); - } finally { - await server.stop(true); - upstream.stop(true); - clearKeyCooldowns("mock"); - } -}); - -test.each([false, true])("chat-native attributes same-key 429 usage then the rotated key (stream=%s)", async (streaming) => { - const { clearRequestLogsForTests, getRequestLogEntries } = await import("../../src/server/request-log"); - const { clearKeyCooldowns } = await import("../../src/providers/key-failover"); - clearRequestLogsForTests(); - clearKeyCooldowns("mock"); - const authorizations: Array = []; - const upstream = Bun.serve({ - port: 0, - fetch(req) { - authorizations.push(req.headers.get("authorization")); - if (authorizations.length === 1) { - return Response.json({ error: { message: "rate limited" }, usage: { prompt_tokens: 10, completion_tokens: 1 } }, { - status: 429, headers: { "retry-after": "0", "content-type": "application/json" }, - }); - } - if (authorizations.length === 2) { - return Response.json({ error: { message: "rate limited" }, usage: { prompt_tokens: 7, completion_tokens: 0 } }, { - status: 429, headers: { "retry-after": "0", "content-type": "application/json" }, - }); - } - if (streaming) { - const chunks = [ - { id: "chatcmpl-1", choices: [{ index: 0, delta: { role: "assistant", content: "ok" }, finish_reason: null }] }, - { id: "chatcmpl-1", choices: [{ index: 0, delta: {}, finish_reason: "stop" }], usage: { prompt_tokens: 3, completion_tokens: 2 } }, - ]; - return new Response(chunks.map(chunk => `data: ${JSON.stringify(chunk)}\n\n`).join("") + "data: [DONE]\n\n", { - headers: { "content-type": "text/event-stream" }, - }); - } - return Response.json({ - id: "chatcmpl-1", object: "chat.completion", - choices: [{ index: 0, message: { role: "assistant", content: "ok" }, finish_reason: "stop" }], - usage: { prompt_tokens: 3, completion_tokens: 2 }, - }); - }, - }); - saveConfig(mockConfig(`${upstream.url.toString().replace(/\/$/, "")}/v1`, { - authMode: "key", - apiKey: "key-one", - apiKeyPool: [{ id: "one", key: "key-one" }, { id: "two", key: "key-two" }], - retryOn429: { attempts: 1, intervalMs: 100, maxIntervalMs: 100, respectRetryAfter: false }, - })); - const server = startServer(0); - try { - const response = await fetch(new URL("/v1/chat/completions", server.url), { - method: "POST", - headers: { "content-type": "application/json" }, - body: JSON.stringify({ model: "mock/test-model", stream: streaming, messages: [{ role: "user", content: "hi" }] }), - }); - expect(response.status).toBe(200); - expect(await response.text()).toContain("ok"); - expect(authorizations).toEqual(["Bearer key-one", "Bearer key-one", "Bearer key-two"]); - const entry = getRequestLogEntries().at(-1); - expect(entry?.attempts).toHaveLength(2); - expect(entry?.attempts?.[0]).toMatchObject({ sendCount: 2, usage: { inputTokens: 17, outputTokens: 1 } }); - expect(entry?.attempts?.[1]).toMatchObject({ sendCount: 1, usage: { inputTokens: 3, outputTokens: 2 } }); - } finally { - await server.stop(true); - upstream.stop(true); - clearKeyCooldowns("mock"); - } -}); - test("chat-native client cancellation cancels the upstream stream and logs 499", async () => { const { clearRequestLogsForTests, getRequestLogEntries } = await import("../../src/server/request-log"); const { handleChatCompletions } = await import("../../src/server/chat-completions"); diff --git a/tests/server/server-combo-failover-e2e.test.ts b/tests/server/server-combo-failover-e2e.test.ts index 9c31a260a0..b735a2514e 100644 --- a/tests/server/server-combo-failover-e2e.test.ts +++ b/tests/server/server-combo-failover-e2e.test.ts @@ -1,4 +1,5 @@ import { registerComboForcedEffortCases } from "../helpers/combo-forced-effort-cases"; +import { comboProviderFactory } from "../helpers/combo-provider"; import { sessionLaneIdFromRequest } from "../../src/server/request-log-conversation"; import { afterEach, beforeEach, describe, expect, mock, setDefaultTimeout, test } from "bun:test"; import { logsFromApiBody } from "../helpers/logs-api"; @@ -59,6 +60,7 @@ const { createCursorAdapter } = await import("../../src/adapters/cursor"); import type { CursorTransportFactory } from "../../src/adapters/cursor/transport"; let customRunTurn: NonNullable | undefined; let customFetchResponse: NonNullable | undefined; +const provider = comboProviderFactory(() => customFetchResponse); let customTransientResponse: (() => Promise) | undefined; let customUsageEstimate: ((model: string) => number | undefined) | undefined; let customCursorTransportFactory: CursorTransportFactory | undefined; @@ -253,28 +255,6 @@ function responsesSuccess(text: string, model = "responses-model"): Record = {}, -): OcxProviderConfig { - return { - adapter, - baseUrl: url, - allowPrivateNetwork: url.includes("127.0.0.1"), - authMode: "key", - apiKey, - ...(adapter === "test-response" ? { fetch: (async (input, init) => { - if (!customFetchResponse) throw new Error("custom fetchResponse not installed"); - return customFetchResponse({ url: String(input), method: init?.method ?? "POST", - headers: Object.fromEntries(new Headers(init?.headers)), body: String(init?.body ?? "") }, - { abortSignal: init?.signal ?? undefined }); - }) as typeof globalThis.fetch } : {}), - ...extra, - }; -} - function comboConfig( providers: OcxConfig["providers"], targets = Object.keys(providers).map((name, index) => ({ provider: name, model: `m${index + 1}` })), diff --git a/tests/server/server-key-failover-e2e.test.ts b/tests/server/server-key-failover-e2e.test.ts index 39c125ddd3..c2e32ddc5f 100644 --- a/tests/server/server-key-failover-e2e.test.ts +++ b/tests/server/server-key-failover-e2e.test.ts @@ -898,3 +898,125 @@ describe("server 429 key failover (end-to-end)", () => { delete process.env.OCX_KEYFAIL_WARM; } }); + +test.each([false, true])("chat-native attributes same-key 429 usage then the rotated key (stream=%s)", async (streaming) => { + const { clearRequestLogsForTests, getRequestLogEntries } = await import("../../src/server/request-log"); + const { clearKeyCooldowns } = await import("../../src/providers/key-failover"); + clearRequestLogsForTests(); + clearKeyCooldowns("mock"); + const authorizations: Array = []; + const upstream = Bun.serve({ + port: 0, + fetch(req) { + authorizations.push(req.headers.get("authorization")); + if (authorizations.length === 1) { + return Response.json({ error: { message: "rate limited" }, usage: { prompt_tokens: 10, completion_tokens: 1 } }, { + status: 429, headers: { "retry-after": "0", "content-type": "application/json" }, + }); + } + if (authorizations.length === 2) { + return Response.json({ error: { message: "rate limited" }, usage: { prompt_tokens: 7, completion_tokens: 0 } }, { + status: 429, headers: { "retry-after": "0", "content-type": "application/json" }, + }); + } + if (streaming) { + const chunks = [ + { id: "chatcmpl-1", choices: [{ index: 0, delta: { role: "assistant", content: "ok" }, finish_reason: null }] }, + { id: "chatcmpl-1", choices: [{ index: 0, delta: {}, finish_reason: "stop" }], usage: { prompt_tokens: 3, completion_tokens: 2 } }, + ]; + return new Response(chunks.map(chunk => `data: ${JSON.stringify(chunk)}\n\n`).join("") + "data: [DONE]\n\n", { + headers: { "content-type": "text/event-stream" }, + }); + } + return Response.json({ + id: "chatcmpl-1", object: "chat.completion", + choices: [{ index: 0, message: { role: "assistant", content: "ok" }, finish_reason: "stop" }], + usage: { prompt_tokens: 3, completion_tokens: 2 }, + }); + }, + }); + saveConfig({ port: 0, hostname: "127.0.0.1", defaultProvider: "mock", providers: { mock: { + adapter: "openai-chat", allowPrivateNetwork: true, + baseUrl: `${upstream.url.toString().replace(/\/$/, "")}/v1`, + authMode: "key", + apiKey: "key-one", + apiKeyPool: [{ id: "one", key: "key-one" }, { id: "two", key: "key-two" }], + retryOn429: { attempts: 1, intervalMs: 100, maxIntervalMs: 100, respectRetryAfter: false }, + } } } as OcxConfig); + const server = startServer(0); + try { + const response = await fetch(new URL("/v1/chat/completions", server.url), { + method: "POST", + headers: { "content-type": "application/json" }, + body: JSON.stringify({ model: "mock/test-model", stream: streaming, messages: [{ role: "user", content: "hi" }] }), + }); + expect(response.status).toBe(200); + expect(await response.text()).toContain("ok"); + expect(authorizations).toEqual(["Bearer key-one", "Bearer key-one", "Bearer key-two"]); + const entry = getRequestLogEntries().at(-1); + expect(entry?.attempts).toHaveLength(2); + expect(entry?.attempts?.[0]).toMatchObject({ sendCount: 2, usage: { inputTokens: 17, outputTokens: 1 } }); + expect(entry?.attempts?.[1]).toMatchObject({ sendCount: 1, usage: { inputTokens: 3, outputTokens: 2 } }); + } finally { + await server.stop(true); + upstream.stop(true); + clearKeyCooldowns("mock"); + } +}); + +test("chat-native preserves same-key retry, key rotation, usage, and request logging", async () => { + const { clearRequestLogsForTests, getRequestLogEntries } = await import("../../src/server/request-log"); + const { clearKeyCooldowns } = await import("../../src/providers/key-failover"); + clearRequestLogsForTests(); + clearKeyCooldowns("mock"); + const authorizations: Array = []; + const upstream = Bun.serve({ + port: 0, + fetch(req) { + authorizations.push(req.headers.get("authorization")); + if (authorizations.length < 3) { + return Response.json({ error: { message: "rate limited", type: "rate_limit_error" } }, { + status: 429, + headers: { "retry-after": "0" }, + }); + } + return Response.json({ + id: "chatcmpl_retry", + object: "chat.completion", + choices: [{ index: 0, message: { role: "assistant", content: "ok" }, finish_reason: "stop" }], + usage: { prompt_tokens: 4, completion_tokens: 2 }, + }); + }, + }); + saveConfig({ port: 0, hostname: "127.0.0.1", defaultProvider: "mock", providers: { mock: { + adapter: "openai-chat", allowPrivateNetwork: true, + baseUrl: `${upstream.url.toString().replace(/\/$/, "")}/v1`, + authMode: "key", + apiKey: "key-one", + apiKeyPool: [{ id: "one", key: "key-one" }, { id: "two", key: "key-two" }], + retryOn429: { attempts: 1, intervalMs: 100, maxIntervalMs: 100, respectRetryAfter: false }, + } } } as OcxConfig); + const server = startServer(0); + try { + const response = await fetch(new URL("/v1/chat/completions", server.url), { + method: "POST", + headers: { "content-type": "application/json" }, + body: JSON.stringify({ model: "mock/test-model", stream: false, messages: [{ role: "user", content: "hi" }] }), + }); + expect(response.status).toBe(200); + await response.text(); + expect(authorizations).toEqual(["Bearer key-one", "Bearer key-one", "Bearer key-two"]); + const entry = getRequestLogEntries().at(-1); + expect(entry?.status).toBe(200); + expect(entry?.usage).toMatchObject({ inputTokens: 4, outputTokens: 2 }); + expect(entry?.attempts).toHaveLength(2); + expect(entry?.attempts?.[0]?.recoveryKinds).toEqual(["rate-limit-429"]); + expect(entry?.attempts?.[0]?.sendCount).toBe(2); + expect(entry?.attempts?.[1]?.recoveryKinds).toEqual(["key-429"]); + expect(entry?.attempts?.[1]?.sendCount).toBe(1); + } finally { + await server.stop(true); + upstream.stop(true); + clearKeyCooldowns("mock"); + } +}); diff --git a/tests/usage/key-attribution.test.ts b/tests/usage/key-attribution.test.ts new file mode 100644 index 0000000000..78359416e9 --- /dev/null +++ b/tests/usage/key-attribution.test.ts @@ -0,0 +1,115 @@ +import { describe, expect, test } from "bun:test"; +import { + addFinalRequestLog, beginRequestAttempt, finishRequestAttempt, noteProviderAttemptSend, + recordKeyAttemptFailure, recordKeyAttemptUsage, applyResponseLogMetadata, + inspectResponseLogSsePayload, type RequestLogContext, type RequestLogEntry, +} from "../../src/server/request-log"; +import { normalizeUsageEntryForTest } from "../../src/usage/log"; + +describe("key attempt accounting", () => { + test("a combo parent copied before streaming rotation cannot overwrite the final key's usage", () => { + const active = beginRequestAttempt(1, "test", "model", "openai-chat"); + const child: RequestLogContext = { provider: "test", model: "model", comboId: "stream", + activeAttempt: active, attempts: [active] }; + const key = (reference: string) => ({ adapter: "openai-chat" as const, authMode: "key" as const, + baseUrl: "https://example.test", _apiKeyAttempt: { reference } }); + noteProviderAttemptSend(child, "test", key("synthetic-a"), undefined); + recordKeyAttemptUsage(child, { inputTokens: 100, outputTokens: 10 }); + const parent = { ...child }; + noteProviderAttemptSend(child, "test", key("synthetic-b"), undefined, "key-429"); + recordKeyAttemptUsage(child, { inputTokens: 200, outputTokens: 20 }); + const rows: RequestLogEntry[] = []; + addFinalRequestLog("stream-key-switch", Date.now(), parent, 200, undefined, row => rows.push(row)); + expect(rows[0].attempts?.map(attempt => attempt.usage?.inputTokens)).toEqual([100, 200]); + expect(rows[0].usage).toMatchObject({ inputTokens: 300, outputTokens: 30 }); + }); + test("adding reported usage cannot upgrade an earlier estimate to a measurement", () => { + const active = beginRequestAttempt(1, "test", "model", "openai-chat"); + const ctx: RequestLogContext = { provider: "test", model: "model", activeAttempt: active }; + recordKeyAttemptUsage(ctx, { inputTokens: 100, outputTokens: 0, estimated: true }); + recordKeyAttemptUsage(ctx, { inputTokens: 10, outputTokens: 2 }); + finishRequestAttempt(active, 429, 1); + expect(active).toMatchObject({ usageStatus: "estimated", usage: { inputTokens: 110, outputTokens: 2, estimated: true } }); + }); + test.each(["synthetic-a", undefined])("a late unreported segment (%s) cannot reuse a stale parent total", reference => { + const active = beginRequestAttempt(1, "test", "model", "openai-chat"); + const child: RequestLogContext = { provider: "test", model: "model", comboId: "stream", + activeAttempt: active, attempts: [active] }; + const key = (value?: string) => ({ adapter: "openai-chat" as const, authMode: "key" as const, + baseUrl: "https://example.test", _apiKeyAttempt: value ? { reference: value } : undefined }); + noteProviderAttemptSend(child, "test", key("synthetic-a"), undefined); + recordKeyAttemptUsage(child, { inputTokens: 100, outputTokens: 10 }); + const parent = { ...child }; + noteProviderAttemptSend(child, "test", key("synthetic-b"), undefined, "key-429"); + noteProviderAttemptSend(child, "test", key(reference), undefined, "key-429"); + const rows: RequestLogEntry[] = []; + addFinalRequestLog("stale-parent", Date.now(), parent, 499, undefined, row => rows.push(row)); + expect(rows[0].attempts?.map(attempt => attempt.usage?.inputTokens)).toEqual([100, undefined, undefined]); + expect(rows[0].attempts?.[2].usageStatus).toBe("unreported"); + }); + test("rotation preserves reported failure usage and the stable active object; unknown stays unreported", async () => { + const provider = (reference?: string) => ({ adapter: "openai-chat" as const, authMode: "key" as const, + baseUrl: "https://example.test/v1", _apiKeyAttempt: reference ? { reference } : undefined }); + const active = beginRequestAttempt(1, "test-provider", "test-model", "openai-chat"); + const ctx: RequestLogContext = { provider: "test-provider", model: "test-model", comboId: "fixture", + activeAttempt: active, activeAttemptStartedAt: Date.now(), attempts: [active] }; + noteProviderAttemptSend(ctx, "test-provider", provider("test-key-a"), 99999); + const labelA = active.accountLogLabel; + const failed = Response.json({ usage: { prompt_tokens: 100, completion_tokens: 20 } }, { status: 429 }); + await recordKeyAttemptFailure(ctx, failed); + expect(await failed.json()).toEqual({ usage: { prompt_tokens: 100, completion_tokens: 20 } }); + noteProviderAttemptSend(ctx, "test-provider", provider("test-key-b"), 200, "rate-limit-429"); + expect(ctx.activeAttempt).toBe(active); + expect(ctx.attempts).toHaveLength(2); + expect(ctx.attempts?.[0]).toMatchObject({ accountLogLabel: labelA, status: 429, ordinal: 1, + usageStatus: "reported", usage: { inputTokens: 100, outputTokens: 20 }, sendCount: 1 }); + expect(active.accountLogLabel).not.toBe(labelA); + expect(active.usage).toBeUndefined(); + // The next failure reports no usage. It must not inherit the preceding account's usage or an estimate. + await recordKeyAttemptFailure(ctx, Response.json({ error: "synthetic" }, { status: 401 })); + noteProviderAttemptSend(ctx, "test-provider", provider(), 300, "key-401"); + expect(ctx.attempts?.[1]).toMatchObject({ status: 401, ordinal: 2, usageStatus: "unreported" }); + expect(ctx.attempts?.[1].usage).toBeUndefined(); + expect(active.accountLogLabel).toBeUndefined(); + recordKeyAttemptUsage(ctx, { inputTokens: 300, outputTokens: 40 }); + const rows: RequestLogEntry[] = []; + addFinalRequestLog("key-rotation", Date.now(), ctx, 200, undefined, row => rows.push(row)); + const roundTrip = normalizeUsageEntryForTest(JSON.parse(JSON.stringify(rows[0])))!; + expect(roundTrip.attempts).toHaveLength(3); + expect(roundTrip.attempts?.map(a => a.ordinal)).toEqual([1, 2, 3]); + expect(roundTrip.attempts?.[0].accountLogLabel).toBe(labelA); + expect(roundTrip.attempts?.[2].usage).toMatchObject({ inputTokens: 300, outputTokens: 40 }); + expect(roundTrip.usage).toMatchObject({ inputTokens: 400, outputTokens: 60 }); + expect(JSON.stringify(roundTrip)).not.toContain("test-key-"); + }); + test("wire snapshots replace the current send against a pre-send baseline", () => { + const active = beginRequestAttempt(1, "test", "model", "openai-chat"); + const ctx: RequestLogContext = { provider: "test", model: "model", activeAttempt: active, attempts: [active] }; + const key = { adapter: "openai-chat" as const, authMode: "key" as const, baseUrl: "https://example.test", _apiKeyAttempt: { reference: "synthetic-a" } }; + noteProviderAttemptSend(ctx, "test", key, undefined); + applyResponseLogMetadata(ctx, { usage: { prompt_tokens: 10, completion_tokens: 1 } }); + inspectResponseLogSsePayload(ctx, JSON.stringify({ usage: { prompt_tokens: 10, completion_tokens: 1 } })); + noteProviderAttemptSend(ctx, "test", key, undefined); + applyResponseLogMetadata(ctx, { usage: { prompt_tokens: 3, completion_tokens: 2 } }); + applyResponseLogMetadata(ctx, { usage: { prompt_tokens: 3, completion_tokens: 2 } }); + finishRequestAttempt(active, 200, 1); + expect(active.usage).toMatchObject({ inputTokens: 13, outputTokens: 3 }); + expect(active.usage?.estimated).toBeUndefined(); + }); + test("an estimated baseline plus repeated and progressive wire snapshots stay one current send", () => { + const active = beginRequestAttempt(1, "test", "model", "openai-chat"); + const ctx: RequestLogContext = { provider: "test", model: "model", activeAttempt: active, attempts: [active] }; + const key = { adapter: "openai-chat" as const, authMode: "key" as const, baseUrl: "https://example.test", _apiKeyAttempt: { reference: "synthetic-a" } }; + noteProviderAttemptSend(ctx, "test", key, undefined); + recordKeyAttemptUsage(ctx, { inputTokens: 10, outputTokens: 0, estimated: true }); + noteProviderAttemptSend(ctx, "test", key, undefined); + applyResponseLogMetadata(ctx, { usage: { prompt_tokens: 3, completion_tokens: 2 } }); + applyResponseLogMetadata(ctx, { usage: { prompt_tokens: 3, completion_tokens: 2 } }); + applyResponseLogMetadata(ctx, { usage: { prompt_tokens: 4, completion_tokens: 2 } }); + finishRequestAttempt(active, 200, 1); + expect(active).toMatchObject({ + usageStatus: "estimated", + usage: { inputTokens: 14, outputTokens: 2, estimated: true }, + }); + }); +}); diff --git a/tests/usage/request-log.test.ts b/tests/usage/request-log.test.ts index 8aed16d053..f27426480a 100644 --- a/tests/usage/request-log.test.ts +++ b/tests/usage/request-log.test.ts @@ -18,9 +18,6 @@ import { getRequestLogEntries, hydrateRequestLogsFromDisk, noteAttemptSend, - noteProviderAttemptSend, - recordKeyAttemptFailure, - recordKeyAttemptUsage, recordAdapterReasoning, recordFirstOutput, requestLogEntryFromPersistedUsage, @@ -28,7 +25,6 @@ import { recordAttemptCredentialSource, inspectResponseLogSsePayload, httpStatusForRequestLogTerminal, - applyResponseLogMetadata, type RequestLogContext, } from "../../src/server/request-log"; import { handleResponses } from "../../src/server/responses"; @@ -2077,111 +2073,3 @@ describe("request log snapshot cursor", () => { expect(selectRequestLogPoll(rows, query, stale, epoch)).toMatchObject({ logs: rows, reset: true }); }); }); - -describe("key attempt accounting", () => { - test("a combo parent copied before streaming rotation cannot overwrite the final key's usage", () => { - const active = beginRequestAttempt(1, "test", "model", "openai-chat"); - const child: RequestLogContext = { provider: "test", model: "model", comboId: "stream", - activeAttempt: active, attempts: [active] }; - const key = (reference: string) => ({ adapter: "openai-chat" as const, authMode: "key" as const, - baseUrl: "https://example.test", _apiKeyAttempt: { reference } }); - noteProviderAttemptSend(child, "test", key("synthetic-a"), undefined); - recordKeyAttemptUsage(child, { inputTokens: 100, outputTokens: 10 }); - const parent = { ...child }; - noteProviderAttemptSend(child, "test", key("synthetic-b"), undefined, "key-429"); - recordKeyAttemptUsage(child, { inputTokens: 200, outputTokens: 20 }); - const rows: RequestLogEntry[] = []; - addFinalRequestLog("stream-key-switch", Date.now(), parent, 200, undefined, row => rows.push(row)); - expect(rows[0].attempts?.map(attempt => attempt.usage?.inputTokens)).toEqual([100, 200]); - expect(rows[0].usage).toMatchObject({ inputTokens: 300, outputTokens: 30 }); - }); - test("adding reported usage cannot upgrade an earlier estimate to a measurement", () => { - const active = beginRequestAttempt(1, "test", "model", "openai-chat"); - const ctx: RequestLogContext = { provider: "test", model: "model", activeAttempt: active }; - recordKeyAttemptUsage(ctx, { inputTokens: 100, outputTokens: 0, estimated: true }); - recordKeyAttemptUsage(ctx, { inputTokens: 10, outputTokens: 2 }); - finishRequestAttempt(active, 429, 1); - expect(active).toMatchObject({ usageStatus: "estimated", usage: { inputTokens: 110, outputTokens: 2, estimated: true } }); - }); - test.each(["synthetic-a", undefined])("a late unreported segment (%s) cannot reuse a stale parent total", reference => { - const active = beginRequestAttempt(1, "test", "model", "openai-chat"); - const child: RequestLogContext = { provider: "test", model: "model", comboId: "stream", - activeAttempt: active, attempts: [active] }; - const key = (value?: string) => ({ adapter: "openai-chat" as const, authMode: "key" as const, - baseUrl: "https://example.test", _apiKeyAttempt: value ? { reference: value } : undefined }); - noteProviderAttemptSend(child, "test", key("synthetic-a"), undefined); - recordKeyAttemptUsage(child, { inputTokens: 100, outputTokens: 10 }); - const parent = { ...child }; - noteProviderAttemptSend(child, "test", key("synthetic-b"), undefined, "key-429"); - noteProviderAttemptSend(child, "test", key(reference), undefined, "key-429"); - const rows: RequestLogEntry[] = []; - addFinalRequestLog("stale-parent", Date.now(), parent, 499, undefined, row => rows.push(row)); - expect(rows[0].attempts?.map(attempt => attempt.usage?.inputTokens)).toEqual([100, undefined, undefined]); - expect(rows[0].attempts?.[2].usageStatus).toBe("unreported"); - }); - test("rotation preserves reported failure usage and the stable active object; unknown stays unreported", async () => { - const provider = (reference?: string) => ({ adapter: "openai-chat" as const, authMode: "key" as const, - baseUrl: "https://example.test/v1", _apiKeyAttempt: reference ? { reference } : undefined }); - const active = beginRequestAttempt(1, "test-provider", "test-model", "openai-chat"); - const ctx: RequestLogContext = { provider: "test-provider", model: "test-model", comboId: "fixture", - activeAttempt: active, activeAttemptStartedAt: Date.now(), attempts: [active] }; - noteProviderAttemptSend(ctx, "test-provider", provider("test-key-a"), 99999); - const labelA = active.accountLogLabel; - const failed = Response.json({ usage: { prompt_tokens: 100, completion_tokens: 20 } }, { status: 429 }); - await recordKeyAttemptFailure(ctx, failed); - expect(await failed.json()).toEqual({ usage: { prompt_tokens: 100, completion_tokens: 20 } }); - noteProviderAttemptSend(ctx, "test-provider", provider("test-key-b"), 200, "rate-limit-429"); - expect(ctx.activeAttempt).toBe(active); - expect(ctx.attempts).toHaveLength(2); - expect(ctx.attempts?.[0]).toMatchObject({ accountLogLabel: labelA, status: 429, ordinal: 1, - usageStatus: "reported", usage: { inputTokens: 100, outputTokens: 20 }, sendCount: 1 }); - expect(active.accountLogLabel).not.toBe(labelA); - expect(active.usage).toBeUndefined(); - // The next failure reports no usage. It must not inherit the preceding account's usage or an estimate. - await recordKeyAttemptFailure(ctx, Response.json({ error: "synthetic" }, { status: 401 })); - noteProviderAttemptSend(ctx, "test-provider", provider(), 300, "key-401"); - expect(ctx.attempts?.[1]).toMatchObject({ status: 401, ordinal: 2, usageStatus: "unreported" }); - expect(ctx.attempts?.[1].usage).toBeUndefined(); - expect(active.accountLogLabel).toBeUndefined(); - recordKeyAttemptUsage(ctx, { inputTokens: 300, outputTokens: 40 }); - const rows: RequestLogEntry[] = []; - addFinalRequestLog("key-rotation", Date.now(), ctx, 200, undefined, row => rows.push(row)); - const roundTrip = normalizeUsageEntryForTest(JSON.parse(JSON.stringify(rows[0])))!; - expect(roundTrip.attempts).toHaveLength(3); - expect(roundTrip.attempts?.map(a => a.ordinal)).toEqual([1, 2, 3]); - expect(roundTrip.attempts?.[0].accountLogLabel).toBe(labelA); - expect(roundTrip.attempts?.[2].usage).toMatchObject({ inputTokens: 300, outputTokens: 40 }); - expect(roundTrip.usage).toMatchObject({ inputTokens: 400, outputTokens: 60 }); - expect(JSON.stringify(roundTrip)).not.toContain("test-key-"); - }); - test("wire snapshots replace the current send against a pre-send baseline", () => { - const active = beginRequestAttempt(1, "test", "model", "openai-chat"); - const ctx: RequestLogContext = { provider: "test", model: "model", activeAttempt: active, attempts: [active] }; - const key = { adapter: "openai-chat" as const, authMode: "key" as const, baseUrl: "https://example.test", _apiKeyAttempt: { reference: "synthetic-a" } }; - noteProviderAttemptSend(ctx, "test", key, undefined); - applyResponseLogMetadata(ctx, { usage: { prompt_tokens: 10, completion_tokens: 1 } }); - inspectResponseLogSsePayload(ctx, JSON.stringify({ usage: { prompt_tokens: 10, completion_tokens: 1 } })); - noteProviderAttemptSend(ctx, "test", key, undefined); - applyResponseLogMetadata(ctx, { usage: { prompt_tokens: 3, completion_tokens: 2 } }); - applyResponseLogMetadata(ctx, { usage: { prompt_tokens: 3, completion_tokens: 2 } }); - finishRequestAttempt(active, 200, 1); - expect(active.usage).toMatchObject({ inputTokens: 13, outputTokens: 3 }); - expect(active.usage?.estimated).toBeUndefined(); - }); - test("an estimated baseline plus repeated and progressive wire snapshots stay one current send", () => { - const active = beginRequestAttempt(1, "test", "model", "openai-chat"); - const ctx: RequestLogContext = { provider: "test", model: "model", activeAttempt: active, attempts: [active] }; - const key = { adapter: "openai-chat" as const, authMode: "key" as const, baseUrl: "https://example.test", _apiKeyAttempt: { reference: "synthetic-a" } }; - noteProviderAttemptSend(ctx, "test", key, undefined); - recordKeyAttemptUsage(ctx, { inputTokens: 10, outputTokens: 0, estimated: true }); - noteProviderAttemptSend(ctx, "test", key, undefined); - applyResponseLogMetadata(ctx, { usage: { prompt_tokens: 3, completion_tokens: 2 } }); - applyResponseLogMetadata(ctx, { usage: { prompt_tokens: 3, completion_tokens: 2 } }); - applyResponseLogMetadata(ctx, { usage: { prompt_tokens: 4, completion_tokens: 2 } }); - finishRequestAttempt(active, 200, 1); - expect(active).toMatchObject({ - usageStatus: "estimated", - usage: { inputTokens: 14, outputTokens: 2, estimated: true }, - }); - }); -}); From 04e064c9628a55ac3b9ec0fd43020c86a2acab3a Mon Sep 17 00:00:00 2001 From: thisisjun786 <259586770+thisisjun786@users.noreply.github.com> Date: Wed, 16 Sep 2026 00:56:58 +0900 Subject: [PATCH 3/9] fix(usage): retain recovery metadata on every refetch send --- src/server/responses/adapter-dispatch.ts | 3 +- structure/transports/responses.md | 5 +++ tests/server/server-key-failover-e2e.test.ts | 39 ++++++++++++++++++++ 3 files changed, 46 insertions(+), 1 deletion(-) diff --git a/src/server/responses/adapter-dispatch.ts b/src/server/responses/adapter-dispatch.ts index 33135cf75a..2863105d7a 100644 --- a/src/server/responses/adapter-dispatch.ts +++ b/src/server/responses/adapter-dispatch.ts @@ -426,10 +426,10 @@ export async function prepareAdapterExchange( logCtx.providerAdapter = transportState.activeAdapter.name; sealRequestAttemptIdentity(logCtx.activeAttempt, logCtx.provider, transportState.activeAdapter.name, logCtx.accountLogLabel); recordAttemptCredentialSource(logCtx.activeAttempt, route.providerName, route.provider, transportState.activeAdapter.name); - transportState.noteRoutedAttemptSend(retryEstimate, recovery); try { try { if (transportState.activeAdapter.fetchResponse) { + transportState.noteRoutedAttemptSend(retryEstimate, recovery); await waitForProviderRequestSlot(route.providerName, route.provider, route.modelId, upstream.signal); // The dispatch boundary is HERE, not before the pacing wait: that wait can reject for // an abort, a saturated queue, an expired slot or a removed provider, and none of @@ -476,6 +476,7 @@ export async function prepareAdapterExchange( if (refetchAllowance?.permit && !refetchAllowance.permit.use()) { throw new SendBudgetExhaustedError(safeHostLabel(retryRequest.url)); } + transportState.noteRoutedAttemptSend(retryEstimate, recoveryKind ?? recovery); // Same boundary on the helper path: the thunk is what reaches the wire, and it // can be refused above before it does. use() past the first attempt is a no-op. onDispatch?.(); diff --git a/structure/transports/responses.md b/structure/transports/responses.md index b2de98cec8..907abf05cb 100644 --- a/structure/transports/responses.md +++ b/structure/transports/responses.md @@ -789,3 +789,8 @@ a spent request keeps the real 429 instead of replaying on a live stream. This is the proxy's own accounting only. Classifying an upstream 429 as org or project spend exhaustion is a separate contract with a separate owner. +Adapter-owned retries enter the same pending dispatch metadata path as initial key sends. +The actual dispatch commits their count and recovery label once; unsent pending metadata +is discarded on process exit and is not usage evidence. See [key attribution](../gui-and-management-api.md#upstream-key-account-attribution). +Generic refetches record metadata inside each admitted retry callback, retaining the +transient recovery reason when present and otherwise the outer recovery reason. diff --git a/tests/server/server-key-failover-e2e.test.ts b/tests/server/server-key-failover-e2e.test.ts index c2e32ddc5f..4bf924c249 100644 --- a/tests/server/server-key-failover-e2e.test.ts +++ b/tests/server/server-key-failover-e2e.test.ts @@ -1020,3 +1020,42 @@ test("chat-native preserves same-key retry, key rotation, usage, and request log clearKeyCooldowns("mock"); } }); + +test.each([false, true])("key refetch retains transient recovery metadata (stream=%s)", async stream => { + resetUsageReadCacheForTests(); + const seen: Array = []; + upstream = Bun.serve({ hostname: "127.0.0.1", port: 0, fetch(req) { + seen.push(req.headers.get("authorization")); + if (seen.length < 3) return Response.json({ error: { message: seen.length === 1 ? "rate limited" : "temporarily unavailable" }, + usage: { prompt_tokens: seen.length, completion_tokens: 0 } }, { + status: seen.length === 1 ? 429 : 503, headers: { "retry-after": "0" }, + }); + const usage = { prompt_tokens: 10, completion_tokens: 2 }; + if (stream) return new Response([ + { id: "chatcmpl-refetch", choices: [{ index: 0, delta: { content: "recovered" }, finish_reason: null }] }, + { id: "chatcmpl-refetch", choices: [{ index: 0, delta: {}, finish_reason: "stop" }], usage }, + ].map(chunk => `data: ${JSON.stringify(chunk)}\n\n`).join("") + "data: [DONE]\n\n", { + headers: { "content-type": "text/event-stream" }, + }); + return Response.json({ id: "chatcmpl-refetch", object: "chat.completion", usage, + choices: [{ index: 0, message: { role: "assistant", content: "recovered" }, finish_reason: "stop" }] }); + } }); + saveConfig({ port: 0, hostname: "127.0.0.1", defaultProvider: "refetch", providers: { refetch: { + adapter: "openai-chat", authMode: "key", allowPrivateNetwork: true, baseUrl: `http://127.0.0.1:${upstream.port}/v1`, + apiKey: "synthetic-refetch-a", apiKeyPool: [{ id: "a", key: "synthetic-refetch-a" }, { id: "b", key: "synthetic-refetch-b" }], + transientRetryOn5xx: { attempts: 3 }, retryOn429: { attempts: 0 }, + } } } as OcxConfig); + const server = startServer(0); + try { + const response = await fetch(new URL("/v1/responses", server.url), { method: "POST", headers: { "content-type": "application/json" }, + body: JSON.stringify({ model: "refetch/test", input: "hello", stream }) }); + expect(response.status).toBe(200); + expect(await response.text()).toContain("recovered"); + expect(seen).toEqual(["Bearer synthetic-refetch-a", "Bearer synthetic-refetch-b", "Bearer synthetic-refetch-b"]); + const attempts = readUsageEntries()[0]?.attempts; + expect(attempts).toHaveLength(2); + expect(attempts?.[0]).toMatchObject({ sendCount: 1, usage: { inputTokens: 1, outputTokens: 0 } }); + expect(attempts?.[1]).toMatchObject({ sendCount: 2, recoveryKinds: ["key-429", "transient-5xx"], + usage: { inputTokens: 12, outputTokens: 2 } }); + } finally { await server.stop(true); } +}); From 06a117c22891609d75e59120b8e35da4772285cb Mon Sep 17 00:00:00 2001 From: JUN Date: Wed, 16 Sep 2026 11:25:53 +0900 Subject: [PATCH 4/9] test(usage): pin the attempts-or-total boundary the carry depends on (#4546) [skip ci] Carried from PR #4717. The Command Code reasoning-effort retry commit is left behind: that retry stays on the same selected key, so it is not needed to tell account A's usage from account B's, and keeping it out keeps this layer reviewable. The injected-executor fix it depended on is already here. Adds the consumer-side assertion the attribution depends on. A row carries BOTH the per-attempt records and the request total, and a reader that added them would report 600 input tokens for 300 that were actually spent. usageAttributions takes the attempts when a row has them and the entry row only when it has none, so the parent total is a fallback for rows written before attempts existed rather than another column to sum. That arithmetic is also why hidden attempts must not be folded into the response the client sees: the Codex client treats response.completed.usage as the exact usage for that response and adds it to its durable turn and thread totals, so a proxy-side sum would corrupt accounting it owns. Closes #4717 Co-authored-by: thisisjun786 <259586770+thisisjun786@users.noreply.github.com> --- tests/usage/key-attribution.test.ts | 24 ++++++++++++++++++++++++ 1 file changed, 24 insertions(+) diff --git a/tests/usage/key-attribution.test.ts b/tests/usage/key-attribution.test.ts index 78359416e9..949d1e4a1c 100644 --- a/tests/usage/key-attribution.test.ts +++ b/tests/usage/key-attribution.test.ts @@ -4,6 +4,8 @@ import { recordKeyAttemptFailure, recordKeyAttemptUsage, applyResponseLogMetadata, inspectResponseLogSsePayload, type RequestLogContext, type RequestLogEntry, } from "../../src/server/request-log"; +import { readFileSync } from "node:fs"; +import { repoPath } from "../helpers/repo-root"; import { normalizeUsageEntryForTest } from "../../src/usage/log"; describe("key attempt accounting", () => { @@ -23,6 +25,28 @@ describe("key attempt accounting", () => { expect(rows[0].attempts?.map(attempt => attempt.usage?.inputTokens)).toEqual([100, 200]); expect(rows[0].usage).toMatchObject({ inputTokens: 300, outputTokens: 30 }); }); + + test("a reader takes the attempts or the request total, never both", () => { + // The row above deliberately carries BOTH the per-attempt records (100 + 200) and the + // request total (300). A consumer that added them would report 600 input tokens for 300 + // that were actually spent, and the same arithmetic is what would corrupt a client's own + // accounting if hidden attempts were folded into the response it sees. + const summary = readFileSync(repoPath("src/usage/summary.ts"), "utf8"); + const attributions = summary.slice( + summary.indexOf("function usageAttributions("), + summary.indexOf("function projectedComboUsage("), + ); + // The entry-level row is the fallback for a request written before attempts existed, and it + // is reachable only when there are none. + expect(attributions).toContain("if (!entry.attempts?.length) {"); + // Everything after that early return maps the attempts; there is no branch that emits the + // entry row alongside them. + const fallback = attributions.indexOf("if (!entry.attempts?.length) {"); + const perAttempt = attributions.indexOf("return entry.attempts.map(attempt =>", fallback); + expect(fallback).toBeGreaterThan(-1); + expect(perAttempt).toBeGreaterThan(fallback); + expect(attributions.match(/return \[\{/g) ?? []).toHaveLength(1); + }); test("adding reported usage cannot upgrade an earlier estimate to a measurement", () => { const active = beginRequestAttempt(1, "test", "model", "openai-chat"); const ctx: RequestLogContext = { provider: "test", model: "model", activeAttempt: active }; From e90d0aeb28e584e7c46aca9e612f4514359c19b1 Mon Sep 17 00:00:00 2001 From: JUN Date: Wed, 16 Sep 2026 11:30:50 +0900 Subject: [PATCH 5/9] fix(routing): give a withheld recovery a retry time that is actually later (#4546) [skip ci] The transient-hold resolver and the pool-wide recovery limiter added in #4626 still have no production caller, so #4701 is not closed here. Wiring them turned up a defect in the thing being wired, and that has to be fixed first. A withheld dispatch promises the caller a retry time. It was computed from the probe pacing alone. When the RATIO limiter is what refused, the account usually has no probe state at all -- nothing was ever granted for it -- so nextProbeAt returned now, and the refusal told the caller to try again immediately. A withheld dispatch that busy-loops puts the same load on an already-failing pool as the dispatch it refused, which is the opposite of what the limiter is for. It also violates the Retry-After half of #4701's completion criteria directly. The limiter is the only thing that knows when its own window moves, so it now says: nextRecoveryAt returns now while the allowance is unspent, and otherwise the moment the oldest bucket still inside the window falls out. Every such bucket started after now - windowMs, so the answer is always strictly in the future, and it is a real change point rather than a guessed delay. The withheld result takes the later of that and the probe pacing. The existing zero-allowance test asserted only that the result was withheld, which is why the defect survived the unit suite that was written to cover this module. It now asserts the time as well. Refs #4701 --- src/routing/probe-lease.ts | 35 ++++++++++++++++++++++++++++++- tests/routing/probe-lease.test.ts | 30 ++++++++++++++++++++++++++ 2 files changed, 64 insertions(+), 1 deletion(-) diff --git a/src/routing/probe-lease.ts b/src/routing/probe-lease.ts index fb63061e01..2182bab3eb 100644 --- a/src/routing/probe-lease.ts +++ b/src/routing/probe-lease.ts @@ -349,7 +349,14 @@ export function resolveHeldAccountDispatch(input: { kind: "withheld", boundAccountId: input.boundAccountId, ...(input.detourAccountId !== undefined ? { detourAccountId: input.detourAccountId } : {}), - retryAt: nextProbeAt(input.boundAccountId, now, input.minProbeIntervalMs), + // Both bounds, not just the probe pacing. A request refused by the RATIO has no probe state + // of its own yet, so `nextProbeAt` answered `now` and the refusal told the caller to try + // again immediately -- a withheld dispatch that busy-loops is the same load as the dispatch + // it refused. The limiter is the only thing that knows when its window moves. + retryAt: Math.max( + nextProbeAt(input.boundAccountId, now, input.minProbeIntervalMs), + limiter.nextRecoveryAt(now), + ), }; } @@ -408,6 +415,16 @@ export interface PoolBackpressureLimiter { tryPermitRetryDispatch(now?: number): boolean; /** Admit one probe dispatch under the same shared recovery budget. */ tryPermitProbeDispatch(now?: number): boolean; + /** + * Earliest moment this limiter could admit another recovery dispatch. + * + * A refusal has to hand back a time, or the caller has nothing to wait on and busy-loops + * against a pool that is already failing -- which is the load this limiter exists to remove. + * `now` when the allowance is not spent; otherwise the moment the oldest bucket still inside + * the window falls out of it, which is strictly in the future and is a real change point + * rather than a guess. + */ + nextRecoveryAt(now?: number): number; state(now?: number): PoolBackpressureState; } @@ -461,6 +478,19 @@ export function createPoolBackpressureLimiter( return true; } + function nextRecoveryAt(now: number): number { + const { initials, recoveries } = totals(now); + if (recoveries + 1 <= allowanceFor(initials)) return now; + // The window has to move before another recovery fits. The earliest that can happen is the + // moment the oldest bucket still inside it leaves, and every such bucket started after + // `now - windowMs`, so the answer is always strictly in the future. + for (const bucket of buckets) { + if (bucket.start <= now - policy.windowMs) continue; + return bucket.start + policy.windowMs; + } + return now + policy.windowMs; + } + return { recordInitialSend(now = Date.now()): void { bucketFor(now).initials += 1; @@ -471,6 +501,9 @@ export function createPoolBackpressureLimiter( tryPermitProbeDispatch(now = Date.now()): boolean { return tryPermit(now); }, + nextRecoveryAt(now = Date.now()): number { + return nextRecoveryAt(now); + }, state(now = Date.now()): PoolBackpressureState { const { initials, recoveries } = totals(now); return { diff --git a/tests/routing/probe-lease.test.ts b/tests/routing/probe-lease.test.ts index e3cf4ece83..1139d3140f 100644 --- a/tests/routing/probe-lease.test.ts +++ b/tests/routing/probe-lease.test.ts @@ -211,6 +211,36 @@ describe("held account dispatch", () => { backpressure: limiter, }); expect(noDetour.kind).toBe("withheld"); + // The refusal has to hand back a time the caller can wait on. This account has no probe + // state of its own -- nothing was ever granted for it -- so the probe pacing knows nothing + // and only the limiter can answer when its window moves. Asserting the kind alone is what + // let a withheld dispatch tell the caller to try again immediately, which is the same load + // as the dispatch it refused. + if (noDetour.kind === "withheld") { + expect(noDetour.retryAt).toBeGreaterThan(now); + expect(noDetour.retryAt).toBe(limiter.nextRecoveryAt(now)); + } + }); + + test("the limiter reports when its window could next admit a recovery", () => { + const now = 2_000_000; + const limiter = createPoolBackpressureLimiter({ + windowMs: 10_000, + maxRetryRatio: 0, + minRecoveryAllowance: 1, + }); + // Allowance is one and nothing has spent it, so a caller may go now. + expect(limiter.nextRecoveryAt(now)).toBe(now); + expect(limiter.tryPermitRetryDispatch(now)).toBe(true); + + // Spent. The answer is a real change point -- when the bucket holding that dispatch leaves + // the window -- not an arbitrary delay, and never `now`. + expect(limiter.tryPermitRetryDispatch(now)).toBe(false); + const retryAt = limiter.nextRecoveryAt(now); + expect(retryAt).toBeGreaterThan(now); + expect(retryAt).toBeLessThanOrEqual(now + 10_000); + // ...and once the window has moved past it, the allowance is back. + expect(limiter.tryPermitRetryDispatch(retryAt)).toBe(true); }); }); From 6317c41ee1990251f6cb0e78e71712e302d8a30f Mon Sep 17 00:00:00 2001 From: JUN Date: Wed, 16 Sep 2026 11:32:21 +0900 Subject: [PATCH 6/9] test(responses): pin the #4546 incident as one system, not five fixes (#4546) Each layer of this lane closes one seam of the #4546 amplification: the credential hop that was charged twice, the spend ledger with no caller, the refusal reported as a provider fault, the usage attributed to the wrong key, the withheld recovery that said "retry now". What none of them checks is whether the seams agree with each other. This composes the real primitives -- the request execution budget, the durable spend ledger with its request-scoped caller, the pool recovery limiter -- and asserts that the numbers describe the same events: physical sends, budget consumption, ledger reservation and settlement, and the refusal the caller is given. The scenarios are the incident's own: a request whose every layer tries to recover, concurrent requests contending for one process-wide recovery allowance, a caller that keeps its detour instead of adding a second trial to a failing account, a fan-out child spending the parent's allowance rather than a fresh one, and a restart that must neither reset a ceiling nor settle the same send twice. A fixture that only counted sends would have passed throughout the incident, which is why every case ties a send count to the spend the ledger recorded for it. --- scripts/test-layout/layout.json | 1 + tests/fixtures/test-layout-expected.json | 1 + ...responses-4546-incident-regression.test.ts | 155 ++++++++++++++++++ 3 files changed, 157 insertions(+) create mode 100644 tests/responses/responses-4546-incident-regression.test.ts diff --git a/scripts/test-layout/layout.json b/scripts/test-layout/layout.json index 1a1234c068..17fc012dc3 100644 --- a/scripts/test-layout/layout.json +++ b/scripts/test-layout/layout.json @@ -171,6 +171,7 @@ "responses-core-modules.test.ts": "responses", "responses-spend-ledger-wiring.test.ts": "responses", "responses-send-budget-errors.test.ts": "responses", + "responses-4546-incident-regression.test.ts": "responses", "chat-responses-control-integration.test.ts": "responses", "coding-agent-tool-result-images.test.ts": "adapters", "hub-usage.test.ts": "server", diff --git a/tests/fixtures/test-layout-expected.json b/tests/fixtures/test-layout-expected.json index 5d6ede1f23..6994165c61 100644 --- a/tests/fixtures/test-layout-expected.json +++ b/tests/fixtures/test-layout-expected.json @@ -3,6 +3,7 @@ "responses-core-modules.test.ts": "responses", "responses-spend-ledger-wiring.test.ts": "responses", "responses-send-budget-errors.test.ts": "responses", + "responses-4546-incident-regression.test.ts": "responses", "chat-responses-control-integration.test.ts": "responses", "coding-agent-tool-result-images.test.ts": "adapters", "hub-usage.test.ts": "server", diff --git a/tests/responses/responses-4546-incident-regression.test.ts b/tests/responses/responses-4546-incident-regression.test.ts new file mode 100644 index 0000000000..2e6436732b --- /dev/null +++ b/tests/responses/responses-4546-incident-regression.test.ts @@ -0,0 +1,155 @@ +import { describe, expect, test } from "bun:test"; +import { + CODEX_TEXT_GUARDED_BUDGET_POLICY, + createRequestExecutionBudget, +} from "../../src/lib/request-execution-budget"; +import { + createSpendReservationLedger, + type SpendJournal, +} from "../../src/lib/spend-reservation-ledger"; +import { createRequestSpendTracker } from "../../src/server/responses/request-spend"; +import { createPoolBackpressureLimiter, resolveHeldAccountDispatch } from "../../src/routing/probe-lease"; +import { clearTransientProbeLeasesForTests } from "../../src/routing/probe-lease"; + +/** + * The #4546 incident, as a system rather than as five separate fixes. + * + * The amplification was never one missing limit. Every layer that could re-send counted its own + * allowance, every recovery leg read a remainder nobody else had spent, and the spend that + * resulted was accounted nowhere that survived a restart. Each layer of this lane fixes one + * seam; what nobody checks is whether the seams agree. + * + * These compose the real primitives -- the request execution budget, the durable spend ledger + * and its request-scoped caller, the pool recovery limiter -- and assert the numbers line up: + * physical sends, budget consumption, ledger settlement and the refusal the client is given all + * describe the same events. A fixture that only counted sends would have passed throughout the + * incident. + */ +const memoryJournal = (): SpendJournal & { lines: string[] } => { + const lines: string[] = []; + return { + lines, + read: () => [...lines], + append: (line: string) => { lines.push(line); }, + rewrite: (next: string[]) => { lines.splice(0, lines.length, ...next); }, + }; +}; + +const logContext = () => ({ + provider: "pool-a", + accountLogLabel: "k0123456789abcdef0123456789abcdef", + usageLogInputTokens: 100, + spendOutputCeilingTokens: 400, +}) as Parameters[0]; + +describe("#4546 cost guard, end to end", () => { + test("a request cannot exceed its ceiling however many layers try to recover", () => { + const journal = memoryJournal(); + const ledger = createSpendReservationLedger({ journal }); + const tracker = createRequestSpendTracker(logContext(), "root-incident", ledger); + const budget = createRequestExecutionBudget(CODEX_TEXT_GUARDED_BUDGET_POLICY, "lr-incident", tracker); + + // Three same-account sends: the initial one and two transient retries. + for (let index = 0; index < 3; index += 1) { + expect(budget.reserveDispatch({ sendClass: "transient", targetKey: "pool-a|m" }).allowed).toBe(true); + } + // The base allowance is gone. A repair leg may still draw the single shared reserve... + const repair = budget.reserveDispatch({ sendClass: "repair", targetKey: "pool-a|m" }); + expect(repair.allowed).toBe(true); + // ...but an account move cannot ALSO have one. This is the intersection the incident lacked: + // each layer used to hold its own allowance, so a spent request still funded every one. + const move = budget.reserveDispatch({ sendClass: "account-failover", targetKey: "pool-b|m" }); + expect(move.allowed).toBe(false); + if (move.allowed) throw new Error("unreachable"); + expect(move.reason).toBe("final-recovery-spent"); + + expect(budget.used).toBe(CODEX_TEXT_GUARDED_BUDGET_POLICY.maxTotalModelSends); + // The ledger saw exactly the sends the budget charged -- no more, and not one fewer. + expect(ledger.snapshot("root", "root-incident")?.reserved).toBe(4 * 500); + }); + + test("concurrent requests share the recovery allowance instead of each holding one", () => { + clearTransientProbeLeasesForTests(); + const now = 5_000_000; + // One initial send in the window, so the ratio floor is the whole allowance. + const limiter = createPoolBackpressureLimiter({ + windowMs: 10_000, maxRetryRatio: 0, minRecoveryAllowance: 1, + }); + limiter.recordInitialSend(now); + + // Two requests bound to the same held account arrive together. Exactly one probes it. + const first = resolveHeldAccountDispatch({ boundAccountId: "held", now, backpressure: limiter }); + const second = resolveHeldAccountDispatch({ boundAccountId: "held", now, backpressure: limiter }); + expect(first.kind).toBe("probe"); + expect(second.kind).toBe("withheld"); + + // The refused one is told when to come back, and it is genuinely later. A refusal that said + // "now" would put the same load on the pool as the dispatch it declined. + if (second.kind === "withheld") { + expect(second.retryAt).toBeGreaterThan(now); + } + // Separate request objects cannot mint private allowances: the limiter is process-wide. + expect(limiter.state(now).recoveryDispatches).toBe(1); + expect(limiter.state(now).refusedTotal).toBeGreaterThan(0); + }); + + test("a request that keeps its detour does not spend a probe on a failing account", () => { + clearTransientProbeLeasesForTests(); + const now = 6_000_000; + const limiter = createPoolBackpressureLimiter({ + windowMs: 10_000, maxRetryRatio: 0, minRecoveryAllowance: 1, + }); + expect(resolveHeldAccountDispatch({ boundAccountId: "held", now, backpressure: limiter }).kind) + .toBe("probe"); + // The probe is out, so the next caller keeps the route that is working rather than adding a + // second trial to an account already known to be failing. + expect(resolveHeldAccountDispatch({ + boundAccountId: "held", detourAccountId: "detour", now, backpressure: limiter, + })).toEqual({ kind: "detour", accountId: "detour" }); + }); + + test("a fan-out child spends the parent's allowance, not a fresh one", () => { + const ledger = createSpendReservationLedger({ journal: memoryJournal() }); + const tracker = createRequestSpendTracker(logContext(), "root-fanout", ledger); + const parent = createRequestExecutionBudget(CODEX_TEXT_GUARDED_BUDGET_POLICY, "lr-parent", tracker); + parent.reserveDispatch({ sendClass: "initial", targetKey: "pool-a|m" }); + + // A combo child inherits the holder. The incident's second half was children each taking a + // full allowance, so a seven-hundred-child fan-out sent seven hundred times under one cap. + const child = parent; + child.reserveDispatch({ sendClass: "combo-failover", targetKey: "pool-b|m" }); + expect(parent.used).toBe(2); + expect(parent.remainingBaseSends(3)).toBe(1); + // One more move is refused: the child already spent the request's single target transition. + const third = child.reserveDispatch({ sendClass: "combo-failover", targetKey: "pool-c|m" }); + expect(third.allowed).toBe(false); + expect(ledger.snapshot("root", "root-fanout")?.reserved).toBe(2 * 500); + }); + + test("a restart neither resets the ceiling nor settles the same send twice", () => { + const journal = memoryJournal(); + const before = createSpendReservationLedger({ journal }); + const tracker = createRequestSpendTracker(logContext(), "root-restart", before); + const budget = createRequestExecutionBudget(CODEX_TEXT_GUARDED_BUDGET_POLICY, "lr-restart", tracker); + budget.reserveDispatch({ sendClass: "initial", targetKey: "pool-a|m" }); + budget.reserveDispatch({ sendClass: "transient", targetKey: "pool-a|m" }); + + // The terminal arrives and the request settles normally. + tracker.settle({ inputTokens: 120, outputTokens: 30 }); + const settledBefore = before.snapshot("root", "root-restart"); + expect(settledBefore?.settled).toBe(150); + expect(settledBefore?.unresolved).toBe(500); + expect(settledBefore?.reserved).toBe(0); + + // Restart. The journal is the whole state, and replaying it changes none of the figures -- + // a ceiling that reset here would hand the next process a fresh allowance for spend that + // already happened, and a second settlement would double-count it. + const after = createSpendReservationLedger({ journal }); + const settledAfter = after.snapshot("root", "root-restart"); + expect(settledAfter?.settled).toBe(150); + expect(settledAfter?.unresolved).toBe(500); + expect(settledAfter?.reserved).toBe(0); + // The send ids are still known, so a replayed request cannot authorise another dispatch. + expect(after.settle("lr-restart", { inputTokens: 1, outputTokens: 1 })).toBe(false); + }); +}); From 94db101206f8aa107e173df5cb2ba5ea18345b89 Mon Sep 17 00:00:00 2001 From: JUN Date: Wed, 16 Sep 2026 11:33:31 +0900 Subject: [PATCH 7/9] test(responses): pin the account-change half of the incident (#4546) The account-change scenario the incident needs, written against current behaviour because the #4710 refusal is owned by another lane and is not in this stack yet. What it pins now: continuation state is dropped and the turn continues, an uploaded file reference is classified non-portable and is NOT removed by the scrub, and the carriers must be read directly because the portability verdict reports only the first reason it finds -- a body carrying both a response id and a file reports the response id. What it documents: once the refusal lands, that body must be declined before dispatch and the refusal must win over the response id. The two properties above are what the change has to preserve, so they are asserted now. Also pins the accounting invariant that refusal owes: a decision made before dispatch spends no send and books no ledger entry. A refusal counted as a send would appear as provider load that never happened and would push a healthy account toward a cooldown. --- ...responses-4546-incident-regression.test.ts | 67 +++++++++++++++++++ 1 file changed, 67 insertions(+) diff --git a/tests/responses/responses-4546-incident-regression.test.ts b/tests/responses/responses-4546-incident-regression.test.ts index 2e6436732b..ea57ae4f7e 100644 --- a/tests/responses/responses-4546-incident-regression.test.ts +++ b/tests/responses/responses-4546-incident-regression.test.ts @@ -10,6 +10,15 @@ import { import { createRequestSpendTracker } from "../../src/server/responses/request-spend"; import { createPoolBackpressureLimiter, resolveHeldAccountDispatch } from "../../src/routing/probe-lease"; import { clearTransientProbeLeasesForTests } from "../../src/routing/probe-lease"; +import { + canPortConversationState, + collectConversationStateCarriers, + applyAccountChangeConversationStateScrub, +} from "../../src/server/responses/account-change-state"; +import { + clearConversationStateIssuerMap, + rememberConversationStateIssuer, +} from "../../src/codex/routing"; /** * The #4546 incident, as a system rather than as five separate fixes. @@ -152,4 +161,62 @@ describe("#4546 cost guard, end to end", () => { // The send ids are still known, so a replayed request cannot authorise another dispatch. expect(after.settle("lr-restart", { inputTokens: 1, outputTokens: 1 })).toBe(false); }); + + test("an account change drops continuation state and keeps the file reference intact", () => { + clearConversationStateIssuerMap(); + const bindingKey = "thread-4546-incident"; + rememberConversationStateIssuer(bindingKey, "account-a"); + + // Continuation state is portable-by-dropping: one cold turn, then the new account records + // itself as the issuer. This half of the contract does not change. + const continuation: Record = { + model: "gpt-5.4", + previous_response_id: "resp_account_a", + input: [{ type: "message", role: "user", content: [{ type: "input_text", text: "keep me" }] }], + }; + expect(applyAccountChangeConversationStateScrub({ + body: continuation, bindingKey, servingAccountId: "account-b", + })).toBe(true); + expect(continuation.previous_response_id).toBeUndefined(); + expect(continuation.input).toBeDefined(); + + // An uploaded file is not. The classifier has always said so, and it says so whether or not + // the body also carries a response id -- the verdict reports the first reason it finds, so + // the file is what the carriers must be read for. + const withFile: Record = { + model: "gpt-5.4", + previous_response_id: "resp_account_a", + input: [{ type: "message", role: "user", content: [{ type: "input_file", file_id: "file_abc123" }] }], + }; + expect(collectConversationStateCarriers(withFile).fileIds).toEqual(["file_abc123"]); + expect(canPortConversationState(collectConversationStateCarriers(withFile)).portable).toBe(false); + + // The scrub does not remove it, and must not: a file reference is content the caller + // attached, not continuation state the turn can do without. + applyAccountChangeConversationStateScrub({ + body: withFile, bindingKey, servingAccountId: "account-b", + }); + expect(collectConversationStateCarriers(withFile).fileIds).toEqual(["file_abc123"]); + + // PENDING CONTRACT (#4710, owned elsewhere): once the refusal lands, this body must be + // declined before dispatch rather than forwarded, and the refusal wins even when a + // previous_response_id is present too. When that arrives, add the refusal assertion here + // -- the two properties below are what it has to preserve, and they are asserted now so the + // change cannot quietly alter them. + clearConversationStateIssuerMap(); + }); + + test("a refusal made before dispatch spends no send and books no spend", () => { + const ledger = createSpendReservationLedger({ journal: memoryJournal() }); + const tracker = createRequestSpendTracker(logContext(), "root-refused", ledger); + const budget = createRequestExecutionBudget(CODEX_TEXT_GUARDED_BUDGET_POLICY, "lr-refused", tracker); + + // Nothing reserved, because nothing dispatched. This is the invariant every pre-dispatch + // refusal in the tree owes the accounting -- a budget refusal, a workflow ceiling, and the + // account-change file refusal #4710 is adding. A refusal counted as a send would show up as + // provider load that never existed, and would push a healthy account toward a cooldown. + expect(budget.used).toBe(0); + expect(ledger.snapshot("root", "root-refused")).toBeUndefined(); + expect(tracker.refusals).toBe(0); + }); }); From 78800ec9d3149a52291ea06e725e248b9e469e95 Mon Sep 17 00:00:00 2001 From: JUN Date: Wed, 16 Sep 2026 12:13:33 +0900 Subject: [PATCH 8/9] fix(responses): keep core.ts at its cap and stop a degraded ledger refusing sends (#4546) Four fixes, batched into one push so the queue only pays once. 1. src/server/responses/core.ts was 214 lines against a 210-line cap in tests/fixtures/file-size-baseline.json. The spend-observer wiring added four lines of comment and continuation. The comment is now one line and the expression one line, and the file is back at its cap. The ratchet only ever lowers caps, so growing past one is a hard failure rather than a nudge. 2. The spend tracker refused a dispatch on ANY ledger denial. Only an operator's configured ceiling should: capacity, durability and a journal this process could not prove complete all mean the ledger cannot ACCOUNT for the send, which is not a reason to refuse one. An unconfigured install keeps the count caps it already had and is not newly refused, and a degraded ledger must not become an outage. 3. The shared ledger is now resolved on the first charge rather than when the request is built. It opens a journal under the OpenCodex home, and a request that never dispatches has no business creating one; this also means the home in effect at dispatch is the one written to, instead of whichever home was current when the first request of the process happened to be constructed. 4. Three assertions in the new tests claimed states the code never reaches. The concurrent-probe case asserted a limiter refusal, but the second caller short-circuits on the lease before it reaches the limiter and costs no allowance; the shared bound is now proved by asking the limiter directly. The exhausted-ceiling case asserted final-recovery-spent where the total ceiling refuses first, so it asserts total-exhausted and checks reserveSpent separately for the point it was making. The unstructured-error control asserted an exact 502 where the property that matters is that the identity is gone, so it asserts that instead. Tests are not typechecked -- tsconfig includes only src -- so a test that asserts the opposite of what it claims passes silently. These were found by reading, not by running. --- src/server/responses/core.ts | 8 ++---- src/server/responses/request-spend.ts | 27 +++++++++++++------ ...responses-4546-incident-regression.test.ts | 21 +++++++++++---- .../responses-send-budget-errors.test.ts | 6 ++++- 4 files changed, 42 insertions(+), 20 deletions(-) diff --git a/src/server/responses/core.ts b/src/server/responses/core.ts index d09bfafb8c..89bf34dad3 100644 --- a/src/server/responses/core.ts +++ b/src/server/responses/core.ts @@ -57,12 +57,8 @@ export async function handleResponses( visionDescribeTerminal: options.visionDescribeTerminal === true || req.headers.get("x-opencodex-vision-describe") === "1", translatorBudget, - // Created once at genuine ingress; a combo child arrives with the parent's holder already - // in options and must not start a fresh allowance. - // The spend observer is installed with it, for the same reason: a child inherits the - // parent's ledger entries instead of opening a second set for the same physical sends. - sendBudget: options.sendBudget - ?? createRequestExecutionBudget(undefined, undefined, attachRequestSpendTracker(req, logCtx)), + // Once at ingress, spend observer included: a combo child inherits the parent's holder. + sendBudget: options.sendBudget ?? createRequestExecutionBudget(undefined, undefined, attachRequestSpendTracker(req, logCtx)), }); return ownsBudget ? finalizeOwnedTranslatorBudget(response, translatorBudget) : response; } catch (error) { diff --git a/src/server/responses/request-spend.ts b/src/server/responses/request-spend.ts index 0f7c088c05..b238c43395 100644 --- a/src/server/responses/request-spend.ts +++ b/src/server/responses/request-spend.ts @@ -44,8 +44,14 @@ export function createRequestSpendTracker( "provider" | "accountLogLabel" | "usageLogInputTokens" | "spendOutputCeilingTokens" >, rootId: string | undefined, - ledger: SpendReservationLedger = sharedSpendLedger(), + injected?: SpendReservationLedger, ): RequestSpendTracker { + // Resolved on the first CHARGE, not when the request is built. The shared ledger opens a + // journal under the OpenCodex home, and a request that never dispatches -- refused at + // admission, answered locally, cancelled before its first send -- has no business creating + // one. It also means the home in effect at dispatch is the one that gets written. + let ledgerRef: SpendReservationLedger | undefined = injected; + const ledger = (): SpendReservationLedger => (ledgerRef ??= sharedSpendLedger()); // Every send this request still owes the ledger an answer for, oldest first. const live: string[] = []; let refusals = 0; @@ -61,12 +67,12 @@ export function createRequestSpendTracker( * than unresolved, for at most one send per request. */ const confirmOlderSends = (): void => { - for (let index = 0; index < live.length - 1; index += 1) ledger.markDispatched(live[index] as string); + for (let index = 0; index < live.length - 1; index += 1) ledger().markDispatched(live[index] as string); }; return { charge(): boolean { const sendId = randomUUID(); - const decision = ledger.reserve({ + const decision = ledger().reserve({ sendId, scopes: { ...(rootId !== undefined ? { rootId } : {}), @@ -80,7 +86,12 @@ export function createRequestSpendTracker( }); if (!decision.reserved) { refusals += 1; - return false; + // Only an operator's configured ceiling refuses a dispatch. Every other denial -- + // capacity, durability, a journal this process could not prove complete -- means the + // ledger cannot ACCOUNT for this send, which is not a reason to refuse one. An + // unconfigured install keeps the count caps it already had and is not newly refused, + // and a degraded ledger must not become an outage. + return decision.denial.reason !== "spend-limit-exceeded"; } live.push(sendId); confirmOlderSends(); @@ -91,7 +102,7 @@ export function createRequestSpendTracker( if (sendId === undefined) return; // Undispatched, so this returns the tokens. If the send was already confirmed by a later // one, `abandon` refuses and unresolved is the only honest outcome left. - if (!ledger.abandon(sendId)) ledger.markLost(sendId); + if (!ledger().abandon(sendId)) ledger().markLost(sendId); }, settle(usage: TerminalSpendUsage | undefined): void { if (resolved) return; @@ -100,16 +111,16 @@ export function createRequestSpendTracker( if (terminal !== undefined) { const reported = typeof usage?.inputTokens === "number" || typeof usage?.outputTokens === "number"; if (reported) { - ledger.settle(terminal, { + ledger().settle(terminal, { inputTokens: usage?.inputTokens ?? 0, outputTokens: usage?.outputTokens ?? 0, }); } else { // The response never reported usage. It may still have been billed. - ledger.markLost(terminal); + ledger().markLost(terminal); } } - for (const sendId of live.splice(0)) ledger.markLost(sendId); + for (const sendId of live.splice(0)) ledger().markLost(sendId); }, get refusals(): number { return refusals; }, }; diff --git a/tests/responses/responses-4546-incident-regression.test.ts b/tests/responses/responses-4546-incident-regression.test.ts index ea57ae4f7e..348d9ac898 100644 --- a/tests/responses/responses-4546-incident-regression.test.ts +++ b/tests/responses/responses-4546-incident-regression.test.ts @@ -65,12 +65,15 @@ describe("#4546 cost guard, end to end", () => { // The base allowance is gone. A repair leg may still draw the single shared reserve... const repair = budget.reserveDispatch({ sendClass: "repair", targetKey: "pool-a|m" }); expect(repair.allowed).toBe(true); - // ...but an account move cannot ALSO have one. This is the intersection the incident lacked: - // each layer used to hold its own allowance, so a spent request still funded every one. + // ...and taking it is what spends the single shared reserve. + expect(budget.reserveSpent).toBe(true); + // An account move cannot ALSO have one. The ceiling is what refuses it, which is the + // intersection the incident lacked: each layer used to hold its own allowance, so a spent + // request still funded every one of them. const move = budget.reserveDispatch({ sendClass: "account-failover", targetKey: "pool-b|m" }); expect(move.allowed).toBe(false); if (move.allowed) throw new Error("unreachable"); - expect(move.reason).toBe("final-recovery-spent"); + expect(move.reason).toBe("total-exhausted"); expect(budget.used).toBe(CODEX_TEXT_GUARDED_BUDGET_POLICY.maxTotalModelSends); // The ledger saw exactly the sends the budget charged -- no more, and not one fewer. @@ -99,7 +102,13 @@ describe("#4546 cost guard, end to end", () => { } // Separate request objects cannot mint private allowances: the limiter is process-wide. expect(limiter.state(now).recoveryDispatches).toBe(1); - expect(limiter.state(now).refusedTotal).toBeGreaterThan(0); + // The withheld result above short-circuits on the lease before it reaches the limiter, so + // it costs no allowance -- asserting a refusal there would claim a path the code never + // took. The shared bound is proved by asking the limiter directly: a third leg, with its + // own request object and its own send budget, finds the one allowance already spent. + expect(limiter.tryPermitRetryDispatch(now)).toBe(false); + expect(limiter.state(now).refusedTotal).toBe(1); + expect(limiter.state(now).recoveryDispatches).toBe(1); }); test("a request that keeps its detour does not spend a probe on a failing account", () => { @@ -158,8 +167,10 @@ describe("#4546 cost guard, end to end", () => { expect(settledAfter?.settled).toBe(150); expect(settledAfter?.unresolved).toBe(500); expect(settledAfter?.reserved).toBe(0); - // The send ids are still known, so a replayed request cannot authorise another dispatch. + // Settlement is keyed on the send id the ledger issued, not on the request. An id it never + // issued -- a caller guessing, or a replayed logical request id -- settles nothing. expect(after.settle("lr-restart", { inputTokens: 1, outputTokens: 1 })).toBe(false); + expect(after.snapshot("root", "root-restart")?.settled).toBe(150); }); test("an account change drops continuation state and keeps the file reference intact", () => { diff --git a/tests/responses/responses-send-budget-errors.test.ts b/tests/responses/responses-send-budget-errors.test.ts index 638bb1a2f4..6e1306980b 100644 --- a/tests/responses/responses-send-budget-errors.test.ts +++ b/tests/responses/responses-send-budget-errors.test.ts @@ -55,7 +55,11 @@ describe("a spent send budget is reported as this proxy's refusal", () => { type: "error", message: "request send budget exhausted before dispatch", }); - expect(unstructured.httpStatus).toBe(502); + // Asserted as the property rather than the exact status: what matters is that the identity + // is gone, so the client cannot tell this from an upstream fault and does not get the 429 + // that would stop it retrying. + expect(unstructured.httpStatus).not.toBe(429); + expect(unstructured.error.code).not.toBe(SEND_BUDGET_EXHAUSTED_CODE); }); test("both adapter catch sites answer before the upstream-failure description", () => { From d48e3d2749daa81f847fea7da8960a6c174923ff Mon Sep 17 00:00:00 2001 From: JUN Date: Wed, 16 Sep 2026 12:41:30 +0900 Subject: [PATCH 9/9] fix(lib): keep an exhausted ceiling exhausted across a restart (#4546) Two source-of-truth failures from the previous tip run, both mine. tests/lib/transient-budget-scope-source.test.ts pinned the exact core.ts line that mints the request's send budget, and bl2 changed it to install the spend observer. The oracle now matches the new shape and additionally asserts the observer is attached at the same place, which is the property that actually matters: a combo child inherits the parent's holder and must not open a second set of ledger entries for the same physical sends. tests/lib/spend-reservation-ledger.test.ts caught a real defect in the replay reconciliation, not a stale expectation. An exhausted scope must still be exhausted after a restart -- that is the whole reason the ledger is on disk -- and abandoning a replayed undispatched reservation handed its tokens back and reset the ceiling. The distinction I drew was wrong. "Open" does not prove nothing was sent: the torn-tail rule immediately above says the journal may be missing its last record, so a send can dispatch and die before its dispatch record lands. Both live states now resolve to unresolved spend, which is the conservative answer and the one that preserves the ceiling. The bl2 wiring test asserted the old split and is updated to the new figures, along with the structure contract and the tracker's own comment. --- src/lib/spend-reservation-ledger.ts | 25 +++++++++---------- src/server/responses/request-spend.ts | 6 ++--- structure/transports/responses.md | 16 ++++++------ .../lib/transient-budget-scope-source.test.ts | 5 +++- .../responses-spend-ledger-wiring.test.ts | 9 ++++--- 5 files changed, 33 insertions(+), 28 deletions(-) diff --git a/src/lib/spend-reservation-ledger.ts b/src/lib/spend-reservation-ledger.ts index 1aeb389333..de7dba4e05 100644 --- a/src/lib/spend-reservation-ledger.ts +++ b/src/lib/spend-reservation-ledger.ts @@ -670,23 +670,22 @@ export function createSpendReservationLedger(options: { } } // A reservation that survived replay has no owner left. The process that made it is gone, - // so nothing in this one can ever settle it, and leaving it live holds its tokens against - // the scope forever -- a ceiling that only ever tightens, which is the opposite of the - // bound this store exists to keep. Deleting the entry is not the alternative: that would - // hand the same send id a second reservation. + // so nothing in this one can ever settle it, and leaving it live means the send stays + // pending forever against a scope that can never resolve it. Deleting the entry is not the + // alternative either: that would hand the same send id a second reservation. // - // The distinction is the one the rest of the module already draws. An UNDISPATCHED - // reservation never reached the wire, so it is abandoned and its tokens come back. A - // DISPATCHED one may already have been billed, so it becomes unresolved spend. Both are - // appended, so the file agrees with memory and the next restart has nothing left to do. + // Both live states resolve to UNRESOLVED, including an undispatched one. The tempting + // distinction -- open never reached the wire, so give its tokens back -- assumes the + // journal is complete up to the crash, and the torn-tail handling above says it is not: a + // send can dispatch and die before its dispatch record lands. Abandoning that reservation + // returns tokens for a send that may have been billed, and worse, it RESETS a ceiling that + // had already fired. An exhausted scope staying exhausted across a restart is the whole + // reason this store is on disk. const reconciledAt = now(); for (const [send, reservation] of reservations) { if (!isLive(reservation.status)) continue; - const abandoned = reservation.status === "open"; - applyResolve(send, abandoned ? "abandoned" : "lost", 0, reconciledAt); - append(abandoned - ? { v: 1, kind: "abandon", send, at: reconciledAt } - : { v: 1, kind: "lost", send, at: reconciledAt }); + applyResolve(send, "lost", 0, reconciledAt); + append({ v: 1, kind: "lost", send, at: reconciledAt }); } } diff --git a/src/server/responses/request-spend.ts b/src/server/responses/request-spend.ts index b238c43395..3d9a9fc2e3 100644 --- a/src/server/responses/request-spend.ts +++ b/src/server/responses/request-spend.ts @@ -62,9 +62,9 @@ export function createRequestSpendTracker( * A booking is only marked dispatched once a LATER send exists, because that later send * proves the earlier one left. The newest booking stays open until it is settled, so a * reservation the budget hands back -- a rotation that found no alternate, a rebuild - * abandoned before the wire -- can still be released for free. The cost of that choice is - * bounded and stated: a hard crash between reserving and sending replays as abandoned rather - * than unresolved, for at most one send per request. + * abandoned before the wire -- can still be released for free while this process is alive. + * A crash resolves every surviving reservation as unresolved spend regardless of this mark, + * because a journal that lost its tail cannot prove a send never left. */ const confirmOlderSends = (): void => { for (let index = 0; index < live.length - 1; index += 1) ledger().markDispatched(live[index] as string); diff --git a/structure/transports/responses.md b/structure/transports/responses.md index 907abf05cb..87e6a0dc56 100644 --- a/structure/transports/responses.md +++ b/structure/transports/responses.md @@ -741,19 +741,21 @@ forget to book. The previous attempt at this wiring shipped the whole reserve/di vocabulary with no caller at all (#4707), which is the failure mode this shape rules out. A booking is confirmed dispatched only once a LATER send exists, because that later send proves -the earlier one left. The newest booking stays open, so a reservation the budget hands back can -still be released for free. The stated cost: a hard crash between reserving and sending replays -as abandoned rather than unresolved, for at most one send per request. +the earlier one left. The newest booking stays open, so a reservation the budget hands back +during this process's lifetime can still be released for free. Settlement follows what the request learned. The terminal usage belongs to the last send that left, so that one settles with the real figure; every earlier send failed without reporting usage of its own and may still have been billed, so it becomes unresolved spend rather than free. A request that reports no usage at all leaves all of them unresolved. -Replay resolves what nobody is left to settle: an undispatched reservation is abandoned and a -dispatched one becomes unresolved, both journaled so a second restart has nothing to redo. -Without it a reservation whose process died held its tokens against the scope forever, which is a -ceiling that only tightens. `tests/responses/responses-spend-ledger-wiring.test.ts` pins the +Replay resolves what nobody is left to settle, and resolves it as unresolved spend whatever state +it was in. Giving an undispatched one its tokens back would assume the journal is complete up to +the crash, and the torn-tail rule says it is not: a send can dispatch and die before its dispatch +record lands. It would also reset a ceiling that had already fired, and an exhausted scope +staying exhausted across a restart is the whole reason this store is on disk. Both are journaled, +so a second restart has nothing to redo. +`tests/responses/responses-spend-ledger-wiring.test.ts` pins the booking, the settlement split, the refund, a ceiling that refuses a dispatch rather than describing it afterwards, and the restart. diff --git a/tests/lib/transient-budget-scope-source.test.ts b/tests/lib/transient-budget-scope-source.test.ts index 8bc9c8d0ea..a26a18bfa8 100644 --- a/tests/lib/transient-budget-scope-source.test.ts +++ b/tests/lib/transient-budget-scope-source.test.ts @@ -47,7 +47,10 @@ describe("transient send budget stays request-scoped", () => { expect(core.match(/const sendBudget = options\.sendBudget \?\? createRequestExecutionBudget\(\);/g)) .toHaveLength(1); // Genuine ingress mints it; a child arrives with the parent's and must not replace it. - expect(core).toContain("sendBudget: options.sendBudget ?? createRequestExecutionBudget(),"); + expect(core).toContain("sendBudget: options.sendBudget ?? createRequestExecutionBudget("); + // ...and the durable spend observer is installed WITH it, for the same reason: a child that + // inherited the holder must not open a second set of ledger entries for the same sends. + expect(core).toContain("attachRequestSpendTracker(req, logCtx)"); // The regressed shape: a counter local to one call frame, which a combo child restarts. expect(core).not.toContain("let transientSendsUsed = 0;"); expect(core.match(/const remainingTransientSendBudget = \(budget: number\): number =>/g)).toHaveLength(1); diff --git a/tests/responses/responses-spend-ledger-wiring.test.ts b/tests/responses/responses-spend-ledger-wiring.test.ts index fb7a724d36..fec30f94e6 100644 --- a/tests/responses/responses-spend-ledger-wiring.test.ts +++ b/tests/responses/responses-spend-ledger-wiring.test.ts @@ -126,15 +126,16 @@ describe("the request path books every physical send on the durable ledger", () const root = after.snapshot("root", "root-e"); // Nothing stays reserved: a reservation with no owner would hold its tokens forever. expect(root?.reserved).toBe(0); - // The confirmed send may already have been billed, so it keeps its tokens as unresolved; - // the one still open never reached the wire and gives them back. - expect(root?.unresolved).toBe(500); + // Both keep their tokens as unresolved, including the one still open. A send can dispatch + // and die before its dispatch record lands, so "open" does not prove nothing was sent -- + // and handing those tokens back would reset a ceiling that had already fired. + expect(root?.unresolved).toBe(1000); expect(root?.settled).toBe(0); // Replaying the same journal again is idempotent: the reconciliation was journaled, so a // second restart has nothing left to resolve and cannot double-book it. const third = createSpendReservationLedger({ journal }); - expect(third.snapshot("root", "root-e")?.unresolved).toBe(500); + expect(third.snapshot("root", "root-e")?.unresolved).toBe(1000); expect(third.snapshot("root", "root-e")?.reserved).toBe(0); }); });