Files
OmniRoute/open-sse/utils/earlyStreamKeepalive.ts
Markus Hartung c545855b26 fix(logging): capture early-keepalive bytes in the call-log artifact (#10331)
Diagnosed while chasing the reused-output-index incident (see
705ac7335 / OpenClaw issue #123342): every call-log artifact showed a
wire-clean response, even for requests that actually failed, because
withEarlyStreamKeepalive injects its startup/keepalive/error frames
directly into the outer response stream, entirely outside the request
handler's own reqLogger. reqLogger.appendConvertedChunk (which
populates pipeline.streamChunks.client) never sees those bytes — only
what chatCore.ts's own SSE writer produced. The persisted artifact was
answering "what did the handler generate," not "what did the client
actually receive," which is the wrong question when diagnosing a
client-visible stream defect.

withEarlyStreamKeepalive wraps the handler's Promise from OUTSIDE its
call tree; the reqLogger it needs to feed is created deep inside
chatCore.ts, after routing/model/provider resolution, and doesn't
exist yet when the keepalive frames are written. The two sides share
no reference — only an identifier, if one is deliberately threaded
through both.

Fix: responses/route.ts now generates a correlationId before calling
handleChat, passes it as handleChat's existing (already-supported,
previously-unused-here) 4th positional arg — which chatCore.ts already
threads into trackPendingRequest's metadata as entry.correlationId,
zero changes needed there — and also into
withEarlyStreamKeepalive's options. The wrapper buffers every direct-
to-client write (startup frame, periodic ticks, in-band error frames)
via the new earlyKeepaliveByteBuffer module, keyed by that same id.
chatCore/attemptLogging.ts, which already has correlationId in scope
right where it assembles the final pipeline payload before saveCallLog,
takes the buffered bytes and prepends them into streamChunks.client in
send order. The verbatim-forwarded real response body is deliberately
NOT re-recorded here — the handler's own reqLogger already captures
that; recording it twice would duplicate it in the artifact.

