diff --git a/src/server/index.ts b/src/server/index.ts index 0601bb04e..4f5775c87 100644 --- a/src/server/index.ts +++ b/src/server/index.ts @@ -90,6 +90,7 @@ import { hydrateRequestLogsFromDisk, httpStatusForRequestLogTerminal, httpStatusForTerminalStatus, + ingressSpanFromHeader, inspectResponseLogSsePayload, nextRequestLogId, recordFirstOutput, @@ -841,11 +842,13 @@ export function startServer(port?: number, deps: StartServerDeps = {}) { } const start = Date.now(); const requestId = nextRequestLogId(start); + const ingressSpan = ingressSpanFromHeader(req.headers.get("x-opencodex-ingress-span")); const logCtx: RequestLogContext = { model: "unknown", provider: "unknown", ...admissionFields(admission), inboundProtocol: "responses", + ...(ingressSpan ? { ingressSpan } : {}), }; let logged = false; const finalizeNativePassthroughLog = ( diff --git a/src/server/request-log.ts b/src/server/request-log.ts index 4e317967b..d28b57b77 100644 --- a/src/server/request-log.ts +++ b/src/server/request-log.ts @@ -36,9 +36,20 @@ import { import { matchesLogConversationId } from "./request-log-conversation"; import { enforceAppOwnedMemoryBudget, type RetainedStoreSnapshot } from "../lib/app-owned-memory"; +const INGRESS_SPAN_RE = /^[A-Za-z0-9_-]{24}_[0-9a-f]{16}$/; + +/** Accept only the content-free app-server correlation token. */ +export function ingressSpanFromHeader(value: string | null): string | undefined { + if (typeof value !== "string") return undefined; + const span = value.trim(); + return INGRESS_SPAN_RE.test(span) ? span : undefined; +} + export interface RequestLogContext { model: string; provider: string; + /** Validated, content-free app-server ingress correlation token. */ + ingressSpan?: string; /** TTFT: ms from request start to the first non-empty model output delta (WP4, devlog 040). */ firstOutputMs?: number; /** Best-effort chat/session correlation for Logs grouping (#330). Opaque; omit when unknown. */ @@ -106,6 +117,8 @@ export interface RequestLogEntry { timestamp: number; model: string; provider: string; + /** Validated, content-free app-server ingress correlation token. */ + ingressSpan?: string; /** TTFT: ms from request start to the first non-empty model output delta; unset for non-streaming/tool-only. */ firstOutputMs?: number; surface?: "claude" | "claude-desktop" | "grok"; @@ -226,6 +239,9 @@ export function requestLogEntryFromPersistedUsage(entry: PersistedUsageEntry): R timestamp: entry.timestamp, model: entry.model, provider: entry.provider, + ...(ingressSpanFromHeader(entry.ingressSpan ?? null) + ? { ingressSpan: ingressSpanFromHeader(entry.ingressSpan ?? null) } + : {}), ...(entry.firstOutputMs !== undefined ? { firstOutputMs: entry.firstOutputMs } : {}), ...(isKnownUsageSurface(entry.surface) ? { surface: entry.surface } : {}), ...(entry.conversationId ? { conversationId: entry.conversationId } : {}), @@ -252,7 +268,7 @@ export function requestLogEntryFromPersistedUsage(entry: PersistedUsageEntry): R usageStatus: entry.usageStatus, ...(entry.usage ? { usage: entry.usage } : {}), ...(entry.totalTokens !== undefined ? { totalTokens: entry.totalTokens } : {}), - ...(entry.attempts?.length ? { attempts: entry.attempts } : {}), + ...(entry.attempts !== undefined ? { attempts: entry.attempts } : {}), ...(routeDecision ? { routeDecision } : {}), }; } @@ -318,6 +334,7 @@ export function addRequestLog(entry: RequestLogEntry) { timestamp: entry.timestamp, provider: entry.provider, model: entry.model, + ...(entry.ingressSpan ? { ingressSpan: entry.ingressSpan } : {}), ...(isKnownUsageSurface(entry.surface) ? { surface: entry.surface } : {}), // This function REBUILDS the persisted row field by field rather than // spreading it, so a field missing here reaches /api/logs and never @@ -346,7 +363,7 @@ export function addRequestLog(entry: RequestLogEntry) { usageStatus: entry.usageStatus, ...(entry.usage ? { usage: entry.usage } : {}), ...(entry.totalTokens !== undefined ? { totalTokens: entry.totalTokens } : {}), - ...(entry.attempts?.length ? { attempts: entry.attempts } : {}), + ...(entry.attempts !== undefined ? { attempts: entry.attempts } : {}), ...failureDiagnostics, ...(entry.routeDecision ? { routeDecision: entry.routeDecision } : {}), }); @@ -805,6 +822,7 @@ export function addFinalRequestLog( timestamp: start, model: isCombo ? logCtx.requestedModel! : logCtx.model, provider: isCombo ? "combo" : logCtx.provider, + ...(logCtx.ingressSpan ? { ingressSpan: logCtx.ingressSpan } : {}), ...(logCtx.surface ? { surface: logCtx.surface } : {}), ...(logCtx.apiKeyId ? { apiKeyId: logCtx.apiKeyId } : {}), ...(logCtx.admissionKind ? { admissionKind: logCtx.admissionKind } : {}), @@ -832,7 +850,7 @@ export function addFinalRequestLog( usageStatus, ...(loggedUsage ? { usage: loggedUsage } : {}), ...(totalTokens !== undefined ? { totalTokens } : {}), - ...(attempts?.length ? { attempts } : {}), + ...(attempts !== undefined ? { attempts } : {}), ...(logCtx.affinity ? { affinity: logCtx.affinity } : {}), ...(logCtx.transportPhase ? { transportPhase: logCtx.transportPhase } : {}), ...(logCtx.terminalSource ? { terminalSource: logCtx.terminalSource } : {}), diff --git a/src/server/responses/core.ts b/src/server/responses/core.ts index dc9e902c5..7c811c4a8 100644 --- a/src/server/responses/core.ts +++ b/src/server/responses/core.ts @@ -1629,6 +1629,19 @@ async function handleResponsesInner( const adapterProvider = resolveWireProtocolOverride(route.providerName, route.modelId, route.provider, inboundWire); const adapter = resolveAdapter(adapterProvider, config.cacheRetention); logCtx.providerAdapter = adapter.name; + // Ordinary requests receive one durable attempt only after their final initial + // adapter is resolved. Combo children own their attempt and retries keep it. + if (!options.comboAttempt && !logCtx.activeAttempt) { + const attempt = beginRequestAttempt( + (logCtx.attempts?.length ?? 0) + 1, + logCtx.provider, + route.modelId, + adapter.name, + ); + logCtx.activeAttempt = attempt; + logCtx.activeAttemptStartedAt = Date.now(); + (logCtx.attempts ??= []).push(attempt); + } sealRequestAttemptIdentity(logCtx.activeAttempt, logCtx.provider, adapter.name); const isPassthrough = "passthrough" in adapter && !!adapter.passthrough; diff --git a/src/usage/log.ts b/src/usage/log.ts index b86aa05d3..efc36d91a 100644 --- a/src/usage/log.ts +++ b/src/usage/log.ts @@ -49,6 +49,8 @@ export interface PersistedUsageEntry { timestamp: number; provider: string; model: string; + /** Validated, content-free app-server ingress correlation token. */ + ingressSpan?: string; surface?: "claude" | "claude-desktop" | "grok"; /** Matched configured key id; absent for environment/loopback admissions and * for every row written before attribution existed. */ @@ -95,6 +97,14 @@ export interface PersistedUsageEntry { routeDecision?: RouteDecisionTraceV1; } +const INGRESS_SPAN_RE = /^[A-Za-z0-9_-]{24}_[0-9a-f]{16}$/; + +function normalizeIngressSpan(value: unknown): string | undefined { + if (typeof value !== "string") return undefined; + const span = value.trim(); + return INGRESS_SPAN_RE.test(span) ? span : undefined; +} + const KNOWN_USAGE_SURFACES = new Set>([ "claude", "claude-desktop", @@ -330,6 +340,9 @@ function normalizeUsageEntry(entry: PersistedUsageEntry): PersistedUsageEntry { timestamp: entry.timestamp, provider: entry.provider, model: entry.model, + ...(normalizeIngressSpan(entry.ingressSpan) + ? { ingressSpan: normalizeIngressSpan(entry.ingressSpan) } + : {}), ...(isKnownUsageSurface(entry.surface) ? { surface: entry.surface } : {}), ...(typeof entry.apiKeyId === "string" && entry.apiKeyId.trim() // Deliberately NOT capped. `capMetadataString` protects free-form metadata @@ -385,7 +398,7 @@ function normalizeUsageEntry(entry: PersistedUsageEntry): PersistedUsageEntry { usageStatus: entry.usageStatus, ...(entry.usage ? { usage: normalizeUsageValue(entry.usage) } : {}), ...(typeof entry.totalTokens === "number" ? { totalTokens: entry.totalTokens } : {}), - ...(attempts.length > 0 ? { attempts } : {}), + ...(Array.isArray(entry.attempts) ? { attempts } : {}), ...(entry.errorCode ? { errorCode: entry.errorCode } : {}), ...(entry.terminalStatus ? { terminalStatus: entry.terminalStatus } : {}), ...(entry.closeReason ? { closeReason: entry.closeReason } : {}), diff --git a/tests/request-log.test.ts b/tests/request-log.test.ts index 50042794d..8e70eb8be 100644 --- a/tests/request-log.test.ts +++ b/tests/request-log.test.ts @@ -16,6 +16,7 @@ import { finishRequestAttempt, getRequestLogEntries, hydrateRequestLogsFromDisk, + ingressSpanFromHeader, noteAttemptSend, recordAdapterReasoning, recordFirstOutput, @@ -53,6 +54,46 @@ function log(overrides: Partial): RequestLogEntry { } describe("request log metadata", () => { + test("round-trips a valid ingress span and omits malformed input", () => { + const valid = "AbCdEfGhIjKlMnOpQrStUvWx_0000000000000001"; + expect(ingressSpanFromHeader(valid)).toBe(valid); + for (const rejected of [ + "too-short", + "gho_ABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789", + "github_pat_ABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789", + "Bearer eyJhbGciOiJIUzI1NiJ9.payload.signature", + "sk-proj-ABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789", + ]) expect(ingressSpanFromHeader(rejected)).toBeUndefined(); + + const projected = requestLogEntryFromPersistedUsage({ + requestId: "ocx-ingress", + timestamp: 1, + provider: "openai", + model: "gpt-test", + ingressSpan: valid, + status: 200, + durationMs: 1, + usageStatus: "unreported", + attempts: [], + }); + expect(projected.ingressSpan).toBe(valid); + expect(projected.attempts).toEqual([]); + }); + + test("does not project malformed persisted ingress spans", () => { + const projected = requestLogEntryFromPersistedUsage({ + requestId: "ocx-bad-ingress", + timestamp: 1, + provider: "openai", + model: "gpt-test", + ingressSpan: "bad value", + status: 200, + durationMs: 1, + usageStatus: "unreported", + }); + expect(projected).not.toHaveProperty("ingressSpan"); + }); + test("records the adapter's exact outbound reasoning parameter", () => { const attempt = beginRequestAttempt(1, "xai", "grok-4.5", "openai-chat"); const logCtx: RequestLogContext = { diff --git a/tests/server-auth.test.ts b/tests/server-auth.test.ts index 849a5a204..a2fd442bd 100644 --- a/tests/server-auth.test.ts +++ b/tests/server-auth.test.ts @@ -2841,9 +2841,11 @@ describe("server local API auth", () => { mkdirSync(TEST_DIR, { recursive: true }); process.env.OPENCODEX_HOME = TEST_DIR; + let upstreamSends = 0; const upstream = Bun.serve({ port: 0, fetch() { + upstreamSends += 1; return new Response( [ "event: response.completed", @@ -2873,7 +2875,10 @@ describe("server local API auth", () => { try { const response = await fetch(new URL("/v1/responses", server.url), { method: "POST", - headers: { "content-type": "application/json" }, + headers: { + "content-type": "application/json", + "x-opencodex-ingress-span": "AbCdEfGhIjKlMnOpQrStUvWx_0000000000000001", + }, body: JSON.stringify({ model: "test-openai/gpt-5.5", input: "hello", stream: true }), }); @@ -2882,6 +2887,12 @@ describe("server local API auth", () => { const logs = logsFromApiBody(await fetch(new URL("/api/logs?tail=1", server.url), { headers: managementHeaders() }).then(r => r.json())); expect(logs.at(-1)).toMatchObject({ status: 200, + ingressSpan: "AbCdEfGhIjKlMnOpQrStUvWx_0000000000000001", + attempts: [{ + ordinal: 1, + sendCount: 1, + recoveryKinds: [], + }], terminalStatus: "completed", closeReason: "terminal", usageStatus: "reported", @@ -2893,6 +2904,7 @@ describe("server local API auth", () => { reasoningOutputTokens: 2, }, }); + expect(upstreamSends).toBe(1); const usage = await fetch(new URL("/api/usage?range=all&surface=codex", server.url), { headers: managementHeaders() }).then(r => r.json()) as { surface: string; diff --git a/tests/usage-log.test.ts b/tests/usage-log.test.ts index 370df85e0..30ed39b29 100644 --- a/tests/usage-log.test.ts +++ b/tests/usage-log.test.ts @@ -38,6 +38,43 @@ afterEach(() => { }); describe("usage log", () => { + test("preserves explicitly empty attempts through normalization", () => { + const normalized = normalizeUsageEntryForTest({ + requestId: "ocx-empty-attempts", + timestamp: 1, + provider: "openai", + model: "gpt-test", + status: 200, + durationMs: 1, + usageStatus: "unreported", + attempts: [], + }); + expect(normalized.attempts).toEqual([]); + }); + + test("normalizes bounded ingress spans and omits malformed or secret-like values", () => { + const valid = "AbCdEfGhIjKlMnOpQrStUvWx_0000000000000001"; + const base = { + requestId: "ocx-ingress-normalization", + timestamp: 1, + provider: "openai", + model: "gpt-test", + status: 200, + durationMs: 1, + usageStatus: "unreported" as const, + }; + expect(normalizeUsageEntryForTest({ ...base, ingressSpan: ` ${valid} ` }).ingressSpan).toBe(valid); + for (const ingressSpan of [ + "too-short", + "gho_ABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789", + "github_pat_ABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789", + "Bearer eyJhbGciOiJIUzI1NiJ9.payload.signature", + "sk-proj-ABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789", + ]) { + expect(normalizeUsageEntryForTest({ ...base, ingressSpan })).not.toHaveProperty("ingressSpan"); + } + }); + test("persists the rate-limit-429 recovery kind on attempts", () => { const entry: PersistedUsageEntry = { requestId: "ocx-ratelimit-kind",