Surface stream failures instead of truncating the answer

[neo-sky]

Summary

• log request_id, duration and a safe error detail on every stream failure
• carry request_id on the remaining stream outcomes and join chat_id to it
• report only a status for upstream HTTP failures, since the SSE parser copies error.message verbatim and it can echo customer input
• fail a stream that produces nothing for its idle budget with a typed timeout that ends the stream

Covers the P0 logging and P1 watchdog in #982.

Rollout

STREAM_WATCHDOG_ENABLED defaults to false, so merging changes no streaming
behaviour until an operator sets it; the logging and redaction are always on.
The 300s and 90s bounds come from partner data measuring total stream duration
rather than inter-token gaps, so they want a look before it is enabled.
Rollback is unsetting the variable.

CompletionError(String) is bounded rather than fully redacted, because most
sites wrap our own text but the Anthropic adapter passes a provider message
through and the two cannot be told apart at runtime.

Verification

• cargo fmt --all -- --check
• cargo clippy --all-targets --all-features -- -D warnings
• cargo test --lib --bins (1463 passed)
• cargo test --test e2e_all (714 passed)

The three database_encryption e2e failures arrived with #968, use fixed
fixture ids on the shared test database, and pass when run serially.

[ironloopai]

Review · Status

🟩 Completed

IronLoop completed the review and posted it to GitHub.

Result

Open submitted review →

Run details

• Run: 9c2a7450-fd01-41f2-b063-c11bfaa54e44
• Base: main at 07798f8
• Head: fix/stream-failure-logging at f926083
• Created: 2026-09-02 17:17 UTC
• Updated: 2026-09-02 17:23 UTC

_{Automatic trigger · attempt 1 of 3 · completed in 5m 41s}

[ironloopai]

Review · Summary

Found four issues in the watchdog and stream-failure logging paths.

Findings: 🔴 High 1 · 🟠 Medium 3

_{Code-specific findings are attached to the diff.}

Validation

• ✅ Patch hygiene — No whitespace errors were found in the proposed change.

Review details

• Run: 9c2a7450-fd01-41f2-b063-c11bfaa54e44
• Attempts: 1

[ironloopai]

🔴 High · Redact arbitrary upstream error text before logging

This sanitizer only removes HTTP(S) URLs and IPv4 addresses. An upstream SSE error frame can carry arbitrary provider-supplied text, including echoed customer input, and the parser preserves that text in CompletionError::HttpError; it will therefore reach the newly added error logs unchanged. Log an allowlisted error category or fully redact provider-supplied message bodies.

[ironloopai]

🟠 Medium · Arm the first-token timeout before provider stream peeking

The interceptor is constructed only after chat_completion_stream_with_attribution returns, but that path awaits the first stream item while peeking for a chat ID (and the NearAI provider also peeks). If the upstream has sent HTTP headers but never sends its first SSE event, this call waits indefinitely and the configured first-token watchdog is never armed. Apply the deadline around the pre-peek path or wrap the stream before any peeking.

[ironloopai]

🟠 Medium · Terminate the stream after synthesizing a timeout

Returning the timeout error leaves the interceptor in Streaming. The routes convert an error to an SSE frame and continue polling, so a permanently pending upstream is re-armed and emits another timeout every budget instead of reaching EOF and [DONE]. The underlying request and its concurrent-request slot remain live until the client disconnects. Transition to a terminal state when emitting this synthetic timeout.

[ironloopai]

🟠 Medium · Include duration for failures after usage has arrived

This added route log has the request ID and error detail but no duration. NearAI requests continuous usage stats, so after its first chunk both usage and chat ID are set; a later provider error follows the billing branch in record_usage_and_metrics, which does not emit either of the new interruption logs. Those common partial-stream failures therefore cannot be correlated with total stream duration. Emit the failure fields whenever last_error is present, before branching on usage, or add duration here.

[lloydmak99]

Surfaces stream failures instead of silently truncating: adds sanitized error logging (always-on) plus an idle-timeout watchdog gated behind STREAM_WATCHDOG_ENABLED, which defaults off. The only always-on behavior change is the extra logging; the watchdog is inert at runtime until enabled, so this is safe to merge. A few things worth addressing before the watchdog is switched on:

• crates/services/src/completions/mod.rs:627 — after a synthesized timeout the stream stays in Streaming and re-arms, so it re-emits a timeout every budget rather than terminating (route at crates/api/src/routes/completions.rs:1851 maps the Err to an SSE frame and keeps polling). Transition to a terminal state after the one timeout. Non-blocking (watchdog off by default).
• crates/services/src/completions/mod.rs:528-530 — non-token passthrough frames (keepalives/pings) return without resetting the idle timer, so a keepalive-only stream could be falsely timed out once the watchdog is enabled. Non-blocking.
• crates/api/src/routes/completions.rs:323 — sanitize_error_message only strips URLs/IPv4, so other echoed provider text still reaches logs; consider logging an allowlisted category/safe fields rather than raw error text. Non-blocking; consistent with the existing privacy approach.

Checks: cargo fmt --all -- --check passed. Could not run cargo check/tests here (no C linker in the sandbox); verified statically that config field wiring, CompletionError::Timeout fields, visibility changes, and all ApiConfig construction sites are correct. Author reports clippy clean and 1411 lib + 703 e2e tests passing.

[lloydmak99]

