mirror of
https://github.com/headroomlabs-ai/headroom.git
synced 2026-08-27 14:17:10 -04:00
## 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>
178 lines
6.5 KiB
Python
178 lines
6.5 KiB
Python
"""Unit tests for fail-open compression observability counters.
|
|
|
|
Covers the related counters added to ``PrometheusMetrics``:
|
|
|
|
* ``headroom_compression_failed_total{reason}`` — recorded at the proxy's
|
|
optimization fail-open site, split into "timeout" vs "error".
|
|
* ``headroom_kompress_size_gate_total{outcome}`` — recorded by ContentRouter
|
|
via the observer hook, split into "exceeded" vs "within".
|
|
* ``headroom_compression_quarantine_total{event}`` — records quarantine
|
|
activation and immediate executor skips while a timed-out worker remains.
|
|
* ``headroom_upstream_connection_errors_total{provider}`` — recorded when the
|
|
streaming path exhausts its connect retries and answers 502 itself.
|
|
|
|
Imports only the metrics module so the test stays free of heavy ML deps.
|
|
"""
|
|
|
|
from __future__ import annotations
|
|
|
|
import asyncio
|
|
import threading
|
|
|
|
import pytest
|
|
|
|
from headroom.proxy.prometheus_metrics import PrometheusMetrics
|
|
|
|
|
|
def test_record_compression_failed_buckets_by_reason() -> None:
|
|
metrics = PrometheusMetrics()
|
|
|
|
metrics.record_compression_failed("timeout")
|
|
metrics.record_compression_failed("error")
|
|
metrics.record_compression_failed("error")
|
|
|
|
assert metrics.compression_failed_by_reason["timeout"] == 1
|
|
assert metrics.compression_failed_by_reason["error"] == 2
|
|
|
|
|
|
def test_record_compression_failed_empty_reason_defaults_to_error() -> None:
|
|
metrics = PrometheusMetrics()
|
|
|
|
metrics.record_compression_failed("")
|
|
|
|
assert metrics.compression_failed_by_reason["error"] == 1
|
|
|
|
|
|
def test_record_upstream_connection_error_buckets_by_provider() -> None:
|
|
metrics = PrometheusMetrics()
|
|
|
|
metrics.record_upstream_connection_error("anthropic")
|
|
metrics.record_upstream_connection_error("openai")
|
|
metrics.record_upstream_connection_error("openai")
|
|
|
|
assert metrics.upstream_connection_errors_by_provider["anthropic"] == 1
|
|
assert metrics.upstream_connection_errors_by_provider["openai"] == 2
|
|
|
|
|
|
def test_record_upstream_connection_error_empty_provider_defaults_to_unknown() -> None:
|
|
metrics = PrometheusMetrics()
|
|
|
|
metrics.record_upstream_connection_error("")
|
|
|
|
assert metrics.upstream_connection_errors_by_provider["unknown"] == 1
|
|
|
|
|
|
async def test_upstream_connection_errors_exported_in_prometheus_text() -> None:
|
|
metrics = PrometheusMetrics()
|
|
metrics.record_upstream_connection_error("anthropic")
|
|
|
|
text = await metrics.export()
|
|
|
|
assert "# TYPE headroom_upstream_connection_errors_total counter" in text
|
|
assert 'headroom_upstream_connection_errors_total{provider="anthropic"} 1' in text
|
|
|
|
|
|
def test_record_kompress_size_gate_buckets_by_outcome() -> None:
|
|
metrics = PrometheusMetrics()
|
|
|
|
metrics.record_kompress_size_gate("exceeded")
|
|
metrics.record_kompress_size_gate("within")
|
|
metrics.record_kompress_size_gate("within")
|
|
|
|
assert metrics.kompress_size_gate_by_outcome["exceeded"] == 1
|
|
assert metrics.kompress_size_gate_by_outcome["within"] == 2
|
|
|
|
|
|
def test_record_compression_quarantine_buckets_by_event() -> None:
|
|
metrics = PrometheusMetrics()
|
|
|
|
metrics.record_compression_quarantine("activated")
|
|
metrics.record_compression_quarantine("skipped")
|
|
metrics.record_compression_quarantine("skipped")
|
|
|
|
assert metrics.compression_quarantine_by_event["activated"] == 1
|
|
assert metrics.compression_quarantine_by_event["skipped"] == 2
|
|
|
|
|
|
@pytest.mark.asyncio
|
|
async def test_counters_exported_in_prometheus_text() -> None:
|
|
metrics = PrometheusMetrics()
|
|
|
|
metrics.record_compression_failed("timeout")
|
|
metrics.record_compression_failed("error")
|
|
metrics.record_kompress_size_gate("exceeded")
|
|
metrics.record_kompress_size_gate("within")
|
|
metrics.record_compression_quarantine("activated")
|
|
metrics.record_compression_quarantine("skipped")
|
|
|
|
text = await metrics.export()
|
|
|
|
assert "# TYPE headroom_compression_failed_total counter" in text
|
|
assert 'headroom_compression_failed_total{reason="timeout"} 1' in text
|
|
assert 'headroom_compression_failed_total{reason="error"} 1' in text
|
|
|
|
assert "# TYPE headroom_kompress_size_gate_total counter" in text
|
|
assert 'headroom_kompress_size_gate_total{outcome="exceeded"} 1' in text
|
|
assert 'headroom_kompress_size_gate_total{outcome="within"} 1' in text
|
|
|
|
assert "# TYPE headroom_compression_quarantine_total counter" in text
|
|
assert 'headroom_compression_quarantine_total{event="activated"} 1' in text
|
|
assert 'headroom_compression_quarantine_total{event="skipped"} 1' in text
|
|
|
|
|
|
@pytest.mark.asyncio
|
|
async def test_counters_absent_from_export_until_recorded() -> None:
|
|
metrics = PrometheusMetrics()
|
|
|
|
text = await metrics.export()
|
|
|
|
# Conditional emission: the families only appear once a sample exists,
|
|
# matching the other labelled-counter blocks in export().
|
|
assert "headroom_compression_failed_total" not in text
|
|
assert "headroom_kompress_size_gate_total" not in text
|
|
assert "headroom_compression_quarantine_total" not in text
|
|
|
|
|
|
@pytest.mark.asyncio
|
|
async def test_reset_runtime_clears_observability_counters() -> None:
|
|
metrics = PrometheusMetrics()
|
|
|
|
metrics.record_compression_failed("timeout")
|
|
metrics.record_kompress_size_gate("exceeded")
|
|
metrics.record_compression_quarantine("activated")
|
|
|
|
await metrics.reset_runtime()
|
|
|
|
assert dict(metrics.compression_failed_by_reason) == {}
|
|
assert dict(metrics.kompress_size_gate_by_outcome) == {}
|
|
assert dict(metrics.compression_quarantine_by_event) == {}
|
|
|
|
|
|
@pytest.mark.asyncio
|
|
async def test_gate_counter_is_thread_safe_under_concurrent_export() -> None:
|
|
# record_kompress_size_gate runs on the compression executor thread while
|
|
# export() reads from the event loop. Concurrent unguarded access would
|
|
# lose increments or raise "dictionary changed size during iteration".
|
|
metrics = PrometheusMetrics()
|
|
n_threads, per_thread = 8, 4000
|
|
errors: list[str] = []
|
|
|
|
def hammer() -> None:
|
|
for i in range(per_thread):
|
|
metrics.record_kompress_size_gate("within" if i % 2 else "exceeded")
|
|
|
|
threads = [threading.Thread(target=hammer) for _ in range(n_threads)]
|
|
for t in threads:
|
|
t.start()
|
|
while any(t.is_alive() for t in threads):
|
|
try:
|
|
await metrics.export()
|
|
except Exception as exc: # pragma: no cover - failure path
|
|
errors.append(repr(exc))
|
|
await asyncio.sleep(0)
|
|
for t in threads:
|
|
t.join()
|
|
|
|
assert not errors, f"export() raced the writer: {errors[:3]}"
|
|
totals = dict(metrics.kompress_size_gate_by_outcome)
|
|
assert sum(totals.values()) == n_threads * per_thread
|