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