fix(learn): include stdout in CLI failure messages, not just stderr (#3080)
## Description `headroom learn` reports CLI backend failures using **stderr only**. `claude -p --output-format stream-json --verbose` writes *nothing* to stderr when the run fails at the API layer, so the failure a user actually sees is a message that stops at the colon: ```text LLM analysis failed: `claude -p --output-format stream-json --verbose` failed (exit 1): ``` The reason is not missing, it is discarded. Claude Code still emits a final `result` event on stdout whose `result` field is the human-readable cause, and the streaming path has already parsed it into `final_result` one line above the `raise`. This makes a whole class of failures undiagnosable for users and maintainers alike: a usage limit, an unreachable local proxy, and an expired login all render identically as an empty message. Reported by a desktop user who could only tell us "sometimes i have this LLM analysis failed" with nothing after the colon. ## Type of Change - [x] Bug fix (non-breaking change that fixes an issue) ## Changes Made - Add `_failure_detail(stderr, stdout, *, result_text=None)` in `headroom/learn/analyzer.py`. Prefers the already-parsed `result` text, falls back to the **tail** of stdout (CLI backends emit the error last, after their whole event log), keeps stderr when present, and returns `"(no output captured)"` so the message is never a dangling colon. - Use it in `_call_claude_cli_streaming` (streaming claude-cli path) and in `_call_cli_llm` (the `subprocess.run` backends, gemini-cli / codex-cli), so the same blind spot is closed for every CLI backend rather than only the one that was reported. - Existing truncation behaviour is unchanged: each stream is still capped at `_MAX_SNIPPET_LEN`. Complements #3016, which makes an analysis failure propagate instead of being swallowed as success; that PR fixes *whether* the user learns a failure happened, this one fixes *what* the failure says. No overlapping lines. ## 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 Output ```text $ uv run --frozen --extra dev pytest tests/test_learn/ -q 247 passed, 4 skipped in 27.08s $ uvx ruff check headroom/learn/analyzer.py tests/test_learn/test_analyzer.py All checks passed! $ uvx ruff format --check headroom/learn/analyzer.py tests/test_learn/test_analyzer.py 2 files already formatted $ uv run --frozen --extra dev mypy headroom/learn/analyzer.py Success: no issues found in 1 source file ``` New tests: `test_claude_cli_nonzero_exit_includes_api_error_from_stdout`, `test_claude_cli_nonzero_exit_with_no_output_says_so`, `test_claude_cli_nonzero_exit_keeps_stderr_when_present`, `test_codex_nonzero_exit_includes_stdout_when_stderr_empty`. ## Real Behavior Proof - Environment: macOS 15.6 (Darwin 24.6.0), Claude Code 2.1.228, Python 3.10.18, headroom on this branch. - Exact command / steps: forced an API-layer failure in the exact command the analyzer runs, capturing the streams separately: `echo "say hi" | claude -p --output-format stream-json --verbose --settings '{"env":{"ANTHROPIC_BASE_URL":"http://127.0.0.1:9"}}' > out.txt 2> err.txt; echo "EXIT=$?"; wc -c err.txt; tail -c 400 out.txt` - Observed result: `EXIT=1`, `err.txt` is **0 bytes**, and the reason appears only in the last stdout line: `"terminal_reason":"api_error", ..., "result":"API Error: Connection refused — a firewall or proxy may be blocking it (ConnectionRefused)"`. A second run with `--bare` produced the same shape with `"result":"Not logged in · Please run /login"`. Before this change both surface as `failed (exit 1):` with nothing after the colon; after it, the `result` text is in the message. The unit tests encode this exact stream shape (stdout `result` event, empty stderr, exit 1). - Not tested: real usage-limit and 429 responses, which I cannot provoke on demand. They travel the same code path as the reproduced `api_error` case (final `result` event on stdout, empty stderr), so they are covered by construction rather than by observation. Windows and the gemini-cli backend were not exercised manually; the shared helper is covered by unit tests for both the streaming and `subprocess.run` paths. ## Runtime Rollout Safety - Rollout-managed feature(s): None. This touches only the error text raised by `headroom learn`'s CLI backends; no rollout-gated feature, flag, or runtime component is involved. - Minimum rollout channel: N/A, not rollout-gated. Ships with the package like any other library fix. - Stable/default behavior changed: Yes, narrowly. The message text of an existing `RuntimeError` on a non-zero CLI exit now includes the stdout/`result` reason alongside stderr. No control flow, exit code, public API, or return value changes: the same exception is raised in the same cases. - Kill switch / disable path: None needed. Nothing is enabled or newly executed, so there is nothing to switch off; the only behavioral surface is the string inside an exception that was already being raised. - Unsafe override required: No. - Qualification impact: None. No qualification-gated path, model, or provider behavior is touched. Callers that pattern-match this message on `"failed (exit N)"` still match, since that prefix is unchanged. - Rollback path: Revert this commit. The previous stderr-only message returns with no migration, state, or config to undo. ## Review Readiness - [x] I have performed a self-review - [x] This PR is ready for human review Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
This commit is contained in:
gglucass
@@ -539,6 +539,40 @@ def _strip_fenced_json(raw: str) -> dict:
|
||||
return result
|
||||
|
||||
|
||||
def _failure_detail(
|
||||
stderr: str | None, stdout: str | None, *, result_text: str | None = None
|
||||
) -> str:
|
||||
"""Build the operator-facing reason for a non-zero CLI exit.
|
||||
|
||||
stderr alone is not enough. `claude -p --output-format stream-json` writes
|
||||
*nothing* to stderr and reports API failures only in its final ``result``
|
||||
event on stdout, so a stderr-only message renders as a bare
|
||||
``failed (exit 1):`` with no reason at all -- the user (and we) cannot tell a
|
||||
usage limit from an unreachable proxy from an expired login.
|
||||
|
||||
Both streams are included when both have content, and stdout is tailed rather
|
||||
than headed because CLI backends emit the error last (a streaming backend's
|
||||
whole event log precedes it).
|
||||
|
||||
Args:
|
||||
stderr: Captured stderr, if any.
|
||||
stdout: Captured stdout, if any.
|
||||
result_text: Pre-extracted reason (claude-cli's final ``result`` field),
|
||||
used in place of the raw stdout tail when available.
|
||||
|
||||
Returns:
|
||||
A non-empty snippet, or ``"(no output captured)"`` when both streams were
|
||||
empty, so the message is never a dangling colon.
|
||||
"""
|
||||
parts: list[str] = []
|
||||
if stderr and stderr.strip():
|
||||
parts.append(stderr.strip()[:_MAX_SNIPPET_LEN])
|
||||
tail = result_text if result_text and result_text.strip() else stdout
|
||||
if tail and tail.strip():
|
||||
parts.append(tail.strip()[-_MAX_SNIPPET_LEN:])
|
||||
return "\n".join(parts) if parts else "(no output captured)"
|
||||
|
||||
|
||||
def _call_cli_llm(digest: str, model: str) -> dict:
|
||||
"""Call a locally installed CLI tool as the LLM backend.
|
||||
|
||||
@@ -611,10 +645,8 @@ def _call_cli_llm(digest: str, model: str) -> dict:
|
||||
) from None
|
||||
|
||||
if result.returncode != 0:
|
||||
stderr_snippet = (result.stderr or "")[:_MAX_SNIPPET_LEN]
|
||||
raise RuntimeError(
|
||||
f"`{' '.join(cmd)}` failed (exit {result.returncode}):\n{stderr_snippet}"
|
||||
)
|
||||
detail = _failure_detail(result.stderr, result.stdout)
|
||||
raise RuntimeError(f"`{' '.join(cmd)}` failed (exit {result.returncode}):\n{detail}")
|
||||
|
||||
# Log stderr warnings even on success (auth refreshes, deprecation notices).
|
||||
if result.stderr and result.stderr.strip():
|
||||
@@ -757,8 +789,14 @@ def _call_claude_cli_streaming(
|
||||
proc.wait()
|
||||
|
||||
if proc.returncode != 0:
|
||||
stderr_blob = "".join(stderr_lines)[:_MAX_SNIPPET_LEN]
|
||||
raise RuntimeError(f"`{' '.join(cmd)}` failed (exit {proc.returncode}):\n{stderr_blob}")
|
||||
# `final_result` is preferred over the raw stdout tail: claude emits a
|
||||
# final `result` event even when the run fails, and its `result` field is
|
||||
# the human-readable reason ("API Error: ...", "Not logged in", usage
|
||||
# limits).
|
||||
detail = _failure_detail(
|
||||
"".join(stderr_lines), "".join(stdout_lines), result_text=final_result
|
||||
)
|
||||
raise RuntimeError(f"`{' '.join(cmd)}` failed (exit {proc.returncode}):\n{detail}")
|
||||
|
||||
stderr_blob = "".join(stderr_lines)
|
||||
if stderr_blob.strip():
|
||||
|
||||
@@ -796,6 +796,51 @@ class TestCallCliLlm:
|
||||
with pytest.raises(RuntimeError, match="failed.*exit 1"):
|
||||
_call_cli_llm("test digest", "claude-cli")
|
||||
|
||||
def test_claude_cli_nonzero_exit_includes_api_error_from_stdout(self):
|
||||
# Regression: `claude -p --output-format stream-json` writes NOTHING to
|
||||
# stderr on an API failure. It still emits a final `result` event whose
|
||||
# `result` field carries the reason, so a stderr-only message rendered as
|
||||
# a bare "failed (exit 1):" with no cause for the user or the logs.
|
||||
api_error = "API Error: Connection refused — a firewall or proxy may be blocking it"
|
||||
stdout = [
|
||||
_stream_event("system", subtype="init"),
|
||||
_stream_event(
|
||||
"result",
|
||||
subtype="success",
|
||||
is_error=False,
|
||||
terminal_reason="api_error",
|
||||
result=api_error,
|
||||
),
|
||||
]
|
||||
popen = _fake_claude_popen(stdout_lines=stdout, stderr_lines=[], returncode=1)
|
||||
with patch("headroom.learn.analyzer.subprocess.Popen", popen):
|
||||
with pytest.raises(RuntimeError) as exc_info:
|
||||
_call_cli_llm("test digest", "claude-cli")
|
||||
message = str(exc_info.value)
|
||||
assert "failed (exit 1)" in message
|
||||
assert api_error in message
|
||||
|
||||
def test_claude_cli_nonzero_exit_with_no_output_says_so(self):
|
||||
popen = _fake_claude_popen(stdout_lines=[], stderr_lines=[], returncode=1)
|
||||
with patch("headroom.learn.analyzer.subprocess.Popen", popen):
|
||||
with pytest.raises(RuntimeError) as exc_info:
|
||||
_call_cli_llm("test digest", "claude-cli")
|
||||
# Never a dangling colon: the message states that nothing was captured.
|
||||
assert "(no output captured)" in str(exc_info.value)
|
||||
|
||||
def test_claude_cli_nonzero_exit_keeps_stderr_when_present(self):
|
||||
popen = _fake_claude_popen(
|
||||
stdout_lines=[_result_event("partial")],
|
||||
stderr_lines=["Error: auth required\n"],
|
||||
returncode=1,
|
||||
)
|
||||
with patch("headroom.learn.analyzer.subprocess.Popen", popen):
|
||||
with pytest.raises(RuntimeError) as exc_info:
|
||||
_call_cli_llm("test digest", "claude-cli")
|
||||
message = str(exc_info.value)
|
||||
assert "auth required" in message
|
||||
assert "partial" in message
|
||||
|
||||
def test_claude_cli_unparseable_result_raises_with_context(self):
|
||||
stdout = [_result_event("This is not JSON at all")]
|
||||
with patch(
|
||||
@@ -843,6 +888,17 @@ class TestCallCliLlm:
|
||||
with pytest.raises(RuntimeError, match="failed.*exit 1"):
|
||||
_call_cli_llm("test digest", "codex-cli")
|
||||
|
||||
@patch("headroom.learn.analyzer.subprocess.run")
|
||||
def test_codex_nonzero_exit_includes_stdout_when_stderr_empty(self, mock_run: MagicMock):
|
||||
mock_run.return_value = MagicMock(
|
||||
returncode=1,
|
||||
stdout="stream error: rate limit exceeded",
|
||||
stderr="",
|
||||
)
|
||||
with pytest.raises(RuntimeError) as exc_info:
|
||||
_call_cli_llm("test digest", "codex-cli")
|
||||
assert "rate limit exceeded" in str(exc_info.value)
|
||||
|
||||
@patch("headroom.learn.analyzer.subprocess.run")
|
||||
def test_codex_stderr_truncated_in_error(self, mock_run: MagicMock):
|
||||
long_stderr = "x" * 5000
|
||||
|
||||
Reference in New Issue
Block a user