Skip to content
Closed
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
3 changes: 3 additions & 0 deletions src/server/index.ts
Original file line number Diff line number Diff line change
Expand Up @@ -90,6 +90,7 @@ import {
hydrateRequestLogsFromDisk,
httpStatusForRequestLogTerminal,
httpStatusForTerminalStatus,
ingressSpanFromHeader,
inspectResponseLogSsePayload,
nextRequestLogId,
recordFirstOutput,
Expand Down Expand Up @@ -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 = (
Expand Down
24 changes: 21 additions & 3 deletions src/server/request-log.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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. */
Expand Down Expand Up @@ -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";
Expand Down Expand Up @@ -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 } : {}),
Expand All @@ -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 } : {}),
};
}
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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 } : {}),
});
Expand Down Expand Up @@ -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 } : {}),
Expand Down Expand Up @@ -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 } : {}),
Expand Down
13 changes: 13 additions & 0 deletions src/server/responses/core.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Comment on lines +1641 to +1643

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

P2 Badge Capture effort after constructing the ordinary attempt

For ordinary Cursor requests, applyRouteDependentNormalization calls recordAttemptRequestedEffort before this block assigns logCtx.activeAttempt. Cursor uses runTurn, so it never reaches a later recordAdapterReasoning call that would backfill the field, even though its request builder uses the selected effort to choose the wire model. Record the settled effort immediately after assigning the new attempt so persisted Cursor attempt telemetry includes requestedEffort.

Useful? React with 👍 / 👎.

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

P2 Badge Distinguish ordinary attempts from combo attempts

Once every ordinary request receives this non-empty attempts array, existing management consumers classify it as a combo solely from entry.attempts?.length; for example, src/server/management/shared.ts:112-115 now reports combo_attempt_unavailable for an unpriced ordinary custom-provider request. Update those consumers to detect an actual combo (such as by the top-level provider/metadata) before using combo-only diagnostics.

Useful? React with 👍 / 👎.

Comment on lines +1641 to +1643

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

P2 Badge Create attempts only when an upstream dispatch starts

When a request resolves the Kiro adapter but carries an unexpanded previous_response_id, the validation immediately below returns 400 without sending upstream; because this block has already pushed an attempt, the deferred finalizer persists a status-400 attempt with sendCount: 0. Later local-only rejections such as the image-bridge stream=true check have the same problem, so request history reports physical attempts that never occurred. Delay attempt creation until the selected dispatch path starts, or omit attempts whose send count remains zero.

Useful? React with 👍 / 👎.

}
sealRequestAttemptIdentity(logCtx.activeAttempt, logCtx.provider, adapter.name);
const isPassthrough = "passthrough" in adapter && !!adapter.passthrough;

Expand Down
15 changes: 14 additions & 1 deletion src/usage/log.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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. */
Expand Down Expand Up @@ -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<NonNullable<PersistedUsageEntry["surface"]>>([
"claude",
"claude-desktop",
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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 } : {}),
Expand Down
41 changes: 41 additions & 0 deletions tests/request-log.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -16,6 +16,7 @@ import {
finishRequestAttempt,
getRequestLogEntries,
hydrateRequestLogsFromDisk,
ingressSpanFromHeader,
noteAttemptSend,
recordAdapterReasoning,
recordFirstOutput,
Expand Down Expand Up @@ -53,6 +54,46 @@ function log(overrides: Partial<RequestLogEntry>): 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 = {
Expand Down
14 changes: 13 additions & 1 deletion tests/server-auth.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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",
Expand Down Expand Up @@ -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 }),
});

Expand All @@ -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",
Expand All @@ -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;
Expand Down
37 changes: 37 additions & 0 deletions tests/usage-log.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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",
Expand Down
Loading