diff --git a/.claude/skills/investigate-issue/SKILL.md b/.claude/skills/investigate-issue/SKILL.md index 49c1e231263..8d19cd2d7cc 100644 --- a/.claude/skills/investigate-issue/SKILL.md +++ b/.claude/skills/investigate-issue/SKILL.md @@ -761,8 +761,62 @@ Once all approved changes are applied: make run-e2e FLOW= ``` -2. Report results to the user, including the red-then-green transcript/summary for Bug issues (what failed before, what passes now) -3. If tests fail, investigate and propose fixes (with approval) +2. Run the provider harness (mandatory for every non-exempt wire-visible change, always scoped; + the exemptions are AGENTS.md's: no wire-visible effect, or behaviour no HTTP request can + reach, and an exempt change must say so in the report). It is a paid live sweep + against real provider accounts: the unfiltered collection is ~1,900 requests. The scope keeps + the run small and `HARNESS_MAX_REQUESTS` (below) is the enforced ceiling. Always use the shared + integration config via `APP_DIR=tests/integrations/python` (that is + `tests/integrations/python/config.json`) and scope the run to the change with `PROVIDER` and + `FEATURE`, or `SMOKE=1` for a cross-cutting change. Never run the unscoped sweep, and never + widen the scope beyond the change, without a separate explicit yes from the user that names + the scope. + + Before launching, resolve the exact request count for the chosen scope (the same filter the + recipe applies) and put the command, the scope, and that count in the plan the user approves: + ```bash + node tests/e2e/api/runners/augment-provider-harness.mjs --source tests/e2e/api/collections/provider-harness.json --out tmp/harness-augmented.json + # PROVIDER/FEATURE scope: one pass + node tests/e2e/api/runners/filter-collection.mjs --source tmp/harness-augmented.json --out tmp/harness-preflight.json --provider --feature "" + # SMOKE=1: the recipe runs a parallel main pass plus a deferred cache-parity pass, so count both + node tests/e2e/api/runners/filter-collection.mjs --source tmp/harness-augmented.json --out tmp/harness-smoke-main.json --smoke tests/e2e/api/collections/smoke-manifest.json --exclude-feature-any cache-parity + node tests/e2e/api/runners/filter-collection.mjs --source tmp/harness-augmented.json --out tmp/harness-smoke-cache.json --smoke tests/e2e/api/collections/smoke-manifest.json --feature-any cache-parity + # stderr of each command ends with: [filter-collection] wrote ... with N requests after filter + ``` + State N for a scoped run, or N_main + N_cache for SMOKE=1, in the plan. When SMOKE=1 is + combined with PROVIDER, FEATURE or FOLDER, apply the same filters to both smoke commands. + The preflight is an estimate: the main pass forks one newman per provider and a producer + shared by several forks runs once per fork, so the live total can exceed the preflight sum + (observed: 102 preflight, 122 live for SMOKE=1). The enforced bound is + `HARNESS_MAX_REQUESTS`: always pass it with the ceiling the user approved. The recipe checks + every newman launch against its exact filtered count before it starts (main shards, 429 + replays, the cache-parity pass, sequential mode); a launch that would cross the cap is + refused and the run exits 3, so the live total can never exceed the approved number. The + stream-cancellation probes are never sent under a cap because their count is not known up + front; if they are wanted, run them as a separately approved `SKIP_STREAM_CANCEL=` run + without the cap. After the run, quote the provider table's Total column as the actual. + + Port 8080 is a blocking precondition. The recipe reuses any server whose `/health` answers + and then never starts the `APP_DIR` one, so a stale listener silently tests old code. Run + `lsof -nP -iTCP:8080 -sTCP:LISTEN` first: if it reports a listener you did not start on the + current working tree in this session, stop, ask the user to shut it down (never kill a + process you did not start), and recheck; do not run the target while `lsof` still reports + it. The one acceptable listener is Bifrost you started yourself from the code under test, + which is also the reliable way to run it, because a cold `make dev` from this config can + take longer than the recipe's 60s health wait: + ```bash + make dev APP_DIR=tests/integrations/python # in the background; wait for /health = 200 + ``` + ```bash + make run-provider-harness-test APP_DIR=tests/integrations/python CI=1 HARNESS_MAX_REQUESTS= PROVIDER= FEATURE="" + # cross-cutting change: the curated smoke set instead + make run-provider-harness-test APP_DIR=tests/integrations/python CI=1 HARNESS_MAX_REQUESTS= SMOKE=1 + ``` + Report the provider status table and `tmp/harness-failures.md` findings, and state exactly + which scope ran. See AGENTS.md "Every fix ends with a provider-harness run". + +3. Report results to the user, including the red-then-green transcript/summary for Bug issues (what failed before, what passes now) +4. If tests fail, investigate and propose fixes (with approval) ## Error Handling diff --git a/AGENTS.md b/AGENTS.md index 3c67d7c9318..029ee50855c 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -580,6 +580,22 @@ Insert into the collection surgically (a script that splices the new object in, The narrow exemptions: changes with no wire-visible effect (comments, internal renames, log lines) and behaviour no HTTP request can reach. If a change is exempt, say so explicitly in the PR rather than leaving the omission unexplained. +### Every non-exempt wire-visible fix ends with a provider-harness run against `tests/integrations/python/config.json` + +Unit tests and `make test-core` are not the finish line. The exemptions are the ones in the previous section: a change with no wire-visible effect (comments, internal renames, log lines, test-only or guidance-only edits) or behaviour no HTTP request can reach is exempt, and the report must say so explicitly. For everything else, after the Go-level red/green loop and the regression reruns, run the live provider harness with the shared integration config, scoped to the change with `PROVIDER` and `FEATURE` so the paid sweep stays small, and report the provider table from the run. `APP_DIR=tests/integrations/python` is the config directory the harness starts Bifrost from; pass it explicitly so a stale server or another config never answers for the code under test. + +```bash +# Scoped to the change (preferred): the provider and a keyword from the affected cases +make run-provider-harness-test APP_DIR=tests/integrations/python CI=1 HARNESS_MAX_REQUESTS= PROVIDER= FEATURE="" + +# Curated ~100-request smoke set across all providers, when the change is cross-cutting +make run-provider-harness-test APP_DIR=tests/integrations/python CI=1 HARNESS_MAX_REQUESTS= SMOKE=1 +``` + +`HARNESS_MAX_REQUESTS` is the enforced spend bound: the recipe checks every newman launch against its exact filtered request count before it starts and refuses any launch that would cross the cap (exit 3), so the live total never exceeds the approved number. Always pass it; the preflight count from `filter-collection.mjs` is only an estimate because shared producers repeat per provider fork. Stream-cancellation probes are never sent under a cap. + +Port 8080 is a blocking precondition: the recipe reuses any server whose `/health` answers and never starts the `APP_DIR` one, so a stale listener silently tests old code. Run `lsof -nP -iTCP:8080 -sTCP:LISTEN` first; if it reports a listener you did not start from the current working tree, stop, have it shut down (never kill a process you did not start), and recheck before running the target. The one acceptable listener is Bifrost you started yourself from the code under test (`make dev APP_DIR=tests/integrations/python` in the background, then wait for `/health`), which is also the reliable pattern since a cold start can outlast the recipe's 60s health wait. For non-exempt changes, do not skip the run because it is paid or slow; scope it instead, and report exactly which scope ran. + ### Always prefer `make test-core` over raw `go test` for provider-level tests The `make test-core` target is the canonical harness for provider tests — it wires up env vars from `.env` (provider API keys), invokes the per-provider `{provider}_test.go` entrypoint in `core/providers//`, and routes through the shared `core/internal/llmtests/` scenario suite that validates end-to-end behavior (including streaming). diff --git a/Makefile b/Makefile index 97cd2b01939..372ff0e00b3 100644 --- a/Makefile +++ b/Makefile @@ -2041,6 +2041,12 @@ run-provider-harness-test: $(if $(HELP),,install-newman) ## Run the Bifrost prov printf ' %-18s %s\n' "HARNESS_JOBS=N" "Cap on concurrently running newman shards (default 100). The grid is ~168 live cells with sub-shards"; \ printf ' %-18s %s\n' "" " on, so the cap does block - which is why HARNESS_CLASSES is ordered slowest-first, to keep the long"; \ printf ' %-18s %s\n' "" " shards holding slots from the start. Lower it if a provider starts returning 429s."; \ + printf ' %-18s %s\n' "HARNESS_MAX_REQUESTS=N" ""; \ + printf ' %-18s %s\n' "" " Approved ceiling on paid requests for this run. Checked with each newman launch's EXACT filtered"; \ + printf ' %-18s %s\n' "" " request count (main shards, 429 replays, the deferred cache-parity pass, sequential mode) before it"; \ + printf ' %-18s %s\n' "" " starts: a launch that would cross the cap is refused, so the live total never exceeds N. Running"; \ + printf ' %-18s %s\n' "" " shards drain and the report merges as usual; the target exits 3. Stream-cancellation probes are"; \ + printf ' %-18s %s\n' "" " never sent under a cap (their count is not known up front). Unset = no cap (default)."; \ printf ' %-18s %s\n' "RETRY_429=N" "Max transient-failure retry attempts per shard (default 3; 0 disables). Covers 429 plus the two"; \ printf ' %-18s %s\n' "" " overload codes - 503 (OpenAI 'engine is currently overloaded') and 529 (Anthropic"; \ printf ' %-18s %s\n' "" " overloaded_error, which is its whole equivalent of 503; its error table has no 503). Other 5xx"; \ @@ -2157,6 +2163,26 @@ run-provider-harness-test: $(if $(HELP),,install-newman) ## Run the Bifrost prov if [ "$$HARNESS_QUIET" = "1" ] || [ "$$MONITOR_LIVE" = "1" ]; then "$$@" >> "$$QUIET_LOG" 2>&1; \ else "$$@"; fi; \ }; \ + : "HARNESS_MAX_REQUESTS is the approved paid-request ceiling for this run. Every newman"; \ + : "launch below passes its exact filtered request count here first; a launch that would"; \ + : "cross the cap is refused and later launches are refused too, so the live total is"; \ + : "bounded by construction rather than estimated from the preflight. Shards already"; \ + : "running drain normally and the report still merges; the target then exits 3."; \ + BUDGET_USED=0; BUDGET_EXCEEDED=0; \ + : "tmp/harness-budget-used mirrors BUDGET_USED so a COMPAT=both parent can hand the"; \ + : "remaining budget to its second sub-run instead of letting both spend the full cap."; \ + mkdir -p tmp; printf '0' > tmp/harness-budget-used; \ + budget_ok() { \ + if [ -z "$(HARNESS_MAX_REQUESTS)" ]; then return 0; fi; \ + if [ "$$BUDGET_EXCEEDED" = "1" ] || [ $$((BUDGET_USED + $$1)) -gt "$(HARNESS_MAX_REQUESTS)" ]; then \ + BUDGET_EXCEEDED=1; \ + say "$(RED)[$$2] not launched: $$1 request(s) would push the total to $$((BUDGET_USED + $$1)), past HARNESS_MAX_REQUESTS=$(HARNESS_MAX_REQUESTS) (launched so far: $$BUDGET_USED)$(NC)"; \ + return 1; \ + fi; \ + BUDGET_USED=$$((BUDGET_USED + $$1)); \ + printf '%s' "$$BUDGET_USED" > tmp/harness-budget-used; \ + return 0; \ + }; \ start_monitor() { \ if [ -f tmp/harness-monitor.pid ]; then return 0; fi; \ if [ "$$HARNESS_QUIET" != "1" ] && [ ! -t 1 ]; then return 0; fi; \ @@ -2200,10 +2226,20 @@ run-provider-harness-test: $(if $(HELP),,install-newman) ## Run the Bifrost prov if [ "$(COMPAT)" = "both" ]; then \ mkdir -p tmp; \ say "$(CYAN)COMPAT=both: running harness with compat OFF then ON (sub-runs forced CI=1 to skip the interactive viewer)...$(NC)"; \ + : "Both sub-runs share one HARNESS_MAX_REQUESTS: the second gets what the first left."; \ + BOTH_REMAINING="$(HARNESS_MAX_REQUESTS)"; BOTH_USED=0; \ for mode in off on; do \ + if [ -n "$$BOTH_REMAINING" ] && [ "$$BOTH_REMAINING" -le 0 ]; then \ + say "$(RED)compat $$mode not run: HARNESS_MAX_REQUESTS=$(HARNESS_MAX_REQUESTS) already spent by the earlier sub-run ($$BOTH_USED launched)$(NC)"; \ + BOTH_RC=3; continue; \ + fi; \ say "$(CYAN)=== Harness run: compat $$mode ===$(NC)"; \ - $(MAKE) run-provider-harness-test COMPAT=$$mode CI=1; \ + $(MAKE) run-provider-harness-test COMPAT=$$mode CI=1 HARNESS_MAX_REQUESTS="$$BOTH_REMAINING"; \ RC=$$?; \ + if [ -n "$$BOTH_REMAINING" ]; then \ + SUB_USED="$$(cat tmp/harness-budget-used 2>/dev/null || echo 0)"; \ + BOTH_USED=$$((BOTH_USED + SUB_USED)); BOTH_REMAINING=$$((BOTH_REMAINING - SUB_USED)); \ + fi; \ mv -f tmp/newman-report.json "tmp/newman-report-compat-$$mode.json" 2>/dev/null || true; \ mv -f tmp/newman-report.html "tmp/newman-report-compat-$$mode.html" 2>/dev/null || true; \ mv -f tmp/harness-failures.md "tmp/harness-failures-compat-$$mode.md" 2>/dev/null || true; \ @@ -2587,6 +2623,9 @@ run-provider-harness-test: $(if $(HELP),,install-newman) ## Run the Bifrost prov rm -f "tmp/harness-filtered-$$SHARD.json"; \ continue; \ fi; \ + : "A refused shard must not leave its filtered file behind: the status table counts"; \ + : "every tmp/harness-filtered-*.json as planned work, so it would show rows that never ran."; \ + budget_ok "$$P_ITEM_COUNT" "$$SHARD" || { rm -f "tmp/harness-filtered-$$SHARD.json"; continue; }; \ : "Block until a slot frees. 'wait -n' reaps one arbitrary child, which is why shard"; \ : "exit codes are recorded by the subshell into tmp/parallel-exit- instead of"; \ : "being collected later with 'wait ' - that pid may already have been reaped here."; \ @@ -2603,6 +2642,10 @@ run-provider-harness-test: $(if $(HELP),,install-newman) ## Run the Bifrost prov done; \ done; \ if [ "$$LAUNCHED" -eq 0 ]; then \ + if [ "$$BUDGET_EXCEEDED" = "1" ]; then \ + say "$(RED)Aborted before any launch: every shard would exceed HARNESS_MAX_REQUESTS=$(HARNESS_MAX_REQUESTS). Raise the cap or narrow PROVIDER/FEATURE.$(NC)"; \ + exit 3; \ + fi; \ say "$(RED)No provider runs were launched. Check PROVIDER/FEATURE/FOLDER filters.$(NC)"; \ exit 1; \ fi; \ @@ -2663,7 +2706,9 @@ run-provider-harness-test: $(if $(HELP),,install-newman) ## Run the Bifrost prov say "$(YELLOW)[$$rs] retry filter failed - keeping the original verdict$(NC)"; \ continue; \ fi; \ - [ "$$(grep -c '"request":' "$$RETRY_COLL" 2>/dev/null || echo 0)" -eq 0 ] && continue; \ + RETRY_COUNT="$$(grep -c '"request":' "$$RETRY_COLL" 2>/dev/null || true)"; RETRY_COUNT="$${RETRY_COUNT:-0}"; \ + [ "$$RETRY_COUNT" -eq 0 ] && continue; \ + budget_ok "$$RETRY_COUNT" "$$rs-retry$$RETRY_ATTEMPT" || { rm -f "$$RETRY_COLL"; continue; }; \ while [ "$$(shard_jobs)" -ge "$$JOBS_CAP" ]; do wait -n 2>/dev/null || true; done; \ ( \ newman_shard "$$rs-retry$$RETRY_ATTEMPT" "$$RETRY_COLL" "tmp/newman-report-$$rs-retry$$RETRY_ATTEMPT.json" "$$rp"; \ @@ -2733,6 +2778,8 @@ run-provider-harness-test: $(if $(HELP),,install-newman) ## Run the Bifrost prov else \ SEQ_PROVIDERS="$(or $(PROVIDER),$(HARNESS_PROVIDERS))"; \ : > tmp/newman-cli.log; \ + SEQ_COUNT="$$(grep -c '"request":' "$$COLLECTION_FILE" 2>/dev/null || true)"; SEQ_COUNT="$${SEQ_COUNT:-0}"; \ + if budget_ok "$$SEQ_COUNT" main; then \ add_pass "$$(printf '{"t":"pass","id":"main","mode":"sequential","log":"tmp/newman-cli.log","collection":"%s"}' "$$COLLECTION_FILE")"; \ newman run "$$COLLECTION_FILE" \ --env-var "baseUrl=$$BASE_URL_VAL" \ @@ -2762,6 +2809,7 @@ run-provider-harness-test: $(if $(HELP),,install-newman) ## Run the Bifrost prov --reporter-htmlextra-darkTheme > tmp/newman-cli.log 2>&1; \ NEWMAN_EXIT=$$?; \ end_pass main; \ + else NEWMAN_EXIT=0; fi; \ if [ "$$HARNESS_MONITORED" != "1" ] && [ "$$HARNESS_QUIET" != "1" ]; then cat tmp/newman-cli.log; fi; \ if command -v jq >/dev/null 2>&1 && [ -f tmp/newman-report.json ]; then \ say "$(CYAN)Sanitizing tmp/newman-report.json (newman embeds the whole parent folder in every failure)...$(NC)"; \ @@ -2782,7 +2830,8 @@ run-provider-harness-test: $(if $(HELP),,install-newman) ## Run the Bifrost prov $(if $(FOLDER),--folder "$(FOLDER)",) \ $${SMOKE_MANIFEST:+--smoke "$$SMOKE_MANIFEST"} \ $(if $(PROVIDER),--provider $(PROVIDER),) || { say "$(RED)Cache parity filter step failed$(NC)"; }; \ - if [ -f tmp/harness-cache-filtered.json ]; then \ + CACHE_COUNT="$$(grep -c '"request":' tmp/harness-cache-filtered.json 2>/dev/null || true)"; CACHE_COUNT="$${CACHE_COUNT:-0}"; \ + if [ -f tmp/harness-cache-filtered.json ] && budget_ok "$$CACHE_COUNT" cache-parity; then \ CACHE_PROVIDERS="$(or $(PROVIDER),$(HARNESS_PROVIDERS))"; \ : > tmp/newman-cli-cache-parity.log; \ add_pass '{"t":"pass","id":"cache-parity","mode":"sequential","log":"tmp/newman-cli-cache-parity.log","collection":"tmp/harness-cache-filtered.json"}'; \ @@ -2825,7 +2874,9 @@ run-provider-harness-test: $(if $(HELP),,install-newman) ## Run the Bifrost prov : "prints normally to a restored main screen."; \ say "$(GREEN)Newman finished. Reports: tmp/newman-report.{json,html} + tmp/newman-cli.log$(NC)"; \ STREAM_CANCEL_EXIT=0; \ - if [ -z "$(SKIP_STREAM_CANCEL)" ] && [ -z "$(RERUN_FAILED)" ] && [ "$(PROVIDER)" != "passthrough" ] && { [ -z "$(FOLDER)" ] || printf '%s' "$(FOLDER)" | grep -qi 'stream'; }; then \ + if [ -n "$(HARNESS_MAX_REQUESTS)" ]; then \ + say "$(YELLOW)Skipping stream cancellation probes: their request count is not known before they run, so they are never sent under HARNESS_MAX_REQUESTS.$(NC)"; \ + elif [ -z "$(SKIP_STREAM_CANCEL)" ] && [ -z "$(RERUN_FAILED)" ] && [ "$(PROVIDER)" != "passthrough" ] && { [ -z "$(FOLDER)" ] || printf '%s' "$(FOLDER)" | grep -qi 'stream'; }; then \ say "$(CYAN)Running stream cancellation probes...$(NC)"; \ $(USE_NODE); node tests/e2e/api/runners/run-stream-cancellation.mjs \ --base-url "$$BASE_URL_VAL" \ @@ -2884,5 +2935,9 @@ run-provider-harness-test: $(if $(HELP),,install-newman) ## Run the Bifrost prov say "$(GREEN)Viewer closed.$(NC)"; \ fi; \ fi; \ + if [ "$$BUDGET_EXCEEDED" = "1" ]; then \ + say "$(RED)Aborted: HARNESS_MAX_REQUESTS=$(HARNESS_MAX_REQUESTS) reached; $$BUDGET_USED request(s) were launched. The provider table above is the actual total.$(NC)"; \ + exit 3; \ + fi; \ if [ "$$NEWMAN_EXIT" -ne 0 ]; then exit $$NEWMAN_EXIT; fi; \ exit $$STREAM_CANCEL_EXIT diff --git a/core/changelog.md b/core/changelog.md index 45bc3db1299..810fc644605 100644 --- a/core/changelog.md +++ b/core/changelog.md @@ -9,4 +9,6 @@ - fix: `default_request_timeout_in_seconds` now bounds the wait for response headers on streaming requests, and cancelling a request now closes the upstream socket. Every fasthttp client is driven through a Bifrost-owned `RoundTripper` (`core/providers/utils/roundtripper.go`) that applies the client's read/write timeouts and the request context to the request write and the header wait, then lifts the socket deadline once headers are parsed so `stream_idle_timeout_in_seconds` remains the only bound on the body. `BuildStreamingClient` and `BuildLargeResponseClient` no longer zero the timeouts. An upstream that accepts the connection and never answers now fails with 504 `RequestTimedOut` after the request timeout and the request's fallbacks are used, instead of pinning the provider worker until the upstream closes the socket; `MakeRequestWithContext` no longer leaves a background `client.Do` running until `ReadTimeout` after its context is cancelled (#7034) - fix: unary large-response downloads (`FinalizeResponseWithLargeDetection`) now bound every body read with `stream_idle_timeout_in_seconds` and close the upstream socket on request cancellation, mirroring the streamed passthrough path; a stall during the prefetch surfaces as 504 `RequestTimedOut` instead of pinning the provider worker, and a stall while the transport drains the `LargeResponseReader` fails the read with the idle-timeout error instead of blocking the writer indefinitely (#7104) - fix: gzip-encoded unary responses are now classified for large-response mode by decompressed size; `Content-Length` describes the compressed bytes, so a body that was small on the wire but large once decompressed used to be materialized in full past `large_response_threshold` (#7104) -- feat: model allow and block lists gain pattern twins. `Key` carries `models_patterns` and `blacklisted_models_patterns`, `ProviderPermit` carries `allowed_models_patterns` and `blacklisted_models_patterns`, and `schemas.ModelAccessRule` evaluates exact lists and RE2 patterns together (full match, case-insensitive, tried against the model name and `provider/model`; block wins). `WhiteList` and `BlackList` stay exact. The provider list-models pipeline takes the rule so a patterns-only key still lists what it can serve \ No newline at end of file +- feat: model allow and block lists gain pattern twins. `Key` carries `models_patterns` and `blacklisted_models_patterns`, `ProviderPermit` carries `allowed_models_patterns` and `blacklisted_models_patterns`, and `schemas.ModelAccessRule` evaluates exact lists and RE2 patterns together (full match, case-insensitive, tried against the model name and `provider/model`; block wins). `WhiteList` and `BlackList` stay exact. The provider list-models pipeline takes the rule so a patterns-only key still lists what it can serve +- fix: an OpenAI-compatible upstream that omits `[DONE]` and then goes silent after `finish_reason` no longer fails the stream when `stream_idle_timeout_in_seconds` fires. The chat and text completion read loops now treat an idle timeout after a terminal signal as a parked upstream, mark the stream parked so the connection is abandoned rather than drained, and synthesize the final chunk with the buffered `finish_reason`; a stall before `finish_reason` still surfaces as the idle-timeout error (#7108) +- fix: a streamed upstream that drops the connection mid-body is again reported as the retryable 502 `provider closed the stream before sending a completion marker` error instead of a generic `Error reading stream: unexpected EOF`. The Bifrost round tripper's chunked decoder surfaced the drop as `io.ErrUnexpectedEOF`, which no provider read loop treats as end of stream; it now reports the plain `io.EOF` fasthttp always did and discards the half-read connection (#7104 follow-up) diff --git a/core/providers/openai/openai.go b/core/providers/openai/openai.go index fd1063e7560..9ae7a07cd17 100644 --- a/core/providers/openai/openai.go +++ b/core/providers/openai/openai.go @@ -616,6 +616,17 @@ func HandleOpenAITextCompletionStreaming( if ctx.Err() != nil { return } + // A silent park after finish_reason (#7108): the response is complete, so the + // idle timeout that finally unblocked the read ends the stream cleanly instead + // of failing a response the client already has. The timer closed the socket + // and claimed ConnectionClosed, so the deferred release skips the drain. + if errors.Is(readErr, providerUtils.ErrStreamIdleTimeout) && finishReason != nil { + ctx.SetValue(schemas.BifrostContextKeyStreamParkedAfterFinish, true) + if usage.TotalTokens == 0 { + logger.Warn("provider %s went silent after finish_reason without sending usage; token counts and cost are unavailable for this request", providerName) + } + break + } if readErr != io.EOF { ctx.SetValue(schemas.BifrostContextKeyStreamEndIndicator, true) logger.Warn("Error reading stream: %v", readErr) @@ -1303,6 +1314,19 @@ func HandleOpenAIChatCompletionStreaming( if ctx.Err() != nil { return } + // A silent park after finish_reason (#7108): the response is complete, so the + // idle timeout that finally unblocked the read ends the stream cleanly instead + // of failing a response the client already has. On the Responses fallback path + // the terminal signal is the pending completed/incomplete event. The timer + // closed the socket and claimed ConnectionClosed, so the deferred release + // skips the drain. + if errors.Is(readErr, providerUtils.ErrStreamIdleTimeout) && (finishReason != nil || pendingFinalEvent != nil) { + ctx.SetValue(schemas.BifrostContextKeyStreamParkedAfterFinish, true) + if usage.TotalTokens == 0 { + logger.Warn("provider %s went silent after finish_reason without sending usage; token counts and cost are unavailable for this request", providerName) + } + break + } if readErr != io.EOF { ctx.SetValue(schemas.BifrostContextKeyStreamEndIndicator, true) logger.Warn("Error reading stream: %v", readErr) diff --git a/core/providers/openai/streamtruncation_test.go b/core/providers/openai/streamtruncation_test.go index c7186356fef..f165119fe46 100644 --- a/core/providers/openai/streamtruncation_test.go +++ b/core/providers/openai/streamtruncation_test.go @@ -727,3 +727,156 @@ func TestImageEditStreamReadErrorReportsOnce(t *testing.T) { assertSingleReadError(t, collectChunks(t, stream)) } + +// silentParkSSEServer writes body and then holds the connection open without +// sending another byte until the client goes away: no [DONE], no heartbeat +// comments, no close. This is the one parked-upstream shape neither the +// post-finish comment rule nor custom_provider_config.does_not_send_done_marker +// reaches, so stream_idle_timeout_in_seconds is the only thing that can end it. +func silentParkSSEServer(t *testing.T, body string) *httptest.Server { + t.Helper() + return httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.Header().Set("Content-Type", "text/event-stream") + w.WriteHeader(http.StatusOK) + flusher, ok := w.(http.Flusher) + if !ok { + return + } + if _, err := w.Write([]byte(body)); err != nil { + return + } + flusher.Flush() + <-r.Context().Done() + })) +} + +// https://github.com/maximhq/bifrost/issues/7108: an upstream that omits [DONE] and +// parks silently after finish_reason has already delivered a complete response, so +// the idle timeout that finally unblocks the read must end the stream cleanly with +// the buffered finish_reason. Surfacing it as a read error tells the client a +// response it has fully received failed. +func TestChatStreamSilentParkAfterFinishReasonEndsCleanlyOnIdleTimeout(t *testing.T) { + stop := "stop" + server := silentParkSSEServer(t, chatChunk("hello", nil)+chatChunk("", &stop)) + defer server.Close() + + ctx := newStreamTestContext() + ctx.SetValue(schemas.BifrostContextKeyStreamIdleTimeout, 300*time.Millisecond) + + provider := newStreamTestProvider(server.URL) + stream, bifrostErr := provider.ChatCompletionStream(ctx, passthroughPostHook, nil, testKey(), basicChatRequest()) + if bifrostErr != nil { + t.Fatalf("stream setup failed: %v", bifrostErr) + } + + chunks := collectChunks(t, stream) + if len(chunks) == 0 { + t.Fatal("expected chunks from a stream that reached finish_reason") + } + for i, chunk := range chunks { + if chunk.BifrostError != nil { + t.Fatalf("chunk %d unexpectedly carried an error: %+v", i, chunk.BifrostError.Error) + } + } + final := chunks[len(chunks)-1] + if final.BifrostChatResponse == nil { + t.Fatalf("expected a synthesized final chat chunk, got %+v", final) + } + if len(final.BifrostChatResponse.Choices) == 0 || + final.BifrostChatResponse.Choices[0].FinishReason == nil || + *final.BifrostChatResponse.Choices[0].FinishReason != stop { + t.Errorf("expected the final chunk to carry finish_reason %q, got %+v", stop, final.BifrostChatResponse.Choices) + } +} + +// The text-completion loop handles the idle-timeout read error on the same switch. +func TestTextCompletionStreamSilentParkAfterFinishReasonEndsCleanlyOnIdleTimeout(t *testing.T) { + server := silentParkSSEServer(t, `data: {"id":"cmpl-repro","object":"text_completion","created":1,"model":"repro-model","choices":[{"index":0,"text":"hello","finish_reason":null}]}`+"\n\n"+ + `data: {"id":"cmpl-repro","object":"text_completion","created":1,"model":"repro-model","choices":[{"index":0,"text":"","finish_reason":"stop"}]}`+"\n\n") + defer server.Close() + + ctx := newStreamTestContext() + ctx.SetValue(schemas.BifrostContextKeyStreamIdleTimeout, 300*time.Millisecond) + + provider := newStreamTestProvider(server.URL) + request := &schemas.BifrostTextCompletionRequest{ + Provider: schemas.OpenAI, + Model: "repro-model", + Input: &schemas.TextCompletionInput{PromptStr: schemas.Ptr("hi")}, + } + stream, bifrostErr := provider.TextCompletionStream(ctx, passthroughPostHook, nil, testKey(), request) + if bifrostErr != nil { + t.Fatalf("stream setup failed: %v", bifrostErr) + } + + chunks := collectChunks(t, stream) + if len(chunks) == 0 { + t.Fatal("expected chunks from a stream that reached finish_reason") + } + for i, chunk := range chunks { + if chunk.BifrostError != nil { + t.Fatalf("chunk %d unexpectedly carried an error: %+v", i, chunk.BifrostError.Error) + } + } + final := chunks[len(chunks)-1] + if final.BifrostTextCompletionResponse == nil { + t.Fatalf("expected a synthesized final text completion chunk, got %+v", final) + } + if len(final.BifrostTextCompletionResponse.Choices) == 0 || + final.BifrostTextCompletionResponse.Choices[0].FinishReason == nil || + *final.BifrostTextCompletionResponse.Choices[0].FinishReason != "stop" { + t.Errorf("expected the final chunk to carry finish_reason \"stop\", got %+v", final.BifrostTextCompletionResponse.Choices) + } +} + +// The Responses-to-Chat fallback reaches the same loop through ResponsesStream with native +// Responses disabled. There the terminal signal is the pending completed event synthesized +// from finish_reason, not finishReason itself, so the idle-timeout branch has to honour it +// too or the parked stream is reported as an error and the completed event is never flushed. +func TestResponsesStreamFallbackSilentParkAfterFinishReasonEndsCleanlyOnIdleTimeout(t *testing.T) { + server := silentParkSSEServer(t, chatChunk("hello", nil)+chatChunkNullDeltaFinish("stop")) + defer server.Close() + + provider := NewOpenAIProvider(&schemas.ProviderConfig{ + NetworkConfig: schemas.NetworkConfig{BaseURL: server.URL}, + CustomProviderConfig: &schemas.CustomProviderConfig{ + AllowedRequests: &schemas.AllowedRequests{ + ChatCompletionStream: true, + ResponsesStream: false, + }, + }, + }, testNoopLogger{}) + + ctx := newStreamTestContext() + ctx.SetValue(schemas.BifrostContextKeyStreamIdleTimeout, 300*time.Millisecond) + + request := &schemas.BifrostResponsesRequest{ + Provider: schemas.OpenAI, + Model: "repro-model", + Input: []schemas.ResponsesMessage{{ + Type: schemas.Ptr(schemas.ResponsesMessageTypeMessage), + Role: schemas.Ptr(schemas.ResponsesInputMessageRoleUser), + Content: &schemas.ResponsesMessageContent{ContentStr: schemas.Ptr("hi")}, + }}, + } + stream, bifrostErr := provider.ResponsesStream(ctx, passthroughPostHook, nil, testKey(), request) + if bifrostErr != nil { + t.Fatalf("stream setup failed: %v", bifrostErr) + } + + var completed *schemas.BifrostResponsesStreamResponse + for i, chunk := range collectChunks(t, stream) { + if chunk.BifrostError != nil { + t.Fatalf("chunk %d unexpectedly carried an error: %+v", i, chunk.BifrostError.Error) + } + if chunk.BifrostResponsesStreamResponse != nil && chunk.BifrostResponsesStreamResponse.Type == schemas.ResponsesStreamResponseTypeCompleted { + completed = chunk.BifrostResponsesStreamResponse + } + } + if completed == nil { + t.Fatal("expected a completed Responses stream event from a parked fallback stream") + } + if completed.Response == nil || completed.Response.StopReason == nil || *completed.Response.StopReason != "stop" { + t.Fatalf("expected stop_reason stop on the completed event, got %+v", completed.Response) + } +} diff --git a/core/providers/utils/makerequest_test.go b/core/providers/utils/makerequest_test.go index a9d2c4edcb7..4d96583c685 100644 --- a/core/providers/utils/makerequest_test.go +++ b/core/providers/utils/makerequest_test.go @@ -597,6 +597,53 @@ func TestContextTransport_ChunkedStreamReleasesConnForReuse(t *testing.T) { } } +// TestContextTransport_TruncatedChunkedStreamReadsAsEOFAndDiscardsConn pins the +// contract every provider read loop and the semantic truncation check (#5546) are +// built on: fasthttp reports an upstream that closes on a chunk boundary as a plain +// io.EOF and leaves "was the stream complete?" to the caller's terminal-marker +// check, which turns a missing marker into the retryable 502 truncation error. The +// standard-library chunked reader says io.ErrUnexpectedEOF for the same close, and +// the loops route any non-EOF error to a generic stream failure instead. The +// half-read connection must still be closed, never returned to the pool: a POST +// (non-idempotent, so fasthttp will not silently retry it) must get a fresh +// connection and succeed. +func TestContextTransport_TruncatedChunkedStreamReadsAsEOFAndDiscardsConn(t *testing.T) { + srv := newScriptedServer(t, func(conn net.Conn, br *bufio.Reader) { + if !readRequest(br) { + return + } + writeAll(t, conn, "HTTP/1.1 200 OK\r\nContent-Type: text/event-stream\r\nTransfer-Encoding: chunked\r\n\r\n") + writeAll(t, conn, "9\r\ndata: a\n\n\r\n") + // Returning closes conn without the terminating 0-length chunk. + }) + client := BuildStreamingClient(srv.client(5 * time.Second)) + + req, resp := streamGet(t, client, "GET") + body, err := io.ReadAll(resp.BodyStream()) + if got := string(body); got != "data: a\n\n" { + t.Fatalf("body before the drop = %q, want %q", got, "data: a\n\n") + } + if err != nil { + t.Fatalf("truncated chunked body read error = %v, want a plain io.EOF (io.ReadAll returns nil on EOF)", err) + } + if err := resp.CloseBodyStream(); err != nil { + t.Fatalf("CloseBodyStream: %v", err) + } + fasthttp.ReleaseRequest(req) + fasthttp.ReleaseResponse(resp) + + req, resp = streamGet(t, client, "POST") + if resp.StatusCode() != 200 { + t.Fatalf("second request status = %d, want 200", resp.StatusCode()) + } + _ = resp.CloseBodyStream() + fasthttp.ReleaseRequest(req) + fasthttp.ReleaseResponse(resp) + if got := srv.accepted.Load(); got != 2 { + t.Fatalf("connections accepted = %d, want 2 (a truncated stream's connection must be discarded, not pooled)", got) + } +} + // TestContextTransport_ContentLengthAndIdentityBodies covers the two // non-chunked framings of a streamed body. func TestContextTransport_ContentLengthAndIdentityBodies(t *testing.T) { diff --git a/core/providers/utils/roundtripper.go b/core/providers/utils/roundtripper.go index 2ade144a332..bdaf9ca6b1a 100644 --- a/core/providers/utils/roundtripper.go +++ b/core/providers/utils/roundtripper.go @@ -395,6 +395,16 @@ func (s *streamBody) Read(p []byte) (int, error) { n, err := s.reader.Read(p) if errors.Is(err, io.EOF) { s.fullyRead = true + } else if errors.Is(err, io.ErrUnexpectedEOF) { + // The peer closed before the terminating 0-length chunk. fasthttp's own + // streaming reader reports that as a plain io.EOF, and every provider read + // loop plus the semantic truncation check (#5546) is built on that contract: + // an EOF without a terminal marker becomes the retryable 502 truncation + // error, while any other read error is a generic stream failure. The + // standard-library chunked reader says io.ErrUnexpectedEOF for the same + // close, so restore the contract here. fullyRead stays false: the half-read + // connection is closed on release, never returned to the pool. + err = io.EOF } return n, err } diff --git a/docs/providers/custom-providers.mdx b/docs/providers/custom-providers.mdx index 293ef5bb4a6..39dadaa5c8c 100644 --- a/docs/providers/custom-providers.mdx +++ b/docs/providers/custom-providers.mdx @@ -261,6 +261,12 @@ Custom providers can be built on these supported providers: Most OpenAI-compatible providers end a stream with a `data: [DONE]` marker, and Bifrost reads until it arrives so that a trailing usage-only chunk — which many providers send after `finish_reason` — is not lost. +Bifrost also ends the stream on its own, with no configuration, when an upstream omits `[DONE]` after `finish_reason`: + +- the upstream closes the connection: the stream ends immediately +- the upstream keeps the connection open and sends SSE heartbeat comments: the stream ends on the second consecutive comment after `finish_reason`, so a trailing usage chunk is still collected +- the upstream keeps the connection open and sends nothing: the stream ends cleanly once `stream_idle_timeout_in_seconds` elapses, with the buffered `finish_reason`. Usage is unavailable for that request if it never arrived + Set `does_not_send_done_marker` to `true` when your upstream instead ends streams on `finish_reason` and never sends `[DONE]`: ```json