fix(logs): sanitize the shadow helper marker at the logging layer

devlog/_plan/260820_bug_pr_backlog_consolidation/080_residual_dispositions.md

@@ -272,3 +272,44 @@ not as a side effect of a quota fix.
 The defensive canonical-URL check inside `fetchOpenCodeGoQuota` (`quota.ts:485-494`) stays: it
 is what stops an API key being sent to a non-canonical host, and it should not depend on the
 dispatch predicate being correct.
+
+### wp18-wp20 — the rest of the chain
+
+**#2027 @yzxcj797 -> PR #2164.** Dispatch gated on the literal name `opencode-go`, so the
+multi-account sibling rows in #1924 had no quota panel and no CLI report. The contributor's
+base-URL swap is closer but does not check the adapter; `registryEntryForProviderDestination`
+already answers exactly this question (endpoint + adapter + key auth) and is the existing
+convention for renamed rows. Rejected: `providerMatchesRegistryTransport` would need
+`preserveCustomDestination`, which also changes routing for same-named custom rows.
+
+**#2155 @waw4303 -> PR #2165.** Field validation ran before the pending-call lookup, so a
+non-string repeat of an already-canonical field killed the turn with a 502. Two corrections:
+`arguments` was gated on a canonical NAME (a name is not evidence about the arguments field,
+so a real payload could be dropped) — now keyed on `sawArgumentsString`; and `id` stayed
+unconditionally terminal. Diagnostics now come from the rejection site, because a stateless
+rescan blamed call 0's accepted padding for call 1's real defect.
+
+**#2163 @Ingwannu -> PR #2166.** Scored 65. Backend attribution was correct; sanitization sat
+at the one call site rather than in the logging layer, so `/api/logs` carried the raw
+caller-supplied value. Moved into `addFinalRequestLog`. #2157 stays open: the GUI half is not
+built, and closing it would claim an affordance that does not exist.
+
+### The stack
+
+Six layers, each rebased onto the current `dev` tip, base refs verified:
+
+#2134 -> #2160 -> #2162 -> #2164 -> #2165 -> #2166
+
+Only one true dependency edge exists in the whole set (none of the six share files). They are
+chained rather than opened as siblings because the user asked for one reviewable stack; that is
+a review-workflow choice, stated rather than dressed up as a code constraint.
+
+A privacy-scan failure caught in CI and not locally: a test fixture API key over 24 characters
+reads as a real bearer token to `scripts/privacy-scan.ts`. Fixed at the L4 commit.
+
+### End state
+
+`gh pr list --label bug --state open` returns only lidge-jun PRs plus #2054, which stays open
+by explicit instruction and carries the wire-probe request. Nine contributor PRs closed with
+attribution across this unit; none was closed without a named reason.
+

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 } : {}),
@@ -327,6 +334,20 @@ export function hydrateRequestLogsFromDisk(
 }
 
 export function addRequestLog(entry: RequestLogEntry) {
+  // Sanitize ONCE, at the ingress, and use that one value for both destinations.
+  //
+  // `addFinalRequestLog` is not the only way in: `addRequestLog` is exported and callable
+  // directly, and it retained the caller's entry verbatim in the in-memory ring while only the
+  // field-by-field disk projection below saw a sanitized value. That split let `/api/logs`
+  // serve a raw upstream-supplied marker — a newline in it can forge a record boundary in a
+  // line-oriented viewer — while `usage.jsonl` looked clean, which is the worst shape for a
+  // sanitization bug because the safe surface is the one you check.
+  const shadowCallRewrittenFrom = sanitizeLogMetadataString(entry.shadowCallRewrittenFrom);
+  const retained: RequestLogEntry = shadowCallRewrittenFrom === entry.shadowCallRewrittenFrom
+    ? entry
+    : { ...entry, ...(shadowCallRewrittenFrom ? { shadowCallRewrittenFrom } : {}) };
+  if (!shadowCallRewrittenFrom && retained !== entry) delete retained.shadowCallRewrittenFrom;
+  entry = retained;
   retainRequestLogEntry(entry);
   try {
     // Failure diagnostics survive the 200-entry ring buffer by riding the persisted
@@ -358,6 +379,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 +929,12 @@ export function addFinalRequestLog(
   const loggedUsage = aggregate?.usage ?? existing.usage;
   const usageStatus = aggregate?.status ?? existing.status;
   const totalTokens = aggregate?.totalTokens ?? existing.totalTokens;
+  // Sanitize at the logging layer, not only at the one call site that populates this today.
+  // The value originates in an upstream-supplied model id, so an unsanitized newline would
+  // let a single field forge a record boundary in any line-oriented log viewer. Doing it here
+  // means a future caller cannot reintroduce the hole by forgetting to sanitize first, and
+  // the in-memory /api/logs row matches what usage.jsonl already stores.
+  const shadowCallRewrittenFrom = sanitizeLogMetadataString(logCtx.shadowCallRewrittenFrom);
   addLog({
     requestId,
     timestamp: start,
@@ -919,6 +949,7 @@ 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 } : {}),

src/server/responses/core.ts

@@ -1838,7 +1838,7 @@ async function handleResponsesInner(
     if (parsed._rawBody && typeof parsed._rawBody === "object") {
       (parsed._rawBody as Record<string, unknown>).reasoning = { effort: "low" };
     }
-    (logCtx as unknown as Record<string, unknown>).shadowCallRewrittenFrom = _sciOriginal;
+    logCtx.shadowCallRewrittenFrom = sanitizeLogMetadataString(_sciOriginal);
     // Helpers must not resume/append into the parent thread's Cursor conversation.
     parsed._cursorIsolateConversation = true;
   }

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) }
       : {}),

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

