mirror of
https://github.com/headroomlabs-ai/headroom.git
synced 2026-08-27 14:17:10 -04:00
a3d9424de9
## Description When every connect retry to the upstream API fails, `_stream_response_inner` synthesizes its own SSE error response (added in #1639, so an h2 `StreamReset` wouldn't surface as an unhandled 502). It was built without a `status_code`, so Starlette defaulted it to **200**. A 200 carrying a lone `event: error` frame and no `message_start` is indistinguishable, to every Anthropic/OpenAI SDK, from a successful stream that produced no events. Claude Code reports: ``` API Error: API returned an empty or malformed response (HTTP 200) - check for a proxy or gateway intercepting the request ``` The client also cannot recover, because 200 is not a retryable status. **It does not self-heal.** Compression fails open on timeout, so the proxy forwards the full uncompressed body; the client retries, re-sends the same oversized payload, hits the same transport failure, and gets another 200. The session is stuck until the client is pointed away from the proxy. Related — same *symptom*, different root cause, so this closes none of them: #3040, #3055, #3019, #2952 (CCR buffered-stream conversion), #3071, #3017. Worth noting that #3040 ("first messages succeed, fails after several turns", closed `NOT_PLANNED`) matches this failure's shape exactly. ## Type of Change - [x] Bug fix (non-breaking change that fixes an issue) - [ ] New feature (non-breaking change that adds functionality) - [x] Breaking change (fix or feature that would cause existing functionality to change) - [x] Documentation update - [ ] Performance improvement - [ ] Code refactoring (no functional changes) Marked breaking because the status code on this path changes 200 to 502. See **Runtime Rollout Safety**. ## Changes Made - `handlers/streaming.py` — the synthesized transport-error response now returns **502**. The structured SSE body is unchanged for clients that read it. No body byte has been forwarded at that point, so the status line is still ours to set. - `prometheus_metrics.py` — new `headroom_upstream_connection_errors_total{provider}`. This path forwards no upstream status, so there was nothing to attribute the failure to in `/metrics`; it survived only as a log line. Mirrors `record_compression_failed` and takes the same `_obs_counter_lock`. - `server.py` — `HEADROOM_LOG_LEVEL` for uvicorn's level, previously hardcoded to `"warning"` with no env var and no CLI flag. Default unchanged. An unrecognized value warns and falls back rather than raising (uvicorn raises `KeyError` on unknown levels). - `docs/content/docs/proxy.mdx` — documents the new env var in the Observability table. ## Testing - [x] Unit tests pass (`pytest`) - [x] Linting passes (`ruff check .`) - [x] Type checking passes (`mypy headroom`) - [x] New tests added for new functionality - [x] Manual testing performed `test_stream_reset_exhaustion_yields_sse_error_not_crash` asserted the SSE body but never the status — which is how the 200 survived. Added a test that pins the status specifically, a happy-path guard, and coverage for the counter and the env-var resolver. ### Test Output ```text $ python -m pytest tests/test_h2_stream_reset_retry.py tests/test_prometheus_obs_counters.py tests/test_uvicorn_log_level_env.py -q 29 passed in 5.26s $ python -m ruff check . All checks passed! $ python -m ruff format --check . 1506 files already formatted $ python -m mypy headroom/proxy/handlers/streaming.py headroom/proxy/prometheus_metrics.py headroom/proxy/server.py Success: no issues found in 3 source files # Fails before the fix (status_code=502 line removed, nothing else changed): $ python -m pytest tests/test_h2_stream_reset_retry.py -k status_is_not_200 assert result.status_code == 502 E assert 200 == 502 FAILED tests/test_h2_stream_reset_retry.py::test_stream_reset_exhaustion_status_is_not_200 1 failed, 5 deselected in 1.28s ``` Broader regression run (181 passed): `test_h2_stream_reset_retry`, `test_prometheus_obs_counters`, `test_uvicorn_log_level_env`, `test_prometheus_label_escaping`, `test_observability_metrics`, `test_prometheus_stage_timing_concurrency`, `test_proxy_streaming_ratelimit_headers`, `test_proxy_retry_429`, `test_proxy_byte_faithful_forwarding`, `test_ws_http_fallback`, `test_mid_turn_steering`, `test_proxy_anthropic_cache_stability`. ## Real Behavior Proof - Environment: Windows 11, Python 3.13.15, headroom @ this branch. Genuine `create_app()` FastAPI app under real uvicorn — no mocks, no TestClient. Upstream pinned to `http://127.0.0.1:59999` (a closed port), so every connect attempt is a real TCP refusal, producing a real `httpx.ConnectError` (an `httpx.TransportError`) into the branch under test. `retry_max_attempts=2`. - Exact command / steps: boot the real app with `HEADROOM_LOG_LEVEL=info` and `ProxyConfig(anthropic_api_url="http://127.0.0.1:59999")`, POST a `stream:true` request to `/v1/messages`, then scrape `/metrics`. Verbatim commands below. - Observed result: `HTTP_STATUS=502` (previously 200), structured SSE error body intact, `headroom_upstream_connection_errors_total{provider="anthropic"} 1`, and a uvicorn access line present only because `HEADROOM_LOG_LEVEL=info` was honored. Verbatim output below. - Not tested: the h2 `StreamReset` variant specifically — reproduced via `ConnectError`, a sibling `httpx.TransportError` travelling the identical code path (the existing `test_stream_reset_exhaustion_*` tests cover `RemoteProtocolError` at unit level). Not exercised against the OpenAI, Gemini, or Bedrock streaming handlers, which have their own error paths. No load or concurrency testing. Commands run after the patch: ```bash # boot the real app with a dead upstream and the new env var set HEADROOM_LOG_LEVEL=info python run_proxy_proof.py # ProxyConfig(anthropic_api_url="http://127.0.0.1:59999") curl -s -o resp.txt -w "HTTP_STATUS=%{http_code}\ncontent_type=%{content_type}\n" \ http://127.0.0.1:8799/v1/messages \ -H "content-type: application/json" \ -H "x-api-key: proof-key" \ -H "anthropic-version: 2023-06-01" \ -d @request.json # {"model":"claude-opus-5","max_tokens":64,"stream":true,"messages":[...]} ``` After-fix evidence: ```text PROOF: HEADROOM_LOG_LEVEL='info' -> uvicorn log_level='info' PROOF: upstream pinned to http://127.0.0.1:59999 (closed port) HTTP_STATUS=502 content_type=text/event-stream; charset=utf-8 event: error data: {"type": "error", "error": {"type": "connection_error", "message": "Failed to connect to upstream API: All connection attempts failed"}} ``` ```text $ curl -s http://127.0.0.1:8799/metrics | grep upstream_connection_errors # HELP headroom_upstream_connection_errors_total Exhausted-retries upstream transport failures by provider; the proxy answered 502 itself because no upstream response arrived # TYPE headroom_upstream_connection_errors_total counter headroom_upstream_connection_errors_total{provider="anthropic"} 1 ``` ```text # uvicorn access log — present only because HEADROOM_LOG_LEVEL=info was honored: INFO: 127.0.0.1:62472 - "POST /v1/messages HTTP/1.1" 502 Bad Gateway INFO: 127.0.0.1:62479 - "GET /metrics HTTP/1.1" 200 OK ``` All three changes are exercised end to end: the status is 502, the structured body survives, the counter increments, and the env var takes effect. Separately, this ran against a real deployment: the fix is live on a self-hosted proxy at `0.35.1-alpha.3` (Azure Container Apps, Cloudflare in front), where the original HTTP 200 was first observed against `0.35.1-alpha.1`. ## Runtime Rollout Safety - Rollout-managed feature(s): none — unconditional bug fix, no flag. - Minimum rollout channel: n/a — ships with the change. - Stable/default behavior changed: yes. This path returns 502 instead of 200. `HEADROOM_LOG_LEVEL` and the new counter both default to current behavior (`warning`; the counter is absent from `/metrics` until the first occurrence). - Kill switch / disable path: none. Happy to add an env guard if you would prefer it staged, though a 200 on this path is never correct. - Unsafe override required: no. - Qualification impact: any client treating the synthesized 200 as success now sees a 5xx. That is the fix — such a client was silently accepting a truncated response. Retry-on-5xx logic in the Anthropic and OpenAI SDKs will now retry a transient transport failure, which is the intended behavior. - Rollback path: revert the commit; single and self-contained. ## Review Readiness - [x] I have performed a self-review - [x] This PR is ready for human review ## Checklist - [x] My code follows the project's style guidelines - [x] I have performed a self-review of my code - [x] I have commented my code, particularly in hard-to-understand areas - [x] I have made corresponding changes to the documentation - [x] My changes generate no new warnings - [x] I have added tests that prove my fix is effective or that my feature works - [x] New and existing unit tests pass locally with my changes - [x] I did **not** edit `CHANGELOG.md` — it is generated by release-please from my Conventional Commit PR title (a CI guard enforces this) ## Screenshots (if applicable) N/A — terminal output above. ## Additional Notes **Scope.** Three changes in one PR, against the "one logical change" guidance. They share a single root cause: this bug was only findable by reading `/metrics`, because the failing path emitted no status, no counter, and (see below) no usable log line. The counter and the env var are the observability that should have made it a five-minute diagnosis instead of a forensic exercise. Happy to split the `HEADROOM_LOG_LEVEL` change into its own PR if you would rather keep the fix minimal — just say so. **Related defect, filed separately as #3087.** While producing the proof above I found that the proxy's own `logger.error("Connection error to upstream API: ...")` never reaches stdout: that run produced **zero** `headroom.proxy` logger lines, only uvicorn's own. Root cause is `_setup_file_logging()` setting `propagate = False` on the `headroom` logger (`helpers.py:1536`), which sends every application record to `~/.headroom/logs/proxy.log` and nowhere else — invisible in any container, where stdout is the log channel. That is precisely why this PR adds a counter rather than trusting a log line. Not fixed here: the right remedy is a maintainer call, so it is written up in #3087 with a repro rather than folded into this PR. **No dependency changes.** The dead-upstream harness used for the proof above is ~25 lines (`ProxyConfig(anthropic_api_url="http://127.0.0.1:59999")` + `uvicorn.run(create_app(config))`); happy to contribute it as an e2e test if that is useful. Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com> |
||
|---|---|---|
| .. | ||
| agent-orchestration.mdx | ||
| agno.mdx | ||
| anthropic-sdk.mdx | ||
| api-reference.mdx | ||
| architecture.mdx | ||
| autogen.mdx | ||
| benchmarks.mdx | ||
| cache-optimization.mdx | ||
| ccr.mdx | ||
| ci-cd-flows.mdx | ||
| claude-code-azure-foundry.mdx | ||
| claude-code-vertex.mdx | ||
| code-compression.mdx | ||
| codex-recovery.mdx | ||
| configuration.mdx | ||
| context-management.mdx | ||
| crewai.mdx | ||
| docker-install.mdx | ||
| errors.mdx | ||
| failure-learning.mdx | ||
| filesystem-contract.mdx | ||
| grok-build.mdx | ||
| how-compression-works.mdx | ||
| image-compression.mdx | ||
| index.mdx | ||
| installation.mdx | ||
| langchain.mdx | ||
| limitations.mdx | ||
| litellm.mdx | ||
| local-llm-prefill.mdx | ||
| mcp.mdx | ||
| memory.mdx | ||
| meta.json | ||
| metrics.mdx | ||
| openai-sdk.mdx | ||
| opencode-deepseek.mdx | ||
| opencode.mdx | ||
| persistent-installs.mdx | ||
| pipeline-extensions.mdx | ||
| proxy.mdx | ||
| quickstart.mdx | ||
| releases.mdx | ||
| runtime-rollouts.mdx | ||
| savings.mdx | ||
| shared-context.mdx | ||
| simulation.mdx | ||
| smart-crusher.mdx | ||
| strands.mdx | ||
| text-and-logs.mdx | ||
| troubleshooting.mdx | ||
| vercel-ai-sdk.mdx | ||
| vscode-claude-code.mdx | ||
| vscode-copilot.mdx | ||