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/scripts/test-layout/layout.json b/scripts/test-layout/layout.json index 91de3bda60..4b3ccee9d5 100644 --- a/scripts/test-layout/layout.json +++ b/scripts/test-layout/layout.json @@ -167,9 +167,11 @@ } }, "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", + "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/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/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/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/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/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..2863105d7a 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,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); - noteAttemptSend(logCtx.activeAttempt, 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 @@ -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, @@ -474,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/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 c4ba12f5ef..4b9e417818 100644 --- a/src/server/responses/compact.ts +++ b/src/server/responses/compact.ts @@ -142,7 +142,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 290f9b8d3b..e1d1758696 100644 --- a/src/server/responses/core-codex-account.ts +++ b/src/server/responses/core-codex-account.ts @@ -67,7 +67,7 @@ import { recordAdapterTier, sealRequestAttemptIdentity, recordAttemptCredentialSource, - noteAttemptSend, + noteProviderAttemptSend, } from "../request-log"; import { codexAuthContextLogLabel } from "../../codex/account-label"; import { chargeWorkflowSends } from "../../lib/workflow-budget"; @@ -724,7 +724,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/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/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-spend.ts b/src/server/responses/request-spend.ts index 0f7c088c05..3d9a9fc2e3 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; @@ -56,17 +62,17 @@ 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); + 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/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 7a4d23583e..9c77eaac24 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 e368479497..31221b4b38 100644 --- a/structure/catalog.md +++ b/structure/catalog.md @@ -357,7 +357,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 ec86ef8027..c7a8e7c8a5 100644 --- a/structure/clients/claude-desktop.md +++ b/structure/clients/claude-desktop.md @@ -112,7 +112,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 850c7ac386..a6cb4c11a4 100644 --- a/structure/codex-home.md +++ b/structure/codex-home.md @@ -283,3 +283,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 e7ffd45769..e756575a91 100644 --- a/structure/config.md +++ b/structure/config.md @@ -281,7 +281,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 503a8bea80..0ad47b07e2 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 0502f6d7c4..e3a479a3da 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 0fbdcefc3e..a4ab2ae1e0 100644 --- a/structure/ops/docs-and-release.md +++ b/structure/ops/docs-and-release.md @@ -344,7 +344,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 ea9630cb3b..e9a780ee53 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 ee5356c228..9b45eaf651 100644 --- a/structure/providers/cursor.md +++ b/structure/providers/cursor.md @@ -132,3 +132,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 a5dabcd21d..6466685e1b 100644 --- a/structure/providers/openai-tiers.md +++ b/structure/providers/openai-tiers.md @@ -593,4 +593,5 @@ Two call sites need the rule — the live path in `reevaluateAffinityQuota` and 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. `src/codex/auth-api/login-flow.ts` distinguishes HTTP 429 from an attempted warmup as `codex_warmup_rate_limited` and preserves that code in OAuth status. Failed attempted warmup does not persist replacement credentials; quota-confirmed deferred registration and HTTP 401/403 handling remain separate. `src/codex/warmup.ts` retains a known 429 when bounded error-body draining times out. diff --git a/structure/providers/xai-grok.md b/structure/providers/xai-grok.md index 2d98e7860d..d146bc53fe 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 40fe7301ae..7eaa1eea8e 100644 --- a/structure/runtime.md +++ b/structure/runtime.md @@ -478,3 +478,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 8e6e96aed9..051031f512 100644 --- a/structure/subagents.md +++ b/structure/subagents.md @@ -329,7 +329,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 8f7967db01..b9b3980bf9 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 d2b8553c97..91d527750a 100644 --- a/structure/transports/inventory.md +++ b/structure/transports/inventory.md @@ -98,7 +98,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 19f36d4545..f2f96927c9 100644 --- a/structure/transports/responses.md +++ b/structure/transports/responses.md @@ -626,6 +626,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 @@ -785,19 +794,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. @@ -833,6 +844,11 @@ 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. ## Combo output headroom A combo child is admitted against two budgets, not one. `resolveInputCeiling` in 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/fixtures/test-layout-expected.json b/tests/fixtures/test-layout-expected.json index 31b0ed04b4..5f9ab55449 100644 --- a/tests/fixtures/test-layout-expected.json +++ b/tests/fixtures/test-layout-expected.json @@ -1,7 +1,9 @@ { + "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", + "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/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/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/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..5eee77907c 100644 --- a/tests/responses/chat-completions-endpoint.test.ts +++ b/tests/responses/chat-completions-endpoint.test.ts @@ -1606,57 +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?.[0]?.recoveryKinds).toEqual(["rate-limit-429", "key-429"]); - } 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/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/responses/responses-4546-incident-regression.test.ts b/tests/responses/responses-4546-incident-regression.test.ts new file mode 100644 index 0000000000..348d9ac898 --- /dev/null +++ b/tests/responses/responses-4546-incident-regression.test.ts @@ -0,0 +1,233 @@ +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"; +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. + * + * 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); + // ...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("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. + 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); + // 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", () => { + 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); + // 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", () => { + 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); + }); +}); 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", () => { 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); }); }); 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); }); }); diff --git a/tests/server/server-combo-failover-e2e.test.ts b/tests/server/server-combo-failover-e2e.test.ts index f636e3480f..e9f1f7047c 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 { registerComboContextOverflowCases } from "../helpers/combo-context-overflow-cases"; import { registerComboContextHeadroomCases } from "../helpers/combo-context-headroom-cases"; import { sessionLaneIdFromRequest } from "../../src/server/request-log-conversation"; @@ -61,6 +62,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; @@ -105,7 +107,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 }); }, }; } @@ -254,22 +257,6 @@ function responsesSuccess(text: string, model = "responses-model"): Record = {}, -): OcxProviderConfig { - return { - adapter, - baseUrl: url, - allowPrivateNetwork: url.includes("127.0.0.1"), - authMode: "key", - apiKey, - ...extra, - }; -} - function comboConfig( providers: OcxConfig["providers"], targets = Object.keys(providers).map((name, index) => ({ provider: name, model: `m${index + 1}` })), @@ -1837,7 +1824,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; @@ -1858,11 +1845,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..4bf924c249 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"; @@ -787,3 +898,164 @@ 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"); + } +}); + +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); } +}); 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/key-attribution.test.ts b/tests/usage/key-attribution.test.ts new file mode 100644 index 0000000000..949d1e4a1c --- /dev/null +++ b/tests/usage/key-attribution.test.ts @@ -0,0 +1,139 @@ +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 { readFileSync } from "node:fs"; +import { repoPath } from "../helpers/repo-root"; +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("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 }; + 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 }, + }); + }); +});