From fe61b17c87ee42152d2e388590c05926596ba337 Mon Sep 17 00:00:00 2001 From: JUN Date: Sun, 20 Sep 2026 21:40:00 +0900 Subject: [PATCH 01/10] feat(usage): record why a request failed, in the landed vocabulary #2366 asked for durable failure attribution and shipped its own FailureSide and seven-member FailureStage to carry it. Lane C2 took the rehydration half and left that vocabulary behind, because defining a second one beside the stage and cause model that had just landed is the class of defect that blocked 2.60.0. This is the same answer expressed in the landed vocabulary. PersistedUsageAttempt and PersistedUsageEntry now carry failureStage and failureCause, both closed roster members. The resend verdict they imply is NOT stored: it is derived at read time, so a row written by an older build can never carry a verdict the current table would no longer reach. The derivation reads only closed values -- an HTTP status, a terminal status, a close reason, a transport phase, a recovery kind. errorCode and upstreamError are deliberately excluded: both are assembled partly from upstream text, so a classification keyed on them is a different answer per provider and per locale, and a grouping key built from them cannot promise it carries no content. That exclusion is what lets the pair be a Prometheus label and a fingerprint component without a masking pass. It runs at addFinalRequestLog, the one seam every request passes exactly once whatever transport served it, and before the attempt snapshot, so the row that reaches disk and the live attempt object carry the same pair. addRequestLog rebuilds the persisted row field by field rather than spreading it, so the pair is written there explicitly -- a field omitted at that line reaches /api/logs and never reaches usage.jsonl, which is the surface the derived projection reads. The stage and cause rosters move to src/usage/telemetry-contract.ts and src/lib/request-failure-model.ts re-exports them, the same relocation lane C2 made for the recovery roster and for the same reason: the dashboard renders a label per member, and a type-only import of the table module would drag its import graph into the browser project. The decision tables stay where they were. The test runs over a cross product built from the rosters themselves rather than a written-out list, so a member added later widens the space instead of leaving a case nobody wrote. Co-authored-by: chilung --- scripts/test-layout/layout.json | 1 + src/lib/request-failure-attribution.ts | 146 ++++++++++++++++++++++ src/lib/request-failure-model.ts | 124 ++++-------------- src/server/request-log.ts | 44 +++++++ src/usage/log.ts | 67 +++++++++- src/usage/telemetry-contract.ts | 108 ++++++++++++++++ tests/fixtures/test-layout-expected.json | 1 + tests/lib/failure-attribution.test.ts | 152 +++++++++++++++++++++++ 8 files changed, 543 insertions(+), 100 deletions(-) create mode 100644 src/lib/request-failure-attribution.ts create mode 100644 tests/lib/failure-attribution.test.ts diff --git a/scripts/test-layout/layout.json b/scripts/test-layout/layout.json index a8d43bc015c..23a1b837451 100644 --- a/scripts/test-layout/layout.json +++ b/scripts/test-layout/layout.json @@ -1190,6 +1190,7 @@ "reasoning-replay-scope-source.test.ts": "lib", "redact.test.ts": "lib", "failure-stage-model.test.ts": "lib", + "failure-attribution.test.ts": "lib", "relay-eager.test.ts": "server", "release-helper.test.ts": "ci-workflows", "release-notes.test.ts": "ci-workflows", diff --git a/src/lib/request-failure-attribution.ts b/src/lib/request-failure-attribution.ts new file mode 100644 index 00000000000..cd1c0c0464c --- /dev/null +++ b/src/lib/request-failure-attribution.ts @@ -0,0 +1,146 @@ +/** + * Derive how far a failed request got and why, from the closed facts the recorder already holds. + * + * #2366 asked for durable failure attribution and shipped its own `FailureSide` and seven-member + * `FailureStage` to carry it. Those are a second attribution vocabulary beside the one that + * landed in {@link ../lib/request-failure-model}, and two vocabularies for one question is the + * class of defect that blocked 2.60.0. This module is the same answer expressed in the landed + * vocabulary: no new stage names, no new cause names, and no new record store. + * + * Everything it reads is a CLOSED value the row already carries -- an HTTP status, a terminal + * status, a close reason, a transport phase, a recovery kind. It never reads `errorCode` or + * `upstreamError`, which are open strings assembled partly from upstream text: a classification + * keyed on those is a different answer per provider and per locale, and a grouping key built from + * them cannot promise it carries no content. + * + * MUST stay a leaf. Its only imports are types and the two tables it decides with, so nothing + * here can pull the usage or budget subsystems into a request path that lacked them. + */ +import type { AttemptRecoveryKind, RequestFailureCause, RequestFailureStage } from "../usage/telemetry-contract"; +import { causeForRecoveryKind } from "./request-failure-model"; +import { classifyRequestOutcome, type RequestOutcomeFacts } from "../usage/request-outcome"; + +/** + * What the recorder knows about one finished exchange at the single seam every request passes. + * + * Deliberately the same narrow set {@link RequestOutcomeFacts} reads, plus the four observation + * facts a stage needs. A field that could carry a provider name, a model, an account or upstream + * text is absent by construction rather than by review. + */ +export interface RequestFailureFacts extends RequestOutcomeFacts { + readonly transportPhase?: "pre_headers" | "mid_stream" | "terminal_sse" | undefined; + /** True once any output-bearing event reached the caller; `firstOutputMs` is the usual source. */ + readonly outputObserved?: boolean | undefined; + /** True once a tool call or other externally visible effect was relayed to the caller. */ + readonly sideEffectObserved?: boolean | undefined; + /** True when this proxy answered the turn itself and issued no upstream request. */ + readonly locallyAnswered?: boolean | undefined; + /** Recovery kinds recorded on the attempt that ended the request. */ + readonly recoveryKinds?: readonly AttemptRecoveryKind[] | undefined; +} + +/** + * How far the caller's view of the exchange got. + * + * Total by construction and ordered downward from the most committed observation, so a fact that + * proves a later stage wins over one that only proves an earlier one. The boundary between + * `headers-only` and `protocol-prelude` is the one genuinely debatable step -- a non-streaming + * 4xx error body is a body, but not a protocol body event -- and it is safe to argue about + * because both stages carry the same `nothing-observed` commitment, so no resend decision turns + * on which side of it a row lands. + */ +export function deriveRequestFailureStage(facts: RequestFailureFacts): RequestFailureStage { + if (facts.terminalStatus === "completed" && facts.outputObserved === true) return "terminal"; + if (facts.sideEffectObserved === true) return "side-effect"; + if (facts.outputObserved === true) return "semantic-output"; + if (facts.terminalStatus !== undefined + || facts.closeReason === "terminal" + || facts.transportPhase === "mid_stream" + || facts.transportPhase === "terminal_sse") return "protocol-prelude"; + if (facts.status >= 100) return "headers-only"; + return "pre-header"; +} + +/** + * Recovery kinds whose cause survives as the FINAL cause when the request ends on the status that + * recovery was made for. + * + * `causeForRecoveryKind` answers why a recovery was ATTEMPTED, which is usually a different + * question from why the request finally failed -- a request that recovered from a 401 and then + * died on a 500 failed for the 500. The two kinds below are the exception: each names a rejection + * the status alone cannot distinguish from an ordinary bad request, so when the request also ends + * on that status the recovery kind is the only evidence of which 4xx it was. + */ +const STATUS_CONFIRMED_RECOVERY_KINDS: Readonly>> = Object.freeze({ + "opaque-blob-rejection": 400, + "reasoning-effort-downgrade": 400, +}); + +function refinedFourHundredCause( + facts: RequestFailureFacts, +): RequestFailureCause | undefined { + for (const kind of facts.recoveryKinds ?? []) { + const confirmedStatus = STATUS_CONFIRMED_RECOVERY_KINDS[kind]; + if (confirmedStatus !== undefined && confirmedStatus === facts.status) return causeForRecoveryKind(kind); + } + return undefined; +} + +/** + * Why the request failed. + * + * Returns `undefined` for an outcome that is not a failure. An incomplete turn is a real + * shortfall and gets a stage, but this dictionary answers "why did it fail", and a turn cut short + * by `max_output_tokens` did not fail for any of these reasons; inventing one would put a + * fabricated cause into a metric label and a grouping key. + * + * The status is the primary evidence because it is the one fact every transport produces. Two + * refinements sit above it, both from closed values: a client cancel is known from the close + * reason before any status is consulted, and a 400 that a recovery kind identified as a rejected + * ciphertext or a rejected reasoning parameter is not the same answer as a rejected payload. + */ +export function deriveRequestFailureCause(facts: RequestFailureFacts): RequestFailureCause | undefined { + const outcome = classifyRequestOutcome(facts); + if (outcome === "completed" || outcome === "incomplete") return undefined; + if (outcome === "aborted") return "client-cancelled"; + if (facts.locallyAnswered === true) return "local-refusal"; + + const status = facts.status; + // A 2xx head that carried a failed terminal: the origin ran the turn and said it failed. With + // no output relayed the useful distinction is that nothing usable came back at all. + if (status >= 100 && status < 400) { + return facts.outputObserved === true ? "upstream-fault" : "empty-output"; + } + if (status === 401) return "credential-rejected"; + if (status === 403) return "credential-rejected"; + if (status === 413) return "payload-too-large"; + if (status === 429) return "rate-limit"; + if (status === 451) return "policy-refusal"; + if (status === 503) return "upstream-declined"; + if (status >= 500) return "upstream-fault"; + if (status >= 400) return refinedFourHundredCause(facts) ?? "payload-rejected"; + // No response head at all. A stream that began and died is ambiguous about whether the origin + // ran the turn; a request that never reached a mid-stream phase provably did not send. + return facts.transportPhase === "mid_stream" || facts.transportPhase === "terminal_sse" + ? "transport-ambiguous" + : "transport-unsent"; +} + +export interface RequestFailureAttribution { + stage: RequestFailureStage; + cause?: RequestFailureCause; +} + +/** + * The attribution to persist, or `undefined` when the request completed. + * + * A completed request has no failure to attribute, and recording a stage for one would put a + * `terminal` row into every grouping that exists to find failures. + */ +export function deriveRequestFailureAttribution( + facts: RequestFailureFacts, +): RequestFailureAttribution | undefined { + if (classifyRequestOutcome(facts) === "completed") return undefined; + const cause = deriveRequestFailureCause(facts); + return { stage: deriveRequestFailureStage(facts), ...(cause ? { cause } : {}) }; +} diff --git a/src/lib/request-failure-model.ts b/src/lib/request-failure-model.ts index f12517f2a45..1fc3211a66b 100644 --- a/src/lib/request-failure-model.ts +++ b/src/lib/request-failure-model.ts @@ -12,41 +12,42 @@ * `PersistedUsageEntry` in src/usage/log.ts, and every projection below reads those structurally * rather than growing a parallel history. * - * MUST stay a leaf. Its only imports are types, erased at runtime, so nothing here can pull the - * usage or budget subsystems into a request path that did not already have them. + * MUST stay a leaf. Its one runtime import is `src/usage/telemetry-contract.ts`, which has no + * imports at all; everything else it names is a type, erased at runtime. So nothing here can + * pull the usage or budget subsystems into a request path that did not already have them. */ import type { SendClass } from "./request-execution-budget"; -import type { AttemptRecoveryKind } from "../usage/telemetry-contract"; +import { + REQUEST_FAILURE_STAGES, + type AttemptRecoveryKind, + type RequestFailureCause, + type RequestFailureStage, + type ResendPermission, +} from "../usage/telemetry-contract"; /** - * How far the exchange got, ordered by how much the DOWNSTREAM CLIENT observed. + * The vocabulary this module decides over is DECLARED in `src/usage/telemetry-contract.ts` and + * re-exported here, so every importer of this module keeps its path while the dashboard can + * reach the same rosters without pulling this file's import graph into the browser project. * - * The order is by client observation rather than by upstream progress, because the question the - * table answers is whether resending can duplicate something the caller already saw. An upstream - * that completed a turn we never relayed has committed nothing downstream; an upstream that - * emitted one token has. + * What stays here is the decision: the per-stage commitment, the per-cause evidence and + * disposition, and the resend permission derived from them. * * A stage is how far the OBSERVABLE progression got, not which events happened to arrive. A turn * that settled carrying no output -- an empty completion, a 4xx error body -- did not reach - * `terminal`; it stalled at `protocol-prelude`, because the caller saw no answer. `terminal` + * `terminal`; it stalled below `semantic-output`, because the caller saw no answer. `terminal` * means the answer was delivered, which is why it is both last and refused. */ -export const REQUEST_FAILURE_STAGES = Object.freeze([ - /** No response head exists. Whether the origin began the turn is not known from the stage alone. */ - "pre-header", - /** A status line and headers exist, and no protocol body event has been parsed yet. */ - "headers-only", - /** The protocol body began with control events only -- `response.created`, quota frames. */ - "protocol-prelude", - /** At least one output-bearing event reached the caller. */ - "semantic-output", - /** A tool call or other externally visible effect was emitted. */ - "side-effect", - /** A terminal event settled the turn after its answer reached the caller. */ - "terminal", -] as const); - -export type RequestFailureStage = typeof REQUEST_FAILURE_STAGES[number]; +export { + REQUEST_FAILURE_CAUSES, + REQUEST_FAILURE_STAGES, + RESEND_PERMISSIONS, +} from "../usage/telemetry-contract"; +export type { + RequestFailureCause, + RequestFailureStage, + ResendPermission, +} from "../usage/telemetry-contract"; /** Position in {@link REQUEST_FAILURE_STAGES}. Derived, so the order is stated exactly once. */ export function stageRank(stage: RequestFailureStage): number { @@ -74,61 +75,6 @@ export function stageCommitment(stage: RequestFailureStage): StageCommitment { return STAGE_COMMITMENT[stage]; } -/** - * Why the request failed, as one closed dictionary for every layer. - * - * Bounded on purpose: these are wire values a maintainer reads and a metric labels by, never a - * credential, an account identifier, an upstream body or prompt content. The four that #5180 and - * the ciphertext path insist on -- `rate-limit`, `quota-exhausted`, `policy-refusal` and - * `ciphertext-refusal` -- are separate members because they need opposite follow-ups: wait, - * change account, change the prompt, strip the ciphertext. - */ -export const REQUEST_FAILURE_CAUSES = Object.freeze([ - /** The bytes provably never reached the origin: connect refused, DNS failure, TLS handshake. */ - "transport-unsent", - /** The bytes left and the connection died before a head. The origin may be running the turn. */ - "transport-ambiguous", - /** The origin answered that it would not start the turn now: 503, overloaded, backpressure. */ - "upstream-declined", - /** A 429 rate limit. Capacity is momentarily gone; waiting is the remedy. */ - "rate-limit", - /** Plan or credit quota is gone. Waiting out a retry window does not help; the account must change. */ - "quota-exhausted", - /** Credentials were rejected: 401, 403 on identity. */ - "credential-rejected", - /** The origin evaluated the content and refused it. Identical bytes get the identical refusal. */ - "policy-refusal", - /** - * The origin rejected a request PARAMETER rather than the content: an unsupported reasoning - * effort, an unknown field. Distinct from `policy-refusal` because the remedy is opposite -- - * the same content succeeds once the parameter is adjusted. - */ - "parameter-rejected", - /** Opaque replay state was rejected as unverifiable. Only a request without it can succeed. */ - "ciphertext-refusal", - /** - * The payload exceeded a size the origin accepts. A smaller rebuild of the same turn can - * succeed, which is why this is not the same answer as `payload-rejected`. - */ - "payload-too-large", - /** The payload was rejected on its merits: unsupported media, malformed part. No repair helps. */ - "payload-rejected", - /** - * The origin returned a server-side fault. Whether it had already begun the turn is not - * knowable from the status, so this is the honest classification for the mixed 5xx set the - * transient layer retries: 503 really did decline, 500 may not have. - */ - "upstream-fault", - /** The turn settled carrying no usable output. */ - "empty-output", - /** The caller went away. */ - "client-cancelled", - /** This proxy refused before dispatch: send budget, route policy, replay refusal. */ - "local-refusal", -] as const); - -export type RequestFailureCause = typeof REQUEST_FAILURE_CAUSES[number]; - /** * What the cause proves about whether the origin ran the turn. * @@ -190,24 +136,6 @@ export function causeDisposition(cause: RequestFailureCause): ResendDisposition return CAUSE_DISPOSITION[cause]; } -/** - * The answer this table exists to give. - * - * Every refusal names WHY it refused, because the three reasons need different operator - * responses and used to arrive as one undifferentiated "no retry". - */ -export type ResendPermission = - /** The same request may be sent again. */ - | "permitted" - /** Only a modified request may be sent: rotated credential, stripped ciphertext. */ - | "permitted-after-repair" - /** Upstream execution state is unknown. No AUTOMATIC resend; see the note below. */ - | "refused-ambiguous" - /** The caller already observed output or an externally visible effect. */ - | "refused-committed" - /** Identical bytes would get the identical answer. */ - | "refused-futile"; - /** * Whether this proxy may send the request again, from the stage it failed at and the cause. * diff --git a/src/server/request-log.ts b/src/server/request-log.ts index d7b4888ee58..bc39aedb785 100644 --- a/src/server/request-log.ts +++ b/src/server/request-log.ts @@ -40,6 +40,7 @@ import { isLogicalRequestId, isValidReasoningWireValue, normalizeClaudeCompatibilityUsageLog, + normalizeRequestFailureAttribution, normalizeRequestSpend, readRecentUsageEntries, usageForFinalLog, @@ -52,9 +53,12 @@ import { type PersistedUsageAttempt, type PersistedUsageEntry, type PersistedClaudeCompatibilityLog, + type RequestFailureCause, + type RequestFailureStage, type UsageStatus, } from "../usage/log"; import type { RequestExecutionBudget } from "../lib/request-execution-budget"; +import { deriveRequestFailureAttribution } from "../lib/request-failure-attribution"; import { appendUsageDebug, isUsageDebugEnabled, @@ -330,6 +334,13 @@ export interface RequestLogEntry { routeDecision?: RouteDecisionTraceV1; /** Closed Claude protocol codes; no request or header values. */ claudeCompatibility?: PersistedClaudeCompatibilityLog; + /** + * How far this request got and why it failed, in the shared stage and cause vocabulary + * (#2366). Derived once at the single finalization seam and carried on the row so the + * dashboard, the durable ledger and the exporter read one answer instead of three. + */ + failureStage?: RequestFailureStage; + failureCause?: RequestFailureCause; } const requestLog: RequestLogEntry[] = []; @@ -455,6 +466,7 @@ export function requestLogEntryFromPersistedUsage(entry: PersistedUsageEntry): R ...(entry.conversationStateScrub === "account-change" ? { conversationStateScrub: "account-change" } : {}), + ...normalizeRequestFailureAttribution(entry), }; } @@ -601,6 +613,10 @@ export function addRequestLog(entry: RequestLogEntry) { ...(isKnownTransportPhase(entry.transportPhase) ? { transportPhase: entry.transportPhase } : {}), ...(isKnownTerminalSource(entry.terminalSource) ? { terminalSource: entry.terminalSource } : {}), ...failureDiagnostics, + // Rebuilt explicitly, like every other field here: this function does not spread the + // entry, so a pair omitted at this line would reach /api/logs and never reach + // usage.jsonl, which is the surface the derived failure projection reads. + ...normalizeRequestFailureAttribution(entry), ...(entry.routeDecision ? { routeDecision: entry.routeDecision } : {}), ...(entry.claudeCompatibility ? { claudeCompatibility: entry.claudeCompatibility } : {}), ...(entry.conversationStateScrub === "account-change" @@ -1369,6 +1385,32 @@ export function addFinalRequestLog( if (errorCode) logCtx.activeAttempt.errorCode = errorCode; else delete logCtx.activeAttempt.errorCode; } + // Derived once, here, because this is the one seam every request passes exactly once however + // it ended. Deriving it at each transport's own exit would give the same request a different + // attribution per transport, which is the disagreement the shared terminal classifier already + // removed once. It runs BEFORE the attempt snapshot below, so the row that reaches disk and + // the live attempt object carry the same pair rather than one of them being stamped too late. + // + // Every input is a closed value. `errorCode` and `upstreamError` are deliberately not read: + // both are assembled partly from upstream text, so a classification keyed on them varies by + // provider and locale, and a grouping key built from them cannot promise it carries no content. + const attribution = deriveRequestFailureAttribution({ + status: effectiveStatus, + ...(meta?.terminalStatus ? { terminalStatus: meta.terminalStatus } : {}), + ...(closeReason ? { closeReason } : {}), + ...(logCtx.transportPhase ? { transportPhase: logCtx.transportPhase } : {}), + outputObserved: logCtx.firstOutputMs !== undefined, + locallyAnswered: logCtx.localTerminalReason !== undefined, + recoveryKinds: logCtx.activeAttempt?.recoveryKinds ?? [], + }); + // The final row and the attempt that ended it describe the same exchange, so they carry the + // same pair rather than each deriving one from a different slice of the facts. + if (logCtx.activeAttempt) { + if (attribution?.stage) logCtx.activeAttempt.failureStage = attribution.stage; + else delete logCtx.activeAttempt.failureStage; + if (attribution?.cause) logCtx.activeAttempt.failureCause = attribution.cause; + else delete logCtx.activeAttempt.failureCause; + } // 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. @@ -1493,6 +1535,8 @@ export function addFinalRequestLog( ...(logCtx.terminalSource ? { terminalSource: logCtx.terminalSource } : {}), ...(logCtx.routeDecision ? { routeDecision: logCtx.routeDecision } : {}), ...(claudeCompatibility ? { claudeCompatibility } : {}), + ...(attribution?.stage ? { failureStage: attribution.stage } : {}), + ...(attribution?.cause ? { failureCause: attribution.cause } : {}), }); if (isUsageDebugEnabled()) { appendUsageDebug({ diff --git a/src/usage/log.ts b/src/usage/log.ts index 4a0be286bcb..b881cdadca3 100644 --- a/src/usage/log.ts +++ b/src/usage/log.ts @@ -15,15 +15,19 @@ import type { CodexWsStageRecord } from "../server/responses/codex-ws-wire"; import { ATTEMPT_RECOVERY_KIND_ROSTER, ATTEMPT_RECOVERY_WITHHELD_ROSTER, + REQUEST_FAILURE_CAUSES, + REQUEST_FAILURE_STAGES, type AttemptRecoveryKind, type AttemptRecoveryWithheld, + type RequestFailureCause, + type RequestFailureStage, type RequestSpendTotals, } from "./telemetry-contract"; // Re-exported so every existing importer keeps its path. The declarations moved to a leaf the // dashboard can import without pulling node:fs and the config barrel into the browser build. -export { ATTEMPT_RECOVERY_KIND_ROSTER, ATTEMPT_RECOVERY_WITHHELD_ROSTER }; -export type { AttemptRecoveryKind, AttemptRecoveryWithheld, RequestSpendTotals }; +export { ATTEMPT_RECOVERY_KIND_ROSTER, ATTEMPT_RECOVERY_WITHHELD_ROSTER, REQUEST_FAILURE_CAUSES, REQUEST_FAILURE_STAGES }; +export type { AttemptRecoveryKind, AttemptRecoveryWithheld, RequestFailureCause, RequestFailureStage, RequestSpendTotals }; export interface PersistedClaudeCompatibilityLog { decision: "shadow"; @@ -173,6 +177,16 @@ export interface PersistedUsageAttempt { * account identifiers. */ codexWsStage?: CodexWsStageRecord; + /** + * How far this attempt's exchange got and why it failed, in the shared vocabulary (#2366). + * + * Both values are closed roster members, so the pair can be a metric label and a grouping key + * without a masking pass. Absent on a completed attempt and on every row written before the + * attribution existed. The resend verdict these two imply is NOT stored: it is derived at read + * time, so a stored row can never carry a verdict the current table would no longer reach. + */ + failureStage?: RequestFailureStage; + failureCause?: RequestFailureCause; } /** @@ -318,6 +332,53 @@ export interface PersistedUsageEntry { routeDecision?: RouteDecisionTraceV1; /** Closed Claude protocol codes only; absent on older rows. */ claudeCompatibility?: PersistedClaudeCompatibilityLog; + /** + * How far this request got and why it failed (#2366). Projected from the attempt that ended + * the request so every surface reads the answer off the same row. Absent on a completed + * request and on rows written before the attribution existed. + */ + failureStage?: RequestFailureStage; + failureCause?: RequestFailureCause; +} + +/** + * Attribution for the logical request, projected from the attempt that ended it (#2366). + * + * Carried on the entry as well as the attempt because the three surfaces that have to agree read + * the entry: a projection that had to reach into `attempts` to answer "why did this fail" would + * be reading a different row from the exporter, which is the disagreement the landed terminal + * classifier already removed once. + */ +export interface PersistedRequestFailureAttribution { + failureStage?: RequestFailureStage; + failureCause?: RequestFailureCause; +} + +const KNOWN_REQUEST_FAILURE_STAGES: ReadonlySet = new Set(REQUEST_FAILURE_STAGES); +const KNOWN_REQUEST_FAILURE_CAUSES: ReadonlySet = new Set(REQUEST_FAILURE_CAUSES); + +/** + * Same closed-set discipline as `isKnownTransportPhase`, with the set DERIVED from the roster + * rather than restated. The recovery vocabulary was written twice once -- as a union and as the + * read-back whitelist -- and a member present in only one of them is written to disk and dropped + * on the next read, which loses exactly the field that says why the row failed. + */ +export function isKnownRequestFailureStage(value: unknown): value is RequestFailureStage { + return typeof value === "string" && KNOWN_REQUEST_FAILURE_STAGES.has(value); +} + +export function isKnownRequestFailureCause(value: unknown): value is RequestFailureCause { + return typeof value === "string" && KNOWN_REQUEST_FAILURE_CAUSES.has(value); +} + +/** The stage/cause pair a normalizer keeps, dropping either half that is not a roster member. */ +export function normalizeRequestFailureAttribution( + raw: { failureStage?: unknown; failureCause?: unknown }, +): PersistedRequestFailureAttribution { + return { + ...(isKnownRequestFailureStage(raw.failureStage) ? { failureStage: raw.failureStage } : {}), + ...(isKnownRequestFailureCause(raw.failureCause) ? { failureCause: raw.failureCause } : {}), + }; } const KNOWN_USAGE_SURFACES = new Set>([ @@ -655,6 +716,7 @@ function normalizeUsageAttempt(raw: unknown): PersistedUsageAttempt | null { : {}), ...(tierOutcome ? { tierOutcome } : {}), ...(codexWsStage ? { codexWsStage } : {}), + ...normalizeRequestFailureAttribution(attempt), }; } @@ -831,6 +893,7 @@ function normalizeUsageEntry(entry: PersistedUsageEntry): PersistedUsageEntry { ...(entry.upstreamError ? { upstreamError: entry.upstreamError } : {}), ...(routeDecision ? { routeDecision } : {}), ...(claudeCompatibility ? { claudeCompatibility } : {}), + ...normalizeRequestFailureAttribution(entry), }; } diff --git a/src/usage/telemetry-contract.ts b/src/usage/telemetry-contract.ts index 21e716cb580..e0cfe330f58 100644 --- a/src/usage/telemetry-contract.ts +++ b/src/usage/telemetry-contract.ts @@ -59,6 +59,114 @@ export const ATTEMPT_RECOVERY_WITHHELD_ROSTER = Object.freeze([ export type AttemptRecoveryWithheld = typeof ATTEMPT_RECOVERY_WITHHELD_ROSTER[number]; +/** + * How far a failed exchange got, ordered by how much the DOWNSTREAM CLIENT observed. + * + * The order is by client observation rather than by upstream progress, because the question it + * answers is whether resending can duplicate something the caller already saw. An upstream that + * completed a turn we never relayed has committed nothing downstream; an upstream that emitted + * one token has. + * + * The roster lives here rather than beside the resend tables for the reason stated at the top of + * this file: the dashboard renders a label per member, and reaching the table module for the + * names would drag its import graph into the browser project. `src/lib/request-failure-model.ts` + * re-exports it, so every existing importer keeps its path and there is still exactly one + * declaration. + */ +export const REQUEST_FAILURE_STAGES = Object.freeze([ + /** No response head exists. Whether the origin began the turn is not known from the stage alone. */ + "pre-header", + /** A status line and headers exist, and no protocol body event has been parsed yet. */ + "headers-only", + /** The protocol body began with control events only -- `response.created`, quota frames. */ + "protocol-prelude", + /** At least one output-bearing event reached the caller. */ + "semantic-output", + /** A tool call or other externally visible effect was emitted. */ + "side-effect", + /** A terminal event settled the turn after its answer reached the caller. */ + "terminal", +] as const); + +export type RequestFailureStage = typeof REQUEST_FAILURE_STAGES[number]; + +/** + * Why the request failed, as one closed dictionary for every layer. + * + * Bounded on purpose: these are wire values a maintainer reads and a metric labels by, never a + * credential, an account identifier, an upstream body or prompt content. That bound is what lets + * the value be a Prometheus label and a grouping key without a masking pass -- a closed roster + * has nothing to mask. + */ +export const REQUEST_FAILURE_CAUSES = Object.freeze([ + /** The bytes provably never reached the origin: connect refused, DNS failure, TLS handshake. */ + "transport-unsent", + /** The bytes left and the connection died before a head. The origin may be running the turn. */ + "transport-ambiguous", + /** The origin answered that it would not start the turn now: 503, overloaded, backpressure. */ + "upstream-declined", + /** A 429 rate limit. Capacity is momentarily gone; waiting is the remedy. */ + "rate-limit", + /** Plan or credit quota is gone. Waiting out a retry window does not help; the account must change. */ + "quota-exhausted", + /** Credentials were rejected: 401, 403 on identity. */ + "credential-rejected", + /** The origin evaluated the content and refused it. Identical bytes get the identical refusal. */ + "policy-refusal", + /** + * The origin rejected a request PARAMETER rather than the content: an unsupported reasoning + * effort, an unknown field. Distinct from `policy-refusal` because the remedy is opposite -- + * the same content succeeds once the parameter is adjusted. + */ + "parameter-rejected", + /** Opaque replay state was rejected as unverifiable. Only a request without it can succeed. */ + "ciphertext-refusal", + /** + * The payload exceeded a size the origin accepts. A smaller rebuild of the same turn can + * succeed, which is why this is not the same answer as `payload-rejected`. + */ + "payload-too-large", + /** The payload was rejected on its merits: unsupported media, malformed part. No repair helps. */ + "payload-rejected", + /** + * The origin returned a server-side fault. Whether it had already begun the turn is not + * knowable from the status, so this is the honest classification for the mixed 5xx set the + * transient layer retries: 503 really did decline, 500 may not have. + */ + "upstream-fault", + /** The turn settled carrying no usable output. */ + "empty-output", + /** The caller went away. */ + "client-cancelled", + /** This proxy refused before dispatch: send budget, route policy, replay refusal. */ + "local-refusal", +] as const); + +export type RequestFailureCause = typeof REQUEST_FAILURE_CAUSES[number]; + +/** + * Whether this proxy may send the request again. Derived at READ time from the stage and the + * cause and never persisted, so a stored row cannot carry a verdict that the current table + * would no longer reach. + * + * Every refusal names WHY it refused, because the three reasons need different operator + * responses and used to arrive as one undifferentiated "no retry". + */ +export const RESEND_PERMISSIONS = Object.freeze([ + /** The same request may be sent again. */ + "permitted", + /** Only a modified request may be sent: rotated credential, stripped ciphertext. */ + "permitted-after-repair", + /** Upstream execution state is unknown. No AUTOMATIC resend. */ + "refused-ambiguous", + /** The caller already observed output or an externally visible effect. */ + "refused-committed", + /** Identical bytes would get the identical answer. */ + "refused-futile", +] as const); + +export type ResendPermission = typeof RESEND_PERMISSIONS[number]; + /** * What one logical request spent upstream, decomposed by how much of it is explained. * diff --git a/tests/fixtures/test-layout-expected.json b/tests/fixtures/test-layout-expected.json index 53fc4cbab3d..4a14a5192d4 100644 --- a/tests/fixtures/test-layout-expected.json +++ b/tests/fixtures/test-layout-expected.json @@ -1016,6 +1016,7 @@ "reasoning-replay-scope-source.test.ts": "lib", "redact.test.ts": "lib", "failure-stage-model.test.ts": "lib", + "failure-attribution.test.ts": "lib", "relay-eager.test.ts": "server", "release-helper.test.ts": "ci-workflows", "release-notes.test.ts": "ci-workflows", diff --git a/tests/lib/failure-attribution.test.ts b/tests/lib/failure-attribution.test.ts new file mode 100644 index 00000000000..737eb195a02 --- /dev/null +++ b/tests/lib/failure-attribution.test.ts @@ -0,0 +1,152 @@ +import { describe, expect, test } from "bun:test"; +import { + deriveRequestFailureAttribution, + deriveRequestFailureCause, + deriveRequestFailureStage, + type RequestFailureFacts, +} from "../../src/lib/request-failure-attribution"; +import { + REQUEST_FAILURE_CAUSES, + REQUEST_FAILURE_STAGES, + permitsResend, + resendPermission, + stageCommitment, +} from "../../src/lib/request-failure-model"; +import { ATTEMPT_RECOVERY_KIND_ROSTER } from "../../src/usage/telemetry-contract"; +import { REQUEST_OUTCOME_CLASSES, classifyRequestOutcome } from "../../src/usage/request-outcome"; + +/** + * The fact space this derivation is total over. + * + * Every axis is read from the module that declares it rather than restated, so a member added to + * a roster widens this cross product instead of leaving a case nobody wrote. The status list is + * the one axis that cannot be derived -- HTTP statuses are not a roster this repository owns -- + * so it enumerates one representative per branch the derivation distinguishes, plus the two + * boundary values (`0`, no head at all, and `499`) that decide a branch on their own. + */ +const STATUSES = [0, 101, 200, 400, 401, 403, 413, 429, 451, 499, 500, 502, 503] as const; +const TERMINAL_STATUSES = [undefined, "completed", "failed", "incomplete"] as const; +const CLOSE_REASONS = [undefined, "terminal", "client_cancel", "non_stream", "body_stall", "body_overflow"] as const; +const TRANSPORT_PHASES = [undefined, "pre_headers", "mid_stream", "terminal_sse"] as const; + +function* factSpace(): Generator { + for (const status of STATUSES) { + for (const terminalStatus of TERMINAL_STATUSES) { + for (const closeReason of CLOSE_REASONS) { + for (const transportPhase of TRANSPORT_PHASES) { + for (const outputObserved of [false, true]) { + for (const sideEffectObserved of [false, true]) { + yield { + status, + ...(terminalStatus ? { terminalStatus } : {}), + ...(closeReason ? { closeReason } : {}), + ...(transportPhase ? { transportPhase } : {}), + outputObserved, + sideEffectObserved, + }; + } + } + } + } + } + } +} + +describe("request failure attribution", () => { + test("every derived stage and cause is a member of the landed rosters", () => { + let seen = 0; + for (const facts of factSpace()) { + seen += 1; + expect(REQUEST_FAILURE_STAGES).toContain(deriveRequestFailureStage(facts)); + const cause = deriveRequestFailureCause(facts); + if (cause !== undefined) expect(REQUEST_FAILURE_CAUSES).toContain(cause); + } + // The generator is the oracle: an axis added above must actually widen the space. + expect(seen).toBe( + STATUSES.length * TERMINAL_STATUSES.length * CLOSE_REASONS.length * TRANSPORT_PHASES.length * 4, + ); + }); + + test("attribution is recorded for exactly the outcomes that are not completed", () => { + const outcomesWithAttribution = new Set(); + for (const facts of factSpace()) { + const outcome = classifyRequestOutcome(facts); + const attribution = deriveRequestFailureAttribution(facts); + if (outcome === "completed") { + expect(attribution).toBeUndefined(); + continue; + } + expect(attribution).toBeDefined(); + outcomesWithAttribution.add(outcome); + } + expect([...outcomesWithAttribution].toSorted()) + .toEqual(REQUEST_OUTCOME_CLASSES.filter(outcome => outcome !== "completed").toSorted()); + }); + + test("a cause is recorded for a failure and withheld from an incomplete turn", () => { + for (const facts of factSpace()) { + const outcome = classifyRequestOutcome(facts); + const cause = deriveRequestFailureCause(facts); + if (outcome === "completed" || outcome === "incomplete") expect(cause).toBeUndefined(); + else expect(cause).toBeDefined(); + } + }); + + test("an aborted request is attributed to the caller, whichever way it was signalled", () => { + expect(deriveRequestFailureCause({ status: 499 })).toBe("client-cancelled"); + expect(deriveRequestFailureCause({ status: 502, closeReason: "client_cancel" })).toBe("client-cancelled"); + }); + + test("a stage never claims more than the caller observed", () => { + for (const facts of factSpace()) { + const stage = deriveRequestFailureStage(facts); + if (facts.outputObserved !== true) { + // Nothing reached the caller, so no stage may report an irreversible observation. + expect(stageCommitment(stage)).not.toBe("output-observed"); + expect(stageCommitment(stage)).not.toBe("answer-delivered"); + } + } + }); + + test("an observed side effect refuses a resend for every cause", () => { + const facts: RequestFailureFacts = { status: 502, sideEffectObserved: true }; + const stage = deriveRequestFailureStage(facts); + for (const cause of REQUEST_FAILURE_CAUSES) { + expect(permitsResend(resendPermission(stage, cause))).toBe(false); + } + }); + + test("a 400 is refined by the recovery kind that identifies which rejection it was", () => { + const base = { status: 400 } as const; + expect(deriveRequestFailureCause(base)).toBe("payload-rejected"); + expect(deriveRequestFailureCause({ ...base, recoveryKinds: ["opaque-blob-rejection"] })) + .toBe("ciphertext-refusal"); + expect(deriveRequestFailureCause({ ...base, recoveryKinds: ["reasoning-effort-downgrade"] })) + .toBe("parameter-rejected"); + }); + + test("a recovery kind does not become the cause when the request ended on another status", () => { + // The attempt recovered from a rejected reasoning parameter and then died on a 500. The + // request failed for the 500, and reporting the earlier rejection would send an operator + // after a problem that was already worked around. + for (const kind of ATTEMPT_RECOVERY_KIND_ROSTER) { + expect(deriveRequestFailureCause({ status: 500, recoveryKinds: [kind] })).toBe("upstream-fault"); + } + }); + + test("a turn that settled with no output is empty output rather than an upstream fault", () => { + expect(deriveRequestFailureCause({ status: 200, terminalStatus: "failed", outputObserved: false })) + .toBe("empty-output"); + expect(deriveRequestFailureCause({ status: 200, terminalStatus: "failed", outputObserved: true })) + .toBe("upstream-fault"); + }); + + test("a request with no response head separates an unsent send from an ambiguous one", () => { + expect(deriveRequestFailureCause({ status: 0 })).toBe("transport-unsent"); + expect(deriveRequestFailureCause({ status: 0, transportPhase: "mid_stream" })).toBe("transport-ambiguous"); + }); + + test("a local refusal is attributed to this proxy rather than to upstream", () => { + expect(deriveRequestFailureCause({ status: 502, locallyAnswered: true })).toBe("local-refusal"); + }); +}); From 3811de4c714860b5cce05524019c61a77d0f36aa Mon Sep 17 00:00:00 2001 From: JUN Date: Sun, 20 Sep 2026 21:46:15 +0900 Subject: [PATCH 02/10] feat(metrics,gui): report the failure cause on every surface Completes the agreement condition for the attribution the previous commit records. The durable row carried a cause and nothing showed it, which is the same shape as the defect lane C2 fixed: a real cause reaching the operator as an absence of one. The exporter gains opencodex_request_failures_total{protocol,cause}. It counts the value the recorder derived rather than deriving one of its own, because the recorder is the only place that sees the transport facts a cause needs, and two derivations of one answer is exactly the disagreement this batch exists to remove. The label set IS the shared dictionary rather than a copy of it. Cardinality is fifteen causes across four protocols -- sixty series, fixed for the lifetime of the roster, every value from a frozen list -- and it labels a counter, never a histogram; a case asserts both. /api/logs computes resendPermission at read time for the row and for each attempt. It is never stored: the tables that decide it live in this build, and a row written by an older one must not assert a permission the current tables would refuse. A case asserts the pair is in the ledger module and the verdict is not. The Logs detail dialog shows the cause, the stage it reached and the resend verdict, and the attempt table leads its reason column with the cause, keeping the exact wire errorCode behind it because that is what a bug report needs. Three satisfies clauses make a missing label a typecheck failure rather than a silent fallback, and the existing catalog oracle now covers the new key groups. This trips the missing_ui_screenshot gate. This lane may not build or run the GUI, so it cannot produce the screenshot; the gate fires on changed paths under gui/, not on words in the description. The visible change is three rows added to the detail dialog for a failed request and a named cause where the attempt table previously showed a bare wire code. Co-authored-by: chilung --- gui/src/i18n/de.ts | 29 +++++ gui/src/i18n/en.ts | 29 +++++ gui/src/i18n/fr.ts | 29 +++++ gui/src/i18n/ja.ts | 29 +++++ gui/src/i18n/ko.ts | 29 +++++ gui/src/i18n/ru.ts | 29 +++++ gui/src/i18n/tr.ts | 29 +++++ gui/src/i18n/vi.ts | 29 +++++ gui/src/i18n/zh-TW.ts | 29 +++++ gui/src/i18n/zh.ts | 29 +++++ gui/src/pages/Logs.tsx | 116 +++++++++++++++++- src/server/management/shared.ts | 19 ++- src/server/request-log.ts | 1 + src/server/request-metrics.ts | 42 ++++++- tests/usage/request-outcome-agreement.test.ts | 70 ++++++++++- 15 files changed, 530 insertions(+), 8 deletions(-) diff --git a/gui/src/i18n/de.ts b/gui/src/i18n/de.ts index a46c0f89fa0..810c92fce0b 100644 --- a/gui/src/i18n/de.ts +++ b/gui/src/i18n/de.ts @@ -885,6 +885,35 @@ export const de: Record = { "logs.detail.sends.label": "Upstream-Sendungen", "logs.detail.sends.unresolved": "ungeklärt", "logs.detail.attempt.recovery.unknown": "Unbekannter Wiederherstellungsgrund", + "logs.detail.cause.label": "Fehlerursache", + "logs.detail.stage.label": "erreicht", + "logs.detail.resend.label": "Erneut senden", + "logs.detail.cause.transportUnsent": "Nie an Upstream gesendet", + "logs.detail.cause.transportAmbiguous": "Verbindung verloren, Upstream-Status unbekannt", + "logs.detail.cause.upstreamDeclined": "Upstream lehnte den Start ab", + "logs.detail.cause.rateLimit": "Ratenlimit erreicht", + "logs.detail.cause.quotaExhausted": "Kontingent aufgebraucht", + "logs.detail.cause.credentialRejected": "Anmeldedaten abgelehnt", + "logs.detail.cause.policyRefusal": "Von der Inhaltsrichtlinie abgelehnt", + "logs.detail.cause.parameterRejected": "Anfrageparameter abgelehnt", + "logs.detail.cause.ciphertextRefusal": "Verschlüsselter Zustand abgelehnt", + "logs.detail.cause.payloadTooLarge": "Nutzlast zu groß", + "logs.detail.cause.payloadRejected": "Nutzlast abgelehnt", + "logs.detail.cause.upstreamFault": "Upstream-Fehler", + "logs.detail.cause.emptyOutput": "Keine verwertbare Ausgabe", + "logs.detail.cause.clientCancelled": "Vom Client abgebrochen", + "logs.detail.cause.localRefusal": "Von diesem Proxy abgelehnt", + "logs.detail.stage.preHeader": "kein Antwortkopf", + "logs.detail.stage.headersOnly": "nur Kopfzeilen", + "logs.detail.stage.protocolPrelude": "Protokollvorspann", + "logs.detail.stage.semanticOutput": "Ausgabe zugestellt", + "logs.detail.stage.sideEffect": "Nebenwirkung ausgelöst", + "logs.detail.stage.terminal": "Antwort zugestellt", + "logs.detail.resend.permitted": "Erneut sendbar", + "logs.detail.resend.permittedAfterRepair": "Nach Korrektur erneut sendbar", + "logs.detail.resend.refusedAmbiguous": "Nicht erneut gesendet: Upstream-Status unbekannt", + "logs.detail.resend.refusedCommitted": "Nicht erneut gesendet: Aufrufer sah bereits Ausgabe", + "logs.detail.resend.refusedFutile": "Nicht erneut gesendet: dieselbe Anfrage scheitert erneut", "logs.detail.reason.usage_missing": "Nutzung wurde nicht gemeldet.", "logs.detail.reason.usage_unsupported": "Dieser Anbieter meldet keine Nutzung.", "logs.detail.reason.output_missing": "Es wurden keine positiven Ausgabe-Tokens gemeldet.", diff --git a/gui/src/i18n/en.ts b/gui/src/i18n/en.ts index 061019df6c3..15f78567293 100644 --- a/gui/src/i18n/en.ts +++ b/gui/src/i18n/en.ts @@ -934,6 +934,35 @@ export const en = { "logs.detail.sends.label": "Upstream sends", "logs.detail.sends.unresolved": "unresolved", "logs.detail.attempt.recovery.unknown": "Unknown recovery reason", + "logs.detail.cause.label": "Failure cause", + "logs.detail.stage.label": "reached", + "logs.detail.resend.label": "Resend", + "logs.detail.cause.transportUnsent": "Never sent upstream", + "logs.detail.cause.transportAmbiguous": "Connection lost, upstream state unknown", + "logs.detail.cause.upstreamDeclined": "Upstream declined to start", + "logs.detail.cause.rateLimit": "Rate limited", + "logs.detail.cause.quotaExhausted": "Quota exhausted", + "logs.detail.cause.credentialRejected": "Credentials rejected", + "logs.detail.cause.policyRefusal": "Refused by content policy", + "logs.detail.cause.parameterRejected": "Request parameter rejected", + "logs.detail.cause.ciphertextRefusal": "Encrypted state rejected", + "logs.detail.cause.payloadTooLarge": "Payload too large", + "logs.detail.cause.payloadRejected": "Payload rejected", + "logs.detail.cause.upstreamFault": "Upstream fault", + "logs.detail.cause.emptyOutput": "No usable output", + "logs.detail.cause.clientCancelled": "Cancelled by the client", + "logs.detail.cause.localRefusal": "Refused by this proxy", + "logs.detail.stage.preHeader": "no response head", + "logs.detail.stage.headersOnly": "headers only", + "logs.detail.stage.protocolPrelude": "protocol prelude", + "logs.detail.stage.semanticOutput": "output delivered", + "logs.detail.stage.sideEffect": "side effect emitted", + "logs.detail.stage.terminal": "answer delivered", + "logs.detail.resend.permitted": "Could be resent", + "logs.detail.resend.permittedAfterRepair": "Could be resent after repair", + "logs.detail.resend.refusedAmbiguous": "Not resent: upstream state unknown", + "logs.detail.resend.refusedCommitted": "Not resent: caller already saw output", + "logs.detail.resend.refusedFutile": "Not resent: the same request would fail again", "logs.detail.reason.usage_missing": "Usage was not reported.", "logs.detail.reason.usage_unsupported": "This provider does not report usage.", "logs.detail.reason.output_missing": "No positive output token count was reported.", diff --git a/gui/src/i18n/fr.ts b/gui/src/i18n/fr.ts index b2e00370208..b86daf22e50 100644 --- a/gui/src/i18n/fr.ts +++ b/gui/src/i18n/fr.ts @@ -915,6 +915,35 @@ export const fr: Record = { "logs.detail.attempt.recovery.anthropicOauth429": "Limitation de débit OAuth Anthropic (429)", "logs.detail.attempt.recovery.image413": "Charge utile d’image trop volumineuse (413)", "logs.detail.attempt.recovery.unknown": "Motif de récupération inconnu", + "logs.detail.cause.label": "Cause de l'échec", + "logs.detail.stage.label": "atteint", + "logs.detail.resend.label": "Renvoi", + "logs.detail.cause.transportUnsent": "Jamais envoyé en amont", + "logs.detail.cause.transportAmbiguous": "Connexion perdue, état amont inconnu", + "logs.detail.cause.upstreamDeclined": "L'amont a refusé de démarrer", + "logs.detail.cause.rateLimit": "Débit limité", + "logs.detail.cause.quotaExhausted": "Quota épuisé", + "logs.detail.cause.credentialRejected": "Identifiants refusés", + "logs.detail.cause.policyRefusal": "Refusé par la politique de contenu", + "logs.detail.cause.parameterRejected": "Paramètre de requête refusé", + "logs.detail.cause.ciphertextRefusal": "État chiffré refusé", + "logs.detail.cause.payloadTooLarge": "Charge utile trop volumineuse", + "logs.detail.cause.payloadRejected": "Charge utile refusée", + "logs.detail.cause.upstreamFault": "Panne en amont", + "logs.detail.cause.emptyOutput": "Aucune sortie exploitable", + "logs.detail.cause.clientCancelled": "Annulé par le client", + "logs.detail.cause.localRefusal": "Refusé par ce proxy", + "logs.detail.stage.preHeader": "aucun en-tête de réponse", + "logs.detail.stage.headersOnly": "en-têtes seulement", + "logs.detail.stage.protocolPrelude": "prélude de protocole", + "logs.detail.stage.semanticOutput": "sortie livrée", + "logs.detail.stage.sideEffect": "effet de bord émis", + "logs.detail.stage.terminal": "réponse livrée", + "logs.detail.resend.permitted": "Peut être renvoyé", + "logs.detail.resend.permittedAfterRepair": "Peut être renvoyé après correction", + "logs.detail.resend.refusedAmbiguous": "Non renvoyé : état amont inconnu", + "logs.detail.resend.refusedCommitted": "Non renvoyé : l'appelant a déjà vu la sortie", + "logs.detail.resend.refusedFutile": "Non renvoyé : la même requête échouerait encore", "logs.detail.reason.usage_missing": "L’utilisation n’a pas été communiquée.", "logs.detail.reason.usage_unsupported": "Ce fournisseur ne communique pas l’utilisation.", "logs.detail.reason.output_missing": "Aucun nombre positif de jetons de sortie n’a été communiqué.", diff --git a/gui/src/i18n/ja.ts b/gui/src/i18n/ja.ts index 7ab8054d2ed..c91cd813dd1 100644 --- a/gui/src/i18n/ja.ts +++ b/gui/src/i18n/ja.ts @@ -846,6 +846,35 @@ export const ja: Record = { "logs.detail.sends.label": "アップストリーム送信", "logs.detail.sends.unresolved": "未確定", "logs.detail.attempt.recovery.unknown": "不明なリカバリ理由", + "logs.detail.cause.label": "失敗の原因", + "logs.detail.stage.label": "到達段階", + "logs.detail.resend.label": "再送", + "logs.detail.cause.transportUnsent": "アップストリームへ未送信", + "logs.detail.cause.transportAmbiguous": "接続が切れ、処理状況は不明", + "logs.detail.cause.upstreamDeclined": "アップストリームが開始を拒否", + "logs.detail.cause.rateLimit": "レート制限", + "logs.detail.cause.quotaExhausted": "クォータ枯渇", + "logs.detail.cause.credentialRejected": "認証情報が拒否されました", + "logs.detail.cause.policyRefusal": "コンテンツポリシーによる拒否", + "logs.detail.cause.parameterRejected": "リクエストパラメータが拒否されました", + "logs.detail.cause.ciphertextRefusal": "暗号化状態が拒否されました", + "logs.detail.cause.payloadTooLarge": "ペイロードが大きすぎます", + "logs.detail.cause.payloadRejected": "ペイロードが拒否されました", + "logs.detail.cause.upstreamFault": "アップストリーム障害", + "logs.detail.cause.emptyOutput": "利用可能な出力なし", + "logs.detail.cause.clientCancelled": "クライアントがキャンセル", + "logs.detail.cause.localRefusal": "このプロキシが拒否", + "logs.detail.stage.preHeader": "レスポンスヘッダーなし", + "logs.detail.stage.headersOnly": "ヘッダーのみ", + "logs.detail.stage.protocolPrelude": "プロトコル前段", + "logs.detail.stage.semanticOutput": "出力を配信済み", + "logs.detail.stage.sideEffect": "副作用が発生", + "logs.detail.stage.terminal": "応答を配信済み", + "logs.detail.resend.permitted": "再送可能", + "logs.detail.resend.permittedAfterRepair": "修正後に再送可能", + "logs.detail.resend.refusedAmbiguous": "再送なし: アップストリームの状態が不明", + "logs.detail.resend.refusedCommitted": "再送なし: 呼び出し元が既に出力を受信", + "logs.detail.resend.refusedFutile": "再送なし: 同じ要求は再び失敗します", "logs.detail.reason.usage_missing": "使用量が報告されませんでした。", "logs.detail.reason.usage_unsupported": "このプロバイダーは使用量を報告しません。", "logs.detail.reason.output_missing": "正の出力トークン数が報告されませんでした。", diff --git a/gui/src/i18n/ko.ts b/gui/src/i18n/ko.ts index 31d5c4af19c..20fef17e1f7 100644 --- a/gui/src/i18n/ko.ts +++ b/gui/src/i18n/ko.ts @@ -916,6 +916,35 @@ export const ko: Record = { "logs.detail.sends.label": "업스트림 전송", "logs.detail.sends.unresolved": "미확인", "logs.detail.attempt.recovery.unknown": "알 수 없는 복구 사유", + "logs.detail.cause.label": "실패 원인", + "logs.detail.stage.label": "도달 지점", + "logs.detail.resend.label": "재전송", + "logs.detail.cause.transportUnsent": "업스트림으로 전송되지 않음", + "logs.detail.cause.transportAmbiguous": "연결이 끊겨 업스트림 처리 여부 불명", + "logs.detail.cause.upstreamDeclined": "업스트림이 시작을 거부함", + "logs.detail.cause.rateLimit": "요청 한도 초과", + "logs.detail.cause.quotaExhausted": "할당량 소진", + "logs.detail.cause.credentialRejected": "자격 증명 거부됨", + "logs.detail.cause.policyRefusal": "콘텐츠 정책으로 거부됨", + "logs.detail.cause.parameterRejected": "요청 파라미터 거부됨", + "logs.detail.cause.ciphertextRefusal": "암호화된 상태 거부됨", + "logs.detail.cause.payloadTooLarge": "페이로드가 너무 큼", + "logs.detail.cause.payloadRejected": "페이로드 거부됨", + "logs.detail.cause.upstreamFault": "업스트림 장애", + "logs.detail.cause.emptyOutput": "사용할 수 있는 출력 없음", + "logs.detail.cause.clientCancelled": "클라이언트가 취소함", + "logs.detail.cause.localRefusal": "이 프록시가 거부함", + "logs.detail.stage.preHeader": "응답 헤더 없음", + "logs.detail.stage.headersOnly": "헤더까지", + "logs.detail.stage.protocolPrelude": "프로토콜 프리앰블", + "logs.detail.stage.semanticOutput": "출력 전달됨", + "logs.detail.stage.sideEffect": "부수 효과 발생", + "logs.detail.stage.terminal": "응답 전달 완료", + "logs.detail.resend.permitted": "재전송 가능", + "logs.detail.resend.permittedAfterRepair": "수정 후 재전송 가능", + "logs.detail.resend.refusedAmbiguous": "재전송 안 함: 업스트림 처리 여부 불명", + "logs.detail.resend.refusedCommitted": "재전송 안 함: 이미 출력이 전달됨", + "logs.detail.resend.refusedFutile": "재전송 안 함: 같은 요청은 다시 실패함", "logs.detail.reason.usage_missing": "usage가 보고되지 않았습니다.", "logs.detail.reason.usage_unsupported": "이 프로바이더는 usage 보고를 지원하지 않습니다.", "logs.detail.reason.output_missing": "양수 출력 토큰 수가 보고되지 않았습니다.", diff --git a/gui/src/i18n/ru.ts b/gui/src/i18n/ru.ts index 9a0f4fc0920..a8a4d6014dc 100644 --- a/gui/src/i18n/ru.ts +++ b/gui/src/i18n/ru.ts @@ -902,6 +902,35 @@ export const ru: Record = { "logs.detail.sends.label": "Отправки к провайдеру", "logs.detail.sends.unresolved": "не подтверждено", "logs.detail.attempt.recovery.unknown": "Неизвестная причина восстановления", + "logs.detail.cause.label": "Причина сбоя", + "logs.detail.stage.label": "достигнуто", + "logs.detail.resend.label": "Повторная отправка", + "logs.detail.cause.transportUnsent": "Не отправлено на сервер", + "logs.detail.cause.transportAmbiguous": "Соединение потеряно, состояние сервера неизвестно", + "logs.detail.cause.upstreamDeclined": "Сервер отказался начать", + "logs.detail.cause.rateLimit": "Превышен лимит запросов", + "logs.detail.cause.quotaExhausted": "Квота исчерпана", + "logs.detail.cause.credentialRejected": "Учётные данные отклонены", + "logs.detail.cause.policyRefusal": "Отклонено политикой контента", + "logs.detail.cause.parameterRejected": "Параметр запроса отклонён", + "logs.detail.cause.ciphertextRefusal": "Зашифрованное состояние отклонено", + "logs.detail.cause.payloadTooLarge": "Слишком большой запрос", + "logs.detail.cause.payloadRejected": "Тело запроса отклонено", + "logs.detail.cause.upstreamFault": "Сбой на стороне сервера", + "logs.detail.cause.emptyOutput": "Нет пригодного вывода", + "logs.detail.cause.clientCancelled": "Отменено клиентом", + "logs.detail.cause.localRefusal": "Отклонено этим прокси", + "logs.detail.stage.preHeader": "нет заголовка ответа", + "logs.detail.stage.headersOnly": "только заголовки", + "logs.detail.stage.protocolPrelude": "начало протокола", + "logs.detail.stage.semanticOutput": "вывод доставлен", + "logs.detail.stage.sideEffect": "побочный эффект отправлен", + "logs.detail.stage.terminal": "ответ доставлен", + "logs.detail.resend.permitted": "Можно отправить повторно", + "logs.detail.resend.permittedAfterRepair": "Можно отправить повторно после исправления", + "logs.detail.resend.refusedAmbiguous": "Не отправлено повторно: состояние сервера неизвестно", + "logs.detail.resend.refusedCommitted": "Не отправлено повторно: клиент уже получил вывод", + "logs.detail.resend.refusedFutile": "Не отправлено повторно: тот же запрос снова не пройдёт", "logs.detail.reason.usage_missing": "Данные об использовании не были сообщены.", "logs.detail.reason.usage_unsupported": "Этот провайдер не сообщает данные об использовании.", "logs.detail.reason.output_missing": "Положительное число выходных токенов не было сообщено.", diff --git a/gui/src/i18n/tr.ts b/gui/src/i18n/tr.ts index f8a086ac3ab..6ef60d46f7d 100644 --- a/gui/src/i18n/tr.ts +++ b/gui/src/i18n/tr.ts @@ -921,6 +921,35 @@ export const tr: Record = { "logs.detail.sends.label": "Yukarı akış gönderimleri", "logs.detail.sends.unresolved": "çözülmemiş", "logs.detail.attempt.recovery.unknown": "Bilinmeyen kurtarma nedeni", + "logs.detail.cause.label": "Hata nedeni", + "logs.detail.stage.label": "ulaşıldı", + "logs.detail.resend.label": "Yeniden gönder", + "logs.detail.cause.transportUnsent": "Sunucuya hiç gönderilmedi", + "logs.detail.cause.transportAmbiguous": "Bağlantı koptu, sunucu durumu bilinmiyor", + "logs.detail.cause.upstreamDeclined": "Sunucu başlamayı reddetti", + "logs.detail.cause.rateLimit": "Hız sınırına takıldı", + "logs.detail.cause.quotaExhausted": "Kota tükendi", + "logs.detail.cause.credentialRejected": "Kimlik bilgileri reddedildi", + "logs.detail.cause.policyRefusal": "İçerik politikası reddetti", + "logs.detail.cause.parameterRejected": "İstek parametresi reddedildi", + "logs.detail.cause.ciphertextRefusal": "Şifreli durum reddedildi", + "logs.detail.cause.payloadTooLarge": "Yük çok büyük", + "logs.detail.cause.payloadRejected": "Yük reddedildi", + "logs.detail.cause.upstreamFault": "Sunucu arızası", + "logs.detail.cause.emptyOutput": "Kullanılabilir çıktı yok", + "logs.detail.cause.clientCancelled": "İstemci iptal etti", + "logs.detail.cause.localRefusal": "Bu proxy reddetti", + "logs.detail.stage.preHeader": "yanıt başlığı yok", + "logs.detail.stage.headersOnly": "yalnızca başlıklar", + "logs.detail.stage.protocolPrelude": "protokol ön bölümü", + "logs.detail.stage.semanticOutput": "çıktı iletildi", + "logs.detail.stage.sideEffect": "yan etki üretildi", + "logs.detail.stage.terminal": "yanıt iletildi", + "logs.detail.resend.permitted": "Yeniden gönderilebilir", + "logs.detail.resend.permittedAfterRepair": "Onarımdan sonra yeniden gönderilebilir", + "logs.detail.resend.refusedAmbiguous": "Yeniden gönderilmedi: sunucu durumu bilinmiyor", + "logs.detail.resend.refusedCommitted": "Yeniden gönderilmedi: çağıran çıktıyı zaten gördü", + "logs.detail.resend.refusedFutile": "Yeniden gönderilmedi: aynı istek yine başarısız olur", "logs.detail.reason.usage_missing": "Kullanım bildirilmedi.", "logs.detail.reason.usage_unsupported": "Bu sağlayıcı kullanım bildirmeyebilir.", "logs.detail.reason.output_missing": "Çıktı jeton sayısı bildirilmedi.", diff --git a/gui/src/i18n/vi.ts b/gui/src/i18n/vi.ts index f9eabd994c7..1c6a33da724 100644 --- a/gui/src/i18n/vi.ts +++ b/gui/src/i18n/vi.ts @@ -908,6 +908,35 @@ export const vi: Record = { "logs.detail.sends.label": "Số lần gửi lên nhà cung cấp", "logs.detail.sends.unresolved": "chưa xác định", "logs.detail.attempt.recovery.unknown": "Lý do khôi phục không rõ", + "logs.detail.cause.label": "Nguyên nhân lỗi", + "logs.detail.stage.label": "đã đến", + "logs.detail.resend.label": "Gửi lại", + "logs.detail.cause.transportUnsent": "Chưa gửi lên thượng nguồn", + "logs.detail.cause.transportAmbiguous": "Mất kết nối, không rõ trạng thái thượng nguồn", + "logs.detail.cause.upstreamDeclined": "Thượng nguồn từ chối bắt đầu", + "logs.detail.cause.rateLimit": "Bị giới hạn tốc độ", + "logs.detail.cause.quotaExhausted": "Đã hết hạn mức", + "logs.detail.cause.credentialRejected": "Thông tin xác thực bị từ chối", + "logs.detail.cause.policyRefusal": "Bị chính sách nội dung từ chối", + "logs.detail.cause.parameterRejected": "Tham số yêu cầu bị từ chối", + "logs.detail.cause.ciphertextRefusal": "Trạng thái mã hoá bị từ chối", + "logs.detail.cause.payloadTooLarge": "Tải trọng quá lớn", + "logs.detail.cause.payloadRejected": "Tải trọng bị từ chối", + "logs.detail.cause.upstreamFault": "Lỗi thượng nguồn", + "logs.detail.cause.emptyOutput": "Không có đầu ra dùng được", + "logs.detail.cause.clientCancelled": "Ứng dụng khách đã huỷ", + "logs.detail.cause.localRefusal": "Proxy này từ chối", + "logs.detail.stage.preHeader": "không có đầu phản hồi", + "logs.detail.stage.headersOnly": "chỉ có tiêu đề", + "logs.detail.stage.protocolPrelude": "phần mở đầu giao thức", + "logs.detail.stage.semanticOutput": "đã gửi đầu ra", + "logs.detail.stage.sideEffect": "đã phát sinh tác dụng phụ", + "logs.detail.stage.terminal": "đã gửi câu trả lời", + "logs.detail.resend.permitted": "Có thể gửi lại", + "logs.detail.resend.permittedAfterRepair": "Có thể gửi lại sau khi sửa", + "logs.detail.resend.refusedAmbiguous": "Không gửi lại: không rõ trạng thái thượng nguồn", + "logs.detail.resend.refusedCommitted": "Không gửi lại: bên gọi đã thấy đầu ra", + "logs.detail.resend.refusedFutile": "Không gửi lại: yêu cầu tương tự vẫn sẽ lỗi", "logs.detail.reason.usage_missing": "Mức sử dụng không được báo cáo.", "logs.detail.reason.usage_unsupported": "Provider này không báo cáo mức sử dụng.", "logs.detail.reason.output_missing": "Không có số lượng output token dương nào được báo cáo.", diff --git a/gui/src/i18n/zh-TW.ts b/gui/src/i18n/zh-TW.ts index 25abb6135b4..81440b39b19 100644 --- a/gui/src/i18n/zh-TW.ts +++ b/gui/src/i18n/zh-TW.ts @@ -2407,6 +2407,35 @@ export const zhTW: Record = { "logs.detail.sends.label": "上游傳送次數", "logs.detail.sends.unresolved": "未結算", "logs.detail.attempt.recovery.unknown": "未知的復原原因", + "logs.detail.cause.label": "失敗原因", + "logs.detail.stage.label": "到達階段", + "logs.detail.resend.label": "重送", + "logs.detail.cause.transportUnsent": "未傳送至上游", + "logs.detail.cause.transportAmbiguous": "連線中斷，上游狀態不明", + "logs.detail.cause.upstreamDeclined": "上游拒絕開始", + "logs.detail.cause.rateLimit": "速率受限", + "logs.detail.cause.quotaExhausted": "配額耗盡", + "logs.detail.cause.credentialRejected": "憑證遭拒", + "logs.detail.cause.policyRefusal": "遭內容政策拒絕", + "logs.detail.cause.parameterRejected": "請求參數遭拒", + "logs.detail.cause.ciphertextRefusal": "加密狀態遭拒", + "logs.detail.cause.payloadTooLarge": "酬載過大", + "logs.detail.cause.payloadRejected": "酬載遭拒", + "logs.detail.cause.upstreamFault": "上游故障", + "logs.detail.cause.emptyOutput": "沒有可用輸出", + "logs.detail.cause.clientCancelled": "用戶端已取消", + "logs.detail.cause.localRefusal": "遭此代理拒絕", + "logs.detail.stage.preHeader": "無回應標頭", + "logs.detail.stage.headersOnly": "僅標頭", + "logs.detail.stage.protocolPrelude": "協定前導", + "logs.detail.stage.semanticOutput": "已傳遞輸出", + "logs.detail.stage.sideEffect": "已產生副作用", + "logs.detail.stage.terminal": "已傳遞答覆", + "logs.detail.resend.permitted": "可以重送", + "logs.detail.resend.permittedAfterRepair": "修復後可以重送", + "logs.detail.resend.refusedAmbiguous": "未重送：上游狀態不明", + "logs.detail.resend.refusedCommitted": "未重送：呼叫端已收到輸出", + "logs.detail.resend.refusedFutile": "未重送：相同請求仍會失敗", "logs.detail.estimate.provider_cost_overlay": "已使用供應商設定的價格覆蓋。", "logs.detail.estimate.priority_lower_bound": "無法取得已確認的 Priority 價格；目前顯示的估算是已知下限。", "pws.cockpitImportDescription": "從此裝置匯入 Cockpit Tools Antigravity JSON 匯出檔。不會顯示檔案內容。", diff --git a/gui/src/i18n/zh.ts b/gui/src/i18n/zh.ts index cf4b6e94055..5148de9c95f 100644 --- a/gui/src/i18n/zh.ts +++ b/gui/src/i18n/zh.ts @@ -897,6 +897,35 @@ export const zh: Record = { "logs.detail.sends.label": "上游发送次数", "logs.detail.sends.unresolved": "未结算", "logs.detail.attempt.recovery.unknown": "未知的恢复原因", + "logs.detail.cause.label": "失败原因", + "logs.detail.stage.label": "到达阶段", + "logs.detail.resend.label": "重发", + "logs.detail.cause.transportUnsent": "未发送到上游", + "logs.detail.cause.transportAmbiguous": "连接中断，上游状态未知", + "logs.detail.cause.upstreamDeclined": "上游拒绝开始", + "logs.detail.cause.rateLimit": "速率受限", + "logs.detail.cause.quotaExhausted": "配额耗尽", + "logs.detail.cause.credentialRejected": "凭据被拒绝", + "logs.detail.cause.policyRefusal": "被内容策略拒绝", + "logs.detail.cause.parameterRejected": "请求参数被拒绝", + "logs.detail.cause.ciphertextRefusal": "加密状态被拒绝", + "logs.detail.cause.payloadTooLarge": "负载过大", + "logs.detail.cause.payloadRejected": "负载被拒绝", + "logs.detail.cause.upstreamFault": "上游故障", + "logs.detail.cause.emptyOutput": "没有可用输出", + "logs.detail.cause.clientCancelled": "客户端已取消", + "logs.detail.cause.localRefusal": "被此代理拒绝", + "logs.detail.stage.preHeader": "无响应头", + "logs.detail.stage.headersOnly": "仅响应头", + "logs.detail.stage.protocolPrelude": "协议前导", + "logs.detail.stage.semanticOutput": "已交付输出", + "logs.detail.stage.sideEffect": "已产生副作用", + "logs.detail.stage.terminal": "已交付答复", + "logs.detail.resend.permitted": "可以重发", + "logs.detail.resend.permittedAfterRepair": "修复后可以重发", + "logs.detail.resend.refusedAmbiguous": "未重发：上游状态未知", + "logs.detail.resend.refusedCommitted": "未重发：调用方已收到输出", + "logs.detail.resend.refusedFutile": "未重发：相同请求仍会失败", "logs.detail.reason.usage_missing": "未上报 usage。", "logs.detail.reason.usage_unsupported": "该提供方不支持上报 usage。", "logs.detail.reason.output_missing": "未上报正数输出 token。", diff --git a/gui/src/pages/Logs.tsx b/gui/src/pages/Logs.tsx index 529e62cef74..9f55f37e45d 100644 --- a/gui/src/pages/Logs.tsx +++ b/gui/src/pages/Logs.tsx @@ -28,7 +28,13 @@ import { validCachedRouteDecision, } from "./log-route-decision"; import { mergeLogDelta, parseLogPollResponse } from "./log-poll"; -import type { AttemptRecoveryKind, RequestSpendTotals } from "../../../src/usage/telemetry-contract"; +import type { + AttemptRecoveryKind, + RequestFailureCause, + RequestFailureStage, + RequestSpendTotals, + ResendPermission, +} from "../../../src/usage/telemetry-contract"; import { classifyRequestOutcome, requestPhysicalSends, @@ -108,7 +114,21 @@ interface LogDisplayMetrics { cost: CostResult; } -interface LogAttempt { +/** + * The durable attribution and the verdict the API derives from it. + * + * `resendPermission` arrives computed rather than stored: the tables that decide it live in the + * proxy and a row must not be able to assert a permission the current tables would refuse. The + * page renders the answer and derives nothing of its own, which is the same rule that keeps the + * outcome class agreeing with the exporter. + */ +interface LogFailureAttribution { + failureStage?: RequestFailureStage; + failureCause?: RequestFailureCause; + resendPermission?: ResendPermission; +} + +interface LogAttempt extends LogFailureAttribution { ordinal: number; provider: string; model: string; @@ -130,7 +150,7 @@ interface LogAttempt { displayMetrics?: LogDisplayMetrics; } -export interface LogEntry { +export interface LogEntry extends LogFailureAttribution { requestId?: string; timestamp: number; model: string; @@ -353,6 +373,51 @@ const OUTCOME_KEYS = { aborted: "logs.detail.outcome.aborted", } as const satisfies Record; +/** + * i18n key for each shared failure cause, total by construction. + * + * The `satisfies` clause is the point. The recovery-kind catalog on this page drifted to nine of + * the durable thirteen and four real causes reached the operator as "Unknown recovery reason" -- + * an absence of a label rendered as an absence of a cause. A missing member here is a typecheck + * failure instead. + */ +const FAILURE_CAUSE_KEYS = { + "transport-unsent": "logs.detail.cause.transportUnsent", + "transport-ambiguous": "logs.detail.cause.transportAmbiguous", + "upstream-declined": "logs.detail.cause.upstreamDeclined", + "rate-limit": "logs.detail.cause.rateLimit", + "quota-exhausted": "logs.detail.cause.quotaExhausted", + "credential-rejected": "logs.detail.cause.credentialRejected", + "policy-refusal": "logs.detail.cause.policyRefusal", + "parameter-rejected": "logs.detail.cause.parameterRejected", + "ciphertext-refusal": "logs.detail.cause.ciphertextRefusal", + "payload-too-large": "logs.detail.cause.payloadTooLarge", + "payload-rejected": "logs.detail.cause.payloadRejected", + "upstream-fault": "logs.detail.cause.upstreamFault", + "empty-output": "logs.detail.cause.emptyOutput", + "client-cancelled": "logs.detail.cause.clientCancelled", + "local-refusal": "logs.detail.cause.localRefusal", +} as const satisfies Record; + +/** i18n key for each stage the caller's view of the exchange reached. */ +const FAILURE_STAGE_KEYS = { + "pre-header": "logs.detail.stage.preHeader", + "headers-only": "logs.detail.stage.headersOnly", + "protocol-prelude": "logs.detail.stage.protocolPrelude", + "semantic-output": "logs.detail.stage.semanticOutput", + "side-effect": "logs.detail.stage.sideEffect", + "terminal": "logs.detail.stage.terminal", +} as const satisfies Record; + +/** i18n key for each resend verdict; every refusal names which refusal it is. */ +const RESEND_PERMISSION_KEYS = { + "permitted": "logs.detail.resend.permitted", + "permitted-after-repair": "logs.detail.resend.permittedAfterRepair", + "refused-ambiguous": "logs.detail.resend.refusedAmbiguous", + "refused-committed": "logs.detail.resend.refusedCommitted", + "refused-futile": "logs.detail.resend.refusedFutile", +} as const satisfies Record; + /** * How this request ended, using the same classifier the Prometheus exporter uses. * @@ -364,6 +429,27 @@ function outcomeKey(entry: Pick= 200 && status < 300) return "var(--green)"; if (status >= 400) return "var(--red)"; @@ -967,6 +1053,7 @@ function LogDetailDialog({ const tokenSplit = cacheSplit(detail); const cost = detail.displayMetrics?.cost; const reasoningWire = reasoningWireLabel(detail); + const detailFailure = failureAttributionLabels(detail, t); const copyRequestId = async () => { if (!detail.requestId) return; @@ -1003,6 +1090,21 @@ function LogDetailDialog({ {t("logs.col.time")}{formatLogDateTime(detail.timestamp, localeTag, serverTimeZone)} {t("logs.detail.outcome.label")} {t(outcomeKey(detail))} + {detailFailure.cause && ( + <> + {t("logs.detail.cause.label")} + + {detailFailure.cause} + {detailFailure.stage && ` (${t("logs.detail.stage.label")}: ${detailFailure.stage})`} + + + )} + {detailFailure.resend && ( + <> + {t("logs.detail.resend.label")} + {detailFailure.resend} + + )} {detail.spend && ( <> {t("logs.detail.sends.label")} @@ -1163,7 +1265,13 @@ function LogDetailDialog({ const attemptCost = attempt.displayMetrics?.cost; const attemptReasoningWire = reasoningWireLabel(attempt); const matched = attemptCost?.kind === "value" ? attemptCost.estimate.price : undefined; - const reason = attempt.errorCode + const attemptFailure = failureAttributionLabels(attempt, t); + // The derived cause leads, because it is the one value in this row that says + // WHY in a vocabulary an operator can act on. `errorCode` stays behind it + // rather than being dropped: it is the exact wire code, which is what a bug + // report needs. + const reason = attemptFailure.cause + ?? attempt.errorCode ?? (attempt.recoveryKinds.length ? attempt.recoveryKinds.map(kind => t(recoveryKindKey(kind))).join(", ") : undefined) diff --git a/src/server/management/shared.ts b/src/server/management/shared.ts index fa3845250f2..d69adc83d47 100644 --- a/src/server/management/shared.ts +++ b/src/server/management/shared.ts @@ -35,12 +35,13 @@ import { clearThreadAccountMap } from "../../codex/routing"; import { primeCodexPoolQuotas } from "../../codex/auth-api"; import { DEFAULT_PROVIDER_CONTEXT_CAP, globalContextCapValue, providerContextCap, providerContextCaps, setAllProviderContextCaps, setGlobalContextCapValue, setProviderContextCap } from "../../providers/context-cap"; import { resolveCodexHomeDir } from "../../codex/home"; -import { readUsageEntries } from "../../usage/log"; +import { isKnownRequestFailureCause, isKnownRequestFailureStage, readUsageEntries } from "../../usage/log"; import { getUsageDebugLogEntries } from "../../usage/debug"; import { cacheObservationFromUsage, parseRange, parseUsageSurface, summarizeUsage } from "../../usage/summary"; import { stripCodexRuntimeProviderFields } from "../../codex/auth-context"; import { getProviderRegistryEntry, providerMatchesRegistryTransport } from "../../providers/registry"; import { getDebugLogEntries } from "../../lib/debug-log-buffer"; +import { resendPermission } from "../../lib/request-failure-model"; import { getInjectionDebugLogEntries } from "../../lib/injection-debug-log"; import { clearDebugSettings, @@ -210,12 +211,27 @@ export function costResult(entry: MetricSource): CostResult { * a Logs-page metric, and widening a separate endpoint's response shape is not this change's * business. Flipping it on later is one argument. */ + +/** + * Whether this proxy could have sent the row again, derived at READ time from the stage and + * cause the recorder stored. + * + * Deliberately not persisted. The verdict is a function of two tables that this build owns, and + * a row written months ago must not be able to assert a permission the current tables would + * refuse -- the whole point of INV-RESEND-01 is that the refusal rules are one statement, and a + * stored verdict would be a second one with no way to correct it. + */ +function resendVerdict(row: { failureStage?: string; failureCause?: string }): { resendPermission?: string } { + if (!isKnownRequestFailureStage(row.failureStage) || !isKnownRequestFailureCause(row.failureCause)) return {}; + return { resendPermission: resendPermission(row.failureStage, row.failureCause) }; +} export function requestLogDto( entry: RequestLogEntry, { includeDecodeRate = true }: { includeDecodeRate?: boolean } = {}, ): Record { return { ...entry, + ...resendVerdict(entry), displayMetrics: { tokPerSecond: tokPerSecondResult(entry), // The parent uses the REQUEST's own TTFT. A combo parent must not borrow an attempt's, @@ -227,6 +243,7 @@ export function requestLogDto( ? { attempts: entry.attempts.map(attempt => ({ ...attempt, + ...resendVerdict(attempt), displayMetrics: { tokPerSecond: tokPerSecondResult(attempt), // Each attempt measures its own attempt-relative TTFT. diff --git a/src/server/request-log.ts b/src/server/request-log.ts index bc39aedb785..97aa86e6cec 100644 --- a/src/server/request-log.ts +++ b/src/server/request-log.ts @@ -1445,6 +1445,7 @@ export function addFinalRequestLog( ...(closeReason ? { closeReason } : {}), ...(attempts !== undefined ? { attempts } : {}), ...(spend ? { spendSends: spend.sends } : {}), + ...(attribution?.cause ? { failureCause: attribution.cause } : {}), }); const cacheProvenance = classifyCacheTelemetryProvenance(loggedUsage, { wireParsed: logCtx.usageWireParsed === true, diff --git a/src/server/request-metrics.ts b/src/server/request-metrics.ts index f678b6565ba..cc3b89db977 100644 --- a/src/server/request-metrics.ts +++ b/src/server/request-metrics.ts @@ -1,6 +1,10 @@ import type { ResponsesTerminalStatus } from "../bridge"; import type { AttemptRecoveryKind } from "../usage/log"; -import { type RequestFailureCause, causeForRecoveryKind } from "../lib/request-failure-model"; +import { + REQUEST_FAILURE_CAUSES, + type RequestFailureCause, + causeForRecoveryKind, +} from "../lib/request-failure-model"; import { REQUEST_OUTCOME_CLASSES, classifyRequestOutcome, @@ -40,6 +44,18 @@ export const REQUEST_METRICS_RECOVERY_CLASSES = Object.freeze([ export const REQUEST_DURATION_BUCKETS_SECONDS = Object.freeze([0.1, 0.25, 0.5, 1, 2.5, 5, 10, 30, 60] as const); export const REQUEST_TTFT_BUCKETS_SECONDS = Object.freeze([0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10, 30] as const); +/** + * The failure-cause label set IS the shared dictionary, for the same reason the result label set + * is the shared outcome vocabulary: a restated copy is what let two surfaces drift into + * disagreeing about the same request. + * + * It labels a COUNTER and never a histogram. Fifteen causes across four protocols is sixty + * series, fixed for the lifetime of the roster, and every value comes from a frozen list, so no + * user, model, account or request identifier can reach a series name. A histogram labelled by + * cause would multiply that by its bucket count for no question anyone asks. + */ +export const REQUEST_METRICS_FAILURE_CAUSES = REQUEST_FAILURE_CAUSES; + export type RequestMetricsProtocol = typeof REQUEST_METRICS_PROTOCOLS[number]; export type RequestMetricsResult = RequestOutcomeClass; export type RequestMetricsRecoveryClass = typeof REQUEST_METRICS_RECOVERY_CLASSES[number]; @@ -56,6 +72,11 @@ export interface RequestMetricFinalFact { recoveryKinds: readonly AttemptRecoveryKind[]; }>; spendSends?: number; + /** + * Why this request failed, as the recorder derived it. Absent when it did not fail, which is + * why the counter below cannot be reconstructed by subtracting completions from totals. + */ + failureCause?: RequestFailureCause; } export interface RequestMetricsRecorder { @@ -79,6 +100,7 @@ interface HistogramCell { const protocolCell = (value: RequestMetricsProtocol): number => REQUEST_METRICS_PROTOCOLS.indexOf(value); const resultCell = (value: RequestMetricsResult): number => REQUEST_METRICS_RESULTS.indexOf(value); const recoveryCell = (value: RequestMetricsRecoveryClass): number => REQUEST_METRICS_RECOVERY_CLASSES.indexOf(value); +const failureCauseCell = (value: RequestFailureCause): number => REQUEST_METRICS_FAILURE_CAUSES.indexOf(value); function matrix(rows: number, columns: number): number[][] { return Array.from({ length: rows }, () => Array.from({ length: columns }, () => 0)); @@ -167,6 +189,7 @@ export function createRequestMetricsOwner( let logicalRequests = matrix(REQUEST_METRICS_PROTOCOLS.length, REQUEST_METRICS_RESULTS.length); let physicalSends = Array.from({ length: REQUEST_METRICS_PROTOCOLS.length }, () => 0); let recoveries = matrix(REQUEST_METRICS_PROTOCOLS.length, REQUEST_METRICS_RECOVERY_CLASSES.length); + let failureCauses = matrix(REQUEST_METRICS_PROTOCOLS.length, REQUEST_METRICS_FAILURE_CAUSES.length); let durations = histograms(REQUEST_DURATION_BUCKETS_SECONDS); let ttft = histograms(REQUEST_TTFT_BUCKETS_SECONDS); let missingTtft = matrix(REQUEST_METRICS_PROTOCOLS.length, REQUEST_METRICS_RESULTS.length); @@ -187,6 +210,13 @@ export function createRequestMetricsOwner( ), 0); physicalSends[protocolIndex]! += sends; + // Counted from the cause the recorder derived, not re-derived here. Two derivations of one + // answer is the disagreement this batch exists to remove, and the recorder is the only + // place that sees the transport facts a cause needs. + if (fact.failureCause !== undefined) { + failureCauses[protocolIndex]![failureCauseCell(fact.failureCause)]! += 1; + } + for (const attempt of attempts ?? []) { for (const kind of new Set(attempt.recoveryKinds)) { recoveries[protocolIndex]![recoveryCell(recoveryClass(kind))]! += 1; @@ -227,6 +257,15 @@ export function createRequestMetricsOwner( lines.push(`opencodex_recoveries_total{protocol="${protocol}",recovery="${recovery}"} ${recoveries[protocolCell(protocol)]![recoveryCell(recovery)]}`); } } + lines.push( + "# HELP opencodex_request_failures_total Finalized logical requests that did not deliver an answer, by derived cause.", + "# TYPE opencodex_request_failures_total counter", + ); + for (const protocol of REQUEST_METRICS_PROTOCOLS) { + for (const cause of REQUEST_METRICS_FAILURE_CAUSES) { + lines.push(`opencodex_request_failures_total{protocol="${protocol}",cause="${cause}"} ${failureCauses[protocolCell(protocol)]![failureCauseCell(cause)]}`); + } + } appendHistogram(lines, "opencodex_request_duration_seconds", "Finalized logical request duration in seconds.", durations, REQUEST_DURATION_BUCKETS_SECONDS); appendHistogram(lines, "opencodex_ttft_seconds", "Observed time to first output in seconds.", ttft, REQUEST_TTFT_BUCKETS_SECONDS); lines.push( @@ -250,6 +289,7 @@ export function createRequestMetricsOwner( logicalRequests = matrix(REQUEST_METRICS_PROTOCOLS.length, REQUEST_METRICS_RESULTS.length); physicalSends = Array.from({ length: REQUEST_METRICS_PROTOCOLS.length }, () => 0); recoveries = matrix(REQUEST_METRICS_PROTOCOLS.length, REQUEST_METRICS_RECOVERY_CLASSES.length); + failureCauses = matrix(REQUEST_METRICS_PROTOCOLS.length, REQUEST_METRICS_FAILURE_CAUSES.length); durations = histograms(REQUEST_DURATION_BUCKETS_SECONDS); ttft = histograms(REQUEST_TTFT_BUCKETS_SECONDS); missingTtft = matrix(REQUEST_METRICS_PROTOCOLS.length, REQUEST_METRICS_RESULTS.length); diff --git a/tests/usage/request-outcome-agreement.test.ts b/tests/usage/request-outcome-agreement.test.ts index b5b30744e9e..3d48ace90fe 100644 --- a/tests/usage/request-outcome-agreement.test.ts +++ b/tests/usage/request-outcome-agreement.test.ts @@ -11,6 +11,8 @@ import { } from "../../src/usage/request-outcome"; import { REQUEST_METRICS_RESULTS, + REQUEST_METRICS_FAILURE_CAUSES, + REQUEST_METRICS_PROTOCOLS, createRequestMetricsOwner, } from "../../src/server/request-metrics"; import { ATTEMPT_RECOVERY_KIND_ROSTER } from "../../src/usage/telemetry-contract"; @@ -191,7 +193,7 @@ describe("the dashboard recovery roster cannot drift from the durable one", () = test("every label key the page names exists in all ten catalogs", () => { const page = readFileSync(repoPath("gui", "src", "pages", "Logs.tsx"), "utf8"); - const keys = [...new Set([...page.matchAll(/"(logs\.detail\.(?:attempt\.recovery|outcome|sends)\.[a-zA-Z0-9]+)"/g)] + const keys = [...new Set([...page.matchAll(/"(logs\.detail\.(?:attempt\.recovery|outcome|sends|cause|stage|resend)\.[a-zA-Z0-9]+)"/g)] .map(match => match[1]!))]; expect(keys.length).toBeGreaterThan(ATTEMPT_RECOVERY_KIND_ROSTER.length); const gaps: string[] = []; @@ -214,6 +216,70 @@ describe("the exporter stays bounded", () => { } const snapshot = metrics.snapshot(); const labels = [...new Set([...snapshot.matchAll(/([a-z_]+)="/g)].map(match => match[1]!))]; - expect(labels.sort()).toEqual(["le", "protocol", "recovery", "result"]); + expect(labels.sort()).toEqual(["cause", "le", "protocol", "recovery", "result"]); + }); + + /** + * The cause label is a counter label and never a histogram one. Fifteen causes across four + * protocols is a fixed sixty series; the same label on a histogram would multiply that by the + * bucket count to answer a question nobody asked. + */ + test("the failure cause labels a counter and no histogram", () => { + const snapshot = createRequestMetricsOwner(1).snapshot(); + const causeLines = snapshot.split("\n").filter(line => line.includes('cause="')); + expect(causeLines.length).toBe( + REQUEST_METRICS_PROTOCOLS.length * REQUEST_METRICS_FAILURE_CAUSES.length, + ); + expect(causeLines.every(line => line.startsWith("opencodex_request_failures_total{"))).toBe(true); + expect(causeLines.some(line => line.includes("_bucket") || line.includes("le="))).toBe(false); + }); +}); + +describe("the failure cause is derived once and reported everywhere", () => { + /** + * The recorder derives the cause; the exporter counts the value it was handed. Two derivations + * of one answer is the disagreement this batch exists to remove, so this asserts the exporter + * has no opinion of its own -- a fact carrying a cause the status alone would classify + * differently is still counted under the cause it was given. + */ + test("the exporter counts the recorder's cause rather than re-deriving one", () => { + for (const cause of REQUEST_METRICS_FAILURE_CAUSES) { + const metrics = createRequestMetricsOwner(1); + metrics.recordFinalRequest({ + protocol: "responses", status: 200, durationMs: 1, terminalStatus: "failed", failureCause: cause, + }); + const snapshot = metrics.snapshot(); + expect(sampleValue(snapshot, `opencodex_request_failures_total{protocol="responses",cause="${cause}"}`)).toBe(1); + } + }); + + test("a request that delivered its answer contributes to no cause series", () => { + const metrics = createRequestMetricsOwner(1); + metrics.recordFinalRequest({ protocol: "responses", status: 200, durationMs: 1, terminalStatus: "completed" }); + const snapshot = metrics.snapshot(); + for (const cause of REQUEST_METRICS_FAILURE_CAUSES) { + expect(sampleValue(snapshot, `opencodex_request_failures_total{protocol="responses",cause="${cause}"}`)).toBe(0); + } + }); + + test("every cause the recorder can derive has a dashboard label", () => { + const page = readFileSync(repoPath("gui", "src", "pages", "Logs.tsx"), "utf8"); + const block = page.slice(page.indexOf("const FAILURE_CAUSE_KEYS"), page.indexOf("} as const satisfies Record !block.includes(`"${cause}":`)); + expect(missing).toEqual([]); + }); + + /** + * The verdict is computed at read time and must not appear in a durable shape. A row written + * by an older build would otherwise assert a permission the current tables refuse, and there + * would be no way to correct it. + */ + test("the resend verdict is never persisted", () => { + const ledger = readFileSync(repoPath("src", "usage", "log.ts"), "utf8"); + expect(ledger).toContain("failureStage"); + expect(ledger).toContain("failureCause"); + expect(ledger).not.toContain("resendPermission"); + const dto = readFileSync(repoPath("src", "server", "management", "shared.ts"), "utf8"); + expect(dto).toContain("resendPermission"); }); }); From 79d10043939a576fa45610af97f94a264dddc819 Mon Sep 17 00:00:00 2001 From: JUN Date: Sun, 20 Sep 2026 21:54:54 +0900 Subject: [PATCH 03/10] feat(usage): group recurring failures as a projection, not a second store #3748 proposed a privacy-safe failure ledger and built it as a second SQLite store beside usage.jsonl, keyed by a free-text signature that regular expressions tried to mask. Both halves are replaced. The store becomes a projection rebuilt from the canonical ledger. It holds a count and two timestamps per group and nothing else, so deleting a row from usage.jsonl removes it from this grouping on the next rebuild -- which is what it means for retention to have one owner instead of four. It reads through the existing scanUsageLedgerCooperatively and therefore inherits every bound that scanner already enforces: the 1 MiB row ceiling, the 1 MiB chunk, the cooperative yield, the opened-EOF snapshot boundary, and the path/device/inode/birthtime identity with its 64 KiB boundary digest. A same-size file whose revision metadata moved forces a rebuild rather than an append, so a replaced ledger can never extend stale groups. The masked signature becomes a fixed-arity tuple of closed roster members. A regular expression can only assert that it removed what it matched; a tuple whose every slot is a member of a frozen list has nothing to remove. The input type cannot express a model, an account, an error message, a prompt, a request id or a timestamp, so no amount of upstream text can reach a fingerprint. Absent facts are explicit nulls in fixed positions, because omitting them would let [a, null, b] and [a, b] collide. The configured provider name is the one input that starts as free text -- users name their own provider entries -- so it is resolved against the provider registry and becomes null when it is not a registry member. A provider named after its owner groups under null, which is the honest answer. This exposed a real hole the fingerprint would otherwise have inherited: terminalStatus was persisted as a plain string and copied through the normalizer on truthiness alone, unlike the inbound protocol, transport phase and terminal source beside it. Harmless while it was only rendered; not harmless as a grouping-key slot, because the value is assembled from an upstream terminal frame. It is now the closed type, derived from the outcome roster rather than restated, and validated on read back. Two parts of the original are deliberately absent. The occurrence list is a second copy of history with its own retention policy. The mutable monitoring/dispatched/fixed/ignored status and its notes are operator state, which cannot be reconstructed from immutable request rows; presenting them as a derived ledger would be presenting a claim this projection cannot make. They need their own owner, keyed by the fingerprint, if they are wanted. The reader is GET /api/usage?failures=1 rather than a new route: it answers a different question from the usage summary and costs a scan, so it is opt-in and a dashboard asking for spend does not pay for it. Co-authored-by: SB Yoon <44089734+yansigit@users.noreply.github.com> --- scripts/test-layout/layout.json | 2 + src/server/management/logs-usage-routes.ts | 19 ++ src/usage/failure-fingerprint.ts | 118 ++++++++++++ src/usage/failure-projection-cache.ts | 174 ++++++++++++++++++ src/usage/failure-projection.ts | 174 ++++++++++++++++++ src/usage/log.ts | 22 ++- src/usage/request-outcome.ts | 48 +++++ tests/fixtures/test-layout-expected.json | 2 + tests/usage/usage-failure-fingerprint.test.ts | 106 +++++++++++ tests/usage/usage-failure-projection.test.ts | 125 +++++++++++++ 10 files changed, 786 insertions(+), 4 deletions(-) create mode 100644 src/usage/failure-fingerprint.ts create mode 100644 src/usage/failure-projection-cache.ts create mode 100644 src/usage/failure-projection.ts create mode 100644 tests/usage/usage-failure-fingerprint.test.ts create mode 100644 tests/usage/usage-failure-projection.test.ts diff --git a/scripts/test-layout/layout.json b/scripts/test-layout/layout.json index 23a1b837451..e1274cf038d 100644 --- a/scripts/test-layout/layout.json +++ b/scripts/test-layout/layout.json @@ -1229,6 +1229,8 @@ "request-log-estimate-cap.test.ts": "usage", "request-log.test.ts": "usage", "request-outcome-agreement.test.ts": "usage", + "usage-failure-fingerprint.test.ts": "usage", + "usage-failure-projection.test.ts": "usage", "request-pacing.test.ts": "usage", "reserve-auth-context.test.ts": "codex-integration", "reserve-availability.test.ts": "codex-integration", diff --git a/src/server/management/logs-usage-routes.ts b/src/server/management/logs-usage-routes.ts index cd1e3ed3b0f..51bf12725ea 100644 --- a/src/server/management/logs-usage-routes.ts +++ b/src/server/management/logs-usage-routes.ts @@ -22,6 +22,7 @@ import { upsertOAuthProvider, } from "../../oauth"; import { removeCredential } from "../../oauth/store"; +import { getFailureProjection } from "../../usage/failure-projection-cache"; import { providerDestinationResolvedError } from "../../lib/destination-policy"; import { enrichProviderFromCatalog, listKeyLoginProviders } from "../../oauth/key-providers"; import { deriveProviderPresets } from "../../providers/derive"; @@ -179,6 +180,24 @@ export async function handleLogsUsageRoutes(ctx: ManagementContext): Promise | null; + readonly terminalStatus: RequestTerminalStatus | null; + readonly closeReason: RequestCloseReason | null; + readonly transportPhase: NonNullable | null; + readonly terminalSource: NonNullable | null; +} + +/** + * Fixed positions, with every absent fact written as an explicit `null`. + * + * Omitting an absent field, or joining the present ones with a delimiter, would let two + * different failures collide: `[a, null, b]` and `[a, b]` are the same string once the nulls + * are dropped. A fixed-arity tuple cannot collide that way, which is why the shape is a tuple + * rather than an object with optional keys. + */ +export type FailureFingerprintTuple = readonly [ + version: typeof FAILURE_FINGERPRINT_VERSION, + cause: FailureFingerprintFacts["cause"], + statusClass: FailureFingerprintFacts["statusClass"], + providerClass: FailureFingerprintFacts["providerClass"], + inboundProtocol: FailureFingerprintFacts["inboundProtocol"], + terminalStatus: FailureFingerprintFacts["terminalStatus"], + closeReason: FailureFingerprintFacts["closeReason"], + transportPhase: FailureFingerprintFacts["transportPhase"], + terminalSource: FailureFingerprintFacts["terminalSource"], +]; + +export function failureStatusClass(status: unknown): FailureStatusClass { + if (typeof status !== "number" || !Number.isInteger(status) || status < 100 || status > 599) { + return "unknown"; + } + const index = Math.floor(status / 100) - 1; + return FAILURE_STATUS_CLASSES[index] ?? "unknown"; +} + +export function canonicalFailureFingerprintTuple( + facts: FailureFingerprintFacts, +): FailureFingerprintTuple { + return [ + FAILURE_FINGERPRINT_VERSION, + facts.cause, + facts.statusClass, + facts.providerClass, + facts.inboundProtocol, + facts.terminalStatus, + facts.closeReason, + facts.transportPhase, + facts.terminalSource, + ]; +} + +/** + * The version travels in the value, not only in the hashed input. + * + * Both matter and for different reasons: hashing it means two versions of the same failure never + * collide, and prefixing it means a reader holding an old fingerprint can tell that it is old + * instead of concluding the failure stopped happening. + */ +export function computeFailureFingerprint(facts: FailureFingerprintFacts): FailureFingerprint { + const digest = createHash("sha256") + .update(JSON.stringify(canonicalFailureFingerprintTuple(facts))) + .digest("hex"); + return `v${FAILURE_FINGERPRINT_VERSION}:${digest}`; +} diff --git a/src/usage/failure-projection-cache.ts b/src/usage/failure-projection-cache.ts new file mode 100644 index 00000000000..953f292fe52 --- /dev/null +++ b/src/usage/failure-projection-cache.ts @@ -0,0 +1,174 @@ +/** + * The scan owner for the failure projection: one checkpointed pass over usage.jsonl. + * + * Shaped after `src/server/management/usage-aggregate-cache.ts`, which solved the same problem + * for the usage summary. That similarity is deliberate -- the correctness here is entirely in + * the checkpoint discipline, and two subtly different versions of it is how a projection quietly + * extends stale groups across a file that was replaced under it. + * + * Every bound this projection obeys belongs to the scanner it calls, not to itself: the 1 MiB + * row ceiling, the 1 MiB chunk, the cooperative yield, the opened-EOF snapshot boundary and the + * path/device/inode/birthtime identity with its 64 KiB boundary digest. A projection with its + * own limits would be a second storage policy, which is what this lane exists to avoid. + */ +import { + currentUsageLogRevision, + usageLogIdentityKey, + usageLogRevisionKey, + type UsageLogRevision, +} from "./log"; +import { + scanUsageLedgerCooperatively, + UsageLedgerRebuildRequiredError, +} from "./ledger-scanner"; +import { + createFailureProjectionAccumulator, + type FailureProjectionAccumulator, + type FailureProjectionSnapshot, +} from "./failure-projection"; + +export type FailureProjectionUpdate = "unchanged" | "append" | "rebuild"; + +export interface FailureProjectionResult extends FailureProjectionSnapshot { + update: FailureProjectionUpdate; + /** True once any row was skipped for exceeding the scanner's row ceiling. Sticky. */ + historyIncomplete: boolean; +} + +interface RetainedProjection { + accumulator: FailureProjectionAccumulator; + historyIncomplete: boolean; + revision: UsageLogRevision | null; + identityKey: string; + revisionKey: string; + processedThroughBytes: number; + processedThroughDigest: string; +} + +const MAX_REBUILD_ATTEMPTS = 2; +let retained: RetainedProjection | null = null; +let inFlight: Promise | null = null; + +function resultFrom(state: RetainedProjection, update: FailureProjectionUpdate): FailureProjectionResult { + return { ...state.accumulator.snapshot(), update, historyIncomplete: state.historyIncomplete }; +} + +function retain( + accumulator: FailureProjectionAccumulator, + scan: Awaited>, + historyIncomplete: boolean, +): RetainedProjection { + return { + accumulator, + historyIncomplete: historyIncomplete || scan.oversizedRows > 0, + revision: scan.revision, + identityKey: usageLogIdentityKey(scan.revision), + revisionKey: usageLogRevisionKey(scan.revision), + processedThroughBytes: scan.processedThroughBytes, + processedThroughDigest: scan.processedThroughDigest, + }; +} + +async function rebuild(signal: AbortSignal | undefined): Promise { + let lastError: unknown; + for (let attempt = 0; attempt < MAX_REBUILD_ATTEMPTS; attempt += 1) { + const accumulator = createFailureProjectionAccumulator(); + try { + const scan = await scanUsageLedgerCooperatively({ + ...(signal ? { signal } : {}), + onEntry: entry => accumulator.add(entry), + }); + retained = retain(accumulator, scan, false); + return resultFrom(retained, "rebuild"); + } catch (error) { + lastError = error; + if (!(error instanceof UsageLedgerRebuildRequiredError) || attempt + 1 >= MAX_REBUILD_ATTEMPTS) throw error; + } + } + throw lastError ?? new Error("failure projection rebuild did not settle"); +} + +/** + * Whether the observed ledger can still be read as an append onto the retained state. + * + * A same-size file whose revision metadata moved is a replacement or an in-place edit, not an + * append. Treating it as one would extend groups built from rows that no longer exist, so it + * forces a rebuild even though the byte count is unchanged. + */ +function requiresRebuild(state: RetainedProjection, observed: UsageLogRevision | null): boolean { + if (state.identityKey !== usageLogIdentityKey(observed)) return true; + if (!state.revision || !observed) return state.revision !== observed; + if (observed.size < state.revision.size) return true; + return observed.size === state.revision.size && usageLogRevisionKey(observed) !== state.revisionKey; +} + +async function append( + state: RetainedProjection, + signal: AbortSignal | undefined, +): Promise { + // Clone first and publish only after the scanner verifies the captured suffix, so a mutation + // discovered mid-scan leaves the retained state exactly as it was. + const candidate = state.accumulator.clone(); + try { + const scan = await scanUsageLedgerCooperatively({ + ...(signal ? { signal } : {}), + startAtBytes: state.processedThroughBytes, + expectedIdentityKey: state.identityKey, + expectedProcessedThroughDigest: state.processedThroughDigest, + onEntry: entry => candidate.add(entry), + }); + retained = retain(candidate, scan, state.historyIncomplete); + return resultFrom(retained, "append"); + } catch (error) { + if (retained === state) retained = null; + if (error instanceof UsageLedgerRebuildRequiredError) return rebuild(signal); + throw error; + } +} + +async function refresh(signal: AbortSignal | undefined): Promise { + const state = retained; + if (!state) return rebuild(signal); + const observed = currentUsageLogRevision(); + if (requiresRebuild(state, observed)) return rebuild(signal); + if (observed && state.revision && observed.size === state.revision.size) { + return resultFrom(state, "unchanged"); + } + return append(state, signal); +} + +/** + * The current grouping, refreshed from the ledger. + * + * Single-flighted: two concurrent readers would otherwise run two scans of the same file and + * one of them would publish over the other's checkpoint. + */ +export async function getFailureProjection( + options: { signal?: AbortSignal } = {}, +): Promise { + if (inFlight) return inFlight; + const flight = refresh(options.signal).finally(() => { + if (inFlight === flight) inFlight = null; + }); + inFlight = flight; + return flight; +} + +/** + * Drop the retained projection. + * + * Safe at any time and for any reason: it is rebuildable from the ledger by construction, which + * is the property that lets memory pressure discard the whole thing rather than prune individual + * groups. Pruning groups would make this projection a retention policy of its own. + */ +export function discardRetainedFailureProjection(): number { + const count = retained?.accumulator.groupCount ?? 0; + retained = null; + return count; +} + +/** Test-only process-state reset for isolated harnesses. */ +export function resetFailureProjectionCacheForTests(): void { + retained = null; + inFlight = null; +} diff --git a/src/usage/failure-projection.ts b/src/usage/failure-projection.ts new file mode 100644 index 00000000000..f235eac3628 --- /dev/null +++ b/src/usage/failure-projection.ts @@ -0,0 +1,174 @@ +/** + * Failures grouped by what they have in common, rebuilt from the canonical ledger. + * + * This is the derived form of #3748. The original built a second durable store; this holds only + * a count and two timestamps per group, and every one of them falls out of a scan of + * usage.jsonl. Delete a row from the ledger and it leaves this projection on the next rebuild, + * which is what it means for retention to have one owner rather than four. + * + * What it deliberately does NOT hold: the occurrence list the original retained (a second copy + * of history with its own retention policy), and the mutable monitoring/dispatched/fixed/ignored + * remediation status with its free-text notes. Those are operator state, not event history: they + * cannot be reconstructed from immutable request rows, so presenting them as a derived ledger + * would be presenting a claim this projection cannot make. They need their own owner if they are + * wanted, keyed by the fingerprint below. + */ +import { getProviderRegistryEntry } from "../providers/registry"; +import { baseProviderLabel } from "../providers/label"; +import { + computeFailureFingerprint, + failureStatusClass, + FAILURE_FINGERPRINT_VERSION, + type FailureFingerprint, + type FailureFingerprintFacts, +} from "./failure-fingerprint"; +import { + classifyRequestOutcome, + isRequestCloseReason, + isRequestTerminalStatus, +} from "./request-outcome"; +import { + isKnownInboundProtocol, + isKnownRequestFailureCause, + isKnownTerminalSource, + isKnownTransportPhase, + type PersistedUsageEntry, +} from "./log"; + +/** + * The configured provider name reduced to a registry member, or null. + * + * The durable `provider` is whatever the user named their provider entry, so it is open text and + * cannot enter a key that promises to carry no content. Resolving it against the registry makes + * the value closed by construction: either it is one of the ids this build ships, or it is + * nothing. A user who names a provider after themselves groups under `null`, which is the + * correct answer -- the projection does not know which provider it is. + */ +export function failureProviderClass(provider: string): string | null { + return getProviderRegistryEntry(baseProviderLabel(provider))?.id ?? null; +} + +export interface FailureProjectionGroup extends FailureFingerprintFacts { + fingerprint: FailureFingerprint; + firstSeen: number; + lastSeen: number; + count: number; +} + +export interface FailureProjectionSnapshot { + fingerprintVersion: typeof FAILURE_FINGERPRINT_VERSION; + groups: readonly FailureProjectionGroup[]; + /** + * Failed rows written before the recorder stored a cause. Counted rather than bucketed under + * an invented "unknown" cause, because a group an operator cannot act on is worse than a + * number that says how much history predates the field. + */ + unattributedFailures: number; + /** Failed rows whose timestamp is not a finite number, so they cannot date a group. */ + invalidTimestampFailures: number; +} + +export interface FailureProjectionAccumulator { + add(entry: PersistedUsageEntry): void; + clone(): FailureProjectionAccumulator; + snapshot(): FailureProjectionSnapshot; + readonly groupCount: number; +} + +interface MutableGroup extends FailureFingerprintFacts { + fingerprint: FailureFingerprint; + firstSeen: number; + lastSeen: number; + count: number; +} + +function factsFor(entry: PersistedUsageEntry): FailureFingerprintFacts | null { + if (!isKnownRequestFailureCause(entry.failureCause)) return null; + return { + cause: entry.failureCause, + statusClass: failureStatusClass(entry.status), + providerClass: failureProviderClass(entry.provider), + inboundProtocol: isKnownInboundProtocol(entry.inboundProtocol) ? entry.inboundProtocol : null, + // Validated rather than copied. This is the one tuple slot whose durable type is a plain + // string, and it is assembled from an upstream terminal frame, so an unvalidated value is + // the single way upstream-controlled text could reach a grouping key. + terminalStatus: isRequestTerminalStatus(entry.terminalStatus) ? entry.terminalStatus : null, + closeReason: isRequestCloseReason(entry.closeReason) ? entry.closeReason : null, + transportPhase: isKnownTransportPhase(entry.transportPhase) ? entry.transportPhase : null, + terminalSource: isKnownTerminalSource(entry.terminalSource) ? entry.terminalSource : null, + }; +} + +function createFrom(groups: Map, counters: { + unattributed: number; + invalidTimestamp: number; +}): FailureProjectionAccumulator { + let unattributedFailures = counters.unattributed; + let invalidTimestampFailures = counters.invalidTimestamp; + + return { + add(entry: PersistedUsageEntry): void { + // The shared classifier decides what a failure is, so this projection and the exporter + // agree on which rows are in scope. An incomplete turn is not here: it has no cause. + if (classifyRequestOutcome(entry) !== "failed") return; + const facts = factsFor(entry); + if (facts === null) { + unattributedFailures += 1; + return; + } + if (typeof entry.timestamp !== "number" || !Number.isFinite(entry.timestamp)) { + invalidTimestampFailures += 1; + return; + } + const fingerprint = computeFailureFingerprint(facts); + const existing = groups.get(fingerprint); + if (existing === undefined) { + groups.set(fingerprint, { + ...facts, + fingerprint, + firstSeen: entry.timestamp, + lastSeen: entry.timestamp, + count: 1, + }); + return; + } + // Min and max rather than first-and-last-written: a ledger is append-ordered in practice + // but nothing in the format promises it, and a projection that assumed order would report + // a first-seen later than its last-seen for a hand-merged file. + existing.firstSeen = Math.min(existing.firstSeen, entry.timestamp); + existing.lastSeen = Math.max(existing.lastSeen, entry.timestamp); + existing.count += 1; + }, + + clone(): FailureProjectionAccumulator { + const copy = new Map(); + for (const [key, group] of groups) copy.set(key, { ...group }); + return createFrom(copy, { + unattributed: unattributedFailures, + invalidTimestamp: invalidTimestampFailures, + }); + }, + + snapshot(): FailureProjectionSnapshot { + // Most recent first, then by fingerprint, so two runs over the same ledger produce the + // same order. A tie broken by insertion order would depend on scan chunking. + const ordered = [...groups.values()] + .map(group => ({ ...group })) + .sort((a, b) => b.lastSeen - a.lastSeen || (a.fingerprint < b.fingerprint ? -1 : a.fingerprint > b.fingerprint ? 1 : 0)); + return { + fingerprintVersion: FAILURE_FINGERPRINT_VERSION, + groups: ordered, + unattributedFailures, + invalidTimestampFailures, + }; + }, + + get groupCount(): number { + return groups.size; + }, + }; +} + +export function createFailureProjectionAccumulator(): FailureProjectionAccumulator { + return createFrom(new Map(), { unattributed: 0, invalidTimestamp: 0 }); +} diff --git a/src/usage/log.ts b/src/usage/log.ts index b881cdadca3..e40c42436fe 100644 --- a/src/usage/log.ts +++ b/src/usage/log.ts @@ -7,6 +7,12 @@ import { enforceAppOwnedMemoryBudget } from "../lib/app-owned-memory"; import { recordOwnedConfigPath } from "../lib/config-ownership"; import { sanitizeLogMetadataString } from "../lib/redact"; import { usageDisplayTotalTokens } from "./totals"; +import { + isRequestCloseReason, + isRequestTerminalStatus, + type RequestCloseReason, + type RequestTerminalStatus, +} from "./request-outcome"; import type { AttemptTierOutcome, OcxUsage } from "../types"; import { normalizeRouteDecisionTrace, type RouteDecisionTraceV1 } from "../routing/trace"; import { ACCOUNT_LOG_LABEL_RE, CODEX_ACCOUNT_LOG_LABEL_RE } from "../codex/account-label"; @@ -304,8 +310,13 @@ export interface PersistedUsageEntry { // Failure diagnostics (devlog/_plan/260716_claudecode_hardening/030): persisted for // status>=400 or non-completed terminals so incidents survive the in-memory ring buffer. errorCode?: string; - terminalStatus?: string; - closeReason?: "terminal" | "client_cancel" | "non_stream" | "body_stall" | "body_overflow"; + /** + * Closed, like `closeReason` beside it has always been. It was `string` while it was only + * rendered; it is a grouping-key slot now, and the value is assembled from an upstream + * terminal frame, so an open type here is the one way upstream text could reach that key. + */ + terminalStatus?: RequestTerminalStatus; + closeReason?: RequestCloseReason; /** Already redacted + capped at capture (request-log.ts redactSecretString().slice(0,500)). */ upstreamError?: string; /** Where the terminal/failure was observed; absent on historic rows. */ @@ -888,8 +899,11 @@ function normalizeUsageEntry(entry: PersistedUsageEntry): PersistedUsageEntry { ...(affinityReason ? { affinityReason } : {}), ...(conversationStateScrub ? { conversationStateScrub } : {}), ...(entry.errorCode ? { errorCode: entry.errorCode } : {}), - ...(entry.terminalStatus ? { terminalStatus: entry.terminalStatus } : {}), - ...(entry.closeReason ? { closeReason: entry.closeReason } : {}), + // Validated rather than copied on truthiness, like the inbound protocol and transport phase + // above. Harmless while these were only rendered; not harmless once the terminal status is + // a grouping-key slot, because the string is assembled from an upstream frame. + ...(isRequestTerminalStatus(entry.terminalStatus) ? { terminalStatus: entry.terminalStatus } : {}), + ...(isRequestCloseReason(entry.closeReason) ? { closeReason: entry.closeReason } : {}), ...(entry.upstreamError ? { upstreamError: entry.upstreamError } : {}), ...(routeDecision ? { routeDecision } : {}), ...(claudeCompatibility ? { claudeCompatibility } : {}), diff --git a/src/usage/request-outcome.ts b/src/usage/request-outcome.ts index 9db60aee365..a72f4cb8662 100644 --- a/src/usage/request-outcome.ts +++ b/src/usage/request-outcome.ts @@ -34,6 +34,54 @@ export const REQUEST_OUTCOME_CLASSES = Object.freeze([ export type RequestOutcomeClass = typeof REQUEST_OUTCOME_CLASSES[number]; +/** + * The terminal statuses a Responses turn can settle on. + * + * Derived from the outcome classes rather than restated: a turn reports whether it completed, + * failed or stopped short, and `aborted` is not one of them because the caller leaving is not a + * terminal the origin emits. Deriving it means a fifth outcome class cannot leave this list + * stale, and restating the three would be the same copy that let the recovery roster drift. + */ +export type RequestTerminalStatus = Exclude; + +/** + * The same three members as a runtime list, filtered out of the outcome roster rather than + * typed out again, so the guard below cannot disagree with the type above it. + */ +export const REQUEST_TERMINAL_STATUSES: readonly RequestTerminalStatus[] = Object.freeze( + REQUEST_OUTCOME_CLASSES.filter((value): value is RequestTerminalStatus => value !== "aborted"), +); + +/** Why the response body stopped being read. Closed, and persisted as such. */ +export const REQUEST_CLOSE_REASONS = Object.freeze([ + "terminal", + "client_cancel", + "non_stream", + "body_stall", + "body_overflow", +] as const); + +export type RequestCloseReason = typeof REQUEST_CLOSE_REASONS[number]; + +/** + * Read-back guards for the two facts that reach a durable row as strings. + * + * `terminalStatus` was typed `string` on the persisted entry and copied through the normalizer + * on truthiness alone, unlike the inbound protocol, transport phase and terminal source beside + * it. That was harmless while the value was only rendered; it stops being harmless the moment + * the value becomes part of a grouping key, because the string is assembled from an upstream + * frame and an unvalidated one would put upstream-controlled text into the key. + */ +export function isRequestTerminalStatus(value: unknown): value is RequestTerminalStatus { + return typeof value === "string" + && (REQUEST_TERMINAL_STATUSES as readonly string[]).includes(value); +} + +export function isRequestCloseReason(value: unknown): value is RequestCloseReason { + return typeof value === "string" + && (REQUEST_CLOSE_REASONS as readonly string[]).includes(value); +} + /** * The facts a terminal classification is allowed to read. * diff --git a/tests/fixtures/test-layout-expected.json b/tests/fixtures/test-layout-expected.json index 4a14a5192d4..dcd391db498 100644 --- a/tests/fixtures/test-layout-expected.json +++ b/tests/fixtures/test-layout-expected.json @@ -1055,6 +1055,8 @@ "request-log-estimate-cap.test.ts": "usage", "request-log.test.ts": "usage", "request-outcome-agreement.test.ts": "usage", + "usage-failure-fingerprint.test.ts": "usage", + "usage-failure-projection.test.ts": "usage", "request-pacing.test.ts": "usage", "reserve-auth-context.test.ts": "codex-integration", "reserve-availability.test.ts": "codex-integration", diff --git a/tests/usage/usage-failure-fingerprint.test.ts b/tests/usage/usage-failure-fingerprint.test.ts new file mode 100644 index 00000000000..ce081ce7034 --- /dev/null +++ b/tests/usage/usage-failure-fingerprint.test.ts @@ -0,0 +1,106 @@ +import { describe, expect, test } from "bun:test"; +import { + FAILURE_FINGERPRINT_VERSION, + FAILURE_STATUS_CLASSES, + canonicalFailureFingerprintTuple, + computeFailureFingerprint, + failureStatusClass, + type FailureFingerprintFacts, +} from "../../src/usage/failure-fingerprint"; +import { REQUEST_FAILURE_CAUSES } from "../../src/lib/request-failure-model"; +import { REQUEST_CLOSE_REASONS, REQUEST_TERMINAL_STATUSES } from "../../src/usage/request-outcome"; + +/** + * A fingerprint that can carry content is not privacy-safe, and one that collides is not a + * grouping key. Both properties are asserted structurally rather than by example, so a slot + * added later has to be given a position instead of quietly joining an existing one. + */ +const BASE: FailureFingerprintFacts = { + cause: "upstream-fault", + statusClass: "5xx", + providerClass: null, + inboundProtocol: null, + terminalStatus: null, + closeReason: null, + transportPhase: null, + terminalSource: null, +}; + +/** Every slot, with a value that differs from BASE, read from the roster that declares it. */ +const VARIATIONS: ReadonlyArray<[keyof FailureFingerprintFacts, unknown]> = [ + ["cause", REQUEST_FAILURE_CAUSES.find(cause => cause !== BASE.cause)!], + ["statusClass", FAILURE_STATUS_CLASSES.find(value => value !== BASE.statusClass)!], + ["providerClass", "openai"], + ["inboundProtocol", "responses"], + ["terminalStatus", REQUEST_TERMINAL_STATUSES[0]!], + ["closeReason", REQUEST_CLOSE_REASONS[0]!], + ["transportPhase", "mid_stream"], + ["terminalSource", "upstream"], +]; + +describe("failure fingerprint", () => { + test("it is deterministic and carries its version in the value", () => { + const first = computeFailureFingerprint(BASE); + expect(computeFailureFingerprint({ ...BASE })).toBe(first); + // The version is imported, never written out: a bump must not be contradicted here. + expect(first.startsWith(`v${FAILURE_FINGERPRINT_VERSION}:`)).toBe(true); + }); + + test("every tuple position changes the fingerprint", () => { + const base = computeFailureFingerprint(BASE); + const unchanged: string[] = []; + for (const [key, value] of VARIATIONS) { + const varied = computeFailureFingerprint({ ...BASE, [key]: value } as FailureFingerprintFacts); + if (varied === base) unchanged.push(String(key)); + } + expect(unchanged).toEqual([]); + }); + + test("the tuple has one fixed position per declared fact plus the version", () => { + const tuple = canonicalFailureFingerprintTuple(BASE); + expect(tuple.length).toBe(Object.keys(BASE).length + 1); + expect(tuple[0]).toBe(FAILURE_FINGERPRINT_VERSION); + // Absent facts are explicit nulls. Dropping them would let [a, null, b] and [a, b] collide. + expect(tuple.slice(3).every(slot => slot === null)).toBe(true); + }); + + test("a missing fact is structurally distinct from a present one that looks like it", () => { + const absent = computeFailureFingerprint(BASE); + const present = computeFailureFingerprint({ ...BASE, providerClass: "null" }); + expect(present).not.toBe(absent); + }); + + test("a field outside the declared facts cannot reach the identity", () => { + const withExtras = { + ...BASE, + provider: "cursor-alice@example.com", + model: "secret-model", + upstreamError: "prompt fragment", + requestId: "req_1", + timestamp: 1, + } as FailureFingerprintFacts; + expect(computeFailureFingerprint(withExtras)).toBe(computeFailureFingerprint(BASE)); + expect(JSON.stringify(canonicalFailureFingerprintTuple(withExtras))).not.toContain("example.com"); + }); + + test("the status class covers every hundred and refuses anything else", () => { + expect(failureStatusClass(101)).toBe("1xx"); + expect(failureStatusClass(204)).toBe("2xx"); + expect(failureStatusClass(302)).toBe("3xx"); + expect(failureStatusClass(429)).toBe("4xx"); + expect(failureStatusClass(503)).toBe("5xx"); + for (const value of [undefined, null, 0, 99, 600, 1.5, Number.NaN, "500"]) { + expect(failureStatusClass(value)).toBe("unknown"); + } + }); + + test("every cause the recorder can store produces a distinct fingerprint", () => { + const seen = new Map(); + for (const cause of REQUEST_FAILURE_CAUSES) { + const fingerprint = computeFailureFingerprint({ ...BASE, cause }); + expect(seen.has(fingerprint)).toBe(false); + seen.set(fingerprint, cause); + } + expect(seen.size).toBe(REQUEST_FAILURE_CAUSES.length); + }); +}); diff --git a/tests/usage/usage-failure-projection.test.ts b/tests/usage/usage-failure-projection.test.ts new file mode 100644 index 00000000000..479ab3962c0 --- /dev/null +++ b/tests/usage/usage-failure-projection.test.ts @@ -0,0 +1,125 @@ +import { describe, expect, test } from "bun:test"; +import { + createFailureProjectionAccumulator, + failureProviderClass, +} from "../../src/usage/failure-projection"; +import { FAILURE_FINGERPRINT_VERSION } from "../../src/usage/failure-fingerprint"; +import { REQUEST_FAILURE_CAUSES } from "../../src/lib/request-failure-model"; +import type { PersistedUsageEntry } from "../../src/usage/log"; + +function row(overrides: Partial): PersistedUsageEntry { + return { + requestId: "req", + timestamp: 1_000, + provider: "openai", + model: "gpt-x", + status: 502, + durationMs: 1, + usageStatus: "unreported", + failureCause: "upstream-fault", + ...overrides, + }; +} + +describe("failure projection", () => { + test("it groups failures that share every closed fact and separates the rest", () => { + const accumulator = createFailureProjectionAccumulator(); + accumulator.add(row({ timestamp: 30 })); + accumulator.add(row({ timestamp: 10, requestId: "req2", model: "another-model" })); + accumulator.add(row({ timestamp: 20, requestId: "req3", failureCause: "rate-limit", status: 429 })); + const snapshot = accumulator.snapshot(); + + expect(snapshot.groups.length).toBe(2); + const fault = snapshot.groups.find(group => group.cause === "upstream-fault")!; + // Two rows that differ only in fields the fingerprint cannot read are one group. + expect(fault.count).toBe(2); + expect(fault.firstSeen).toBe(10); + expect(fault.lastSeen).toBe(30); + expect(snapshot.fingerprintVersion).toBe(FAILURE_FINGERPRINT_VERSION); + }); + + test("first and last seen are a minimum and a maximum, not a scan order", () => { + const accumulator = createFailureProjectionAccumulator(); + for (const timestamp of [50, 10, 90, 30]) accumulator.add(row({ timestamp })); + const [group] = accumulator.snapshot().groups; + expect(group!.firstSeen).toBe(10); + expect(group!.lastSeen).toBe(90); + expect(group!.count).toBe(4); + }); + + test("a snapshot holds a count and two timestamps, never an occurrence list", () => { + const accumulator = createFailureProjectionAccumulator(); + for (const timestamp of [1, 2, 3]) accumulator.add(row({ timestamp })); + const [group] = accumulator.snapshot().groups; + expect(Object.keys(group!).toSorted()).toEqual([ + "cause", "closeReason", "count", "fingerprint", "firstSeen", "inboundProtocol", + "lastSeen", "providerClass", "statusClass", "terminalSource", "terminalStatus", "transportPhase", + ]); + }); + + test("a request that delivered its answer is not a failure", () => { + const accumulator = createFailureProjectionAccumulator(); + accumulator.add(row({ status: 200, terminalStatus: "completed", failureCause: undefined })); + accumulator.add(row({ status: 200, terminalStatus: "incomplete", failureCause: undefined })); + const snapshot = accumulator.snapshot(); + expect(snapshot.groups).toEqual([]); + expect(snapshot.unattributedFailures).toBe(0); + }); + + test("a failed row written before the cause existed is counted, not bucketed", () => { + const accumulator = createFailureProjectionAccumulator(); + accumulator.add(row({ failureCause: undefined })); + const snapshot = accumulator.snapshot(); + expect(snapshot.groups).toEqual([]); + expect(snapshot.unattributedFailures).toBe(1); + }); + + test("a row that cannot be dated does not invent a timestamp", () => { + const accumulator = createFailureProjectionAccumulator(); + accumulator.add(row({ timestamp: Number.NaN })); + const snapshot = accumulator.snapshot(); + expect(snapshot.groups).toEqual([]); + expect(snapshot.invalidTimestampFailures).toBe(1); + }); + + test("an upstream-supplied terminal status cannot reach a grouping key", () => { + const accumulator = createFailureProjectionAccumulator(); + accumulator.add(row({ terminalStatus: "prompt text from upstream" as never })); + const [group] = accumulator.snapshot().groups; + expect(group!.terminalStatus).toBeNull(); + expect(JSON.stringify(accumulator.snapshot())).not.toContain("prompt text"); + }); + + test("a provider the user named themselves does not enter the key", () => { + expect(failureProviderClass("openai")).toBe("openai"); + expect(failureProviderClass("my-private-endpoint")).toBeNull(); + const accumulator = createFailureProjectionAccumulator(); + accumulator.add(row({ provider: "alice-personal-key" })); + expect(JSON.stringify(accumulator.snapshot())).not.toContain("alice"); + }); + + test("a clone folds new rows without touching the accumulator it came from", () => { + const original = createFailureProjectionAccumulator(); + original.add(row({ timestamp: 10 })); + const candidate = original.clone(); + candidate.add(row({ timestamp: 20 })); + expect(original.snapshot().groups[0]!.count).toBe(1); + expect(candidate.snapshot().groups[0]!.count).toBe(2); + expect(original.snapshot().groups[0]!.lastSeen).toBe(10); + }); + + test("ordering is by recency then fingerprint, so two runs agree", () => { + const build = () => { + const accumulator = createFailureProjectionAccumulator(); + for (const [index, cause] of REQUEST_FAILURE_CAUSES.entries()) { + accumulator.add(row({ timestamp: 1_000 - (index % 3), failureCause: cause })); + } + return accumulator.snapshot().groups.map(group => group.fingerprint); + }; + expect(build()).toEqual(build()); + const accumulator = createFailureProjectionAccumulator(); + accumulator.add(row({ timestamp: 10, failureCause: "rate-limit" })); + accumulator.add(row({ timestamp: 90, failureCause: "upstream-fault" })); + expect(accumulator.snapshot().groups[0]!.cause).toBe("upstream-fault"); + }); +}); From 85c8aae82a6f4678926df58710bd059c7a4f26be Mon Sep 17 00:00:00 2001 From: JUN Date: Sun, 20 Sep 2026 22:00:47 +0900 Subject: [PATCH 04/10] feat(responses): count what an attempt delivered, on the attempt #3983 wanted the signals a stream diagnostic gives -- a missing terminal, adapter-to-client loss, empty output, partial output size -- and emitted one debug line per event to get them. Two things make that the wrong shape. It is a second durable record. emitDebugLine writes the in-process ring AND stderr, and stderr is redirected to the service log under both launchd and systemd, so an installed service accumulates a per-event history beside the ledger with its own retention, sequencing, request identity and masking. And per-event lines needed a per-payload fingerprint to correlate; under a process-global random key that makes every repeated prompt fragment, tool name and error message correlatable for the lifetime of the process. Five bounded counts on PersistedUsageAttempt answer the same questions and cannot carry content at all. They ride the attempt, so they inherit the ledger's normalization, masking and retention instead of acquiring their own, and the debug ring now FORMATS one line per finalized attempt from what the recorder already counted -- appendDebugLogLine directly, never emitDebugLine, so the ring is a live view of the durable record rather than a parallel source for it. The counting point matters. Adapter events are counted at the one seam every adapter parse already passes; relayed frames are counted after a SUCCESSFUL controller enqueue in the SSE bridge. Counting both at the reader would make the two numbers equal by construction and erase the one discrepancy they exist to expose. The recorder is bound to the request's translator budget -- an object every bridge on the delivery path already receives -- and reaches the current attempt through a callback rather than holding one, so a mid-request attempt rotation credits the attempt that is live rather than one already finalized. sideEffectEvents feeds the failure stage, which makes side-effect reachable for the first time: a relayed tool call is an externally visible effect, so the resend verdict refuses. Counting it at the transport rather than the adapter is what makes that correct -- an emitted tool call the client never received has committed nothing. Two things from the original are deliberately absent: run-turn-execution.ts is untouched, because its accounting distinguishes adapters that report their own physical sends and carrying the PR's unconditional pre-count would double-charge them; and no content HMAC exists anywhere here. Also narrows the 400 refinement added earlier in this branch, after review: it now consults only the LAST recovery recorded on the attempt, and a finalizer that can prove a cause passes it directly instead. The key-account rotation now attributes the attempt it seals, which previously reached the ledger with no attribution at all because the finalization seam only ever sees the last attempt of a request. Co-authored-by: yansigit --- scripts/test-layout/layout.json | 1 + src/bridge/sse.ts | 10 ++ src/lib/debug.ts | 40 ++++++ src/lib/request-failure-attribution.ts | 45 ++++-- src/server/request-log.ts | 32 +++++ src/server/responses/request-transport.ts | 17 ++- src/usage/attempt-delivery.ts | 156 +++++++++++++++++++++ src/usage/log.ts | 11 ++ src/usage/telemetry-contract.ts | 31 ++++ tests/fixtures/test-layout-expected.json | 1 + tests/lib/failure-attribution.test.ts | 27 ++++ tests/usage/usage-attempt-delivery.test.ts | 128 +++++++++++++++++ 12 files changed, 484 insertions(+), 15 deletions(-) create mode 100644 src/usage/attempt-delivery.ts create mode 100644 tests/usage/usage-attempt-delivery.test.ts diff --git a/scripts/test-layout/layout.json b/scripts/test-layout/layout.json index e1274cf038d..0c3078ef891 100644 --- a/scripts/test-layout/layout.json +++ b/scripts/test-layout/layout.json @@ -1231,6 +1231,7 @@ "request-outcome-agreement.test.ts": "usage", "usage-failure-fingerprint.test.ts": "usage", "usage-failure-projection.test.ts": "usage", + "usage-attempt-delivery.test.ts": "usage", "request-pacing.test.ts": "usage", "reserve-auth-context.test.ts": "codex-integration", "reserve-availability.test.ts": "codex-integration", diff --git a/src/bridge/sse.ts b/src/bridge/sse.ts index 0466963eb57..a1f5a0fb8a4 100644 --- a/src/bridge/sse.ts +++ b/src/bridge/sse.ts @@ -16,6 +16,7 @@ import { type OcxErrorPayload, } from "../lib/errors"; import { redactSecretString } from "../lib/redact"; +import { attemptDeliveryRecorder, classifyRelayedResponseEvent } from "../usage/attempt-delivery"; import { mayBecomePatchEnvelope, repairFreeformToolInput, @@ -162,6 +163,10 @@ export function bridgeToResponsesSSE( // at terminal/cancel below. const ownsBudget = !options?.translatorBudget; const budget = options?.translatorBudget ?? createTranslatorBudget(); + // Resolved from the CALLER's budget only. A bridge that owns its budget is not serving a + // logged request -- there is no attempt to count against, and a locally created scope would + // never have had a recorder bound to it. + const delivery = attemptDeliveryRecorder(options?.translatorBudget); // Idempotent: safe to call at every stream-death path; disposal must come // AFTER the final charges (emitDone), never inside reportTerminal. const disposeOwnedBudget = () => { if (ownsBudget) budget.dispose(); }; @@ -278,6 +283,11 @@ export function bridgeToResponsesSSE( controller.enqueue(frame); budget?.releaseRetained(frameBytes, { kind: "live_transient" }); emittedFrames++; + // After a SUCCESSFUL enqueue, never before it. A frame that threw on the way to the + // transport did not reach the caller, and counting it here would make the relayed + // total equal the adapter total by construction -- erasing the one discrepancy these + // counters exist to expose (#3983). + delivery?.noteRelayedEvent(classifyRelayedResponseEvent(name, data)); } catch (error) { if (isTranslatorBudgetExceededError(error)) { terminateForTranslatorOverflow?.(error); diff --git a/src/lib/debug.ts b/src/lib/debug.ts index 938e5737ea7..9167b6ccbd0 100644 --- a/src/lib/debug.ts +++ b/src/lib/debug.ts @@ -52,3 +52,43 @@ export function debugProviderDiagnosticLazy( /* diagnostics must never affect request handling */ } } + +/** + * One line per finalized attempt, formatted from what the recorder already counted. + * + * #3983 wanted this visibility and emitted a line per stream event to get it. Two things made + * that the wrong shape. It is a second record: `emitDebugLine` writes the ring AND stderr, and + * a service manager redirects stderr to a file, so an installed service accumulates a per-event + * history beside the ledger with its own retention and sequencing. And per-event lines needed a + * per-payload fingerprint to correlate, which under a process-global key makes every repeated + * prompt fragment and tool name correlatable for the life of the process. + * + * So this writes the ring ONLY -- `appendDebugLogLine` directly, never `emitDebugLine` -- and + * says nothing the ledger does not already hold. The ring becomes a live view of the durable + * record rather than a parallel source for it. + */ +export function debugAttemptDeliverySummary( + requestId: string, + attempt: { + ordinal: number; + adapter: string; + deliverySummary?: { + adapterEvents: number; + relayedEvents: number; + semanticBytes: number; + sideEffectEvents: number; + terminalEvents: number; + }; + }, +): void { + if (!isDebugEnabled() || !attempt.deliverySummary) return; + try { + appendDebugLogLine(`[ocx:${attempt.adapter}:delivery] ${JSON.stringify({ + requestId, + ordinal: attempt.ordinal, + ...attempt.deliverySummary, + })}`); + } catch { + /* diagnostics must never affect request handling */ + } +} diff --git a/src/lib/request-failure-attribution.ts b/src/lib/request-failure-attribution.ts index cd1c0c0464c..ba445f83716 100644 --- a/src/lib/request-failure-attribution.ts +++ b/src/lib/request-failure-attribution.ts @@ -35,8 +35,21 @@ export interface RequestFailureFacts extends RequestOutcomeFacts { readonly sideEffectObserved?: boolean | undefined; /** True when this proxy answered the turn itself and issued no upstream request. */ readonly locallyAnswered?: boolean | undefined; - /** Recovery kinds recorded on the attempt that ended the request. */ + /** + * Recovery kinds recorded on the attempt that ended the request, in the order they happened. + * Only the LAST one is ever consulted, and only under the narrow rule below. + */ readonly recoveryKinds?: readonly AttemptRecoveryKind[] | undefined; + /** + * A cause the CALLER proved, which the status alone cannot reconstruct. + * + * Set only by a finalizer that is sealing an attempt it knows the rejection for -- the + * key-account rotation seals the previous attempt because a named recovery rejected it, and + * that argument is direct evidence rather than an inference from history. It outranks the + * status table and is outranked by a client cancel, which is a fact about the caller and not + * about the origin. + */ + readonly causeHint?: RequestFailureCause | undefined; } /** @@ -62,14 +75,21 @@ export function deriveRequestFailureStage(facts: RequestFailureFacts): RequestFa } /** - * Recovery kinds whose cause survives as the FINAL cause when the request ends on the status that - * recovery was made for. + * The two recovery kinds that name a 4xx the status alone cannot tell apart. * * `causeForRecoveryKind` answers why a recovery was ATTEMPTED, which is usually a different - * question from why the request finally failed -- a request that recovered from a 401 and then - * died on a 500 failed for the 500. The two kinds below are the exception: each names a rejection - * the status alone cannot distinguish from an ordinary bad request, so when the request also ends - * on that status the recovery kind is the only evidence of which 4xx it was. + * question from why the request finally failed -- one that recovered from a 401 and then died on + * a 500 failed for the 500. So the rule here is deliberately narrow on three axes at once: only + * these two kinds, only when they are the LAST recovery this attempt recorded, and only when the + * attempt then ended on the very status that recovery was made for. Everything else falls + * through to the status table. + * + * The residual: a ciphertext recovery that SUCCEEDED, followed by an unrelated 400 on the same + * attempt, still reads as `ciphertext-refusal`, because a successful recovery does not currently + * clear its own evidence. Closing that belongs in the recovery path rather than here -- it is + * recorded in this lane's devlog as the next step -- and the rule is kept meanwhile because + * without it a rejected ciphertext, a rejected reasoning parameter and a rejected payload are one + * undifferentiated answer, which is three different remedies collapsed into one. */ const STATUS_CONFIRMED_RECOVERY_KINDS: Readonly>> = Object.freeze({ "opaque-blob-rejection": 400, @@ -79,11 +99,10 @@ const STATUS_CONFIRMED_RECOVERY_KINDS: Readonly 0, locallyAnswered: logCtx.localTerminalReason !== undefined, recoveryKinds: logCtx.activeAttempt?.recoveryKinds ?? [], }); @@ -1428,6 +1441,10 @@ export function addFinalRequestLog( ...(attempt.recoveryWithheld?.length ? { recoveryWithheld: [...attempt.recoveryWithheld] } : {}), ...(attempt.usage ? { usage: { ...attempt.usage } } : {}), ...(attempt.tierOutcome ? { tierOutcome: { ...attempt.tierOutcome } } : {}), + // Detached, like every mutable field beside it: the live summary keeps counting if the + // stream is still draining, and a shared reference would let a finalized row change after + // it was written. + ...(attempt.deliverySummary ? { deliverySummary: { ...attempt.deliverySummary } } : {}), })); const isCombo = logCtx.comboId !== undefined && (attempts?.length ?? 0) > 0; const aggregate = isCombo ? aggregateAttemptUsage(attempts ?? []) : null; @@ -1539,6 +1556,8 @@ export function addFinalRequestLog( ...(attribution?.stage ? { failureStage: attribution.stage } : {}), ...(attribution?.cause ? { failureCause: attribution.cause } : {}), }); + // Formatted from the finalized snapshot, so the ring shows exactly what the ledger holds. + for (const attempt of attempts ?? []) debugAttemptDeliverySummary(requestId, attempt); if (isUsageDebugEnabled()) { appendUsageDebug({ ts: Date.now(), @@ -1785,8 +1804,21 @@ export function noteProviderAttemptSend( finishRequestAttempt(attempt, attempt.status >= 100 ? attempt.status : recovery === "key-401" ? 401 : recovery?.includes("429") ? 429 : 502, Date.now() - (logCtx.activeAttemptStartedAt ?? Date.now()), attempt.usage); + // This attempt is being sealed because a NAMED recovery rejected it, so the recovery kind + // is direct evidence here rather than an inference from history. Without this the sealed + // attempt would reach the ledger with no attribution at all: the finalization seam below + // only ever sees the last attempt of the request. + const sealedAttribution = deriveRequestFailureAttribution({ + status: attempt.status, + outputObserved: attempt.firstOutputMs !== undefined, + sideEffectObserved: (attempt.deliverySummary?.sideEffectEvents ?? 0) > 0, + ...(recovery ? { causeHint: causeForRecoveryKind(recovery) } : {}), + }); + if (sealedAttribution?.stage) attempt.failureStage = sealedAttribution.stage; + if (sealedAttribution?.cause) attempt.failureCause = sealedAttribution.cause; const completed = { ...attempt, recoveryKinds: [...attempt.recoveryKinds], ...(attempt.usage ? { usage: { ...attempt.usage } } : {}), + ...(attempt.deliverySummary ? { deliverySummary: { ...attempt.deliverySummary } } : {}), ...(attempt.tierOutcome ? { tierOutcome: { ...attempt.tierOutcome } } : {}) }; const attempts = logCtx.attempts ??= [attempt]; const index = attempts.indexOf(attempt); diff --git a/src/server/responses/request-transport.ts b/src/server/responses/request-transport.ts index 46d70186289..e6834c7e941 100644 --- a/src/server/responses/request-transport.ts +++ b/src/server/responses/request-transport.ts @@ -64,6 +64,7 @@ import { recordKeyAttemptUsage, } from "../request-log"; import type { AttemptRecoveryKind } from "../../usage/log"; +import { bindAttemptDeliveryRecorder } from "../../usage/attempt-delivery"; import { resolvePassiveRouteSubjectId } from "../passive-route-linker"; /** Owns live credential selection and adapter bindings for one request. */ @@ -298,15 +299,25 @@ export async function prepareResponsesTransport( recordKeyAttemptUsage(logCtx, event.usage); } }; + // Counted at the one seam every adapter parse passes, and counted for EVERY event rather + // than only usage-bearing ones: the number this pairs with is the frame count the client + // transport relayed, and a difference between the two is the loss signal (#3983). Reading + // the current attempt through logCtx rather than capturing one keeps the count with the + // attempt that is live when the event arrives, across a mid-request attempt rotation. + const delivery = bindAttemptDeliveryRecorder(translatorBudget, () => logCtx.activeAttempt); + const observeEvent = (event: AdapterEvent, response: object): void => { + delivery.noteAdapterEvent(); + observeUsage(event, response); + }; const parseStream = resolved.parseStream.bind(resolved); resolved.parseStream = async function* (...args) { - for await (const event of parseStream(...args)) { observeUsage(event, args[0]); yield event; } + for await (const event of parseStream(...args)) { observeEvent(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])); + events.forEach(event => observeEvent(event, args[0])); return events; }; } @@ -321,7 +332,7 @@ export async function prepareResponsesTransport( const runTurn = resolved.runTurn.bind(resolved); rawRunTurns.set(resolved, (requestParsed, incoming, emit) => { const response = {}; - return runTurn(requestParsed, incoming, event => { observeUsage(event, response); emit(event); }); + return runTurn(requestParsed, incoming, event => { observeEvent(event, response); emit(event); }); }); resolved.runTurn = (requestParsed, incoming, emit) => runSelectedTurn(resolved, requestParsed, incoming, emit); } diff --git a/src/usage/attempt-delivery.ts b/src/usage/attempt-delivery.ts new file mode 100644 index 00000000000..2b3ed8f78d2 --- /dev/null +++ b/src/usage/attempt-delivery.ts @@ -0,0 +1,156 @@ +/** + * Counting what an attempt delivered, without recording what it said. + * + * The recorder below is bound to a request-scoped object and reaches the CURRENT attempt through + * a callback rather than holding one. An attempt can be rotated mid-request -- a key-account + * change seals the old one and starts a fresh one -- and a recorder holding a reference would + * keep crediting frames to an attempt that had already been finalized and snapshotted. + * + * Nothing here reads a payload's content. `semanticBytes` is a length; the event classification + * reads only a frame's type name and an item's type name, both of which are protocol constants. + */ +import type { AttemptDeliverySummary } from "./telemetry-contract"; + +export interface AttemptDeliveryTarget { + deliverySummary?: AttemptDeliverySummary; +} + +export interface RelayedEventObservation { + semanticBytes?: number; + sideEffect?: boolean; + terminal?: boolean; +} + +export interface AttemptDeliveryRecorder { + noteAdapterEvent(): void; + noteRelayedEvent(observation?: RelayedEventObservation): void; +} + +export function createAttemptDeliverySummary(): AttemptDeliverySummary { + return { adapterEvents: 0, relayedEvents: 0, semanticBytes: 0, sideEffectEvents: 0, terminalEvents: 0 }; +} + +/** + * Saturating addition. + * + * A counter that wraps or drifts into a non-integer is worse than one that stops: the row would + * be dropped by the normalizer and the whole summary lost. A long-lived stream that somehow + * reaches the safe-integer ceiling keeps a readable, if pinned, number. + */ +function bump(current: number, by: number): number { + if (!Number.isFinite(by) || by <= 0) return current; + return Math.min(Number.MAX_SAFE_INTEGER, current + Math.floor(by)); +} + +const SEMANTIC_DELTA_EVENTS: ReadonlySet = new Set([ + "response.output_text.delta", + "response.reasoning_summary_text.delta", + "response.reasoning_text.delta", + "response.function_call_arguments.delta", + "response.custom_tool_call_input.delta", +]); + +const TERMINAL_EVENTS: ReadonlySet = new Set([ + "response.completed", + "response.incomplete", + "response.failed", +]); + +const SIDE_EFFECT_ITEM_TYPES: ReadonlySet = new Set([ + "function_call", + "custom_tool_call", + "web_search_call", +]); + +/** + * What one relayed frame contributes, read from its type name alone. + * + * A side effect is counted when the item STARTS, not on its argument fragments and not again on + * the matching done frame, so one tool call is one effect however many deltas carried its + * arguments. + */ +export function classifyRelayedResponseEvent( + name: string, + data: Record, +): RelayedEventObservation { + const observation: RelayedEventObservation = {}; + if (SEMANTIC_DELTA_EVENTS.has(name) && typeof data.delta === "string") { + observation.semanticBytes = Buffer.byteLength(data.delta, "utf8"); + } + if (name === "response.output_item.added") { + const item = data.item; + const type = item !== null && typeof item === "object" + ? (item as Record).type + : undefined; + if (typeof type === "string" && SIDE_EFFECT_ITEM_TYPES.has(type)) observation.sideEffect = true; + } + if (TERMINAL_EVENTS.has(name)) observation.terminal = true; + return observation; +} + +const recordersByScope = new WeakMap(); + +/** + * Bind a recorder to a request-scoped object. + * + * The scope is the request's translator budget, which every bridge on the delivery path already + * receives. Reusing it avoids threading a new parameter through six call sites where any one of + * them silently defaulting would leave a transport uncounted -- the failure mode that made + * `locallyAnswered` travel on the attempt instead of as an argument. + */ +export function bindAttemptDeliveryRecorder( + scope: object, + currentAttempt: () => AttemptDeliveryTarget | undefined, +): AttemptDeliveryRecorder { + const summaryFor = (): AttemptDeliverySummary | undefined => { + const attempt = currentAttempt(); + if (!attempt) return undefined; + return attempt.deliverySummary ??= createAttemptDeliverySummary(); + }; + const recorder: AttemptDeliveryRecorder = { + noteAdapterEvent(): void { + const summary = summaryFor(); + if (summary) summary.adapterEvents = bump(summary.adapterEvents, 1); + }, + noteRelayedEvent(observation): void { + const summary = summaryFor(); + if (!summary) return; + summary.relayedEvents = bump(summary.relayedEvents, 1); + if (observation?.semanticBytes) summary.semanticBytes = bump(summary.semanticBytes, observation.semanticBytes); + if (observation?.sideEffect) summary.sideEffectEvents = bump(summary.sideEffectEvents, 1); + if (observation?.terminal) summary.terminalEvents = bump(summary.terminalEvents, 1); + }, + }; + recordersByScope.set(scope, recorder); + return recorder; +} + +export function attemptDeliveryRecorder(scope: object | undefined): AttemptDeliveryRecorder | undefined { + return scope ? recordersByScope.get(scope) : undefined; +} + +/** + * A persisted summary is trusted only when all five counts are non-negative safe integers. + * + * The whole record is dropped rather than repaired: a partially trusted count is a number an + * operator would compare against another number, and half a summary is how a loss signal turns + * into a false one. + */ +export function normalizeAttemptDeliverySummary(value: unknown): AttemptDeliverySummary | undefined { + if (!value || typeof value !== "object" || Array.isArray(value)) return undefined; + const raw = value as Record; + const counts = createAttemptDeliverySummary(); + for (const key of Object.keys(counts) as Array) { + const count = raw[key]; + if (typeof count !== "number" || !Number.isSafeInteger(count) || count < 0) return undefined; + counts[key] = count; + } + return counts; +} + +/** A detached copy, so a snapshotted attempt cannot keep counting after it was finalized. */ +export function cloneAttemptDeliverySummary( + summary: AttemptDeliverySummary | undefined, +): AttemptDeliverySummary | undefined { + return summary ? { ...summary } : undefined; +} diff --git a/src/usage/log.ts b/src/usage/log.ts index e40c42436fe..b8467fca876 100644 --- a/src/usage/log.ts +++ b/src/usage/log.ts @@ -7,6 +7,7 @@ import { enforceAppOwnedMemoryBudget } from "../lib/app-owned-memory"; import { recordOwnedConfigPath } from "../lib/config-ownership"; import { sanitizeLogMetadataString } from "../lib/redact"; import { usageDisplayTotalTokens } from "./totals"; +import { normalizeAttemptDeliverySummary } from "./attempt-delivery"; import { isRequestCloseReason, isRequestTerminalStatus, @@ -25,6 +26,7 @@ import { REQUEST_FAILURE_STAGES, type AttemptRecoveryKind, type AttemptRecoveryWithheld, + type AttemptDeliverySummary, type RequestFailureCause, type RequestFailureStage, type RequestSpendTotals, @@ -183,6 +185,11 @@ export interface PersistedUsageAttempt { * account identifiers. */ codexWsStage?: CodexWsStageRecord; + /** + * What this attempt delivered, as five bounded counts (#3983). Absent on attempts whose + * transport does not pass through the Responses bridge and on pre-instrumentation rows. + */ + deliverySummary?: AttemptDeliverySummary; /** * How far this attempt's exchange got and why it failed, in the shared vocabulary (#2366). * @@ -659,6 +666,9 @@ function normalizeUsageAttempt(raw: unknown): PersistedUsageAttempt | null { const codexWsStage = "codexWsStage" in attempt ? normalizeCodexWsStageRecord(attempt.codexWsStage) : undefined; + const deliverySummary = "deliverySummary" in attempt + ? normalizeAttemptDeliverySummary(attempt.deliverySummary) + : undefined; const recoveryKinds = Array.isArray(attempt.recoveryKinds) ? [...new Set(attempt.recoveryKinds.filter( (value): value is AttemptRecoveryKind => typeof value === "string" @@ -727,6 +737,7 @@ function normalizeUsageAttempt(raw: unknown): PersistedUsageAttempt | null { : {}), ...(tierOutcome ? { tierOutcome } : {}), ...(codexWsStage ? { codexWsStage } : {}), + ...(deliverySummary ? { deliverySummary } : {}), ...normalizeRequestFailureAttribution(attempt), }; } diff --git a/src/usage/telemetry-contract.ts b/src/usage/telemetry-contract.ts index e0cfe330f58..790bfc2bac9 100644 --- a/src/usage/telemetry-contract.ts +++ b/src/usage/telemetry-contract.ts @@ -167,6 +167,37 @@ export const RESEND_PERMISSIONS = Object.freeze([ export type ResendPermission = typeof RESEND_PERMISSIONS[number]; +/** + * What an attempt actually delivered, as five bounded counts (#3983). + * + * #3983 wanted these signals and emitted one debug line per event to get them. That is a second + * durable record: `emitDebugLine` writes the in-process ring AND stderr, and stderr is redirected + * to the service log under both launchd and systemd, so an installed service ends up with a + * per-event history beside the ledger, carrying its own retention, sequencing and identity. It + * also fingerprinted each payload under a process-global random key, which makes every repeated + * prompt fragment, tool name and error message correlatable for the process lifetime. + * + * Counts answer the same questions -- a missing terminal, adapter-to-client loss, empty output, + * partial output size -- and cannot carry content at all. They ride the attempt, so they inherit + * the ledger's normalization, masking and retention rather than acquiring their own. + * + * Counted where the event is DELIVERED, not where it is read. An adapter event the client never + * received is exactly the discrepancy worth seeing, and counting both ends at the reader would + * make the two numbers equal by construction. + */ +export interface AttemptDeliverySummary { + /** Events this attempt's adapter produced. */ + adapterEvents: number; + /** Frames that reached the client transport, after a successful enqueue. */ + relayedEvents: number; + /** UTF-8 bytes of output-bearing delta actually relayed. Never the content itself. */ + semanticBytes: number; + /** Externally visible effects relayed: a tool call or a search call starting. */ + sideEffectEvents: number; + /** Terminal frames relayed. Zero on a delivered stream is the missing-terminal signal. */ + terminalEvents: number; +} + /** * What one logical request spent upstream, decomposed by how much of it is explained. * diff --git a/tests/fixtures/test-layout-expected.json b/tests/fixtures/test-layout-expected.json index dcd391db498..b232905c037 100644 --- a/tests/fixtures/test-layout-expected.json +++ b/tests/fixtures/test-layout-expected.json @@ -1057,6 +1057,7 @@ "request-outcome-agreement.test.ts": "usage", "usage-failure-fingerprint.test.ts": "usage", "usage-failure-projection.test.ts": "usage", + "usage-attempt-delivery.test.ts": "usage", "request-pacing.test.ts": "usage", "reserve-auth-context.test.ts": "codex-integration", "reserve-availability.test.ts": "codex-integration", diff --git a/tests/lib/failure-attribution.test.ts b/tests/lib/failure-attribution.test.ts index 737eb195a02..f661af9b576 100644 --- a/tests/lib/failure-attribution.test.ts +++ b/tests/lib/failure-attribution.test.ts @@ -149,4 +149,31 @@ describe("request failure attribution", () => { test("a local refusal is attributed to this proxy rather than to upstream", () => { expect(deriveRequestFailureCause({ status: 502, locallyAnswered: true })).toBe("local-refusal"); }); + + test("a cause the finalizer proved outranks the status table", () => { + // The key-account rotation seals the previous attempt because a named recovery rejected it. + // That argument is evidence; reconstructing the cause from 502 would lose it. + expect(deriveRequestFailureCause({ status: 502, causeHint: "credential-rejected" })) + .toBe("credential-rejected"); + // A client cancel is a fact about the caller and still outranks the hint. + expect(deriveRequestFailureCause({ status: 499, causeHint: "credential-rejected" })) + .toBe("client-cancelled"); + }); + + test("only the last recovery refines a 400, and only on its own status", () => { + // The attempt recovered from a rejected ciphertext and then hit a rejected parameter. + expect(deriveRequestFailureCause({ + status: 400, + recoveryKinds: ["opaque-blob-rejection", "reasoning-effort-downgrade"], + })).toBe("parameter-rejected"); + // A recovery for a different status never refines this one. + expect(deriveRequestFailureCause({ status: 400, recoveryKinds: ["oauth-401"] })) + .toBe("payload-rejected"); + }); + + test("a relayed side effect raises the stage above observed output", () => { + expect(deriveRequestFailureStage({ status: 502, outputObserved: true })).toBe("semantic-output"); + expect(deriveRequestFailureStage({ status: 502, outputObserved: true, sideEffectObserved: true })) + .toBe("side-effect"); + }); }); diff --git a/tests/usage/usage-attempt-delivery.test.ts b/tests/usage/usage-attempt-delivery.test.ts new file mode 100644 index 00000000000..980f0466ea9 --- /dev/null +++ b/tests/usage/usage-attempt-delivery.test.ts @@ -0,0 +1,128 @@ +import { describe, expect, test } from "bun:test"; +import { + attemptDeliveryRecorder, + bindAttemptDeliveryRecorder, + classifyRelayedResponseEvent, + createAttemptDeliverySummary, + normalizeAttemptDeliverySummary, + type AttemptDeliveryTarget, +} from "../../src/usage/attempt-delivery"; +import { normalizeUsageEntryForTest, type PersistedUsageEntry } from "../../src/usage/log"; + +const COUNTERS = Object.keys(createAttemptDeliverySummary()); + +describe("attempt delivery summary", () => { + test("the recorder credits the attempt that is live when the event arrives", () => { + let active: AttemptDeliveryTarget | undefined = {}; + const first = active; + const scope = {}; + const recorder = bindAttemptDeliveryRecorder(scope, () => active); + recorder.noteAdapterEvent(); + recorder.noteRelayedEvent({ semanticBytes: 4, terminal: true }); + + // A key-account change seals the attempt and starts a fresh one mid-request. A recorder + // holding a reference would keep crediting the sealed row. + const second: AttemptDeliveryTarget = {}; + active = second; + recorder.noteAdapterEvent(); + + expect(first.deliverySummary).toEqual({ + adapterEvents: 1, relayedEvents: 1, semanticBytes: 4, sideEffectEvents: 0, terminalEvents: 1, + }); + expect(second.deliverySummary).toEqual({ + adapterEvents: 1, relayedEvents: 0, semanticBytes: 0, sideEffectEvents: 0, terminalEvents: 0, + }); + }); + + test("a scope with no attempt records nothing and does not throw", () => { + const scope = {}; + const recorder = bindAttemptDeliveryRecorder(scope, () => undefined); + expect(() => { recorder.noteAdapterEvent(); recorder.noteRelayedEvent(); }).not.toThrow(); + expect(attemptDeliveryRecorder(scope)).toBe(recorder); + expect(attemptDeliveryRecorder(undefined)).toBeUndefined(); + expect(attemptDeliveryRecorder({})).toBeUndefined(); + }); + + test("semantic bytes count delivered UTF-8, never the text itself", () => { + const observation = classifyRelayedResponseEvent("response.output_text.delta", { delta: "한글" }); + expect(observation.semanticBytes).toBe(6); + expect(JSON.stringify(observation)).not.toContain("한글"); + }); + + test("one tool call is one side effect, whatever carried its arguments", () => { + const target: AttemptDeliveryTarget = {}; + const recorder = bindAttemptDeliveryRecorder({}, () => target); + recorder.noteRelayedEvent(classifyRelayedResponseEvent("response.output_item.added", { + item: { type: "function_call", name: "lookup" }, + })); + recorder.noteRelayedEvent(classifyRelayedResponseEvent("response.function_call_arguments.delta", { delta: "{}" })); + recorder.noteRelayedEvent(classifyRelayedResponseEvent("response.output_item.done", { + item: { type: "function_call", name: "lookup" }, + })); + expect(target.deliverySummary!.sideEffectEvents).toBe(1); + expect(target.deliverySummary!.relayedEvents).toBe(3); + }); + + test("framing and control frames are relayed events but not semantic or terminal ones", () => { + for (const name of ["response.created", "response.heartbeat", "response.output_item.done"]) { + const observation = classifyRelayedResponseEvent(name, {}); + expect(observation.semanticBytes).toBeUndefined(); + expect(observation.terminal).toBeUndefined(); + expect(observation.sideEffect).toBeUndefined(); + } + for (const name of ["response.completed", "response.incomplete", "response.failed"]) { + expect(classifyRelayedResponseEvent(name, {}).terminal).toBe(true); + } + }); + + test("a summary survives the ledger round trip and an invalid one is dropped whole", () => { + const row = (deliverySummary: unknown): PersistedUsageEntry => ({ + requestId: "req", timestamp: 1, provider: "openai", model: "m", status: 200, + durationMs: 1, usageStatus: "unreported", + attempts: [{ + ordinal: 1, provider: "openai", model: "m", adapter: "openai", status: 200, + durationMs: 1, sendCount: 1, recoveryKinds: [], usageStatus: "unreported", + deliverySummary, + } as never], + }); + const good = { adapterEvents: 5, relayedEvents: 4, semanticBytes: 12, sideEffectEvents: 1, terminalEvents: 1 }; + expect(normalizeUsageEntryForTest(row(good)).attempts![0]!.deliverySummary).toEqual(good); + + // Half a summary is how a loss signal becomes a false one, so a bad count drops all five. + for (const broken of [ + { ...good, relayedEvents: -1 }, + { ...good, semanticBytes: 1.5 }, + { ...good, terminalEvents: "1" }, + { adapterEvents: 1 }, + null, + [], + ]) { + expect(normalizeUsageEntryForTest(row(broken)).attempts![0]!.deliverySummary).toBeUndefined(); + } + // An attempt written before the field existed still reads back. + const legacy = normalizeUsageEntryForTest(row(undefined)); + expect(legacy.attempts![0]!.deliverySummary).toBeUndefined(); + expect(legacy.attempts![0]!.ordinal).toBe(1); + }); + + test("the normalizer requires every declared counter, so a new one cannot be forgotten", () => { + const complete = createAttemptDeliverySummary(); + expect(normalizeAttemptDeliverySummary(complete)).toEqual(complete); + for (const key of COUNTERS) { + const missing: Record = { ...complete }; + delete missing[key]; + expect(normalizeAttemptDeliverySummary(missing)).toBeUndefined(); + } + }); + + test("the summary carries counts only, so no content can ride it", () => { + const target: AttemptDeliveryTarget = {}; + const recorder = bindAttemptDeliveryRecorder({}, () => target); + recorder.noteRelayedEvent(classifyRelayedResponseEvent("response.output_text.delta", { + delta: "the user's private prompt", + })); + const serialized = JSON.stringify(target.deliverySummary); + expect(serialized).not.toContain("private"); + expect(Object.values(target.deliverySummary!).every(value => typeof value === "number")).toBe(true); + }); +}); From 325547d787a72bc716585b4aa7cfd3018f2b7107 Mon Sep 17 00:00:00 2001 From: JUN Date: Sun, 20 Sep 2026 22:07:15 +0900 Subject: [PATCH 05/10] feat(usage): opt-in size limit for the usage ledger, with a revision contract #5063 proposed retention on the canonical ledger, which is the right architecture: the alternative is a projection that hides rows the ledger still has, and that is a second retention policy. What its implementation could not promise is that a row appended between its size snapshot and its rename survived -- it captured a size, copied a suffix, and renamed over whatever was there. Its own concurrency test performed two sequential calls and said so. Two things close that here. The append is synchronous and the compaction runs inside the same call stack, with no await between the append and the publication, so no in-process append can interleave; a second server on the same home cannot append at all, because it is refused by the existing ledger-owner lease at startup, which is why the hook is installed after ownership rather than before. And validateBeforeRename re-opens the target immediately before the rename and refuses unless identity, size and revision metadata are byte-for-byte what was copied -- so an append from anywhere else aborts the replacement rather than losing the row. Both the original file and that append survive, and the next append retries from a fresh revision. A test drives exactly that window through an injected hook, because a contract nothing can drive is a contract nobody has checked. Publication goes through the shared atomic writer rather than a hand-rolled temp lifecycle, which is where the exclusive private temp, the identity assertions, the platform-aware replace and the residual cleanup already live. The writer gains a streaming form so the retained span is copied in bounded chunks instead of held in memory as one string, and that form fsyncs the temp before the rename and does not swallow the failure: a replacement whose replacement is not on disk can lose the rows it was meant to keep. Rows are copied byte for byte and never parsed or re-serialized. A retention pass that understood the row shape would silently drop every field it was written before, which for this branch would mean the failure stage and cause it just added. The invalidation half was missing entirely from the original. Deleting rows invalidates three readers that do not watch the file: the 2,000-entry Logs ring, which otherwise keeps serving rows the ledger no longer has until eviction or a restart; the retained usage aggregate and failure projection, whose checkpoints now point past a boundary that moved; and the request-history index, whose source identity changed. All three are discarded after a replacement. This does NOT close #5063. The Usage-page control it also asks for is not here: this branch may not build or run the GUI, so it cannot produce the screenshot that gate requires, and shipping an unverifiable control is worse than shipping the policy the control would set. The limit is settable in config.json today and the docs say so. Co-authored-by: Vocllum <149675937+Vocllum@users.noreply.github.com> --- .../docs/reference/configuration/server.md | 21 +++ scripts/test-layout/layout.json | 1 + src/config/atomic-write.ts | 60 ++++++- src/config/schema/config-schema.ts | 8 + src/server/index.ts | 4 + src/server/request-log.ts | 18 ++ src/server/usage-ledger-retention.ts | 74 ++++++++ src/types/config.ts | 7 + src/usage/ledger-retention.ts | 160 ++++++++++++++++++ src/usage/log.ts | 16 ++ src/usage/retention-contract.ts | 28 +++ tests/fixtures/test-layout-expected.json | 1 + tests/usage/usage-ledger-retention.test.ts | 116 +++++++++++++ 13 files changed, 512 insertions(+), 2 deletions(-) create mode 100644 src/server/usage-ledger-retention.ts create mode 100644 src/usage/ledger-retention.ts create mode 100644 src/usage/retention-contract.ts create mode 100644 tests/usage/usage-ledger-retention.test.ts diff --git a/docs-site/src/content/docs/reference/configuration/server.md b/docs-site/src/content/docs/reference/configuration/server.md index 6deae1998c5..57d7587672d 100644 --- a/docs-site/src/content/docs/reference/configuration/server.md +++ b/docs-site/src/content/docs/reference/configuration/server.md @@ -26,6 +26,7 @@ runs helper features around provider requests. | `corsAllowOrigins?` | `string[]` | `[]` | Additional exact origins allowed by CORS. Loopback origins are always allowed. Authority-based browser extension origins such as `chrome-extension://` are supported; `*` is not a wildcard. Firefox and Safari regenerate the extension UUID (per install / per browser launch), so update the entry when the origin changes. | | `apiKeys?` | `OcxApiKey[]` | `[]` | Generated `ocx_…` data-plane admission credentials on non-loopback binds. They do not authorize management APIs; management access uses the separate credential documented in the [management reference](/reference/management-api/). Dashboard-managed. | | `storageCleanupPolicy?` | `StorageCleanupPolicy` | disabled | Opt-in archived-session cleanup policy. Never enabled implicitly. | +| `usageLedgerMaxBytes?` | `number` | unset | Opt-in ceiling in bytes for `usage.jsonl`. Absent means the request history grows without limit, which stays the default. See [usage history size](#usage-history-size). | | `appOwnedMemoryBudgetMb?` | `number` | `256` | Cap in MiB for evictable app-owned logs, caches, blobs, and continuation payloads. Range 64–4096; not an RSS cap. | | `metricsExport.enabled?` | `boolean` | `false` | Enable process-local aggregate request metrics at authenticated `GET /api/metrics`. Restart required; disabled mode returns 404 and starts no exporter activity. | | `spend?` | `{ root?: { maxTokens?: number }; identity?: { maxTokens?: number }; pool?: { maxTokens?: number }; retentionDays?: number }` | unset | Durable token ceilings, off unless you write one. Each scope bounds settled spend plus in-flight reservations plus unresolved spend: `root` is one task including its whole fan-out, `identity` is one account across every task it serves, and `pool` is one provider pool. They intersect, so a request is admitted only when all three have room — which is what holds a ceiling against a client that mints a new task id per request. A reservation is the request's whole input plus its enforceable output ceiling, counted as if every cached prefix misses. Observe-only mode still journals, so every server owns the state directory's single-writer lease; an explicit sibling must use a separate `OPENCODEX_HOME`. Spend survives an ordinary process restart when its writes reached the filesystem, but the journal does not promise survival across host power loss because each append is not fsynced. Raising or removing the value is what grants more. `maxTokens` must be a positive integer (0 would refuse everything), `retentionDays` is 1–365 and defaults to 7, and an unknown key in this section is rejected rather than ignored. A refusal is a local HTTP 429 carrying `x-opencodex-local-refusal: workflow_spend_exhausted`, and its message names the scope and the ceiling; no provider is contacted. | @@ -370,6 +371,26 @@ either `target.reduceToBytes` or `target.removeOldestPercent`. `mode` defaults t Configure it on the Storage page or with `GET`/`PUT /api/storage/cleanup-policy`; trigger a manual run with `POST /api/storage/cleanup-policy/run`. +## Usage history size + +`usageLedgerMaxBytes` is unset by default, and unset means the request history in `usage.jsonl` +grows without limit. Nothing deletes history you did not ask to have deleted. + +Set it to a byte ceiling and the proxy trims the file after an append crosses it, keeping the +newest whole rows and dropping the oldest. It trims a little below the ceiling rather than exactly +to it, so the next append does not immediately re-cross the line. The minimum accepted value is +1 MiB; a smaller number, or one that is not a safe integer, leaves the limit off rather than +failing the configuration. + +Rows are copied byte for byte and never rewritten, so every field survives a trim — including +fields a newer build wrote that an older one does not understand. The replacement is refused +outright if anything appended to the ledger while it ran, so a request logged during a trim is +never lost; the next append tries again. Trimming also refreshes what the dashboard shows, so +`/api/logs` stops serving rows the ledger no longer has. + +There is no dashboard control for this yet; set it in `config.json` or with +`ocx config set usageLedgerMaxBytes `. + ## Quota-reset notifications (`quotaResetNotify`) Off by default. When the section is absent, no detection runs, no timer starts, and no state diff --git a/scripts/test-layout/layout.json b/scripts/test-layout/layout.json index 0c3078ef891..fd4aa706312 100644 --- a/scripts/test-layout/layout.json +++ b/scripts/test-layout/layout.json @@ -1232,6 +1232,7 @@ "usage-failure-fingerprint.test.ts": "usage", "usage-failure-projection.test.ts": "usage", "usage-attempt-delivery.test.ts": "usage", + "usage-ledger-retention.test.ts": "usage", "request-pacing.test.ts": "usage", "reserve-auth-context.test.ts": "codex-integration", "reserve-availability.test.ts": "codex-integration", diff --git a/src/config/atomic-write.ts b/src/config/atomic-write.ts index 27f4471d402..0bbebdd3ba3 100644 --- a/src/config/atomic-write.ts +++ b/src/config/atomic-write.ts @@ -2,6 +2,7 @@ import { chmodSync, closeSync, fchmodSync, + fsyncSync, fstatSync, lstatSync, openSync, @@ -191,6 +192,40 @@ function writePrivateTempFile( carryHardenAcrossContentWrite(path); } +/** + * The same private temp, filled by a writer that streams into the descriptor. + * + * For content that must not be held in memory as one string. The identity assertions, the + * ownership handshake and the hardening are the same; the difference is that the bytes arrive in + * bounded chunks and the descriptor is flushed before it closes. + * + * The `fsync` is not optional here and its failure is not swallowed. A replacement whose + * REPLACEMENT is not on disk can lose the rows it was supposed to retain, so the throw is what + * stops the rename from happening at all. + */ +function writePrivateTempFileWith( + path: string, + write: (descriptor: number) => void, + timeoutMemoKey: string, + onCreated: () => void, +): void { + const descriptor = openSync(path, "wx", 0o600); + onCreated(); + try { + if (windowsHardeningApplies()) { + hardenSecretPath(path, { required: true, timeoutMemoKey }); + } + if (process.platform !== "win32") fchmodSync(descriptor, 0o600); + assertPrivateTempDescriptor(path, descriptor); + write(descriptor); + assertPrivateTempDescriptor(path, descriptor); + fsyncSync(descriptor); + } finally { + closeSync(descriptor); + } + carryHardenAcrossContentWrite(path); +} + async function writePrivateTempFileAsync( path: string, content: string, @@ -217,7 +252,7 @@ async function writePrivateTempFileAsync( function atomicWriteFileToTarget( path: string, - content: string, + content: string | ((descriptor: number) => void), target: string, io?: AtomicWriteIO, hooks: AtomicWriteHooks = {}, @@ -246,7 +281,11 @@ function atomicWriteFileToTarget( }; try { if (io) ownsTemp = true; - effective.write(tmp, content); + // A streaming writer bypasses the string form of `write` and nothing else. Every later + // step -- harden, the pre-rename hooks, the rename and the whole residual-cleanup path, + // which still scrubs through `effective.write(tmp, "")` -- is shared with the string form. + if (typeof content === "function") writePrivateTempFileWith(tmp, content, path, () => { ownsTemp = true; }); + else effective.write(tmp, content); hooks.afterTempWrite?.(tmp, target); effective.harden(tmp); hardened = true; @@ -296,6 +335,23 @@ export function atomicWriteFile( atomicWriteFileToTarget(path, content, resolveWriteTarget(path), io, hooks); } +/** + * Atomically replace a file with bytes produced straight into the temporary descriptor. + * + * Same publication contract as {@link atomicWriteFile}: an exclusively created private temp, the + * identity assertions around the write, `hooks.validateBeforeRename` immediately before the + * rename, the platform-aware replace, and the residual cleanup on any failure. A custom + * {@link AtomicWriteIO} is not accepted, because the point of this form is that the default + * writer owns the descriptor. + */ +export function atomicWriteFileStreamed( + path: string, + write: (descriptor: number) => void, + hooks: AtomicWriteHooks = {}, +): void { + atomicWriteFileToTarget(path, write, resolveWriteTarget(path), undefined, hooks); +} + /** * Atomically replace the named directory entry without resolving a symlink at * that entry. This is for files in directories writable by another process: diff --git a/src/config/schema/config-schema.ts b/src/config/schema/config-schema.ts index 1711b8b314a..d521fa7b3f7 100644 --- a/src/config/schema/config-schema.ts +++ b/src/config/schema/config-schema.ts @@ -46,6 +46,7 @@ import { MAIN_CODEX_ACCOUNT_NAMESPACE_TARGET, } from "../../codex/account-namespace-match"; import { UPSTREAM_HOST_CIRCUIT_MAX_THRESHOLD } from "../../codex/upstream-host-health"; +import { MIN_USAGE_LEDGER_MAX_BYTES } from "../../usage/retention-contract"; import { COMBO_NAMESPACE, comboConfigIssues } from "../../combos/types"; import { routingProfileIssues } from "../../routing/profile"; import { POLICY_NAMESPACE } from "../../routing/profile-namespace"; @@ -82,6 +83,13 @@ export const configSchema = z.object({ managementUsageMaxReadBytes: z.number().int().positive().default(64 * 1024 * 1024).describe( "Deprecated compatibility limit for bounded legacy usage readers; GET /api/usage always aggregates the complete ledger", ), + // Opt-in ledger ceiling. A hand edit below the floor, or a non-safe integer, disables only + // this limit rather than failing the config: refusing to start because history retention was + // mistyped would be a worse outcome than not trimming history. + usageLedgerMaxBytes: z.number().int().safe() + .min(MIN_USAGE_LEDGER_MAX_BYTES) + .optional() + .catch(undefined), // Invalid hand edits disable only this opt-in circuit. Live writes remain strict. upstreamHostCircuitThreshold: z.number().int() .min(0) diff --git a/src/server/index.ts b/src/server/index.ts index dc3462d638a..5ab9dccb34f 100644 --- a/src/server/index.ts +++ b/src/server/index.ts @@ -111,6 +111,7 @@ import { type RequestLogEntry, } from "./request-log"; import { sessionLaneIdFromRequest } from "./request-log-conversation"; +import { setUsageLedgerRetention } from "./usage-ledger-retention"; import { admitHttpWorkflowTurn, workflowDecisionRefusalResponse, type WorkflowRefusalLog } from "./workflow-refusal"; export { addFinalRequestLog, @@ -303,6 +304,9 @@ function startServerWithSpendLedgerOwner(port: number | undefined, deps: StartSe enforceAppOwnedMemoryBudget(); // Observe-only mode still journals physical sends, so every server owns before configuring. spendLedgerLifecycle.configure(config.spend); + // After ownership: a second server on the same home is refused above, so the process running + // this line is the only one appending to usage.jsonl and the only one that may compact it. + setUsageLedgerRetention(config.usageLedgerMaxBytes); registerCodexCooldownRecoveryProbeWorker(config); // Issue #42 Phase 3: opt-in archived auto-cleanup (default OFF). Unref'd hourly // tick for daily/weekly; startup evaluation is fire-and-forget after listen. diff --git a/src/server/request-log.ts b/src/server/request-log.ts index 7578a84a70c..77f9e0cdbd3 100644 --- a/src/server/request-log.ts +++ b/src/server/request-log.ts @@ -529,6 +529,24 @@ export function hydrateRequestLogsFromDisk( } } +/** + * Rebuild the Logs ring after retention deleted rows from the ledger. + * + * Without this a compaction is invisible where an operator actually looks: the ring holds up to + * 2,000 entries independently of the file, so rows deleted from disk keep serving through + * /api/logs until eviction or a restart -- the dashboard showing history the ledger no longer + * has. Observers are deliberately not replayed; they exist to watch NEW rows arrive, and + * replaying a rehydration through them would announce two thousand arrivals that did not happen. + */ +export function rehydrateRequestLogsAfterLedgerReplacement( + reader: () => PersistedUsageEntry[] = () => readRecentUsageEntries(MAX_LOG_SIZE), +): number { + requestLog.length = 0; + requestLogBytes = 0; + requestLogsHydratedFromDisk = false; + return hydrateRequestLogsFromDisk(reader); +} + export function addRequestLog(entry: RequestLogEntry) { // Sanitize ONCE, at the ingress, and use that one value for both destinations. // diff --git a/src/server/usage-ledger-retention.ts b/src/server/usage-ledger-retention.ts new file mode 100644 index 00000000000..fe0eafb6d6a --- /dev/null +++ b/src/server/usage-ledger-retention.ts @@ -0,0 +1,74 @@ +/** + * Runtime owner for the opt-in usage-ledger size limit (#5063). + * + * The compactor in `src/usage/ledger-retention.ts` knows how to publish a smaller ledger safely. + * This is the part that decides when, and -- the half #5063 was missing -- what has to be + * discarded afterwards. + * + * Deleting rows from usage.jsonl invalidates three readers that do not watch the file: the + * 2,000-entry Logs ring, which otherwise keeps serving rows the ledger no longer has; the + * retained usage aggregate and failure projection, whose checkpoints now point past a boundary + * that moved; and the request-history index, whose source identity has changed. A compaction + * that skips any of them makes the dashboard disagree with the ledger, which is the disagreement + * this batch exists to remove. + */ +import { setUsageLedgerAppendHook } from "../usage/log"; +import { enforceUsageLedgerSizeLimit } from "../usage/ledger-retention"; +import { discardRetainedFailureProjection } from "../usage/failure-projection-cache"; +import { rehydrateRequestLogsAfterLedgerReplacement } from "./request-log"; +import type { UsageLedgerRetentionStatus } from "../usage/retention-contract"; +import { currentUsageLogRevision } from "../usage/log"; + +let configuredMaxBytes: number | undefined; +let enforcing = false; + +function invalidateLedgerReaders(): void { + // Ordered cheapest-first, and each guarded on its own: a projection that fails to discard + // must not stop the ring from being rebuilt, because the ring is the surface an operator is + // looking at while this happens. + try { discardRetainedFailureProjection(); } catch { /* rebuildable by construction */ } + void (async () => { + try { + const { discardRetainedUsageAggregate } = await import("./management/usage-aggregate-cache"); + discardRetainedUsageAggregate(); + } catch { /* rebuildable by construction */ } + try { + const { closeRequestHistoryIndex } = await import("../routing/history/indexer"); + closeRequestHistoryIndex(); + } catch { /* the index rebuilds from its own source-identity contract */ } + })(); + try { rehydrateRequestLogsAfterLedgerReplacement(); } catch { /* the ring refills as rows arrive */ } +} + +function enforceNow(): void { + // Re-entrancy guard, not a lock. The compaction itself runs inside the append call stack, and + // its own publication writes nothing through appendUsageEntry -- this exists so a future + // caller on that path cannot start a second pass over a file the first one is replacing. + if (enforcing) return; + enforcing = true; + try { + const result = enforceUsageLedgerSizeLimit(configuredMaxBytes); + if (result.kind === "replaced") invalidateLedgerReaders(); + } catch (error) { + // Never fail a request because history could not be trimmed. The limit is not enforced and + // says so; the next append tries again from a fresh revision. + console.warn( + `[usage-retention] could not enforce the usage ledger size limit: ${error instanceof Error ? error.message : String(error)}`, + ); + } finally { + enforcing = false; + } +} + +/** Install or update the policy. `undefined` removes the hook entirely. */ +export function setUsageLedgerRetention(maxBytes: number | undefined): void { + configuredMaxBytes = maxBytes; + setUsageLedgerAppendHook(maxBytes === undefined ? null : enforceNow); +} + +export function usageLedgerRetentionStatus(): UsageLedgerRetentionStatus { + return { + ...(configuredMaxBytes !== undefined ? { maxBytes: configuredMaxBytes } : {}), + currentBytes: currentUsageLogRevision()?.size ?? 0, + }; +} diff --git a/src/types/config.ts b/src/types/config.ts index 38b29fe8bb5..6f73b99cd42 100644 --- a/src/types/config.ts +++ b/src/types/config.ts @@ -824,6 +824,13 @@ export interface OcxConfig { * See `src/storage/policy.ts`. */ storageCleanupPolicy?: StorageCleanupPolicy; + /** + * Opt-in ceiling in bytes for `usage.jsonl`. Absent means the ledger grows without limit, + * which stays the default: history an operator did not ask to delete is not deleted. Values + * below the documented floor are treated as unset rather than enforced, because a ceiling + * smaller than a row cannot be met without emptying the file. + */ + usageLedgerMaxBytes?: number; /** Generated API keys for external access to the proxy's /v1/responses endpoint. */ apiKeys?: OcxApiKeyEntry[]; /** Auto-start/sync the proxy from the Codex shim before launching Codex. Default true. */ diff --git a/src/usage/ledger-retention.ts b/src/usage/ledger-retention.ts new file mode 100644 index 00000000000..aaaf17bcc5b --- /dev/null +++ b/src/usage/ledger-retention.ts @@ -0,0 +1,160 @@ +/** + * Opt-in size limit for the canonical usage ledger (#5063). + * + * Retention on usage.jsonl is the right architecture -- the alternative is a projection that + * deletes rows the ledger still has, which is a second retention policy. What #5063's version + * could not promise is that a row appended by another writer between its size snapshot and its + * rename survived: it captured a size, copied a suffix, and renamed over whatever was there. + * + * Two things close that here. The append is synchronous and this runs inside the same call + * stack, with no await between the append and the publication, so no in-process append can + * interleave. And `validateBeforeRename` re-opens the target immediately before the rename and + * refuses unless its identity, size and revision metadata are byte-for-byte what was copied -- + * so an append from anywhere else aborts the replacement instead of losing the row. The original + * file and that append both survive; the next append retries from a fresh revision. + * + * What remains outside the contract: a program that ignores the OpenCodex ledger owner entirely + * can still write between the final comparison and the rename. No portable conditional rename + * exists to prevent that, and the honest claim is that the race is closed for every cooperating + * writer and detected up to the last possible moment for anything else. + */ +import { closeSync, fstatSync, openSync, readSync, writeSync } from "node:fs"; +import { atomicWriteFileStreamed } from "../config/atomic-write"; +import { + currentUsageLogRevision, + usageLogIdentityKey, + usageLogPath, + usageLogRevisionKey, + type UsageLogRevision, +} from "./log"; +import { + MIN_USAGE_LEDGER_MAX_BYTES, + USAGE_LEDGER_RETENTION_TARGET_RATIO, +} from "./retention-contract"; + +/** Bounded copy buffer. Matches the ledger scanner's chunk so one storage policy governs both. */ +const COPY_CHUNK_BYTES = 1024 * 1024; + +export class UsageLedgerRevisionChangedError extends Error { + readonly code = "usage_ledger_revision_changed"; + + constructor() { + super("usage ledger changed while its retained span was being published"); + this.name = "UsageLedgerRevisionChangedError"; + } +} + +export type UsageLedgerRetentionResult = + | { kind: "disabled" } + | { kind: "unchanged"; currentBytes: number } + | { kind: "replaced"; currentBytes: number; removedBytes: number } + | { kind: "deferred"; currentBytes: number; reason: "revision-changed" | "no-boundary" }; + +/** + * The first LF at or after `from`, so the retained span starts on a row boundary. + * + * Any nonempty suffix that is not LF-terminated is uncommitted by the scanner's definition, even + * if it happens to parse. Starting anywhere but after an LF would publish half a row as a whole + * one, which is the shape that makes a ledger unreadable rather than merely shorter. + */ +function firstRowBoundary(fd: number, from: number, end: number): number | null { + const buffer = Buffer.allocUnsafe(COPY_CHUNK_BYTES); + for (let position = from; position < end;) { + const read = readSync(fd, buffer, 0, Math.min(buffer.byteLength, end - position), position); + if (read <= 0) return null; + const index = buffer.subarray(0, read).indexOf(0x0a); + if (index >= 0) return position + index + 1; + position += read; + } + return null; +} + +function copyRange(sourceFd: number, targetFd: number, from: number, to: number): void { + const buffer = Buffer.allocUnsafe(COPY_CHUNK_BYTES); + for (let position = from; position < to;) { + const read = readSync(sourceFd, buffer, 0, Math.min(buffer.byteLength, to - position), position); + if (read <= 0) throw new Error("usage ledger shrank while its retained span was copied"); + let written = 0; + while (written < read) written += writeSync(targetFd, buffer, written, read - written); + position += read; + } +} + +function sameRevision(a: UsageLogRevision | null, b: UsageLogRevision | null): boolean { + return a !== null && b !== null + && usageLogIdentityKey(a) === usageLogIdentityKey(b) + && usageLogRevisionKey(a) === usageLogRevisionKey(b) + && a.size === b.size; +} + +/** + * Trim the ledger to the newest whole rows when it exceeds `maxBytes`. + * + * Rows are copied BYTE FOR BYTE and never parsed or re-serialized. That is what keeps the + * failure stage and cause, the attempts, the spend record and any field a later build adds + * intact through a compaction: a retention pass that understood the row shape would silently + * drop every field it was written before. + */ +export function enforceUsageLedgerSizeLimit( + maxBytes: number | undefined, + /** + * Runs after the retained span is copied and before the pre-rename check. + * + * A parameter rather than an exported flag, so the only way to reach this window is to be the + * caller. The revision guard below is the one piece of this module that cannot be observed + * from its inputs and outputs, and a contract nothing can drive is a contract nobody has + * checked. + */ + options: { onSpanCopied?: () => void } = {}, +): UsageLedgerRetentionResult { + if (maxBytes === undefined || !Number.isSafeInteger(maxBytes) || maxBytes < MIN_USAGE_LEDGER_MAX_BYTES) { + return { kind: "disabled" }; + } + const captured = currentUsageLogRevision(); + if (!captured || captured.size <= maxBytes) { + return captured ? { kind: "unchanged", currentBytes: captured.size } : { kind: "disabled" }; + } + const path = usageLogPath(); + // Trim below the ceiling rather than to it, so an append does not immediately re-cross the + // line and make every subsequent append pay for a full rewrite. + const target = Math.floor(maxBytes * USAGE_LEDGER_RETENTION_TARGET_RATIO); + let sourceFd: number; + try { + sourceFd = openSync(path, "r"); + } catch { + return { kind: "deferred", currentBytes: captured.size, reason: "revision-changed" }; + } + try { + const opened = fstatSync(sourceFd); + if (Number(opened.size) !== captured.size || Number(opened.ino) !== captured.ino) { + return { kind: "deferred", currentBytes: captured.size, reason: "revision-changed" }; + } + const start = firstRowBoundary(sourceFd, Math.max(0, captured.size - target), captured.size); + // No LF in the retained window means one row is larger than the whole target. Deleting it + // would empty the ledger to satisfy a ceiling it cannot meet, so nothing is done. + if (start === null || start >= captured.size) { + return { kind: "deferred", currentBytes: captured.size, reason: "no-boundary" }; + } + atomicWriteFileStreamed(path, descriptor => { + copyRange(sourceFd, descriptor, start, captured.size); + options.onSpanCopied?.(); + }, { + // The last possible moment. Anything that appended, replaced or rewrote the ledger while + // the copy ran moves size, inode or revision metadata, and the throw leaves both the + // original file and that write exactly as they are. + validateBeforeRename: () => { + if (!sameRevision(currentUsageLogRevision(), captured)) { + throw new UsageLedgerRevisionChangedError(); + } + }, + }); + return { kind: "replaced", currentBytes: captured.size - start, removedBytes: start }; + } catch (error) { + if (error instanceof UsageLedgerRevisionChangedError) { + return { kind: "deferred", currentBytes: captured.size, reason: "revision-changed" }; + } + throw error; + } finally { + closeSync(sourceFd); + } +} diff --git a/src/usage/log.ts b/src/usage/log.ts index b8467fca876..88a74cbbff6 100644 --- a/src/usage/log.ts +++ b/src/usage/log.ts @@ -953,6 +953,20 @@ function ensureUsageLogDir(now: number): void { ensuredUsageLogDir = { path: dir, checkedAt: now }; } +/** + * One owner hook, run after an append lands. + * + * A slot rather than a direct call, because the only consumer -- ledger retention -- reads this + * module's revision helpers, and importing it back here would be a static cycle. The hook runs + * INSIDE the synchronous append call stack on purpose: that is what makes "no in-process append + * can interleave with a compaction" true rather than merely likely. + */ +let afterUsageLedgerAppend: (() => void) | null = null; + +export function setUsageLedgerAppendHook(hook: (() => void) | null): void { + afterUsageLedgerAppend = hook; +} + export function appendUsageEntry(entry: PersistedUsageEntry): void { const line = `${JSON.stringify(normalizeUsageEntry(entry))}\n`; const path = usageLogPath(); @@ -973,10 +987,12 @@ export function appendUsageEntry(entry: PersistedUsageEntry): void { ensuredUsageLogDir = null; ensuredUsageLogFile = null; doAppend(); + afterUsageLedgerAppend?.(); return; } throw error; } + afterUsageLedgerAppend?.(); } export type UsageLogRevision = { diff --git a/src/usage/retention-contract.ts b/src/usage/retention-contract.ts new file mode 100644 index 00000000000..bc8d10feece --- /dev/null +++ b/src/usage/retention-contract.ts @@ -0,0 +1,28 @@ +/** + * The usage-ledger retention limits, stated once for the schema, the server and the dashboard. + * + * Import-free, for the reason `telemetry-contract.ts` gives: the dashboard is a separate + * TypeScript project, and a type-only import still drags the imported file's whole graph into + * the browser build. Anything added here must keep that property. + */ + +/** + * Below this a ceiling cannot hold even one large row plus its successor, so a value under it is + * treated as unset rather than enforced into an empty ledger. + */ +export const MIN_USAGE_LEDGER_MAX_BYTES = 1024 * 1024; + +/** What the dashboard offers when a user turns the limit on. Not a default for the proxy. */ +export const SUGGESTED_USAGE_LEDGER_MAX_BYTES = 1024 * 1024 * 1024; + +/** + * Trim to this fraction of the ceiling rather than to the ceiling itself, so the next append does + * not immediately re-cross it and charge every subsequent append a full rewrite. + */ +export const USAGE_LEDGER_RETENTION_TARGET_RATIO = 0.9; + +export interface UsageLedgerRetentionStatus { + /** Absent when no limit is configured. */ + maxBytes?: number; + currentBytes: number; +} diff --git a/tests/fixtures/test-layout-expected.json b/tests/fixtures/test-layout-expected.json index b232905c037..3f13c57008c 100644 --- a/tests/fixtures/test-layout-expected.json +++ b/tests/fixtures/test-layout-expected.json @@ -1058,6 +1058,7 @@ "usage-failure-fingerprint.test.ts": "usage", "usage-failure-projection.test.ts": "usage", "usage-attempt-delivery.test.ts": "usage", + "usage-ledger-retention.test.ts": "usage", "request-pacing.test.ts": "usage", "reserve-auth-context.test.ts": "codex-integration", "reserve-availability.test.ts": "codex-integration", diff --git a/tests/usage/usage-ledger-retention.test.ts b/tests/usage/usage-ledger-retention.test.ts new file mode 100644 index 00000000000..35363e13853 --- /dev/null +++ b/tests/usage/usage-ledger-retention.test.ts @@ -0,0 +1,116 @@ +import { afterEach, beforeEach, describe, expect, test } from "bun:test"; +import { appendFileSync, mkdirSync, mkdtempSync, readFileSync, statSync, writeFileSync } from "node:fs"; +import { tmpdir } from "node:os"; +import { dirname, join } from "node:path"; +import { removeTreeWithRetry } from "../helpers/remove-tree"; +import { enforceUsageLedgerSizeLimit } from "../../src/usage/ledger-retention"; +import { + MIN_USAGE_LEDGER_MAX_BYTES, + USAGE_LEDGER_RETENTION_TARGET_RATIO, +} from "../../src/usage/retention-contract"; +import { usageLogPath } from "../../src/usage/log"; + +let home: string; +let previousHome: string | undefined; + +/** Rows of a known size, each carrying a field no normalizer in this build knows about. */ +function writeRows(count: number, padding: number): string[] { + const path = usageLogPath(); + mkdirSync(dirname(path), { recursive: true }); + const lines = Array.from({ length: count }, (_, index) => JSON.stringify({ + requestId: `req-${index}`, + aFieldThisBuildDoesNotKnow: "x".repeat(padding), + })); + writeFileSync(path, lines.map(line => `${line}\n`).join(""), { encoding: "utf-8", mode: 0o600 }); + return lines; +} + +beforeEach(() => { + previousHome = process.env.OPENCODEX_HOME; + home = mkdtempSync(join(tmpdir(), "ocx-ledger-retention-")); + process.env.OPENCODEX_HOME = home; +}); + +afterEach(() => { + if (previousHome === undefined) delete process.env.OPENCODEX_HOME; + else process.env.OPENCODEX_HOME = previousHome; + removeTreeWithRetry(home); +}); + +describe("usage ledger retention", () => { + test("no limit, a limit below the floor, and a ledger under the limit leave the file alone", () => { + writeRows(20, 64); + const before = readFileSync(usageLogPath(), "utf-8"); + expect(enforceUsageLedgerSizeLimit(undefined).kind).toBe("disabled"); + expect(enforceUsageLedgerSizeLimit(MIN_USAGE_LEDGER_MAX_BYTES - 1).kind).toBe("disabled"); + expect(enforceUsageLedgerSizeLimit(MIN_USAGE_LEDGER_MAX_BYTES).kind).toBe("unchanged"); + expect(readFileSync(usageLogPath(), "utf-8")).toBe(before); + }); + + test("it keeps the newest whole rows, byte for byte, including fields it does not understand", () => { + const lines = writeRows(200, 16 * 1024); + const originalBytes = statSync(usageLogPath()).size; + expect(enforceUsageLedgerSizeLimit(MIN_USAGE_LEDGER_MAX_BYTES).kind).toBe("replaced"); + + const after = readFileSync(usageLogPath(), "utf-8"); + const retained = after.split("\n").filter(line => line !== ""); + expect(retained.length).toBeGreaterThan(0); + expect(retained.length).toBeLessThan(lines.length); + // Identical to the tail they came from: rows are copied, never parsed and rewritten, which + // is what keeps a field this build has never heard of intact through a compaction. + expect(retained).toEqual(lines.slice(lines.length - retained.length)); + expect(after).toContain("aFieldThisBuildDoesNotKnow"); + expect(after.endsWith("\n")).toBe(true); + const size = statSync(usageLogPath()).size; + expect(size).toBeLessThan(originalBytes); + expect(size).toBeLessThanOrEqual( + Math.floor(MIN_USAGE_LEDGER_MAX_BYTES * USAGE_LEDGER_RETENTION_TARGET_RATIO), + ); + }); + + test("an unterminated final row is carried as-is and never promoted", () => { + writeRows(200, 16 * 1024); + const torn = JSON.stringify({ requestId: "torn" }).slice(0, 12); + appendFileSync(usageLogPath(), torn); + expect(enforceUsageLedgerSizeLimit(MIN_USAGE_LEDGER_MAX_BYTES).kind).toBe("replaced"); + const lines = readFileSync(usageLogPath(), "utf-8").split("\n"); + // No LF was invented to make it committed: the scanner's definition is unchanged here. + expect(lines.at(-1)).toBe(torn); + for (const line of lines.slice(0, -1)) { + if (line !== "") expect(() => JSON.parse(line) as unknown).not.toThrow(); + } + }); + + test("one row larger than the whole target defers instead of emptying the ledger", () => { + writeRows(1, MIN_USAGE_LEDGER_MAX_BYTES * 2); + const before = readFileSync(usageLogPath(), "utf-8"); + const result = enforceUsageLedgerSizeLimit(MIN_USAGE_LEDGER_MAX_BYTES); + expect(result.kind).toBe("deferred"); + expect(result).toMatchObject({ reason: "no-boundary" }); + expect(readFileSync(usageLogPath(), "utf-8")).toBe(before); + }); + + test("a row appended while the retained span is copied aborts the replacement", () => { + const lines = writeRows(200, 16 * 1024); + const raced = JSON.stringify({ requestId: "appended-during-copy" }); + const result = enforceUsageLedgerSizeLimit(MIN_USAGE_LEDGER_MAX_BYTES, { + onSpanCopied: () => appendFileSync(usageLogPath(), `${raced}\n`), + }); + + // This is the defect the revision contract exists to close. #5063 captured a size, copied a + // suffix and renamed over whatever was there, so this row was silently lost. + expect(result.kind).toBe("deferred"); + expect(result).toMatchObject({ reason: "revision-changed" }); + const after = readFileSync(usageLogPath(), "utf-8"); + expect(after).toContain("appended-during-copy"); + // Nothing was trimmed either: the original file is exactly as it was, plus the new row. + expect(after.split("\n").filter(line => line !== "").length).toBe(lines.length + 1); + }); + + test("the published file keeps owner-only permissions", () => { + if (process.platform === "win32") return; + writeRows(200, 16 * 1024); + expect(enforceUsageLedgerSizeLimit(MIN_USAGE_LEDGER_MAX_BYTES).kind).toBe("replaced"); + expect(statSync(usageLogPath()).mode & 0o777).toBe(0o600); + }); +}); From 246b31f2c75d7bab65504ad882955a55038b443c Mon Sep 17 00:00:00 2001 From: JUN Date: Sun, 20 Sep 2026 22:23:42 +0900 Subject: [PATCH 06/10] fix(usage): read transport evidence before the status, and map 402 Adversarial review of this branch found three cases where the derived cause was wrong against real request paths rather than against the fabricated facts the first test used. A stream that dies mid-flight is reported as a SYNTHETIC 502 -- a tail this proxy wrote, with transportPhase mid_stream and the attempt marked aborted. Read in status order that 502 became upstream-fault, which claims the origin answered when it did not. Transport evidence now outranks the numeric status. Both causes refuse an automatic resend, so this is an accuracy fix rather than a safety one, but a label an operator cannot trust is a label they stop reading. 402 had no branch and fell through to payload-rejected, which made quota-exhausted unreachable and pointed an operator at the payload when the account is what has to change. transport-unsent was reachable only through a fabricated status 0: a real connect failure is formatted as 502 by the dispatch path. Worse, it was the FALL-THROUGH, and it is the one transport cause that permits an automatic resend. It is now reachable only through causeHint, from a site that classified a pre-connect failure and can prove it; everything else answers transport-ambiguous, which is the honest classification for an unknown execution state and the safe direction for a permission decision. Review also found the streamed atomic replacement fsynced the temp's contents and not the directory entry recording the rename, so a host losing power after a successful call could leave the old ledger or an indeterminate directory. The streaming form now syncs the parent directory. Only that form does: it is the one making a durability claim, and charging every config write for a promise its callers were never given is a different change. The regression cases now use the production shapes -- a synthetic 502 after mid_stream, an aborted stream, an upstream 502 that stays an upstream fault -- rather than a status no transport produces. --- src/config/atomic-write.ts | 30 ++++++++++++++++++++++++++ src/config/schema/config-schema.ts | 3 ++- src/lib/request-failure-attribution.ts | 26 +++++++++++++++++----- src/server/request-log.ts | 2 ++ src/server/usage-ledger-retention.ts | 3 +-- structure/gui-and-management-api.md | 23 ++++++++++++++++++-- structure/overview.md | 18 ++++++++++------ tests/lib/failure-attribution.test.ts | 25 ++++++++++++++++++--- 8 files changed, 110 insertions(+), 20 deletions(-) diff --git a/src/config/atomic-write.ts b/src/config/atomic-write.ts index 0bbebdd3ba3..2bdb9508e2c 100644 --- a/src/config/atomic-write.ts +++ b/src/config/atomic-write.ts @@ -163,6 +163,27 @@ function carryHardenAcrossContentWrite(path: string): void { reattributeHardenedSecretPath(path); } +/** + * Commit the directory entry a rename just wrote. + * + * Best effort by platform, not by importance: Windows has no directory descriptor to sync and + * some filesystems refuse the open, and failing a replacement that already happened would be + * worse than reporting it. The throw that matters is the temp's own `fsync`, which runs before + * the rename and stops it. + */ +function syncParentDirectory(target: string): void { + if (process.platform === "win32") return; + let descriptor: number | undefined; + try { + descriptor = openSync(dirname(target), "r"); + fsyncSync(descriptor); + } catch { + /* the rename already landed; a directory that cannot be synced is not a reason to undo it */ + } finally { + if (descriptor !== undefined) { try { closeSync(descriptor); } catch { /* already closed */ } } + } +} + function writePrivateTempFile( path: string, content: string, @@ -292,6 +313,15 @@ function atomicWriteFileToTarget( hooks.beforeRename?.(tmp, target); hooks.validateBeforeRename?.(target); effective.rename(tmp, target); + // The rename is only as durable as the directory entry recording it. Fsyncing the temp's + // CONTENT and then losing the entry in a power cut leaves the old file in place, or the + // directory in an indeterminate state, while the caller was told the replacement landed. + // + // Only the streaming form does this. It is the one that makes a durability claim -- a + // replacement is not an append, and losing it can lose the rows it was meant to keep -- and + // adding a directory sync to the string form would charge every config write for a promise + // its callers have never been given. + if (typeof content === "function") syncParentDirectory(target); forgetEphemeralSecretPath(tmp); } catch (cause) { if (!ownsTemp) throw cause; diff --git a/src/config/schema/config-schema.ts b/src/config/schema/config-schema.ts index d521fa7b3f7..6d1e936670c 100644 --- a/src/config/schema/config-schema.ts +++ b/src/config/schema/config-schema.ts @@ -86,8 +86,9 @@ export const configSchema = z.object({ // Opt-in ledger ceiling. A hand edit below the floor, or a non-safe integer, disables only // this limit rather than failing the config: refusing to start because history retention was // mistyped would be a worse outcome than not trimming history. - usageLedgerMaxBytes: z.number().int().safe() + usageLedgerMaxBytes: z.number().int() .min(MIN_USAGE_LEDGER_MAX_BYTES) + .max(Number.MAX_SAFE_INTEGER) .optional() .catch(undefined), // Invalid hand edits disable only this opt-in circuit. Live writes remain strict. diff --git a/src/lib/request-failure-attribution.ts b/src/lib/request-failure-attribution.ts index ba445f83716..098af493003 100644 --- a/src/lib/request-failure-attribution.ts +++ b/src/lib/request-failure-attribution.ts @@ -29,6 +29,10 @@ import { classifyRequestOutcome, type RequestOutcomeFacts } from "../usage/reque */ export interface RequestFailureFacts extends RequestOutcomeFacts { readonly transportPhase?: "pre_headers" | "mid_stream" | "terminal_sse" | undefined; + /** Where the status and message came from: an origin response, or a tail this proxy wrote. */ + readonly terminalSource?: "upstream" | "synthetic" | undefined; + /** True when the upstream stream died after its head was committed. */ + readonly streamAborted?: boolean | undefined; /** True once any output-bearing event reached the caller; `firstOutputMs` is the usual source. */ readonly outputObserved?: boolean | undefined; /** True once a tool call or other externally visible effect was relayed to the caller. */ @@ -127,6 +131,16 @@ export function deriveRequestFailureCause(facts: RequestFailureFacts): RequestFa if (facts.causeHint !== undefined) return facts.causeHint; const status = facts.status; + // Transport evidence outranks the numeric status, because a stream that died mid-flight is + // reported as a SYNTHETIC 502 -- a tail this proxy wrote, not an answer the origin gave. Read + // in status order that 502 becomes `upstream-fault`, which claims the origin answered when it + // did not. Both causes refuse an automatic resend, so this is an accuracy fix rather than a + // safety one, but a label an operator cannot trust is a label they stop reading. + if (facts.streamAborted === true + || (facts.terminalSource === "synthetic" + && (facts.transportPhase === "mid_stream" || facts.transportPhase === "terminal_sse"))) { + return "transport-ambiguous"; + } // A 2xx head that carried a failed terminal: the origin ran the turn and said it failed. With // no output relayed the useful distinction is that nothing usable came back at all. if (status >= 100 && status < 400) { @@ -134,17 +148,19 @@ export function deriveRequestFailureCause(facts: RequestFailureFacts): RequestFa } if (status === 401) return "credential-rejected"; if (status === 403) return "credential-rejected"; + // Payment required. Waiting out a retry window does not help; the account has to change. + if (status === 402) return "quota-exhausted"; if (status === 413) return "payload-too-large"; if (status === 429) return "rate-limit"; if (status === 451) return "policy-refusal"; if (status === 503) return "upstream-declined"; if (status >= 500) return "upstream-fault"; if (status >= 400) return refinedFourHundredCause(facts) ?? "payload-rejected"; - // No response head at all. A stream that began and died is ambiguous about whether the origin - // ran the turn; a request that never reached a mid-stream phase provably did not send. - return facts.transportPhase === "mid_stream" || facts.transportPhase === "terminal_sse" - ? "transport-ambiguous" - : "transport-unsent"; + // No response head at all, and nothing proved the bytes never left. `transport-ambiguous` is + // the honest answer for an unknown execution state, and it is the safe one: it refuses an + // automatic resend where `transport-unsent` would permit one. `transport-unsent` is reachable + // only through `causeHint`, from a site that classified a pre-connect failure and can prove it. + return "transport-ambiguous"; } export interface RequestFailureAttribution { diff --git a/src/server/request-log.ts b/src/server/request-log.ts index 77f9e0cdbd3..cc6866a8dbb 100644 --- a/src/server/request-log.ts +++ b/src/server/request-log.ts @@ -1419,6 +1419,8 @@ export function addFinalRequestLog( ...(meta?.terminalStatus ? { terminalStatus: meta.terminalStatus } : {}), ...(closeReason ? { closeReason } : {}), ...(logCtx.transportPhase ? { transportPhase: logCtx.transportPhase } : {}), + ...(logCtx.terminalSource ? { terminalSource: logCtx.terminalSource } : {}), + ...(logCtx.activeAttempt?.streamAborted === true ? { streamAborted: true } : {}), // The REQUEST's output observation, not the final attempt's. // // A request that relayed output on its first attempt and then failed over has committed diff --git a/src/server/usage-ledger-retention.ts b/src/server/usage-ledger-retention.ts index fe0eafb6d6a..46b5d676f04 100644 --- a/src/server/usage-ledger-retention.ts +++ b/src/server/usage-ledger-retention.ts @@ -12,12 +12,11 @@ * that skips any of them makes the dashboard disagree with the ledger, which is the disagreement * this batch exists to remove. */ -import { setUsageLedgerAppendHook } from "../usage/log"; +import { currentUsageLogRevision, setUsageLedgerAppendHook } from "../usage/log"; import { enforceUsageLedgerSizeLimit } from "../usage/ledger-retention"; import { discardRetainedFailureProjection } from "../usage/failure-projection-cache"; import { rehydrateRequestLogsAfterLedgerReplacement } from "./request-log"; import type { UsageLedgerRetentionStatus } from "../usage/retention-contract"; -import { currentUsageLogRevision } from "../usage/log"; let configuredMaxBytes: number | undefined; let enforcing = false; diff --git a/structure/gui-and-management-api.md b/structure/gui-and-management-api.md index de51d06c3c4..726af4a7023 100644 --- a/structure/gui-and-management-api.md +++ b/structure/gui-and-management-api.md @@ -528,6 +528,21 @@ monitoring or protection against another process changing the path again after t An opt-in shadow-call rewrite persists the bounded, redacted original helper model as `shadowCallRewrittenFrom`, so helper traffic remains identifiable after restart without storing request content or inferring a helper subtype from timing. +A failed request persists closed `failureStage` and `failureCause` members on the attempt that ended +it and on the logical row, derived once at `addFinalRequestLog` from facts that are themselves +closed; `errorCode` and `upstreamError` carry upstream text and are deliberately not read there. The +resend verdict they imply is never stored — `/api/logs` computes `resendPermission` at read time, so +a row written by an older build cannot assert a permission the current tables refuse. An attempt also +carries `deliverySummary`: adapter events, relayed frames, semantic bytes, side effects and terminal +frames, counted where each event is delivered rather than where it is read, so the gap between the +first two is the loss signal. Provider debug formats one ring line per finalized attempt from those +counts and writes no second record. `GET /api/usage?failures=1` groups failed rows by a versioned +fingerprint over closed vocabularies only, rebuilt through the same cooperative scanner and +inheriting its bounds, so deleting a ledger row removes it from the grouping. +`usageLedgerMaxBytes` is unset by default; when set, an append that crosses it publishes the newest +whole rows byte for byte through the shared atomic writer, refuses the rename unless the source is +the exact revision that was copied, and then discards the Logs ring, the retained aggregates and the +request-history index so no surface serves rows the ledger no longer has. `src/usage/summary.ts` turns that file into the `/api/usage` shape — totals, daily zero-filled grid, model and provider breakdowns, and `measured / reported / unreported / unsupported / estimated` counts. The management route scans the ledger from its beginning in fixed 1 MiB chunks on a @@ -625,11 +640,15 @@ log scan, or persistence. Restart creates a fresh owner, resets every counter/hi The label vocabularies are closed: protocol is `responses`, `chat`, `messages`, or `unknown`; result is `completed`, `failed`, `incomplete`, or `aborted`; recovery is one of the coarse classes listed in -`REQUEST_METRICS_RECOVERY_CLASSES`, which is the roster the exporter itself iterates. The count is +`REQUEST_METRICS_RECOVERY_CLASSES`, and cause is one of the shared failure causes in +`REQUEST_METRICS_FAILURE_CAUSES`, which aliases the dictionary rather than copying it. Each is the +roster the exporter itself iterates. The count is deliberately not restated here: it was written as eight, a bounded label value was added, and the documentation then contradicted the output it describes. A logical request increments once, physical sends sum the finalized attempt counts, and each distinct -recovery kind already retained on an attempt contributes once to its coarse class. HTTP 200 never +recovery kind already retained on an attempt contributes once to its coarse class. +`opencodex_request_failures_total` counts the cause the recorder derived and never re-derives one, +and it labels a counter only: no histogram carries a cause. HTTP 200 never overrides a failed terminal event. Duration observes every valid finalized duration; TTFT observes only finite nonnegative first-output values, while `opencodex_ttft_missing_total` is the complementary denominator. No request, credential, account, provider, model, conversation, raw error, prompt, tool, diff --git a/structure/overview.md b/structure/overview.md index db168062a43..3f007f7b32f 100644 --- a/structure/overview.md +++ b/structure/overview.md @@ -138,13 +138,17 @@ still cover the rule, which is a judgement only review makes. there, reported as an unidentified holder otherwise. A configured `port: 0` still asks the OS for a port, and an explicit `--port` still waits for its pin instead of hopping. Enforced by `tests/cli/cli-dispatch.test.ts`. -- **INV-RESEND-01** — One vocabulary in `src/lib/request-failure-model.ts` states how far a failed - request got, why it failed, and whether it may be sent again. Once the caller has observed output - or an externally visible effect, no cause automatically permits a resend, and a cause whose - upstream execution state is unknown is not made replayable by having budget left. A refusal names - which of the three refusals it is. The decision is derived from per-stage and per-cause facts - rather than written out as a stage-by-cause matrix, so a new member cannot leave a stale cell. - Enforced by `tests/lib/failure-stage-model.test.ts`. +- **INV-RESEND-01** — One vocabulary states how far a failed request got, why it failed, and whether + it may be sent again. The rosters are declared in the import-free `src/usage/telemetry-contract.ts` + so the dashboard can name their members, and `src/lib/request-failure-model.ts` re-exports them and + owns the decision. Once the caller has observed output or an externally visible effect, no cause + automatically permits a resend, and a cause whose upstream execution state is unknown is not made + replayable by having budget left. A refusal names which of the three refusals it is. The decision is + derived from per-stage and per-cause facts rather than written out as a stage-by-cause matrix, so a + new member cannot leave a stale cell. `src/lib/request-failure-attribution.ts` derives the pair from + closed recorder facts and never from `errorCode` or `upstreamError`, which are open strings; the + resend verdict is computed at read time and never persisted. + Enforced by `tests/lib/failure-stage-model.test.ts` and `tests/lib/failure-attribution.test.ts`. CI enumerates that domain layout through `scripts/ci/run-bun-test-batches.sh`. Its default general scope and 12-file/120-second process shape leave the dedicated Linux storage-policy and api-usage diff --git a/tests/lib/failure-attribution.test.ts b/tests/lib/failure-attribution.test.ts index f661af9b576..8ff5e393470 100644 --- a/tests/lib/failure-attribution.test.ts +++ b/tests/lib/failure-attribution.test.ts @@ -141,9 +141,28 @@ describe("request failure attribution", () => { .toBe("upstream-fault"); }); - test("a request with no response head separates an unsent send from an ambiguous one", () => { - expect(deriveRequestFailureCause({ status: 0 })).toBe("transport-unsent"); - expect(deriveRequestFailureCause({ status: 0, transportPhase: "mid_stream" })).toBe("transport-ambiguous"); + test("a stream that died mid-flight is ambiguous, not an upstream fault", () => { + // The production shape: the relay reports a SYNTHETIC 502 after a mid-stream read failure + // and marks the attempt aborted. Reading the 502 in status order would claim the origin + // answered when it did not. + expect(deriveRequestFailureCause({ + status: 502, transportPhase: "mid_stream", terminalSource: "synthetic", + })).toBe("transport-ambiguous"); + expect(deriveRequestFailureCause({ status: 502, streamAborted: true })).toBe("transport-ambiguous"); + // An upstream 502 that is genuinely upstream stays an upstream fault. + expect(deriveRequestFailureCause({ status: 502, terminalSource: "upstream" })).toBe("upstream-fault"); + }); + + test("an unknown execution state never reads as a proven unsent send", () => { + // `transport-unsent` permits an automatic resend, so it is reachable only from a site that + // classified a pre-connect failure and can prove it. Everything else answers ambiguously, + // which is the safe direction. + expect(deriveRequestFailureCause({ status: 0 })).toBe("transport-ambiguous"); + expect(deriveRequestFailureCause({ status: 0, causeHint: "transport-unsent" })).toBe("transport-unsent"); + }); + + test("payment required is a quota problem, not a bad payload", () => { + expect(deriveRequestFailureCause({ status: 402 })).toBe("quota-exhausted"); }); test("a local refusal is attributed to this proxy rather than to upstream", () => { From 77cded1de2ca85e06164368437f616b754772c60 Mon Sep 17 00:00:00 2001 From: JUN Date: Sun, 20 Sep 2026 22:28:57 +0900 Subject: [PATCH 07/10] fix(usage): count buffered delivery, and read rosters instead of restating them Three findings from the second adversarial review round. A non-streaming turn delivers its whole answer as one body and calls no per-frame recorder, so every buffered response persisted adapter events with zero relayed ones. That is the adapter-to-client loss signal, raised on every buffered request, which makes the signal worthless. The buffered seam now records its delivery from the body it built: everything the adapter produced did reach the client, in one piece, and the semantic bytes and side effects are read from the assembled output. The body is read by field name rather than by the adapter event union, so a member added later is not a merge-time exhaustiveness failure in a counter that does not need one. Two tests claimed their cross products came from the declared vocabularies and then wrote the members out by hand, which is how an added member leaves an exhaustive test green without being exercised. They now read REQUEST_TERMINAL_STATUSES, REQUEST_CLOSE_REASONS and a transport-phase roster that is declared once in the contract leaf and consumed by the ledger validator instead of being stated twice. INV-RESEND-01 named two enforcing tests while the structure checker binds only the first, so the second was prose-only assurance. The attribution rule is now its own INV-ATTRIBUTION-01 with one binding, and the test names it so the binding is readable from both sides. Adds the lane record, including the two limits this branch does not close: the six intermediate attempt finalizers that still reach the ledger unattributed, and the successful-recovery case that can still misattribute a 400. It also records a pre-existing defect found while reviewing the atomic writer -- its scrub fallback opens with "wx" and so always fails on an existing temp -- which is left alone because it predates this branch and sits on a security-adjacent path. --- .../260920_round2_followups/050_lane_r5.md | 180 ++++++++++++++++++ src/bridge/response-json.ts | 10 +- src/usage/attempt-delivery.ts | 42 ++++ src/usage/log.ts | 7 +- src/usage/telemetry-contract.ts | 15 ++ structure/overview.md | 12 +- tests/lib/failure-attribution.test.ts | 19 +- tests/usage/request-outcome-agreement.test.ts | 14 +- tests/usage/usage-attempt-delivery.test.ts | 33 ++++ 9 files changed, 314 insertions(+), 18 deletions(-) create mode 100644 devlog/_plan/260920_round2_followups/050_lane_r5.md diff --git a/devlog/_plan/260920_round2_followups/050_lane_r5.md b/devlog/_plan/260920_round2_followups/050_lane_r5.md new file mode 100644 index 00000000000..47202b886c0 --- /dev/null +++ b/devlog/_plan/260920_round2_followups/050_lane_r5.md @@ -0,0 +1,180 @@ +# Lane R5 — the four telemetry pull requests as derived consumers of the recorder + +Status: OPEN. Branch `codex/260920-r5-telemetry-derived`, rebased onto `dev` after `origin/dev` +advanced mid-lane. One branch, ordered commits, one pull request to `dev`. + +Lane C deferred #2366, #3748, #3983 and #5063 "as implemented", because each adds a parallel store +or a second emission path. [030_lane_c2.md](../260920_meaning_preservation_batch/030_lane_c2.md) +then specified the derived form for each. This lane builds those four forms. It adds no store: the +durable shapes stay `PersistedUsageAttempt` and `PersistedUsageEntry`, and every projection reads +them. + +## What landed, per pull request + +### #2366 (chilung-cgu) — durable failure attribution, in the landed vocabulary + +`failureStage` and `failureCause` now ride the attempt that ended a request and the logical row, +both closed roster members. `FailureSide` and the seven-member `FailureStage` are not here: two +attribution vocabularies for one question is the class that blocked 2.60.0. The PR's widening of +`transportPhase` and `terminalSource` to arbitrary strings is not here either; those validators +stay closed, and `terminalStatus` — which was a plain `string` — joined them, because it is now a +grouping-key slot and it is assembled from an upstream frame. + +The derivation reads only closed values. `errorCode` and `upstreamError` are excluded on purpose: +both carry upstream text, so a classification keyed on them is a different answer per provider and +per locale, and a key built from them cannot promise it carries no content. That exclusion is what +lets the pair be a Prometheus label and a fingerprint component with no masking pass. + +It runs at `addFinalRequestLog`, the one seam every request passes exactly once, and before the +attempt snapshot so the disk row and the live attempt carry the same pair. `addRequestLog` rebuilds +the persisted row field by field, so the pair is written there explicitly — a field omitted at that +line reaches `/api/logs` and never reaches `usage.jsonl`. + +**The resend verdict is not stored.** `/api/logs` computes `resendPermission` at read time for the +row and each attempt. The tables that decide it live in this build; a row written months ago must +not assert a permission the current tables refuse. + +**Known limit, recorded rather than hidden.** Only the attempt that ends a request, plus the one +sealed by a key-account rotation, carry attribution. The other intermediate finalizers — +`policy-fallback.ts` and five sites in `core-combo.ts` — still reach the ledger unattributed. Each +has different evidence in scope and a branch verified by static review alone should not add six new +classification call sites at once. The logical row is attributed in every case, which is what the +projection and the exporter read. + +**Second known limit.** A ciphertext or reasoning-parameter recovery that SUCCEEDED, followed by an +unrelated 400 on the same attempt, still reads as that recovery's cause. The rule is narrowed to +the last recorded kind on the matching status, and the proper fix — clearing recovery evidence on +success in `core-opaque-recovery.ts` — belongs in the recovery path, not the derivation. + +### #3748 (yansigit) — a failure grouping, not a second ledger + +`src/telemetry/` and its SQLite store are not built. Failed rows are grouped by a versioned +fingerprint over a fixed-arity tuple of closed roster members, folded during a scan of +`usage.jsonl` through the existing `scanUsageLedgerCooperatively`. The projection holds a count and +two timestamps per group; delete a ledger row and it leaves the grouping on the next rebuild. + +The free-text `signature` and its regex masking are replaced by construction rather than by a +better regex: an expression can only assert it removed what it matched, while a tuple whose every +slot comes from a frozen list has nothing to remove. Absent facts are explicit nulls in fixed +positions, because omitting them would let `[a, null, b]` and `[a, b]` collide. + +**A deliberate divergence from 030_lane_c2.md, flagged for the coordinator.** That document says +"No provider". The lane brief for R5 says the fingerprint is over "closed cause + provider + model +class". The brief is the later and more direct instruction, so `providerClass` is in the tuple — +resolved against the provider registry so it is a registry id or `null`, never the alias a user +typed. Model class is NOT in the tuple: no closed model-class vocabulary exists in this repository +and inventing one is the union-exhaustive hazard this batch exists to avoid. Removing +`providerClass` is one slot and a version bump if the coordinator prefers the C2 shape. + +The mutable `monitoring/dispatched/fixed/ignored` status and its notes are absent. They are +operator state; they cannot be reconstructed from immutable request rows, so presenting them as a +derived ledger would be a claim this projection cannot make. + +The reader is `GET /api/usage?failures=1` rather than a new route: it answers a different question +from the usage summary and costs a scan, so it is opt-in and no new CLI-parity surface appears. + +### #3983 (yansigit) — five counts on the attempt, no second emission path + +`emitDebugLine` writes the in-process ring AND stderr, and stderr is redirected to the service log +under launchd and systemd, so the PR's per-event lines would give an installed service a durable +per-event history beside the ledger. Its per-payload HMAC used a process-global random key, making +every repeated prompt fragment, tool name and error message correlatable for the process lifetime. + +Instead the attempt carries adapter events, relayed frames, semantic bytes, side effects and +terminal frames. Adapter events are counted at the existing adapter-parse seam; relayed frames +after a SUCCESSFUL `controller.enqueue`. Counting both at the reader would make them equal by +construction and erase the loss signal. The recorder is bound to the request's translator budget +and reaches the current attempt through a callback, so a mid-request attempt rotation credits the +live attempt rather than one already finalized. The debug ring now FORMATS one line per finalized +attempt from those counts, through `appendDebugLogLine` and never `emitDebugLine`. + +Adversarial review caught the case this design gets wrong on its own: a non-streaming turn delivers +one body and calls no per-frame recorder, so every buffered response would have persisted adapter +events with zero relayed ones — the loss signal, raised on every buffered request. The buffered +seam now records its delivery from the body it built. + +`run-turn-execution.ts` is untouched. Its accounting distinguishes adapters that report their own +physical sends, and the PR's unconditional pre-count would double-charge them. + +### #5063 (Vocllum) — retention with a revision contract + +`usageLedgerMaxBytes` is unset by default and unset means unlimited. When set, an append that +crosses it publishes the newest whole rows byte for byte through the shared atomic writer. + +The defect this closes: #5063 captured a size, copied a suffix and renamed over whatever was there, +so a row appended in between was silently dropped; its own concurrency test performed two +sequential calls and said it could not test concurrency. Two things close it. The append is +synchronous and the compaction runs inside the same call stack, so no in-process append can +interleave, and a second server on the same home cannot append at all — it is refused by the +existing ledger-owner lease, which is why the hook is installed after ownership. And +`validateBeforeRename` re-opens the target immediately before the rename and refuses unless +identity, size and revision metadata are byte-for-byte what was copied. A focused test drives that +exact window through an injected hook. + +Rows are copied and never parsed, which is what keeps a field a newer build wrote intact through a +compaction. The writer gained a streaming form so the retained span is not held in memory, and that +form fsyncs the temp before the rename and the parent directory after it. + +The invalidation half was missing from the original entirely. A compaction now discards the +2,000-entry Logs ring, the retained usage aggregate and failure projection, and the request-history +index — otherwise `/api/logs` keeps serving rows the ledger no longer has. + +**This does not close #5063.** The Usage-page control it also asks for is not here: this lane may +not build or run the GUI, so it cannot produce the screenshot the gate requires, and shipping an +unverifiable control is worse than shipping the policy it would set. The limit is settable in +`config.json` today and the configuration reference says so. Remaining scope: the dashboard +control, its management route, and the ten catalog strings. + +## The GUI screenshot gate + +This branch changes `gui/src/pages/Logs.tsx` and the ten locale catalogs, so `missing_ui_screenshot` +fires. It fires on changed paths under `gui/`, not on words in a description, and this lane may not +run `bun run build:gui`. A maintainer comment or the `gui-screenshot-waived` label is the documented +resolution. + +The evidence to judge it without the screenshot: the catalog edits are purely additive (+29 lines, +0 removed, in each of ten files, all exempt from the file-size ratchet), every new key exists in all +ten catalogs, and three `satisfies` clauses make a missing label a typecheck failure rather than a +silent fallback. The visible change is three rows added to the Logs detail dialog for a failed +request — the cause, the stage it reached and the resend verdict — and a named cause where the +attempt table previously led with a bare wire code. + +## Pre-existing defect found and deliberately not fixed here + +`src/config/atomic-write.ts` scrubs a failed temp through `effective.write(tmp, "")`, but the default +writer opens with `"wx"`, so that fallback always fails with `EEXIST` on an existing temp. It only +matters when `truncate` has also failed, and the temp is owner-only. It predates this branch and +affects every atomic config write, including secret-bearing ones, so fixing it is a change to a +security-adjacent path that belongs in its own lane rather than inside a telemetry branch. + +## Verification + +Static source review plus exact-head hosted CI, and three adversarial reviews at high effort +covering typecheck hazards, repository gates, and runtime correctness and privacy. Their findings +are in the branch: the transport-evidence precedence, the 402 mapping, `transport-unsent` no longer +being the fall-through, the parent-directory fsync, the buffered delivery accounting, the rosters +read instead of restated in two tests, and the invariant split into INV-RESEND-01 and +INV-ATTRIBUTION-01 so each binds exactly one test. + +NOT RUN on this branch, by instruction: `bun run test`, any individual `bun test` file, +`bun run typecheck`, `bun run build:gui`, `bun run lint:gui`, `bun install`, +`bun run structure:check`, `bun run privacy:scan`, and any live `ocx` execution. None of these may +be recorded as passing. + +Checked statically: + +- no file this branch touches is at or over its file-size ratchet cap; `src/server/index.ts` sits at + 884 against 893, and the ten catalogs are exempt; +- `scripts/test-layout/layout.json` and `tests/fixtures/test-layout-expected.json` agree key for key, + and each new test's regex seed resolves to the domain it is registered to — `failure-attribution` + is named to avoid the `request-` seed that would have placed it in `usage`; +- `src/usage/telemetry-contract.ts` still has no imports, `src/usage/request-outcome.ts` still reaches + nothing but it, and `gui/src/pages/Logs.tsx` still never names `src/usage/log`; +- no test or document restates a source constant: the rosters, the fingerprint version and the label + keys are read from the modules that declare them. + +## Issues + +#2366, #3748 and #3983 are addressed by these derived forms; the coordinator decides closure. #5063 +is partially addressed and must not be closed — its dashboard control is named above as remaining +scope. diff --git a/src/bridge/response-json.ts b/src/bridge/response-json.ts index cdc9cd1a02e..ccb03b62087 100644 --- a/src/bridge/response-json.ts +++ b/src/bridge/response-json.ts @@ -7,6 +7,7 @@ import type { OcxUsage, } from "../types"; import { coerceIntegerToolArguments } from "../lib/tool-argument-integers"; +import { attemptDeliveryRecorder } from "../usage/attempt-delivery"; import { adapterFailureFromMessage, classifyError, @@ -51,7 +52,14 @@ export function buildResponseJSON( ): Record { // Default-budget safety net: a caller that omits the budget gets a bounded // default (disposed with the call), never the unbounded append path. - if (options?.translatorBudget) return buildResponseJSONWithBudget(events, modelId, options); + if (options?.translatorBudget) { + const body = buildResponseJSONWithBudget(events, modelId, options); + // A buffered turn delivers its whole answer as one body, so nothing calls the per-frame + // recorder on the SSE bridge. Without this the attempt would persist adapter events with + // zero relayed ones, which is the loss signal -- raised on every non-streaming request. + attemptDeliveryRecorder(options.translatorBudget)?.noteBufferedDelivery(body); + return body; + } const budget = createTranslatorBudget(); try { return buildResponseJSONWithBudget(events, modelId, { ...options, translatorBudget: budget }); diff --git a/src/usage/attempt-delivery.ts b/src/usage/attempt-delivery.ts index 2b3ed8f78d2..c1c011747f8 100644 --- a/src/usage/attempt-delivery.ts +++ b/src/usage/attempt-delivery.ts @@ -24,6 +24,7 @@ export interface RelayedEventObservation { export interface AttemptDeliveryRecorder { noteAdapterEvent(): void; noteRelayedEvent(observation?: RelayedEventObservation): void; + noteBufferedDelivery(body: Record): void; } export function createAttemptDeliverySummary(): AttemptDeliverySummary { @@ -88,6 +89,38 @@ export function classifyRelayedResponseEvent( return observation; } +/** + * What one buffered response body delivered. + * + * A non-streaming turn has no frames: the whole answer reaches the client as one JSON body. Read + * naively that looks like total relay loss -- adapter events counted, nothing relayed -- which is + * precisely the signal these counters exist to raise, so a buffered response would raise it on + * every request and make it worthless. Everything the adapter produced DID reach the client here; + * it arrived in one piece. So the relayed total is set to the adapter total rather than left at + * zero, and the semantic facts are read from the body that was built. + * + * Fields are read defensively and by name. Keying this on the adapter event union would make a + * member added later a merge-time exhaustiveness failure in a counter that does not need one. + */ +function observeBufferedBody(body: Record): { semanticBytes: number; sideEffects: number } { + const output = Array.isArray(body.output) ? body.output : []; + let semanticBytes = 0; + let sideEffects = 0; + for (const entry of output) { + if (entry === null || typeof entry !== "object") continue; + const item = entry as Record; + if (typeof item.type === "string" && SIDE_EFFECT_ITEM_TYPES.has(item.type)) sideEffects += 1; + if (typeof item.arguments === "string") semanticBytes += Buffer.byteLength(item.arguments, "utf8"); + const content = Array.isArray(item.content) ? item.content : []; + for (const part of content) { + if (part === null || typeof part !== "object") continue; + const text = (part as Record).text; + if (typeof text === "string") semanticBytes += Buffer.byteLength(text, "utf8"); + } + } + return { semanticBytes, sideEffects }; +} + const recordersByScope = new WeakMap(); /** @@ -120,6 +153,15 @@ export function bindAttemptDeliveryRecorder( if (observation?.sideEffect) summary.sideEffectEvents = bump(summary.sideEffectEvents, 1); if (observation?.terminal) summary.terminalEvents = bump(summary.terminalEvents, 1); }, + noteBufferedDelivery(body): void { + const summary = summaryFor(); + if (!summary) return; + const observed = observeBufferedBody(body); + summary.relayedEvents = Math.max(summary.relayedEvents, summary.adapterEvents); + summary.semanticBytes = bump(summary.semanticBytes, observed.semanticBytes); + summary.sideEffectEvents = bump(summary.sideEffectEvents, observed.sideEffects); + summary.terminalEvents = bump(summary.terminalEvents, 1); + }, }; recordersByScope.set(scope, recorder); return recorder; diff --git a/src/usage/log.ts b/src/usage/log.ts index 88a74cbbff6..6955db2073a 100644 --- a/src/usage/log.ts +++ b/src/usage/log.ts @@ -24,6 +24,7 @@ import { ATTEMPT_RECOVERY_WITHHELD_ROSTER, REQUEST_FAILURE_CAUSES, REQUEST_FAILURE_STAGES, + REQUEST_TRANSPORT_PHASES, type AttemptRecoveryKind, type AttemptRecoveryWithheld, type AttemptDeliverySummary, @@ -434,12 +435,10 @@ export function isKnownInboundProtocol(value: unknown): value is NonNullable); } -const KNOWN_TRANSPORT_PHASES = new Set>([ - "pre_headers", "mid_stream", "terminal_sse", -]); +const KNOWN_TRANSPORT_PHASES: ReadonlySet = new Set(REQUEST_TRANSPORT_PHASES); export function isKnownTransportPhase(value: unknown): value is NonNullable { - return typeof value === "string" && KNOWN_TRANSPORT_PHASES.has(value as NonNullable); + return typeof value === "string" && KNOWN_TRANSPORT_PHASES.has(value); } const KNOWN_TERMINAL_SOURCES = new Set>([ diff --git a/src/usage/telemetry-contract.ts b/src/usage/telemetry-contract.ts index 790bfc2bac9..ff8a0e08901 100644 --- a/src/usage/telemetry-contract.ts +++ b/src/usage/telemetry-contract.ts @@ -167,6 +167,21 @@ export const RESEND_PERMISSIONS = Object.freeze([ export type ResendPermission = typeof RESEND_PERMISSIONS[number]; +/** + * Where a terminal or failure was observed on the wire. + * + * Declared here because three modules read it as a closed set -- the durable row's validator, + * the failure attribution and the failure fingerprint -- and a fourth restatement in a test is + * how a member added later leaves an "exhaustive" cross product green without exercising it. + */ +export const REQUEST_TRANSPORT_PHASES = Object.freeze([ + "pre_headers", + "mid_stream", + "terminal_sse", +] as const); + +export type RequestTransportPhase = typeof REQUEST_TRANSPORT_PHASES[number]; + /** * What an attempt actually delivered, as five bounded counts (#3983). * diff --git a/structure/overview.md b/structure/overview.md index 3f007f7b32f..1936771b764 100644 --- a/structure/overview.md +++ b/structure/overview.md @@ -145,10 +145,14 @@ still cover the rule, which is a judgement only review makes. automatically permits a resend, and a cause whose upstream execution state is unknown is not made replayable by having budget left. A refusal names which of the three refusals it is. The decision is derived from per-stage and per-cause facts rather than written out as a stage-by-cause matrix, so a - new member cannot leave a stale cell. `src/lib/request-failure-attribution.ts` derives the pair from - closed recorder facts and never from `errorCode` or `upstreamError`, which are open strings; the - resend verdict is computed at read time and never persisted. - Enforced by `tests/lib/failure-stage-model.test.ts` and `tests/lib/failure-attribution.test.ts`. + new member cannot leave a stale cell. + Enforced by `tests/lib/failure-stage-model.test.ts`. +- **INV-ATTRIBUTION-01** — `src/lib/request-failure-attribution.ts` derives the persisted failure + stage and cause from closed recorder facts only, never from `errorCode` or `upstreamError`, which + are assembled partly from upstream text. An unknown upstream execution state is attributed to a + cause that refuses an automatic resend rather than to one that permits it, and the resend verdict + the pair implies is computed at read time and never persisted. + Enforced by `tests/lib/failure-attribution.test.ts`. CI enumerates that domain layout through `scripts/ci/run-bun-test-batches.sh`. Its default general scope and 12-file/120-second process shape leave the dedicated Linux storage-policy and api-usage diff --git a/tests/lib/failure-attribution.test.ts b/tests/lib/failure-attribution.test.ts index 8ff5e393470..8b8b438d2a7 100644 --- a/tests/lib/failure-attribution.test.ts +++ b/tests/lib/failure-attribution.test.ts @@ -13,11 +13,19 @@ import { stageCommitment, } from "../../src/lib/request-failure-model"; import { ATTEMPT_RECOVERY_KIND_ROSTER } from "../../src/usage/telemetry-contract"; -import { REQUEST_OUTCOME_CLASSES, classifyRequestOutcome } from "../../src/usage/request-outcome"; +import { + REQUEST_CLOSE_REASONS, + REQUEST_OUTCOME_CLASSES, + REQUEST_TERMINAL_STATUSES, + classifyRequestOutcome, +} from "../../src/usage/request-outcome"; +import { REQUEST_TRANSPORT_PHASES } from "../../src/usage/telemetry-contract"; /** * The fact space this derivation is total over. * + * Holds INV-ATTRIBUTION-01 from structure/overview.md. + * * Every axis is read from the module that declares it rather than restated, so a member added to * a roster widens this cross product instead of leaving a case nobody wrote. The status list is * the one axis that cannot be derived -- HTTP statuses are not a roster this repository owns -- @@ -25,9 +33,12 @@ import { REQUEST_OUTCOME_CLASSES, classifyRequestOutcome } from "../../src/usage * boundary values (`0`, no head at all, and `499`) that decide a branch on their own. */ const STATUSES = [0, 101, 200, 400, 401, 403, 413, 429, 451, 499, 500, 502, 503] as const; -const TERMINAL_STATUSES = [undefined, "completed", "failed", "incomplete"] as const; -const CLOSE_REASONS = [undefined, "terminal", "client_cancel", "non_stream", "body_stall", "body_overflow"] as const; -const TRANSPORT_PHASES = [undefined, "pre_headers", "mid_stream", "terminal_sse"] as const; +// Read from the modules that declare them, so a member added later widens this space instead of +// leaving a case nobody wrote. Restating them is what let the recovery roster drift to nine of +// thirteen while every test stayed green. +const TERMINAL_STATUSES = [undefined, ...REQUEST_TERMINAL_STATUSES] as const; +const CLOSE_REASONS = [undefined, ...REQUEST_CLOSE_REASONS] as const; +const TRANSPORT_PHASES = [undefined, ...REQUEST_TRANSPORT_PHASES] as const; function* factSpace(): Generator { for (const status of STATUSES) { diff --git a/tests/usage/request-outcome-agreement.test.ts b/tests/usage/request-outcome-agreement.test.ts index 3d48ace90fe..f741dd86a66 100644 --- a/tests/usage/request-outcome-agreement.test.ts +++ b/tests/usage/request-outcome-agreement.test.ts @@ -3,6 +3,8 @@ import { readFileSync } from "node:fs"; import { repoPath } from "../helpers/repo-root"; import { REQUEST_OUTCOME_CLASSES, + REQUEST_CLOSE_REASONS, + REQUEST_TERMINAL_STATUSES, classifyRequestOutcome, requestPhysicalSends, requestSettledSends, @@ -34,11 +36,13 @@ function sampleValue(snapshot: string, series: string): number { return line === undefined ? Number.NaN : Number(line.slice(series.length + 1)); } -/** Every combination a terminal can arrive in, built from the declared vocabularies. */ -const TERMINAL_STATUSES = [undefined, "completed", "failed", "incomplete"] as const; -const CLOSE_REASONS = [ - undefined, "terminal", "client_cancel", "non_stream", "body_stall", "body_overflow", -] as const; +/** + * Every combination a terminal can arrive in, read from the modules that declare them rather + * than written out. A restated list is how a member added later leaves this cross product green + * without ever being exercised. + */ +const TERMINAL_STATUSES = [undefined, ...REQUEST_TERMINAL_STATUSES] as const; +const CLOSE_REASONS = [undefined, ...REQUEST_CLOSE_REASONS] as const; const STATUSES = [101, 200, 204, 399, 400, 429, 499, 500, 502] as const; describe("terminal classification is stated once", () => { diff --git a/tests/usage/usage-attempt-delivery.test.ts b/tests/usage/usage-attempt-delivery.test.ts index 980f0466ea9..f5681baf7a2 100644 --- a/tests/usage/usage-attempt-delivery.test.ts +++ b/tests/usage/usage-attempt-delivery.test.ts @@ -125,4 +125,37 @@ describe("attempt delivery summary", () => { expect(serialized).not.toContain("private"); expect(Object.values(target.deliverySummary!).every(value => typeof value === "number")).toBe(true); }); + + test("a buffered response does not read as total relay loss", () => { + const target: AttemptDeliveryTarget = {}; + const recorder = bindAttemptDeliveryRecorder({}, () => target); + for (let index = 0; index < 4; index += 1) recorder.noteAdapterEvent(); + // Nothing calls the per-frame recorder on a non-streaming turn: the whole answer arrives as + // one body. Left at zero, every buffered request would raise the adapter-to-client loss + // signal these counters exist for. + recorder.noteBufferedDelivery({ + output: [ + { type: "message", content: [{ type: "output_text", text: "hello" }] }, + { type: "function_call", name: "lookup", arguments: "{}" }, + ], + }); + expect(target.deliverySummary).toEqual({ + adapterEvents: 4, + relayedEvents: 4, + semanticBytes: 7, + sideEffectEvents: 1, + terminalEvents: 1, + }); + }); + + test("a buffered body contributes counts and never its text", () => { + const target: AttemptDeliveryTarget = {}; + const recorder = bindAttemptDeliveryRecorder({}, () => target); + recorder.noteAdapterEvent(); + recorder.noteBufferedDelivery({ + output: [{ type: "message", content: [{ type: "output_text", text: "a private answer" }] }], + }); + expect(JSON.stringify(target.deliverySummary)).not.toContain("private"); + expect(target.deliverySummary!.semanticBytes).toBe(16); + }); }); From fa106585c23d251ca5250e5cc602b21694fcf304 Mon Sep 17 00:00:00 2001 From: JUN Date: Sun, 20 Sep 2026 23:09:38 +0900 Subject: [PATCH 08/10] refactor(server): move failure attribution out of request-log.ts The file-size ratchet reported NEW_OVERSIZED on the first exact-head run. src/server/request-log.ts carries the whole request-logging surface and was 1,962 lines against the repository's 2,000-line seed threshold; the attribution wiring pushed it to 2,015. The remedy is a move, never a number: the cap only ever goes down, and a threshold is not something to negotiate with. The two places a stage and cause are decided and written -- the finalization seam, and the attempt sealed by a key-account rotation -- now live in src/server/request-log-failure-attribution.ts. Behaviour is unchanged: the same facts go in, the same attempt is stamped before the snapshot, and the same pair reaches the row. request-log.ts is 1,979 lines after the move. That is 21 lines of headroom, which the lane record notes for whoever touches this file next. --- .../260920_round2_followups/050_lane_r5.md | 11 +++ src/server/request-log-failure-attribution.ts | 99 +++++++++++++++++++ src/server/request-log.ts | 52 ++-------- 3 files changed, 118 insertions(+), 44 deletions(-) create mode 100644 src/server/request-log-failure-attribution.ts diff --git a/devlog/_plan/260920_round2_followups/050_lane_r5.md b/devlog/_plan/260920_round2_followups/050_lane_r5.md index 47202b886c0..7343408d0cf 100644 --- a/devlog/_plan/260920_round2_followups/050_lane_r5.md +++ b/devlog/_plan/260920_round2_followups/050_lane_r5.md @@ -147,6 +147,17 @@ matters when `truncate` has also failed, and the temp is owner-only. It predates affects every atomic config write, including secret-bearing ones, so fixing it is a change to a security-adjacent path that belongs in its own lane rather than inside a telemetry branch. +## The file-size ratchet caught this branch once + +`src/server/request-log.ts` carries the whole request-logging surface and was 1,962 lines against +the repository's 2,000-line seed threshold. The attribution wiring pushed it to 2,015, and +`file-size ratchet: repository` reported `NEW_OVERSIZED` on the first exact-head run. The remedy is +the one AGENTS.md gives — a move, never a number — so the two places a stage and cause are decided +and written moved to `src/server/request-log-failure-attribution.ts`, leaving the file at 1,979. + +Worth recording for the next lane that touches this file: 21 lines of headroom is not much, and +the cap only ever moves down. + ## Verification Static source review plus exact-head hosted CI, and three adversarial reviews at high effort diff --git a/src/server/request-log-failure-attribution.ts b/src/server/request-log-failure-attribution.ts new file mode 100644 index 00000000000..9a22e0ba8bb --- /dev/null +++ b/src/server/request-log-failure-attribution.ts @@ -0,0 +1,99 @@ +/** + * Where a request's failure attribution is derived and stamped. + * + * A sibling of `request-log.ts` rather than a section inside it. That file carries the whole + * request-logging surface and sits against the 2,000-line repository ceiling, which only ever + * moves down; this is the extraction that rule asks for, not a cap that was negotiated. + * + * It holds the two places a stage and cause are decided and written. Both read the recorder's + * own closed facts and neither reads `errorCode` or `upstreamError`, which are assembled partly + * from upstream text. + */ +import { deriveRequestFailureAttribution } from "../lib/request-failure-attribution"; +import { causeForRecoveryKind } from "../lib/request-failure-model"; +import type { AttemptRecoveryKind, PersistedUsageAttempt, RequestFailureCause, RequestFailureStage } from "../usage/log"; +import type { ResponsesTerminalStatus } from "../bridge"; + +/** The subset of the log context this derivation may see. Narrow on purpose. */ +export interface FinalRequestAttributionFacts { + readonly status: number; + readonly terminalStatus?: ResponsesTerminalStatus | undefined; + readonly closeReason?: "terminal" | "client_cancel" | "non_stream" | "body_stall" | "body_overflow" | undefined; + readonly transportPhase?: "pre_headers" | "mid_stream" | "terminal_sse" | undefined; + readonly terminalSource?: "upstream" | "synthetic" | undefined; + /** The REQUEST's first-output observation, not the final attempt's. See below. */ + readonly outputObserved: boolean; + readonly locallyAnswered: boolean; + readonly attempt?: PersistedUsageAttempt | undefined; +} + +export interface StampedAttribution { + failureStage?: RequestFailureStage; + failureCause?: RequestFailureCause; +} + +/** + * Derive the attribution for a finished logical request and stamp the attempt that ended it. + * + * Called from the one seam every request passes exactly once, and BEFORE the attempt snapshot, + * so the row that reaches disk and the live attempt object carry the same pair. Deriving it at + * each transport's own exit would give the same request a different attribution per transport, + * which is the disagreement the shared terminal classifier already removed once. + * + * `outputObserved` is the request's observation rather than the final attempt's. A request that + * relayed output on its first attempt and then failed over has committed that output to the + * caller whatever the last attempt saw, so the logical row and the attempt that ended it carry + * the same answer. Reading the attempt-local value would produce a MORE permissive resend verdict + * for exactly that case, and a permission decision has to fail in the safe direction. + */ +export function attributeFinalRequest(facts: FinalRequestAttributionFacts): StampedAttribution { + const attribution = deriveRequestFailureAttribution({ + status: facts.status, + ...(facts.terminalStatus ? { terminalStatus: facts.terminalStatus } : {}), + ...(facts.closeReason ? { closeReason: facts.closeReason } : {}), + ...(facts.transportPhase ? { transportPhase: facts.transportPhase } : {}), + ...(facts.terminalSource ? { terminalSource: facts.terminalSource } : {}), + ...(facts.attempt?.streamAborted === true ? { streamAborted: true } : {}), + outputObserved: facts.outputObserved, + // The one fact that can raise a stage above `semantic-output`, and the reason it is counted + // at the transport rather than at the adapter: an emitted tool call the client never + // received has committed nothing, and a resend for it is still safe (#3983). + sideEffectObserved: (facts.attempt?.deliverySummary?.sideEffectEvents ?? 0) > 0, + locallyAnswered: facts.locallyAnswered, + recoveryKinds: facts.attempt?.recoveryKinds ?? [], + }); + // The final row and the attempt that ended it describe the same exchange, so they carry the + // same pair rather than each deriving one from a different slice of the facts. + if (facts.attempt) { + if (attribution?.stage) facts.attempt.failureStage = attribution.stage; + else delete facts.attempt.failureStage; + if (attribution?.cause) facts.attempt.failureCause = attribution.cause; + else delete facts.attempt.failureCause; + } + return { + ...(attribution?.stage ? { failureStage: attribution.stage } : {}), + ...(attribution?.cause ? { failureCause: attribution.cause } : {}), + }; +} + +/** + * Attribute an attempt being sealed because a named recovery rejected it. + * + * The recovery kind is direct evidence here rather than an inference from history: this attempt + * is ending precisely because that recovery was needed. Without it the sealed attempt would reach + * the ledger with no attribution at all, because the finalization seam only ever sees the last + * attempt of a request. + */ +export function attributeSealedAttempt( + attempt: PersistedUsageAttempt, + recovery: AttemptRecoveryKind | undefined, +): void { + const attribution = deriveRequestFailureAttribution({ + status: attempt.status, + outputObserved: attempt.firstOutputMs !== undefined, + sideEffectObserved: (attempt.deliverySummary?.sideEffectEvents ?? 0) > 0, + ...(recovery ? { causeHint: causeForRecoveryKind(recovery) } : {}), + }); + if (attribution?.stage) attempt.failureStage = attribution.stage; + if (attribution?.cause) attempt.failureCause = attribution.cause; +} diff --git a/src/server/request-log.ts b/src/server/request-log.ts index cc6866a8dbb..ac1ad98270d 100644 --- a/src/server/request-log.ts +++ b/src/server/request-log.ts @@ -58,8 +58,7 @@ import { type UsageStatus, } from "../usage/log"; import type { RequestExecutionBudget } from "../lib/request-execution-budget"; -import { deriveRequestFailureAttribution } from "../lib/request-failure-attribution"; -import { causeForRecoveryKind } from "../lib/request-failure-model"; +import { attributeFinalRequest, attributeSealedAttempt } from "./request-log-failure-attribution"; import { debugAttemptDeliverySummary } from "../lib/debug"; import { appendUsageDebug, @@ -1405,45 +1404,18 @@ export function addFinalRequestLog( if (errorCode) logCtx.activeAttempt.errorCode = errorCode; else delete logCtx.activeAttempt.errorCode; } - // Derived once, here, because this is the one seam every request passes exactly once however - // it ended. Deriving it at each transport's own exit would give the same request a different - // attribution per transport, which is the disagreement the shared terminal classifier already - // removed once. It runs BEFORE the attempt snapshot below, so the row that reaches disk and - // the live attempt object carry the same pair rather than one of them being stamped too late. - // - // Every input is a closed value. `errorCode` and `upstreamError` are deliberately not read: - // both are assembled partly from upstream text, so a classification keyed on them varies by - // provider and locale, and a grouping key built from them cannot promise it carries no content. - const attribution = deriveRequestFailureAttribution({ + // Derived and stamped in a sibling module, before the attempt snapshot below. Every input is + // a closed value; the open error strings are deliberately not among them. + const attribution = attributeFinalRequest({ status: effectiveStatus, ...(meta?.terminalStatus ? { terminalStatus: meta.terminalStatus } : {}), ...(closeReason ? { closeReason } : {}), ...(logCtx.transportPhase ? { transportPhase: logCtx.transportPhase } : {}), ...(logCtx.terminalSource ? { terminalSource: logCtx.terminalSource } : {}), - ...(logCtx.activeAttempt?.streamAborted === true ? { streamAborted: true } : {}), - // The REQUEST's output observation, not the final attempt's. - // - // A request that relayed output on its first attempt and then failed over has committed - // that output to the caller whatever the last attempt saw, so the logical row and the - // attempt that ended it carry the same answer. Reading the attempt-local value here would - // produce a MORE permissive resend verdict for exactly that case, and a permission - // decision has to fail in the safe direction. outputObserved: logCtx.firstOutputMs !== undefined, - // The one fact that can raise a stage above `semantic-output`, and the reason it is - // counted at the transport rather than at the adapter: an emitted tool call the client - // never received has committed nothing, and a resend for it is still safe (#3983). - sideEffectObserved: (logCtx.activeAttempt?.deliverySummary?.sideEffectEvents ?? 0) > 0, locallyAnswered: logCtx.localTerminalReason !== undefined, - recoveryKinds: logCtx.activeAttempt?.recoveryKinds ?? [], + ...(logCtx.activeAttempt ? { attempt: logCtx.activeAttempt } : {}), }); - // The final row and the attempt that ended it describe the same exchange, so they carry the - // same pair rather than each deriving one from a different slice of the facts. - if (logCtx.activeAttempt) { - if (attribution?.stage) logCtx.activeAttempt.failureStage = attribution.stage; - else delete logCtx.activeAttempt.failureStage; - if (attribution?.cause) logCtx.activeAttempt.failureCause = attribution.cause; - else delete logCtx.activeAttempt.failureCause; - } // 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. @@ -1482,7 +1454,7 @@ export function addFinalRequestLog( ...(closeReason ? { closeReason } : {}), ...(attempts !== undefined ? { attempts } : {}), ...(spend ? { spendSends: spend.sends } : {}), - ...(attribution?.cause ? { failureCause: attribution.cause } : {}), + ...(attribution.failureCause ? { failureCause: attribution.failureCause } : {}), }); const cacheProvenance = classifyCacheTelemetryProvenance(loggedUsage, { wireParsed: logCtx.usageWireParsed === true, @@ -1573,8 +1545,7 @@ export function addFinalRequestLog( ...(logCtx.terminalSource ? { terminalSource: logCtx.terminalSource } : {}), ...(logCtx.routeDecision ? { routeDecision: logCtx.routeDecision } : {}), ...(claudeCompatibility ? { claudeCompatibility } : {}), - ...(attribution?.stage ? { failureStage: attribution.stage } : {}), - ...(attribution?.cause ? { failureCause: attribution.cause } : {}), + ...attribution, }); // Formatted from the finalized snapshot, so the ring shows exactly what the ledger holds. for (const attempt of attempts ?? []) debugAttemptDeliverySummary(requestId, attempt); @@ -1828,14 +1799,7 @@ export function noteProviderAttemptSend( // is direct evidence here rather than an inference from history. Without this the sealed // attempt would reach the ledger with no attribution at all: the finalization seam below // only ever sees the last attempt of the request. - const sealedAttribution = deriveRequestFailureAttribution({ - status: attempt.status, - outputObserved: attempt.firstOutputMs !== undefined, - sideEffectObserved: (attempt.deliverySummary?.sideEffectEvents ?? 0) > 0, - ...(recovery ? { causeHint: causeForRecoveryKind(recovery) } : {}), - }); - if (sealedAttribution?.stage) attempt.failureStage = sealedAttribution.stage; - if (sealedAttribution?.cause) attempt.failureCause = sealedAttribution.cause; + attributeSealedAttempt(attempt, recovery); const completed = { ...attempt, recoveryKinds: [...attempt.recoveryKinds], ...(attempt.usage ? { usage: { ...attempt.usage } } : {}), ...(attempt.deliverySummary ? { deliverySummary: { ...attempt.deliverySummary } } : {}), From 9e09698ab623e2890a6895198c9d87fea475297d Mon Sep 17 00:00:00 2001 From: JUN Date: Sun, 20 Sep 2026 23:24:56 +0900 Subject: [PATCH 09/10] fix(metrics): derive the exposition counts instead of restating them Three exact-head failures, all from the new failure-cause counter and all in assertions that counted by hand. management-metrics-export.test.ts already derives its sample total from the closed vocabularies -- its own comment says the literal "went stale the moment a bounded label value was added, which is the failure mode this repository keeps hitting in merges". The new counter's contribution is added to that arithmetic the same way. Its HELP/TYPE assertion was the literal 7 the comment warns about, so it now reads the metric names out of the exposition and asserts the two groups name the same set exactly once each, which is what deterministic grouping means and what no added metric can make stale. The dashboard-union assertion matched the literal string "import type { AttemptRecoveryKind", which broke when the import wrapped across lines to take the three new names. It now matches the property it was testing -- the name arrives from the contract leaf and the page declares no union of its own -- without depending on how the import is formatted. The public metrics table in the management-API reference gains the new series. --- .../src/content/docs/reference/management-api.md | 1 + tests/server/management-metrics-export.test.ts | 15 +++++++++++---- tests/usage/request-outcome-agreement.test.ts | 4 +++- 3 files changed, 15 insertions(+), 5 deletions(-) diff --git a/docs-site/src/content/docs/reference/management-api.md b/docs-site/src/content/docs/reference/management-api.md index 6dbf08fd9d8..9a91de21711 100644 --- a/docs-site/src/content/docs/reference/management-api.md +++ b/docs-site/src/content/docs/reference/management-api.md @@ -285,6 +285,7 @@ boundary. Histogram buckets are cumulative and end with `le="+Inf"`, equal to th | `opencodex_logical_requests_total` | `protocol`, `result` | One observation per finalized logical request. | | `opencodex_physical_sends_total` | `protocol` | Actual upstream sends summed from finalized attempts. | | `opencodex_recoveries_total` | `protocol`, `recovery` | Distinct recovery kinds observed per attempt, projected to a closed class. | +| `opencodex_request_failures_total` | `protocol`, `cause` | Finalized requests that did not deliver an answer, by the cause the recorder derived. Counter only; no histogram carries a cause. | | `opencodex_request_duration_seconds` | `protocol`, `result` | Fixed-bucket duration histogram for finalized requests. | | `opencodex_ttft_seconds` | `protocol`, `result` | Fixed-bucket TTFT histogram for requests with observed first output. | | `opencodex_ttft_missing_total` | `protocol`, `result` | Complementary count for requests without observed TTFT. | diff --git a/tests/server/management-metrics-export.test.ts b/tests/server/management-metrics-export.test.ts index 9759a2d91b0..560874e661b 100644 --- a/tests/server/management-metrics-export.test.ts +++ b/tests/server/management-metrics-export.test.ts @@ -21,6 +21,7 @@ import { REQUEST_DURATION_BUCKETS_SECONDS, REQUEST_METRICS_PROTOCOLS, REQUEST_METRICS_RECOVERY_CLASSES, + REQUEST_METRICS_FAILURE_CAUSES, REQUEST_METRICS_RESULTS, REQUEST_TTFT_BUCKETS_SECONDS, } from "../../src/server/request-metrics"; @@ -462,6 +463,7 @@ describe("request metrics aggregation", () => { cells + REQUEST_METRICS_PROTOCOLS.length + REQUEST_METRICS_PROTOCOLS.length * REQUEST_METRICS_RECOVERY_CLASSES.length + + REQUEST_METRICS_PROTOCOLS.length * REQUEST_METRICS_FAILURE_CAUSES.length + cells * perHistogram(REQUEST_DURATION_BUCKETS_SECONDS) + cells * perHistogram(REQUEST_TTFT_BUCKETS_SECONDS) + cells @@ -480,10 +482,15 @@ describe("request metrics aggregation", () => { .toBeLessThan(output.indexOf("opencodex_request_duration_seconds_bucket")); const helpLines = output.split("\n").filter(line => line.startsWith("# HELP ")); const typeLines = output.split("\n").filter(line => line.startsWith("# TYPE ")); - expect(helpLines).toHaveLength(7); - expect(typeLines).toHaveLength(7); - expect(new Set(helpLines.map(line => line.split(" ")[2])).size).toBe(7); - expect(new Set(typeLines.map(line => line.split(" ")[2])).size).toBe(7); + // Every metric name the exporter emits, read from the exposition rather than counted by + // hand: the literal was correct until a metric was added, which is the same staleness the + // sample arithmetic above avoids. + const metricNames = new Set(helpLines.map(line => line.split(" ")[2])); + expect(helpLines).toHaveLength(metricNames.size); + expect(typeLines).toHaveLength(metricNames.size); + expect(new Set(typeLines.map(line => line.split(" ")[2]))).toEqual(metricNames); + // Each name appears exactly once in each group, which is what deterministic grouping means. + expect(helpLines.length).toBeGreaterThan(REQUEST_METRICS_PROTOCOLS.length); expect(sampleValue(output, 'opencodex_request_duration_seconds_bucket{protocol="responses",result="completed",le="+Inf"}')) .toBe(sampleValue(output, 'opencodex_request_duration_seconds_count{protocol="responses",result="completed"}')); expect(metrics.snapshot()).toBe(output); diff --git a/tests/usage/request-outcome-agreement.test.ts b/tests/usage/request-outcome-agreement.test.ts index f741dd86a66..7b1b49dbf65 100644 --- a/tests/usage/request-outcome-agreement.test.ts +++ b/tests/usage/request-outcome-agreement.test.ts @@ -191,7 +191,9 @@ describe("the dashboard recovery roster cannot drift from the durable one", () = test("the page derives the union rather than restating it", () => { const page = readFileSync(repoPath("gui", "src", "pages", "Logs.tsx"), "utf8"); - expect(page).toContain("import type { AttemptRecoveryKind"); + // Matched without depending on how the import is wrapped: the property is that the name + // arrives from the contract leaf, not that it sits first on a single line. + expect(/import type \{[^}]*\bAttemptRecoveryKind\b[^}]*\}\s*from\s*"[^"]*usage\/telemetry-contract"/s.test(page)).toBe(true); expect(page).not.toContain('type AttemptRecoveryKind ='); }); From 714ddbf7e2794554db6487722617daaa0c2906c6 Mon Sep 17 00:00:00 2001 From: JUN Date: Sun, 20 Sep 2026 23:26:00 +0900 Subject: [PATCH 10/10] fix(config): assert every temp writer keeps exclusive creation, not two of them The streamed writer added a third openSync(path, "wx", 0o600) and the portability test counted exactly two. The count was the weaker form of what it meant: the property is that no temp writer in atomic-write.ts drops the O_CREAT bit, and that holds for however many writers exist. It is now a set comparison over every openSync on the temp path, which a fourth writer cannot make stale and an unsafe spelling cannot pass. The edit is line-neutral because that file sits exactly at its ratchet cap. --- tests/windows/windows-secret-acl.test.ts | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/tests/windows/windows-secret-acl.test.ts b/tests/windows/windows-secret-acl.test.ts index 29d1b7bc3f9..a5a2f379c54 100644 --- a/tests/windows/windows-secret-acl.test.ts +++ b/tests/windows/windows-secret-acl.test.ts @@ -636,11 +636,11 @@ describe("atomic secret temp writer portability", () => { test("sync and async secret temp writers use Bun-portable exclusive creation", async () => { // Bun on Windows misinterpreted the equivalent numeric O_* combination as // ENOENT, so every pid/config/oauth temp write failed during ocx start - // and on management-API config saves. Keep both writers on the portable - // exclusive-write spelling ("wx" keeps O_EXCL; 0o600 keeps the private - // mode) so the O_CREAT bit can never be dropped again. + // and on management-API config saves. EVERY temp writer keeps the portable + // exclusive spelling ("wx" keeps O_EXCL; 0o600 keeps the private mode); a + // count would go stale the next time a writer is added, so this is a set. const src = readFileSync(repoPath("src", "config", "atomic-write.ts"), "utf8"); - expect(src.match(/openSync\(path, "wx", 0o600\)/g)).toHaveLength(2); + expect(new Set(src.match(/openSync\(path,[^)]*\)/g) ?? [])).toEqual(new Set(['openSync(path, "wx", 0o600)'])); }); });