diff --git a/devlog/_plan/260820_bug_pr_backlog_consolidation/080_residual_dispositions.md b/devlog/_plan/260820_bug_pr_backlog_consolidation/080_residual_dispositions.md index 3aa59cc031..a35be68067 100644 --- a/devlog/_plan/260820_bug_pr_backlog_consolidation/080_residual_dispositions.md +++ b/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. + diff --git a/src/server/request-log.ts b/src/server/request-log.ts index 9658cbd2fa..26a69a14ab 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 } : {}), @@ -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 } : {}), 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..09512c50e1 100644 --- a/tests/request-log.test.ts +++ b/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. 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 () => {