The buffer is consumed exactly once per correlationId and swept on a
10-minute TTL so a request that never reaches the persist call
(aborted, detailed logging disabled, a route that doesn't opt in)
cannot leak entries forever.

Scoped to /v1/responses only, where the incident actually happened.
/v1/chat/completions and /v1/messages call withEarlyStreamKeepalive the
same way and would need the identical two-line route change to opt in;
left as a follow-up rather than bundled in sight-unseen.

Test plan:
- tests/unit/early-keepalive-byte-buffer.test.ts (new): record/take
  ordering, single-consumption, per-id isolation, empty-input no-ops,
  unbounded-growth cap
- tests/unit/early-stream-keepalive.test.ts: two new tests — a
  correlationId records the startup frame and keepalive ticks but NOT
  the forwarded body; omitting correlationId is a true no-op
- tests/unit/attempt-logging-early-keepalive-merge.test.ts (new): real
  temp-DB end-to-end proof against the actual persisted call-log row —
  early bytes prepended in send order, consumed exactly once, no-op
  without a correlationId, gated by detailedLoggingEnabled matching the
  existing streamChunks capture gate
- tests/unit/chatcore-attempt-logging.test.ts (existing): unchanged,
  still passing — confirms the merge addition doesn't disturb existing
  persistence behavior
- 44 passed total across the above plus earlyStreamKeepalive.test.ts,
  2 pre-existing skips unrelated to this change
- tsgo --noEmit: clean on all touched files
2026-08-18 10:57:31 -03:00

439 lines
20 KiB
TypeScript

/**
* @file earlyStreamKeepalive.ts
* @description Early SSE keepalive wrapper so short idle-read clients stay connected
* while the handler waits on upstream first-byte (reasoning models, combo failover).
*
* @changes
* - [2026-07-28] [Cursor Grok 4.5] - Scrub omniroute from client-facing keepalive id/model/comment frames
* - [2026-07-28] [Cursor Grok 4.5] - Neutralize Responses startup thinking text (no OmniRoute brand leak)
*
* Strict HTTP clients (notably Codex CLI's `reqwest`, which has a ~5s idle-read
* timeout) drop the connection if no bytes arrive shortly after the request.
* The proxy holds the streaming response until `ensureStreamReadiness` observes
* the upstream's first useful byte — which can exceed 5s for reasoning models
* that "think" before emitting any token (#2544). `curl` has no such idle
* timeout, so it was never affected, which is why the bug looked client-specific.
*
* This wrapper keeps the connection warm without disturbing the handler's
* internal logic (combo failover, stream readiness, account cooldown all still
* run inside the handler before it resolves):
*
* - Fast path: if the handler resolves within `thresholdMs`, its `Response`
* is returned verbatim — identical status, headers, and body. There is zero
* behavior change for normal latency, so metadata headers and non-200 error
* statuses are fully preserved for the common case.
*
* - Slow path: if the handler is still pending after `thresholdMs`, a 200
* `text/event-stream` response is opened immediately and SSE comment
* heartbeats are emitted every `intervalMs` until the handler resolves; its
* body is then forwarded. If the handler ultimately fails, a structured
* `event: error` frame is emitted in-band (the response is already committed
* to 200, so the HTTP status can no longer change).
*/
import { ResponsesOutputIndexStack } from "./responsesOutputIndexStack.ts";
import { recordEarlyKeepaliveBytes } from "./earlyKeepaliveByteBuffer.ts";
const ENCODER = new TextEncoder();
const KEEPALIVE_FRAME = ENCODER.encode(": keepalive\n\n");
// OpenAI-compatible keepalive: a syntactically valid empty streaming chunk.
// Some OpenAI-compatible clients parse every non-empty SSE line as JSON and
// reject legal SSE comments before their first provider chunk arrives.
// id/model stay brand-neutral — these frames go to the client, not upstream.
export const OPENAI_KEEPALIVE_FRAME = ENCODER.encode(
'data: {"id":"chatcmpl-keepalive","object":"chat.completion.chunk","created":0,"model":"keepalive","choices":[{"index":0,"delta":{},"finish_reason":null}]}\n\n'
);
// The first slow-path frame must be a valid OpenAI chunk without creating
// visible reasoning that clients persist into the conversation.
export const OPENAI_STARTUP_FRAME = OPENAI_KEEPALIVE_FRAME;
// Anthropic Messages-format keepalive: a REAL `ping` SSE event, not a comment.
// Anthropic clients (Claude Code, the Anthropic SDK) reset their stream/first-token
// watchdog on real SSE events but ignore SSE comments (`: ...`), so on a slow first
// token the comment frame lets the client abort and retry the stream. Anthropic's own
// API emits `event: ping` for exactly this reason; the /v1/messages route mirrors it.
export const ANTHROPIC_PING_FRAME = ENCODER.encode('event: ping\ndata: {"type":"ping"}\n\n');
// Responses API keepalive: a self-contained, self-closed synthetic reasoning
// item (added -> summary_part.added -> text.delta -> summary_part.done ->
// output_item.done). Unlike open-sse/utils/stream.ts's own
// emitSyntheticResponsesReasoningSummary — which only supplements a REAL
// upstream item that the real provider stream will close on its own — this
// placeholder item has no real counterpart: the upstream response, once it
// arrives, starts its own independent response.created lifecycle from
// scratch and will never close this one. It must therefore send its own
// response.output_item.done here, not just reasoning_summary_part.done
// (that only closes the nested summary part, not the output item itself).
// Without it, a strict client tracking open items by output_index (as the
// Responses API spec requires) sees this item still open at index 0 and
// throws a collision the moment the real response's own output_item.added
// reuses that same index — reproduced live 2026-08-13, OpenClaw issue
// https://github.com/openclaw/openclaw/issues/123342.
//
// The output_index is allocated from ResponsesOutputIndexStack instead of a
// hardcoded literal so this stays structurally correct: forgetting the
// close() call throws at module load (assertAllClosed() below), not
// silently at some future real request.
const RESPONSES_STARTUP_ITEM_ID = "rs_keepalive";
// Brand-neutral placeholder — clients persist this as visible reasoning.
const STARTUP_THINKING_TEXT = "✨";
const startupIndexStack = new ResponsesOutputIndexStack();
const RESPONSES_STARTUP_OUTPUT_INDEX = startupIndexStack.open();
const startupEvents = [
{
event: "response.output_item.added",
data: {
type: "response.output_item.added",
output_index: RESPONSES_STARTUP_OUTPUT_INDEX,
item: { id: RESPONSES_STARTUP_ITEM_ID, type: "reasoning", summary: [] },
},
},
{
event: "response.reasoning_summary_part.added",
data: {
type: "response.reasoning_summary_part.added",
item_id: RESPONSES_STARTUP_ITEM_ID,
output_index: RESPONSES_STARTUP_OUTPUT_INDEX,
summary_index: 0,
part: { type: "summary_text", text: "" },
},
},
{
event: "response.reasoning_summary_text.delta",
data: {
type: "response.reasoning_summary_text.delta",
item_id: RESPONSES_STARTUP_ITEM_ID,
output_index: RESPONSES_STARTUP_OUTPUT_INDEX,
summary_index: 0,
delta: STARTUP_THINKING_TEXT,
},
},
{
event: "response.reasoning_summary_part.done",
data: {
type: "response.reasoning_summary_part.done",
item_id: RESPONSES_STARTUP_ITEM_ID,
output_index: RESPONSES_STARTUP_OUTPUT_INDEX,
summary_index: 0,
part: { type: "summary_text", text: STARTUP_THINKING_TEXT },
},
},
];
// close() runs before the output_item.done event is built (not just before
// it's appended) so assertAllClosed() below is a real check, not scaffolding
// that always trivially passes.
startupIndexStack.close(RESPONSES_STARTUP_OUTPUT_INDEX);
startupEvents.push({
event: "response.output_item.done",
data: {
type: "response.output_item.done",
output_index: RESPONSES_STARTUP_OUTPUT_INDEX,
item: {
id: RESPONSES_STARTUP_ITEM_ID,
type: "reasoning",
summary: [{ type: "summary_text", text: STARTUP_THINKING_TEXT }],
},
},
});
startupIndexStack.assertAllClosed();
export const RESPONSES_STARTUP_THINKING_FRAME = ENCODER.encode(
startupEvents.map((e) => `event: ${e.event}\ndata: ${JSON.stringify(e.data)}\n\n`).join("")
);
// Anthropic Messages API default — Anthropic's own spec really does use a named
// `event: error` SSE frame, so this is correct there. It is WRONG for the OpenAI-
// format routes below: Chat Completions and Responses streaming never use the SSE
// `event:` field at all, only bare `data: {...}` lines — a naive line-based parser
// (the kind most OpenAI-compatible clients use, not a full EventSource) can silently
// drop an unrecognized `event:` line and/or desync on the `data:` line that follows,
// so this error would never surface to the client at all (log ids
// 1784465227489-a2cbc0 / 1784457764961-73 territory: a client that gives up with no
// visible reason). See OPENAI_CHAT_ERROR_FRAME / OPENAI_RESPONSES_ERROR_FRAME below
// for the per-format-correct alternatives.
const ERROR_FRAME = ENCODER.encode(
`event: error\ndata: ${JSON.stringify({
error: { message: "Upstream stream failed before completion.", type: "stream_error" },
})}\n\n`
);
// Chat Completions convention: a plain `data:` line, no `event:` field. This
// matches what the openai-node SDK's stream iterator actually checks for — it
// inspects each parsed chunk for a top-level `error` key regardless of any SSE
// event name (there isn't one to check, since real OpenAI chat completions
// streams never send `event:` lines).
export const OPENAI_CHAT_ERROR_FRAME = ENCODER.encode(
`data: ${JSON.stringify({
error: { message: "Upstream stream failed before completion.", type: "stream_error" },
})}\n\n`
);
// Responses API convention: also a plain `data:` line, but the discriminator is
// the `type` field INSIDE the JSON payload (matching every other Responses API
// event — response.output_text.delta, response.completed, etc.), not an SSE
// `event:` field.
export const OPENAI_RESPONSES_ERROR_FRAME = ENCODER.encode(
`data: ${JSON.stringify({
type: "error",
code: null,
message: "Upstream stream failed before completion.",
param: null,
})}\n\n`
);
export type EarlyStreamKeepaliveOptions = {
/** Wait this long for the handler before committing to a keepalive stream. */
thresholdMs?: number;
/** Keepalive cadence once committed (must stay under the client idle timeout). */
intervalMs?: number;
/** Client request signal — propagated so a client disconnect cancels the upstream read. */
signal?: AbortSignal | null;
/**
* Frame emitted on each keepalive tick. Defaults to an SSE comment
* (`: keepalive`). Anthropic-format routes (/v1/messages) must pass
* `ANTHROPIC_PING_FRAME` instead, because Anthropic clients ignore SSE comments
* for their stream watchdog and only a real `event: ping` keeps them from aborting.
*/
keepaliveFrame?: Uint8Array;
/**
* Frame emitted ONCE, immediately, as the very first byte of the slow path —
* before the recurring `keepaliveFrame` ticks start. Defaults to
* `keepaliveFrame` when omitted (today's behavior, unchanged). Pass a
* content-bearing frame (e.g. `OPENAI_STARTUP_THINKING_FRAME`) so the client
* sees visible progress instead of an empty/no-op keepalive on the first byte.
*/
startupFrame?: Uint8Array;
/** Extra headers to include in the keepalive response (e.g. X-Correlation-Id). */
extraHeaders?: Record<string, string>;
/**
* Frame emitted if the handler ultimately fails (or the upstream stream dies
* mid-flight with zero bytes forwarded) after the slow path has already
* committed to HTTP 200. Defaults to the Anthropic-style `event: error` frame
* (correct for /v1/messages). OpenAI-format routes (/v1/chat/completions,
* /v1/responses) MUST pass OPENAI_CHAT_ERROR_FRAME / OPENAI_RESPONSES_ERROR_FRAME
* instead — see the doc comment on the default ERROR_FRAME above for why.
*/
errorFrame?: Uint8Array;
/**
* Request correlation id, threaded from the route's own handleChat(...,
* correlationId) call. When set, every byte this wrapper writes to the
* client directly (startup frame, periodic keepalive ticks, and any
* in-band error frame) — everything except the verbatim-forwarded real
* response body, which the handler's own reqLogger already captures — is
* recorded via earlyKeepaliveByteBuffer and merged into this same
* request's call-log streamChunks.client by
* chatCore/attemptLogging.ts, so the persisted artifact reflects what
* actually went out on the wire instead of only what the inner handler
* produced. Omit to leave today's behavior unchanged (no recording).
*/
correlationId?: string;
};
/**
* Tagged with a string rather than an `ok: true | false` boolean: this workspace compiles
* with `strictNullChecks: false`, where a boolean-literal discriminant narrows the positive
* branch but not the negative one — so reading `.error` off the rejected arm did not
* type-check. A string discriminant narrows both branches under the same settings.
*/
type SettledHandler =
{ status: "fulfilled"; response: Response } | { status: "rejected"; error: unknown };
export async function withEarlyStreamKeepalive(
handlerPromise: Promise<Response>,
options: EarlyStreamKeepaliveOptions = {}
): Promise<Response> {
const thresholdMs = Math.max(0, options.thresholdMs ?? 2_000);
const intervalMs = Math.max(250, options.intervalMs ?? 2_500);
const signal = options.signal ?? null;
const keepaliveFrame = options.keepaliveFrame ?? KEEPALIVE_FRAME;
const startupFrame = options.startupFrame ?? keepaliveFrame;
const extraHeaders = options.extraHeaders ?? {};
const errorFrame = options.errorFrame ?? ERROR_FRAME;
// Single source of truth for whether THIS route's error framing uses a named SSE
// `event: error` line (Anthropic) or a plain `data:` line (OpenAI Chat Completions /
// Responses) — derived from errorFrame itself so the dynamic real-upstream-body case
// below stays consistent with the static default-message case without a second option.
const errorFrameUsesNamedEvent = new TextDecoder().decode(errorFrame).startsWith("event:");
const correlationId = options.correlationId;
const frameDecoder = correlationId ? new TextDecoder() : null;
// Records every direct-to-client write EXCEPT the forwarded real response
// body — that one is already captured by the handler's own reqLogger, so
// recording it again here would duplicate it in the persisted artifact.
const recordClientBytes = (chunk: Uint8Array): void => {
if (!correlationId || !frameDecoder) return;
recordEarlyKeepaliveBytes(correlationId, frameDecoder.decode(chunk));
};
// Settle into a tagged result so neither race branch leaves an unhandled
// rejection when the threshold timer wins.
const settled: Promise<SettledHandler> = handlerPromise.then(
(response) => ({ status: "fulfilled" as const, response }),
(error) => ({ status: "rejected" as const, error })
);
let timer: ReturnType<typeof setTimeout> | undefined;
const raced = await Promise.race([
settled.then((result) => ({ kind: "settled" as const, result })),
new Promise<{ kind: "timeout" }>((resolve) => {
timer = setTimeout(() => resolve({ kind: "timeout" }), thresholdMs);
}),
]);
if (timer) clearTimeout(timer);
if (raced.kind === "settled") {
// Fast path — return verbatim, or rethrow so the route's normal error handling runs.
const result = raced.result;
if (result.status === "fulfilled") return result.response;
throw result.error;
}
// Slow path — open the SSE stream now and keep it warm until the handler resolves.
// Cleanup state is hoisted so both start() and cancel() (client disconnect) can stop
// the keepalive loop and cancel the upstream read.
let stopKeepalive = () => {};
let upstreamReader: ReadableStreamDefaultReader<Uint8Array> | null = null;
let aborted = false;
const stream = new ReadableStream<Uint8Array>({
async start(controller) {
let stopped = false;
const interval = setInterval(() => {
if (stopped) return;
try {
controller.enqueue(keepaliveFrame);
recordClientBytes(keepaliveFrame);
} catch {
stopped = true;
clearInterval(interval);
}
}, intervalMs);
if (interval && typeof interval === "object" && "unref" in interval) {
interval.unref?.();
}
// First frame immediately on commit so the client sees a byte right away.
// Use `startupFrame` (e.g. OPENAI_STARTUP_THINKING_FRAME / ANTHROPIC_PING_FRAME)
// — an SSE comment here would be ignored by Anthropic clients' watchdog on a
// sub-interval gap, defeating the keepalive for exactly the case it targets.
try {
controller.enqueue(startupFrame);
recordClientBytes(startupFrame);
} catch {
/* consumer already gone */
}
stopKeepalive = () => {
stopped = true;
clearInterval(interval);
};
const onAbort = () => {
if (aborted) return;
aborted = true;
stopKeepalive();
upstreamReader?.cancel().catch(() => {});
try {
controller.close();
} catch {
/* already closed */
}
};
signal?.addEventListener("abort", onAbort, { once: true });
// addEventListener does not replay an abort that happened before registration.
// Checking after registration closes that gap without missing a concurrent abort.
if (signal?.aborted) onAbort();
try {
const result = await settled;
stopKeepalive();
if (aborted) {
// The synthetic keepalive response can be cancelled before the handler resolves.
// Cancel the eventual real response so its upstream work and lifecycle hooks finish.
if (result.status === "fulfilled" && result.response.body) {
await result.response.body.cancel().catch(() => undefined);
}
return;
}
if (result.status === "rejected") {
// Handler rejected — emit a generic error frame (never the raw error/stack).
controller.enqueue(errorFrame);
recordClientBytes(errorFrame);
} else {
const response = result.response;
const contentType = (response.headers.get("content-type") || "").toLowerCase();
const isSse = contentType.includes("text/event-stream");
if (response.body && isSse) {
// Real SSE stream — forward it verbatim.
upstreamReader = response.body.getReader();
let bytesForwarded = 0;
try {
while (true) {
const { done, value } = await upstreamReader.read();
if (done) break;
if (value) {
controller.enqueue(value);
bytesForwarded += value.byteLength;
}
}
} catch (readErr) {
// Upstream stream failed mid-flight. Only emit an error frame if
// NO content was forwarded yet — otherwise the client already
// received partial content and a late error frame would corrupt
// the SSE stream. Silently close instead; the client will see
// the stream end naturally.
if (bytesForwarded === 0) {
controller.enqueue(errorFrame);
recordClientBytes(errorFrame);
}
}
} else {
// Non-SSE response (e.g. a JSON error) reached us after we already
// committed to a 200 event-stream, so the HTTP status can no longer
// change. Frame the (already-sanitized) body as an in-band error event
// instead of forwarding raw JSON, which would be malformed SSE.
const text = response.body ? await response.text().catch(() => "") : "";
const dataLine =
text.trim() ||
JSON.stringify({ error: { message: "stream_error", type: "stream_error" } });
const framed = errorFrameUsesNamedEvent
? `event: error\ndata: ${dataLine}\n\n`
: `data: ${dataLine}\n\n`;
const framedBytes = ENCODER.encode(framed);
controller.enqueue(framedBytes);
recordClientBytes(framedBytes);
}
}
} catch {
// Defensive: never surface a raw error/stack to the client.
if (!aborted) {
try {
controller.enqueue(errorFrame);
recordClientBytes(errorFrame);
} catch {
/* consumer gone */
}
}
} finally {
stopKeepalive();
signal?.removeEventListener("abort", onAbort);
try {
controller.close();
} catch {
/* already closed */
}
}
},
cancel() {
// Consumer (Next.js → client) went away — stop keepalives and release the upstream.
aborted = true;
stopKeepalive();
upstreamReader?.cancel().catch(() => {});
},
});
return new Response(stream, {
status: 200,
headers: {
"Content-Type": "text/event-stream; charset=utf-8",
"Cache-Control": "no-cache, no-transform",
Connection: "keep-alive",
...extraHeaders,
},
});
}