tests/request-log.test.ts

@@ -11,6 +11,7 @@ import {
 } from "../src/server";
 import {
   aggregateAttemptUsage,
+  addRequestLog,
   beginRequestAttempt,
   clearRequestLogsForTests,
   finishRequestAttempt,
@@ -258,6 +259,102 @@ 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;
+    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: "gpt-5.6-luna",
+      }, 200);
+
+      const [persisted] = readUsageEntries();
+      expect(persisted?.shadowCallRewrittenFrom).toBe("gpt-5.6-luna");
+      expect(getRequestLogEntries()[0]?.shadowCallRewrittenFrom).toBe("gpt-5.6-luna");
+    } finally {
+      clearRequestLogsForTests();
+      if (previousHome === undefined) delete process.env.OPENCODEX_HOME;
+      else process.env.OPENCODEX_HOME = previousHome;
+      resetUsageReadCacheForTests();
+      rmSync(home, { recursive: true, force: true });
+    }
+  });
+
+  // The value is caller-controlled, so proving it lands is only half the contract: the
+  // persistence path must also be the SANITIZED one. A test that only ever writes a safe
+  // short slug passes identically whether `sanitizeLogMetadataString` is applied or not.
+  test("the shadow marker reaches usage.jsonl through the sanitizer, not raw", () => {
+    const home = mkdtempSync(join(tmpdir(), "ocx-shadow-unsafe-"));
+    const previousHome = process.env.OPENCODEX_HOME;
+    process.env.OPENCODEX_HOME = home;
+    try {
+      clearRequestLogsForTests();
+      resetUsageReadCacheForTests();
+      addFinalRequestLog("ocx-shadow-unsafe", 1, {
+        model: "grok-4.5",
+        provider: "xai",
+        // A newline would let one field forge a record boundary in a line-oriented log
+        // viewer, and the trailing run is long enough to be over the 64-character bound.
+        shadowCallRewrittenFrom: `gpt-5.6-luna\nInjected: yes ${"x".repeat(80)}`,
+      }, 200);
+
+      const [persisted] = readUsageEntries();
+      const marker = persisted?.shadowCallRewrittenFrom;
+      expect(marker).toBeDefined();
+      expect(marker).not.toContain("\n");
+      expect(marker!.length).toBeLessThanOrEqual(64);
+      expect(marker!.startsWith("gpt-5.6-luna")).toBe(true);
+      expect(getRequestLogEntries()[0]?.shadowCallRewrittenFrom).not.toContain("\n");
+    } finally {
+      clearRequestLogsForTests();
+      if (previousHome === undefined) delete process.env.OPENCODEX_HOME;
+      else process.env.OPENCODEX_HOME = previousHome;
+      resetUsageReadCacheForTests();
+      rmSync(home, { recursive: true, force: true });
+    }
+  });
+
+  // `addFinalRequestLog` is not the only ingress: `addRequestLog` is exported and callable
+  // directly. Sanitizing only on the disk projection left the in-memory ring — and therefore
+  // /api/logs — serving the raw value, which is the worst shape for a sanitization bug
+  // because the surface you would check is the clean one.
+  test("the direct addRequestLog ingress sanitizes memory and disk identically", () => {
+    const home = mkdtempSync(join(tmpdir(), "ocx-shadow-ingress-"));
+    const previousHome = process.env.OPENCODEX_HOME;
+    process.env.OPENCODEX_HOME = home;
+    try {
+      clearRequestLogsForTests();
+      resetUsageReadCacheForTests();
+      addRequestLog({
+        requestId: "ocx-shadow-direct",
+        timestamp: Date.now(),
+        provider: "xai",
+        model: "grok-4.5",
+        status: 200,
+        shadowCallRewrittenFrom: `gpt-5.6-luna\nInjected: yes ${"x".repeat(80)}`,
+      } as RequestLogEntry);
+
+      const inMemory = getRequestLogEntries()[0]?.shadowCallRewrittenFrom;
+      const [persisted] = readUsageEntries();
+      expect(inMemory).toBeDefined();
+      expect(inMemory).not.toContain("\n");
+      expect(inMemory!.length).toBeLessThanOrEqual(64);
+      // The two surfaces must agree: a divergence here is exactly the bug.
+      expect(inMemory).toBe(persisted?.shadowCallRewrittenFrom);
+    } 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 +1409,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 +1432,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 +1480,7 @@ describe("request log restart hydrate", () => {
         terminalStatus: "failed",
         closeReason: "terminal",
         upstreamError: "Provider unreachable",
+        shadowCallRewrittenFrom: "gpt-5.6-luna",
       },
     ];
 
@@ -1392,6 +1492,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.

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<Response> {
+async function post(
+  config: OcxConfig,
+  model: string,
+  requestKind?: string,
+  logCtx: RequestLogContext = { model: "", provider: "" },
+): Promise<Response> {
   const headers: Record<string, string> = { "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<Record<string, unknown>> = [];
+    const logCtx: RequestLogContext = { model: "", provider: "" };
     globalThis.fetch = (async (_url: unknown, init?: RequestInit) => {
       bodies.push(JSON.parse(String(init?.body ?? "{}")) as Record<string, unknown>);
       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 () => {