From 6f44cd646e035bb774538b2ea06c3e92d4146dfb Mon Sep 17 00:00:00 2001 From: xyjk Date: Tue, 29 Sep 2026 13:27:38 -0700 Subject: [PATCH] fix: retain first-output timing for tool-only Responses turns Constraint: Keep the existing once-only callback and empty/control-event exclusions in native and adapted Responses streams. Rejected: Match every event ending in .delta | control and echo payloads must not start output timing. Confidence: high Scope-risk: narrow Directive: First-output timing is a proxy observation, not the start of hidden reasoning or exact model decoding. Tested: 183 focused Bun tests; TypeScript typecheck; privacy scan; structure checks; documentation build; pre-fix regressions reproduce missing timing. Not-tested: Full repository suite; upstream live inference on this dev checkout. --- .../src/content/docs/guides/web-dashboard.md | 5 ++++ src/bridge/sse.ts | 6 ++-- src/server/relay.ts | 4 ++- structure/transports/responses-wire-shapes.md | 2 +- structure/transports/responses.md | 2 +- tests/adapters/bridge.test.ts | 23 +++++++++++++-- tests/server/response-log-inspection.test.ts | 29 +++++++++++++++++++ 7 files changed, 64 insertions(+), 7 deletions(-) diff --git a/docs-site/src/content/docs/guides/web-dashboard.md b/docs-site/src/content/docs/guides/web-dashboard.md index 3645ae7c1d3..37358265a49 100644 --- a/docs-site/src/content/docs/guides/web-dashboard.md +++ b/docs-site/src/content/docs/guides/web-dashboard.md @@ -71,6 +71,11 @@ host and port over a LAN IP or an alias. ## Dashboard layout +Responses first-output timing includes streamed function arguments and custom-tool input, as well +as text and reasoning. A tool-only turn can therefore have a first-output time even without prose. +Empty deltas and tool-start notifications do not start this timer. It measures the proxy's first +observed output, not the start of hidden model reasoning or exact model decoding throughput. + Overview uses matching status cards and full-width settings rows. On wide screens, labels share one column and model/effort controls share another. On narrower screens, controls move below their labels in the same reading order. Long version labels are shortened visually; hover the version diff --git a/src/bridge/sse.ts b/src/bridge/sse.ts index 068b8d0118e..7374d4be0b3 100644 --- a/src/bridge/sse.ts +++ b/src/bridge/sse.ts @@ -88,7 +88,7 @@ export function bridgeToResponsesSSE( * response.completed — codex-rs collect_compaction_output requires exactly one. */ compaction?: boolean; - /** One-shot: first non-empty text/thinking/raw-reasoning delta observed (WP4 TTFT). */ + /** One-shot: first non-empty text/thinking/raw-reasoning/tool-input delta observed. */ onFirstOutput?: () => void; onTerminal?: (status: ResponsesTerminalStatus) => void; onCompletedResponse?: (response: Record, providerState?: OcxProviderContinuationState) => void; @@ -707,7 +707,9 @@ export function bridgeToResponsesSSE( ? event.thinking.length > 0 : event.type === "reasoning_raw_delta" ? event.text.length > 0 - : false; + : event.type === "tool_call_delta" + ? event.arguments.length > 0 + : false; if (!nonEmpty) return; firstOutputReported = true; try { options?.onFirstOutput?.(); } catch { /* metrics must not break the stream */ } diff --git a/src/server/relay.ts b/src/server/relay.ts index c2cc93758f0..947598d5c03 100644 --- a/src/server/relay.ts +++ b/src/server/relay.ts @@ -686,7 +686,9 @@ export function firstOutputFromParsed(parsed: unknown): boolean { const event = parsed as { type?: unknown; delta?: unknown }; return (event.type === "response.output_text.delta" || event.type === "response.reasoning_summary_text.delta" - || event.type === "response.reasoning_text.delta") + || event.type === "response.reasoning_text.delta" + || event.type === "response.function_call_arguments.delta" + || event.type === "response.custom_tool_call_input.delta") && typeof event.delta === "string" && event.delta.length > 0; } diff --git a/structure/transports/responses-wire-shapes.md b/structure/transports/responses-wire-shapes.md index 31f2610de7d..3528041fe77 100644 --- a/structure/transports/responses-wire-shapes.md +++ b/structure/transports/responses-wire-shapes.md @@ -503,7 +503,7 @@ No pool timer or shutdown registration exists before eligible traffic activates Translated response request-log tracking and the heartbeat relay also reuse `createSseInspector`. This keeps every client-facing SSE observation path on the same byte-bounded, discard-and-resynchronize frame policy and ensures the -request-log, first-output, and terminal observers share one payload parse. +request-log, first-output, and terminal observers share one payload parse. First-output timing recognizes nonempty text, reasoning, function-argument, and custom-tool-input deltas; empty deltas, tool scaffolding, control/echo frames, and terminal snapshots do not start it. The inspector records a structured `response.failed` status before invoking the terminal observer. Native Responses, Chat Completions, Claude Messages, and WebSocket request logs must therefore finalize through the context-aware terminal mapper; recognized diff --git a/structure/transports/responses.md b/structure/transports/responses.md index bbd5923ce18..0f470df58e6 100644 --- a/structure/transports/responses.md +++ b/structure/transports/responses.md @@ -576,7 +576,7 @@ reuses `beginInferenceAttempt` and `createFinalRequestLog` with its own 401/429 ## Adapter-to-Responses bridge `src/bridge.ts` is a re-export facade; the implementation lives in `src/bridge/`. -`src/bridge/sse.ts` (`bridgeToResponsesSSE`) turns adapter events into the Responses SSE stream, +`src/bridge/sse.ts` (`bridgeToResponsesSSE`) turns adapter events into the Responses SSE stream; its once-only first-output observer includes nonempty `tool_call_delta` arguments (including custom-tool input), but not tool-start scaffolding or empty arguments, and `src/bridge/response-json.ts` (`buildResponseJSON`) builds the non-streaming Responses body from the same events. `buildResponseJSON` records a buffered delivery on the attempt unless the caller passes `recordBufferedDelivery: false`, which the direct client encoders do because they diff --git a/tests/adapters/bridge.test.ts b/tests/adapters/bridge.test.ts index 793b1e32eda..52130707e74 100644 --- a/tests/adapters/bridge.test.ts +++ b/tests/adapters/bridge.test.ts @@ -61,17 +61,36 @@ describe("Responses bridge reasoning and usage parity", () => { expect(firstOutputs).toBe(1); }); - test("first-output callback ignores tool-only streams", async () => { + test("first-output callback observes tool-only streams once", async () => { let firstOutputs = 0; await collectSse(bridgeToResponsesSSE(replay([ { type: "tool_call_start", id: "call_1", name: "read_file" }, + { type: "tool_call_delta", arguments: "" }, { type: "tool_call_delta", arguments: "{}" }, + { type: "tool_call_delta", arguments: " " }, { type: "tool_call_end", id: "call_1" }, { type: "done" }, ]), "routed/model", undefined, undefined, undefined, undefined, undefined, { onFirstOutput: () => { firstOutputs += 1; }, })); - expect(firstOutputs).toBe(0); + expect(firstOutputs).toBe(1); + }); + + test("first-output callback observes custom tool input but not empty tool scaffolding", async () => { + for (const input of ["", "synthetic input"]) { + let firstOutputs = 0; + const frames = await collectSse(bridgeToResponsesSSE(replay([ + { type: "tool_call_start", id: "custom_1", name: "probe_tool" }, + { type: "tool_call_delta", arguments: input }, + { type: "tool_call_end", id: "custom_1" }, + { type: "done" }, + ]), "routed/model", undefined, new Set(["probe_tool"]), undefined, undefined, undefined, { + onFirstOutput: () => { firstOutputs += 1; }, + })); + expect(firstOutputs).toBe(input.length ? 1 : 0); + expect(frames.some(frame => frame.event === "response.completed")).toBe(true); + if (input) expect(frames.some(frame => frame.event === "response.custom_tool_call_input.delta")).toBe(true); + } }); test("first-output callback still fires for hidden reasoning", async () => { diff --git a/tests/server/response-log-inspection.test.ts b/tests/server/response-log-inspection.test.ts index 35ab799bce1..157f78f13bf 100644 --- a/tests/server/response-log-inspection.test.ts +++ b/tests/server/response-log-inspection.test.ts @@ -12,6 +12,35 @@ import type { RequestLogContext } from "../../src/server/request-log"; const encoder = new TextEncoder(); const frame = (payload: unknown) => encoder.encode(`data: ${JSON.stringify(payload)}\n\n`); + +describe("tool-output first timing", () => { + for (const type of ["response.function_call_arguments.delta", "response.custom_tool_call_input.delta"]) { + test(`${type} starts timing once through fragmented SSE`, () => { + let firstOutputs = 0; + const inspector = createSseInspector({ onFirstOutput: () => { firstOutputs++; } }); + for (const event of [ + { type: "response.created" }, + { type: "response.output_item.added", item: { type: "function_call", arguments: "" } }, + { type: "response.steer.input.delta", delta: "echo" }, + { type: "response.inject.input.delta", delta: "echo" }, + { type, delta: "" }, + { type, delta: 42 }, + ]) inspector.feed(frame(event)); + expect(firstOutputs).toBe(0); + for (const delta of ["{", " "]) { + const bytes = frame({ type, delta }); + inspector.feed(bytes.subarray(0, 11)); + inspector.feed(bytes.subarray(11)); + } + expect(firstOutputs).toBe(1); + inspector.feed(frame({ type: "response.output_text.delta", delta: "later prose" })); + inspector.feed(frame({ type: "response.completed", response: { status: "completed", output: [] } })); + inspector.finish(); + expect(firstOutputs).toBe(1); + expect(inspector.terminalSeen()).toBe(true); + }); + } +}); const terminal = (id = "fixture-response") => ({ type: "response.completed", response: {