diff --git a/docs-site/src/content/docs/reference/cli/agents.md b/docs-site/src/content/docs/reference/cli/agents.md index 9ec77d26cf..d2cfa0fa07 100644 --- a/docs-site/src/content/docs/reference/cli/agents.md +++ b/docs-site/src/content/docs/reference/cli/agents.md @@ -178,6 +178,10 @@ ocx debug usage on|off|status|reset ocx debug usage logs [-f|--follow] ``` +Provider debug also records structural adapter/bridge stream events: sequence, attempt and recovery labels, byte counts, and process-local HMAC fingerprints. Text, reasoning, tool arguments, queries, and provider state are not included in these stream diagnostic records. Fingerprints change after a proxy restart; disable provider debug after collecting a reproduction. +Raw credentials, account IDs, and request bodies are never recorded in stream diagnostics. + + With no scope, `ocx debug` prints usage and, when the proxy is stopped, the next-start environment defaults. Provider debug defaults from `OCX_DEBUG=1` (legacy `OCX_DEBUG_FRAMES=1` also works); usage debug defaults from `OPENCODEX_USAGE_DEBUG=1`. diff --git a/src/bridge.ts b/src/bridge.ts index beb49a3f99..0608956de8 100644 --- a/src/bridge.ts +++ b/src/bridge.ts @@ -5,3 +5,5 @@ export { setOwnedBudgetAbandonedMsForTests } from "./bridge/internal"; export { buildResponseJSON } from "./bridge/response-json"; export { bridgeToResponsesSSE } from "./bridge/sse"; export type { ResponsesTerminalStatus } from "./bridge/sse"; +export { adapterEventDiagnosticDetails, diagnoseAdapterEvent } from "./bridge/diagnostic"; +export type { BridgeDiagnosticContext, BridgeDiagnosticSequence } from "./bridge/diagnostic"; diff --git a/src/bridge/diagnostic.ts b/src/bridge/diagnostic.ts new file mode 100644 index 0000000000..fb60812b2f --- /dev/null +++ b/src/bridge/diagnostic.ts @@ -0,0 +1,85 @@ +import type { AdapterEvent } from "../types"; +import { debugFingerprint, debugStreamDiagnostic, type DebugStreamDiagnosticContext } from "../lib/debug"; + +export interface BridgeDiagnosticSequence { value: number } + +export interface BridgeDiagnosticContext extends DebugStreamDiagnosticContext { + sequence?: BridgeDiagnosticSequence; +} + +export function adapterEventDiagnosticDetails(event: AdapterEvent): Record { + switch (event.type) { + case "text_delta": + return { byteLength: Buffer.byteLength(event.text), fingerprint: debugFingerprint(event.text) }; + case "thinking_delta": + return { byteLength: Buffer.byteLength(event.thinking), fingerprint: debugFingerprint(event.thinking) }; + case "reasoning_raw_delta": + return { byteLength: Buffer.byteLength(event.text), fingerprint: debugFingerprint(event.text) }; + case "thinking_signature": + case "redacted_thinking": + case "kiro_redacted_reasoning": { + const content = event.type === "thinking_signature" ? event.signature : event.data; + return { byteLength: Buffer.byteLength(content), fingerprint: debugFingerprint(content) }; + } + case "tool_call_delta": + return { byteLength: Buffer.byteLength(event.arguments), fingerprint: debugFingerprint(event.arguments) }; + case "tool_call_start": + return { + idByteLength: Buffer.byteLength(event.id), + idFingerprint: debugFingerprint(event.id), + nameByteLength: Buffer.byteLength(event.name), + nameFingerprint: debugFingerprint(event.name), + }; + case "web_search_call_begin": + return { idByteLength: Buffer.byteLength(event.id), idFingerprint: debugFingerprint(event.id) }; + case "web_search_call_end": { + const queries = JSON.stringify(event.queries); + return { + idByteLength: Buffer.byteLength(event.id), + idFingerprint: debugFingerprint(event.id), + byteLength: Buffer.byteLength(queries), + fingerprint: debugFingerprint(queries), + status: event.status, + }; + } + case "error": + return { + byteLength: Buffer.byteLength(event.message), + fingerprint: debugFingerprint(event.message), + ...(event.status !== undefined ? { status: event.status } : {}), + ...(event.code !== undefined + ? { codeByteLength: Buffer.byteLength(event.code), codeFingerprint: debugFingerprint(event.code) } + : {}), + ...(event.retryable !== undefined ? { retryable: event.retryable } : {}), + }; + case "incomplete": + return { + ...(event.message !== undefined ? { byteLength: Buffer.byteLength(event.message), fingerprint: debugFingerprint(event.message) } : {}), + reasonByteLength: Buffer.byteLength(event.reason), + reasonFingerprint: debugFingerprint(event.reason), + ...(event.retryable !== undefined ? { retryable: event.retryable } : {}), + }; + case "done": + return { + ...(event.stopReason !== undefined + ? { stopReasonByteLength: Buffer.byteLength(event.stopReason), stopReasonFingerprint: debugFingerprint(event.stopReason) } + : {}), + ...(event.endTurn !== undefined ? { endTurn: event.endTurn } : {}), + }; + default: + return {}; + } +} + +/** Emit one adapter-stage diagnostic while preserving one sequence across sidecar iterations. */ +export function diagnoseAdapterEvent(context: BridgeDiagnosticContext, event: AdapterEvent): void { + const sequence = context.sequence ??= { value: 0 }; + debugStreamDiagnostic( + context, + "adapter", + ++sequence.value, + event.type, + adapterEventDiagnosticDetails(event), + ); +} + diff --git a/src/bridge/sse.ts b/src/bridge/sse.ts index 66d15f58fc..72e90ec92f 100644 --- a/src/bridge/sse.ts +++ b/src/bridge/sse.ts @@ -49,6 +49,8 @@ import { } from "../lib/translator-budget"; import { adapterFailureFromEvent, emptyChunks, joinChunks, ownedBudgetAbandonedMs, responsesUsage, toolCallArgumentsUsable, uuid, webSearchAction } from "./internal"; import type { OutputItem, StringChunks } from "./internal"; +import { adapterEventDiagnosticDetails, type BridgeDiagnosticContext } from "./diagnostic"; +import { debugStreamDiagnostic } from "../lib/debug"; function sseEvent(name: string, data: Record): string { return `event: ${name}\ndata: ${JSON.stringify(data)}\n\n`; @@ -127,13 +129,15 @@ export function bridgeToResponsesSSE( */ replayCacheScope?: OcxReasoningReplayScopeRef; /** - * Test seam for the wire/stall beat loop. Production omits this and uses the - * global timers; injecting here must not change scheduling semantics. - */ + * Test seam for the wire/stall beat loop. Production omits this and uses the + * global timers; injecting here must not change scheduling semantics. + */ timers?: { setInterval: (handler: () => void, ms: number) => unknown; clearInterval: (id: unknown) => void; }; + /** Internal, opt-in structural stream diagnostics. */ + diagnostic?: BridgeDiagnosticContext; }, ): ReadableStream { const replayCacheScope = options?.replayCacheScope; @@ -386,6 +390,7 @@ export function bridgeToResponsesSSE( }; const responseId = options?.responseId ?? `resp_${uuid()}`; let seq = 0; + let diagnosticSequence = 0; // Set once the client is gone (cancel) or an enqueue throws on a torn-down controller, so we // never enqueue again and never throw a second time inside start() — the RC2 double-throw that // otherwise surfaced as proxy-side stream noise on every client disconnect. @@ -941,6 +946,17 @@ export function bridgeToResponsesSSE( } if (next.done) { upstreamDone = true; break; } const event = next.value; + if (options?.diagnostic) { + debugStreamDiagnostic( + options.diagnostic, + "bridge", + options.diagnostic.sequence + ? ++options.diagnostic.sequence.value + : ++diagnosticSequence, + event.type, + adapterEventDiagnosticDetails(event), + ); + } let terminalEvent = false; // Invisible adapter heartbeats (and buffered web-search progress) count as upstream // liveness only — they must not suppress wire keepalives that re-arm Codex idle timers. diff --git a/src/images/loop.ts b/src/images/loop.ts index 193bbef45f..0a154a3264 100644 --- a/src/images/loop.ts +++ b/src/images/loop.ts @@ -18,7 +18,7 @@ import type { AdapterEvent, OcxMessage, OcxParsedRequest, OcxProviderContinuatio import { namespacedToolName, toolChoiceToolPredicate } from "../types"; import { cloneProviderOpaqueToolCallMetadata } from "../responses/provider-opaque-metadata"; import type { AttemptRecoveryKind } from "../usage/log"; -import { bridgeToResponsesSSE } from "../bridge"; +import { bridgeToResponsesSSE, diagnoseAdapterEvent, type BridgeDiagnosticContext } from "../bridge"; import { clearableDeadline, idleDeadline } from "../lib/abort"; import { readBoundedResponseBody } from "../lib/bounded-body"; import { applyUpstreamRecoveryInit, fetchWithResetRetry, prepareSameTarget429Wait } from "../lib/upstream-retry"; @@ -332,6 +332,8 @@ export interface ImageBridgeDeps { onCompletedResponse?: (response: Record, providerState?: OcxProviderContinuationState) => void; /** WebSocket Responses path only — leave response id empty for protocol compatibility. */ forceEmptyResponseId?: boolean; + /** Internal, opt-in structural stream diagnostics shared with the final bridge. */ + diagnostic?: BridgeDiagnosticContext; } /** @@ -717,6 +719,12 @@ export async function runWithImageBridge(deps: ImageBridgeDeps): Promise { const events: AdapterEvent[] = prepared.collectedEvents ?? []; const iterationBudget = prepared.collectedEvents ? undefined : createIterationEventBudget(); + if (!iterationBudget && deps.diagnostic) { + // Collected runTurn events skip the streaming parse loop below, so diagnose + // them here before terminal scanning and replay. + deps.diagnostic.adapterName = prepared.responseAdapter.name; + for (const event of events) diagnoseAdapterEvent(deps.diagnostic, event); + } try { if (iterationBudget) { const parse = prepared.responseAdapter.parseStream.bind(prepared.responseAdapter); @@ -725,6 +733,10 @@ export async function runWithImageBridge(deps: ImageBridgeDeps): Promise deps.onUsage?.(usage), } : {}), ...(deps.onCompletedResponse ? { onCompletedResponse: deps.onCompletedResponse } : {}), + ...(deps.diagnostic ? { diagnostic: deps.diagnostic } : {}), }, ); return new Response(sse, { headers: SSE_HEADERS }); diff --git a/src/lib/debug.ts b/src/lib/debug.ts index 5d4b54b050..2f42134d2b 100644 --- a/src/lib/debug.ts +++ b/src/lib/debug.ts @@ -1,7 +1,10 @@ +import { createHmac, randomBytes } from "node:crypto"; import { appendDebugLogLine } from "./debug-log-buffer"; import { isDebugEnabled } from "./debug-settings"; import { redactSecrets } from "./redact"; +let debugFingerprintKey: Uint8Array | undefined; + function emitDebugLine(line: string): void { if (!isDebugEnabled()) return; try { @@ -29,3 +32,42 @@ export function debugProviderDiagnostic(adapter: string, event: string, details: /* diagnostics must never affect request handling */ } } + +/** Process-local, content-free correlation aid for opt-in provider diagnostics. */ +export function debugFingerprint(value: string | Uint8Array): string | undefined { + if (!isDebugEnabled()) return undefined; + try { + debugFingerprintKey ??= randomBytes(32); + return createHmac("sha256", debugFingerprintKey).update(value).digest("hex"); + } catch { + return undefined; + } +} + +export interface DebugStreamDiagnosticContext { + requestId: string; + adapterName: string; + attempt?: number; + recovery?: string; +} + +export type DebugStreamDiagnosticStage = "adapter" | "bridge"; + +/** Emit one structural line for an adapter/bridge event without retaining its content. */ +export function debugStreamDiagnostic( + context: DebugStreamDiagnosticContext, + stage: DebugStreamDiagnosticStage, + sequence: number, + eventType: string, + details?: Record, +): void { + debugProviderDiagnostic(context.adapterName, "stream", { + stage, + sequence, + eventType, + ...(context.requestId !== undefined ? { requestId: context.requestId } : {}), + ...(context.attempt !== undefined ? { attempt: context.attempt } : {}), + ...(context.recovery !== undefined ? { recovery: context.recovery } : {}), + ...details, + }); +} diff --git a/src/server/responses/adapter-continuation.ts b/src/server/responses/adapter-continuation.ts index 8ead32049e..07916e90ca 100644 --- a/src/server/responses/adapter-continuation.ts +++ b/src/server/responses/adapter-continuation.ts @@ -32,6 +32,7 @@ import { import { redactSecretString } from "../../lib/redact"; import { resolveWireProtocolOverride } from "../adapter-resolve"; import { bindRouteReasoningReplayScope } from "./core-replay"; +import { diagnoseAdapterEvents } from "./stream-diagnostics"; import { ANTHROPIC_POOL_MAX_FAILOVERS_PER_REQUEST, rotateAnthropicAccountOn429, @@ -86,6 +87,8 @@ export function createAdapterContinuations( | "applyFailoverSnapshot" | "replayOAuthCredentialSnapshot" | "noteRoutedAttemptSend" + | "streamDiagnostic" + | "noteDiagnosticAttemptSend" >, sidecarState: Pick, sendBudgetState: Pick< @@ -196,7 +199,11 @@ export function createAdapterContinuations( const replayKind: AttemptRecoveryKind | undefined = recoveryKind; try { if (transportState.activeAdapter.fetchResponse) { - transportState.noteRoutedAttemptSend(continuationEstimate, replayKind); + transportState.noteDiagnosticAttemptSend( + continuationEstimate, + replayKind, + transportState.activeAdapter.name, + ); await waitForProviderRequestSlot(route.providerName, route.provider, nextParsed.modelId, upstream.signal); return await transportState.activeAdapter.fetchResponse(builtContinuationRequest, { abortSignal: upstream.signal, @@ -221,7 +228,11 @@ export function createAdapterContinuations( : fetchWithResetRetry; return await fetchContinuationWithRetryPolicy( recovery => { - transportState.noteRoutedAttemptSend(continuationEstimate, recovery ?? replayKind); + transportState.noteDiagnosticAttemptSend( + continuationEstimate, + recovery ?? replayKind, + transportState.activeAdapter.name, + ); return fetchWithHeaderTimeout( builtContinuationRequest.url, applyUpstreamRecoveryInit({ @@ -534,7 +545,13 @@ export function createAdapterContinuations( response, upstream.signal, bodyInactivityMs, - guarded => transportState.activeAdapter.parseStream(guarded, translatorBudget, logCtx.activeTierMetadata), + guarded => + diagnoseAdapterEvents( + transportState.activeAdapter.parseStream(guarded, translatorBudget, logCtx.activeTierMetadata), + () => transportState.activeAdapter.name, + transportState.streamDiagnostic, + logCtx, + ), ); } else if (transportState.activeAdapter.parseResponse) { yield* await readResponseBodyWithInactivity( diff --git a/src/server/responses/adapter-delivery.ts b/src/server/responses/adapter-delivery.ts index e0351128bd..b077f91d7f 100644 --- a/src/server/responses/adapter-delivery.ts +++ b/src/server/responses/adapter-delivery.ts @@ -20,6 +20,7 @@ import { ResponseBodyInactivityError, } from "../../lib/response-body-inactivity"; import { resolveStallTimeoutSec } from "../../stall-timeout"; +import { diagnoseAdapterEvents } from "./stream-diagnostics"; /** One responsibility of the Responses request pipeline; state owners are explicit. */ export async function deliverAdapterResponse( @@ -32,7 +33,7 @@ export async function deliverAdapterResponse( | "rememberKiroDeliveredFinalAnswer" | "responseStateOptions" >, - transportState: Pick, + transportState: Pick, sidecarState: Pick, responseEffects: Pick< ResponsesEffects, @@ -79,7 +80,13 @@ export async function deliverAdapterResponse( upstreamResponse, upstream.signal, bodyInactivityMs, - response => transportState.activeAdapter.parseStream(response, translatorBudget, logCtx.activeTierMetadata), + response => + diagnoseAdapterEvents( + transportState.activeAdapter.parseStream(response, translatorBudget, logCtx.activeTierMetadata), + () => transportState.activeAdapter.name, + transportState.streamDiagnostic, + logCtx, + ), ); } catch (error) { if (error instanceof ResponseBodyInactivityError) { @@ -128,6 +135,7 @@ export async function deliverAdapterResponse( toolParameterSchemas, ...(options.onFirstOutput ? { onFirstOutput: options.onFirstOutput } : {}), ...(routedCompaction ? { compaction: true } : {}), + ...(transportState.streamDiagnostic ? { diagnostic: transportState.streamDiagnostic.context } : {}), // Same grok-surface split as the runTurn branch above. ...(logCtx.surface === "grok" ? { heartbeatStyle: "comment" as const } : {}), onUsage: usage => { diff --git a/src/server/responses/request-transport.ts b/src/server/responses/request-transport.ts index 604380b4fb..9ec94a7d64 100644 --- a/src/server/responses/request-transport.ts +++ b/src/server/responses/request-transport.ts @@ -65,6 +65,7 @@ import { } from "../request-log"; import type { AttemptRecoveryKind } from "../../usage/log"; import { resolvePassiveRouteSubjectId } from "../passive-route-linker"; +import { createStreamDiagnostic, type StreamDiagnostic } from "./stream-diagnostics"; /** Owns live credential selection and adapter bindings for one request. */ export async function prepareResponsesTransport( @@ -253,6 +254,21 @@ export async function prepareResponsesTransport( if (usesApiKeyAccount(route.provider)) pendingKeySend = { estimate, recovery }; else noteProviderAttemptSend(logCtx, route.providerName, route.provider, estimate, recovery); }; + // Opt-in structural stream diagnostics shared by the adapter, continuation, + // sidecar, and bridge stages of this request. Created once so every stage + // appends to a single sequence; undefined unless provider debug is on. + const streamDiagnostic: StreamDiagnostic | undefined = createStreamDiagnostic(route.providerName); + const noteDiagnosticAttemptSend = ( + estimate: number | undefined, + recovery?: AttemptRecoveryKind, + adapterName?: string, + ): void => { + noteRoutedAttemptSend(estimate, recovery); + if (!streamDiagnostic) return; + streamDiagnostic.context.attempt = logCtx.activeAttempt?.ordinal; + streamDiagnostic.context.recovery = recovery; + if (adapterName) streamDiagnostic.context.adapterName = adapterName; + }; const commitKeyAttemptSend = (): void => { if (!usesApiKeyAccount(route.provider)) return; noteProviderAttemptSend(logCtx, route.providerName, route.provider, @@ -796,6 +812,8 @@ export async function prepareResponsesTransport( refreshRunTurnAdapter, oauthDispatch, noteRoutedAttemptSend, + noteDiagnosticAttemptSend, + streamDiagnostic, commitKeyAttemptSend, bindKeyUsageFromBridge, anthropicSessionKey, diff --git a/src/server/responses/run-turn-execution.ts b/src/server/responses/run-turn-execution.ts index 0eda091879..a9812a089c 100644 --- a/src/server/responses/run-turn-execution.ts +++ b/src/server/responses/run-turn-execution.ts @@ -38,6 +38,7 @@ import { import { rememberResponseState } from "../../responses/state"; import { trackStreamLifetime } from "../lifecycle"; import { awaitThoughtSignatureDurability } from "../../responses/thought-signature-replay"; +import { diagnoseAdapterEvents } from "./stream-diagnostics"; /** One responsibility of the Responses request pipeline; state owners are explicit. */ export async function executeResponsesRunTurn( @@ -67,6 +68,8 @@ export async function executeResponsesRunTurn( | "resolveSelectionAdapter" | "adapter" | "noteRoutedAttemptSend" + | "noteDiagnosticAttemptSend" + | "streamDiagnostic" | "bindKeyUsageFromBridge" >, sidecarState: Pick, @@ -146,7 +149,11 @@ export async function executeResponsesRunTurn( await waitForProviderRequestSlot(route.providerName, route.provider, route.modelId, runTurnAbort.signal); } await refreshRunTurnSelection(); - transportState.noteRoutedAttemptSend(logCtx.usageLogInputTokens, recovery); + transportState.noteDiagnosticAttemptSend( + logCtx.usageLogInputTokens, + recovery, + transportState.runTurnAdapter.name, + ); const runTurnProviderFetch = providerFetch( route.provider, options.codexWsRuntimeIdentity, @@ -376,7 +383,13 @@ export async function executeResponsesRunTurn( console.warn(emptyCompletionNotice(route.providerName, route.modelId)); }); const sseStream = bridgeToResponsesSSE( - guardedSource, parsed._responseModelId ?? parsed.modelId, toolNsMap, freeformToolNames, toolSearchToolNames, + diagnoseAdapterEvents( + guardedSource, + () => transportState.runTurnAdapter.name, + transportState.streamDiagnostic, + logCtx, + ), + parsed._responseModelId ?? parsed.modelId, toolNsMap, freeformToolNames, toolSearchToolNames, () => { cancelResponseCompletion(); runTurnAbort.abort(); @@ -393,6 +406,7 @@ export async function executeResponsesRunTurn( toolParameterSchemas, ...(options.onFirstOutput ? { onFirstOutput: options.onFirstOutput } : {}), ...(routedCompaction ? { compaction: true } : {}), + ...(transportState.streamDiagnostic ? { diagnostic: transportState.streamDiagnostic.context } : {}), // grok-build's strict decoder dies on the typed response.heartbeat frame; its // eventsource layer tolerates comment keep-alives. Codex needs the opposite. ...(logCtx.surface === "grok" ? { heartbeatStyle: "comment" as const } : {}), diff --git a/src/server/responses/sidecar-execution.ts b/src/server/responses/sidecar-execution.ts index de1156b222..3acf76799e 100644 --- a/src/server/responses/sidecar-execution.ts +++ b/src/server/responses/sidecar-execution.ts @@ -66,6 +66,8 @@ export async function executeResponsesSidecars( | "resolveSelectionAdapter" | "oauthDispatch" | "noteRoutedAttemptSend" + | "noteDiagnosticAttemptSend" + | "streamDiagnostic" | "bindKeyUsageFromBridge" >, sidecarState: Pick, @@ -326,7 +328,12 @@ export async function executeResponsesSidecars( ...(vidPlan ? { videoPlan: vidPlan } : {}), forwardHeaders: requestState.selectedForwardHeaders, onAttemptSend: (recovery?: AttemptRecoveryKind) => - transportState.noteRoutedAttemptSend(logCtx.usageLogInputTokens, recovery), + transportState.noteDiagnosticAttemptSend( + logCtx.usageLogInputTokens, + recovery, + transportState.adapter.name, + ), + ...(transportState.streamDiagnostic ? { diagnostic: transportState.streamDiagnostic.context } : {}), abortSignal: options.abortSignal, maxRounds: imgPlan && vidPlan ? clampImageMaxRounds(Math.min(config.images?.maxRounds ?? 3, config.images?.videoMaxRounds ?? 2)) diff --git a/src/server/responses/stream-diagnostics.ts b/src/server/responses/stream-diagnostics.ts new file mode 100644 index 0000000000..94cb6a9221 --- /dev/null +++ b/src/server/responses/stream-diagnostics.ts @@ -0,0 +1,61 @@ +import { randomUUID } from "node:crypto"; +import type { AdapterEvent } from "../../types"; +import type { RequestLogContext } from "../request-log"; +import { debugStreamDiagnostic } from "../../lib/debug"; +import { isDebugEnabled } from "../../lib/debug-settings"; +import { + adapterEventDiagnosticDetails, + type BridgeDiagnosticContext, + type BridgeDiagnosticSequence, +} from "../../bridge"; +/** + * Opt-in structural stream diagnostics shared across one request adapter, + * continuation, sidecar, and bridge stages. Created once per request so every + * stage appends to a single sequence; absent unless provider debug is on. + */ +export type StreamDiagnostic = { + context: BridgeDiagnosticContext; + state: BridgeDiagnosticSequence; +}; + +export function createStreamDiagnostic(initialAdapterName: string): StreamDiagnostic | undefined { + if (!isDebugEnabled()) return undefined; + const state: BridgeDiagnosticSequence = { value: 0 }; + return { + context: { requestId: randomUUID(), adapterName: initialAdapterName, sequence: state }, + state, + }; +} +/** + * Wrap an adapter event stream with per-event structural diagnostics. + * The adapter name resolves lazily at each event so failover rotations that + * swap the serving adapter mid-stream are attributed to the adapter that + * actually produced the event, never to a stale capture. + */ +export function diagnoseAdapterEvents( + events: AsyncIterable, + getAdapterName: () => string, + diagnostic: StreamDiagnostic | undefined, + logCtx: RequestLogContext, +): AsyncIterable { + if (!diagnostic) return events; + const { context, state } = diagnostic; + return (async function* () { + for await (const event of events) { + const attempt = logCtx.activeAttempt; + debugStreamDiagnostic( + { + requestId: context.requestId, + adapterName: getAdapterName(), + ...(attempt?.ordinal !== undefined ? { attempt: attempt.ordinal } : {}), + ...(attempt?.recoveryKinds.at(-1) !== undefined ? { recovery: attempt.recoveryKinds.at(-1) } : {}), + }, + "adapter", + ++state.value, + event.type, + adapterEventDiagnosticDetails(event), + ); + yield event; + } + })(); +} diff --git a/src/web-search/loop.ts b/src/web-search/loop.ts index 48a5cdc8cd..4f0a60df0b 100644 --- a/src/web-search/loop.ts +++ b/src/web-search/loop.ts @@ -4,7 +4,7 @@ import { namespacedToolName, toolChoiceToolPredicate } from "../types"; import { cloneProviderOpaqueToolCallMetadata } from "../responses/provider-opaque-metadata"; import type { AttemptRecoveryKind } from "../usage/log"; import { isTruncatedStopReason } from "../responses/truncated-stop-reason"; -import { bridgeToResponsesSSE } from "../bridge"; +import { bridgeToResponsesSSE, diagnoseAdapterEvent, type BridgeDiagnosticContext } from "../bridge"; import { runWebSearch, type SidecarOutcome, type SidecarOutcomeRecorder, type SidecarSettings } from "./executor"; import { runAnthropicWebSearch } from "./anthropic-executor"; import { runXaiWebSearch, type XaiSearchOptions } from "./xai-executor"; @@ -342,6 +342,8 @@ export interface WebSearchLoopDeps { retryOn429Policy?: Required | null; /** Called only when the final bridged Responses stream reaches completed or incomplete. */ onCompletedResponse?: (response: Record) => void; + /** Internal, opt-in structural stream diagnostics shared with the final bridge. */ + diagnostic?: BridgeDiagnosticContext; } /** @@ -641,6 +643,10 @@ export async function runWithWebSearch(deps: WebSearchLoopDeps): Promise { @@ -33,7 +35,94 @@ async function collectSse(stream: ReadableStream): Promise<{ event?: }); } +const initialDebugEnv = process.env.OCX_DEBUG; + describe("Responses bridge reasoning and usage parity", () => { + afterEach(() => { + resetDebugSettingsForTests(); + resetDebugLogBufferForTests(); + if (initialDebugEnv === undefined) delete process.env.OCX_DEBUG; + else process.env.OCX_DEBUG = initialDebugEnv; + }); + + test("bridge diagnostics classify each adapter event once without changing the wire", async () => { + process.env.OCX_DEBUG = "1"; + const error = spyOn(console, "error").mockImplementation(() => {}); + try { + const events: AdapterEvent[] = [ + { type: "assistant_boundary" }, + { type: "text_delta", text: "fixture reasoning and secret" }, + { type: "tool_call_start", id: "call-1", name: "secret_tool" }, + { type: "tool_call_delta", arguments: '{"secret":"argument"}' }, + { type: "tool_call_end" }, + { type: "done" }, + ]; + const frames = await collectSse(bridgeToResponsesSSE(replay(events), "routed/model", undefined, undefined, undefined, undefined, undefined, { + diagnostic: { requestId: "req-1", adapterName: "openai-chat", attempt: 2, recovery: "empty-completion" }, + })); + const lines = getDebugLogEntries().map(entry => entry.line).filter(line => line.includes("\"stage\":\"bridge\"")); + expect(lines).toHaveLength(events.length); + expect(lines.filter(line => line.includes('"eventType":"assistant_boundary"'))).toHaveLength(1); + expect(lines.filter(line => line.includes('"eventType":"tool_call_start"'))).toHaveLength(1); + expect(lines.filter(line => line.includes('"eventType":"tool_call_delta"'))).toHaveLength(1); + expect(lines.every(line => !line.includes("fixture reasoning and secret") && !line.includes("secret_tool") && !line.includes("secret"))).toBe(true); + expect(frames.filter(frame => frame.event === "response.completed")).toHaveLength(1); + expect(frames.find(frame => frame.event === "response.output_text.delta")?.data).toMatchObject({ delta: "fixture reasoning and secret" }); + } finally { + error.mockRestore(); + } + }); + + test("incomplete diagnostics fingerprint upstream-controlled reasons instead of logging them", async () => { + process.env.OCX_DEBUG = "1"; + const error = spyOn(console, "error").mockImplementation(() => {}); + const reason = "upstream err.message fixture-secret"; + try { + await collectSse(bridgeToResponsesSSE(replay([ + { type: "incomplete", reason }, + ]), "routed/model", undefined, undefined, undefined, undefined, undefined, { + diagnostic: { requestId: "req-incomplete", adapterName: "openai-responses", attempt: 1 }, + })); + const line = getDebugLogEntries().map(entry => entry.line).find(entry => entry.includes('"stage":"bridge"')) ?? ""; + expect(line).not.toContain(reason); + expect(line).toContain(`"reasonByteLength":${Buffer.byteLength(reason)}`); + expect(line).toContain('"reasonFingerprint"'); + } finally { + error.mockRestore(); + } + }); + + test("diagnostics fingerprint arbitrary upstream error codes and stop reasons", async () => { + process.env.OCX_DEBUG = "1"; + const error = spyOn(console, "error").mockImplementation(() => {}); + const code = "Bearer upstream-code-secret@example.test"; + const stopReason = "provider-stop-secret-account-123"; + try { + await collectSse(bridgeToResponsesSSE(replay([ + { type: "error", message: "failed", code }, + ]), "routed/model", undefined, undefined, undefined, undefined, undefined, { + diagnostic: { requestId: "req-upstream-fields", adapterName: "openai-chat" }, + })); + const errorLine = getDebugLogEntries().map(entry => entry.line) + .find(line => line.includes('"stage":"bridge"') && line.includes('"eventType":"error"')) ?? ""; + await collectSse(bridgeToResponsesSSE(replay([ + { type: "done", stopReason }, + ]), "routed/model", undefined, undefined, undefined, undefined, undefined, { + diagnostic: { requestId: "req-upstream-fields", adapterName: "openai-chat" }, + })); + const doneLine = getDebugLogEntries().map(entry => entry.line) + .find(line => line.includes('"stage":"bridge"') && line.includes('"eventType":"done"')) ?? ""; + expect(errorLine).not.toContain(code); + expect(errorLine).toContain(`"codeByteLength":${Buffer.byteLength(code)}`); + expect(errorLine).toContain('"codeFingerprint"'); + expect(doneLine).not.toContain(stopReason); + expect(doneLine).toContain(`"stopReasonByteLength":${Buffer.byteLength(stopReason)}`); + expect(doneLine).toContain('"stopReasonFingerprint"'); + } finally { + error.mockRestore(); + } + }); + test("first-output callback fires once on first non-empty delta (heartbeat/empty skipped)", async () => { let firstOutputs = 0; await collectSse(bridgeToResponsesSSE(replay([ diff --git a/tests/adapters/terminal-continuation-owner-rotation.test.ts b/tests/adapters/terminal-continuation-owner-rotation.test.ts index 458f8237b6..a00a0f2355 100644 --- a/tests/adapters/terminal-continuation-owner-rotation.test.ts +++ b/tests/adapters/terminal-continuation-owner-rotation.test.ts @@ -1,4 +1,4 @@ -import { afterEach, beforeEach, describe, expect, mock, test } from "bun:test"; +import { afterEach, beforeEach, describe, expect, mock, spyOn, test } from "bun:test"; import { mkdtempSync} from "node:fs"; import { tmpdir } from "node:os"; import { join } from "node:path"; @@ -16,6 +16,8 @@ import type { OcxParsedRequest, OcxProviderConfig, } from "../../src/types"; +import { getDebugLogEntries, resetDebugLogBufferForTests } from "../../src/lib/debug-log-buffer"; +import { resetDebugSettingsForTests } from "../../src/lib/debug-settings"; import { removeTreeWithRetry } from "../helpers/remove-tree"; interface BuildObservation { @@ -24,6 +26,7 @@ interface BuildObservation { } let builds: BuildObservation[] = []; +const PREVIOUS_DEBUG = process.env.OCX_DEBUG; function eventsForPhase(phase: string): AdapterEvent[] { if (phase === "seed") { @@ -46,6 +49,16 @@ function eventsForPhase(phase: string): AdapterEvent[] { }, ]; } + if (phase === "final") { + return [ + { type: "text_delta", text: "completed after connection reset" }, + { + type: "done", + stopReason: "end_turn", + providerState: { kiro: { conversationId: "private-final" } }, + }, + ]; + } if (phase === "rotated") { return [ { type: "text_delta", text: "completed on the rotated key" }, @@ -127,9 +140,81 @@ describe("terminal continuation provider-owner rotation", () => { else process.env.OPENCODEX_HOME = previousHome; clearKeyCooldowns(); clearResponseStateForTests(); + resetDebugSettingsForTests(); + resetDebugLogBufferForTests(); + if (PREVIOUS_DEBUG === undefined) delete process.env.OCX_DEBUG; + else process.env.OCX_DEBUG = PREVIOUS_DEBUG; removeTreeWithRetry(testHome); }); + // Connection-reset replay was refused upstream by #4798 (ambiguous resets no longer + // replay without an explicit opt-in), so this coverage rides the same-target 429 replay + // instead. The diagnostic assertions are unchanged: recovery labels must appear on both + // adapter- and bridge-stage lines. + test("continuation rate-limit-429 recovery labels adapter and bridge diagnostics", async () => { + process.env.OCX_DEBUG = "1"; + const error = spyOn(console, "error").mockImplementation(() => {}); + const key = "key-continuation-000111222333"; + const config: OcxConfig = { + port: 0, + defaultProvider: "owned", + providers: { + owned: { + adapter: "test-terminal-owned", + baseUrl: "https://owned-terminal.test/v1", + authMode: "key", + apiKey: key, + terminalContinuationGuard: true, + replayTransientFailures: true, + retryOn429: { enabled: true }, + }, + }, + } as OcxConfig; + saveConfig(config); + let sends = 0; + globalThis.fetch = (async (_input, init) => { + sends += 1; + if (sends === 1) return new Response("", { headers: { "x-test-phase": "plan" } }); + if (sends === 2) { + return new Response("", { status: 429, headers: { "retry-after": "0", "x-test-phase": "plan" } }); + } + expect(new Headers(init?.headers).get("authorization")).toBe(`Bearer ${key}`); + return new Response("", { headers: { "x-test-phase": "final" } }); + }) as typeof fetch; + try { + const response = await handleResponses( + new Request("http://localhost/v1/responses", { + method: "POST", + headers: { "content-type": "application/json" }, + body: JSON.stringify({ + model: "owned/model", + input: "Please modify the file now", + stream: true, + tools: [{ type: "function", name: "read_file", description: "read", parameters: { type: "object" } }], + }), + }), + config, + { model: "", provider: "" }, + ); + expect(response.status).toBe(200); + await response.text(); + const lines = getDebugLogEntries().map(entry => entry.line); + const adapter = lines.find(line => + line.includes('"stage":"adapter"') + && line.includes('"eventType":"text_delta"') + && line.includes('"recovery":"rate-limit-429"')) ?? ""; + const bridge = lines.find(line => + line.includes('"stage":"bridge"') + && line.includes('"eventType":"text_delta"') + && line.includes('"recovery":"rate-limit-429"')) ?? ""; + expect(adapter).toContain('"recovery":"rate-limit-429"'); + expect(bridge).toContain('"recovery":"rate-limit-429"'); + expect(sends).toBe(3); + } finally { + error.mockRestore(); + } + }); + test("429 rotation fences inherited state and persists the rotated owner", async () => { const keyA = "key-alpha-000111222333"; const keyB = "key-beta-444555666777"; diff --git a/tests/images/loop.test.ts b/tests/images/loop.test.ts index 9dbddf1a68..c9905d4a76 100644 --- a/tests/images/loop.test.ts +++ b/tests/images/loop.test.ts @@ -1,4 +1,4 @@ -import { afterAll, beforeAll, beforeEach, describe, expect, mock, test } from "bun:test"; +import { afterAll, afterEach, beforeAll, beforeEach, describe, expect, mock, spyOn, test } from "bun:test"; import { tmpdir } from "node:os"; import { join } from "node:path"; import { randomUUID } from "node:crypto"; @@ -13,8 +13,11 @@ import { TRANSLATOR_MAX_CALL_ARGUMENT_BYTES, TRANSLATOR_MAX_TURN_BYTES, translat const realParseStreamWithProgress = parseStreamWithProgress; let useRealProgressStream = false; let fulfillCallCount = 0; +import { getDebugLogEntries, resetDebugLogBufferForTests } from "../../src/lib/debug-log-buffer"; +import { resetDebugSettingsForTests } from "../../src/lib/debug-settings"; const PREV_HOME = process.env.OPENCODEX_HOME; +const PREV_DEBUG = process.env.OCX_DEBUG; let runWithImageBridgeProduction: typeof import("../../src/images/loop")["runWithImageBridge"]; let clampImageMaxRounds: typeof import("../../src/images/loop")["clampImageMaxRounds"]; let DEFAULT_MAX_ROUNDS: typeof import("../../src/images/loop")["DEFAULT_MAX_ROUNDS"]; @@ -59,6 +62,12 @@ function runWithImageBridge( }); } afterAll(() => { if (PREV_HOME === undefined) delete process.env.OPENCODEX_HOME; else process.env.OPENCODEX_HOME = PREV_HOME; mock.restore(); }); +afterEach(() => { + resetDebugSettingsForTests(); + resetDebugLogBufferForTests(); + if (PREV_DEBUG === undefined) delete process.env.OCX_DEBUG; + else process.env.OCX_DEBUG = PREV_DEBUG; +}); // --- Mock adapter: yields canned events per iteration from a queue --- let streamQueue: AdapterEvent[][] = []; @@ -328,6 +337,27 @@ describe("runWithImageBridge", () => { } }); + test("routed image streams carry adapter and bridge diagnostics", async () => { + process.env.OCX_DEBUG = "1"; + const error = spyOn(console, "error").mockImplementation(() => {}); + try { + streamQueue = [[{ type: "text_delta", text: "image diagnostic secret" }, { type: "done" }]]; + const response = await runWithImageBridge({ + parsed: makeParsed(), + adapter: mockAdapter, + plan, + diagnostic: { requestId: "image-diagnostic", adapterName: "test" }, + }); + await response.text(); + const lines = getDebugLogEntries().map(entry => entry.line); + expect(lines.some(line => line.includes('"stage":"adapter"') && line.includes('"eventType":"text_delta"'))).toBe(true); + expect(lines.some(line => line.includes('"stage":"bridge"') && line.includes('"eventType":"text_delta"'))).toBe(true); + expect(lines.every(line => !line.includes("image diagnostic secret"))).toBe(true); + } finally { + error.mockRestore(); + } + }); + test("translator overflow remains typed through the image loop and bridge", async () => { const sse = await runAndGetSSE([[ { @@ -1050,6 +1080,31 @@ describe("runWithImageBridge — runTurn adapter", () => { expect(sse).toContain("hello from runTurn"); }); + test("runTurn collected events carry adapter-stage diagnostics", async () => { + process.env.OCX_DEBUG = "1"; + const error = spyOn(console, "error").mockImplementation(() => {}); + try { + const response = await runWithImageBridge({ + parsed: makeParsed(), + adapter: { + ...mockAdapter, + runTurn: async (_parsed, _incoming, emit) => { + emit({ type: "text_delta", text: "runturn diagnostic secret" }); + emit({ type: "done" }); + }, + }, + plan, + diagnostic: { requestId: "image-runturn-diagnostic", adapterName: "test" }, + }); + await response.text(); + const lines = getDebugLogEntries().map(entry => entry.line); + expect(lines.some(line => line.includes('"stage":"adapter"') && line.includes('"eventType":"text_delta"'))).toBe(true); + expect(lines.every(line => !line.includes("runturn diagnostic secret"))).toBe(true); + } finally { + error.mockRestore(); + } + }); + test("runTurn adapter → error event surfaces as upstream failure", async () => { runTurnEventQueue = [ [{ type: "error", message: "cursor blew up" }], diff --git a/tests/lib/debug.test.ts b/tests/lib/debug.test.ts index b80f7db41f..57b595beb6 100644 --- a/tests/lib/debug.test.ts +++ b/tests/lib/debug.test.ts @@ -3,7 +3,7 @@ import { appendDebugLogLine, debugBufferMetrics, getDebugLogEntries, resetDebugL import { ResourceAdmissionError, RETAINED_TRUNCATION_MARKER, retainedUtf8Bytes, truncateRetainedUtf8 } from "../../src/lib/admission"; import { getInjectionDebugLogEntries, injectionDebugLog, resetInjectionDebugLogBufferForTests } from "../../src/lib/injection-debug-log"; import { markActivity, activityBreadcrumb } from "../../src/lib/sidecar-tracker"; -import { debugDroppedFrame, debugProviderDiagnostic } from "../../src/lib/debug"; +import { debugDroppedFrame, debugFingerprint, debugProviderDiagnostic, debugStreamDiagnostic } from "../../src/lib/debug"; import { resetDebugSettingsForTests, setDebugSettings } from "../../src/lib/debug-settings"; describe("retained UTF-8 sizing", () => { @@ -142,6 +142,47 @@ describe("debug frame logging", () => { } }); + test("debug fingerprints are process-stable, content-free, and debug-gated", () => { + delete process.env.OCX_DEBUG; + expect(debugFingerprint("fixture reasoning and secret")).toBeUndefined(); + + process.env.OCX_DEBUG = "1"; + const same = debugFingerprint("fixture reasoning and secret"); + const again = debugFingerprint("fixture reasoning and secret"); + const different = debugFingerprint("different fixture"); + expect(same).toMatch(/^[0-9a-f]{64}$/); + expect(again).toBe(same); + expect(different).toMatch(/^[0-9a-f]{64}$/); + expect(different).not.toBe(same); + expect(getDebugLogEntries()).toHaveLength(0); + }); + + test("stream diagnostics are structural and omit content", () => { + process.env.OCX_DEBUG = "1"; + const error = spyOn(console, "error").mockImplementation(() => {}); + try { + debugStreamDiagnostic( + { requestId: "req-1", adapterName: "openai-chat" }, + "adapter", + 3, + "text_delta", + { byteLength: 21, fingerprint: debugFingerprint("fixture reasoning and secret"), attempt: 2, recovery: "empty-completion" }, + ); + const line = getDebugLogEntries()[0]?.line ?? ""; + expect(line).toContain("[ocx:openai-chat:stream]"); + expect(line).toContain('"stage":"adapter"'); + expect(line).toContain('"sequence":3'); + expect(line).toContain('"eventType":"text_delta"'); + expect(line).toContain('"byteLength":21'); + expect(line).toContain('"fingerprint"'); + expect(line).toContain('"attempt":2'); + expect(line).toContain('"recovery":"empty-completion"'); + expect(line).not.toContain("fixture reasoning and secret"); + } finally { + error.mockRestore(); + } + }); + test("debugProviderDiagnostic emits when enabled via runtime settings API", () => { delete process.env.OCX_DEBUG; setDebugSettings({ debug: true }); diff --git a/tests/web-search/web-search.test.ts b/tests/web-search/web-search.test.ts index 1e5331da33..d6399946f9 100644 --- a/tests/web-search/web-search.test.ts +++ b/tests/web-search/web-search.test.ts @@ -14,6 +14,8 @@ import type { AdapterFetchContext, ProviderAdapter } from "../../src/adapters/ba import type { OcxMessage, OcxParsedRequest } from "../../src/types"; import { fakeChatGptJwt } from "../helpers/fake-chatgpt-jwt"; import { createTestTranslatorBudget } from "../helpers/translator-budget"; +import { getDebugLogEntries, resetDebugLogBufferForTests } from "../../src/lib/debug-log-buffer"; +import { resetDebugSettingsForTests } from "../../src/lib/debug-settings"; import { withUpstreamHttpVersion } from "../../src/lib/upstream-http-version"; /** @@ -566,7 +568,47 @@ describe("web-search sidecar planning", () => { }); const originalFetch = globalThis.fetch; -afterEach(() => { globalThis.fetch = originalFetch; }); +const originalDebug = process.env.OCX_DEBUG; +afterEach(() => { + globalThis.fetch = originalFetch; + resetDebugSettingsForTests(); + resetDebugLogBufferForTests(); + if (originalDebug === undefined) delete process.env.OCX_DEBUG; + else process.env.OCX_DEBUG = originalDebug; +}); + +test("routed web-search streams carry adapter and bridge diagnostics", async () => { + process.env.OCX_DEBUG = "1"; + const error = spyOn(console, "error").mockImplementation(() => {}); + try { + const adapter: ProviderAdapter = { + name: "diagnostic-search", + buildRequest: () => ({ url: "https://routed.test/v1", method: "POST", headers: {}, body: "{}" }), + fetchResponse: async () => new Response("wire", { status: 200 }), + async *parseStream() { + yield { type: "text_delta", text: "search diagnostic secret" }; + yield { type: "done" }; + }, + }; + const response = await runWithWebSearch({ + parsed: parseRequest({ model: "routed/model", input: "hi", stream: true, tools: [{ type: "web_search" }] }), + adapter, + forwardProvider, + hostedTool: { type: "web_search" }, + selectedForwardHeaders: new Headers({ authorization: "Bearer token" }), + settings: { model: "gpt-5.6-luna", reasoning: "low", timeoutMs: 30_000 }, + maxSearches: 1, + diagnostic: { requestId: "search-diagnostic", adapterName: "diagnostic-search" }, + }); + await response.text(); + const lines = getDebugLogEntries().map(entry => entry.line); + expect(lines.some(line => line.includes('"stage":"adapter"') && line.includes('"eventType":"text_delta"'))).toBe(true); + expect(lines.some(line => line.includes('"stage":"bridge"') && line.includes('"eventType":"text_delta"'))).toBe(true); + expect(lines.every(line => !line.includes("search diagnostic secret"))).toBe(true); + } finally { + error.mockRestore(); + } +}); test("issue #2885 — Zhipu-shaped web-search routing preserves the provider HTTP version pin", async () => { let routedProtocol: string | undefined;