From 3d9fb6c8ca5a82984870b600b586cf05c4464064 Mon Sep 17 00:00:00 2001 From: Ingwannu Date: Thu, 20 Aug 2026 00:51:00 +0000 Subject: [PATCH] fix(logs): persist shadow helper attribution --- src/server/request-log.ts | 14 +++++++++ src/server/responses/core.ts | 2 +- src/usage/log.ts | 4 +++ structure/05_gui-and-management-api.md | 3 ++ tests/request-log.test.ts | 37 ++++++++++++++++++++++++ tests/responses-shadow-intercept.test.ts | 14 +++++++-- 6 files changed, 70 insertions(+), 4 deletions(-) diff --git a/src/server/request-log.ts b/src/server/request-log.ts index 9658cbd2fa..af401abb7b 100644 --- a/src/server/request-log.ts +++ b/src/server/request-log.ts @@ -65,6 +65,8 @@ export interface RequestLogContext { /** Stable non-PII Codex Pool account identity for durable usage attribution. */ accountLogLabel?: string; requestedModel?: string; + /** Original bare helper model when the opt-in shadow-call route rewrote this request. */ + shadowCallRewrittenFrom?: string; /** Internal structural combo identity; omitted from RequestLogEntry/JSONL. */ comboId?: string; requestedEffort?: string; @@ -142,6 +144,8 @@ export interface RequestLogEntry { /** Best-effort chat/session correlation for Logs grouping (#330). */ conversationId?: string; requestedModel?: string; + /** Original bare helper model when the opt-in shadow-call route rewrote this request. */ + shadowCallRewrittenFrom?: string; requestedEffort?: string; effectiveEffort?: string; reasoningWireField?: string; @@ -255,6 +259,9 @@ export function requestLogEntryFromPersistedUsage(entry: PersistedUsageEntry): R ? { accountLogLabel: entry.accountLogLabel } : {}), ...(entry.requestedModel ? { requestedModel: entry.requestedModel } : {}), + ...(entry.shadowCallRewrittenFrom + ? { shadowCallRewrittenFrom: entry.shadowCallRewrittenFrom } + : {}), ...(entry.requestedEffort ? { requestedEffort: entry.requestedEffort } : {}), ...(entry.effectiveEffort ? { effectiveEffort: entry.effectiveEffort } : {}), ...(entry.reasoningWireField ? { reasoningWireField: entry.reasoningWireField } : {}), @@ -358,6 +365,9 @@ export function addRequestLog(entry: RequestLogEntry) { ...(entry.conversationId ? { conversationId: entry.conversationId } : {}), ...(entry.resolvedModel ? { resolvedModel: entry.resolvedModel } : {}), ...(entry.requestedModel ? { requestedModel: entry.requestedModel } : {}), + ...(entry.shadowCallRewrittenFrom + ? { shadowCallRewrittenFrom: entry.shadowCallRewrittenFrom } + : {}), ...(entry.requestedEffort ? { requestedEffort: entry.requestedEffort } : {}), ...(entry.effectiveEffort ? { effectiveEffort: entry.effectiveEffort } : {}), ...(entry.reasoningWireField ? { reasoningWireField: entry.reasoningWireField } : {}), @@ -905,6 +915,7 @@ export function addFinalRequestLog( const loggedUsage = aggregate?.usage ?? existing.usage; const usageStatus = aggregate?.status ?? existing.status; const totalTokens = aggregate?.totalTokens ?? existing.totalTokens; + const shadowCallRewrittenFrom = sanitizeLogMetadataString(logCtx.shadowCallRewrittenFrom); addLog({ requestId, timestamp: start, @@ -919,6 +930,9 @@ export function addFinalRequestLog( : {}), ...(logCtx.conversationId ? { conversationId: logCtx.conversationId } : {}), ...(logCtx.requestedModel ? { requestedModel: logCtx.requestedModel } : {}), + ...(shadowCallRewrittenFrom + ? { shadowCallRewrittenFrom } + : {}), ...(logCtx.requestedEffort ? { requestedEffort: logCtx.requestedEffort } : {}), ...(logCtx.effectiveEffort ? { effectiveEffort: logCtx.effectiveEffort } : {}), ...(logCtx.reasoningWireField ? { reasoningWireField: logCtx.reasoningWireField } : {}), diff --git a/src/server/responses/core.ts b/src/server/responses/core.ts index 9e2813d0b5..f693bc6699 100644 --- a/src/server/responses/core.ts +++ b/src/server/responses/core.ts @@ -1838,7 +1838,7 @@ async function handleResponsesInner( if (parsed._rawBody && typeof parsed._rawBody === "object") { (parsed._rawBody as Record).reasoning = { effort: "low" }; } - (logCtx as unknown as Record).shadowCallRewrittenFrom = _sciOriginal; + logCtx.shadowCallRewrittenFrom = sanitizeLogMetadataString(_sciOriginal); // Helpers must not resume/append into the parent thread's Cursor conversation. parsed._cursorIsolateConversation = true; } diff --git a/src/usage/log.ts b/src/usage/log.ts index a526d8ddf5..fd93059e68 100644 --- a/src/usage/log.ts +++ b/src/usage/log.ts @@ -84,6 +84,8 @@ export interface PersistedUsageEntry { conversationId?: string; resolvedModel?: string; requestedModel?: string; + /** Original bare helper model when the opt-in shadow-call route rewrote this request. */ + shadowCallRewrittenFrom?: string; /** Reasoning effort / service-tier metadata for GUI Logs after restart. */ requestedEffort?: string; /** Adapter-normalized tier and exact upstream parameter emitted for this request. */ @@ -427,6 +429,7 @@ function normalizeUsageEntry(entry: PersistedUsageEntry): PersistedUsageEntry { const tierOutcome = entry.tierOutcome ? normalizeAttemptTierOutcome(entry.tierOutcome) : undefined; const callerServiceTier = sanitizeLogMetadataString(entry.callerServiceTier); const responseServiceTier = sanitizeLogMetadataString(entry.responseServiceTier); + const shadowCallRewrittenFrom = sanitizeLogMetadataString(entry.shadowCallRewrittenFrom); const routeDecision = entry.routeDecision ? normalizeRouteDecisionTrace(entry.routeDecision) : undefined; @@ -453,6 +456,7 @@ function normalizeUsageEntry(entry: PersistedUsageEntry): PersistedUsageEntry { : {}), ...(entry.resolvedModel ? { resolvedModel: entry.resolvedModel } : {}), ...(entry.requestedModel ? { requestedModel: entry.requestedModel } : {}), + ...(shadowCallRewrittenFrom ? { shadowCallRewrittenFrom } : {}), ...(typeof entry.requestedEffort === "string" && entry.requestedEffort ? { requestedEffort: capMetadataString(entry.requestedEffort) } : {}), diff --git a/structure/05_gui-and-management-api.md b/structure/05_gui-and-management-api.md index a4bbcbe6db..688f112020 100644 --- a/structure/05_gui-and-management-api.md +++ b/structure/05_gui-and-management-api.md @@ -320,6 +320,9 @@ keeps the saved state and renders fixed `ocx sync` guidance without server/accou ## Usage accounting `src/usage/log.ts` writes append-only JSONL to `~/.opencodex/usage.jsonl` with file mode `0o600`. +An opt-in shadow-call rewrite persists the bounded, redacted original helper model as +`shadowCallRewrittenFrom`, so helper traffic remains identifiable after restart without storing +request content or inferring a helper subtype from timing. `src/usage/summary.ts` turns that file into the `/api/usage` shape — totals, daily zero-filled grid, model and provider breakdowns, and `measured / reported / unreported / unsupported / estimated` counts. A Codex-surface response also includes an `accounts` breakdown keyed by the stable non-PII diff --git a/tests/request-log.test.ts b/tests/request-log.test.ts index e1f6eefab7..63d18646b2 100644 --- a/tests/request-log.test.ts +++ b/tests/request-log.test.ts @@ -258,6 +258,39 @@ describe("request log metadata", () => { expect(captured2[0]).not.toHaveProperty("firstOutputMs"); }); + test("persists the shadow helper source marker to usage.jsonl", () => { + const home = mkdtempSync(join(tmpdir(), "ocx-shadow-usage-")); + const previousHome = process.env.OPENCODEX_HOME; + const rawSecret = `sk-proj-${"x".repeat(96)}`; + const unsafeMarker = `gpt-5.6-luna\r\nBearer ${rawSecret}\u0007 ${"tail".repeat(32)}`; + process.env.OPENCODEX_HOME = home; + try { + clearRequestLogsForTests(); + resetUsageReadCacheForTests(); + addFinalRequestLog("ocx-shadow-marker", 1, { + model: "grok-4.5", + provider: "xai", + requestedModel: "gpt-5.6-luna", + shadowCallRewrittenFrom: unsafeMarker, + }, 200); + + const [persisted] = readUsageEntries(); + const persistedMarker = persisted?.shadowCallRewrittenFrom; + const inMemoryMarker = getRequestLogEntries()[0]?.shadowCallRewrittenFrom; + expect(persistedMarker).toBe(inMemoryMarker); + expect(persistedMarker).toBeDefined(); + expect(persistedMarker!.length).toBeLessThanOrEqual(64); + expect(persistedMarker).not.toContain(rawSecret); + expect(persistedMarker).not.toMatch(/[\u0000-\u001f\u007f-\u009f\u2028\u2029]/); + } finally { + clearRequestLogsForTests(); + if (previousHome === undefined) delete process.env.OPENCODEX_HOME; + else process.env.OPENCODEX_HOME = previousHome; + resetUsageReadCacheForTests(); + rmSync(home, { recursive: true, force: true }); + } + }); + test("records ordered attempts with sealed identity, fresh estimates, and deduplicated recoveries", () => { const a = beginRequestAttempt(1, "provisional-a", "model-a", "openai-chat"); noteAttemptSend(a, 100); @@ -1312,6 +1345,7 @@ describe("request log restart hydrate", () => { provider: "chatgpt-pabcdef", model: "gpt-5.6-sol", requestedModel: "gpt-5.6-sol", + shadowCallRewrittenFrom: "gpt-5.6-luna", requestedEffort: "high", effectiveEffort: "high", reasoningWireField: "reasoning_effort", @@ -1334,6 +1368,7 @@ describe("request log restart hydrate", () => { provider: "chatgpt-pabcdef", model: "gpt-5.6-sol", requestedModel: "gpt-5.6-sol", + shadowCallRewrittenFrom: "gpt-5.6-luna", requestedEffort: "high", effectiveEffort: "high", reasoningWireField: "reasoning_effort", @@ -1381,6 +1416,7 @@ describe("request log restart hydrate", () => { terminalStatus: "failed", closeReason: "terminal", upstreamError: "Provider unreachable", + shadowCallRewrittenFrom: "gpt-5.6-luna", }, ]; @@ -1392,6 +1428,7 @@ describe("request log restart hydrate", () => { errorCode: "upstream_server_error", upstreamError: "Provider unreachable", requestedEffort: "xhigh", + shadowCallRewrittenFrom: "gpt-5.6-luna", }); // Idempotent: a second start in the same process must not duplicate. diff --git a/tests/responses-shadow-intercept.test.ts b/tests/responses-shadow-intercept.test.ts index 7950f86c60..18ee9eb059 100644 --- a/tests/responses-shadow-intercept.test.ts +++ b/tests/responses-shadow-intercept.test.ts @@ -10,6 +10,7 @@ import { join } from "node:path"; import { handleResponses, isShadowSourceModel } from "../src/server/responses"; import { shouldInterceptShadowCall } from "../src/lib/shadow-call"; import { handleManagementAPI } from "../src/server/management-api"; +import type { RequestLogContext } from "../src/server/request-log"; import type { OcxConfig } from "../src/types"; import { catalogConvergenceFactory } from "./helpers/catalog-convergence"; @@ -90,7 +91,12 @@ function interceptConfig(): OcxConfig { } as OcxConfig; } -async function post(config: OcxConfig, model: string, requestKind?: string): Promise { +async function post( + config: OcxConfig, + model: string, + requestKind?: string, + logCtx: RequestLogContext = { model: "", provider: "" }, +): Promise { const headers: Record = { "content-type": "application/json" }; if (requestKind) { headers["x-codex-turn-metadata"] = JSON.stringify({ request_kind: requestKind }); @@ -104,7 +110,7 @@ async function post(config: OcxConfig, model: string, requestKind?: string): Pro stream: false, reasoning: { effort: "high" }, }), - }), config, { model: "", provider: "" }); + }), config, logCtx); } describe("shadow call intercept request path (issue #311)", () => { @@ -130,6 +136,7 @@ describe("shadow call intercept request path (issue #311)", () => { test("rewrites a gpt-5.6-luna turn request too (#1684)", async () => { const bodies: Array> = []; + const logCtx: RequestLogContext = { model: "", provider: "" }; globalThis.fetch = (async (_url: unknown, init?: RequestInit) => { bodies.push(JSON.parse(String(init?.body ?? "{}")) as Record); return new Response(JSON.stringify({ @@ -138,10 +145,11 @@ describe("shadow call intercept request path (issue #311)", () => { }), { status: 200, headers: { "content-type": "application/json" } }); }) as typeof fetch; - await post(interceptConfig(), "gpt-5.6-luna", "turn"); + await post(interceptConfig(), "gpt-5.6-luna", "turn", logCtx); expect(bodies.length).toBe(1); expect(String(bodies[0]?.model ?? "")).toContain("grok-4.5"); + expect(logCtx.shadowCallRewrittenFrom).toBe("gpt-5.6-luna"); }); test("leaves gpt-5.6-terra requests unrewritten", async () => {