From 7e0b07017194bd3c0ec9107e1dfadf7c9e63acad Mon Sep 17 00:00:00 2001 From: yuanyuanlove Date: Wed, 21 Oct 2026 21:02:06 +0800 Subject: [PATCH] fix(usage): preserve source-aware cache evidence across attempts --- .../content/docs/guides/codex-integration.md | 11 + scripts/test-layout/layout.json | 2 +- src/adapters/anthropic.ts | 2 + src/adapters/openai-responses/passthrough.ts | 6 +- src/server/relay.ts | 7 +- src/server/request-log.ts | 177 ++++++----- src/server/responses/advisor-retention.ts | 19 +- src/server/responses/compact.ts | 2 +- src/server/responses/compaction-recovery.ts | 3 +- .../responses/empty-completion-guard.ts | 26 +- src/server/responses/native-steering-log.ts | 28 +- .../responses/passthrough-completion.ts | 2 +- src/server/responses/passthrough-delivery.ts | 5 +- src/server/responses/request-transport.ts | 2 + src/server/responses/terminal-guard.ts | 23 +- src/types/request.ts | 15 + src/usage/cache-diagnostic.ts | 17 +- src/usage/cache-telemetry.ts | 179 +++++++++++ src/usage/log.ts | 31 +- src/usage/summary.ts | 51 +-- src/web-search/loop.ts | 36 ++- structure/advisor.md | 2 +- structure/dashboard-and-usage.md | 20 +- structure/providers-and-adapters.md | 2 + structure/providers/opengateway.md | 2 +- structure/transports/responses.md | 2 +- structure/transports/streaming-health.md | 2 +- .../anthropic-cache-evidence.test.ts | 41 +++ .../anthropic-error-stop-reason.test.ts | 3 +- .../anthropic-thinking-usage.test.ts | 4 +- .../advisor-cache-evidence-retention.test.ts | 63 ++++ tests/advisor/advisor-retention.test.ts | 8 +- tests/fixtures/test-layout-expected.json | 2 +- tests/responses/cache-telemetry-flow.test.ts | 259 +++++++++++++++ .../cache-telemetry-guard-mergers.test.ts | 77 +++++ tests/responses/cache-telemetry-http.test.ts | 300 ++++++++++++++++++ .../cache-telemetry-native-seams.test.ts | 210 ++++++++++++ .../responses/empty-completion-guard.test.ts | 8 +- tests/server/terminal-guard.test.ts | 6 +- tests/usage/cache-diagnostic.test.ts | 4 +- tests/usage/cache-telemetry-attempts.test.ts | 242 ++++++++++++++ tests/usage/cache-telemetry-evidence.test.ts | 106 +++++++ tests/usage/key-attribution.test.ts | 6 +- tests/usage/request-log.test.ts | 4 +- .../usage-spend-cache-provenance.test.ts | 53 +++- tests/usage/usage-summary.test.ts | 4 +- .../web-search-loop-cache-evidence.test.ts | 107 +++++++ 47 files changed, 1974 insertions(+), 207 deletions(-) create mode 100644 src/usage/cache-telemetry.ts create mode 100644 tests/adapters/anthropic/anthropic-cache-evidence.test.ts create mode 100644 tests/advisor/advisor-cache-evidence-retention.test.ts create mode 100644 tests/responses/cache-telemetry-flow.test.ts create mode 100644 tests/responses/cache-telemetry-guard-mergers.test.ts create mode 100644 tests/responses/cache-telemetry-http.test.ts create mode 100644 tests/responses/cache-telemetry-native-seams.test.ts create mode 100644 tests/usage/cache-telemetry-attempts.test.ts create mode 100644 tests/usage/cache-telemetry-evidence.test.ts create mode 100644 tests/web-search/web-search-loop-cache-evidence.test.ts diff --git a/docs-site/src/content/docs/guides/codex-integration.md b/docs-site/src/content/docs/guides/codex-integration.md index 6dd84dcce22..ec5249d318a 100644 --- a/docs-site/src/content/docs/guides/codex-integration.md +++ b/docs-site/src/content/docs/guides/codex-integration.md @@ -931,6 +931,17 @@ See [The parser and bridge](/reference/architecture/#the-parser) for the explici There is no provider-level setting that can add a missing `tool_search` declaration; ordinary code-mode discovery remains a separate path. +### Cache accounting evidence + +Cache summaries distinguish upstream-reported values from client-compatible defaults. An explicit +upstream zero is measured; an omitted cache counter is unknown. Cache-read and cache-creation +counts remain separate, and a missing round or sent attempt cannot become observed merely because +other rounds reported usage. Unsent candidates without usage do not dilute the aggregate. +Only complete observed cache reads contribute to the hit-rate numerator and its matching input +denominator. Partial totals can remain visible without implying a measured hit rate; historical +zero-only records without source evidence remain unknown. These are accounting corrections, not +a measured performance improvement. + ### Cache-read diagnostics Set `OPENCODEX_CACHE_DEBUG=1` before starting the proxy to write one diagnostic record per diff --git a/scripts/test-layout/layout.json b/scripts/test-layout/layout.json index 60eee142abe..7bc42ce6e94 100644 --- a/scripts/test-layout/layout.json +++ b/scripts/test-layout/layout.json @@ -2,7 +2,7 @@ "version": 1, "root": "tests", "explicitShards": ["layout-clients.json", "layout-codex-collision.json"], - "explicit": { "combo-description.test.ts": "routing", "combo-description-catalog.test.ts": "codex-integration", "codex-provider-routing.test.ts": "codex-integration", "config-native-reasoning-retention.test.ts": "config", "server-native-reasoning-retention-merge.test.ts": "server", "server-native-reasoning-retention.test.ts": "server", "responses-retained-reasoning-stream-recovery.test.ts": "responses", "openai-native-hosted-search-history.test.ts": "adapters/openai", "responses-native-compact-search-history.test.ts": "responses", "config-hosted-search-projection.test.ts": "config", "gcp-credential-boundary.test.ts": "adapters/google", "gcp-sa-marker.test.ts": "adapters/google", "gcp-sa-adapter.test.ts": "adapters/google", "management-gcp-credential-input.test.ts": "server", "codex-preserve-signed-in.test.ts": "codex-integration", "cli-account-preservation.test.ts": "cli", "service-state-isolation.test.ts": "service", "compaction-history-framing.test.ts": "responses", "catalog-native-max-context.test.ts": "codex-integration", "protocol-argon-thought-boundary.test.ts": "responses", "service-log.test.ts": "service", "messages-native-empty-inline.test.ts": "claude-integration", "catalog-auto-review-override.test.ts": "codex-integration", "management-auto-review-settings.test.ts": "server", "management-auto-review-auth.test.ts": "server", "prefer-model-alias-ids.test.ts": "server", "responses-mimo-envelope.test.ts": "responses", "responses-call-id-linkage.test.ts": "responses", "bridge-terminal-refusal.test.ts": "adapters", "loop-terminal-refusal.test.ts": "images", "web-search-terminal-refusal.test.ts": "web-search", "combo-terminal-refusal.test.ts": "routing", "server-terminal-refusal-wiring.test.ts": "server", "incomplete-reason-normalization.test.ts": "responses", "advisor-retention.test.ts": "advisor", "responses-native-key-cooldown.test.ts": "responses", "responses-run-turn-key-readmission.test.ts": "responses", "qoder-spawn-readmission.test.ts": "adapters", "api-key-selection-cooldown.test.ts": "providers", "api-key-auto-pause-distribution.test.ts": "providers", "explicit-key-pause-oauth-boundary.test.ts": "providers", "server-chat-native-key-selection.test.ts": "server", "compact-key-selection.test.ts": "responses", "messages-native-key-selection.test.ts": "claude-integration", + "explicit": { "cache-telemetry-native-seams.test.ts": "responses", "anthropic-cache-evidence.test.ts": "adapters/anthropic", "advisor-cache-evidence-retention.test.ts": "advisor", "cache-telemetry-flow.test.ts": "responses", "cache-telemetry-guard-mergers.test.ts": "responses", "cache-telemetry-http.test.ts": "responses", "cache-telemetry-attempts.test.ts": "usage", "cache-telemetry-evidence.test.ts": "usage", "web-search-loop-cache-evidence.test.ts": "web-search", "combo-description.test.ts": "routing", "combo-description-catalog.test.ts": "codex-integration", "codex-provider-routing.test.ts": "codex-integration", "config-native-reasoning-retention.test.ts": "config", "server-native-reasoning-retention-merge.test.ts": "server", "server-native-reasoning-retention.test.ts": "server", "responses-retained-reasoning-stream-recovery.test.ts": "responses", "openai-native-hosted-search-history.test.ts": "adapters/openai", "responses-native-compact-search-history.test.ts": "responses", "config-hosted-search-projection.test.ts": "config", "gcp-credential-boundary.test.ts": "adapters/google", "gcp-sa-marker.test.ts": "adapters/google", "gcp-sa-adapter.test.ts": "adapters/google", "management-gcp-credential-input.test.ts": "server", "codex-preserve-signed-in.test.ts": "codex-integration", "cli-account-preservation.test.ts": "cli", "service-state-isolation.test.ts": "service", "compaction-history-framing.test.ts": "responses", "catalog-native-max-context.test.ts": "codex-integration", "protocol-argon-thought-boundary.test.ts": "responses", "service-log.test.ts": "service", "messages-native-empty-inline.test.ts": "claude-integration", "catalog-auto-review-override.test.ts": "codex-integration", "management-auto-review-settings.test.ts": "server", "management-auto-review-auth.test.ts": "server", "prefer-model-alias-ids.test.ts": "server", "responses-mimo-envelope.test.ts": "responses", "responses-call-id-linkage.test.ts": "responses", "bridge-terminal-refusal.test.ts": "adapters", "loop-terminal-refusal.test.ts": "images", "web-search-terminal-refusal.test.ts": "web-search", "combo-terminal-refusal.test.ts": "routing", "server-terminal-refusal-wiring.test.ts": "server", "incomplete-reason-normalization.test.ts": "responses", "advisor-retention.test.ts": "advisor", "responses-native-key-cooldown.test.ts": "responses", "responses-run-turn-key-readmission.test.ts": "responses", "qoder-spawn-readmission.test.ts": "adapters", "api-key-selection-cooldown.test.ts": "providers", "api-key-auto-pause-distribution.test.ts": "providers", "explicit-key-pause-oauth-boundary.test.ts": "providers", "server-chat-native-key-selection.test.ts": "server", "compact-key-selection.test.ts": "responses", "messages-native-key-selection.test.ts": "claude-integration", "openai-chat-standalone-bare-block.test.ts": "adapters/openai", "owner-registry-isolation.test.ts": "config", "responses-auto-pause-replay-owner.test.ts": "responses", "responses-account-auto-pause.test.ts": "responses", "oauth-account-auto-pause.test.ts": "oauth", "responses-account-auto-pause-wire-owner.test.ts": "responses", "oauth-upsert-paused-api-key.test.ts": "oauth", "management-account-auto-pause.test.ts": "server", "cli-account-key-pause.test.ts": "cli", "oauth-account-auto-pause-revision.test.ts": "oauth", "config-account-auto-pause-revisions.test.ts": "config", "codex-history-pending-wal.test.ts": "codex-integration", "responses-anthropic-billing-send-budget.test.ts": "responses", "anthropic-billing-ownership.test.ts": "adapters/anthropic", "server-anthropic-billing.test.ts": "server", "server-anthropic-billing-boundaries.test.ts": "server", "router-anthropic-billing-failover.test.ts": "routing", "anthropic-billing-refusal.test.ts": "adapters/anthropic", "messages-request-id-headers.test.ts": "claude-integration", "bounded-file-read.test.ts": "lib", "responses-undeclared-tool-guard-inbound.test.ts": "responses", "explicit-empty-tool-catalog.test.ts": "responses", "explicit-empty-tool-catalog-history.test.ts": "responses", diff --git a/src/adapters/anthropic.ts b/src/adapters/anthropic.ts index aef61bfad9d..d7b2e7c9292 100644 --- a/src/adapters/anthropic.ts +++ b/src/adapters/anthropic.ts @@ -7,6 +7,7 @@ import { createAdapterTierMetadata, type AdapterTierMetadata } from "../provider import { ANTHROPIC_FAST_MODE_BETA, mergeAnthropicBetaHeader } from "../providers/anthropic-fast"; import { createToolCallIdAllocator, type ToolCallIdAllocator } from "./tool-call-id"; import { debugDroppedFrame } from "../lib/debug"; +import { rawCacheTelemetry } from "../usage/cache-telemetry"; import type { AdapterEvent, OcxAssistantMessage, @@ -652,6 +653,7 @@ function usageFromAnthropic(usage: unknown): OcxUsage | undefined { return { inputTokens, outputTokens: output, + cacheTelemetry: rawCacheTelemetry(usage), ...(reasoningOutputTokens !== undefined ? { reasoningOutputTokens } : {}), ...(hasCache ? { cachedInputTokens: read, diff --git a/src/adapters/openai-responses/passthrough.ts b/src/adapters/openai-responses/passthrough.ts index 050686dcc3e..ddb8e6a8375 100644 --- a/src/adapters/openai-responses/passthrough.ts +++ b/src/adapters/openai-responses/passthrough.ts @@ -1,6 +1,7 @@ import { truncationReasonFor } from "../../responses/truncated-stop-reason"; import { normalizeRoutedAgentMessages } from "../routed-agent-messages"; import { frameCompactionHistory } from "../../responses/compaction-history-framing"; +import { rawCacheTelemetry } from "../../usage/cache-telemetry"; import { nameRoutedIdentity, repairIdentityInResponsesBody, stripRoutedIdentity } from "../identity"; import { stripBracketedModelSuffix } from "../openai-chat"; import { normalizeOpenCodeGoAdditionalTools } from "../opencode-go-additional-tools"; @@ -140,12 +141,15 @@ function usageFromResponsesPayload(payload: unknown): OcxUsage | undefined { && key !== "cache_write_1h_tokens")) || (isPlainObject(usage.output_tokens_details) && Object.keys(usage.output_tokens_details).some(key => key !== "reasoning_tokens")); - if (inputTokens === 0 && outputTokens === 0 && !hasExtras) return undefined; + if (inputTokens === 0 && outputTokens === 0 && !hasExtras + && typeof (usage.input_tokens_details as Record | undefined)?.cached_tokens !== "number" + && typeof (usage.input_tokens_details as Record | undefined)?.cache_write_tokens !== "number") return undefined; const inputDetails = isPlainObject(usage.input_tokens_details) ? usage.input_tokens_details : undefined; const outputDetails = isPlainObject(usage.output_tokens_details) ? usage.output_tokens_details : undefined; return { inputTokens, outputTokens, + cacheTelemetry: rawCacheTelemetry(usage), ...(typeof usage.total_tokens === "number" ? { totalTokens: usage.total_tokens } : {}), ...(typeof inputDetails?.cached_tokens === "number" ? { cachedInputTokens: inputDetails.cached_tokens } : {}), ...(typeof inputDetails?.cache_write_tokens === "number" ? { cacheCreationInputTokens: inputDetails.cache_write_tokens } : {}), diff --git a/src/server/relay.ts b/src/server/relay.ts index 133d11d3ae0..8cbed66d763 100644 --- a/src/server/relay.ts +++ b/src/server/relay.ts @@ -1105,6 +1105,8 @@ export type SseInspector = { }; export type SseInspectorHandlers = { + /** True only at the upstream observation seam, before client encoders/defaults. */ + upstreamUsage?: boolean; onTerminal?: (status: ResponsesTerminalStatus, httpStatusOverride?: number) => void; logCtx?: RequestLogContext; onCompletedResponse?: (response: { id?: unknown; output?: unknown; status?: unknown }) => void; @@ -1326,7 +1328,7 @@ export function createSseInspector(handlers: SseInspectorHandlers): SseInspector } } if (!reported && handlers.logCtx) { - inspectResponseLogSsePayloadParsed(handlers.logCtx, payload, parsed); + inspectResponseLogSsePayloadParsed(handlers.logCtx, payload, parsed, handlers.upstreamUsage ? "upstream" : "client"); } // Before any terminal handling: a consumer deciding on the whole turn must observe this // payload even when the terminal snapshot that follows no longer mentions it. @@ -1536,6 +1538,7 @@ export function createSseInspector(handlers: SseInspectorHandlers): SseInspector export type InspectionDrainBounds = { ms: number; bytes: number }; export type InspectionConsumerOptions = { + upstreamUsage?: boolean; clientGoneSignal?: AbortSignal; drainBounds?: Partial; upstream?: AbortController; @@ -1714,6 +1717,7 @@ export function consumeForInspection( onTerminal, logCtx, onCompletedResponse, + upstreamUsage: options?.upstreamUsage, onParsedPayload: payload => { const message = boundedBareUpstreamErrorMessage(payload); if (message !== undefined) bareUpstreamError = message; @@ -1774,6 +1778,7 @@ export function consumeForResponseLogMetadata( logCtx, onCompletedResponse, onParsedPayload: options?.onParsedPayload, + upstreamUsage: options?.upstreamUsage, onFirstOutput, pinCompletedResponseIdToFirstSeen: options?.pinCompletedResponseIdToFirstSeen, }); diff --git a/src/server/request-log.ts b/src/server/request-log.ts index 089e0a8a77a..e2f01fe200b 100644 --- a/src/server/request-log.ts +++ b/src/server/request-log.ts @@ -1,4 +1,6 @@ import { existsSync, readFileSync } from "node:fs"; +import { aggregateCacheTelemetry, finalAttemptUsage, rawCacheTelemetry, withAdapterCacheTelemetry, usageFromResponsesPayload, type UsageObservationSource } from "../usage/cache-telemetry"; +import type { CacheTelemetry } from "../types/request"; import { randomBytes } from "node:crypto"; import { stampApiKeyAccountLabel, usesApiKeyAccount } from "../providers/label"; import { KEY_ACCOUNT_LOG_LABEL_RE } from "../codex/account-label"; @@ -94,6 +96,11 @@ import type { PromptCacheKeySource, } from "../usage/cache-diagnostic"; +// Weak ownership keeps an earlier attempt's raw counter presence out of a later attempt. +const rawCacheObservations = new WeakMap(); +const rawCacheSendBaselines = new WeakMap(); +const cacheIncompletePhysicalAttempts = new WeakSet(); +const unreportedFinalizedUsage = new WeakMap(); const CACHE_DIAGNOSTIC_HOOK = Symbol.for("opencodex.cache-diagnostic.v1"); interface CacheDiagnosticHooks { /** Whether inbound bodies are actually recorded; the hook is registered at import either way. */ @@ -132,9 +139,8 @@ export interface RequestLogContext extends UpstreamErrorDiagnostics { */ executionBudget?: RequestExecutionBudget; /** - * True once usage counts were taken from a response wire rather than reported raw by the - * adapter. It decides cache provenance: the normalizer writes zero-default token-detail - * objects, so an all-zero cache detail from a parsed wire is not a measured cache miss. + * Compatibility marker: usage was parsed from a response wire. Cache provenance is carried + * by usage.cacheTelemetry, not inferred from this flag or from zero-valued counters. */ usageWireParsed?: boolean; /** @@ -279,7 +285,9 @@ export function observeCacheDiagnosticInbound( headers: Headers, source: PromptCacheKeySource, ): void { - const draft = cacheDiagnosticHooks()?.observeInbound(body, headers, source); + const hooks = cacheDiagnosticHooks(); + if (!hooks?.enabled()) return; + const draft = hooks.observeInbound(body, headers, source); if (draft) logCtx.cacheDiagnosticDraft = draft; } @@ -933,7 +941,7 @@ export function catalogModelSupportsServiceTier(modelId: string, serviceTier: st } } -export function applyResponseLogMetadata(logCtx: RequestLogContext, payload: unknown): void { +export function applyResponseLogMetadata(logCtx: RequestLogContext, payload: unknown, usageSource: UsageObservationSource = "client"): void { if (!payload || typeof payload !== "object") return; if (logCtx.observedTerminalStatus === undefined) { const eventType = (payload as { type?: unknown }).type; @@ -964,75 +972,35 @@ export function applyResponseLogMetadata(logCtx: RequestLogContext, payload: unk } else if (Object.prototype.hasOwnProperty.call(source, "service_tier")) { logCtx.activeTierMetadata?.observeResponseServiceTier(serviceTier); } - const usage = usageFromResponsesPayload((source as { usage?: unknown }).usage); + const rawUsage = (source as { usage?: unknown }).usage; + if (usageSource === "upstream" && (Object.hasOwn(source, "usage") + || ["completed", "failed", "incomplete"].includes(String((source as { status?: unknown }).status)) + || ["response.completed", "response.failed", "response.incomplete"].includes(String((payload as { type?: unknown }).type)))) { + rawCacheObservations.set(logCtx.activeAttempt ?? logCtx, rawCacheTelemetry(rawUsage)); + } + const usage = usageFromResponsesPayload(rawUsage, usageSource); + const current = logCtx.activeAttempt ? logCtx.activeAttempt.usage : logCtx.usage; + const original = current?.cacheTelemetry?.source; + // A second pass over client-defaulted values must not replace raw evidence. + if (usageSource === "client" && (original === "upstream" || original === "adapter" || original === "aggregate")) return; if (usage && !logCtx.usageFromBridge) { if (!recordKeyWireAttemptUsage(logCtx, usage)) { logCtx.usage = usage; if (logCtx.activeAttempt) logCtx.activeAttempt.usage = usage; } - // Counts taken off a wire, not reported raw. The zero-default token-detail objects strict - // clients require are indistinguishable here from a measured zero, so the cache detail these - // counts carry is recorded as synthesized rather than as an observed miss. - logCtx.usageWireParsed = true; + logCtx.usageWireParsed = true; // Compatibility marker only, never a provenance decision. + } else if (usageSource === "upstream" && current && !logCtx.usageFromBridge + && (["completed", "failed", "incomplete"].includes(String((source as { status?: unknown }).status)) + || ["response.completed", "response.failed", "response.incomplete"].includes(String((payload as { type?: unknown }).type)))) { + // A final event without usage must not inherit a prior event's cache reading. + const { cachedInputTokens: _cached, cacheReadInputTokens: _read, cacheCreationInputTokens: _creation, cacheCreation1hInputTokens: _oneHour, ...retained } = current; + const cleared = { ...retained, cacheTelemetry: rawCacheTelemetry(rawUsage) }; + logCtx.usage = cleared; + if (logCtx.activeAttempt) logCtx.activeAttempt.usage = cleared; } } -export function usageFromResponsesPayload(usage: unknown): OcxUsage | undefined { - if (!usage || typeof usage !== "object") return undefined; - const raw = usage as { - input_tokens?: unknown; - output_tokens?: unknown; - input_tokens_details?: { cached_tokens?: unknown; cache_write_tokens?: unknown; cache_write_1h_tokens?: unknown }; - output_tokens_details?: { reasoning_tokens?: unknown }; - total_tokens?: unknown; - prompt_tokens?: unknown; - completion_tokens?: unknown; - prompt_tokens_details?: { cached_tokens?: unknown; cache_write_tokens?: unknown }; - completion_tokens_details?: { reasoning_tokens?: unknown }; - }; - if (typeof raw.input_tokens === "number" && typeof raw.output_tokens === "number") { - return { - inputTokens: raw.input_tokens, - outputTokens: raw.output_tokens, - ...(typeof raw.total_tokens === "number" ? { totalTokens: raw.total_tokens } : {}), - ...(typeof raw.input_tokens_details?.cached_tokens === "number" - ? { - cachedInputTokens: raw.input_tokens_details.cached_tokens, - cacheReadInputTokens: raw.input_tokens_details.cached_tokens, - } - : {}), - ...(typeof raw.input_tokens_details?.cache_write_tokens === "number" - ? { cacheCreationInputTokens: raw.input_tokens_details.cache_write_tokens } - : {}), - ...(typeof raw.input_tokens_details?.cache_write_1h_tokens === "number" - ? { cacheCreation1hInputTokens: raw.input_tokens_details.cache_write_1h_tokens } - : {}), - ...(typeof raw.output_tokens_details?.reasoning_tokens === "number" - ? { reasoningOutputTokens: raw.output_tokens_details.reasoning_tokens } - : {}), - }; - } - if (typeof raw.prompt_tokens === "number" && typeof raw.completion_tokens === "number") { - return { - inputTokens: raw.prompt_tokens, - outputTokens: raw.completion_tokens, - ...(typeof raw.total_tokens === "number" ? { totalTokens: raw.total_tokens } : {}), - ...(typeof raw.prompt_tokens_details?.cached_tokens === "number" - ? { - cachedInputTokens: raw.prompt_tokens_details.cached_tokens, - cacheReadInputTokens: raw.prompt_tokens_details.cached_tokens, - } - : {}), - ...(typeof raw.prompt_tokens_details?.cache_write_tokens === "number" - ? { cacheCreationInputTokens: raw.prompt_tokens_details.cache_write_tokens } - : {}), - ...(typeof raw.completion_tokens_details?.reasoning_tokens === "number" - ? { reasoningOutputTokens: raw.completion_tokens_details.reasoning_tokens } - : {}), - }; - } - return undefined; -} +export { usageFromResponsesPayload }; /** * Mark a refusal this proxy synthesized locally. Sets origin to `synthetic` and a @@ -1049,9 +1017,9 @@ export function markLocalRequestLogRefusal( logCtx.terminalSource = "synthetic"; } -export function inspectResponseLogJson(logCtx: RequestLogContext, text: string): void { +export function inspectResponseLogJson(logCtx: RequestLogContext, text: string, source: UsageObservationSource = "client"): void { try { - applyResponseLogMetadata(logCtx, JSON.parse(text)); + applyResponseLogMetadata(logCtx, JSON.parse(text), source); } catch { logCtx.activeTierMetadata?.markResponseUnparseable(); /* body may not be JSON; request log metadata is best-effort only */ @@ -1079,12 +1047,13 @@ export function inspectResponseLogSsePayloadParsed( logCtx: RequestLogContext, payload: string | null, parsed: unknown | undefined, + source: UsageObservationSource = "client", ): void { if (!payload || payload.trim() === "[DONE]") return; const debugEnabled = isUsageDebugEnabled(); const sseAlreadyMarked = logCtx.usageDebugBodyKind === "sse"; if (parsed !== undefined) recordGenerationEvent(logCtx, (parsed as { type?: unknown } | null)?.type); - if (parsed !== undefined) applyResponseLogMetadata(logCtx, parsed); + if (parsed !== undefined) applyResponseLogMetadata(logCtx, parsed, source); else logCtx.activeTierMetadata?.markResponseUnparseable(); captureUpstreamErrorParsed(logCtx, payload, parsed); if (debugEnabled) { @@ -1386,6 +1355,13 @@ export function addFinalRequestLog( const closeReason = effectiveStatus === 499 ? "client_cancel" : meta?.closeReason; + let finalUsage = finalAttemptUsage(logCtx.usage, logCtx.activeAttempt, logCtx.attempts); + if (logCtx.activeAttempt) captureFreshAdapterCacheObservation(logCtx.activeAttempt, finalUsage); + const finalSendMissing = logCtx.activeAttempt && unchangedUsageSinceSend(logCtx.activeAttempt, finalUsage); + if (finalUsage && (finalSendMissing || (logCtx.activeAttempt && cacheIncompletePhysicalAttempts.has(logCtx.activeAttempt)))) { + finalUsage = { ...finalUsage, cacheTelemetry: aggregateCacheTelemetry([finalUsage, undefined]) }; + logCtx.activeAttempt!.usage = finalUsage; + } if (logCtx.activeAttempt) { finishRequestAttempt( logCtx.activeAttempt, @@ -1393,7 +1369,7 @@ export function addFinalRequestLog( Date.now() - (logCtx.activeAttemptStartedAt ?? start), keyUsageOwners.has(logCtx.activeAttempt) ? logCtx.activeAttempt.usage - : logCtx.usage, + : finalUsage, ); // The final row and its active physical attempt describe the same terminal. Preserve the // semantic code on both so detailed attempt telemetry cannot regress to a generic status code. @@ -1416,10 +1392,10 @@ export function addFinalRequestLog( // The one seam every request passes exactly once, whatever transport served it and however // it ended. The terminal usage belongs to the last send that left; the ledger resolves every // earlier send of this request as unresolved spend rather than handing its tokens back. - logCtx.spendTracker?.settle(logCtx.usage); + logCtx.spendTracker?.settle(finalSendMissing ? undefined : finalUsage); const existing = finalizedUsage( logCtx.providerAdapter ?? logCtx.provider, - logCtx.usage, + finalUsage, logCtx.usageLogInputTokens, contextWindowForModel(logCtx.providerAdapter ?? logCtx.provider, logCtx.model), logCtx.localTerminalReason !== undefined, @@ -1458,12 +1434,15 @@ export function addFinalRequestLog( ...(spend ? { spendSends: spend.sends } : {}), ...(attribution.failureCause ? { failureCause: attribution.failureCause } : {}), }); - const cacheProvenance = classifyCacheTelemetryProvenance(loggedUsage, { - wireParsed: logCtx.usageWireParsed === true, - }); + const cacheProvenance = classifyCacheTelemetryProvenance(loggedUsage); const logicalRequestId = logCtx.logicalRequestId ?? logCtx.executionBudget?.logicalRequestId; const normalizedCacheValue = loggedUsage?.cacheReadInputTokens ?? loggedUsage?.cachedInputTokens; - cacheDiagnosticHooks()?.finalize({ + const diagnosticHooks = cacheDiagnosticHooks(); + const rawOwner = logCtx.activeAttempt ?? logCtx; + const rawObservation = rawCacheObservations.get(rawOwner) + ?? (finalUsage?.cacheTelemetry?.source === "upstream" + && finalUsage.cacheTelemetry !== rawCacheSendBaselines.get(rawOwner)?.cacheTelemetry ? finalUsage.cacheTelemetry : undefined); + if (diagnosticHooks?.enabled()) diagnosticHooks.finalize({ requestId, ...(isLogicalRequestId(logicalRequestId) ? { logicalRequestId } : {}), protocol: logCtx.inboundProtocol ?? "responses", @@ -1472,10 +1451,8 @@ export function addFinalRequestLog( ...(isCodexUsageAccountLogLabel(logCtx.accountLogLabel) ? { accountLogLabel: logCtx.accountLogLabel } : {}), ...(logCtx.affinity ? { affinityMove: logCtx.affinity } : {}), ...(logCtx.affinityReason ? { affinityReason: logCtx.affinityReason } : {}), - // loggedUsage carries the upstream cache counter by reference all the way from the - // adapter extraction for the native Responses route, so an undefined read here is a - // genuinely absent counter rather than a defaulted one. - ...(normalizedCacheValue !== undefined ? { rawCacheCounterValue: normalizedCacheValue } : {}), + // An aggregate or a client normalization is not an original upstream payload. + ...(rawObservation ? { rawCacheTelemetry: rawObservation } : {}), ...(normalizedCacheValue !== undefined ? { normalizedCacheValue } : {}), cacheProvenance, ...(logCtx.cacheDiagnosticDraft ? { draft: logCtx.cacheDiagnosticDraft } : {}), @@ -1542,7 +1519,7 @@ export function addFinalRequestLog( // "unknown" is recorded rather than omitted whenever usage exists: a row that reported tokens // with no cache detail at all is a different fact from a row with no usage, and the summary // has to refuse both as a hit-rate denominator. - ...(loggedUsage || cacheProvenance !== "unknown" ? { cacheProvenance } : {}), + cacheProvenance, ...(logCtx.affinity ? { affinity: logCtx.affinity } : {}), ...(logCtx.affinityReason ? { affinityReason: logCtx.affinityReason } : {}), ...(logCtx.conversationStateScrub === "account-change" @@ -1686,7 +1663,7 @@ export async function recordKeyAttemptFailure(logCtx: RequestLogContext, respons const body = await readBoundedResponseBody(response.clone(), { signal, totalTimeoutMs: 1000, inactivityTimeoutMs: 1000 }); if (body.truncated || body.oversized) return; const value = JSON.parse(body.text); - const usage = usageFromResponsesPayload(value?.usage ?? value?.response?.usage); + const usage = usageFromResponsesPayload(value?.usage ?? value?.response?.usage, "upstream"); if (usage) recordKeyWireAttemptUsage(logCtx, usage); } catch { /* Absent/malformed usage remains unknown; recovery still owns the response. */ } finally { signal?.removeEventListener("abort", cancelOriginal); } @@ -1694,8 +1671,10 @@ export async function recordKeyAttemptFailure(logCtx: RequestLogContext, respons /** Add raw per-response usage before a bridge combines multiple rounds for the client. */ export function recordKeyAttemptUsage(logCtx: RequestLogContext, usage: OcxUsage | undefined): void { + usage = withAdapterCacheTelemetry(usage); const attempt = logCtx.activeAttempt; if (!attempt || !usage) return; + captureFreshAdapterCacheObservation(attempt, usage); attempt.usage = attempt.usage ? aggregateAttemptUsage([{ ...attempt, usageStatus: attempt.usage.estimated ? "estimated" : "reported" }, { ...attempt, usage, usageStatus: usage.estimated ? "estimated" : "reported" }]).usage @@ -1745,6 +1724,7 @@ export function noteProviderAttemptSend( } for (const key of Object.keys(attempt)) delete (attempt as unknown as Record)[key]; Object.assign(attempt, fresh); + cacheIncompletePhysicalAttempts.delete(attempt); delete logCtx.usage; logCtx.activeAttemptStartedAt = Date.now(); } @@ -1791,6 +1771,15 @@ export function noteAttemptSend( recovery?: AttemptRecoveryKind, ): void { if (!attempt) return; + // A later measured send cannot fill an earlier unreported physical-send gap. + if (attempt.sendCount > 0 && attempt.locallyAnswered !== true && rawCacheSendBaselines.has(attempt) + && (attempt.usage === rawCacheSendBaselines.get(attempt) || unchangedUsageSinceSend(attempt, attempt.usage))) { + cacheIncompletePhysicalAttempts.add(attempt); + } + // Stable attempt objects survive rotation/resends; only this physical send may supply raw facts. + rawCacheObservations.delete(attempt); + unreportedFinalizedUsage.delete(attempt); + rawCacheSendBaselines.set(attempt, attempt.usage); attempt.sendCount += 1; if (typeof inputTokenEstimate === "number" && Number.isFinite(inputTokenEstimate) @@ -1823,15 +1812,35 @@ export function noteAttemptRecoveryWithheld( if (!attempt.recoveryWithheld.includes(reason)) attempt.recoveryWithheld.push(reason); } +function captureFreshAdapterCacheObservation(attempt: PersistedUsageAttempt, usage?: OcxUsage): void { + const evidence = usage?.cacheTelemetry; + if (evidence?.source === "upstream" && evidence !== rawCacheSendBaselines.get(attempt)?.cacheTelemetry + && !rawCacheObservations.has(attempt)) rawCacheObservations.set(attempt, evidence); +} + +function unchangedUsageSinceSend(attempt: PersistedUsageAttempt, usage?: OcxUsage): boolean { + const same = (previous?: OcxUsage) => !!usage && !!previous + && (usage === previous || (usage.cacheTelemetry !== undefined && usage.cacheTelemetry === previous.cacheTelemetry)); + return attempt.locallyAnswered !== true + && (same(rawCacheSendBaselines.get(attempt)) || same(unreportedFinalizedUsage.get(attempt))); +} + export function finishRequestAttempt( attempt: PersistedUsageAttempt, status: number, durationMs: number, usage?: OcxUsage, ): PersistedUsageAttempt { + let current = usage ?? attempt.usage; + captureFreshAdapterCacheObservation(attempt, current); + const finalSendMissing = unchangedUsageSinceSend(attempt, current); + if (current && (cacheIncompletePhysicalAttempts.has(attempt) || finalSendMissing)) { + current = { ...current, cacheTelemetry: aggregateCacheTelemetry([current, undefined]) }; + if (finalSendMissing) unreportedFinalizedUsage.set(attempt, current); + } const finalized = finalizedUsage( attempt.adapter, - usage ?? attempt.usage, + current, attempt.inputTokenEstimate, contextWindowForModel(attempt.adapter, attempt.model), attempt.locallyAnswered === true, @@ -1839,6 +1848,7 @@ export function finishRequestAttempt( attempt.status = status; attempt.durationMs = Math.max(0, durationMs); attempt.usageStatus = finalized.status; + attempt.cacheProvenance = classifyCacheTelemetryProvenance(finalized.usage); if (finalized.usage) attempt.usage = finalized.usage; else delete attempt.usage; if (finalized.totalTokens !== undefined) attempt.totalTokens = finalized.totalTokens; @@ -1895,6 +1905,7 @@ export function aggregateAttemptUsage( 0, ); const aggregate: OcxUsage = { + cacheTelemetry: aggregateCacheTelemetry(measured.map(attempt => attempt.usage)), inputTokens: usages.reduce((sum, usage) => sum + usage.inputTokens, 0), outputTokens: usages.reduce((sum, usage) => sum + usage.outputTokens, 0), totalTokens, diff --git a/src/server/responses/advisor-retention.ts b/src/server/responses/advisor-retention.ts index 8d8dbd6e2ca..434b51f5eec 100644 --- a/src/server/responses/advisor-retention.ts +++ b/src/server/responses/advisor-retention.ts @@ -1,3 +1,4 @@ +import { aggregateCacheTelemetry } from "../../usage/cache-telemetry"; import { jsonUtf8Bytes } from "../../lib/json-byte-size"; import { TRANSLATOR_MAX_TURN_BYTES, @@ -16,6 +17,7 @@ export class AdvisorRetention { private historyBytes = 0; private copyBytes = 0; private usageBytes = 0; + private missingUsage = false; private events = 0; private calls = 0; @@ -30,17 +32,19 @@ export class AdvisorRetention { /** Usage can alias a terminal payload. Keep its own owner after the raw leg ends. */ usage(first: OcxUsage | undefined, second: OcxUsage | undefined): OcxUsage | undefined { - if (!second) return first; - // Two-input merge materializes a new object. Reserve before merging, including - // a conservative bound for concatenation if a provider supplied malformed scalars. - const bytes = first - ? (jsonUtf8Bytes(first) + jsonUtf8Bytes(second)) * 2 + 256 - : jsonUtf8Bytes(second) + 1; + this.missingUsage ||= !second; + if (!first && !second) return undefined; + // Reserve before materializing either a first observation or an aggregate. The fixed + // allowance covers closed cache metadata; malformed scalar concatenations remain bounded. + const bytes = first && second + ? (jsonUtf8Bytes(first) + jsonUtf8Bytes(second)) * 2 + 512 + : jsonUtf8Bytes(first ?? second) + 512; this.charge(bytes, "request_copies"); this.copyBytes += bytes; let retained = 0; try { - const merged = mergeUsage(first, second); + let merged = mergeUsage(first, second)!; + if (this.missingUsage) merged = { ...merged, cacheTelemetry: aggregateCacheTelemetry([merged, undefined]) }; const measured = jsonUtf8Bytes(merged, bytes) + 1; if (measured > bytes) throw new TranslatorBudgetExceededError("request_copies", TRANSLATOR_MAX_TURN_BYTES); retained = measured; @@ -113,5 +117,6 @@ export class AdvisorRetention { this.historyBytes = 0; this.shared?.releaseRetained(this.usageBytes, { kind: "request_copies" }); this.usageBytes = 0; + this.missingUsage = false; } } diff --git a/src/server/responses/compact.ts b/src/server/responses/compact.ts index 32263104a72..91014c77b04 100644 --- a/src/server/responses/compact.ts +++ b/src/server/responses/compact.ts @@ -1644,7 +1644,7 @@ export async function handleResponsesCompact( } } catch { /* A malformed body cannot establish serving provenance. */ } } - inspectResponseLogJson(logCtx, compactText); + inspectResponseLogJson(logCtx, compactText, "upstream"); if (!options.compactionRoutingOverride) forgetCompactHandoffRoute(req, admission); rememberServingConversationStateIssuer(outcomeCtx, codexPoolAffinityKey(req.headers)); } else if (!options.compactionRoutingOverride && quotaFailure && (!storedPool401ReplayAttempted || wasAccountAutoPaused(upstream))) { diff --git a/src/server/responses/compaction-recovery.ts b/src/server/responses/compaction-recovery.ts index f35c6a8d39f..44bb13f7c94 100644 --- a/src/server/responses/compaction-recovery.ts +++ b/src/server/responses/compaction-recovery.ts @@ -317,7 +317,8 @@ export async function runWithCompactionRecovery( void completed.response.body?.cancel().catch(() => undefined); void response.body?.cancel().catch(() => undefined); if (snapshot.stream === true) { - const usage = usageFromResponsesPayload(json.usage); + // dispatch already returned client JSON, possibly with bridge-defaulted cache zeros. + const usage = usageFromResponsesPayload(json.usage, "client"); async function* events(): AsyncGenerator { yield { type: "text_delta", text: preserved }; yield { type: "done", compactionEncryptedContent: encryptedContent, ...(usage ? { usage } : {}) }; diff --git a/src/server/responses/empty-completion-guard.ts b/src/server/responses/empty-completion-guard.ts index 0b8728897c1..212a6fb4cc7 100644 --- a/src/server/responses/empty-completion-guard.ts +++ b/src/server/responses/empty-completion-guard.ts @@ -1,3 +1,4 @@ +import { aggregateCacheTelemetry, withAdapterCacheTelemetry } from "../../usage/cache-telemetry"; import type { AdapterEvent, OcxConfig, OcxUsage } from "../../types"; import { sanitizeLogMetadataString } from "../../lib/redact"; @@ -160,6 +161,8 @@ export function mergeUsage( first: OcxUsage | undefined, second: OcxUsage | undefined, ): OcxUsage | undefined { + first = withAdapterCacheTelemetry(first); + second = withAdapterCacheTelemetry(second); if (!first) return second; if (!second) return first; const sumOptional = (key: keyof OcxUsage): number | undefined => { @@ -170,7 +173,11 @@ export function mergeUsage( : undefined; }; const cachedInputTokens = sumOptional("cachedInputTokens"); - const cacheReadInputTokens = sumOptional("cacheReadInputTokens"); + const cacheReadInputTokens = sumOptional("cacheReadInputTokens") === undefined ? undefined + : [first, second].reduce((sum, usage) => { + const read = usage.cacheReadInputTokens ?? usage.cachedInputTokens; + return sum + (typeof read === "number" ? read : 0); + }, 0); const cacheCreationInputTokens = sumOptional("cacheCreationInputTokens"); const cacheCreation1hInputTokens = sumOptional("cacheCreation1hInputTokens"); const reasoningOutputTokens = sumOptional("reasoningOutputTokens"); @@ -185,6 +192,7 @@ export function mergeUsage( inputTokens, outputTokens, totalTokens: inputTokens + outputTokens, + cacheTelemetry: aggregateCacheTelemetry([first, second]), ...(contextTotalTokens !== undefined ? { contextTotalTokens } : {}), ...(cachedInputTokens !== undefined ? { cachedInputTokens } : {}), ...(cacheReadInputTokens !== undefined ? { cacheReadInputTokens } : {}), @@ -232,9 +240,16 @@ export async function* guardEmptyCompletionEventStream( let passthrough = false; let retries = 0; let usage: OcxUsage | undefined; + // A missing physical terminal is not the initial, empty numeric accumulator. + let missingUsage = false; + const addUsage = (round: OcxUsage | undefined): OcxUsage | undefined => { + missingUsage ||= !round; + const merged = mergeUsage(usage, round); + return merged && missingUsage ? { ...merged, cacheTelemetry: aggregateCacheTelemetry([merged, undefined]) } : merged; + }; const withUsage = (event: AdapterEvent & { usage?: OcxUsage }): AdapterEvent => { - const merged = mergeUsage(usage, event.usage); + const merged = addUsage(event.usage); return merged ? { ...event, ...(merged ? { usage: merged } : {}) } : event; }; const releaseHeld = (): AdapterEvent[] => { @@ -273,7 +288,7 @@ export async function* guardEmptyCompletionEventStream( continue; } if (event.type === "done") { - usage = mergeUsage(usage, event.usage); + usage = addUsage(event.usage); if (event.stopReason !== undefined && VISIBLE_INCOMPLETE_STOP_REASONS.has(event.stopReason)) { // Rendered as response.incomplete: a stated failure, not the silent // empty success this guard exists to catch. @@ -305,7 +320,7 @@ export async function* guardEmptyCompletionEventStream( // The upstream failed the turn before any text or tool call (#6876: Vertex dropped a // malformed function call). Nothing actionable reached the client, so this is the same // replay-safe shape as an empty completion: retry the identical turn once. - usage = mergeUsage(usage, event.usage); + usage = addUsage(event.usage); markRetryBoundary(); retries += 1; try { @@ -323,7 +338,7 @@ export async function* guardEmptyCompletionEventStream( // the stream's own error framing — same move as the router's // empty_completion_retry_failed. Client cancels (499) pass through, and a // replay-safe failure that repeats keeps its own, more specific message. - yield emptyCompletionRetryFailedEvent(mergeUsage(usage, event.usage), true); + yield emptyCompletionRetryFailedEvent(addUsage(event.usage), true); return; } yield* releaseHeld(); @@ -354,6 +369,7 @@ export async function* guardEmptyCompletionEventStream( if (isReasoningEvent(event)) yield { type: "heartbeat" }; } if (!terminalSeen) { + usage = addUsage(undefined); // A terminal-less EOF before text or a tool call is replay-safe: nothing // actionable reached the client. Retry once, then surface a stated error // instead of letting the bridge reduce the turn to adapter_eof. diff --git a/src/server/responses/native-steering-log.ts b/src/server/responses/native-steering-log.ts index 0f3a3e202e8..b60e16a2272 100644 --- a/src/server/responses/native-steering-log.ts +++ b/src/server/responses/native-steering-log.ts @@ -1,11 +1,12 @@ -import { inspectResponseLogSsePayload, usageFromResponsesPayload, type RequestLogContext } from "../request-log"; +import { inspectResponseLogSsePayloadParsed, usageFromResponsesPayload, type RequestLogContext } from "../request-log"; import type { OcxUsage } from "../../types"; +import { aggregateCacheTelemetry } from "../../usage/cache-telemetry"; import { MAX_NATIVE_STEERING_RESPONSES } from "./native-steering"; /** Count every terminal once. Control frames may echo user input: never sample them. */ export function createNativeSteeringLogObserver(logCtx: RequestLogContext, onFirstOutput?: () => void): (payload: string) => void { let outputSeen = false; - const usages = new Map(); + const usages = new Map(); return payload => { let event: { type?: string; delta?: unknown; response?: { id?: string; usage?: unknown; incomplete_details?: { reason?: string } } }; try { event = JSON.parse(payload); } catch { return; } @@ -16,28 +17,37 @@ export function createNativeSteeringLogObserver(logCtx: RequestLogContext, onFir // A steered parent is not a failed logical turn. Keep its usage, but never // label an eventual successful successor as an upstream failure. if (!(event.type === "response.incomplete" && event.response?.incomplete_details?.reason === "steered")) { - inspectResponseLogSsePayload(logCtx, payload); + // Native-control delivery bypasses the client rewrite/bridge chain; usage is raw. + inspectResponseLogSsePayloadParsed(logCtx, payload, event, "upstream"); } const terminal = ["response.completed", "response.failed", "response.incomplete"].includes(event.type ?? ""); if (terminal && typeof event.response?.id === "string") { - const usage = usageFromResponsesPayload(event.response.usage); - if (usage && (usages.has(event.response.id) || usages.size < MAX_NATIVE_STEERING_RESPONSES)) { - // Retain numeric counters only, never arbitrary rawUsage metadata. - const counters: OcxUsage = { inputTokens: usage.inputTokens, outputTokens: usage.outputTokens }; + const usage = usageFromResponsesPayload(event.response.usage, "upstream"); + if (usages.has(event.response.id) || usages.size < MAX_NATIVE_STEERING_RESPONSES) { + // Retain counters and closed evidence only, never arbitrary rawUsage metadata. + const counters: OcxUsage | undefined = usage ? { inputTokens: usage.inputTokens, outputTokens: usage.outputTokens, + cacheTelemetry: usage.cacheTelemetry } : undefined; for (const key of ["totalTokens", "cachedInputTokens", "cacheReadInputTokens", "cacheCreationInputTokens", "cacheCreation1hInputTokens", "reasoningOutputTokens"] as const) { - if (typeof usage[key] === "number") counters[key] = usage[key]; + if (counters && typeof usage?.[key] === "number") counters[key] = usage[key]; } usages.set(event.response.id, counters); } } if (!usages.size) return; + const measured = [...usages.values()].filter((usage): usage is OcxUsage => usage !== undefined); + if (!measured.length) { + delete logCtx.usage; + if (logCtx.activeAttempt) delete logCtx.activeAttempt.usage; + return; + } const total: OcxUsage = { inputTokens: 0, outputTokens: 0 }; - for (const usage of usages.values()) { + for (const usage of measured) { for (const key of ["inputTokens", "outputTokens", "totalTokens", "cachedInputTokens", "cacheReadInputTokens", "cacheCreationInputTokens", "cacheCreation1hInputTokens", "reasoningOutputTokens"] as const) { const value = usage[key]; if (typeof value === "number" && Number.isFinite(value)) total[key] = (total[key] ?? 0) + value; } } + total.cacheTelemetry = usages.size === 1 ? measured[0]!.cacheTelemetry : aggregateCacheTelemetry([...usages.values()]); logCtx.usage = total; if (logCtx.activeAttempt) logCtx.activeAttempt.usage = total; }; diff --git a/src/server/responses/passthrough-completion.ts b/src/server/responses/passthrough-completion.ts index 85ccac8af4a..6623b5839c7 100644 --- a/src/server/responses/passthrough-completion.ts +++ b/src/server/responses/passthrough-completion.ts @@ -30,7 +30,7 @@ export function guardPassthroughCompletion( signal, retryEnabled: config.emptyCompletionRetry, stallTimeoutMs: resolveStallTimeoutMs(config.stallTimeoutSec), - recordUsage: usage => { recordKeyWireAttemptUsage(logCtx, usageFromResponsesPayload(usage)); }, + recordUsage: usage => { recordKeyWireAttemptUsage(logCtx, usageFromResponsesPayload(usage, "upstream")); }, retry: async () => { const result = await rebuildAndRefetch("empty-completion"); if (!("failed" in result)) return result; diff --git a/src/server/responses/passthrough-delivery.ts b/src/server/responses/passthrough-delivery.ts index cac782e0e28..f1cd157122f 100644 --- a/src/server/responses/passthrough-delivery.ts +++ b/src/server/responses/passthrough-delivery.ts @@ -1052,6 +1052,7 @@ export async function deliverPassthroughResponse( const effectInspector = createSseInspector({ onTerminal: reportNativeTerminal, logCtx, + upstreamUsage: true, onParsedPayload: noteInspectedPayload, onFirstOutput: options.onFirstOutput, pinCompletedResponseIdToFirstSeen: githubCopilotRepairEnabled, @@ -1132,6 +1133,7 @@ export async function deliverPassthroughResponse( const inspector = createSseInspector({ onTerminal: reportNativeTerminal, logCtx, + upstreamUsage: true, onCompletedResponse: rememberPassthroughResponse && !grokUpstreamEchoEnabled && responseEffects.plaintextV2AgentMessageToolNames.size === 0 ? rememberPassthroughResponseChecked : undefined, onParsedPayload: noteInspectedPayload, onFirstOutput: options.onFirstOutput, @@ -1196,6 +1198,7 @@ export async function deliverPassthroughResponse( linkAbortSignal(upstream, turnAc.signal); registerTurn(turnAc, options.turnAdmissionLease); const inspectionConsumerOptions = { + upstreamUsage: true, // Request abort can reject the fetch body before the response cancel hook runs. clientGoneSignal, drainBounds: { ms: 15_000, bytes: 32 * 1024 * 1024 }, @@ -1286,7 +1289,7 @@ export async function deliverPassthroughResponse( return formatErrorResponse(502, "upstream_error", "upstream JSON response stalled before completing"); } const text = bounded.text; - inspectResponseLogJson(logCtx, text); + inspectResponseLogJson(logCtx, text, "upstream"); let plaintextV2RestoreFailed = false; let clientJson = (() => { const restoredNamespace = restoreRoutedNamespaceCallsInJson( diff --git a/src/server/responses/request-transport.ts b/src/server/responses/request-transport.ts index 397ffa2187d..761b97e760f 100644 --- a/src/server/responses/request-transport.ts +++ b/src/server/responses/request-transport.ts @@ -1,5 +1,6 @@ import { SendBudgetExhaustedError } from "../../lib/upstream-retry"; import { anthropicBillingPhysicalFetch } from "../../providers/anthropic-billing-ownership"; +import { withAdapterCacheTelemetry } from "../../usage/cache-telemetry"; import { rebindPhysicalSend } from "../../lib/request-execution-budget"; import { anthropicModelQuotaFor } from "../../oauth/anthropic-model-quota"; import { anthropicRatePolicyFor } from "../../oauth/anthropic-rate-limit-policy"; @@ -519,6 +520,7 @@ export async function prepareResponsesTransport( pendingKeySend = undefined; }; const bindKeyUsageFromBridge = (usage: OcxUsage | undefined): void => { + usage = withAdapterCacheTelemetry(usage); logCtx.usageFromBridge = true; if (usesApiKeyAccount(route.provider)) { logCtx.usage = logCtx.activeAttempt?.usage; diff --git a/src/server/responses/terminal-guard.ts b/src/server/responses/terminal-guard.ts index a1870add66f..f808daa8d32 100644 --- a/src/server/responses/terminal-guard.ts +++ b/src/server/responses/terminal-guard.ts @@ -1,3 +1,4 @@ +import { aggregateCacheTelemetry, withAdapterCacheTelemetry } from "../../usage/cache-telemetry"; import { assistantReplayContent } from "../../responses/assistant-replay"; import type { AdapterEvent, @@ -158,6 +159,8 @@ export function isTerminalGuardPassthroughOnly(event: AdapterEvent): boolean { /** Merge two reported usages (canonical Responses convention). Shared with the advisor guard. */ export function mergeUsage(first: OcxUsage | undefined, second: OcxUsage | undefined): OcxUsage | undefined { + first = withAdapterCacheTelemetry(first); + second = withAdapterCacheTelemetry(second); if (!first) return second; if (!second) return first; const sumOptional = (key: keyof OcxUsage): number | undefined => { @@ -168,7 +171,11 @@ export function mergeUsage(first: OcxUsage | undefined, second: OcxUsage | undef : undefined; }; const cachedInputTokens = sumOptional("cachedInputTokens"); - const cacheReadInputTokens = sumOptional("cacheReadInputTokens"); + const cacheReadInputTokens = sumOptional("cacheReadInputTokens") === undefined ? undefined + : [first, second].reduce((sum, usage) => { + const read = usage.cacheReadInputTokens ?? usage.cachedInputTokens; + return sum + (typeof read === "number" ? read : 0); + }, 0); const cacheCreationInputTokens = sumOptional("cacheCreationInputTokens"); const cacheCreation1hInputTokens = sumOptional("cacheCreation1hInputTokens"); const reasoningOutputTokens = sumOptional("reasoningOutputTokens"); @@ -179,6 +186,7 @@ export function mergeUsage(first: OcxUsage | undefined, second: OcxUsage | undef inputTokens, outputTokens, totalTokens: inputTokens + outputTokens, + cacheTelemetry: aggregateCacheTelemetry([first, second]), ...(cachedInputTokens !== undefined ? { cachedInputTokens } : {}), ...(cacheReadInputTokens !== undefined ? { cacheReadInputTokens } : {}), ...(cacheCreationInputTokens !== undefined ? { cacheCreationInputTokens } : {}), @@ -205,6 +213,13 @@ export async function* guardTerminalEventStream(options: GuardedEventStreamOptio let parsed = options.parsed; let continuations = 0; let accumulatedUsage: OcxUsage | undefined; + // A missing physical terminal is not the initial, empty numeric accumulator. + let missingUsage = false; + const addUsage = (round: OcxUsage | undefined): OcxUsage | undefined => { + missingUsage ||= !round; + const merged = mergeUsage(accumulatedUsage, round); + return merged && missingUsage ? { ...merged, cacheTelemetry: aggregateCacheTelemetry([merged, undefined]) } : merged; + }; let source: AsyncIterable = options.firstEvents; while (true) { @@ -229,7 +244,7 @@ export async function* guardTerminalEventStream(options: GuardedEventStreamOptio : { decision: "pass" as const }; const normalStop = event.stopReason !== "max_tokens" && event.stopReason !== "content_filter"; if (normalStop && analysis.decision === "continue" && continuations < maxContinuations) { - accumulatedUsage = mergeUsage(accumulatedUsage, event.usage); + accumulatedUsage = addUsage(event.usage); continuations += 1; parsed = buildContinuationRequest(parsed, seen); seen.length = 0; @@ -247,13 +262,13 @@ export async function* guardTerminalEventStream(options: GuardedEventStreamOptio } break; } - const usage = mergeUsage(accumulatedUsage, event.usage); + const usage = addUsage(event.usage); yield usage ? { ...event, usage } : event; return; } if (event.type === "incomplete" || event.type === "error") { terminalSeen = true; - const usage = mergeUsage(accumulatedUsage, event.usage); + const usage = addUsage(event.usage); yield usage ? { ...event, usage } : event; return; } diff --git a/src/types/request.ts b/src/types/request.ts index edc20eaae0d..89338e1f925 100644 --- a/src/types/request.ts +++ b/src/types/request.ts @@ -533,6 +533,19 @@ export interface OcxUrlCitation { title?: string; } +/** Content-free cache evidence, captured before client defaults. Missing counters are not zero. */ +export interface CacheTelemetry { + source: "upstream" | "adapter" | "client" | "aggregate"; + usagePresent: boolean; + read?: number; + creation?: number; + /** Aggregate evidence is complete only when every contributing usage is observed. */ + complete?: boolean; + /** Aggregate sums may be partial even when every round reports some cache detail. */ + readComplete?: boolean; + creationComplete?: boolean; +} + /** * Canonical usage convention (devlog/260711_claude_inbound/070): * - `inputTokens` is the TOTAL prompt size, INCLUDING cache reads and cache writes @@ -545,6 +558,8 @@ export interface OcxUrlCitation { * - `totalTokens` = inputTokens + outputTokens. Never re-add cache detail on top. */ export interface OcxUsage { + /** Internal/persisted evidence; never serialize this metadata onto the client wire. */ + cacheTelemetry?: CacheTelemetry; /** Provider-reported credit spend, independent of token estimates and USD pricing. */ providerCredits?: number; inputTokens: number; diff --git a/src/usage/cache-diagnostic.ts b/src/usage/cache-diagnostic.ts index 14918c60568..7376986762c 100644 --- a/src/usage/cache-diagnostic.ts +++ b/src/usage/cache-diagnostic.ts @@ -6,6 +6,8 @@ import { CODEX_AFFINITY_DEBUG_SAFE_HEADERS } from "../codex/affinity-debug"; import { getConfigDir } from "../config"; import { recordOwnedConfigPath } from "../lib/config-ownership"; import type { CacheTelemetryProvenance } from "./log"; +import type { CacheTelemetry } from "../types/request"; +import { normalizeCacheTelemetry } from "./cache-telemetry"; const CACHE_DEBUG_KEY = randomBytes(32); const MAX_BLOCKS = 128; @@ -42,6 +44,8 @@ export interface CacheDiagnosticFinalFacts { * all, which keeps a measured zero distinct from an absent-then-defaulted zero. */ rawCacheCounterValue?: number; + /** Original upstream presence/counters, never inferred from an aggregate or client wire. */ + rawCacheTelemetry?: CacheTelemetry; normalizedCacheValue?: number; cacheProvenance: CacheTelemetryProvenance; draft?: CacheDiagnosticDraft; @@ -238,6 +242,9 @@ export function appendFinalCacheDiagnostic(facts: CacheDiagnosticFinalFacts): vo const outboundKey = draft.promptCacheKey?.outbound; const inboundPrefix = draft.prefix?.inbound ?? prefixFingerprint(undefined); const outboundPrefix = draft.prefix?.outbound ?? prefixFingerprint(undefined); + const evidence = normalizeCacheTelemetry(facts.rawCacheTelemetry); + const raw = evidence?.source === "upstream" ? evidence : undefined; + const rawRead = raw?.read ?? facts.rawCacheCounterValue; const record = { version: 1 as const, ts: Date.now(), @@ -272,9 +279,13 @@ export function appendFinalCacheDiagnostic(facts: CacheDiagnosticFinalFacts): vo ...(facts.affinityReason ? { affinityReason: facts.affinityReason } : {}), }, cache: { - rawUpstream: facts.rawCacheCounterValue !== undefined - ? { present: true, value: facts.rawCacheCounterValue } - : { present: false }, + rawUpstream: { + observed: raw !== undefined || facts.rawCacheCounterValue !== undefined, + ...(raw ? { usagePresent: raw.usagePresent } : {}), + present: rawRead !== undefined, + ...(rawRead !== undefined ? { value: rawRead } : {}), + ...(raw?.creation !== undefined ? { creation: raw.creation } : {}), + }, normalized: { present: facts.normalizedCacheValue !== undefined, ...(facts.normalizedCacheValue !== undefined ? { value: facts.normalizedCacheValue } : {}), diff --git a/src/usage/cache-telemetry.ts b/src/usage/cache-telemetry.ts new file mode 100644 index 00000000000..13c27775c31 --- /dev/null +++ b/src/usage/cache-telemetry.ts @@ -0,0 +1,179 @@ +/** Cache counters and provenance only. Never retain a raw payload, body, or credential here. */ +import type { CacheTelemetry, OcxUsage } from "../types/request"; + +export type CacheProvenance = "observed" | "synthesized" | "unknown"; +export type UsageObservationSource = "upstream" | "client"; +const number = (value: unknown): value is number => typeof value === "number" && Number.isFinite(value) && value >= 0; +const record = (value: unknown): value is Record => value !== null && typeof value === "object" && !Array.isArray(value); + +export function rawCacheTelemetry(raw: unknown): CacheTelemetry { + if (!record(raw)) return { source: "upstream", usagePresent: false }; + const details = record(raw.input_tokens_details) ? raw.input_tokens_details + : record(raw.prompt_tokens_details) ? raw.prompt_tokens_details : undefined; + const read = details?.cached_tokens ?? raw.cache_read_input_tokens; + const creation = details?.cache_write_tokens ?? raw.cache_creation_input_tokens; + return { + source: "upstream", usagePresent: true, + ...(number(read) ? { read } : {}), + ...(number(creation) ? { creation } : {}), + }; +} + +/** Adapter callbacks precede the bridge's zero-default client encoder. */ +export function withAdapterCacheTelemetry(usage: OcxUsage | undefined): OcxUsage | undefined { + if (!usage) return usage; + if (usage.cacheTelemetry !== undefined) { + const evidence = normalizeCacheTelemetry(usage.cacheTelemetry); + // Invalid metadata is not permission to reinterpret normalized counters as raw evidence. + return evidence ? usage : { ...usage, cacheTelemetry: { source: "aggregate", usagePresent: true, complete: false } }; + } + const read = usage.cacheReadInputTokens ?? usage.cachedInputTokens; + return { + ...usage, + cacheTelemetry: { + source: usage.estimated ? "client" : "adapter", usagePresent: true, + ...(number(read) ? { read } : {}), + ...(number(usage.cacheCreationInputTokens) ? { creation: usage.cacheCreationInputTokens } : {}), + }, + }; +} + +/** Validate and detach only the closed evidence fields when persisting or reading a ledger. */ +export function normalizeCacheTelemetry(value: unknown): CacheTelemetry | undefined { + if (!record(value) || typeof value.source !== "string" + || !["upstream", "adapter", "client", "aggregate"].includes(value.source) + || typeof value.usagePresent !== "boolean" + || (value.read !== undefined && !number(value.read)) + || (value.creation !== undefined && !number(value.creation)) + || (["complete", "readComplete", "creationComplete"] as const).some(field => value[field] !== undefined + && (value.source !== "aggregate" || typeof value[field] !== "boolean")) + || (!value.usagePresent && (value.read !== undefined || value.creation !== undefined))) return undefined; + return { + source: value.source as CacheTelemetry["source"], usagePresent: value.usagePresent, + ...(number(value.read) ? { read: value.read } : {}), + ...(number(value.creation) ? { creation: value.creation } : {}), + ...(typeof value.complete === "boolean" ? { complete: value.complete } : {}), + ...(typeof value.readComplete === "boolean" ? { readComplete: value.readComplete } : {}), + ...(typeof value.creationComplete === "boolean" ? { creationComplete: value.creationComplete } : {}), + }; +} + +export function cacheProvenance(usage: OcxUsage | undefined): CacheProvenance { + if (!usage) return "unknown"; + const evidence = normalizeCacheTelemetry(usage.cacheTelemetry); + if (evidence) { + if (!evidence.usagePresent || evidence.source === "client" + || (evidence.source === "aggregate" && evidence.complete !== true)) return "unknown"; + if (number(evidence.read) || number(evidence.creation)) return "observed"; + return [usage.cachedInputTokens, usage.cacheReadInputTokens, usage.cacheCreationInputTokens].some(number) + ? "synthesized" : "unknown"; + } + if (usage.cacheTelemetry !== undefined) return "unknown"; + // Old zeros (or wire-parsed zeros without evidence) cannot be backfilled. Positive counts + // remain usable; unlike zero they cannot have been produced by zero-default normalization. + return [usage.cachedInputTokens, usage.cacheReadInputTokens, usage.cacheCreationInputTokens] + .some(value => number(value) && value > 0) ? "observed" : "unknown"; +} + +/** A historic label cannot recover whether an old zero was defaulted or measured. */ +export function cacheProvenanceForRecord(usage: OcxUsage | undefined, stored?: CacheProvenance): CacheProvenance { + const derived = cacheProvenance(usage); + if (usage?.cacheTelemetry || derived === "unknown") return derived; + return stored ?? derived; +} + +/** Identity, not numeric similarity, prevents a new unresolved attempt borrowing old usage. */ +export function finalAttemptUsage(usage: OcxUsage | undefined, active?: { usage?: OcxUsage }, attempts?: readonly { usage?: OcxUsage }[]): OcxUsage | undefined { + if (!active) return usage; + if (active.usage) return active.usage; + const belongsElsewhere = usage && attempts?.some(attempt => attempt !== active && (attempt.usage === usage + || (usage.cacheTelemetry !== undefined && attempt.usage?.cacheTelemetry === usage.cacheTelemetry))); + return belongsElsewhere ? undefined : usage; +} + +export function aggregateCacheTelemetry(usages: readonly (OcxUsage | undefined)[]): CacheTelemetry { + const evidence = usages.map(usage => { + const saved = normalizeCacheTelemetry(usage?.cacheTelemetry); + if (saved || !usage || usage.cacheTelemetry !== undefined) return saved; + // Legacy positive counters remain usable; legacy zero alone is not an observation. + if (cacheProvenance(usage) !== "observed") return undefined; + const read = usage.cacheReadInputTokens ?? usage.cachedInputTokens; + const creation = usage.cacheCreationInputTokens; + return { source: "adapter" as const, usagePresent: true, + ...(number(read) && read > 0 ? { read } : {}), + ...(number(creation) && creation > 0 ? { creation } : {}) }; + }); + const complete = usages.length > 0 && usages.every(usage => cacheProvenance(usage) === "observed"); + const sum = (field: "read" | "creation") => { + const values = evidence.flatMap(item => item?.source !== "client" && number(item?.[field]) ? [item![field]!] : []); + const total = values.reduce((sum, value) => sum + value, 0); + return values.length && number(total) ? total : undefined; + }; + const fieldComplete = (field: "read" | "creation") => complete && evidence.every(item => + number(item?.[field]) && item?.[field === "read" ? "readComplete" : "creationComplete"] !== false); + const read = sum("read"); + const creation = sum("creation"); + return { source: "aggregate", usagePresent: usages.some(usage => usage !== undefined + && normalizeCacheTelemetry(usage.cacheTelemetry)?.usagePresent !== false), complete, + readComplete: fieldComplete("read") && read !== undefined, + creationComplete: fieldComplete("creation") && creation !== undefined, + ...(read !== undefined ? { read } : {}), ...(creation !== undefined ? { creation } : {}) }; +} + +export function usageFromResponsesPayload(usage: unknown, source: UsageObservationSource = "client"): OcxUsage | undefined { + if (!usage || typeof usage !== "object") return undefined; + const raw = usage as { + input_tokens?: unknown; + output_tokens?: unknown; + input_tokens_details?: { cached_tokens?: unknown; cache_write_tokens?: unknown; cache_write_1h_tokens?: unknown }; + output_tokens_details?: { reasoning_tokens?: unknown }; + total_tokens?: unknown; + prompt_tokens?: unknown; + completion_tokens?: unknown; + prompt_tokens_details?: { cached_tokens?: unknown; cache_write_tokens?: unknown }; + completion_tokens_details?: { reasoning_tokens?: unknown }; + }; + if (typeof raw.input_tokens === "number" && typeof raw.output_tokens === "number") { + return { + inputTokens: raw.input_tokens, + outputTokens: raw.output_tokens, + cacheTelemetry: source === "upstream" ? rawCacheTelemetry(raw) : { source: "client", usagePresent: true }, + ...(typeof raw.total_tokens === "number" ? { totalTokens: raw.total_tokens } : {}), + ...(typeof raw.input_tokens_details?.cached_tokens === "number" + ? { + cachedInputTokens: raw.input_tokens_details.cached_tokens, + cacheReadInputTokens: raw.input_tokens_details.cached_tokens, + } + : {}), + ...(typeof raw.input_tokens_details?.cache_write_tokens === "number" + ? { cacheCreationInputTokens: raw.input_tokens_details.cache_write_tokens } + : {}), + ...(typeof raw.input_tokens_details?.cache_write_1h_tokens === "number" + ? { cacheCreation1hInputTokens: raw.input_tokens_details.cache_write_1h_tokens } : {}), + ...(typeof raw.output_tokens_details?.reasoning_tokens === "number" + ? { reasoningOutputTokens: raw.output_tokens_details.reasoning_tokens } + : {}), + }; + } + if (typeof raw.prompt_tokens === "number" && typeof raw.completion_tokens === "number") { + return { + inputTokens: raw.prompt_tokens, + outputTokens: raw.completion_tokens, + cacheTelemetry: source === "upstream" ? rawCacheTelemetry(raw) : { source: "client", usagePresent: true }, + ...(typeof raw.total_tokens === "number" ? { totalTokens: raw.total_tokens } : {}), + ...(typeof raw.prompt_tokens_details?.cached_tokens === "number" + ? { + cachedInputTokens: raw.prompt_tokens_details.cached_tokens, + cacheReadInputTokens: raw.prompt_tokens_details.cached_tokens, + } + : {}), + ...(typeof raw.prompt_tokens_details?.cache_write_tokens === "number" + ? { cacheCreationInputTokens: raw.prompt_tokens_details.cache_write_tokens } + : {}), + ...(typeof raw.completion_tokens_details?.reasoning_tokens === "number" + ? { reasoningOutputTokens: raw.completion_tokens_details.reasoning_tokens } + : {}), + }; + } + return undefined; +} diff --git a/src/usage/log.ts b/src/usage/log.ts index e9e61d2da0c..daff01be87b 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 { redactSecretString, sanitizeLogMetadataString } from "../lib/redact"; import { usageDisplayTotalTokens } from "./totals"; +import { cacheProvenance, cacheProvenanceForRecord, normalizeCacheTelemetry } from "./cache-telemetry"; import { normalizePersistedJevDecision, type PersistedJevDecisionV1, @@ -95,8 +96,8 @@ export type UsageCredentialSource = "grok-oauth" | "xai-api-key"; * Where a row's cache-token detail came from. * * Strict-client normalization emits zero-default token-detail objects on every bridged wire - * (`responsesUsage` in src/bridge.ts), so a `cached_tokens: 0` read back off that wire is a - * wire-compatibility artifact and not a measured cache miss. The three values stay distinct all + * (`responsesUsage` in src/bridge.ts), so a `cached_tokens: 0` read back off that wire alone + * cannot distinguish a compatibility artifact from a measured cache miss. The three values stay distinct all * the way to the summary because folding `synthesized` or `unknown` into `observed` is what * lets a pool that discarded every warm prefix still report a plausible cache hit rate (#4546). */ @@ -113,22 +114,16 @@ export function isKnownCacheTelemetryProvenance(value: unknown): value is CacheT /** * Classify one usage record's cache detail. * - * `wireParsed` means the counts were read back off a response wire rather than reported raw by - * the adapter. An all-zero cache detail from that source cannot be told apart from the zero - * defaults the normalizer writes, so it is `synthesized`; the same shape reported raw is a real - * zero and stays `observed`. A record with no cache fields at all is `unknown`, which is not a - * zero either. + * Presence evidence from the upstream/adapter boundary distinguishes real zero from defaulted + * zero. The legacy wireParsed argument is accepted for compatibility, never used as evidence. + * Zero-only historical rows without evidence remain unknown; positive legacy readings remain + * usable because a zero-default normalizer could not have produced them. */ export function classifyCacheTelemetryProvenance( usage: OcxUsage | undefined, - options: { wireParsed?: boolean } = {}, + _options: { wireParsed?: boolean } = {}, ): CacheTelemetryProvenance { - if (!usage) return "unknown"; - const present = [usage.cachedInputTokens, usage.cacheReadInputTokens, usage.cacheCreationInputTokens] - .filter((value): value is number => typeof value === "number" && Number.isFinite(value)); - if (present.length === 0) return "unknown"; - if (present.some(value => value > 0)) return "observed"; - return options.wireParsed === true ? "synthesized" : "observed"; + return cacheProvenance(usage); } export interface PersistedUsageAttempt { @@ -567,7 +562,11 @@ export function usageStatusForFinalLog(usage: OcxUsage | undefined): UsageStatus function normalizeUsageValue(usage: OcxUsage | undefined): OcxUsage | undefined { if (!usage) return undefined; + const cacheTelemetry = normalizeCacheTelemetry(usage.cacheTelemetry) + ?? (usage.cacheTelemetry !== undefined + ? { source: "aggregate" as const, usagePresent: true, complete: false } : undefined); return { + ...(cacheTelemetry ? { cacheTelemetry } : {}), inputTokens: usage.inputTokens, outputTokens: usage.outputTokens, // Absolute active-context checkpoint (types.ts). Stateful providers such as Kiro report @@ -775,7 +774,7 @@ function normalizeUsageAttempt(raw: unknown): PersistedUsageAttempt | null { : {}), ...(typeof attempt.errorCode === "string" ? { errorCode: attempt.errorCode } : {}), ...(isKnownCacheTelemetryProvenance(attempt.cacheProvenance) - ? { cacheProvenance: attempt.cacheProvenance } + ? { cacheProvenance: cacheProvenanceForRecord(attempt.usage as OcxUsage | undefined, attempt.cacheProvenance) } : {}), ...(isLabRouteSubjectId(attempt.labRouteSubjectId) ? { labRouteSubjectId: attempt.labRouteSubjectId } @@ -1068,7 +1067,7 @@ function normalizeUsageEntry(entry: PersistedUsageEntry): PersistedUsageEntry { ...(Array.isArray(entry.attempts) ? { attempts } : {}), ...(spend ? { spend } : {}), ...(isKnownCacheTelemetryProvenance(entry.cacheProvenance) - ? { cacheProvenance: entry.cacheProvenance } + ? { cacheProvenance: cacheProvenanceForRecord(entry.usage, entry.cacheProvenance) } : {}), ...(transportPhase ? { transportPhase } : {}), ...(terminalSource ? { terminalSource } : {}), diff --git a/src/usage/summary.ts b/src/usage/summary.ts index c84265636cc..be54033ddf8 100644 --- a/src/usage/summary.ts +++ b/src/usage/summary.ts @@ -1,10 +1,10 @@ import { baseProviderLabel } from "../providers/label"; import { canonicalAntigravityUsageModel } from "../providers/antigravity-models"; import { usageDisplayTotalTokens } from "./totals"; +import { aggregateCacheTelemetry, cacheProvenanceForRecord, normalizeCacheTelemetry } from "./cache-telemetry"; import type { UsageTimeWindow } from "./time-range"; import { isUnresolvedRequestedModel, usageModelPriceOptions } from "./model-identity"; import { - classifyCacheTelemetryProvenance, isCodexUsageAccountLogLabel, type CacheTelemetryProvenance, type PersistedUsageEntry, @@ -247,8 +247,9 @@ export function cacheTokensFromUsage(usage?: PersistedUsageEntry["usage"]): { hasCacheTelemetry: boolean; } { if (!usage) return { read: undefined, creation: undefined, hasCacheTelemetry: false }; - const creation = usage.cacheCreationInputTokens; - const read = typeof usage.cacheReadInputTokens === "number" + const evidence = normalizeCacheTelemetry(usage.cacheTelemetry); + const creation = evidence ? evidence.creation : usage.cacheCreationInputTokens; + const read = evidence ? evidence.read : typeof usage.cacheReadInputTokens === "number" ? usage.cacheReadInputTokens : typeof usage.cachedInputTokens === "number" && typeof creation === "number" ? Math.max(0, usage.cachedInputTokens - creation) @@ -262,21 +263,22 @@ export function cacheTokensFromUsage(usage?: PersistedUsageEntry["usage"]): { /** * Cache tokens plus the provenance that says whether they may be averaged. * - * A persisted `cacheProvenance` wins; a row written before the field existed is reconstructed - * from its own shape, which reproduces the previous reading exactly (telemetry present is - * observed, absent is unknown) so historical rows do not change meaning. Only `observed` reaches + * Validated original evidence wins. Historical zero-only rows cannot distinguish measured + * misses from client defaults, regardless of their old provenance label. Only `observed` reaches * a hit-rate denominator: a synthesized zero was emitted for wire compatibility and an unknown * was never measured, and averaging either as a zero is how a cold pool reports a warm cache. */ export function cacheObservationFromUsage( usage: PersistedUsageEntry["usage"], provenance: CacheTelemetryProvenance | undefined, -): { read: number | undefined; creation: number | undefined; provenance: CacheTelemetryProvenance } { +): { read: number | undefined; creation: number | undefined; provenance: CacheTelemetryProvenance; readObserved: boolean } { const { read, creation, hasCacheTelemetry } = cacheTokensFromUsage(usage); // A row cannot have observed what it does not carry, so a stored label never opens the // denominator for a record with no cache fields in it. - if (!usage || !hasCacheTelemetry) return { read, creation, provenance: "unknown" }; - return { read, creation, provenance: provenance ?? classifyCacheTelemetryProvenance(usage) }; + if (!usage || !hasCacheTelemetry) return { read, creation, provenance: "unknown", readObserved: false }; + const observed = cacheProvenanceForRecord(usage, provenance); + return { read, creation, provenance: observed, readObserved: observed === "observed" + && typeof read === "number" && normalizeCacheTelemetry(usage.cacheTelemetry)?.readComplete !== false }; } export function calculateCacheHitRate( @@ -493,10 +495,8 @@ export function usageAttributions(entry: PersistedUsageEntry): UsageAttribution[ }]; } return entry.attempts.map(attempt => { - // An attempt's own provenance wins; the row's is the fallback for a child written before - // attempt-level provenance existed. A child carrying no cache fields still resolves to - // unknown in cacheObservationFromUsage, so it cannot inherit a sibling's observation. - const cacheProvenance = attempt.cacheProvenance ?? entry.cacheProvenance; + // A parent or sibling is not evidence about this physical attempt. + const cacheProvenance = attempt.cacheProvenance; return { requestId: entry.requestId, provider: attempt.provider, @@ -562,6 +562,12 @@ function projectedComboUsage( if (!hasUsage && !hasTotalTokens) return {}; const usage = hasUsage ? { + cacheTelemetry: aggregateCacheTelemetry( + attempts.filter(attempt => attempt.usage || (attempt.sendCount !== 0 && attempt.locallyAnswered !== true)) + .map(({ usage }) => usage && !usage.cacheTelemetry + ? { ...usage, cachedInputTokens: cacheTokensFromUsage(usage).read, cacheReadInputTokens: cacheTokensFromUsage(usage).read } + : usage), + ), inputTokens, outputTokens, ...(hasCacheTelemetry ? { cachedInputTokens, cacheReadInputTokens, cacheCreationInputTokens } : {}), @@ -626,10 +632,10 @@ function addCacheProvenanceTotals( totals: UsageSummaryTotals, entry: Pick, ): void { - const { provenance } = cacheObservationFromUsage(entry.usage, entry.cacheProvenance); + const { provenance, readObserved } = cacheObservationFromUsage(entry.usage, entry.cacheProvenance); if (provenance === "observed") { totals.cacheObservedRequests = (totals.cacheObservedRequests ?? 0) + 1; - totals.cacheObservedInputTokens = (totals.cacheObservedInputTokens ?? 0) + (entry.usage?.inputTokens ?? 0); + if (readObserved) totals.cacheObservedInputTokens = (totals.cacheObservedInputTokens ?? 0) + (entry.usage?.inputTokens ?? 0); return; } if (provenance === "synthesized") { @@ -730,6 +736,8 @@ interface UsageModelAccumulator { cacheObserved: boolean; /** Input tokens from attributions with OBSERVED cache detail; the hit-rate denominator. */ cacheObservedInputTokens: number; + /** Read numerator from exactly the same complete observations as the denominator. */ + cacheObservedReadTokens: number; throughputOutputTokens: number; throughputDurationMs: number; throughputSamples: number; @@ -931,6 +939,7 @@ function blankModelAccumulator( cacheCreationInputTokens: 0, cacheObserved: false, cacheObservedInputTokens: 0, + cacheObservedReadTokens: 0, throughputOutputTokens: 0, throughputDurationMs: 0, throughputSamples: 0, @@ -962,6 +971,7 @@ function mergeModelAccumulator(target: UsageModelAccumulator, source: UsageModel target.cacheCreationInputTokens += source.cacheCreationInputTokens; target.cacheObserved ||= source.cacheObserved; target.cacheObservedInputTokens += source.cacheObservedInputTokens; + target.cacheObservedReadTokens += source.cacheObservedReadTokens; target.throughputOutputTokens += source.throughputOutputTokens; target.throughputDurationMs += source.throughputDurationMs; target.throughputSamples += source.throughputSamples; @@ -1139,7 +1149,7 @@ function buildDayModels( outputTokens: model.outputTokens, cacheReadInputTokens: model.cacheReadInputTokens, cacheCreationInputTokens: model.cacheCreationInputTokens, - cacheHitRate: calculateCacheHitRate(model.cacheObserved, model.cacheObservedInputTokens, model.cacheReadInputTokens), + cacheHitRate: calculateCacheHitRate(model.cacheObserved, model.cacheObservedInputTokens, model.cacheObservedReadTokens), cacheObservedInputTokens: model.cacheObservedInputTokens, ...(model.estimatedCostUsd !== undefined ? { estimatedCostUsd: model.estimatedCostUsd } : {}), })); @@ -1178,7 +1188,7 @@ function buildUsageModels( cachedInputTokens: model.cacheReadInputTokens, cacheReadInputTokens: model.cacheReadInputTokens, cacheCreationInputTokens: model.cacheCreationInputTokens, - cacheHitRate: calculateCacheHitRate(model.cacheObserved, model.cacheObservedInputTokens, model.cacheReadInputTokens), + cacheHitRate: calculateCacheHitRate(model.cacheObserved, model.cacheObservedInputTokens, model.cacheObservedReadTokens), cacheObservedInputTokens: model.cacheObservedInputTokens, priceCoverageRatio: requests > 0 ? counts.pricedRequests / requests : 0, pricedRequests: counts.pricedRequests, @@ -1223,7 +1233,7 @@ function buildUsageProviders( cachedInputTokens: provider.cacheReadInputTokens, cacheReadInputTokens: provider.cacheReadInputTokens, cacheCreationInputTokens: provider.cacheCreationInputTokens, - cacheHitRate: calculateCacheHitRate(provider.cacheObserved, provider.cacheObservedInputTokens, provider.cacheReadInputTokens), + cacheHitRate: calculateCacheHitRate(provider.cacheObserved, provider.cacheObservedInputTokens, provider.cacheObservedReadTokens), cacheObservedInputTokens: provider.cacheObservedInputTokens, priceCoverageRatio: requests > 0 ? counts.pricedRequests / requests : 0, pricedRequests: counts.pricedRequests, @@ -1403,14 +1413,15 @@ class StreamingUsageSummaryAccumulator implements UsageSummaryAccumulator { breakdown.throughputDurationMs += attribution.durationMs!; breakdown.throughputSamples += 1; } - const { read, creation, provenance } = cacheObservationFromUsage( + const { read, creation, readObserved } = cacheObservationFromUsage( attribution.usage, attribution.cacheProvenance, ); // Only an observation opens the denominator. A synthesized zero and an unreported detail // both contribute their tokens to inputTokens and nothing to the cache average, which is // the difference between "no cache reads measured" and "no cache reads happened". - if (provenance === "observed") { + if (readObserved) { + breakdown.cacheObservedReadTokens += read!; breakdown.cacheObserved = true; breakdown.cacheObservedInputTokens += attribution.usage.inputTokens; } diff --git a/src/web-search/loop.ts b/src/web-search/loop.ts index 43baa4c57db..0bfa0817e66 100644 --- a/src/web-search/loop.ts +++ b/src/web-search/loop.ts @@ -1,3 +1,4 @@ +import { aggregateCacheTelemetry, withAdapterCacheTelemetry } from "../usage/cache-telemetry"; import { bindAnthropicRejectionResponse } from "../adapters/anthropic-rejection-memo"; import { anthropicDeclaredTools } from "../adapters/anthropic-tool-catalog"; import { enableAnthropicReplayCapture, takeAnthropicReplay, bindAnthropicReplay, type AnthropicReplaySnapshot } from "../adapters/anthropic-replay"; @@ -464,6 +465,20 @@ export async function runWithWebSearch(deps: WebSearchLoopDeps): Promise { + const merged = mergeUsage(countersOnly(hiddenUsage), round); + return merged && (hiddenUsageMissing || !round) + ? { ...merged, cacheTelemetry: aggregateCacheTelemetry([merged, undefined]) } : merged; + }; + const addHiddenUsage = (round: OcxUsage | undefined): void => { + hiddenUsageMissing ||= !round; + hiddenUsage = mergeUsage(hiddenUsage, round); + if (hiddenUsage && hiddenUsageMissing) hiddenUsage = { + ...hiddenUsage, cacheTelemetry: aggregateCacheTelemetry([hiddenUsage, undefined]), + }; + }; let accountRefusalOutputStarted = false; const connectTimeoutMs = deps.connectTimeoutMs ?? 200_000; const routedModelStallTimeoutMs = deps.routedModelStallTimeoutMs ?? 200_000; @@ -712,7 +727,10 @@ export async function runWithWebSearch(deps: WebSearchLoopDeps): Promise {}; + let errorUsageReported = false; try { const parse: ProviderAdapter["parseStream"] = (response, budget) => { if (prepared.responseAdapter.name === "anthropic") releaseCapture = enableAnthropicReplayCapture(response); return prepared.responseAdapter.parseStream(response, budget); }; - for await (const event of parseStreamWithProgress(prepared.response, parse, { + for await (const parsedEvent of parseStreamWithProgress(prepared.response, parse, { signal, inactivityTimeoutMs: routedModelStallTimeoutMs, translatorBudget, preserveAdapterError: deps.thinkingRecovery !== undefined, // A pass that fails was still billed; the error path reports it with the hidden passes. - onErrorUsage: usage => { hiddenUsage = mergeUsage(hiddenUsage, usage); }, + onErrorUsage: usage => { errorUsageReported = true; addHiddenUsage(usage); }, })) { + let event = parsedEvent; if (event.type === "done") { anthropicReplay = takeAnthropicReplay(event); if (anthropicReplay) replaySnapshots.add(anthropicReplay); } + if ((event.type === "done" || event.type === "incomplete") && event.usage) { + event = { ...event, usage: withAdapterCacheTelemetry(event.usage) }; + } if (event.type === "heartbeat") yield event; // Kiro's explicit-completion protocol marks ordinary assistant text as commentary while // it performs a bounded final-answer retry. That text is safe to surface immediately and @@ -826,6 +849,7 @@ export async function runWithWebSearch(deps: WebSearchLoopDeps): Promise event.type))], })); - hiddenUsage = mergeUsage(hiddenUsage, terminalEvent.usage); + addHiddenUsage(terminalEvent.usage); if (!split.hasMalformedToolCall && !split.hasRealToolCall && emptyAnswerRetries === 0) { emptyAnswerRetries++; console.warn("[web-search-loop] empty forced answer — retrying once with tool calls disabled"); @@ -1110,7 +1134,7 @@ export async function runWithWebSearch(deps: WebSearchLoopDeps): Promise deps.onUsage?.(mergeUsage(countersOnly(hiddenUsage), usage)) } : {}), + ...(deps.onUsage ? { onUsage: (usage: OcxUsage | undefined) => deps.onUsage?.(withHiddenUsage(usage)) } : {}), ...(deps.onCompletedResponse ? { onCompletedResponse: deps.onCompletedResponse } : {}), }, ); diff --git a/structure/advisor.md b/structure/advisor.md index 6c070725acf..fdebc92d6e3 100644 --- a/structure/advisor.md +++ b/structure/advisor.md @@ -33,7 +33,7 @@ tool arguments pass through without a retained copy and end replay retention for Reconstruction reserves space before joining or parsing admitted sources; raw and replay owners overlap until the replacement is admitted. Appended history remains charged through the guard's final exit. Accumulated usage has a separate retained owner across legs; replacement admits the -new usage while raw terminal data and prior usage remain charged. An optional request translator +new usage while raw terminal data and prior usage remain charged, including bounded cache-evidence metadata slack. Missing worker-leg usage reduces aggregate completeness without synthetic tokens (`tests/advisor/advisor-cache-evidence-retention.test.ts`). An optional request translator budget receives separate local charges, never shared event/call leases or disposal. All exits, including iterator close, release only the guard's own charges. Refusals use content-free 502 `upstream_error` / `translation_buffer_limit` events. diff --git a/structure/dashboard-and-usage.md b/structure/dashboard-and-usage.md index e38d47e0faf..a6a2f050a2f 100644 --- a/structure/dashboard-and-usage.md +++ b/structure/dashboard-and-usage.md @@ -307,15 +307,15 @@ that discarded a warmed prompt-cache prefix. `/api/usage` totals these as `sends accounting source, and `attemptCount` is the smaller number because retry layers re-send inside one attempt. -Cache detail is qualified by provenance rather than read as a measurement. `cacheProvenance` is -`observed`, `synthesized` or `unknown`: strict-client normalization emits zero-default -token-detail objects on every bridged wire, so a `cached_tokens: 0` recovered from a parsed wire -is a wire-compatibility artifact, and a row with no cache fields measured nothing at all. Only -observed input tokens reach the `cacheHitRate` denominator, reported alongside it as -`cacheObservedInputTokens`, and the summary counts the three provenances separately. A row -written before the field existed is reconstructed from its own shape, so historical rows keep -their previous reading. `/api/logs` marks a non-observed detail with `cache_detail_missing` on -the cost estimate rather than pricing the turn as a measured uncached send. +Cache detail is qualified by explicit `cacheTelemetry` evidence from `src/usage/cache-telemetry.ts`; `cacheProvenance` is `observed`, `synthesized` or `unknown`; upstream zero is observed, missing +fields remain unknown, and bridged client defaults cannot manufacture an observation. Canonical +`cachedInputTokens` is cache read, not read plus creation; reads and writes are summed separately. Unlabelled historic combined-cache records retain their legacy read/write recovery. +Multi-round guards retain per-field completeness, including sent rounds without usage. Unsent, +usage-free candidates and local answers do not dilute measured attempt evidence. Only complete +observed reads and their matching input tokens enter `cacheHitRate`/`cacheObservedInputTokens`; +partial totals remain visible but do not inflate the rate. Ledger reloads preserve the allowlisted +metadata; legacy zero-only rows stay unknown and attempts never borrow parent provenance. +`/api/logs` marks non-observed detail `cache_detail_missing` rather than pricing it as uncached. A pool selection that produced no account reaches no auth context, so its cause is recorded on the request that failed for it: reasons are held per (thread, model lane) and consumed by that @@ -398,7 +398,7 @@ untouched. For diagnosing cache-read instability without capturing content, set `OPENCODEX_CACHE_DEBUG=1` before start. `src/usage/cache-diagnostic.ts` then writes one record per finalized request to `~/.opencodex/cache-debug.jsonl` (same `0o600` file, same 200-to-100 rolling bound) holding only -presence booleans, counts, closed enums, the raw upstream cache counter before defaulting, and +presence booleans, counts, closed enums, separate raw observation/usage/read/write presence, and process-local HMAC equality tags for the prompt-cache key, allowlisted session headers, the account log label, and ordered instruction/tool/message blocks (capped at 128 per section, first divergent section/index only). The signing key is created at process start and never persisted, so tags diff --git a/structure/providers-and-adapters.md b/structure/providers-and-adapters.md index 04987b76b41..3bf58463537 100644 --- a/structure/providers-and-adapters.md +++ b/structure/providers-and-adapters.md @@ -12,6 +12,8 @@ A shared-quota Anthropic 429 or classified pre-output account 403 records the se The Anthropic helper sends share the same routing authority: `getAnthropicSidecarAccessToken` resolves the vision-describe and web-search sidecars' helper model through the same first-match route decision, so a routed send authenticates as the route's own account rather than whatever pool account happens to be active. A strict route with no eligible account fails the helper locally instead of silently falling back to the active outsider, matching the primary-traffic contract; callers without a pool config keep the plain stored-credential path. Generic OAuth conversation ownership follows [the generic account-pool contract](providers/generic-account-pool.md#conversation-affinity). +Anthropic adapter usage preserves raw cache-read/write presence before numeric defaults, so write-only usage cannot become an observed zero read. Canonical cache read and creation remain separate; `tests/adapters/anthropic/anthropic-cache-evidence.test.ts` pins JSON/SSE parsing and non-leaking client serialization. + ## GitHub Copilot Auto selection `src/providers/github-copilot-transport.ts` retains the credential-specific destination and headers. Automatic selection requires a nonempty catalog whose every valid row explicitly has `model_picker_enabled: false`; missing or malformed permissions retain named routes. Named picker projection removes only explicitly false rows. diff --git a/structure/providers/opengateway.md b/structure/providers/opengateway.md index 12eeff8ec3c..9694328d21e 100644 --- a/structure/providers/opengateway.md +++ b/structure/providers/opengateway.md @@ -28,7 +28,7 @@ background mode and nonreplayable responses prevent replay. This destination def `emptyCompletionRetry: false` and `OCX_EMPTY_COMPLETION_RETRY=0` disable it. `src/server/responses/passthrough-completion.ts` connects one replacement to the existing send budget, pacing, accounting and abort path. Even a replacement HTTP 503 or connection reset cannot -add another physical send. Discarded usage is recorded once per attempt; a second empty completion +add another physical send. Discarded usage is recorded once per attempt with upstream cache-counter presence preserved before client defaults; a second empty completion fails as `empty_completion_retry_failed`, while HTTP failures and budget refusals retain their response. `src/server/responses/passthrough-dispatch.ts` caps that recovery's allowance at one send and disables ambiguous reset resends on it. Text, refusal, tool/action or unknown events release the original bytes without replay. Inspection diff --git a/structure/transports/responses.md b/structure/transports/responses.md index 805c208809d..33717e07db3 100644 --- a/structure/transports/responses.md +++ b/structure/transports/responses.md @@ -1,6 +1,6 @@ # Responses Transport -Native result continuations and function-result injection follow [the mode-specific result and control contract](streaming-health.md#experimental-native-function-result-injection); this surface does not infer upstream support or alter its defaults. +Native JSON/SSE inspection and Responses passthrough capture raw cache evidence before client normalization; bridged guards preserve missing-round provenance. `tests/responses/cache-telemetry-http.test.ts` covers auto/legacy/eager relay, fragmentation, cancellation and slow consumers without upstream calls. Native result continuations and function-result injection follow [the mode-specific result and control contract](streaming-health.md#experimental-native-function-result-injection); this surface does not infer upstream support or alter its defaults. Native steering follows [the shared WebSocket contract](streaming-health.md#experimental-native-mid-turn-steering); this surface's defaults remain unchanged. diff --git a/structure/transports/streaming-health.md b/structure/transports/streaming-health.md index c2812203286..54d98e335be 100644 --- a/structure/transports/streaming-health.md +++ b/structure/transports/streaming-health.md @@ -411,7 +411,7 @@ working without inventing IDs or silently dropping the steering instruction. Native chains bypass single-response SSE repair/terminal truncation. Wire IDs, lane IDs and control events are preserved. A single bounded reader owns delivery; client cancellation, -account invalidation and shutdown abort its upstream. Numeric usage is summed once per +account invalidation and shutdown abort its upstream. Cache evidence follows each native terminal, with missing usage reducing aggregate completeness rather than fabricating a cache read; control events are excluded (`tests/responses/cache-telemetry-native-seams.test.ts`). Numeric usage is summed once per response; steering control frames (which can contain returned user input) are not log samples. Bounds: 32 outstanding submissions, 128 response IDs per chain, 32 MiB replay journal diff --git a/tests/adapters/anthropic/anthropic-cache-evidence.test.ts b/tests/adapters/anthropic/anthropic-cache-evidence.test.ts new file mode 100644 index 00000000000..c13a8f6b126 --- /dev/null +++ b/tests/adapters/anthropic/anthropic-cache-evidence.test.ts @@ -0,0 +1,41 @@ +import { describe, expect, test } from "bun:test"; +import { createAnthropicAdapter } from "../../../src/adapters/anthropic"; +import { responsesUsage } from "../../../src/bridge/internal"; +import { cacheObservationFromUsage } from "../../../src/usage/summary"; +import type { AdapterEvent, OcxUsage } from "../../../src/types"; +import { withTestTranslatorBudget } from "../../helpers/translator-budget"; + +const adapter = () => withTestTranslatorBudget(createAnthropicAdapter({ + adapter: "anthropic", baseUrl: "https://api.anthropic.com", apiKey: "fixture-key", +})); +function terminal(events: AdapterEvent[]): OcxUsage | undefined { + const event = events.find(event => event.type === "done"); + return event?.type === "done" ? event.usage : undefined; +} +for (const stream of [false, true]) describe(`Anthropic ${stream ? "SSE" : "JSON"} raw cache presence`, () => { + for (const read of [undefined, 0, 4, 40]) test(`reads ${read ?? "absent"} with ten writes stay distinct`, async () => { + const usage = { input_tokens: 50, output_tokens: 2, cache_creation_input_tokens: 10, + ...(read === undefined ? {} : { cache_read_input_tokens: read }) }; + let events: AdapterEvent[]; + if (stream) { + const frames = [ + { type: "message_start", message: { usage: { ...usage, output_tokens: 0 } } }, + { type: "message_delta", delta: { stop_reason: "end_turn" }, usage: { output_tokens: 2 } }, + { type: "message_stop" }, + ].map(frame => `event: ${frame.type}\ndata: ${JSON.stringify(frame)}\n\n`).join(""); + events = []; + for await (const event of adapter().parseStream(new Response(frames))) events.push(event); + } else { + events = await adapter().parseResponse!(Response.json({ content: [{ type: "text", text: "ok" }], + stop_reason: "end_turn", usage })) as AdapterEvent[]; + } + const value = terminal(events)!; + expect(value.inputTokens).toBe(60 + (read ?? 0)); + expect(value.cacheTelemetry).toEqual({ source: "upstream", usagePresent: true, creation: 10, + ...(read === undefined ? {} : { read }) }); + expect(cacheObservationFromUsage(value, undefined)).toMatchObject({ read, creation: 10, readObserved: read !== undefined }); + const client = responsesUsage(value); + expect(JSON.stringify(client)).not.toContain("cacheTelemetry"); + expect(client.input_tokens_details).toMatchObject({ cached_tokens: read ?? 0, cache_write_tokens: 10 }); + }); +}); diff --git a/tests/adapters/anthropic/anthropic-error-stop-reason.test.ts b/tests/adapters/anthropic/anthropic-error-stop-reason.test.ts index eaf07ef5492..47cd30036f9 100644 --- a/tests/adapters/anthropic/anthropic-error-stop-reason.test.ts +++ b/tests/adapters/anthropic/anthropic-error-stop-reason.test.ts @@ -21,7 +21,7 @@ describe("Anthropic usage numeric boundary", () => { })) as AdapterEvent[]; const done = events.find(event => event.type === "done"); expect(done && "usage" in done ? done.usage : undefined) - .toEqual(usage ? { inputTokens: 0, outputTokens: 0 } : undefined); + .toEqual(usage ? { inputTokens: 0, outputTokens: 0, cacheTelemetry: { source: "upstream", usagePresent: true } } : undefined); } }); @@ -36,6 +36,7 @@ describe("Anthropic usage numeric boundary", () => { const done = events.find(event => event.type === "done"); expect(done && "usage" in done ? done.usage : undefined).toEqual({ inputTokens: 15, outputTokens: 4, cachedInputTokens: 3, cacheReadInputTokens: 3, cacheCreationInputTokens: 2, + cacheTelemetry: { source: "upstream", usagePresent: true, read: 3, creation: 2 }, }); }); diff --git a/tests/adapters/anthropic/anthropic-thinking-usage.test.ts b/tests/adapters/anthropic/anthropic-thinking-usage.test.ts index 3706bd248ef..73aae062732 100644 --- a/tests/adapters/anthropic/anthropic-thinking-usage.test.ts +++ b/tests/adapters/anthropic/anthropic-thinking-usage.test.ts @@ -54,6 +54,7 @@ describe("Anthropic reported thinking usage (#6719)", () => { expect(terminalUsage(events)).toEqual({ inputTokens: 15, outputTokens: 292, reasoningOutputTokens: 156, cachedInputTokens: 3, cacheReadInputTokens: 3, cacheCreationInputTokens: 2, + cacheTelemetry: { source: "upstream", usagePresent: true, read: 3, creation: 2 }, }); const json = buildResponseJSON(events, "anthropic/claude-test"); expect(json.usage).toMatchObject({ output_tokens: 292, total_tokens: 307, output_tokens_details: { reasoning_tokens: 156 } }); @@ -94,7 +95,7 @@ describe("Anthropic reported thinking usage (#6719)", () => { test("zero is reported while absent details remain unreported internally", async () => { expect(terminalUsage(await buffered({ ...counts, output_tokens_details: { thinking_tokens: 0 } }))?.reasoningOutputTokens).toBe(0); expect(terminalUsage(await buffered(counts))).not.toHaveProperty("reasoningOutputTokens"); - expect(terminalUsage(await buffered({}))).toEqual({ inputTokens: 0, outputTokens: 0 }); + expect(terminalUsage(await buffered({}))).toEqual({ inputTokens: 0, outputTokens: 0, cacheTelemetry: { source: "upstream", usagePresent: true } }); }); test.each([null, [], "details", {}, { thinking_tokens: "156" }, { thinking_tokens: null }, { thinking_tokens: -1 }, { thinking_tokens: true }, { thinking_tokens: 293 }].map(outputDetails => ({ outputDetails })))( @@ -102,6 +103,7 @@ describe("Anthropic reported thinking usage (#6719)", () => { for (const events of [await buffered({ ...counts, output_tokens_details: outputDetails }), await streaming({ output_tokens: 292, output_tokens_details: outputDetails })]) { expect(terminalUsage(events)).toEqual({ inputTokens: 15, outputTokens: 292, cachedInputTokens: 3, cacheReadInputTokens: 3, cacheCreationInputTokens: 2, + cacheTelemetry: { source: "upstream", usagePresent: true, read: 3, creation: 2 }, }); } }, diff --git a/tests/advisor/advisor-cache-evidence-retention.test.ts b/tests/advisor/advisor-cache-evidence-retention.test.ts new file mode 100644 index 00000000000..29086c24da5 --- /dev/null +++ b/tests/advisor/advisor-cache-evidence-retention.test.ts @@ -0,0 +1,63 @@ +import { expect, test } from "bun:test"; +import type { OcxUsage } from "../../src/types"; +import { AdvisorRetention } from "../../src/server/responses/advisor-retention"; +import { jsonUtf8Bytes } from "../../src/lib/json-byte-size"; +import { TranslatorBudgetExceededError } from "../../src/lib/translator-budget"; +import { createTestTranslatorBudget } from "../helpers/translator-budget"; + +const usage = (): OcxUsage => ({ inputTokens: 100, outputTokens: 1, cachedInputTokens: 40 }); + +test("first adapter cache observation retains exactly its transformed bytes", () => { + const budget = createTestTranslatorBudget(); + const retention = new AdvisorRetention(budget); + const original = usage(); + const first = retention.usage(undefined, original)!; + expect(first.cacheTelemetry).toEqual({ source: "adapter", usagePresent: true, read: 40 }); + expect(original.cacheTelemetry).toBeUndefined(); + expect(budget.snapshot().currentBytes).toBe(jsonUtf8Bytes(first) + 1); + const second = retention.usage(first, usage())!; + expect(second.cacheTelemetry).toMatchObject({ source: "aggregate", complete: true, read: 80, readComplete: true }); + expect(budget.snapshot().currentBytes).toBe(jsonUtf8Bytes(second) + 1); + retention.release(); + expect(budget.snapshot().currentBytes).toBe(0); +}); + +test.each([true, false])("missing physical usage remains unknown without fabricated tokens (first=%s)", missingFirst => { + const budget = createTestTranslatorBudget(); + const retention = new AdvisorRetention(budget); + const first = retention.usage(undefined, missingFirst ? undefined : usage()); + if (missingFirst) expect(budget.snapshot().currentBytes).toBe(0); + const second = retention.usage(first, missingFirst ? usage() : undefined)!; + expect(second).toMatchObject({ inputTokens: 100, outputTokens: 1, + cacheTelemetry: { source: "aggregate", complete: false, read: 40, readComplete: false } }); + expect(budget.snapshot().currentBytes).toBe(jsonUtf8Bytes(second) + 1); + retention.release(); + expect(budget.snapshot().currentBytes).toBe(0); +}); + +test("failed replacement does not leak its reservation or release the previous owner", () => { + const budget = createTestTranslatorBudget({ maxTurnBytes: 1000 }); + const retention = new AdvisorRetention(budget); + const first = retention.usage(undefined, usage())!; + const before = budget.snapshot().currentBytes; + expect(() => retention.usage(first, { ...usage(), rawUsage: { synthetic: "x".repeat(600) } })) + .toThrow(TranslatorBudgetExceededError); + expect(budget.snapshot().currentBytes).toBe(before); + expect(budget.snapshot().highWaterBytes).toBeLessThanOrEqual(1000); + retention.release(); + expect(budget.snapshot().currentBytes).toBe(0); +}); + +test("post-admission failure releases only the new copy reservation", () => { + const budget = createTestTranslatorBudget(); + const retention = new AdvisorRetention(budget); + const first = retention.usage(undefined, usage())!; + const before = budget.snapshot().currentBytes; + let reads = 0; + const second: OcxUsage = { inputTokens: 1, outputTokens: 1, + get cacheTelemetry() { if (++reads > 1) throw new Error("synthetic getter failure"); return undefined; } }; + expect(() => retention.usage(first, second)).toThrow("synthetic getter failure"); + expect(budget.snapshot().currentBytes).toBe(before); + retention.release(); + expect(budget.snapshot().currentBytes).toBe(0); +}); diff --git a/tests/advisor/advisor-retention.test.ts b/tests/advisor/advisor-retention.test.ts index 73459c4d3dc..0a3e5068204 100644 --- a/tests/advisor/advisor-retention.test.ts +++ b/tests/advisor/advisor-retention.test.ts @@ -271,7 +271,7 @@ test.each(["done", "error", "incomplete"] as const)("normal numeric usage is mer } finally { budget.dispose(); } }); -test("absent later usage preserves the admitted usage reference until iterator close", async () => { +test("absent later usage keeps admitted counters and incomplete cache evidence until iterator close", async () => { const budget = createTranslatorBudget(); const usage = usageFromOpenAIChat({ prompt_tokens_details: { cached_tokens: "x".repeat(400) } }); const guard = createAdvisorGuard({ consult: async () => ({ ok: true, isError: false, content: "advice" }), formatUnavailable: () => "limit" }); @@ -282,7 +282,7 @@ test("absent later usage preserves the admitted usage reference until iterator c expect((await iterator.next()).value).toEqual({ type: "assistant_boundary" }); const terminal = (await iterator.next()).value; expect(terminal).toMatchObject({ type: "done", usage }); - expect(terminal && "usage" in terminal ? terminal.usage : undefined).toBe(usage); + expect(terminal && "usage" in terminal ? terminal.usage : undefined).toEqual({ ...usage, cacheTelemetry: { source: "aggregate", usagePresent: true, complete: false, readComplete: false, creationComplete: false } }); expect(budget.snapshot().currentBytes).toBeGreaterThan(400); await iterator.return(); expect(budget.snapshot().currentBytes).toBe(0); @@ -291,7 +291,7 @@ test("absent later usage preserves the admitted usage reference until iterator c test("a usage merge refusal keeps the previous owner for one content-free budget error", async () => { const budget = createTranslatorBudget({ maxTurnBytes: 6_000 }); - const first = usageFromOpenAIChat({ prompt_tokens_details: { cached_tokens: "x".repeat(1_200) } }); + const first = usageFromOpenAIChat({ prompt_tokens_details: { cached_tokens: "x".repeat(1_200) } }); first.cacheTelemetry = { source: "adapter", usagePresent: true }; const second = usageFromOpenAIChat({ completion_tokens_details: { reasoning_tokens: "y".repeat(2_000) } }); try { const result = await run(stream([...call("c"), { type: "done", usage: first }]), budget, @@ -320,7 +320,7 @@ test("a successful usage replacement releases the previous large owner before th return stream([done]); }); expect(legs).toBe(2); - expect(result.events.at(-1)).toEqual({ type: "done", usage: { inputTokens: 3, outputTokens: 4, totalTokens: 7 } }); + expect(result.events.at(-1)).toEqual({ type: "done", usage: { inputTokens: 3, outputTokens: 4, totalTokens: 7, cacheTelemetry: { source: "aggregate", usagePresent: true, complete: false, readComplete: false, creationComplete: false } } }); expect(budget.snapshot().currentBytes).toBe(0); } finally { budget.dispose(); } }); diff --git a/tests/fixtures/test-layout-expected.json b/tests/fixtures/test-layout-expected.json index 563b2d53550..e7d5b638829 100644 --- a/tests/fixtures/test-layout-expected.json +++ b/tests/fixtures/test-layout-expected.json @@ -1,4 +1,4 @@ -{ "combo-description.test.ts": "routing", "combo-description-catalog.test.ts": "codex-integration", "catalog-auto-review-override.test.ts": "codex-integration", "management-auto-review-settings.test.ts": "server", "management-auto-review-auth.test.ts": "server", "prefer-model-alias-ids.test.ts": "server", "responses-mimo-envelope.test.ts": "responses", "responses-call-id-linkage.test.ts": "responses", +{ "cache-telemetry-native-seams.test.ts": "responses", "anthropic-cache-evidence.test.ts": "adapters/anthropic", "advisor-cache-evidence-retention.test.ts": "advisor", "cache-telemetry-flow.test.ts": "responses", "cache-telemetry-guard-mergers.test.ts": "responses", "cache-telemetry-http.test.ts": "responses", "cache-telemetry-attempts.test.ts": "usage", "cache-telemetry-evidence.test.ts": "usage", "web-search-loop-cache-evidence.test.ts": "web-search", "combo-description.test.ts": "routing", "combo-description-catalog.test.ts": "codex-integration", "catalog-auto-review-override.test.ts": "codex-integration", "management-auto-review-settings.test.ts": "server", "management-auto-review-auth.test.ts": "server", "prefer-model-alias-ids.test.ts": "server", "responses-mimo-envelope.test.ts": "responses", "responses-call-id-linkage.test.ts": "responses", "bridge-terminal-refusal.test.ts": "adapters", "loop-terminal-refusal.test.ts": "images", "web-search-terminal-refusal.test.ts": "web-search", diff --git a/tests/responses/cache-telemetry-flow.test.ts b/tests/responses/cache-telemetry-flow.test.ts new file mode 100644 index 00000000000..634b173759a --- /dev/null +++ b/tests/responses/cache-telemetry-flow.test.ts @@ -0,0 +1,259 @@ +import { afterEach, beforeEach, describe, expect, test } from "bun:test"; +import { mkdtempSync, readFileSync } from "node:fs"; +import { tmpdir } from "node:os"; +import { join } from "node:path"; +import type { ServerWebSocket } from "bun"; +import type { OcxConfig } from "../../src/types"; +import { createServeOptions, type ServeOptionsContext } from "../../src/server/index/serve-options"; +import { createWebsocketHandler } from "../../src/server/index/websocket-handler"; +import { tryAdmitTurn } from "../../src/server/lifecycle"; +import type { WsData } from "../../src/server/ws-bridge"; +import { addFinalRequestLog, applyResponseLogMetadata, beginRequestAttempt, finishRequestAttempt, + getRequestLogEntries, clearRequestLogsForTests, noteAttemptSend, type RequestLogContext } from "../../src/server/request-log"; +import { cacheDiagnosticPath } from "../../src/usage/cache-diagnostic"; +import { readUsageEntries } from "../../src/usage/log"; +import { summarizeUsage } from "../../src/usage/summary"; +import { responsesUsage } from "../../src/bridge/internal"; +import { acquireOwnedSpendHome } from "../helpers/owned-spend-home"; +import { removeTreeWithRetry } from "../helpers/remove-tree"; + +const PROXY_ENV = ["HTTP_PROXY", "HTTPS_PROXY", "ALL_PROXY", "NO_PROXY", "http_proxy", "https_proxy", "all_proxy", "no_proxy"]; +const ENV = [...PROXY_ENV, "OPENCODEX_HOME", "OPENCODEX_CACHE_DEBUG"]; +let saved: Record; +let home: string; +let release: () => void; +const realWs = globalThis.WebSocket; +const realFetch = globalThis.fetch; +let rawUsage: unknown; +let terminal = "completed"; +let upstreamSends = 0; +let interimUsage: unknown; +const settings = (): OcxConfig => ({ port: 0, bind: "127.0.0.1", defaultProvider: "openai", websockets: true, + providers: { openai: { adapter: "openai-responses", baseUrl: "https://chatgpt.com/backend-api/codex", + authMode: "forward", codexAccountMode: "direct" } } } as OcxConfig); + +/** The real WS transport and parsers run; only the external socket is replaced. */ +class UpstreamSocket extends EventTarget { + readyState = 0; + constructor(..._args: unknown[]) { super(); queueMicrotask(() => { this.readyState = 1; this.dispatchEvent(new Event("open")); }); } + send(text: string) { + const frame = JSON.parse(text); + if (frame.type !== "response.create") return; + upstreamSends++; + const usage = rawUsage; + queueMicrotask(() => { + this.emit({ type: "response.created", response: { id: "fixture-response", status: "in_progress", output: [], + ...(interimUsage === undefined ? {} : { usage: interimUsage }) } }); + this.emit({ type: "response.done", response: { id: "fixture-response", status: terminal, output: [], + ...(usage === undefined ? {} : { usage }) } }); + }); + } + emit(value: object) { this.dispatchEvent(new MessageEvent("message", { data: JSON.stringify(value) })); } + ping() { this.dispatchEvent(new Event("pong")); } + close() { if (this.readyState === 3) return; this.readyState = 3; this.dispatchEvent(new Event("close")); } +} + +beforeEach(() => { + saved = Object.fromEntries(ENV.map(name => [name, process.env[name]])); + for (const name of PROXY_ENV) delete process.env[name]; + home = mkdtempSync(join(tmpdir(), "cache-origin-flow-")); + process.env.OPENCODEX_HOME = home; + process.env.OPENCODEX_CACHE_DEBUG = "1"; + globalThis.WebSocket = UpstreamSocket as unknown as typeof WebSocket; + globalThis.fetch = (async () => { throw new Error("unexpected HTTP fallback: no real network allowed"); }) as typeof fetch; + rawUsage = undefined; interimUsage = undefined; terminal = "completed"; upstreamSends = 0; + clearRequestLogsForTests(); + release = acquireOwnedSpendHome(); +}); +afterEach(() => { + release(); + globalThis.WebSocket = realWs; globalThis.fetch = realFetch; + clearRequestLogsForTests(); + for (const name of ENV) { if (saved[name] === undefined) delete process.env[name]; else process.env[name] = saved[name]; } + removeTreeWithRetry(home); +}); + +async function waitFor(condition: () => boolean): Promise { + for (let index = 0; index < 1000; index++) { if (condition()) return; await Bun.sleep(2); } + throw new Error("cache telemetry final log did not settle"); +} + +async function runEntry(transport: "http" | "websocket", config = settings()): Promise { + const headers = new Headers({ authorization: "Bearer fixture-credential", "session-id": "fixture-session", "thread-id": "fixture-thread" }); + const frame = { model: config.defaultProvider === "openai" ? "gpt-5.6-sol" : `${config.defaultProvider}/gpt-5.6-sol`, + input: "prompt-content-sentinel", reasoning: { effort: "high" }, stream: true }; + if (transport === "http") { + const context = { config, deps: {}, ingressForServer: () => "public", packageTreeIntegrity: { status: () => ({ ok: true }) }, + runAdmittedHttpTurn: async (_req: Request, _policy: unknown, work: (lease: NonNullable>) => Promise) => { + const lease = tryAdmitTurn(); + if (!lease) throw new Error("test turn admission refused"); + try { return await work(lease); } finally { lease.release(); } + }, + } as unknown as ServeOptionsContext; + const options = createServeOptions(context); + const response = await options.fetch(new Request("http://127.0.0.1/v1/responses", { + method: "POST", headers: new Headers([...headers, ["content-type", "application/json"]]), body: JSON.stringify(frame), + }), { timeout() {}, requestIP: () => ({ address: "127.0.0.1" }) } as never); + expect(response.status).toBe(200); + const text = await response.text(); + await waitFor(() => getRequestLogEntries().length > 0); + return text; + } + const handler = createWebsocketHandler({ config, deps: {} } as ServeOptionsContext); + const sent: string[] = []; + const ws = { readyState: 1, data: { headers } as WsData, + send(text: string) { sent.push(text); return 1; }, close() {}, + } as unknown as ServerWebSocket; + handler.message(ws, JSON.stringify({ type: "response.create", ...frame })); + await waitFor(() => getRequestLogEntries().length > 0 && ws.data.cancel === undefined); + handler.close(ws, 1000, "fixture completed"); + return sent.join("\n"); +} + +function diagnostic() { + return JSON.parse(readFileSync(cacheDiagnosticPath(), "utf8").trim().split("\n").at(-1)!); +} + +describe("cache telemetry reaches final logs from both real ingress owners", () => { + for (const transport of ["http", "websocket"] as const) { + for (const cached of [0, undefined, 40] as const) { + test(`${transport}: upstream cache ${cached === undefined ? "absent" : cached} is not guessed from client zeros`, async () => { + rawUsage = { input_tokens: 100, output_tokens: 5, ...(cached === undefined ? {} : { input_tokens_details: { cached_tokens: cached } }) }; + const client = await runEntry(transport); + expect(upstreamSends).toBe(1); + expect(client).not.toContain("cacheTelemetry"); + const row = getRequestLogEntries().at(-1)!; + expect(row.cacheProvenance).toBe(cached === undefined ? "unknown" : "observed"); + expect(row.usage?.cacheTelemetry).toMatchObject({ source: "upstream", usagePresent: true }); + expect(row.usage?.cacheTelemetry?.read).toBe(cached); + const persisted = readUsageEntries().at(-1)!; + expect(persisted.cacheProvenance).toBe(row.cacheProvenance); + expect(persisted.attempts?.at(-1)?.cacheProvenance).toBe(row.cacheProvenance); + const raw = diagnostic().cache.rawUpstream; + expect(raw.observed).toBe(true); + expect(raw.present).toBe(cached !== undefined); + expect(raw.value).toBe(cached); + const summary = summarizeUsage([persisted], "all", Date.now()); + expect(summary.summary.cacheObservedRequests).toBe(cached === undefined ? 0 : 1); + expect(summary.summary.cacheUnknownRequests).toBe(cached === undefined ? 1 : 0); + const debug = readFileSync(cacheDiagnosticPath(), "utf8"); + expect(debug).not.toContain("prompt-content-sentinel"); + expect(debug).not.toContain("fixture-credential"); + }); + } + test(`${transport}: a terminal without any usage stays unknown`, async () => { + await runEntry(transport); + expect(getRequestLogEntries().at(-1)!.cacheProvenance).toBe("unknown"); + expect(diagnostic().cache.rawUpstream.present).toBe(false); + }); + for (const status of ["incomplete", "failed"]) test(`${transport}: ${status} terminals preserve a real zero`, async () => { + terminal = status; + rawUsage = { input_tokens: 100, output_tokens: 5, input_tokens_details: { cached_tokens: 0 } }; + await runEntry(transport); + expect(getRequestLogEntries().at(-1)!.cacheProvenance).toBe("observed"); + expect(getRequestLogEntries().at(-1)!.terminalStatus).toBe(status); + }); + test(`${transport}: final missing usage does not inherit an earlier frame's cache reading`, async () => { + interimUsage = { input_tokens: 100, output_tokens: 0, input_tokens_details: { cached_tokens: 50 } }; + await runEntry(transport); + const row = getRequestLogEntries().at(-1)!; + expect(row.cacheProvenance).toBe("unknown"); + expect(row.usage?.cachedInputTokens).toBeUndefined(); + expect(row.usage?.cacheReadInputTokens).toBeUndefined(); + expect(diagnostic().cache.rawUpstream).toMatchObject({ observed: true, usagePresent: false, present: false }); + }); + } +}); + +for (const transport of ["http", "websocket"] as const) for (const cached of [0, undefined, 40]) test(`${transport}: real adapter bridge retains ${cached === undefined ? "absent cache detail" : cached} before client defaulting`, async () => { + const config = { port: 0, bind: "127.0.0.1", defaultProvider: "bridge", providers: { + bridge: { adapter: "openai-chat", baseUrl: "https://upstream.invalid/v1", apiKey: "fixture-key" }, + } } as OcxConfig; + globalThis.fetch = (async () => new Response([ + { id: "chat-fixture", choices: [{ index: 0, delta: { content: "fixture output" }, finish_reason: null }] }, + { id: "chat-fixture", choices: [{ index: 0, delta: {}, finish_reason: "stop" }], usage: { + prompt_tokens: 100, completion_tokens: 5, ...(cached === undefined ? {} : { prompt_tokens_details: { cached_tokens: cached } }), + } }, + ].map(event => `data: ${JSON.stringify(event)}\n\n`).join("") + "data: [DONE]\n\n", { + headers: { "content-type": "text/event-stream" }, + })) as typeof fetch; + const client = await runEntry(transport, config); + expect(client).toContain("cached_tokens"); // The real Responses encoder emits strict-client defaults. + expect(client).not.toContain("cacheTelemetry"); + const row = readUsageEntries().at(-1)!; + expect(row.cacheProvenance).toBe(cached === undefined ? "unknown" : "observed"); + expect(row.usage?.cacheTelemetry?.read).toBe(cached); + // Adapter-reported canonical counts are not a raw upstream payload observation. + expect(diagnostic().cache.rawUpstream).toMatchObject({ observed: false, present: false }); +}); + +test("client zero defaults cannot overwrite absent raw counters; unobserved client-only zeros are unknown", () => { + const ctx: RequestLogContext = { provider: "test", model: "test" }; + const usage = { input_tokens: 100, output_tokens: 1 }; + applyResponseLogMetadata(ctx, { usage }, "upstream"); + const encoded = responsesUsage(ctx.usage); + expect(encoded.input_tokens_details).toEqual({ cached_tokens: 0 }); + applyResponseLogMetadata(ctx, { usage: encoded }); + addFinalRequestLog("defaulted", Date.now(), ctx, 200); + expect(getRequestLogEntries().at(-1)!.cacheProvenance).toBe("unknown"); + expect(diagnostic().cache.rawUpstream).toMatchObject({ observed: true, present: false }); + const clientOnly: RequestLogContext = { provider: "test", model: "test" }; + applyResponseLogMetadata(clientOnly, { usage: encoded }); + addFinalRequestLog("client-only", Date.now(), clientOnly, 200); + expect(getRequestLogEntries().at(-1)!.cacheProvenance).toBe("unknown"); + expect(diagnostic().cache.rawUpstream).toMatchObject({ observed: false, present: false }); +}); + +test("a type-only terminal without usage clears prior evidence even when response.status is absent", () => { + const ctx: RequestLogContext = { provider: "test", model: "test" }; + applyResponseLogMetadata(ctx, { type: "response.created", response: { + usage: { input_tokens: 100, output_tokens: 1, input_tokens_details: { cached_tokens: 50 } }, + } }, "upstream"); + applyResponseLogMetadata(ctx, { type: "response.completed", response: {} }, "upstream"); + addFinalRequestLog("type-only-terminal", Date.now(), ctx, 200); + expect(readUsageEntries().at(-1)!.cacheProvenance).toBe("unknown"); + expect(diagnostic().cache.rawUpstream).toMatchObject({ observed: true, usagePresent: false, present: false }); +}); + +test("an unresolved final attempt cannot borrow usage or raw cache evidence from an earlier send", () => { + const first = beginRequestAttempt(1, "one", "test", "openai-responses"); + const last = beginRequestAttempt(2, "two", "test", "openai-responses"); + noteAttemptSend(first, undefined); noteAttemptSend(last, undefined); + const ctx: RequestLogContext = { provider: "two", model: "test", attempts: [first, last], activeAttempt: first }; + applyResponseLogMetadata(ctx, { usage: { input_tokens: 100, output_tokens: 1, input_tokens_details: { cached_tokens: 50 } } }, "upstream"); + finishRequestAttempt(first, 200, 1, ctx.usage); + ctx.activeAttempt = last; // Deliberately keep the context's old usage reference. + addFinalRequestLog("unresolved-final-send", Date.now(), ctx, 502); + const row = readUsageEntries().at(-1)!; + expect(row.cacheProvenance).toBe("unknown"); + // Some runtime baselines retain non-combo multi-attempt totals. Those real earlier-send + // costs may remain on the parent, but are not a cache observation of the unresolved send. + if (row.usage !== undefined) expect(row.usage).toMatchObject({ + inputTokens: 100, outputTokens: 1, cacheReadInputTokens: 50, + cacheTelemetry: { source: "aggregate", complete: false, read: 50 }, + }); + expect(row.attempts?.[1].usage).toBeUndefined(); + expect(row.attempts?.[1].cacheProvenance).toBe("unknown"); + expect(row.attempts?.[0].cacheProvenance).toBe("observed"); + expect(diagnostic().cache.rawUpstream).toMatchObject({ observed: false, present: false }); +}); + +test("physical attempts own their evidence; aggregate and final raw are not sibling projections", () => { + const first = beginRequestAttempt(1, "one", "test", "openai-responses"); + const second = beginRequestAttempt(2, "two", "test", "openai-responses"); + const ctx: RequestLogContext = { provider: "two", model: "test", comboId: "combo", attempts: [first, second], activeAttempt: first }; + applyResponseLogMetadata(ctx, { usage: { input_tokens: 100, output_tokens: 1, input_tokens_details: { cached_tokens: 0 } } }, "upstream"); + finishRequestAttempt(first, 200, 1, ctx.usage); + ctx.activeAttempt = second; delete ctx.usage; + applyResponseLogMetadata(ctx, { usage: { input_tokens: 100, output_tokens: 1 } }, "upstream"); + addFinalRequestLog("two-attempts", Date.now(), ctx, 200); + const row = readUsageEntries().at(-1)!; + expect(row.attempts?.map(attempt => attempt.cacheProvenance)).toEqual(["observed", "unknown"]); + expect(row.cacheProvenance).toBe("unknown"); + expect(row.usage).toMatchObject({ inputTokens: 200, outputTokens: 2, + cacheTelemetry: { source: "aggregate", complete: false, read: 0 } }); + expect(diagnostic().cache.rawUpstream).toMatchObject({ observed: true, present: false }); + const summary = summarizeUsage([row], "all", Date.now()); + expect(summary.providers.find(provider => provider.provider === "one")?.cacheObservedInputTokens).toBe(100); + expect(summary.providers.find(provider => provider.provider === "two")?.cacheObservedInputTokens).toBe(0); +}); diff --git a/tests/responses/cache-telemetry-guard-mergers.test.ts b/tests/responses/cache-telemetry-guard-mergers.test.ts new file mode 100644 index 00000000000..f4483fd4849 --- /dev/null +++ b/tests/responses/cache-telemetry-guard-mergers.test.ts @@ -0,0 +1,77 @@ +import { describe, expect, test } from "bun:test"; +import type { AdapterEvent, OcxParsedRequest, OcxUsage } from "../../src/types"; +import { guardEmptyCompletionEventStream, mergeUsage as mergeEmpty } from "../../src/server/responses/empty-completion-guard"; +import { guardTerminalEventStream, mergeUsage as mergeTerminal } from "../../src/server/responses/terminal-guard"; +import { cacheProvenance, usageFromResponsesPayload } from "../../src/usage/cache-telemetry"; + +const value = (extra: Partial = {}): OcxUsage => ({ inputTokens: 100, outputTokens: 1, ...extra }); +const events = async function* (...items: AdapterEvent[]): AsyncGenerator { yield* items; }; +const parsed: OcxParsedRequest = { modelId: "fixture", stream: true, options: {}, context: { + messages: [{ role: "user", content: "Check and fix this code", timestamp: 1 }], + tools: [{ name: "exec_command", description: "run", parameters: {} }], +} }; +async function terminal(source: AsyncIterable) { + let usage: OcxUsage | undefined; + for await (const event of source) if (event.type === "done" || event.type === "incomplete" || event.type === "error") usage = event.usage; + return usage; +} + +for (const [name, merge] of [["empty", mergeEmpty], ["terminal", mergeTerminal]] as const) { + describe(`${name} cache merger`, () => { + test("the initial undefined accumulator is not a missing physical round", () => { + const merged = merge(undefined, value({ cachedInputTokens: 0 })); + expect(merged?.cacheTelemetry).toEqual({ source: "adapter", usagePresent: true, read: 0 }); + expect(cacheProvenance(merged)).toBe("observed"); + }); + test("two raw measurements preserve read-only counters and zero evidence", () => { + const merged = merge(value({ cachedInputTokens: 40, cacheCreationInputTokens: 10 }), value({ cachedInputTokens: 0 })); + expect(merged).toMatchObject({ inputTokens: 200, outputTokens: 2, cachedInputTokens: 40, + cacheTelemetry: { source: "aggregate", complete: true, read: 40, creation: 10, readComplete: true, creationComplete: false } }); + }); + test.each([true, false])("mixed read aliases include every leg (explicit first=%s)", explicitFirst => { + const cachedOnly = value({ cachedInputTokens: 40, cacheCreationInputTokens: 10 }); + const explicit = value({ cachedInputTokens: 5, cacheReadInputTokens: 5 }); + const merged = merge(explicitFirst ? explicit : cachedOnly, explicitFirst ? cachedOnly : explicit); + expect(merged).toMatchObject({ cachedInputTokens: 45, cacheReadInputTokens: 45, + cacheCreationInputTokens: 10, cacheTelemetry: { read: 45, complete: true, readComplete: true } }); + }); + test("a malformed cached alias cannot concatenate into the explicit read sum", () => { + const merged = merge(value({ cachedInputTokens: "invalid" as unknown as number }), value({ cacheReadInputTokens: 5 })); + expect(merged?.cacheReadInputTokens).toBe(5); + expect(merged?.cacheTelemetry).toMatchObject({ read: 5, complete: false, readComplete: false }); + }); + test("missing fields and client-derived fields keep the sum incomplete", () => { + for (const second of [value(), usageFromResponsesPayload({ input_tokens: 100, output_tokens: 1, + input_tokens_details: { cached_tokens: 50 } })]) { + const merged = merge(value({ cachedInputTokens: 40 }), second); + expect(merged?.cacheTelemetry).toMatchObject({ source: "aggregate", complete: false, read: 40, readComplete: false }); + expect(cacheProvenance(merged)).toBe("unknown"); + } + }); + }); +} + +for (const kind of ["empty", "terminal"] as const) { + const run = (first: OcxUsage | undefined, second: OcxUsage | undefined) => terminal(kind === "empty" + ? guardEmptyCompletionEventStream({ firstEvents: events({ type: "done", usage: first }), + continuation: () => events({ type: "text_delta", text: "answer" }, { type: "done", usage: second }) }) + : guardTerminalEventStream({ parsed, adapterName: "openai-chat", + firstEvents: events({ type: "text_delta", text: "Let me check." }, { type: "done", usage: first }), + continuation: () => events({ type: "text_delta", text: "answer" }, { type: "done", usage: second }) })); + test.each([true, false])(`${kind} guard retains a missing whole usage round (first=%s)`, async missingFirst => { + const known = value({ cachedInputTokens: 40 }); + const merged = await run(missingFirst ? undefined : known, missingFirst ? known : undefined); + expect(merged?.inputTokens).toBe(100); + expect(merged?.cacheTelemetry).toMatchObject({ source: "aggregate", complete: false, read: 40, readComplete: false }); + expect(cacheProvenance(merged)).toBe("unknown"); + }); + test(`${kind} guard does not manufacture numeric usage for all missing rounds`, async () => { + expect(await run(undefined, undefined)).toBeUndefined(); + }); +} + +test("a terminal-less empty round remains unknown after retry succeeds", async () => { + const merged = await terminal(guardEmptyCompletionEventStream({ firstEvents: events(), + continuation: () => events({ type: "text_delta", text: "answer" }, { type: "done", usage: value({ cachedInputTokens: 0 }) }) })); + expect(merged?.cacheTelemetry).toMatchObject({ source: "aggregate", complete: false, read: 0, readComplete: false }); +}); diff --git a/tests/responses/cache-telemetry-http.test.ts b/tests/responses/cache-telemetry-http.test.ts new file mode 100644 index 00000000000..445a4b3cdd7 --- /dev/null +++ b/tests/responses/cache-telemetry-http.test.ts @@ -0,0 +1,300 @@ +import { afterEach, beforeEach, describe, expect, test } from "bun:test"; +import { mkdtempSync, readFileSync } from "node:fs"; +import { tmpdir } from "node:os"; +import { join } from "node:path"; +import type { OcxConfig } from "../../src/types"; +import { createServeOptions, type ServeOptionsContext } from "../../src/server/index/serve-options"; +import { tryAdmitTurn } from "../../src/server/lifecycle"; +import { setRelayPlatformForTests } from "../../src/server/responses/passthrough-delivery"; +import { clearRequestLogsForTests, getRequestLogEntries } from "../../src/server/request-log"; +import { cacheDiagnosticPath } from "../../src/usage/cache-diagnostic"; +import { readUsageEntries } from "../../src/usage/log"; +import { acquireOwnedSpendHome } from "../helpers/owned-spend-home"; +import { removeTreeWithRetry } from "../helpers/remove-tree"; + +const PROXY_ENV = ["HTTP_PROXY", "HTTPS_PROXY", "ALL_PROXY", "NO_PROXY", "http_proxy", "https_proxy", "all_proxy", "no_proxy"]; +const ENV = [...PROXY_ENV, "OPENCODEX_HOME", "OPENCODEX_CACHE_DEBUG"]; +const realFetch = globalThis.fetch; +const realWebSocket = globalThis.WebSocket; +const encoder = new TextEncoder(); +const outputText = "HTTP fixture 中文😀 output"; +let saved: Record; +let home: string; +let release: () => void; +let upstreamResponse: () => Response; +let upstreamSends: number; +let outbound: Record; + +// Linux auto and the explicit tee pin exercise the HTTP tee path; the narrow platform +// seam reaches the real Darwin eager opt-in without changing process.platform or storage. +const paths = [ + { name: "auto HTTP", mode: "auto", platform: "linux" }, + { name: "legacy-tee HTTP", mode: "legacy-tee", platform: "linux" }, + { name: "eager-relay HTTP", mode: "eager-relay", platform: "darwin" }, +] as const; + +beforeEach(() => { + saved = Object.fromEntries(ENV.map(name => [name, process.env[name]])); + for (const name of PROXY_ENV) delete process.env[name]; + home = mkdtempSync(join(tmpdir(), "cache-telemetry-http-")); + process.env.OPENCODEX_HOME = home; + process.env.OPENCODEX_CACHE_DEBUG = "1"; + upstreamSends = 0; + outbound = {}; + upstreamResponse = () => { throw new Error("HTTP fixture was not configured"); }; + globalThis.fetch = (async (input: RequestInfo | URL, init?: RequestInit) => { + const url = input instanceof Request ? input.url : String(input); + // No original fetch fallback exists: unexpected URLs fail before any network I/O. + expect(url).toBe("https://cache-http-fixture.invalid/v1/responses"); + expect(init?.method).toBe("POST"); + outbound = JSON.parse(String(init?.body)); + upstreamSends++; + return upstreamResponse(); + }) as typeof fetch; + globalThis.WebSocket = class { + constructor() { throw new Error("HTTP fixture must not open an upstream WebSocket"); } + } as unknown as typeof WebSocket; + clearRequestLogsForTests(); + release = acquireOwnedSpendHome(); +}); + +afterEach(() => { + release(); + globalThis.fetch = realFetch; + globalThis.WebSocket = realWebSocket; + setRelayPlatformForTests(undefined); + clearRequestLogsForTests(); + for (const name of ENV) { + if (saved[name] === undefined) delete process.env[name]; + else process.env[name] = saved[name]; + } + removeTreeWithRetry(home); +}); + +async function bounded(work: Promise): Promise { + let timer: ReturnType | undefined; + try { + return await Promise.race([work, new Promise((_, reject) => { + timer = setTimeout(() => reject(new Error("HTTP cache fixture did not settle within 2s")), 2_000); + })]); + } finally { clearTimeout(timer); } +} + +async function finalLog() { + const deadline = Date.now() + 2_000; + while (getRequestLogEntries().length === 0 && Date.now() < deadline) await Bun.sleep(2); + expect(upstreamSends).toBe(1); + expect(getRequestLogEntries()).toHaveLength(1); + expect(readUsageEntries()).toHaveLength(1); + return getRequestLogEntries()[0]!; +} + +async function entry(path: typeof paths[number], stream = true): Promise { + setRelayPlatformForTests(path.platform); + const config = { port: 0, bind: "127.0.0.1", defaultProvider: "http-fixture", streamMode: path.mode, + providers: { "http-fixture": { adapter: "openai-responses", baseUrl: "https://cache-http-fixture.invalid/v1", + apiKey: "fixture-not-a-real-key", authMode: "key" } }, + } as OcxConfig; + const context = { + config, deps: {}, ingressForServer: () => "public", packageTreeIntegrity: { status: () => ({ ok: true }) }, + runAdmittedHttpTurn: async (_req: Request, _policy: unknown, + work: (lease: NonNullable>) => Promise) => { + const lease = tryAdmitTurn(); + if (!lease) throw new Error("HTTP fixture turn admission refused"); + try { return await work(lease); } finally { lease.release(); } + }, + } as unknown as ServeOptionsContext; + const response = await bounded(createServeOptions(context).fetch(new Request("http://127.0.0.1/v1/responses", { + method: "POST", headers: { "content-type": "application/json", "session-id": "fixture-private-session" }, + body: JSON.stringify({ model: "http-fixture/cache-fixture-model", input: "fixture-private-prompt", stream }), + }), { timeout() {}, requestIP: () => ({ address: "127.0.0.1" }) } as never)); + expect(response.status).toBe(200); + expect(outbound.stream).toBe(stream); + return response; +} + +function usage(cached?: number) { + return { input_tokens: 100, output_tokens: 5, + ...(cached === undefined ? {} : { input_tokens_details: { cached_tokens: cached } }) }; +} + +function terminal(rawUsage?: unknown) { + return { id: "resp_http_fixture", object: "response", status: "completed", model: "cache-fixture-model", + output: [{ id: "msg_http_fixture", type: "message", role: "assistant", status: "completed", + content: [{ type: "output_text", text: outputText, annotations: [] }] }], + ...(rawUsage === undefined ? {} : { usage: rawUsage }) }; +} + +function event(payload: unknown, multiline = false): string { + const json = JSON.stringify(payload, null, multiline ? 2 : undefined); + return `event: ${(payload as { type: string }).type}\r\n` + + json.split("\n").map(line => `data: ${line}\r\n`).join("") + "\r\n"; +} + +function completed(rawUsage?: unknown, multiline = false): string { + return event({ type: "response.output_text.delta", output_index: 0, content_index: 0, delta: outputText }) + + event({ type: "response.completed", response: terminal(rawUsage) }, multiline); +} + +function fragmented(text: string): ReadableStream { + const bytes = encoder.encode(text); + // Every byte of the first non-ASCII character is split, including the UTF-8 sequence. + const unicode = bytes.findIndex(byte => byte >= 0x80); + const cuts = [...new Set([0, unicode, unicode + 1, unicode + 2, unicode + 3, + ...Array.from({ length: Math.ceil(bytes.length / 37) }, (_, index) => index * 37), bytes.length])] + .filter(index => index >= 0 && index <= bytes.length).sort((a, b) => a - b); + let index = 0; + return new ReadableStream({ pull(controller) { + if (index === cuts.length - 1) { controller.close(); return; } + controller.enqueue(bytes.subarray(cuts[index]!, cuts[++index]!)); + } }, { highWaterMark: 0 }); +} + +function sse(body: string | ReadableStream): Response { + return new Response(body, { headers: { "content-type": "text/event-stream" } }); +} + +function assertEvidence(cached: number | undefined, usagePresent = true) { + const row = getRequestLogEntries()[0]!; + const persisted = readUsageEntries()[0]!; + const provenance = cached === undefined ? "unknown" : "observed"; + expect(row.cacheProvenance).toBe(provenance); + expect(persisted.cacheProvenance).toBe(provenance); + expect(persisted.attempts).toHaveLength(1); + expect(persisted.attempts![0]!.cacheProvenance).toBe(provenance); + if (usagePresent) { + for (const value of [row.usage, persisted.usage, persisted.attempts![0]!.usage]) { + expect(value?.cacheTelemetry).toEqual({ source: "upstream", usagePresent: true, + ...(cached === undefined ? {} : { read: cached }) }); + } + } else { + for (const value of [row.usage, persisted.usage, persisted.attempts![0]!.usage]) { + expect(value?.cachedInputTokens).toBeUndefined(); + expect(value?.cacheReadInputTokens).toBeUndefined(); + if (value?.cacheTelemetry) expect(value.cacheTelemetry).toEqual({ source: "upstream", usagePresent: false }); + } + } + const debug = readFileSync(cacheDiagnosticPath(), "utf8"); + const diagnostic = JSON.parse(debug.trim().split("\n").at(-1)!); + expect(diagnostic.cache.rawUpstream).toEqual({ observed: true, usagePresent, present: cached !== undefined, + ...(cached === undefined ? {} : { value: cached }) }); + for (const privateValue of ["fixture-private-prompt", "fixture-private-session", "fixture-not-a-real-key", outputText]) { + expect(debug).not.toContain(privateValue); + } +} + +describe("cache telemetry through actual upstream HTTP delivery", () => { + for (const path of paths) { + for (const cached of [0, undefined, 40]) { + test(`${path.name}: fragmented multiline SSE retains ${cached ?? "missing"} raw cache evidence`, async () => { + upstreamResponse = () => sse(fragmented(completed(usage(cached), true))); + const client = await bounded((await entry(path)).text()); + expect(client).toContain(outputText); + expect(client).toContain("response.completed"); + expect(client).not.toContain("cacheTelemetry"); + await finalLog(); + assertEvidence(cached); + }); + + test(`${path.name}: nonstream JSON retains ${cached ?? "missing"} raw cache evidence`, async () => { + upstreamResponse = () => Response.json(terminal(usage(cached))); + const client = await bounded((await entry(path, false)).text()); + expect(JSON.parse(client).output[0].content[0].text).toBe(outputText); + expect(client).not.toContain("cacheTelemetry"); + await finalLog(); + assertEvidence(cached); + }); + } + + test(`${path.name}: terminal without usage is an observed absence, not a measured zero`, async () => { + upstreamResponse = () => sse(fragmented(completed())); + const client = await bounded((await entry(path)).text()); + expect(client).not.toContain("cacheTelemetry"); + await finalLog(); + assertEvidence(undefined, false); + }); + + test(`${path.name}: a final absent usage clears an earlier frame's cache counter`, async () => { + upstreamResponse = () => sse(fragmented(event({ type: "response.created", response: { + id: "resp_http_fixture", status: "in_progress", output: [], usage: usage(40), + } }) + completed())); + expect(await bounded((await entry(path)).text())).not.toContain("cacheTelemetry"); + await finalLog(); + assertEvidence(undefined, false); + }); + + test(`${path.name}: slow client keeps the same upstream evidence`, async () => { + upstreamResponse = () => sse(fragmented(completed(usage(0), true))); + const reader = (await entry(path)).body!.getReader(); + // Let inspection finish while the client has not read even its first byte. + await finalLog(); + assertEvidence(0); + const client = await bounded((async () => { + const decoder = new TextDecoder(); + let text = ""; + for (;;) { + const chunk = await reader.read(); + if (chunk.done) return text + decoder.decode(); + text += decoder.decode(chunk.value, { stream: true }); + await Bun.sleep(2); + } + })()); + expect(client).toContain(outputText); + expect(client).not.toContain("cacheTelemetry"); + await finalLog(); + assertEvidence(0); + }); + + test(`${path.name}: midstream error does not invent a raw usage observation`, async () => { + let pulls = 0; + upstreamResponse = () => sse(new ReadableStream({ pull(controller) { + if (pulls++ === 0) controller.enqueue(encoder.encode(event({ type: "response.output_text.delta", delta: outputText }))); + else controller.error(new Error("fixture upstream reset")); + } }, { highWaterMark: 0 })); + const client = await bounded((await entry(path)).text()); + expect(client).toContain("response.failed"); + expect(client).not.toContain("cacheTelemetry"); + const row = await finalLog(); + expect(row.cacheProvenance).toBe("unknown"); + expect(row.terminalStatus).toBe("failed"); + expect(readUsageEntries()[0]!.attempts?.[0]?.cacheProvenance).toBe("unknown"); + const raw = JSON.parse(readFileSync(cacheDiagnosticPath(), "utf8").trim()).cache.rawUpstream; + expect(raw).toEqual({ observed: false, present: false }); + }); + + test(`${path.name}: a real terminal received after client cancellation retains upstream zero`, async () => { + let controller!: ReadableStreamDefaultController; + upstreamResponse = () => sse(new ReadableStream({ start(value) { + controller = value; + controller.enqueue(encoder.encode(event({ type: "response.output_text.delta", delta: outputText }))); + } }, { highWaterMark: 0 })); + const reader = (await entry(path)).body!.getReader(); + expect((await bounded(reader.read())).done).toBe(false); + expect(getRequestLogEntries()).toHaveLength(0); + await bounded(reader.cancel("fixture client closed")); + controller.enqueue(encoder.encode(event({ type: "response.completed", response: terminal(usage(0)) }))); + controller.close(); + const row = await finalLog(); + expect(row.terminalStatus).toBe("completed"); + assertEvidence(0); + }); + + test(`${path.name}: cancelled client without a later terminal stays unknown`, async () => { + let controller!: ReadableStreamDefaultController; + upstreamResponse = () => sse(new ReadableStream({ start(value) { + controller = value; + controller.enqueue(encoder.encode(event({ type: "response.output_text.delta", delta: outputText }))); + } }, { highWaterMark: 0 })); + const reader = (await entry(path)).body!.getReader(); + expect((await bounded(reader.read())).done).toBe(false); + await bounded(reader.cancel("fixture client closed")); + controller.close(); // Settle the drain without waiting for the production 15s deadline. + const row = await finalLog(); + expect(row.closeReason).toBe("client_cancel"); + expect(row.cacheProvenance).toBe("unknown"); + expect(readUsageEntries()[0]!.attempts?.[0]?.cacheProvenance).toBe("unknown"); + const raw = JSON.parse(readFileSync(cacheDiagnosticPath(), "utf8").trim()).cache.rawUpstream; + expect(raw).toEqual({ observed: false, present: false }); + }); + } +}); diff --git a/tests/responses/cache-telemetry-native-seams.test.ts b/tests/responses/cache-telemetry-native-seams.test.ts new file mode 100644 index 00000000000..498d4816cfb --- /dev/null +++ b/tests/responses/cache-telemetry-native-seams.test.ts @@ -0,0 +1,210 @@ +import { afterEach, beforeEach, describe, expect, test } from "bun:test"; +import { mkdtempSync, readFileSync } from "node:fs"; +import { tmpdir } from "node:os"; +import { join } from "node:path"; +import { + addFinalRequestLog, beginRequestAttempt, clearRequestLogsForTests, noteAttemptSend, + noteProviderAttemptSend, type RequestLogContext, +} from "../../src/server/request-log"; +import { createNativeSteeringLogObserver } from "../../src/server/responses/native-steering-log"; +import { guardPassthroughCompletion } from "../../src/server/responses/passthrough-completion"; +import { usageFromComboFailureText } from "../../src/server/responses/core-combo-failure"; +import { handleResponsesCompact } from "../../src/server/responses/compact"; +import type { OcxConfig, OcxProviderConfig } from "../../src/types"; +import { cacheProvenance } from "../../src/usage/cache-telemetry"; +import { cacheDiagnosticPath } from "../../src/usage/cache-diagnostic"; +import { readUsageEntries } from "../../src/usage/log"; +import { acquireOwnedSpendHome } from "../helpers/owned-spend-home"; +import { removeTreeWithRetry } from "../helpers/remove-tree"; + +const PROXY_ENV = ["HTTP_PROXY", "HTTPS_PROXY", "ALL_PROXY", "NO_PROXY", "http_proxy", "https_proxy", "all_proxy", "no_proxy"]; +const ENV = [...PROXY_ENV, "OPENCODEX_HOME", "OPENCODEX_CACHE_DEBUG"]; +const realFetch = globalThis.fetch; +const realSocket = globalThis.WebSocket; +let saved: Record; +let home: string; +let release: () => void; + +beforeEach(() => { + saved = Object.fromEntries(ENV.map(key => [key, process.env[key]])); + for (const key of PROXY_ENV) delete process.env[key]; + home = mkdtempSync(join(tmpdir(), "cache-native-seams-")); + process.env.OPENCODEX_HOME = home; + process.env.OPENCODEX_CACHE_DEBUG = "1"; + globalThis.fetch = (async () => { throw new Error("No network in native cache seam fixtures"); }) as typeof fetch; + globalThis.WebSocket = class { + constructor() { throw new Error("No upstream sockets in native cache seam fixtures"); } + } as unknown as typeof WebSocket; + clearRequestLogsForTests(); + release = acquireOwnedSpendHome(); +}); + +afterEach(() => { + release(); + globalThis.fetch = realFetch; + globalThis.WebSocket = realSocket; + clearRequestLogsForTests(); + for (const key of ENV) { + if (saved[key] === undefined) delete process.env[key]; + else process.env[key] = saved[key]; + } + removeTreeWithRetry(home); +}); + +const rawUsage = (cached?: number) => ({ input_tokens: 10, output_tokens: 2, + ...(cached === undefined ? {} : { input_tokens_details: { cached_tokens: cached } }), + privateMetadata: "must-not-survive-internal-usage", +}); + +function context(): RequestLogContext { + const attempt = beginRequestAttempt(1, "fixture", "fixture-model", "openai-responses"); + noteAttemptSend(attempt, undefined); + return { provider: "fixture", model: "fixture-model", attempts: [attempt], activeAttempt: attempt }; +} + +function payload(id: string, usage?: unknown, steered = false): string { + return JSON.stringify({ type: steered ? "response.incomplete" : "response.completed", response: { + id, status: steered ? "incomplete" : "completed", output: [], + ...(steered ? { incomplete_details: { reason: "steered" } } : {}), + ...(usage === undefined ? {} : { usage }), + } }); +} + +describe("native-control raw cache observations", () => { + for (const cached of [0, undefined, 40]) test(`a single terminal retains ${cached ?? "missing"} upstream evidence`, () => { + const log = context(); + createNativeSteeringLogObserver(log)(payload("one", rawUsage(cached))); + expect(log.usage?.cacheTelemetry).toEqual({ source: "upstream", usagePresent: true, + ...(cached === undefined ? {} : { read: cached }) }); + expect(cacheProvenance(log.usage)).toBe(cached === undefined ? "unknown" : "observed"); + expect(JSON.stringify(log.usage)).not.toContain("must-not-survive"); + addFinalRequestLog("native-fixture", Date.now(), log, 200); + const saved = readUsageEntries()[0]!; + expect(saved.usage?.cacheTelemetry).toEqual(log.usage?.cacheTelemetry); + expect(saved.attempts?.[0]?.usage?.cacheTelemetry).toEqual(log.usage?.cacheTelemetry); + const raw = JSON.parse(readFileSync(cacheDiagnosticPath(), "utf8").trim()).cache.rawUpstream; + expect(raw).toEqual({ observed: true, usagePresent: true, present: cached !== undefined, + ...(cached === undefined ? {} : { value: cached }) }); + }); + + for (const [first, second] of [[0, 0], [0, undefined], [undefined, 0], [40, 0]] as const) { + test(`successor chain combines ${first ?? "missing"}/${second ?? "missing"} without upgrading partial evidence`, () => { + const log = context(); + const inspect = createNativeSteeringLogObserver(log); + inspect(payload("parent", rawUsage(first), true)); + inspect(payload("successor", rawUsage(second))); + expect(log.usage).toMatchObject({ inputTokens: 20, outputTokens: 4, + cacheTelemetry: { source: "aggregate", complete: first !== undefined && second !== undefined, + read: (first ?? 0) + (second ?? 0) } }); + expect(cacheProvenance(log.usage)).toBe(first === undefined || second === undefined ? "unknown" : "observed"); + expect(log.upstreamError).toBeUndefined(); + inspect(payload("successor", rawUsage(second))); + expect(log.usage?.inputTokens).toBe(20); + expect(log.activeAttempt?.usage).toBe(log.usage); + }); + } + + test("a terminal with no usage makes the native chain incomplete, not fully observed", () => { + const log = context(); + const inspect = createNativeSteeringLogObserver(log); + inspect(payload("parent", rawUsage(0), true)); + inspect(payload("successor")); + expect(log.usage).toMatchObject({ inputTokens: 10, outputTokens: 2, + cacheTelemetry: { source: "aggregate", complete: false, read: 0 } }); + expect(cacheProvenance(log.usage)).toBe("unknown"); + addFinalRequestLog("absent-successor", Date.now(), log, 200); + expect(JSON.parse(readFileSync(cacheDiagnosticPath(), "utf8").trim()).cache.rawUpstream) + .toEqual({ observed: true, usagePresent: false, present: false }); + }); + + test("a repeated terminal that omits usage cannot leave its previous cache count", () => { + const log = context(); + const inspect = createNativeSteeringLogObserver(log); + inspect(payload("one", rawUsage(40))); + inspect(payload("one")); + expect(log.usage).toBeUndefined(); + expect(log.activeAttempt?.usage).toBeUndefined(); + }); + + test("control acknowledgements cannot contribute a cache observation", () => { + const log = context(); + const inspect = createNativeSteeringLogObserver(log); + for (const type of ["response.steer.accepted", "response.inject.failed"]) { + inspect(JSON.stringify({ type, response: { id: "control", usage: rawUsage(40) } })); + } + expect(log.usage).toBeUndefined(); + }); +}); + +describe("discarded OpenGateway completion usage is still raw", () => { + for (const stream of [false, true]) for (const cached of [0, undefined, 40]) { + test(`${stream ? "SSE" : "JSON"} records ${cached ?? "missing"} before replacing the empty completion`, async () => { + const attempt = beginRequestAttempt(1, "fixture", "fixture-model", "openai-responses"); + const log: RequestLogContext = { provider: "fixture", model: "fixture-model", attempts: [attempt], activeAttempt: attempt }; + noteProviderAttemptSend(log, "fixture", { adapter: "openai-responses", authMode: "key" }, undefined); + const snapshot = { id: "empty", object: "response", status: "completed", output: [], usage: rawUsage(cached) }; + const source = stream + ? new Response(`data: ${JSON.stringify({ type: "response.completed", response: snapshot })}\n\n`, + { headers: { "content-type": "text/event-stream" } }) + : Response.json(snapshot); + const response = await guardPassthroughCompletion(source, { + url: "https://apis.opengateway.ai/v1/responses", method: "POST", headers: {}, + body: JSON.stringify({ model: "fixture-model", input: "fixture", store: false, stream }), + }, { emptyCompletionRetry: false }, new AbortController().signal, log, + async () => { throw new Error("Retry disabled in cache seam fixture"); }); + expect(await response.text()).not.toContain("cacheTelemetry"); + expect(log.activeAttempt?.usage?.cacheTelemetry).toEqual({ source: "upstream", usagePresent: true, + ...(cached === undefined ? {} : { read: cached }) }); + expect(cacheProvenance(log.usage)).toBe(cached === undefined ? "unknown" : "observed"); + expect(JSON.stringify(log.usage)).not.toContain("must-not-survive"); + }); + } +}); + +for (const cached of [0, 40]) test(`client failure JSON with cache ${cached} cannot claim raw upstream evidence`, () => { + const usage = usageFromComboFailureText(JSON.stringify({ response: { usage: rawUsage(cached) } })); + expect(usage?.cacheTelemetry).toEqual({ source: "client", usagePresent: true }); + expect(cacheProvenance(usage)).toBe("unknown"); +}); + +describe("native compact raw HTTP usage", () => { + for (const cached of [0, undefined, 40, null]) test(`buffered compact preserves ${cached === null ? "no usage" : cached ?? "missing counter"}`, async () => { + let sends = 0; + const snapshot = { id: "compact-fixture", object: "response", status: "completed", + output: [{ id: "compaction-fixture", type: "compaction", encrypted_content: "fixture-compaction-ciphertext" }], + ...(cached === null ? {} : { usage: rawUsage(cached) }) }; + const provider: OcxProviderConfig & { fetch: typeof fetch } = { + adapter: "openai-responses", baseUrl: "https://api.openai.com/v1", authMode: "key", apiKey: "fixture-only-key", + // The physical send is an in-memory fixture, not a wrapper around a real fetch. + fetch: (async (input: RequestInfo | URL, init?: RequestInit) => { + expect(String(input)).toBe("https://api.openai.com/v1/responses/compact"); + expect(init?.method).toBe("POST"); + sends++; + return Response.json(snapshot); + }) as typeof fetch, + }; + const config = { port: 0, defaultProvider: "openai-apikey", providers: { "openai-apikey": provider } } as OcxConfig; + const log: RequestLogContext = { provider: "", model: "" }; + const response = await handleResponsesCompact(new Request("http://127.0.0.1/v1/responses/compact", { + method: "POST", headers: { "content-type": "application/json" }, + body: JSON.stringify({ model: "openai-apikey/gpt-5.5", input: [{ role: "user", content: "fixture compact input" }] }), + }), config, log); + expect(response.status).toBe(200); + const client = await response.text(); + expect(JSON.parse(client)).toEqual(snapshot); + expect(client).not.toContain("cacheTelemetry"); + expect(sends).toBe(1); + expect(log.usage?.cacheTelemetry).toEqual(cached === null ? undefined : { + source: "upstream", usagePresent: true, ...(cached === undefined ? {} : { read: cached }), + }); + addFinalRequestLog("native-compact", Date.now(), log, 200); + const saved = readUsageEntries()[0]!; + expect(saved.cacheProvenance).toBe(cached === undefined || cached === null ? "unknown" : "observed"); + // Native compact currently records request usage without creating an attempt row. + expect(saved.usage?.cacheTelemetry).toEqual(log.usage?.cacheTelemetry); + expect(JSON.parse(readFileSync(cacheDiagnosticPath(), "utf8").trim()).cache.rawUpstream).toEqual({ + observed: true, usagePresent: cached !== null, present: cached !== undefined && cached !== null, + ...(cached === undefined || cached === null ? {} : { value: cached }), + }); + }); +}); diff --git a/tests/responses/empty-completion-guard.test.ts b/tests/responses/empty-completion-guard.test.ts index ca77326ce78..6b5c68d20bd 100644 --- a/tests/responses/empty-completion-guard.test.ts +++ b/tests/responses/empty-completion-guard.test.ts @@ -88,7 +88,7 @@ describe("empty-completion guard retry", () => { expect(withoutHeartbeats(events)).toEqual([ { type: "thinking_delta", thinking: "thinking..." }, { type: "text_delta", text: "answer" }, - { type: "done", usage: { inputTokens: 10, outputTokens: 2 } }, + { type: "done", usage: { inputTokens: 10, outputTokens: 2, cacheTelemetry: { source: "adapter", usagePresent: true } } }, ]); }); @@ -119,7 +119,7 @@ describe("empty-completion guard retry", () => { { type: "assistant_boundary" }, { type: "thinking_delta", thinking: "second attempt" }, { type: "text_delta", text: "finally an answer" }, - { type: "done", usage: { inputTokens: 30, outputTokens: 5, totalTokens: 35 } }, + { type: "done", usage: { inputTokens: 30, outputTokens: 5, totalTokens: 35, cacheTelemetry: { source: "aggregate", usagePresent: true, complete: false, readComplete: false, creationComplete: false } } }, ]); }); @@ -160,7 +160,7 @@ describe("empty-completion guard retry", () => { inputTokens: 300, outputTokens: 30, totalTokens: 330, - cachedInputTokens: 40, + cachedInputTokens: 40, cacheTelemetry: { source: "aggregate", usagePresent: true, complete: false, read: 40, readComplete: false, creationComplete: false }, reasoningOutputTokens: 12, providerCredits: 0.05, }); @@ -249,7 +249,7 @@ describe("empty-completion guard retry", () => { expect(continuations).toBe(0); expect(withoutHeartbeats(events)).toEqual([ { type: "thinking_delta", thinking: "..." }, - { type: "done", stopReason: "max_tokens", usage: { inputTokens: 5, outputTokens: 1 } }, + { type: "done", stopReason: "max_tokens", usage: { inputTokens: 5, outputTokens: 1, cacheTelemetry: { source: "adapter", usagePresent: true } } }, ]); }); diff --git a/tests/server/terminal-guard.test.ts b/tests/server/terminal-guard.test.ts index 053a472e3a0..aa612931a7c 100644 --- a/tests/server/terminal-guard.test.ts +++ b/tests/server/terminal-guard.test.ts @@ -486,7 +486,7 @@ describe("terminal guard bounded retention", () => { expect(actual).toHaveLength(events.length); for (let i = 0; i < events.length - 1; i += 1) expect(actual[i]).toBe(events[i]); // Terminal usage is preserved through the existing shallow-copy path. - expect(actual.at(-1)).toEqual(done); + expect(actual.at(-1)).toEqual({ ...done, usage: { ...done.usage, cacheTelemetry: { source: "adapter", usagePresent: true } } }); }); } @@ -587,7 +587,7 @@ describe("terminal guard lifecycle and accounting", () => { expect(calls).toBe(1); expect(actual).toEqual([ announcement, { type: "assistant_boundary" }, - { type: "error", message: failure.message, usage }, + { type: "error", message: failure.message, usage: { ...usage, cacheTelemetry: { source: "client", usagePresent: true, read: 3, creation: 1 } } }, ]); }); } @@ -613,7 +613,7 @@ describe("terminal guard lifecycle and accounting", () => { expect(actual.filter(event => event.type === "done")).toHaveLength(0); expect(actual.at(-1)).toEqual({ type: "error", message: "second continuation setup failed", - usage: { inputTokens: 20, outputTokens: 4, totalTokens: 24, cachedInputTokens: 6 }, + usage: { inputTokens: 20, outputTokens: 4, totalTokens: 24, cachedInputTokens: 6, cacheTelemetry: { source: "aggregate", usagePresent: true, complete: true, read: 6, readComplete: true, creationComplete: false } }, }); }); diff --git a/tests/usage/cache-diagnostic.test.ts b/tests/usage/cache-diagnostic.test.ts index 4e61d7976d4..c1193f15c94 100644 --- a/tests/usage/cache-diagnostic.test.ts +++ b/tests/usage/cache-diagnostic.test.ts @@ -172,9 +172,9 @@ describe("cache diagnostic", () => { append("absent", observeInbound({}, new Headers()), { provenance: "unknown" }); const [zero, absent] = diagnosticRecords(); - expect(zero.cache.rawUpstream).toEqual({ present: true, value: 0 }); + expect(zero.cache.rawUpstream).toEqual({ observed: true, present: true, value: 0 }); expect(zero.cache.normalized).toEqual({ present: true, value: 0, provenance: "observed" }); - expect(absent.cache.rawUpstream).toEqual({ present: false }); + expect(absent.cache.rawUpstream).toEqual({ observed: false, present: false }); expect(absent.cache.normalized).toEqual({ present: false, provenance: "unknown" }); }); diff --git a/tests/usage/cache-telemetry-attempts.test.ts b/tests/usage/cache-telemetry-attempts.test.ts new file mode 100644 index 00000000000..c07eaa07e3b --- /dev/null +++ b/tests/usage/cache-telemetry-attempts.test.ts @@ -0,0 +1,242 @@ +import { afterEach, beforeEach, describe, expect, test } from "bun:test"; +import { mkdtempSync, readFileSync } from "node:fs"; +import { tmpdir } from "node:os"; +import { join } from "node:path"; +import type { OcxUsage, OcxProviderConfig } from "../../src/types"; +import { addFinalRequestLog, aggregateAttemptUsage, applyResponseLogMetadata, beginRequestAttempt, + clearRequestLogsForTests, finishRequestAttempt, noteAttemptSend, noteProviderAttemptSend, recordKeyAttemptUsage, type RequestLogContext } from "../../src/server/request-log"; +import { cacheDiagnosticPath } from "../../src/usage/cache-diagnostic"; +import { cacheProvenance, rawCacheTelemetry, withAdapterCacheTelemetry } from "../../src/usage/cache-telemetry"; +import { readUsageEntries, type PersistedUsageEntry } from "../../src/usage/log"; +import { cacheTokensFromUsage, createUsageSummaryAccumulator, summarizeUsage } from "../../src/usage/summary"; +import { removeTreeWithRetry } from "../helpers/remove-tree"; + +let home: string; +let previousHome: string | undefined; +let previousDebug: string | undefined; +beforeEach(() => { + previousHome = process.env.OPENCODEX_HOME; + previousDebug = process.env.OPENCODEX_CACHE_DEBUG; + home = mkdtempSync(join(tmpdir(), "cache-attempts-")); + process.env.OPENCODEX_HOME = home; + process.env.OPENCODEX_CACHE_DEBUG = "1"; + clearRequestLogsForTests(); +}); +afterEach(() => { + if (previousHome === undefined) delete process.env.OPENCODEX_HOME; + else process.env.OPENCODEX_HOME = previousHome; + if (previousDebug === undefined) delete process.env.OPENCODEX_CACHE_DEBUG; + else process.env.OPENCODEX_CACHE_DEBUG = previousDebug; + clearRequestLogsForTests(); + removeTreeWithRetry(home); +}); +const measured = (): OcxUsage => ({ inputTokens: 100, outputTokens: 5, cachedInputTokens: 40, + cacheTelemetry: rawCacheTelemetry({ input_tokens_details: { cached_tokens: 40 } }) }); +function attempt(ordinal: number, sends: number, usage?: OcxUsage) { + const value = beginRequestAttempt(ordinal, "test", "test", "openai-responses"); + for (let i = 0; i < sends; i++) noteAttemptSend(value, undefined); + if (usage) finishRequestAttempt(value, 200, 1, usage); + return value; +} +function entry(id: string, usage: OcxUsage): PersistedUsageEntry { + return { requestId: id, timestamp: Date.now(), provider: "test", model: "test", status: 200, + durationMs: 1, usageStatus: "reported", usage, cacheProvenance: cacheProvenance(usage) }; +} +function rawDiagnostic() { + return JSON.parse(readFileSync(cacheDiagnosticPath(), "utf8").trim().split("\n").at(-1)!).cache.rawUpstream; +} + +describe("attempt cache completeness", () => { + test("a zero-send candidate does not turn an observed send into unknown", () => { + const result = aggregateAttemptUsage([attempt(1, 1, measured()), attempt(2, 0)]); + expect(result.status).toBe("reported"); + expect(result.usage?.cacheTelemetry).toMatchObject({ source: "aggregate", complete: true, read: 40 }); + expect(cacheProvenance(result.usage)).toBe("observed"); + }); + test("a sent but unreported attempt remains unknown", () => { + const result = aggregateAttemptUsage([attempt(1, 1, measured()), attempt(2, 1)]); + expect(result.status).toBe("unreported"); + expect(result.usage?.cacheTelemetry).toMatchObject({ complete: false, read: 40 }); + expect(cacheProvenance(result.usage)).toBe("unknown"); + }); + test("legacy positive counters cannot erase a sent missing-usage attempt", () => { + const legacy = { inputTokens: 100, outputTokens: 5, cachedInputTokens: 40 }; + const result = aggregateAttemptUsage([attempt(1, 1, legacy), attempt(2, 1)]); + expect(result.usage?.cacheTelemetry).toMatchObject({ source: "aggregate", complete: false, read: 40 }); + expect(cacheProvenance(result.usage)).toBe("unknown"); + expect(cacheProvenance(aggregateAttemptUsage([attempt(1, 1, legacy), attempt(2, 0)]).usage)).toBe("observed"); + }); + test("a locally answered candidate contributes no missing upstream usage", () => { + const local = attempt(2, 1); local.locallyAnswered = true; + expect(cacheProvenance(aggregateAttemptUsage([attempt(1, 1, measured()), local]).usage)).toBe("observed"); + }); + test("an explicit usage record is counted even when send instrumentation is absent", () => { + const result = aggregateAttemptUsage([attempt(1, 1, measured()), attempt(2, 0, { inputTokens: 20, outputTokens: 1 })]); + expect(result.usage?.inputTokens).toBe(120); + expect(cacheProvenance(result.usage)).toBe("unknown"); + }); +}); + +describe("summary cache counters and matched rate samples", () => { + test.each([[40, 10], [4, 10]])("canonical read %i is never reduced by write %i", (read, write) => { + const usage = withAdapterCacheTelemetry({ inputTokens: 100, outputTokens: 1, + cachedInputTokens: read, cacheCreationInputTokens: write })!; + expect(cacheTokensFromUsage(usage)).toMatchObject({ read, creation: write }); + const summary = summarizeUsage([entry("canonical", usage)], "all", Date.now()); + expect(summary.models[0]?.cacheReadInputTokens).toBe(read); + expect(summary.models[0]?.cacheHitRate).toBe(read / 100); + // Unlabeled historic rows retain the old read+write fallback interpretation. + expect(cacheTokensFromUsage({ inputTokens: 100, outputTokens: 1, + cachedInputTokens: read, cacheCreationInputTokens: write }).read).toBe(Math.max(0, read - write)); + }); + test("a write-only measurement does not assert that read was zero", () => { + const usage = withAdapterCacheTelemetry({ inputTokens: 100, outputTokens: 1, cacheCreationInputTokens: 10 })!; + const summary = summarizeUsage([entry("writes-only", usage)], "all", Date.now()); + expect(summary.models[0]?.cacheCreationInputTokens).toBe(10); + expect(summary.models[0]?.cacheObservedInputTokens).toBe(0); + expect(summary.models[0]?.cacheHitRate).toBeNull(); + }); + test("partial aggregate reads remain visible but never inflate a complete sample's rate", () => { + const partial: OcxUsage = { inputTokens: 200, outputTokens: 2, cachedInputTokens: 80, + cacheTelemetry: { source: "aggregate", usagePresent: true, read: 80, complete: false, readComplete: false } }; + const summary = summarizeUsage([entry("complete", measured()), entry("partial", partial)], "all", Date.now()); + expect(summary.models[0]?.cacheReadInputTokens).toBe(120); + expect(summary.models[0]?.cacheObservedInputTokens).toBe(100); + expect(summary.models[0]?.cacheHitRate).toBe(0.4); + expect(summary.providers[0]?.cacheHitRate).toBe(0.4); + expect(summary.days.find(day => day.models.length)?.models[0]?.cacheHitRate).toBe(0.4); + }); + test("mixed read-known and write-only rounds have no fully observed read denominator", () => { + const usage: OcxUsage = { inputTokens: 200, outputTokens: 2, cachedInputTokens: 40, cacheCreationInputTokens: 10, + cacheTelemetry: { source: "aggregate", usagePresent: true, read: 40, creation: 10, + complete: true, readComplete: false, creationComplete: false } }; + const summary = summarizeUsage([entry("asymmetric", usage)], "all", Date.now()); + expect(summary.models[0]?.cacheObservedInputTokens).toBe(0); + expect(summary.models[0]?.cacheHitRate).toBeNull(); + }); +}); + +test("final spend settlement cannot borrow an earlier attempt's usage", () => { + const first = attempt(1, 1, measured()); const last = attempt(2, 1); + let settled: unknown = "not-called"; + const ctx: RequestLogContext = { provider: "test", model: "test", usage: first.usage, + attempts: [first, last], activeAttempt: last, spendTracker: { settle(usage) { settled = usage; } } }; + addFinalRequestLog("stale-usage", Date.now(), ctx, 502); + expect(settled).toBeUndefined(); + const row = readUsageEntries().at(-1)!; + expect(row.usage?.inputTokens).toBe(100); + expect(row.attempts?.[0].usage?.cachedInputTokens).toBe(40); + expect(row.attempts?.[1].usage).toBeUndefined(); + expect(row.cacheProvenance).toBe("unknown"); + expect(rawDiagnostic()).toMatchObject({ observed: false, present: false }); +}); + +test("observed terminal absence is different from no raw observation", () => { + const ctx: RequestLogContext = { provider: "test", model: "test" }; + applyResponseLogMetadata(ctx, { type: "response.completed", response: {} }, "upstream"); + addFinalRequestLog("missing-usage", Date.now(), ctx, 200); + expect(rawDiagnostic()).toEqual({ observed: true, usagePresent: false, present: false }); +}); + +test("a final missing usage clears the earlier one-hour write detail too", () => { + const ctx: RequestLogContext = { provider: "test", model: "test" }; + applyResponseLogMetadata(ctx, { usage: { input_tokens: 100, output_tokens: 1, + input_tokens_details: { cached_tokens: 40, cache_write_tokens: 10, cache_write_1h_tokens: 5 } } }, "upstream"); + applyResponseLogMetadata(ctx, { type: "response.completed", response: {} }, "upstream"); + addFinalRequestLog("missing-terminal", Date.now(), ctx, 200); + expect(readUsageEntries().at(-1)?.usage?.cacheCreation1hInputTokens).toBeUndefined(); + expect(rawDiagnostic()).toEqual({ observed: true, usagePresent: false, present: false }); +}); + +for (const rotate of [false, true]) for (const prefinish of [false, true]) test(`a failed physical resend never borrows raw cache evidence (rotation=${rotate}, prefinish=${prefinish})`, () => { + const active = beginRequestAttempt(1, "test", "test", "openai-responses"); + let settled: unknown = "not-settled"; + const ctx: RequestLogContext = { provider: "test", model: "test", attempts: [active], activeAttempt: active, + spendTracker: { settle(usage) { settled = usage; } } }; + const provider = (apiKey: string): OcxProviderConfig => ({ adapter: "openai-responses", authMode: "key", + _apiKeyAttempt: { reference: apiKey }, baseUrl: "https://example.test/v1" }); + noteProviderAttemptSend(ctx, "test", provider("synthetic-a"), undefined); + applyResponseLogMetadata(ctx, { usage: { input_tokens: 100, output_tokens: 5, + input_tokens_details: { cached_tokens: 40 } } }, "upstream"); + const previousEvidence = active.usage?.cacheTelemetry; + expect(previousEvidence?.source).toBe("upstream"); + noteProviderAttemptSend(ctx, "test", provider(rotate ? "synthetic-b" : "synthetic-a"), undefined, "key-429"); + expect(ctx.activeAttempt).toBe(active); + expect(ctx.attempts).toHaveLength(rotate ? 2 : 1); + if (prefinish) finishRequestAttempt(active, 502, 1); + addFinalRequestLog(`failed-resend-${rotate}-${prefinish}`, Date.now(), ctx, 502); + expect(rawDiagnostic()).toEqual({ observed: false, present: false }); + const row = readUsageEntries().at(-1)!; + expect(row.usage?.cachedInputTokens).toBe(40); + expect(row.cacheProvenance).toBe("unknown"); + expect(row.attempts?.at(-1)?.cacheProvenance).toBe("unknown"); + expect(settled).toBeUndefined(); +}); + +test("fresh adapter raw evidence after a resend remains observable", () => { + const active = attempt(1, 1, measured()); + const ctx: RequestLogContext = { provider: "test", model: "test", attempts: [active], activeAttempt: active }; + noteAttemptSend(active, undefined); + active.usage = { ...measured(), cacheTelemetry: rawCacheTelemetry({ cache_read_input_tokens: 0 }) }; + ctx.usage = active.usage; + addFinalRequestLog("fresh-adapter", Date.now(), ctx, 200); + expect(rawDiagnostic()).toMatchObject({ observed: true, usagePresent: true, present: true, value: 0 }); +}); + +test("filtered legacy combo projection keeps missing evidence and historical read recovery", () => { + const legacy: OcxUsage = { inputTokens: 100, outputTokens: 5, cachedInputTokens: 40, cacheCreationInputTokens: 10 }; + const row = entry("legacy-filter", legacy); + row.attempts = [attempt(1, 1, legacy), attempt(2, 1)]; + const accumulator = createUsageSummaryAccumulator({ filter: { provider: "test" } }); + accumulator.add(row); + const summary = accumulator.summarize("all", Date.now(), "all"); + expect(summary.summary.cacheReadInputTokens).toBe(30); + expect(summary.summary.cacheUnknownRequests).toBe(1); + expect(summary.summary.cacheObservedInputTokens ?? 0).toBe(0); +}); + +for (const reported of [[false, true], [true, false, true]]) test(`missing physical send stays unknown after recovery (${reported})`, () => { + const active = beginRequestAttempt(1, "test", "test", "openai-responses"); + const ctx: RequestLogContext = { provider: "test", model: "test", attempts: [active], activeAttempt: active }; + const provider: OcxProviderConfig = { adapter: "openai-responses", authMode: "key", + _apiKeyAttempt: { reference: "synthetic-a" }, baseUrl: "https://example.test/v1" }; + for (const observed of reported) { + noteProviderAttemptSend(ctx, "test", provider, undefined); + if (observed) applyResponseLogMetadata(ctx, { usage: { input_tokens: 100, output_tokens: 5, + input_tokens_details: { cached_tokens: 40 } } }, "upstream"); + } + addFinalRequestLog(`recovered-gap-${reported.length}`, Date.now(), ctx, 200); + const row = readUsageEntries().at(-1)!; + expect(row.usage?.cachedInputTokens).toBe(reported.filter(Boolean).length * 40); + expect(row.cacheProvenance).toBe("unknown"); + expect(row.attempts?.[0].cacheProvenance).toBe("unknown"); + // The newest send did report a raw value, independent of incomplete chain evidence. + expect(rawDiagnostic()).toMatchObject({ observed: true, present: true, value: 40 }); +}); + +for (const prefinish of [false, true]) test(`fresh adapter raw facts survive an earlier missing send (prefinish=${prefinish})`, () => { + const active = attempt(1, 1); + const ctx: RequestLogContext = { provider: "test", model: "test", attempts: [active], activeAttempt: active }; + noteAttemptSend(active, undefined); + active.usage = measured(); + ctx.usage = active.usage; + if (prefinish) finishRequestAttempt(active, 200, 1); + addFinalRequestLog(`adapter-gap-${prefinish}`, Date.now(), ctx, 200); + expect(readUsageEntries().at(-1)?.cacheProvenance).toBe("unknown"); + expect(rawDiagnostic()).toMatchObject({ observed: true, usagePresent: true, present: true, value: 40 }); +}); + +test("key adapter rounds preserve the last raw reading before summing evidence", () => { + const active = beginRequestAttempt(1, "test", "test", "anthropic"); + const ctx: RequestLogContext = { provider: "test", model: "test", attempts: [active], activeAttempt: active }; + const provider: OcxProviderConfig = { adapter: "anthropic", authMode: "key", + _apiKeyAttempt: { reference: "synthetic-a" }, baseUrl: "https://example.test/v1" }; + for (let round = 0; round < 2; round++) { + noteProviderAttemptSend(ctx, "test", provider, undefined); + recordKeyAttemptUsage(ctx, measured()); + } + addFinalRequestLog("adapter-key-rounds", Date.now(), ctx, 200); + expect(readUsageEntries().at(-1)?.usage?.cachedInputTokens).toBe(80); + expect(readUsageEntries().at(-1)?.cacheProvenance).toBe("observed"); + expect(rawDiagnostic()).toMatchObject({ observed: true, present: true, value: 40 }); +}); diff --git a/tests/usage/cache-telemetry-evidence.test.ts b/tests/usage/cache-telemetry-evidence.test.ts new file mode 100644 index 00000000000..d43a46c5f6a --- /dev/null +++ b/tests/usage/cache-telemetry-evidence.test.ts @@ -0,0 +1,106 @@ +import { describe, expect, test } from "bun:test"; +import type { CacheTelemetry, OcxUsage } from "../../src/types/request"; +import { aggregateCacheTelemetry, cacheProvenance, normalizeCacheTelemetry, rawCacheTelemetry, + usageFromResponsesPayload, withAdapterCacheTelemetry } from "../../src/usage/cache-telemetry"; + +const usage = (extra: Partial = {}): OcxUsage => ({ inputTokens: 100, outputTokens: 1, ...extra }); +const observed = (extra: Partial = {}) => withAdapterCacheTelemetry(usage(extra))!; + +describe("cache evidence counters", () => { + test.each([[40, 10], [4, 10], [0, 10]])("canonical read %i is not reduced by write %i", (read, creation) => { + const value = observed({ cachedInputTokens: read, cacheCreationInputTokens: creation }); + expect(value.cacheTelemetry).toEqual({ source: "adapter", usagePresent: true, read, creation }); + expect(cacheProvenance(value)).toBe("observed"); + expect(aggregateCacheTelemetry([value, value])).toEqual({ source: "aggregate", usagePresent: true, + complete: true, read: read * 2, creation: creation * 2, readComplete: true, creationComplete: true }); + }); + + test("explicit read is authoritative and legacy positive read remains read-only", () => { + expect(observed({ cachedInputTokens: 40, cacheReadInputTokens: 12, cacheCreationInputTokens: 10 }).cacheTelemetry?.read).toBe(12); + expect(aggregateCacheTelemetry([usage({ cachedInputTokens: 40, cacheCreationInputTokens: 10 })])).toMatchObject({ read: 40, creation: 10 }); + expect(aggregateCacheTelemetry([usage({ cachedInputTokens: 0, cacheCreationInputTokens: 10 })])).toMatchObject({ readComplete: false, creation: 10 }); + expect(aggregateCacheTelemetry([usage({ cachedInputTokens: 0, cacheCreationInputTokens: 10 })]).read).toBeUndefined(); + }); + + test.each([-1, NaN, Infinity, -Infinity])("invalid counter %s never becomes observed zero", invalid => { + const value = observed({ cachedInputTokens: invalid, cacheCreationInputTokens: invalid }); + expect(value.cacheTelemetry).toEqual({ source: "adapter", usagePresent: true }); + expect(cacheProvenance(value)).toBe("unknown"); + expect(rawCacheTelemetry({ input_tokens_details: { cached_tokens: invalid, cache_write_tokens: invalid } })) + .toEqual({ source: "upstream", usagePresent: true }); + expect(normalizeCacheTelemetry({ source: "adapter", usagePresent: true, read: invalid })).toBeUndefined(); + }); + + test("invalid metadata cannot fall back to otherwise positive canonical counters", () => { + const value = usage({ cachedInputTokens: 40, + cacheTelemetry: { source: "adapter", usagePresent: true, read: -1 } }); + expect(cacheProvenance(value)).toBe("unknown"); + expect(cacheProvenance(withAdapterCacheTelemetry(value))).toBe("unknown"); + expect(aggregateCacheTelemetry([value])).toMatchObject({ complete: false, readComplete: false }); + }); + + test.each([["client"], ["aggregate"], ["upstream"], ["adapter"], { toString: () => "upstream" }, { source: "adapter" }].map(source => ({ source })))( + "a non-string provenance source cannot become observed", + ({ source }) => { + const malformed = { source, usagePresent: true, read: 40 }; + expect(normalizeCacheTelemetry(malformed)).toBeUndefined(); + const value = usage({ cachedInputTokens: 40, cacheTelemetry: malformed as unknown as CacheTelemetry }); + expect(cacheProvenance(value)).toBe("unknown"); + expect(cacheProvenance(withAdapterCacheTelemetry(value))).toBe("unknown"); + // The closed unknown marker remains unknown after repeated JSON persistence/reload. + let persisted = withAdapterCacheTelemetry(value)!; + for (let i = 0; i < 2; i++) { + const decoded = JSON.parse(JSON.stringify(persisted)) as OcxUsage; + persisted = { ...decoded, cacheTelemetry: normalizeCacheTelemetry(decoded.cacheTelemetry) }; + expect(cacheProvenance(persisted)).toBe("unknown"); + expect(persisted.cacheTelemetry).toEqual({ source: "aggregate", usagePresent: true, complete: false }); + } + }, + ); + + test("client payloads and estimates cannot impersonate raw upstream evidence", () => { + const raw = { input_tokens: 100, output_tokens: 1, input_tokens_details: { cached_tokens: 40 } }; + const client = usageFromResponsesPayload(raw); + expect(client?.cacheTelemetry).toEqual({ source: "client", usagePresent: true }); + expect(cacheProvenance(withAdapterCacheTelemetry(client))).toBe("unknown"); + expect(cacheProvenance(usageFromResponsesPayload(raw, "upstream"))).toBe("observed"); + expect(aggregateCacheTelemetry([observed({ cachedInputTokens: 2 }), observed({ cachedInputTokens: 40, estimated: true })])) + .toMatchObject({ complete: false, read: 2, readComplete: false }); + }); +}); + +describe("cache aggregate evidence", () => { + test("read/write evidence stays asymmetric and nested partial sums stay partial", () => { + const combined = aggregateCacheTelemetry([observed({ cachedInputTokens: 40 }), observed({ cacheCreationInputTokens: 10 })]); + expect(combined).toEqual({ source: "aggregate", usagePresent: true, complete: true, + read: 40, creation: 10, readComplete: false, creationComplete: false }); + expect(cacheProvenance(usage({ cacheTelemetry: combined }))).toBe("observed"); + expect(aggregateCacheTelemetry([usage({ cacheTelemetry: combined }), observed({ cachedInputTokens: 5, cacheCreationInputTokens: 2 })])) + .toEqual({ source: "aggregate", usagePresent: true, complete: true, + read: 45, creation: 12, readComplete: false, creationComplete: false }); + }); + + test("missing usage is a contributing unknown but an empty collection proves nothing", () => { + expect(aggregateCacheTelemetry([])).toEqual({ source: "aggregate", usagePresent: false, + complete: false, readComplete: false, creationComplete: false }); + expect(aggregateCacheTelemetry([undefined, observed({ cachedInputTokens: 0 })])) + .toEqual({ source: "aggregate", usagePresent: true, complete: false, + read: 0, readComplete: false, creationComplete: false }); + }); + + test("closed aggregate flags survive normalization without arbitrary metadata", () => { + const evidence: CacheTelemetry = { source: "aggregate", usagePresent: true, complete: true, + read: 0, readComplete: true, creationComplete: false }; + expect(normalizeCacheTelemetry({ ...evidence, raw: "never retain" })).toEqual(evidence); + expect(normalizeCacheTelemetry({ ...evidence, source: "upstream" })).toBeUndefined(); + expect(normalizeCacheTelemetry({ ...evidence, readComplete: "yes" })).toBeUndefined(); + }); + + test("overflowed sums cannot produce infinite cache evidence", () => { + const value = observed({ cachedInputTokens: Number.MAX_VALUE }); + const aggregate = aggregateCacheTelemetry([value, value]); + expect(aggregate.read).toBeUndefined(); + expect(aggregate.readComplete).toBe(false); + expect(normalizeCacheTelemetry(aggregate)).toEqual(aggregate); + }); +}); diff --git a/tests/usage/key-attribution.test.ts b/tests/usage/key-attribution.test.ts index 092bd9f8a2f..6607d81127b 100644 --- a/tests/usage/key-attribution.test.ts +++ b/tests/usage/key-attribution.test.ts @@ -277,9 +277,9 @@ describe("key attempt accounting", () => { noteProviderAttemptSend(ctx, "test", key, undefined); recordKeyAttemptUsage(ctx, { inputTokens: 10, outputTokens: 0, estimated: true }); noteProviderAttemptSend(ctx, "test", key, undefined); - applyResponseLogMetadata(ctx, { usage: { prompt_tokens: 3, completion_tokens: 2 } }); - applyResponseLogMetadata(ctx, { usage: { prompt_tokens: 3, completion_tokens: 2 } }); - applyResponseLogMetadata(ctx, { usage: { prompt_tokens: 4, completion_tokens: 2 } }); + applyResponseLogMetadata(ctx, { usage: { prompt_tokens: 3, completion_tokens: 2 } }, "upstream"); + applyResponseLogMetadata(ctx, { usage: { prompt_tokens: 3, completion_tokens: 2 } }, "upstream"); + applyResponseLogMetadata(ctx, { usage: { prompt_tokens: 4, completion_tokens: 2 } }, "upstream"); finishRequestAttempt(active, 200, 1); expect(active).toMatchObject({ usageStatus: "estimated", diff --git a/tests/usage/request-log.test.ts b/tests/usage/request-log.test.ts index 29a7c38ee1f..91ee5532159 100644 --- a/tests/usage/request-log.test.ts +++ b/tests/usage/request-log.test.ts @@ -222,7 +222,7 @@ describe("request log metadata", () => { defaultProvider: "gateway", providers: { gateway: { - adapter: "openai-responses", + adapter: "openai-responses", fetch: globalThis.fetch, // Keep this synthetic fixture off ambient proxy transports. authMode: "key", apiKey: "test-key", baseUrl: "https://gateway.example/v1", @@ -678,7 +678,7 @@ describe("request log metadata", () => { ordinal: 1, status: 200, usageStatus: "reported", - usage: { inputTokens: 9, outputTokens: 3, totalTokens: 12 }, + usage: { inputTokens: 9, outputTokens: 3, totalTokens: 12, cacheTelemetry: { source: "client", usagePresent: true } }, }), ]); }); diff --git a/tests/usage/usage-spend-cache-provenance.test.ts b/tests/usage/usage-spend-cache-provenance.test.ts index e18638c2215..efe5573dedb 100644 --- a/tests/usage/usage-spend-cache-provenance.test.ts +++ b/tests/usage/usage-spend-cache-provenance.test.ts @@ -6,6 +6,7 @@ import { type PersistedUsageEntry, } from "../../src/usage/log"; import { cacheObservationFromUsage, summarizeUsage } from "../../src/usage/summary"; +import { rawCacheTelemetry } from "../../src/usage/cache-telemetry"; const NOW = Date.UTC(2026, 8, 14, 12, 0, 0); @@ -22,10 +23,12 @@ function entry(overrides: Partial & { requestId: string }): } describe("cache telemetry provenance", () => { - test("a zero is observed when reported raw and synthesized when read off a wire", () => { + test("zero classification follows original presence, not the wireParsed heuristic", () => { const zeroDetail = { inputTokens: 1000, outputTokens: 10, cachedInputTokens: 0, cacheReadInputTokens: 0 }; - expect(classifyCacheTelemetryProvenance(zeroDetail)).toBe("observed"); - expect(classifyCacheTelemetryProvenance(zeroDetail, { wireParsed: true })).toBe("synthesized"); + expect(classifyCacheTelemetryProvenance(zeroDetail)).toBe("unknown"); + expect(classifyCacheTelemetryProvenance(zeroDetail, { wireParsed: true })).toBe("unknown"); + expect(classifyCacheTelemetryProvenance({ ...zeroDetail, cacheTelemetry: rawCacheTelemetry({ input_tokens_details: { cached_tokens: 0 } }) }, { wireParsed: true })).toBe("observed"); + expect(classifyCacheTelemetryProvenance({ ...zeroDetail, cacheTelemetry: rawCacheTelemetry({}) })).toBe("synthesized"); // A positive reading is a measurement whatever carried it. expect(classifyCacheTelemetryProvenance({ ...zeroDetail, cacheReadInputTokens: 5 }, { wireParsed: true })) .toBe("observed"); @@ -34,9 +37,11 @@ describe("cache telemetry provenance", () => { expect(classifyCacheTelemetryProvenance(undefined)).toBe("unknown"); }); - test("a row written before the field existed keeps its previous reading", () => { - expect(cacheObservationFromUsage({ inputTokens: 10, outputTokens: 1, cacheReadInputTokens: 0 }, undefined).provenance) - .toBe("observed"); + test("historical zeros without original evidence stay unknown regardless of the old label", () => { + for (const label of [undefined, "observed", "synthesized"] as const) { + expect(cacheObservationFromUsage({ inputTokens: 10, outputTokens: 1, cacheReadInputTokens: 0 }, label).provenance).toBe("unknown"); + } + expect(cacheObservationFromUsage({ inputTokens: 10, outputTokens: 1, cacheReadInputTokens: 5 }, undefined).provenance).toBe("observed"); expect(cacheObservationFromUsage({ inputTokens: 10, outputTokens: 1 }, undefined).provenance).toBe("unknown"); expect(cacheObservationFromUsage(undefined, undefined).provenance).toBe("unknown"); // A stored label cannot invent a denominator the row has no fields for. @@ -44,6 +49,20 @@ describe("cache telemetry provenance", () => { }); }); +test("ledger reload retains exact zero evidence, strips unknown metadata, and never backfills old zero labels", () => { + const evidence = { ...rawCacheTelemetry({ input_tokens_details: { cached_tokens: 0 } }), untrusted: "credential-sentinel" }; + const normalized = normalizeUsageEntryForTest(entry({ requestId: "evidence-zero", cacheProvenance: "observed", + usage: { inputTokens: 10, outputTokens: 1, cacheReadInputTokens: 0, cacheTelemetry: evidence } })); + expect(normalized.cacheProvenance).toBe("observed"); + expect(normalized.usage?.cacheTelemetry).toEqual({ source: "upstream", usagePresent: true, read: 0 }); + expect(JSON.stringify(normalized)).not.toContain("credential-sentinel"); + for (const cacheProvenance of ["observed", "synthesized"] as const) { + const old = normalizeUsageEntryForTest(entry({ requestId: "historic-zero", cacheProvenance, + usage: { inputTokens: 10, outputTokens: 1, cacheReadInputTokens: 0 } })); + expect(old.cacheProvenance).toBe("unknown"); + } +}); + describe("persisted spend record", () => { test("counts must be whole, non-negative and internally consistent", () => { expect(normalizeRequestSpend({ sends: 4, settled: 3, unresolved: 1, reserved: 4 })) @@ -60,7 +79,7 @@ describe("persisted spend record", () => { const normalized = normalizeUsageEntryForTest(entry({ requestId: "ocx-1", logicalRequestId: "lr-abc-1", - usage: { inputTokens: 100, outputTokens: 5 }, + usage: { inputTokens: 100, outputTokens: 5, cachedInputTokens: 0, cacheTelemetry: rawCacheTelemetry({}) }, spend: { sends: 4, settled: 4, unresolved: 0, reserved: 4, policyVersion: "guarded-v1" }, cacheProvenance: "synthesized", })); @@ -123,7 +142,7 @@ describe("usage summary spend and cache provenance", () => { }), entry({ requestId: "ocx-synth", - usage: { inputTokens: 1000, outputTokens: 10, cachedInputTokens: 0, cacheReadInputTokens: 0 }, + usage: { inputTokens: 1000, outputTokens: 10, cachedInputTokens: 0, cacheReadInputTokens: 0, cacheTelemetry: rawCacheTelemetry({}) }, cacheProvenance: "synthesized", }), ], "30d", NOW); @@ -150,7 +169,7 @@ describe("usage summary spend and cache provenance", () => { const summary = summarizeUsage([ entry({ requestId: "ocx-only-synth", - usage: { inputTokens: 500, outputTokens: 10, cachedInputTokens: 0, cacheReadInputTokens: 0 }, + usage: { inputTokens: 500, outputTokens: 10, cachedInputTokens: 0, cacheReadInputTokens: 0, cacheTelemetry: rawCacheTelemetry({}) }, cacheProvenance: "synthesized", }), ], "30d", NOW); @@ -176,7 +195,7 @@ describe("usage summary spend and cache provenance", () => { { ordinal: 2, provider: "anthropic", model: "claude-opus-5", adapter: "anthropic", status: 200, durationMs: 5, sendCount: 1, recoveryKinds: [], usageStatus: "reported", - usage: { inputTokens: 1000, outputTokens: 10, cachedInputTokens: 0, cacheReadInputTokens: 0 }, + usage: { inputTokens: 1000, outputTokens: 10, cachedInputTokens: 0, cacheReadInputTokens: 0, cacheTelemetry: rawCacheTelemetry({}) }, cacheProvenance: "synthesized", }, ], @@ -190,3 +209,17 @@ describe("usage summary spend and cache provenance", () => { expect(opus?.cacheObservedInputTokens).toBe(0); }); }); + +// Invalid evidence must not become a legacy positive reading after JSONL normalization. +test("invalid cache evidence stays unknown after repeated ledger normalization", () => { + const source = entry({ requestId: "invalid-evidence", cacheProvenance: "observed", usage: { + inputTokens: 100, outputTokens: 5, cachedInputTokens: 40, + cacheTelemetry: { source: "invented", usagePresent: true, read: 40, secret: "metadata-sentinel" } as never, + } }); + const once = normalizeUsageEntryForTest(source); + const twice = normalizeUsageEntryForTest(JSON.parse(JSON.stringify(once))); + expect(once.cacheProvenance).toBe("unknown"); + expect(twice.cacheProvenance).toBe("unknown"); + expect(cacheObservationFromUsage(twice.usage, twice.cacheProvenance).provenance).toBe("unknown"); + expect(JSON.stringify(twice)).not.toContain("metadata-sentinel"); +}); diff --git a/tests/usage/usage-summary.test.ts b/tests/usage/usage-summary.test.ts index 50242799917..3c11ca592ac 100644 --- a/tests/usage/usage-summary.test.ts +++ b/tests/usage/usage-summary.test.ts @@ -432,7 +432,7 @@ describe("day-level estimated cost", () => { model: i === total - 1 ? "overflow-cache-tail" : `overflow-cache-${String(i).padStart(4, "0")}`, usageStatus: "reported", usage: i === total - 1 - ? { inputTokens: 100, outputTokens: 1, cacheReadInputTokens: cacheRead } + ? { inputTokens: 100, outputTokens: 1, cacheReadInputTokens: cacheRead, cacheTelemetry: { source: "upstream", usagePresent: true, read: cacheRead } } : { inputTokens: 1, outputTokens: 1 }, })); @@ -1620,7 +1620,7 @@ describe("summarizeUsage", () => { usage: { inputTokens: 500, outputTokens: 100, - cacheReadInputTokens: 0, + cacheReadInputTokens: 0, cacheTelemetry: { source: "upstream", usagePresent: true, read: 0 }, }, }), entry({ diff --git a/tests/web-search/web-search-loop-cache-evidence.test.ts b/tests/web-search/web-search-loop-cache-evidence.test.ts new file mode 100644 index 00000000000..ab0bae969ea --- /dev/null +++ b/tests/web-search/web-search-loop-cache-evidence.test.ts @@ -0,0 +1,107 @@ +import { afterEach, describe, expect, spyOn, test } from "bun:test"; +import type { ProviderAdapter } from "../../src/adapters/base"; +import type { AdapterEvent, OcxParsedRequest, OcxUsage } from "../../src/types"; +import { cacheProvenance } from "../../src/usage/cache-telemetry"; +import { runWithWebSearch } from "../../src/web-search/loop"; +import { buildWebSearchTool } from "../../src/web-search/synthetic-tool"; +import { createTestTranslatorBudget } from "../helpers/translator-budget"; + +const usage = (extra: Partial = {}): OcxUsage => ({ inputTokens: 100, outputTokens: 1, ...extra }); +const search = (value?: OcxUsage): AdapterEvent[] => [ + { type: "tool_call_start", id: "search", name: "web_search" }, + { type: "tool_call_delta", arguments: JSON.stringify({ query: "fixture" }) }, + { type: "tool_call_end" }, { type: "done", usage: value }, +]; +const answer = (value?: OcxUsage): AdapterEvent[] => [{ type: "text_delta", text: "answer" }, { type: "done", usage: value }]; +const originalFetch = globalThis.fetch; +afterEach(() => { globalThis.fetch = originalFetch; }); + +// No API-key billing wrapper and no live model/search requests: evidence must be captured by +// the loop itself, not fabricated from its final sum by the outer request transport callback. +async function drive(passes: AdapterEvent[][]) { + spyOn(globalThis, "fetch").mockResolvedValue(Response.json({ results: [] })); + const reported: (OcxUsage | undefined)[] = []; + const adapter: ProviderAdapter = { + name: "fixture", + buildRequest: () => ({ url: "https://routed.test/v1", method: "POST", headers: {}, body: "{}" }), + fetchResponse: async () => new Response("synthetic"), + async *parseStream() { yield* passes.shift()!; }, + }; + const parsed: OcxParsedRequest = { modelId: "fixture", stream: true, options: {}, + context: { messages: [], tools: [buildWebSearchTool()] } }; + const response = await runWithWebSearch({ parsed, adapter, backend: "exa", exaApiKey: "fixture", + hostedTool: { type: "web_search" }, settings: { model: "fixture", reasoning: "low", timeoutMs: 1000 }, + maxSearches: 1, incomingMeta: { headers: new Headers(), translatorBudget: createTestTranslatorBudget() }, + onUsage: value => reported.push(value) }); + const text = await response.text(); + const terminal = text.split("\n").filter(line => line.startsWith("data: {")).map(line => JSON.parse(line.slice(6))) + .find(frame => frame.type === "response.completed" || frame.type === "response.failed"); + return { reported, text, clientUsage: terminal?.response?.usage }; +} + +describe("web-search physical-round cache evidence", () => { + test("zero plus read/write evidence is complete without reducing canonical reads", async () => { + const { reported, text, clientUsage } = await drive([ + search(usage({ cachedInputTokens: 0 })), answer(usage({ cachedInputTokens: 40, cacheCreationInputTokens: 10 })), + ]); + expect(reported).toHaveLength(1); + expect(reported[0]).toMatchObject({ inputTokens: 200, outputTokens: 2, cachedInputTokens: 40, + cacheTelemetry: { source: "aggregate", usagePresent: true, complete: true, read: 40, creation: 10, + readComplete: true, creationComplete: false } }); + expect(cacheProvenance(reported[0])).toBe("observed"); + expect(clientUsage).toMatchObject({ input_tokens: 100, output_tokens: 1, input_tokens_details: { cached_tokens: 40 } }); + expect(text).not.toContain("cacheTelemetry"); + expect(text).not.toContain("readComplete"); + }); + + test.each([true, false])("missing cache fields remain unknown (first=%s)", async missingFirst => { + const known = usage({ cachedInputTokens: 40 }); + const { reported } = await drive([search(missingFirst ? usage() : known), answer(missingFirst ? known : usage())]); + expect(reported[0]).toMatchObject({ inputTokens: 200, + cacheTelemetry: { source: "aggregate", complete: false, read: 40, readComplete: false } }); + expect(cacheProvenance(reported[0])).toBe("unknown"); + }); + + test.each([true, false])("missing whole usage remains unknown (first=%s)", async missingFirst => { + const known = usage({ cachedInputTokens: 0 }); + const { reported } = await drive([search(missingFirst ? undefined : known), answer(missingFirst ? known : undefined)]); + expect(reported[0]).toMatchObject({ inputTokens: 100, + cacheTelemetry: { source: "aggregate", complete: false, read: 0, readComplete: false } }); + expect(cacheProvenance(reported[0])).toBe("unknown"); + }); + + test("write-only and read-only rounds keep their partial sums without asserting a full read denominator", async () => { + const { reported } = await drive([search(usage({ cacheCreationInputTokens: 10 })), answer(usage({ cachedInputTokens: 40 }))]); + expect(reported[0]?.cacheTelemetry).toEqual({ source: "aggregate", usagePresent: true, complete: true, + read: 40, creation: 10, readComplete: false, creationComplete: false }); + }); + + test("an unreported empty forced-answer retry stays in completeness accounting", async () => { + const { reported } = await drive([search(usage({ cachedInputTokens: 0 })), [{ type: "done" }], answer(usage({ cachedInputTokens: 40 }))]); + expect(reported[0]).toMatchObject({ inputTokens: 200, + cacheTelemetry: { complete: false, read: 40, readComplete: false } }); + }); + + test.each(["error", "EOF"])("a physical %s without usage leaves earlier evidence incomplete", async kind => { + const failed: AdapterEvent[] = kind === "error" ? [{ type: "error", message: "synthetic failure" }] : []; + const { reported, text } = await drive([search(usage({ cachedInputTokens: 40 })), failed]); + expect(text).toContain("response.failed"); + expect(reported).toHaveLength(1); + expect(reported[0]?.cacheTelemetry).toMatchObject({ complete: false, read: 40, readComplete: false }); + }); + + test("reported error usage is observed before accumulation and counted once", async () => { + const { reported, text } = await drive([search(usage({ cachedInputTokens: 40 })), [ + { type: "error", message: "synthetic failure", usage: usage({ cachedInputTokens: 5 }) }, + ]]); + expect(text).toContain("response.failed"); + expect(reported).toHaveLength(1); + expect(reported[0]).toMatchObject({ inputTokens: 200, + cacheTelemetry: { complete: true, read: 45, readComplete: true } }); + }); + + test("a single physical response is not tainted by the empty hidden accumulator", async () => { + const { reported } = await drive([answer(usage({ cachedInputTokens: 0 }))]); + expect(reported[0]?.cacheTelemetry).toEqual({ source: "adapter", usagePresent: true, read: 0 }); + }); +});