The watchdog logic is sound and, critically, gated off by default (STREAM_WATCHDOG_ENABLED=false), so merging changes no production streaming behavior until an operator opts in. Timer arming/re-arming is correct (a delivered token disarms and the next Pending re-arms with a fresh deadline), the emitted CompletionError::Timeout is an existing variant already handled by the route's error categorizer, and the new logging fields are IDs/numerics with provider error text routed through the existing sanitize_error_message.

Optional, non-blocking follow-ups:

• crates/services/src/completions/mod.rs:528 — SSE control/keepalive events (event.chunk.is_none()) return early without clearing idle_armed, so a prefill that emits only keepalives can still hit the first-token timeout despite being alive. Appears intentional (wall-clock idle measures token progress, not connection liveness) and is behind the disabled flag — just confirm this matches intent before enabling.
• crates/services/src/completions/mod.rs:197 — error_detail logs sanitized provider error text, which only strips URLs/IPs; non-URL customer content in an upstream error string could reach a warn log. Consistent with existing SSE-frame handling, not a regression; tighten the allowlist only if desired.

Note the PR currently has merge conflicts and needs a rebase before merging.

Checks run locally: cargo fmt --check and git diff --check clean; cargo check (offline) passes for config, services, and api; cargo test -p config -- stream_watchdog (4 passed, covering zero/>3600/bound-ordering validation); cargo test -p services -- completions passes including the stalled-stream, slow-prefill, unwatched-stream, and interrupted-stream/redaction tests. Clippy passed; full integration/e2e suites not run (require DB/vLLM).

[neo-sky]

Pushed fixes for all of these, plus the keepalive one from the review.

• http errors log the status only now, the SSE parser copies the upstream message verbatim so it can carry customer text
• the synthesized timeout ends the stream instead of re-arming
• deadlined the provider call, the chat_id peek happens before the interceptor exists so nothing was watching that window
• failures that reach the billing branch carry duration now
• keepalives clear the idle timer

Two I left alone. The provider deadline has no unit test, it needs the pool mocked. And CompletionError(String) is capped rather than fully redacted, most sites wrap our own text but the anthropic adapter passes the provider's through and you can't tell them apart at runtime.

Also merged main in, the only conflict was the chat_id peek that #952 restructured.

[lloydmak99]

Re-review of the delta since my approval at f926083 (commits 6f9f86b and the merge of main). The logging/redaction changes and the bot-review fixes look right, but the watchdog has three problems that only show up once STREAM_WATCHDOG_ENABLED=true, which is the whole point of the feature. Off by default so merge is safe, but these should land before anyone flips the flag.

1. In-stream provider error leaves a stale idle deadline — crates/services/src/completions/mod.rs ~L602
The Poll::Ready(Some(Err)) arm does not clear idle_armed or reset the timer. The route keeps polling after an error, so on the next Pending the re-arm at if !self.idle_armed is skipped and the old deadline (measured from the last token, not from the error) is polled. If it has elapsed, a synthetic Timeout is returned immediately: last_error is overwritten (the usage stop_reason misreports the real upstream error), the client gets a second data: {error} frame, and the stream goes Done without Finalizing. Clear idle_armed in the Err arm (or just reset the sleep there).

2. Watchdog timeout skips Finalizing, so pinned chat_ids leak — same file ~L642
state = Done on timeout means create_signature_future never runs. In provider-signature mode that path (attestation/chat_signatures.rs:137) is the only place unpin_chat_connection(chat_id) is called; Drop doesn't unpin. Every watchdog-terminated index-routed stream leaves a permanent entry in the nearai fleet signature_rotation map, which has no bound and is not cleared by store_backend_count. Pre-PR the Err arm stayed in Streaming and the inner Ready(None) still ran Finalizing. Either route the timeout through Finalizing (skip the signature fetch but keep the unpin) or unpin explicitly on the timeout path.

3. Outer first-token deadline caps the whole pool call and starves fallback — same file ~L1737
tokio::time::timeout(first_token, provider_call) wraps provider selection, attestation, every provider attempt and the backoff rounds, and its clock starts before the nearai TTFB guard's. With defaults (STREAM_WATCHDOG_FIRST_TOKEN_SECONDS=300 == DEFAULT_CONTROL_TIMEOUT_SECS=300) the outer deadline always fires first, so on a TTFB stall the pool's retry loop is dropped mid-send and the fallback provider is never tried; the client gets a 504 "prefill" that would previously have been served by fallback. Config validation doesn't cross-check the two knobs. Suggest either a per-attempt deadline inside the pool, or requiring first_token > control_timeout * attempts + backoff at config load.

Smaller, non-blocking:

• Keepalive comments clear both budgets (idle_armed = false before the chunk.is_none() check), so the watchdog detects a byte-silent upstream, not a token-silent one. Deliberate per the test, and no fleet hop emits mid-stream comments today, but the truncation RCA explicitly warns heartbeats would mask this. Worth a comment at minimum.
• Because the pool peek buffers the first data chunk before InterceptStream exists, the interceptor's prefill branch is only reachable with >32 leading control events; a_slow_prefill_is_not_mistaken_for_a_stall tests a dead path and the real first-token bound (the outer wrapper) has no test.
• Each mid-stream failure is logged twice with identical fields (route Completion stream error + Drop Stream failed), and sanitize_error_message compiles three regexes per call. Cache them in OnceLock like FETCH_STATUS and log once.
• The CompletionError(String) 200-char bound leaving Anthropic upstream text in logs is acknowledged in the description; fine as a documented residual.