From cf57bc0c14f4fc4a88e112d4c72bd6e40019c3c8 Mon Sep 17 00:00:00 2001 From: luvs01 <27862058+luvs01@users.noreply.github.com> Date: Wed, 16 Sep 2026 02:33:55 +0000 Subject: [PATCH 1/2] fix(logs): bound response inspection without losing SSE finality Adapt luvs01/opencodex#177 and #106 onto current dev. Preserve terminal ownership with bounded tee read-ahead, stream non-SSE bodies, and cover cancellation races. --- .../docs/guides/response-inspection.md | 36 ++ scripts/test-layout/layout.json | 4 +- src/server/inspection-tee.ts | 107 +++++ src/server/relay.ts | 33 +- src/server/response-log-body.ts | 153 +++++++ src/server/responses/passthrough-delivery.ts | 11 +- structure/adapters/registry.md | 2 + structure/catalog.md | 2 + structure/clients/claude-desktop.md | 2 + structure/data-planes/images.md | 2 + structure/data-planes/inbound-compat.md | 2 + structure/gui-and-management-api.md | 2 + structure/ops/docs-and-release.md | 2 + structure/ops/service-and-sidecars.md | 2 + structure/overview.md | 2 + structure/providers/xai-grok.md | 2 + structure/runtime.md | 2 + structure/subagents.md | 2 + structure/transports/byte-accounting.md | 31 ++ structure/transports/inventory.md | 2 + structure/transports/responses.md | 2 + structure/transports/streaming-health.md | 2 + tests/fixtures/test-layout-expected.json | 4 +- tests/server/response-log-inspection.test.ts | 380 ++++++++++++++++++ tests/usage/request-log-nonstream.test.ts | 110 +++++ 25 files changed, 874 insertions(+), 25 deletions(-) create mode 100644 docs-site/src/content/docs/guides/response-inspection.md create mode 100644 src/server/inspection-tee.ts create mode 100644 src/server/response-log-body.ts create mode 100644 tests/server/response-log-inspection.test.ts create mode 100644 tests/usage/request-log-nonstream.test.ts diff --git a/docs-site/src/content/docs/guides/response-inspection.md b/docs-site/src/content/docs/guides/response-inspection.md new file mode 100644 index 0000000000..e1ac72b3b5 --- /dev/null +++ b/docs-site/src/content/docs/guides/response-inspection.md @@ -0,0 +1,36 @@ +--- +title: Response inspection and large responses +description: How bounded diagnostic retention and streaming inspection interact with response delivery. +--- + +OpenCodex keeps response diagnostics bounded without making the logging limit a +limit on the bytes delivered to your client. Other provider, request and transport +limits still apply independently. + +## JSON and ordinary error responses + +JSON inspection retains at most 32 MiB of source bytes. If the body exceeds that +allowance, logging drops its retained copy and continues forwarding the original +response. It does not parse a truncated prefix as authoritative usage or model +metadata. Usage already supplied by another trusted path is preserved; missing +usage is not replaced with an invented zero. Ordinary non-JSON error diagnostics +retain only the first 8 KiB and pass through the existing redaction logic. + +The client receives chunks as it reads them rather than waiting for diagnostic +inspection of the whole body. A read failure is recorded as 502 and cancellation +as 499 in request history; these diagnostic outcomes do not rewrite HTTP headers +that have already been sent. Logging is finalized once. + +## Streaming responses + +Native SSE inspection pauses when it runs too far ahead of client consumption. +The allowance is 32 MiB plus source-chunk/native-prefetch overhead, not a total +response-size limit or a cap on all process memory. A longer response is still +inspected through its actual completion event, including terminal usage and +continuation state. + +After the client disconnects, the existing bounded drain can still observe a late +completion for up to 15 seconds or 32 MiB of additional inspection. A forced +shutdown is different: it discards uncompleted candidates rather than recording +them as a completed response. Existing transport selection and WebSocket memory +bounds are unchanged. No new configuration setting is required. diff --git a/scripts/test-layout/layout.json b/scripts/test-layout/layout.json index 885d2abcd4..81ee5423df 100644 --- a/scripts/test-layout/layout.json +++ b/scripts/test-layout/layout.json @@ -1456,7 +1456,9 @@ "execution-budget-permits.test.ts": "lib", "spend-instrumentation-log.test.ts": "server", "codex-pool-refresh-backoff.test.ts": "codex-integration", - "responses-account-change-scrub.test.ts": "responses" + "responses-account-change-scrub.test.ts": "responses", + "response-log-inspection.test.ts": "server", + "request-log-nonstream.test.ts": "usage" }, "migrated": [ "adapters", diff --git a/src/server/inspection-tee.ts b/src/server/inspection-tee.ts new file mode 100644 index 0000000000..b3a9344a4f --- /dev/null +++ b/src/server/inspection-tee.ts @@ -0,0 +1,107 @@ +/** Read-ahead allowance, not a lifetime limit on SSE inspection or delivery. */ +export const MAX_INSPECTION_READ_AHEAD_BYTES = 32 * 1024 * 1024; + +export interface InspectionTeeOptions { + /** Release pacing so the inspection owner's existing bounded drain can run. */ + clientGoneSignal?: AbortSignal; + /** Internal test seam; callers must not take this value from upstream data. */ + maxReadAheadBytes?: number; +} + +/** + * Keep native tee cancellation semantics while pacing the inspection branch. + * + * Inspection may lead raw client consumption by the allowance plus one source + * chunk (and native tee prefetch). It never stops merely because the whole turn + * crossed that size: terminal, usage and continuation observers retain ownership. + * Count raw client bytes BEFORE rewrites, which may shrink, drop or expand them. + * Push sources still need their own producer-side bound; this is not an RSS cap. + */ +export function teeWithBoundedInspection( + source: ReadableStream, + options: InspectionTeeOptions = {}, +): [ReadableStream, ReadableStream] { + const limit = options.maxReadAheadBytes ?? MAX_INSPECTION_READ_AHEAD_BYTES; + if (!Number.isSafeInteger(limit) || limit <= 0) { + throw new RangeError("Inspection read-ahead limit must be a positive safe integer"); + } + const [client, inspection] = source.tee(); + let leadBytes = 0; + let pacingReleased = false; + let credit: Promise | undefined; + let wake: (() => void) | undefined; + + const wakeReader = () => { + const resolve = wake; + wake = undefined; + credit = undefined; + resolve?.(); + }; + const releasePacing = () => { + pacingReleased = true; + wakeReader(); + }; + const signal = options.clientGoneSignal; + if (signal?.aborted) releasePacing(); + else signal?.addEventListener("abort", releasePacing, { once: true }); + + const wrap = ( + body: ReadableStream, + isClient: boolean, + ): ReadableStream => { + const reader = body.getReader(); + let ended = false; + // An upstream error must wake an inspector waiting for credit, not remain + // hidden until the client happens to issue another read. One observer per + // reader, not a permanent Promise.race reaction attached on every chunk. + void reader.closed.catch(releasePacing); + const releaseLock = () => { + try { reader.releaseLock(); } catch { /* a pending read owns the lock */ } + }; + const finish = () => { + ended = true; + releasePacing(); + if (!isClient) signal?.removeEventListener("abort", releasePacing); + }; + return new ReadableStream({ + async pull(controller) { + if (ended) return; + if (!isClient && !pacingReleased && leadBytes >= limit) { + credit ??= new Promise(resolve => { wake = resolve; }); + await credit; + if (ended) return; + } + try { + const result = await reader.read(); + if (ended) return; + if (result.done) { + finish(); + releaseLock(); + controller.close(); + return; + } + if (isClient) { + leadBytes -= result.value.byteLength; + if (leadBytes < limit) wakeReader(); + } else { + leadBytes += result.value.byteLength; + } + controller.enqueue(result.value); + } catch (error) { + if (ended) return; + finish(); + releaseLock(); + controller.error(error); + } + }, + cancel(reason) { + finish(); + // Awaiting one tee branch's cancellation waits for the sibling. The + // owner must be free to finish cleanup and cancel/read that sibling. + void reader.cancel(reason).catch(() => undefined); + releaseLock(); + }, + }, { highWaterMark: 0 }); + }; + return [wrap(client, true), wrap(inspection, false)]; +} diff --git a/src/server/relay.ts b/src/server/relay.ts index f480ace68a..7dbfe14288 100644 --- a/src/server/relay.ts +++ b/src/server/relay.ts @@ -26,6 +26,7 @@ import { MAX_CLIENT_SSE_FRAME_BYTES, } from "./sse-frame-buffer"; import { replaceSseDataPayload } from "./sse-payload-rewrite"; +import { createBoundedResponseLogBody } from "./response-log-body"; const nativePassthroughSseResponses = new WeakSet(); const eagerRelaySseResponses = new WeakSet(); @@ -718,25 +719,16 @@ export function responseWithDeferredRequestLog( } if (!response.body || !contentType.includes("text/event-stream")) { if (response.body && (contentType.includes("application/json") || response.status >= 400)) { - const finalizeJsonLog = async () => { - const text = await response.text(); - // Non-JSON error bodies: inspect/log only a bounded prefix (the stored - // upstreamError is 500 chars anyway); the FULL text is still forwarded to the - // client below, unchanged. JSON bodies keep full inspection (usage parsing). - const isJson = contentType.includes("application/json"); - inspectResponseLogJson(logCtx, isJson ? text : text.slice(0, 8192)); - addFinalRequestLog(requestId, start, logCtx, response.status, { closeReason: "non_stream" }, addLog); - return text; - }; - const body = new ReadableStream({ - async start(controller) { - try { - controller.enqueue(new TextEncoder().encode(await finalizeJsonLog())); - controller.close(); - } catch (err) { - addFinalRequestLog(requestId, start, logCtx, 502, { closeReason: "non_stream" }, addLog); - try { controller.error(err); } catch { /* already torn down */ } - } + const body = createBoundedResponseLogBody(response.body, { + json: contentType.includes("application/json"), + inspect: text => inspectResponseLogJson(logCtx, text), + finalize: reason => { + // Preserve wire status; request history follows the adjacent SSE + // convention for a client cancellation or upstream read failure. + const status = reason === "cancel" ? 499 : reason === "read_error" ? 502 : response.status; + addFinalRequestLog(requestId, start, logCtx, status, { + closeReason: reason === "cancel" ? "client_cancel" : "non_stream", + }, addLog); }, }); return new Response(body, { @@ -1338,6 +1330,9 @@ function startBoundedInspectionPump(options: InspectionPumpOptions): void { try { for (;;) { const { done, value } = await reader.read(); + // Hard cancellation settles a pending read as EOF. Do not flush a + // partial terminal after the owner already finalized cancellation. + if (cancelled) break; if (clientGoneSignal?.aborted) markClientGone(); if (drainStopped) { // stopDrain() cancelled the reader; the settled read is the wake-up. diff --git a/src/server/response-log-body.ts b/src/server/response-log-body.ts new file mode 100644 index 0000000000..5ac4329652 --- /dev/null +++ b/src/server/response-log-body.ts @@ -0,0 +1,153 @@ +/** Bounds diagnostic retention, never the bytes delivered to the caller. */ +export const MAX_RESPONSE_LOG_INSPECTION_BYTES = 32 * 1024 * 1024; +export const MAX_NON_JSON_ERROR_INSPECTION_BYTES = 8 * 1024; +const INSPECTION_BLOCK_BYTES = 64 * 1024; + +export type ResponseLogBodyEnd = "eof" | "read_error" | "cancel"; + +export interface ResponseLogBodyOptions { + json: boolean; + inspect: (text: string) => void; + finalize: (reason: ResponseLogBodyEnd) => void; + /** Internal test seam; this is not a provider-controlled limit. */ + maxInspectionBytes?: number; +} + +/** Fixed-size blocks bound both retained bytes and per-chunk bookkeeping. */ +class ResponseLogInspection { + private blocks: Uint8Array[] = []; + private bytes = 0; + private overflowed = false; + + constructor(private readonly json: boolean, private readonly limit: number) {} + + append(chunk: Uint8Array): void { + if (this.overflowed || chunk.byteLength === 0) return; + if (this.json && chunk.byteLength > this.limit - this.bytes) { + // A JSON prefix is not an authoritative response. Drop it immediately, + // without either truncating the delivery stream or retaining later bytes. + this.overflowed = true; + this.dispose(); + return; + } + let remaining = Math.min(chunk.byteLength, this.limit - this.bytes); + let offset = 0; + while (remaining > 0) { + const blockOffset = this.bytes % INSPECTION_BLOCK_BYTES; + if (blockOffset === 0) { + this.blocks.push(new Uint8Array(Math.min(INSPECTION_BLOCK_BYTES, this.limit - this.bytes))); + } + const block = this.blocks[this.blocks.length - 1]!; + const length = Math.min(remaining, block.byteLength - blockOffset); + block.set(chunk.subarray(offset, offset + length), blockOffset); + this.bytes += length; + offset += length; + remaining -= length; + } + } + + text(reason: ResponseLogBodyEnd): string | undefined { + // Even a syntactically valid JSON prefix must not update usage/model + // metadata when the transport did not reach EOF. + if (this.json && (reason !== "eof" || this.overflowed)) return undefined; + const combined = new Uint8Array(this.bytes); + let offset = 0; + for (const block of this.blocks) { + const length = Math.min(block.byteLength, this.bytes - offset); + combined.set(block.subarray(0, length), offset); + offset += length; + } + return new TextDecoder().decode(combined); + } + + dispose(): void { + this.blocks.length = 0; + this.bytes = 0; + } +} + +/** Optional diagnostics must not change the response's transport outcome. */ +function bestEffort(callback: () => void): void { + try { + callback(); + } catch { + return; + } +} + +/** + * Forward one upstream read per downstream pull, with bounded side inspection. + * EOF, read failure and cancellation each finalize at most once. Cancellation + * does not await the upstream cancel promise: one branch of a tee can otherwise + * wait for a sibling that the same caller intends to consume or cancel later. + */ +export function createBoundedResponseLogBody( + body: ReadableStream, + options: ResponseLogBodyOptions, +): ReadableStream { + const limit = options.maxInspectionBytes ?? (options.json + ? MAX_RESPONSE_LOG_INSPECTION_BYTES + : MAX_NON_JSON_ERROR_INSPECTION_BYTES); + if (!Number.isSafeInteger(limit) || limit < 0) { + throw new RangeError("Response log inspection limit must be a non-negative safe integer"); + } + const inspection = new ResponseLogInspection(options.json, limit); + const reader = body.getReader(); + let ended = false; + let inspectionFailed = false; + + const release = () => bestEffort(() => reader.releaseLock()); + const finish = (reason: ResponseLogBodyEnd) => { + if (ended) return; + ended = true; // Set before callbacks or a pending read resumes. + try { + if (!inspectionFailed) { + bestEffort(() => { + const text = inspection.text(reason); + if (text !== undefined) options.inspect(text); + }); + } + } finally { + inspection.dispose(); + bestEffort(() => options.finalize(reason)); + } + }; + + return new ReadableStream({ + async pull(controller) { + if (ended) return; + let result: Awaited>; + try { + result = await reader.read(); + } catch (error) { + if (ended) return; // Cancellation owns its pending-read settlement. + finish("read_error"); + release(); + controller.error(error); + return; + } + if (ended) return; + if (result.done) { + finish("eof"); + release(); + controller.close(); + return; + } + if (!inspectionFailed) { + try { + inspection.append(result.value); + } catch { + inspectionFailed = true; + inspection.dispose(); + } + } + // Do not decode/re-encode transport bytes, including malformed UTF-8. + controller.enqueue(result.value); + }, + cancel(reason) { + finish("cancel"); + bestEffort(() => { void reader.cancel(reason).catch(() => undefined); }); + release(); + }, + }, { highWaterMark: 0 }); +} diff --git a/src/server/responses/passthrough-delivery.ts b/src/server/responses/passthrough-delivery.ts index 79e6ca3d46..0d2292e6d6 100644 --- a/src/server/responses/passthrough-delivery.ts +++ b/src/server/responses/passthrough-delivery.ts @@ -15,6 +15,7 @@ import { relayWithAbort, } from "../relay"; import { isUsageDebugEnabled } from "../../usage/debug"; +import { teeWithBoundedInspection } from "../inspection-tee"; import { codexForwardTerminalOutcomeRecorder, usesCodexForwardPoolAuth, @@ -593,16 +594,18 @@ export async function deliverPassthroughResponse( })), ); } - const [nativeBody, inspectBody] = passthroughSseBody.tee(); const turnAc = new AbortController(); const clientGone = new AbortController(); + const clientGoneSignal = options.abortSignal + ? AbortSignal.any([clientGone.signal, options.abortSignal]) + : clientGone.signal; + // Pace against raw bytes before rewrites, without detaching terminal ownership. + const [nativeBody, inspectBody] = teeWithBoundedInspection(passthroughSseBody, { clientGoneSignal }); linkAbortSignal(upstream, turnAc.signal); registerTurn(turnAc, options.turnAdmissionLease); const inspectionConsumerOptions = { // Request abort can reject the fetch body before the response cancel hook runs. - clientGoneSignal: options.abortSignal - ? AbortSignal.any([clientGone.signal, options.abortSignal]) - : clientGone.signal, + clientGoneSignal, drainBounds: { ms: 15_000, bytes: 32 * 1024 * 1024 }, upstream, pinCompletedResponseIdToFirstSeen: githubCopilotRepairEnabled, diff --git a/structure/adapters/registry.md b/structure/adapters/registry.md index 83e8f4f466..0d6e3e96b2 100644 --- a/structure/adapters/registry.md +++ b/structure/adapters/registry.md @@ -183,3 +183,5 @@ implement legacy call/result pairing. Modern tool-image carriers are unchanged. raw passthrough; `tests/responses/chat-media-translation.test.ts` reaches the real HTTP translation boundary and verifies that rejection sends no upstream request. Canonical Responses identity sanitation and narrowly scoped pre-output combo recovery follow [request-local target compatibility](../runtime.md#request-local-target-compatibility); other adapter contracts remain unchanged. + +Shared response-log retention and native SSE inspection pacing follow the [bounded inspection contract](../transports/byte-accounting.md#response-log-inspection); other subsystem behavior remains unchanged. diff --git a/structure/catalog.md b/structure/catalog.md index bf9d6e3751..31097991ef 100644 --- a/structure/catalog.md +++ b/structure/catalog.md @@ -395,3 +395,5 @@ Exact [model input declarations](config.md#explicit-per-model-capability-declara ## Renamed destination reasoning metadata `src/providers/derive.ts` fills missing reasoning tables for renamed providers accepted by the existing fixed-key destination matcher. Model entries are cloned and explicit user entries (including empty arrays) win. Provider-wide effort defaults fill only when undefined; Command Code unknown models therefore keep the registry's empty picker policy unless overridden. Identity, transport and other capability axes are unchanged. The gathered row drives client exports; this metadata contract does not prove arbitrary gateway routing. + +Shared response-log retention and native SSE inspection pacing follow the [bounded inspection contract](transports/byte-accounting.md#response-log-inspection); other subsystem behavior remains unchanged. diff --git a/structure/clients/claude-desktop.md b/structure/clients/claude-desktop.md index 01a583c182..5214abb6ba 100644 --- a/structure/clients/claude-desktop.md +++ b/structure/clients/claude-desktop.md @@ -157,3 +157,5 @@ The [explicit model-capability contract](../config.md#explicit-per-model-capabil Exact [model input declarations](../config.md#explicit-per-model-capability-declarations) now feed text-only eligibility and catalog hints; existing image-description/omission handling consumes them before the main upstream send. Provider-scoped approval reviewer settings are projected by the [catalog owner](../catalog.md#provider-scoped-approval-reviewer); this surface retains its existing routing, transport and account-selection behavior. + +Shared response-log retention and native SSE inspection pacing follow the [bounded inspection contract](../transports/byte-accounting.md#response-log-inspection); other subsystem behavior remains unchanged. diff --git a/structure/data-planes/images.md b/structure/data-planes/images.md index a7420072bf..b80dc11a85 100644 --- a/structure/data-planes/images.md +++ b/structure/data-planes/images.md @@ -121,3 +121,5 @@ Live sideband admission and its bounded upstream handshake follow the [runtime c The [explicit model-capability contract](../config.md#explicit-per-model-capability-declarations) preserves operator declarations through provider storage and catalog capture; it does not infer upstream capability or change this surface's routing behavior. Provider-scoped approval reviewer settings are projected by the [catalog owner](../catalog.md#provider-scoped-approval-reviewer); this surface retains its existing routing, transport and account-selection behavior. + +Shared response-log retention and native SSE inspection pacing follow the [bounded inspection contract](../transports/byte-accounting.md#response-log-inspection); other subsystem behavior remains unchanged. diff --git a/structure/data-planes/inbound-compat.md b/structure/data-planes/inbound-compat.md index 33ca8c76b0..67bc76feb9 100644 --- a/structure/data-planes/inbound-compat.md +++ b/structure/data-planes/inbound-compat.md @@ -331,3 +331,5 @@ Modern `tool` images continue through the existing following-user carrier. These an OpenCodex conversion limit, not a provider capability claim. Final Responses-to-adapter admission follows the [registry contract](../adapters/registry.md#untranslated-input-media). Canonical Responses identity sanitation and narrowly scoped pre-output combo recovery follow [request-local target compatibility](../runtime.md#request-local-target-compatibility); other adapter contracts remain unchanged. + +Shared response-log retention and native SSE inspection pacing follow the [bounded inspection contract](../transports/byte-accounting.md#response-log-inspection); other subsystem behavior remains unchanged. diff --git a/structure/gui-and-management-api.md b/structure/gui-and-management-api.md index 4628ca5e50..ed46b7ee02 100644 --- a/structure/gui-and-management-api.md +++ b/structure/gui-and-management-api.md @@ -632,3 +632,5 @@ The [explicit model-capability contract](config.md#explicit-per-model-capability Exact [model input declarations](config.md#explicit-per-model-capability-declarations) now feed text-only eligibility and catalog hints; existing image-description/omission handling consumes them before the main upstream send. The raw provider editor round-trips `autoReviewModel` and `autoReviewModelOverrides` through editor-owned DTO fields. POST/PATCH/PUT share validation; PUT copies schema-normalized values into the persisted and live candidate before adoption. Canonical `openai` rejects these fields, including clear forms. Field-masked writes (PATCH, editor PUT, reload) pin every registry-seed key and ignore operator overlays the seed never defines, most commonly `selectedModels`; POST keeps the exact-key comparison. Canonical `openai` still rejects `allowPrivateNetwork`, which must not short-circuit destination DNS checks on the ChatGPT forward row. Existing authentication, origin checks and stale-baseline protection still govern the writes. See [reviewer projection](catalog.md#provider-scoped-approval-reviewer). + +Shared response-log retention and native SSE inspection pacing follow the [bounded inspection contract](transports/byte-accounting.md#response-log-inspection); other subsystem behavior remains unchanged. diff --git a/structure/ops/docs-and-release.md b/structure/ops/docs-and-release.md index 0c0ffe38d0..4ae05d713b 100644 --- a/structure/ops/docs-and-release.md +++ b/structure/ops/docs-and-release.md @@ -384,3 +384,5 @@ Exact [model input declarations](../config.md#explicit-per-model-capability-decl Provider-scoped approval reviewer settings are projected by the [catalog owner](../catalog.md#provider-scoped-approval-reviewer); this surface retains its existing routing, transport and account-selection behavior. Renamed fixed-key providers receive [missing reasoning metadata](../catalog.md#renamed-destination-reasoning-metadata) during derivation; explicit per-model entries and provider defaults retain precedence. + +Shared response-log retention and native SSE inspection pacing follow the [bounded inspection contract](../transports/byte-accounting.md#response-log-inspection); other subsystem behavior remains unchanged. diff --git a/structure/ops/service-and-sidecars.md b/structure/ops/service-and-sidecars.md index e28575b432..bcfa626bcc 100644 --- a/structure/ops/service-and-sidecars.md +++ b/structure/ops/service-and-sidecars.md @@ -182,3 +182,5 @@ Live sideband admission and its bounded upstream handshake follow the [runtime c The [explicit model-capability contract](../config.md#explicit-per-model-capability-declarations) preserves operator declarations through provider storage and catalog capture; it does not infer upstream capability or change this surface's routing behavior. Provider-scoped approval reviewer settings are projected by the [catalog owner](../catalog.md#provider-scoped-approval-reviewer); this surface retains its existing routing, transport and account-selection behavior. + +Shared response-log retention and native SSE inspection pacing follow the [bounded inspection contract](../transports/byte-accounting.md#response-log-inspection); other subsystem behavior remains unchanged. diff --git a/structure/overview.md b/structure/overview.md index 0151115adc..d8f01d4bbc 100644 --- a/structure/overview.md +++ b/structure/overview.md @@ -147,3 +147,5 @@ Translated Chat request construction uses the [inline-image budget](transports/s The [explicit model-capability contract](config.md#explicit-per-model-capability-declarations) preserves operator declarations through provider storage and catalog capture; it does not infer upstream capability or change this surface's routing behavior. Provider-scoped approval reviewer settings are projected by the [catalog owner](catalog.md#provider-scoped-approval-reviewer); this surface retains its existing routing, transport and account-selection behavior. + +Shared response-log retention and native SSE inspection pacing follow the [bounded inspection contract](transports/byte-accounting.md#response-log-inspection); other subsystem behavior remains unchanged. diff --git a/structure/providers/xai-grok.md b/structure/providers/xai-grok.md index dc982c5639..6eb9b12dd4 100644 --- a/structure/providers/xai-grok.md +++ b/structure/providers/xai-grok.md @@ -141,3 +141,5 @@ Account quota surfaces use [safe probe diagnostics](../transports/inventory.md#a Live sideband admission and its bounded upstream handshake follow the [runtime contract](../runtime.md#live-sideband-handshake); the ordinary Responses WebSocket exchange remains separate. Translated audio/file admission follows the [final-adapter input contract](../adapters/registry.md#untranslated-input-media); native raw passthrough remains separate. + +Shared response-log retention and native SSE inspection pacing follow the [bounded inspection contract](../transports/byte-accounting.md#response-log-inspection); other subsystem behavior remains unchanged. diff --git a/structure/runtime.md b/structure/runtime.md index 248c3011c6..b0777cf4dc 100644 --- a/structure/runtime.md +++ b/structure/runtime.md @@ -442,3 +442,5 @@ change target selection. `src/server/responses/core-combo.ts` applies the policy and preserves the original requested effort separately from effective wire telemetry. `src/server/chat-completions.ts` routes combos through that same child pipeline while retaining the current config-aware native-Chat eligibility check for non-combo routes. + +Shared response-log retention and native SSE inspection pacing follow the [bounded inspection contract](transports/byte-accounting.md#response-log-inspection); other subsystem behavior remains unchanged. diff --git a/structure/subagents.md b/structure/subagents.md index c0c92891f7..597c6b70a7 100644 --- a/structure/subagents.md +++ b/structure/subagents.md @@ -374,3 +374,5 @@ Exact [model input declarations](config.md#explicit-per-model-capability-declara Provider-scoped approval reviewer settings are projected by the [catalog owner](catalog.md#provider-scoped-approval-reviewer); this surface retains its existing routing, transport and account-selection behavior. Renamed fixed-key providers receive [missing reasoning metadata](catalog.md#renamed-destination-reasoning-metadata) during derivation; explicit per-model entries and provider defaults retain precedence. + +Shared response-log retention and native SSE inspection pacing follow the [bounded inspection contract](transports/byte-accounting.md#response-log-inspection); other subsystem behavior remains unchanged. diff --git a/structure/transports/byte-accounting.md b/structure/transports/byte-accounting.md index 7f01dee197..2128c7d68a 100644 --- a/structure/transports/byte-accounting.md +++ b/structure/transports/byte-accounting.md @@ -39,3 +39,34 @@ These optimizations do not add request queues, retry policies, or RSS-based admi Translated audio/file admission follows the [final-adapter input contract](../adapters/registry.md#untranslated-input-media); native raw passthrough remains separate. Canonical Responses identity sanitation and narrowly scoped pre-output combo recovery follow [request-local target compatibility](../runtime.md#request-local-target-compatibility); other adapter contracts remain unchanged. + +## Response-log inspection + +`src/server/response-log-body.ts` forwards raw response chunks on downstream demand. +Diagnostic retention is limited to 32 MiB for JSON and an 8 KiB prefix for other +HTTP error bodies. Fixed 64 KiB blocks also bound per-chunk bookkeeping. These +are retained-source-byte limits, not peak heap or response-delivery limits: +joining, decoding and parsing a bounded JSON body can temporarily use more memory. +An oversized JSON candidate is discarded immediately; partial JSON on read error +or cancellation never replaces model or usage metadata. Existing trusted metadata +is preserved. The existing parser and redaction path inspect complete admitted +JSON and bounded non-JSON error prefixes. EOF, read error and cancellation finalize +once; history records the original status, 502 or 499 respectively, without +rewriting the response status or bytes already sent to the client. + +`src/server/inspection-tee.ts` paces the native SSE inspection branch against raw +client consumption before rewrites. Its 32 MiB read-ahead allowance is not a total +turn limit: long streams retain terminal, usage and continuation observation. +The allowance can be exceeded by one source chunk plus native tee prefetch; it is +not an RSS limit or a producer-side bound for push transports. Existing eager-path +selection, WebSocket bounds and SSE frame/output-item limits are unchanged. +Client departure releases pacing to the existing 15-second/32-MiB bounded drain. +One tee branch's cancellation is never awaited by the wrapper, because that +promise may depend on its sibling. A hard owner abort discards pending candidates +rather than flushing them as successful terminals; genuine EOF/read-error tail +handling remains distinct. + +`tests/server/response-log-inspection.test.ts` covers the real inspector/relay +composition, including a turn beyond 32 MiB, late usage/output, slow readers, +cancellation and read-error races. `tests/usage/request-log-nonstream.test.ts` +binds the bounded non-stream wrapper to request-log status and metadata behavior. diff --git a/structure/transports/inventory.md b/structure/transports/inventory.md index ca80373a8e..4b6989a30a 100644 --- a/structure/transports/inventory.md +++ b/structure/transports/inventory.md @@ -148,3 +148,5 @@ Renamed fixed-key providers receive [missing reasoning metadata](../catalog.md#r Translated audio/file admission follows the [final-adapter input contract](../adapters/registry.md#untranslated-input-media); native raw passthrough remains separate. Canonical Responses identity sanitation and narrowly scoped pre-output combo recovery follow [request-local target compatibility](../runtime.md#request-local-target-compatibility); other adapter contracts remain unchanged. + +Shared response-log retention and native SSE inspection pacing follow the [bounded inspection contract](byte-accounting.md#response-log-inspection); other subsystem behavior remains unchanged. diff --git a/structure/transports/responses.md b/structure/transports/responses.md index 9af5e63100..a703fc2231 100644 --- a/structure/transports/responses.md +++ b/structure/transports/responses.md @@ -702,3 +702,5 @@ What must not happen is a ladder that charges and then returns through a path th nor releases. That is not a lost send; it is a send the request never made, spending an allowance a later recovery in the same request then cannot have. `tests/lib/execution-budget-permits.test.ts` pins both ladder shapes against exactly that. + +Shared response-log retention and native SSE inspection pacing follow the [bounded inspection contract](byte-accounting.md#response-log-inspection); other subsystem behavior remains unchanged. diff --git a/structure/transports/streaming-health.md b/structure/transports/streaming-health.md index 682fbb2ca2..f834554dc4 100644 --- a/structure/transports/streaming-health.md +++ b/structure/transports/streaming-health.md @@ -252,3 +252,5 @@ Live sideband admission and its bounded upstream handshake follow the [runtime c The [explicit model-capability contract](../config.md#explicit-per-model-capability-declarations) preserves operator declarations through provider storage and catalog capture; it does not infer upstream capability or change this surface's routing behavior. Provider-scoped approval reviewer settings are projected by the [catalog owner](../catalog.md#provider-scoped-approval-reviewer); this surface retains its existing routing, transport and account-selection behavior. + +Shared response-log retention and native SSE inspection pacing follow the [bounded inspection contract](byte-accounting.md#response-log-inspection); other subsystem behavior remains unchanged. diff --git a/tests/fixtures/test-layout-expected.json b/tests/fixtures/test-layout-expected.json index d2eb5d244b..118cf2115d 100644 --- a/tests/fixtures/test-layout-expected.json +++ b/tests/fixtures/test-layout-expected.json @@ -1288,5 +1288,7 @@ "execution-budget-permits.test.ts": "lib", "spend-instrumentation-log.test.ts": "server", "codex-pool-refresh-backoff.test.ts": "codex-integration", - "responses-account-change-scrub.test.ts": "responses" + "responses-account-change-scrub.test.ts": "responses", + "response-log-inspection.test.ts": "server", + "request-log-nonstream.test.ts": "usage" } diff --git a/tests/server/response-log-inspection.test.ts b/tests/server/response-log-inspection.test.ts new file mode 100644 index 0000000000..f2bd6ff18f --- /dev/null +++ b/tests/server/response-log-inspection.test.ts @@ -0,0 +1,380 @@ +import { describe, expect, test } from "bun:test"; +import { teeWithBoundedInspection } from "../../src/server/inspection-tee"; +import { createBoundedResponseLogBody } from "../../src/server/response-log-body"; +import { + consumeForInspection, + consumeForResponseLogMetadata, + createSseInspector, + relaySseWithFailedTail, + type InspectionConsumerOptions, +} from "../../src/server/relay"; +import type { RequestLogContext } from "../../src/server/request-log"; + +const encoder = new TextEncoder(); +const frame = (payload: unknown) => encoder.encode(`data: ${JSON.stringify(payload)}\n\n`); +const terminal = (id = "fixture-response") => ({ + type: "response.completed", + response: { + id, status: "completed", output: [], + usage: { input_tokens: 3, output_tokens: 2, total_tokens: 5 }, + }, +}); + +async function bounded(promise: Promise): Promise { + let timer: ReturnType | undefined; + try { + return await Promise.race([ + promise, + new Promise((_, reject) => { + timer = setTimeout(() => reject(new Error("inspection did not settle")), 2_000); + }), + ]); + } finally { + if (timer !== undefined) clearTimeout(timer); + } +} + +function controlledSource() { + let controller!: ReadableStreamDefaultController; + const cancelReasons: unknown[] = []; + return { + body: new ReadableStream({ + start(value) { controller = value; }, + cancel(reason) { cancelReasons.push(reason); }, + }, { highWaterMark: 0 }), + push(bytes: Uint8Array) { controller.enqueue(bytes); }, + error(reason: unknown) { controller.error(reason); }, + cancelReasons, + }; +} + +function observe(body: ReadableStream, extra: Partial = {}) { + const clientGone = new AbortController(); + const hardAbort = new AbortController(); + const upstream = new AbortController(); + const [client, inspection] = teeWithBoundedInspection(body, { + clientGoneSignal: clientGone.signal, + maxReadAheadBytes: 64, + }); + const logCtx: RequestLogContext = { model: "fixture-model", provider: "fixture-provider" }; + const outcomes: Array<{ status: string; httpStatus?: number }> = []; + const completed: Array<{ id?: unknown; output?: unknown; status?: unknown }> = []; + let cancels = 0; + let dones = 0; + let firstOutputs = 0; + let feedResolve!: () => void; + const fed = new Promise(resolve => { feedResolve = resolve; }); + const done = new Promise(resolve => { + consumeForInspection( + inspection, + (status, httpStatus) => outcomes.push({ status, httpStatus }), + hardAbort.signal, + () => { dones += 1; resolve(); }, + logCtx, + () => { cancels += 1; }, + response => completed.push(response), + () => { firstOutputs += 1; }, + { + clientGoneSignal: clientGone.signal, + drainBounds: { ms: 1_000, bytes: 4_096 }, + upstream, + inspectorFactory: handlers => { + const inspector = createSseInspector(handlers); + return { + ...inspector, + feed(chunk) { inspector.feed(chunk); feedResolve(); }, + }; + }, + ...extra, + }, + ); + }); + return { + client: relaySseWithFailedTail(client, upstream, reason => clientGone.abort(reason)), + hardAbort, upstream, fed, done, logCtx, outcomes, completed, + counts: () => ({ cancels, dones, firstOutputs }), + }; +} + +describe("bounded inspection tee with real Responses consumers", () => { + test("a turn larger than 32 MiB retains its late terminal, usage and reconstructed output", async () => { + const delta = frame({ type: "response.output_text.delta", delta: "x".repeat(8_192) }); + const item = { type: "message", id: "fixture-message", role: "assistant", content: [] }; + let chunks = 0; + const source = new ReadableStream({ + pull(controller) { + const index = chunks++; + if (index < 4_100) controller.enqueue(delta); + else if (index === 4_100) { + controller.enqueue(frame({ type: "response.output_item.done", output_index: 0, item })); + } else if (index === 4_101) { + controller.enqueue(frame(terminal())); + } + // Deliberately keep the connection open; the protocol terminal owns cleanup. + }, + }, { highWaterMark: 0 }); + const state = observe(source); + const reader = state.client.getReader(); + let bytes = 0; + try { + for (;;) { + const chunk = await reader.read(); + if (chunk.done) break; + bytes += chunk.value.byteLength; + } + await bounded(state.done); + expect(bytes).toBeGreaterThan(32 * 1024 * 1024); + expect(state.outcomes).toEqual([{ status: "completed", httpStatus: undefined }]); + expect(state.completed).toHaveLength(1); + expect(state.completed[0]?.output).toEqual([item]); + expect(state.logCtx.usage?.inputTokens).toBe(3); + expect(state.logCtx.usage?.outputTokens).toBe(2); + expect(state.counts()).toEqual({ cancels: 0, dones: 1, firstOutputs: 1 }); + } finally { + await reader.cancel(); + state.hardAbort.abort(); + } + }, 15_000); + + test("disconnect releases pacing and a late terminal wins inside the bounded drain", async () => { + const source = controlledSource(); + const state = observe(source.body); + source.push(frame({ type: "response.output_text.delta", delta: "x".repeat(128) })); + await bounded(state.fed); + await bounded(state.client.cancel("fixture client gone")); + source.push(frame(terminal("late"))); + await bounded(state.done); + expect(state.outcomes.map(value => value.status)).toEqual(["completed"]); + expect(state.completed[0]?.id).toBe("late"); + expect(state.counts().cancels).toBe(0); + expect(state.counts().dones).toBe(1); + expect(state.upstream.signal.aborted).toBe(true); + }); + + test("a silent post-disconnect source still stops at the inspection time bound", async () => { + const source = controlledSource(); + const state = observe(source.body, { drainBounds: { ms: 10, bytes: 4_096 } }); + await state.client.cancel("fixture disconnect"); + await bounded(state.done); + expect(state.outcomes).toEqual([]); + expect(state.counts()).toEqual({ cancels: 1, dones: 1, firstOutputs: 0 }); + expect(state.upstream.signal.aborted).toBe(true); + expect(source.cancelReasons).toHaveLength(1); + }); + + test("the post-disconnect byte bound cannot parse a terminal beyond its prefix", async () => { + const source = controlledSource(); + const state = observe(source.body, { drainBounds: { ms: 1_000, bytes: 8 } }); + await state.client.cancel("fixture disconnect"); + source.push(frame(terminal("beyond-bound"))); + await bounded(state.done); + expect(state.outcomes).toEqual([]); + expect(state.completed).toEqual([]); + expect(state.counts().cancels).toBe(1); + expect(state.counts().dones).toBe(1); + }); + + test("hard abort must not flush an unterminated completed candidate as success", async () => { + const source = controlledSource(); + const state = observe(source.body); + source.push(encoder.encode(`data: ${JSON.stringify(terminal("aborted"))}`)); + await bounded(state.fed); + state.hardAbort.abort("fixture shutdown"); + await bounded(state.done); + expect(state.outcomes).toEqual([]); + expect(state.completed).toEqual([]); + expect(state.counts().cancels).toBe(1); + expect(state.counts().dones).toBe(1); + await state.client.cancel("cleanup"); + }); + + test("source error wakes a credit-blocked inspector and preserves synthetic 502 provenance", async () => { + const source = controlledSource(); + const state = observe(source.body); + source.push(frame({ type: "response.output_text.delta", delta: "x".repeat(128) })); + await bounded(state.fed); + source.error(new Error("fixture source reset")); + await bounded(state.done); + expect(state.outcomes).toEqual([{ status: "failed", httpStatus: 502 }]); + expect(state.logCtx.transportPhase).toBe("mid_stream"); + expect(state.logCtx.terminalSource).toBe("synthetic"); + expect(state.counts().dones).toBe(1); + await state.client.cancel("cleanup").catch(() => undefined); + }); + + test("an actual read error still flushes a real terminal lacking a final delimiter", async () => { + const source = controlledSource(); + const state = observe(source.body); + source.push(encoder.encode(`data: ${JSON.stringify(terminal("tail"))}`)); + await bounded(state.fed); + source.error(new Error("fixture reset after terminal")); + await bounded(state.done); + expect(state.outcomes.map(value => value.status)).toEqual(["completed"]); + expect(state.completed[0]?.id).toBe("tail"); + expect(state.counts().cancels).toBe(0); + await state.client.cancel("cleanup").catch(() => undefined); + }); + + test("the metadata-only consumer also retains late usage and releases exactly once", async () => { + const clientGone = new AbortController(); + const upstream = new AbortController(); + const source = new ReadableStream({ + start(controller) { + controller.enqueue(frame({ type: "response.output_text.delta", delta: "x".repeat(128) })); + controller.enqueue(frame(terminal("metadata"))); + }, + }); + const [client, inspection] = teeWithBoundedInspection(source, { + maxReadAheadBytes: 16, clientGoneSignal: clientGone.signal, + }); + const logCtx: RequestLogContext = { model: "fixture-model", provider: "fixture-provider" }; + const completed: unknown[] = []; + let dones = 0; + const done = new Promise(resolve => { + consumeForResponseLogMetadata(inspection, logCtx, undefined, + () => { dones += 1; resolve(); }, response => completed.push(response), undefined, + { clientGoneSignal: clientGone.signal, upstream, drainBounds: { ms: 1_000, bytes: 4_096 } }); + }); + const delivery = relaySseWithFailedTail(client, upstream, reason => clientGone.abort(reason)); + expect(await new Response(delivery).text()).toContain("response.completed"); + await bounded(done); + expect(logCtx.usage?.inputTokens).toBe(3); + expect(logCtx.usage?.outputTokens).toBe(2); + expect(completed).toHaveLength(1); + expect(dones).toBe(1); + }); +}); + +describe("inspection pacing boundary", () => { + test("invalid allowances are rejected before locking the source", () => { + for (const limit of [0, -1, NaN, Infinity, 1.5]) { + const source = controlledSource(); + expect(() => teeWithBoundedInspection(source.body, { maxReadAheadBytes: limit })).toThrow(RangeError); + expect(source.body.locked).toBe(false); + } + }); + + test("a slow client bounds inspection progress until raw client bytes are consumed", async () => { + const source = new ReadableStream({ + start(controller) { + controller.enqueue(encoder.encode("12345678")); + controller.enqueue(encoder.encode("abcdefgh")); + controller.close(); + }, + }); + const [client, inspection] = teeWithBoundedInspection(source, { maxReadAheadBytes: 8 }); + const reader = inspection.getReader(); + expect((await reader.read()).value).toEqual(encoder.encode("12345678")); + let settled = false; + const next = reader.read().then(result => { settled = true; return result; }); + await Bun.sleep(5); + expect(settled).toBe(false); + const clientReader = client.getReader(); + await clientReader.read(); + expect((await bounded(next)).value).toEqual(encoder.encode("abcdefgh")); + await reader.cancel("inspection done"); + await clientReader.cancel("client done"); + }); + + test("cancelling only inspection settles promptly and leaves all client bytes intact", async () => { + const payload = encoder.encode("unmodified client response"); + const source = new Response(payload).body!; + const [client, inspection] = teeWithBoundedInspection(source, { maxReadAheadBytes: 8 }); + await bounded(inspection.cancel("inspection detached")); + expect(new Uint8Array(await new Response(client).arrayBuffer())).toEqual(payload); + }); + + test("already-aborted client signal releases pacing for the bounded drain owner", async () => { + const signal = AbortSignal.abort("already gone"); + const source = new Response("abcdefghijklmnop").body!; + const [client, inspection] = teeWithBoundedInspection(source, { maxReadAheadBytes: 1, clientGoneSignal: signal }); + expect(await bounded(new Response(inspection).text())).toBe("abcdefghijklmnop"); + await client.cancel(); + }); +}); + +describe("non-stream inspection boundary", () => { + test("JSON over its inspection allowance is delivered intact but never inspected", async () => { + const inspected: string[] = []; + const ended: string[] = []; + const payload = '{"value":"too large"}'; + const body = createBoundedResponseLogBody(new Response(payload).body!, { + json: true, maxInspectionBytes: 8, + inspect: text => inspected.push(text), finalize: reason => ended.push(reason), + }); + expect(await new Response(body).text()).toBe(payload); + expect(inspected).toEqual([]); + expect(ended).toEqual(["eof"]); + }); + + test("JSON exactly at its byte allowance is inspected once", async () => { + const payload = '{"x":1}'; + const inspected: string[] = []; + const body = createBoundedResponseLogBody(new Response(payload).body!, { + json: true, maxInspectionBytes: encoder.encode(payload).byteLength, + inspect: text => inspected.push(text), finalize() { return; }, + }); + expect(await new Response(body).text()).toBe(payload); + expect(inspected).toEqual([payload]); + }); + + test("non-JSON retains an exact byte prefix across one-byte source chunks", async () => { + let sent = 0; + const inspected: string[] = []; + const source = new ReadableStream({ + pull(controller) { + if (sent++ < 10_000) controller.enqueue(new Uint8Array([120])); + else controller.close(); + }, + }, { highWaterMark: 0 }); + const body = createBoundedResponseLogBody(source, { + json: false, inspect: text => inspected.push(text), finalize() { return; }, + }); + expect((await new Response(body).text()).length).toBe(10_000); + expect(inspected).toEqual(["x".repeat(8_192)]); + }); + + test("no downstream pull means no logging-driven upstream read", async () => { + let reads = 0; + const source = new ReadableStream({ + pull(controller) { reads += 1; controller.enqueue(new Uint8Array([120])); }, + }, { highWaterMark: 0 }); + const body = createBoundedResponseLogBody(source, { + json: false, inspect() { return; }, finalize() { return; }, + }); + await Bun.sleep(5); + expect(reads).toBe(0); + await body.cancel(); + }); + + test("diagnostic callback exceptions cannot corrupt transport or duplicate finalization", async () => { + let finals = 0; + const payload = new Uint8Array([255, 0, 128]); + const body = createBoundedResponseLogBody(new Response(payload).body!, { + json: false, + inspect() { throw new Error("fixture diagnostic exception"); }, + finalize() { finals += 1; throw new Error("fixture finalizer exception"); }, + }); + expect(new Uint8Array(await new Response(body).arrayBuffer())).toEqual(payload); + expect(finals).toBe(1); + }); + + test("cancellation wins a pending read and never inspects a valid-looking JSON prefix", async () => { + const source = controlledSource(); + const inspected: string[] = []; + const ended: string[] = []; + const body = createBoundedResponseLogBody(source.body, { + json: true, inspect: text => inspected.push(text), finalize: reason => ended.push(reason), + }); + const reader = body.getReader(); + const first = reader.read(); + source.push(encoder.encode('{"model":"not-complete"}')); + await first; + const pending = reader.read(); + await bounded(reader.cancel("fixture cancel")); + await bounded(pending); + expect(inspected).toEqual([]); + expect(ended).toEqual(["cancel"]); + expect(source.cancelReasons).toEqual(["fixture cancel"]); + }); +}); diff --git a/tests/usage/request-log-nonstream.test.ts b/tests/usage/request-log-nonstream.test.ts new file mode 100644 index 0000000000..ac2608a1ca --- /dev/null +++ b/tests/usage/request-log-nonstream.test.ts @@ -0,0 +1,110 @@ +import { describe, expect, test } from "bun:test"; +import { responseWithDeferredRequestLog } from "../../src/server/relay"; +import { MAX_RESPONSE_LOG_INSPECTION_BYTES } from "../../src/server/response-log-body"; +import type { RequestLogContext, RequestLogEntry } from "../../src/server/request-log"; + +const encoder = new TextEncoder(); +function tracked(response: Response, context?: RequestLogContext) { + const entries: RequestLogEntry[] = []; + const logCtx = context ?? { model: "requested-model", provider: "fixture-provider" }; + const result = responseWithDeferredRequestLog(response, "ocx-test-bounded-nonstream", Date.now(), logCtx, + entry => { entries.push(entry); }); + return { result, entries, logCtx }; +} +function pendingSource() { + let controller!: ReadableStreamDefaultController; + const cancellations: unknown[] = []; + const body = new ReadableStream({ + start(value) { controller = value; }, + cancel(reason) { cancellations.push(reason); }, + }, { highWaterMark: 0 }); + return { body, controller, cancellations }; +} + +describe("deferred non-stream request log integration", () => { + test("keeps original response status, statusText, headers and invalid UTF-8 bytes", async () => { + const payload = new Uint8Array([255, 0, 128, 13, 10]); + const { result, entries } = tracked(new Response(payload, { + status: 503, statusText: "Fixture Unavailable", + headers: { "content-type": "text/plain", "x-fixture": "preserved" }, + })); + expect(result.status).toBe(503); + expect(result.statusText).toBe("Fixture Unavailable"); + expect(result.headers.get("x-fixture")).toBe("preserved"); + expect(new Uint8Array(await result.arrayBuffer())).toEqual(payload); + expect(entries).toHaveLength(1); + expect(entries[0]?.status).toBe(503); + }); + + test("inspects complete small JSON using the existing metadata parser", async () => { + const payload = JSON.stringify({ model: "resolved-model", usage: { input_tokens: 3, output_tokens: 2, total_tokens: 5 } }); + const { result, entries } = tracked(new Response(payload, { headers: { "content-type": "application/json" } })); + expect(await result.text()).toBe(payload); + expect(entries).toHaveLength(1); + expect(entries[0]?.resolvedModel).toBe("resolved-model"); + expect(entries[0]?.status).toBe(200); + }); + + test("does not overwrite routed model/usage context from oversized JSON", async () => { + const payload = JSON.stringify({ model: "do-not-inspect", padding: "x".repeat(MAX_RESPONSE_LOG_INSPECTION_BYTES) }); + const { result, entries, logCtx } = tracked(new Response(payload, { headers: { "content-type": "application/json" } })); + expect(await result.text()).toBe(payload); + expect(entries).toHaveLength(1); + expect(logCtx.resolvedModel).toBeUndefined(); + expect(logCtx.model).toBe("requested-model"); + expect(logCtx.usage).toBeUndefined(); + }); + + test("non-JSON diagnostic text still uses the existing redaction/parser path", async () => { + const payload = "synthetic provider failed: " + "x".repeat(12000); + const { result, entries } = tracked(new Response(payload, { status: 502, headers: { "content-type": "text/plain" } })); + expect(await result.text()).toBe(payload); + expect(entries).toHaveLength(1); + expect(entries[0]?.upstreamError?.startsWith("synthetic provider failed:")).toBe(true); + expect(entries[0]?.upstreamError?.length).toBeLessThanOrEqual(500); + }); + + test("cancellation follows the existing 499 convention without changing wire status", async () => { + const source = pendingSource(); + const { result, entries } = tracked(new Response(source.body, { status: 200, headers: { "content-type": "application/json" } })); + const reader = result.body!.getReader(); + const pending = reader.read(); + await reader.cancel("fixture client left"); + await pending; + expect(result.status).toBe(200); + expect(entries).toHaveLength(1); + expect(entries[0]?.status).toBe(499); + expect(source.cancellations).toEqual(["fixture client left"]); + }); + + test("a read failure is logged once as 502 and rejects the consumer", async () => { + const source = pendingSource(); + const { result, entries, logCtx } = tracked(new Response(source.body, { headers: { "content-type": "application/json" } })); + const reader = result.body!.getReader(); + const first = reader.read(); + source.controller.enqueue(encoder.encode('{"model":"not-complete"}')); + await first; + const failed = reader.read(); + source.controller.error(new Error("fixture transport reset")); + await expect(failed).rejects.toThrow("fixture transport reset"); + expect(entries).toHaveLength(1); + expect(entries[0]?.status).toBe(502); + expect(logCtx.resolvedModel).toBeUndefined(); + }); + + test("a bodyless response is unaffected", () => { + const original = new Response(null, { status: 204 }); + const { result, entries } = tracked(original); + expect(result).toBe(original); + expect(entries).toHaveLength(1); + expect(entries[0]?.status).toBe(204); + }); + + test("an unrelated non-error binary response is unaffected", async () => { + const original = new Response(new Uint8Array([1, 2, 3]), { headers: { "content-type": "application/octet-stream" } }); + const { result, entries } = tracked(original); + expect(result).toBe(original); + expect(entries).toHaveLength(1); + expect(new Uint8Array(await result.arrayBuffer())).toEqual(new Uint8Array([1, 2, 3])); + }); +}); From 149f0a9b4ad541d193b93cb8676875175f15a674 Mon Sep 17 00:00:00 2001 From: luvs01 <27862058+luvs01@users.noreply.github.com> Date: Wed, 16 Sep 2026 15:44:13 +0900 Subject: [PATCH 2/2] test(logs): pin the bounded inspection tee and document the guide entry --- docs-site/astro.config.mjs | 1 + tests/responses/passthrough-abort.test.ts | 7 +- tests/server/response-log-inspection.test.ts | 86 ++++++++++++++++++++ 3 files changed, 93 insertions(+), 1 deletion(-) diff --git a/docs-site/astro.config.mjs b/docs-site/astro.config.mjs index 329deb984a..df02daf48b 100644 --- a/docs-site/astro.config.mjs +++ b/docs-site/astro.config.mjs @@ -86,6 +86,7 @@ export default defineConfig({ translations: { fr: "Guides", ko: "가이드", "zh-CN": "指南", "zh-TW": "指南", ru: "Руководства", ja: "ガイド", tr: "Kılavuzlar" }, items: [ { label: "Remote Hub Deployment", translations: { fr: "Déploiement Remote Hub", ko: "Remote Hub 배포", "zh-CN": "Remote Hub 部署", "zh-TW": "Remote Hub 部署", ru: "Развёртывание Remote Hub", ja: "Remote Hub のデプロイ", tr: "Remote Hub Dağıtımı" }, slug: "guides/remote-hub" }, + { label: "Response Inspection", slug: "guides/response-inspection" }, { label: "Remote Workspace", translations: { fr: "Espace de travail distant", ko: "원격 워크스페이스", "zh-CN": "远程工作区", "zh-TW": "遠端工作區", ru: "Удалённая рабочая область", ja: "リモートワークスペース", tr: "Uzak Çalışma Alanı" }, slug: "guides/remote-workspace" }, { label: "Providers", translations: { fr: "Fournisseurs", ko: "프로바이더", "zh-CN": "提供商", "zh-TW": "供應商", ru: "Провайдеры", ja: "プロバイダー", tr: "Sağlayıcılar" }, slug: "guides/providers" }, { label: "Factory Droid Bridge", translations: { fr: "Pont Factory Droid", ko: "Factory Droid 브리지" }, slug: "guides/factory-droid" }, diff --git a/tests/responses/passthrough-abort.test.ts b/tests/responses/passthrough-abort.test.ts index 0ce5b112ce..97eaf771b3 100644 --- a/tests/responses/passthrough-abort.test.ts +++ b/tests/responses/passthrough-abort.test.ts @@ -46,6 +46,7 @@ describe("passthrough relayWithAbort (RC2, passthrough path)", () => { const coreSource = await readSource("src/server/responses/passthrough-delivery.ts"); const relaySource = await readSource("src/server/relay.ts"); const capsSource = await readSource("src/lib/bun-stream-caps.ts"); + const inspectionTeeSource = await readSource("src/server/inspection-tee.ts"); const sseBranch = coreSource.slice( coreSource.indexOf("if (isEventStream && upstreamResponse.body)"), coreSource.indexOf("const body = relayWithAbort(upstreamResponse.body, upstream);"), @@ -61,7 +62,11 @@ describe("passthrough relayWithAbort (RC2, passthrough path)", () => { expect(sseBranch).toContain("const terminalRepairPolicy = providerModelResponsesTerminalRepair("); expect(sseBranch).toContain("const passthroughSseBody = terminalRepairPolicy"); expect(sseBranch).toContain(": upstreamResponse.body;"); - expect(sseBranch).toContain("passthroughSseBody.tee()"); + // Native tee stays inside the bounded observer. The production owner passes + // the raw stream and disconnect signal before any client-side rewrite. + expect(sseBranch).toMatch(/const \[nativeBody, inspectBody\] = teeWithBoundedInspection\(passthroughSseBody, \{ clientGoneSignal \}\)/); + expect(inspectionTeeSource).toContain("const [client, inspection] = source.tee();"); + expect(sseBranch.indexOf("teeWithBoundedInspection(")).toBeLessThan(sseBranch.indexOf("const rewrittenBody =")); // Rewrite traffic is derived from the finalized block chain so every // provider-specific transform participates in the platform gate. expect(sseBranch).toContain("const repairConfig = route.provider.responsesItemIdRepair;"); diff --git a/tests/server/response-log-inspection.test.ts b/tests/server/response-log-inspection.test.ts index f2bd6ff18f..35ab799bce 100644 --- a/tests/server/response-log-inspection.test.ts +++ b/tests/server/response-log-inspection.test.ts @@ -43,6 +43,7 @@ function controlledSource() { cancel(reason) { cancelReasons.push(reason); }, }, { highWaterMark: 0 }), push(bytes: Uint8Array) { controller.enqueue(bytes); }, + close() { controller.close(); }, error(reason: unknown) { controller.error(reason); }, cancelReasons, }; @@ -294,6 +295,91 @@ describe("inspection pacing boundary", () => { }); describe("non-stream inspection boundary", () => { + test.each(["eof", "read_error", "cancel", "cancel_rejected"] as const)("releases its source reader after %s", async outcome => { + let controller!: ReadableStreamDefaultController; + const source = new ReadableStream({ + start(value) { controller = value; }, + cancel() { if (outcome === "cancel_rejected") return Promise.reject(new Error("fixture cancel rejection")); }, + }, { highWaterMark: 0 }); + const ended: string[] = []; + const reader = createBoundedResponseLogBody(source, { + json: false, inspect() {}, finalize: reason => ended.push(reason), + }).getReader(); + const pending = reader.read(); + if (outcome === "eof") { controller.close(); await bounded(pending); } + else if (outcome === "read_error") { + const failure = new Error("fixture reader failure"); + controller.error(failure); + await expect(pending).rejects.toBe(failure); + } else { await bounded(reader.cancel("fixture cancellation")); await bounded(pending); } + expect(source.locked).toBe(false); + expect(ended).toEqual([outcome === "cancel_rejected" ? "cancel" : outcome]); + }); + + test("a bounded body can cancel one native tee branch without waiting for or truncating its sibling", async () => { + const source = controlledSource(); + const [left, right] = source.body.tee(); + const ended: string[] = []; + const reader = createBoundedResponseLogBody(left, { + json: false, inspect() {}, finalize: reason => ended.push(reason), + }).getReader(); + const sibling = right.getReader(); + const first = reader.read(), siblingFirst = sibling.read(); + source.push(encoder.encode("first")); + await bounded(Promise.all([first, siblingFirst])); + await bounded(reader.cancel("inspection finished")); + expect(left.locked).toBe(false); + expect(ended).toEqual(["cancel"]); + expect(source.cancelReasons).toEqual([]); + const next = sibling.read(); + source.push(encoder.encode("second")); + expect((await bounded(next)).value).toEqual(encoder.encode("second")); + source.close(); + expect((await bounded(sibling.read())).done).toBe(true); + sibling.releaseLock(); + }); + + test("diagnostic bytes do not alias mutable chunks delivered to the client", async () => { + const source = controlledSource(); + const inspected: string[] = []; + const reader = createBoundedResponseLogBody(source.body, { + json: false, inspect: text => inspected.push(text), finalize() {}, + }).getReader(); + const original = encoder.encode("original"); + const pending = reader.read(); + source.push(original); + await bounded(pending); + original.fill(120); + source.close(); + await bounded(reader.read()); + expect(inspected).toEqual(["original"]); + }); + + test("multibyte error inspection ends at the byte prefix while delivery remains whole", async () => { + const payload = "한".repeat(10_000); + const inspected: string[] = []; + const body = createBoundedResponseLogBody(new Response(payload).body!, { + json: false, inspect: text => inspected.push(text), finalize() {}, + }); + expect(await new Response(body).text()).toBe(payload); + expect(inspected).toEqual([new TextDecoder().decode(encoder.encode(payload).subarray(0, 8_192))]); + }); + + test("cancel wins a racing source error without finalizing twice", async () => { + const source = controlledSource(); + const ended: string[] = []; + const reader = createBoundedResponseLogBody(source.body, { + json: true, inspect() { throw new Error("partial JSON must not be inspected"); }, finalize: reason => ended.push(reason), + }).getReader(); + const pending = reader.read(); + await Promise.resolve(); + source.error(new Error("fixture source failure")); + await bounded(reader.cancel("fixture cancellation")); + await bounded(pending); + expect(ended).toEqual(["cancel"]); + expect(source.body.locked).toBe(false); + }); + test("JSON over its inspection allowance is delivered intact but never inspected", async () => { const inspected: string[] = []; const ended: string[] = [];