mirror of
https://github.com/headroomlabs-ai/headroom.git
synced 2026-08-27 14:17:10 -04:00
## Description Closes #3088 The buffered CCR path flips a streaming turn to `stream: false` so a `headroom_retrieve` call can be resolved server-side. Everything it does *after* the provider answers — retrieval, memory tool calls, turn hooks, usage accounting, caching, SSE resynthesis — is post-processing layered on a turn that already succeeded and was already billed. When any of that raised, the entire turn surfaced to the client as a generic `api_error`. In the reported capture the provider returned a complete **69,351-byte** answer in 1.9s and the client received **1,841 bytes**: keepalives, then a synthesized failure. A paid-for response was discarded because a bookkeeping step downstream of it broke. **On the reporter's stated root cause:** the "≈30s compression timeout" inference does not hold. Their own log says *"[12 seconds later]"*, which matches 49 pings × the 0.25s post-commit interval, not 30s. And `COMPRESSION_TIMEOUT_SECONDS` guards `_count_offloaded`, which **fails open** to estimation and cannot propagate. So that correlation is a coincidence. **What actually raises is still unidentified**, and that is the second half of this report. The handler logged `f"Request failed: {type(e).__name__}: {e}"` with no `exc_info`, which is exactly why the reporter found "no visible traceback" — and why reading the entire post-upstream path (memory tool calls, `run_response_hooks`, CCR handling all catch internally) does not reveal it either. ## Type of Change - [x] Bug fix (non-breaking change that fixes an issue) ## Changes Made - Capture the upstream response the moment it parses as a 200, before any post-processing can touch it. - Wrap the buffered operation so an unexpected raise relays that captured response as SSE instead of a synthesized error. - Log the exception with `exc_info=True`. Salvaging **without** this would paper over the defect permanently; the goal is to stop losing user turns while making the real bug diagnosable. - Refuse to salvage a response the client cannot safely consume. A reply still carrying an unresolved `headroom_retrieve` call is exactly the case the handler already fails closed on — relaying it would hand the client a tool call it is not expected to service and a marker nobody expanded. The check reuses the existing `residual_ccr_status` / `has_ccr_tool_calls` signals rather than inventing a second notion of "safe". **This is containment, not root cause.** It converts a hard failure on a successful turn into a degraded success, and makes the underlying raise visible so it can be fixed properly. I have said so in the commit message too, so this is not mistaken for a full diagnosis later. ## Testing - [x] Unit tests pass (`pytest`) - [x] Linting passes (`ruff check .`) - [x] New tests added for new functionality - [x] Manual testing performed New `tests/test_buffered_ccr_salvage.py` covers the reported shape (thinking + text, and the captured `bash` tool_use turn with no retrieve call), that the healthy path is untouched, and that an unresolved retrieve call is never relayed. ### Test Output ```text # BEFORE (main) — the same test file reproduces the report exactly: E AssertionError: {"type": "error", "error": {"type": "api_error", "message": "An error occurred while processing your request. Please try again."}} E assert 502 == 200 # AFTER (this branch): $ pytest tests/test_buffered_ccr_salvage.py -q 8 passed, 1 warning in 2.94s $ pytest tests/ -q 3 failed, 11168 passed, 581 skipped in 421.26s (0:07:01) Same 3 failures as a clean-main baseline run on this machine: tests/test_graceful_shutdown.py::test_run_server_installs_cancelled_error_filter tests/test_learn/test_integration.py::TestCodexIntegration::test_full_pipeline tests/test_release_workflows.py::test_no_native_tls_in_wheel_build_tree $ ruff check . && ruff format --check . All checks passed! ``` ## Real Behavior Proof - Environment: this branch driven through the real FastAPI app with a stubbed upstream returning a complete 200 turn; macOS arm64, Python 3.12. - Exact command / steps: posted a buffered CCR turn, then forced a post-upstream step to raise (`_record_request_outcome`), standing in for whatever breaks in the field; ran the identical test file against `main` and against this branch. - Observed result: on `main` the client gets HTTP 502 with the report's literal `api_error` string; on this branch the client gets HTTP 200 `text/event-stream` carrying the provider's own content (`message_start`, thinking, text / `toolu_bash`) and no invented error. - Not tested: the field defect itself. What raises in the reporter's environment is still unknown — that is what the added traceback logging exists to surface. A follow-up will need their logs on a build carrying this change. ## Runtime Rollout Safety - Rollout-managed feature(s): none — this guards an existing code path and is not behind a rollout channel. - Minimum rollout channel: n/a (ships to stable with the fix). - Stable/default behavior changed: yes, and only in the failure case. A buffered turn whose post-processing raises now returns the upstream's answer instead of a 502 `api_error`. Successful turns are byte-identical. - Kill switch / disable path: no new switch. The guard only engages on an exception that previously produced a hard failure, so disabling it would restore the bug. - Unsafe override required: no. - Qualification impact: none — no qualification-gated surface is touched. - Rollback path: revert this commit; the previous behavior (synthesized `api_error`) returns. ## 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] 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` ## Additional Notes Documentation update is marked N/A: no user-facing flag or endpoint changes. Type checking (`mypy headroom`) was not run separately; `ruff` is the gate this repo's CI enforces. Same family, still open: #3078, #3082, #3017, #2857, #2825. The added traceback is the fastest route to whether they share this root cause. 🤖 Generated with [Claude Code](https://claude.com/claude-code) Co-authored-by: Tejas Chopra <tejas@Tejass-MacBook-Pro.local> Co-authored-by: Claude Opus 5 <noreply@anthropic.com>
228 lines
7.7 KiB
Python
228 lines
7.7 KiB
Python
"""A successful upstream turn must never become a synthesized error (#3088).
|
|
|
|
The buffered CCR path flips a streaming turn to ``stream: false`` so retrieval
|
|
can be resolved server-side. Everything it does *after* the provider answers —
|
|
retrieval, memory tool calls, turn hooks, usage accounting, caching, SSE
|
|
resynthesis — is post-processing layered on a turn that already succeeded and
|
|
was already billed.
|
|
|
|
When one of those steps raised, the whole turn surfaced to the client as:
|
|
|
|
event: error
|
|
data: {"type":"error","error":{"type":"api_error", ...}}
|
|
|
|
In the reported capture the provider had returned a complete 69,351-byte answer
|
|
in 1.9s; the client received 1,841 bytes of keepalives and that error. The
|
|
answer was paid for and thrown away, and no traceback was logged, so the real
|
|
defect stayed invisible.
|
|
|
|
These tests pin the two halves of the fix: relay the upstream's own answer
|
|
rather than inventing a failure, and refuse to relay a response the client
|
|
cannot safely consume.
|
|
"""
|
|
|
|
from __future__ import annotations
|
|
|
|
import json
|
|
|
|
import pytest
|
|
|
|
fastapi = pytest.importorskip("fastapi")
|
|
httpx = pytest.importorskip("httpx")
|
|
|
|
from fastapi.testclient import TestClient # noqa: E402
|
|
|
|
from headroom.cache.backends import InMemoryBackend # noqa: E402
|
|
from headroom.cache.compression_store import ( # noqa: E402
|
|
get_compression_store,
|
|
reset_compression_store,
|
|
)
|
|
from headroom.ccr.tool_injection import create_ccr_tool_definition # noqa: E402
|
|
from headroom.proxy.server import ProxyConfig, create_app # noqa: E402
|
|
|
|
|
|
def _config() -> ProxyConfig:
|
|
return ProxyConfig(
|
|
optimize=False,
|
|
cache_enabled=False,
|
|
rate_limit_enabled=False,
|
|
memory_enabled=False,
|
|
ccr_inject_tool=True,
|
|
ccr_handle_responses=True,
|
|
ccr_context_tracking=False,
|
|
image_optimize=False,
|
|
# Commit immediately, so a failure is exercised on the committed path
|
|
# too — the shape the report was filed against.
|
|
buffered_ccr_grace_seconds=5.0,
|
|
)
|
|
|
|
|
|
@pytest.fixture(autouse=True)
|
|
def _store():
|
|
reset_compression_store()
|
|
get_compression_store(backend=InMemoryBackend())
|
|
try:
|
|
yield
|
|
finally:
|
|
reset_compression_store()
|
|
|
|
|
|
def _marker() -> str:
|
|
return get_compression_store().store(
|
|
original=json.dumps({"earlier": "tool output"}),
|
|
compressed="{}",
|
|
original_item_count=1,
|
|
)
|
|
|
|
|
|
def _upstream(content: list[dict], stop_reason: str = "end_turn") -> dict:
|
|
return {
|
|
"id": "msg_upstream",
|
|
"type": "message",
|
|
"role": "assistant",
|
|
"model": "claude-sonnet-4-6",
|
|
"content": content,
|
|
"stop_reason": stop_reason,
|
|
"usage": {
|
|
"input_tokens": 1200,
|
|
"output_tokens": 295,
|
|
"cache_read_input_tokens": 0,
|
|
"cache_creation_input_tokens": 0,
|
|
},
|
|
}
|
|
|
|
|
|
def _body() -> dict:
|
|
return {
|
|
"model": "claude-sonnet-4-6",
|
|
"max_tokens": 512,
|
|
"stream": True,
|
|
"tools": [create_ccr_tool_definition("anthropic")],
|
|
"messages": [{"role": "user", "content": f"go (earlier output at <<ccr:{_marker()}>>)"}],
|
|
}
|
|
|
|
|
|
def _headers() -> dict[str, str]:
|
|
return {"x-api-key": "test-key", "anthropic-version": "2023-06-01"}
|
|
|
|
|
|
def _run(upstream: dict, *, break_post_processing: bool):
|
|
"""Drive one buffered turn, optionally exploding after the upstream answers."""
|
|
app = create_app(_config())
|
|
with TestClient(app) as client:
|
|
proxy = client.app.state.proxy
|
|
|
|
async def _fake_retry(method, url, headers, body, stream=False, **kwargs): # noqa: ANN001
|
|
return httpx.Response(200, json=upstream)
|
|
|
|
proxy._retry_request = _fake_retry # type: ignore[assignment]
|
|
|
|
if break_post_processing:
|
|
# Stand in for any of the post-upstream steps failing. The point is
|
|
# that the provider already answered; what broke is ours.
|
|
real = proxy._record_request_outcome
|
|
|
|
async def _boom(*args, **kwargs): # noqa: ANN002, ANN003
|
|
raise RuntimeError("post-processing exploded")
|
|
|
|
proxy._record_request_outcome = _boom # type: ignore[assignment]
|
|
assert real is not None
|
|
|
|
return client.post("/v1/messages", json=_body(), headers=_headers())
|
|
|
|
|
|
# --------------------------------------------------------------------------- #
|
|
# The reported failure
|
|
# --------------------------------------------------------------------------- #
|
|
def test_a_successful_turn_survives_post_processing_blowing_up() -> None:
|
|
"""The whole point: the client gets the answer the provider produced."""
|
|
upstream = _upstream(
|
|
[
|
|
{"type": "thinking", "thinking": "reasoning", "signature": "sig-1"},
|
|
{"type": "text", "text": "here is the answer"},
|
|
]
|
|
)
|
|
|
|
resp = _run(upstream, break_post_processing=True)
|
|
|
|
assert resp.status_code == 200, resp.text
|
|
assert "text/event-stream" in resp.headers["content-type"]
|
|
# The provider's content reaches the client...
|
|
assert "here is the answer" in resp.text
|
|
assert "message_start" in resp.text
|
|
# ...and no invented failure does.
|
|
assert "api_error" not in resp.text
|
|
|
|
|
|
def test_a_client_tool_call_is_salvaged_too() -> None:
|
|
"""The captured failure was a `bash` tool_use turn with no retrieve call."""
|
|
upstream = _upstream(
|
|
[
|
|
{"type": "thinking", "thinking": "plan", "signature": "sig-2"},
|
|
{
|
|
"type": "tool_use",
|
|
"id": "toolu_bash",
|
|
"name": "bash",
|
|
"input": {"command": "ls"},
|
|
},
|
|
],
|
|
stop_reason="tool_use",
|
|
)
|
|
|
|
resp = _run(upstream, break_post_processing=True)
|
|
|
|
assert resp.status_code == 200, resp.text
|
|
assert "toolu_bash" in resp.text
|
|
assert "api_error" not in resp.text
|
|
|
|
|
|
def test_the_healthy_path_is_untouched() -> None:
|
|
"""Salvage must not change a turn that never failed."""
|
|
upstream = _upstream([{"type": "text", "text": "ordinary answer"}])
|
|
|
|
resp = _run(upstream, break_post_processing=False)
|
|
|
|
assert resp.status_code == 200, resp.text
|
|
assert "ordinary answer" in resp.text
|
|
assert "api_error" not in resp.text
|
|
|
|
|
|
# --------------------------------------------------------------------------- #
|
|
# What must never be salvaged
|
|
# --------------------------------------------------------------------------- #
|
|
def test_an_unresolved_retrieve_call_is_not_relayed() -> None:
|
|
"""Failing closed here is deliberate and stays that way.
|
|
|
|
The buffered path exists to resolve ``headroom_retrieve`` server-side. A
|
|
response still carrying one is precisely the case the handler already fails
|
|
closed on — relaying it would hand the client a tool call it is not expected
|
|
to service and a marker nobody expanded.
|
|
"""
|
|
app = create_app(_config())
|
|
with TestClient(app) as client:
|
|
proxy = client.app.state.proxy
|
|
unresolved = _upstream(
|
|
[
|
|
{
|
|
"type": "tool_use",
|
|
"id": "toolu_ccr",
|
|
"name": "headroom_retrieve",
|
|
"input": {"hash_key": "deadbeefcafe"},
|
|
}
|
|
],
|
|
stop_reason="tool_use",
|
|
)
|
|
assert proxy._can_salvage_buffered_upstream(unresolved) is False
|
|
|
|
# An ordinary turn is salvageable, so the guard is not simply off.
|
|
assert (
|
|
proxy._can_salvage_buffered_upstream(_upstream([{"type": "text", "text": "hi"}]))
|
|
is True
|
|
)
|
|
|
|
|
|
@pytest.mark.parametrize("bad", [None, "not-a-dict", 42, []])
|
|
def test_a_non_dict_response_is_never_salvaged(bad) -> None: # type: ignore[no-untyped-def]
|
|
app = create_app(_config())
|
|
with TestClient(app) as client:
|
|
assert client.app.state.proxy._can_salvage_buffered_upstream(bad) is False
|