ouyangbo/hermes-agent
1
0
Fork 0
Code Issues Pull Requests Actions 10 Packages Projects Releases Wiki Activity

fix(tui_gateway): name the cause in the turn-finished record

Browse Source 
Fixes #89117

The whole of #89117 is two log lines:

    tui_turn finished: ui_session=0dfcee58 status=error error_retained=True duration=0.9s

A provider 4xx, a budget wall, a billing block and a crashed finalizer all
produce exactly those characters, so an intermittent failure cannot be
triaged from the one record that is guaranteed to exist.

The bookend came from #86865, which added it to trace compression
rotations across #86647 -- identities and a coarse status were the job, and
content was deliberately excluded. What that leaves is a returned-error
path (provider 4xx, budget, billing) which writes no other log line at all.
The exception path at least prints `[gateway-turn] <Type>: <msg>` to
stderr, so the failures that go unlogged are exactly the sub-second ones
this issue is about.

Both failure paths now stash a one-line cause, and the bookend appends it.
The record keeps its shape when nothing failed: a successful turn gains no
new fields.

The cause is redacted with `redact_sensitive_text(force=True)` and capped at
240 characters with a visible ellipsis, because a 4xx body routinely quotes
the request that produced it -- adding the cause without redacting it would
write an Authorization header the user never chose to log. Redaction fails
closed: if the redactor cannot run, the fragment reads `<unredactable>`
rather than the raw message. Whitespace is collapsed so a multi-line
provider body cannot split the record, which is the only property that
makes it greppable for a bug like this one.

12 regression tests. Four mutations proven: disabling the helper fails 9,
dropping redaction fails 2, dropping truncation fails 1, wiring only the
exception path fails 4.
This commit is contained in:
Jack Lau
2026-08-18 09:07:12 -05:00
committed by Teknium
parent 86fa1fcd4f
commit 23ca96052c
2 changed files with 351 additions and 1 deletions
Download Patch File Download Diff File Expand all files Collapse all files
tests/tui_gateway/test_turn_finished_failure_cause.py
+290
View File
@@ -0,0 +1,290 @@
"""A failed TUI turn must say why in its own record (#89117).
#89117 is a report made entirely of two log lines::
tui_turn finished: ui_session=0dfcee58 status=error error_retained=True duration=0.9s
tui_turn finished: ui_session=093285e9 status=error error_retained=True duration=0.9s
That is the whole evidence, and it is not enough to act on: a provider 4xx, a
budget wall, a billing block and a crashed finalizer all produce exactly those
characters. The bookend was added by #86865 to trace compression rotations, so
it carries identities and a coarse status by design — but it is also the *only*
record the returned-error path writes. A sub-second failure almost always takes
that path (the provider rejected the request before any work happened), so the
quietest failures are precisely the ones with nothing to read. The exception
path at least prints ``[gateway-turn] <Type>: <msg>`` to stderr.
These tests pin the cause into the record on both failure paths, and pin the
content discipline #86865 established while doing it: prompts are never logged,
and the provider's message is redacted and length-capped, because a 4xx body
can quote the request that produced it.
"""
from __future__ import annotations
import logging
import threading
import types
import pytest
from tui_gateway import server
class _InlineThread:
"""Run the turn synchronously so tests observe its final state."""
def __init__(self, target=None, daemon=None, args=(), kwargs=None):
self._target = target
self._args = args
self._kwargs = kwargs or {}
def start(self):
if self._target is not None:
self._target(*self._args, **self._kwargs)
def is_alive(self):
return False
def join(self, timeout=None):
return None
def _session(agent=None, **extra):
return {
"agent": agent if agent is not None else types.SimpleNamespace(),
"session_key": "gw-session-key",
"history": [],
"history_lock": threading.Lock(),
"history_version": 0,
"running": True,
"attached_images": [],
"image_counter": 0,
"cols": 80,
"slash_worker": None,
"show_reasoning": False,
"tool_progress_mode": "all",
"inflight_turn": None,
**extra,
}
@pytest.fixture()
def turn_env(monkeypatch, tmp_path):
"""Neutralize the turn pipeline's environment-heavy side paths."""
monkeypatch.setattr(server.threading, "Thread", _InlineThread)
monkeypatch.setattr(server, "_emit", lambda *a, **k: None)
monkeypatch.setattr(server, "_wire_callbacks", lambda sid: None)
monkeypatch.setattr(server, "_sync_agent_model_with_config", lambda sid, session: None)
monkeypatch.setattr(server, "_session_cwd", lambda session: str(tmp_path))
monkeypatch.setattr(server, "_register_session_cwd", lambda session: None)
monkeypatch.setattr(server, "_tts_stream_begin", lambda: None)
monkeypatch.setattr(server, "_sync_session_key_after_compress", lambda *a, **k: None)
monkeypatch.setattr(server, "_get_usage", lambda agent: {})
def _finished(caplog):
records = [r for r in caplog.records if "tui turn finished" in r.getMessage()]
assert len(records) == 1, f"expected exactly one bookend, got {len(records)}"
return records[0].getMessage()
def _run(session, prompt="go"):
server._run_prompt_submit("rid", "ui-sid", session, prompt)
def _agent_returning(result):
return types.SimpleNamespace(
session_id="agent-sid-1",
run_conversation=lambda *a, **k: result,
clear_interrupt=lambda: None,
)
class TestTheReportedRecordNowNamesItsCause:
def test_returned_error_carries_the_provider_message(self, turn_env, caplog):
"""The reporter's exact line shape, with the missing half filled in."""
session = _session(agent=_agent_returning({
"final_response": "",
"error": "Error code: 402 - {'error': {'message': 'insufficient credits'}}",
"failed": True,
}))
with caplog.at_level(logging.INFO, logger="tui_gateway.server"):
_run(session)
msg = _finished(caplog)
assert "status=error" in msg
assert "error_retained=True" in msg
assert "insufficient credits" in msg, (
"a record that says only status=error is what #89117 is about"
)
def test_structured_failure_reason_is_logged_when_present(self, turn_env, caplog):
"""The billing wall already ships a machine-readable reason; use it.
``failure_reason`` is the field the client renders a billing-specific
recovery surface from, so it is the one field guaranteed to be stable
enough to grep a log for across releases.
"""
session = _session(agent=_agent_returning({
"final_response": "",
"error": "payment required",
"failure_reason": "billing_wall",
"failed": True,
}))
with caplog.at_level(logging.INFO, logger="tui_gateway.server"):
_run(session)
assert "failure_reason=billing_wall" in _finished(caplog)
def test_exception_path_carries_the_exception(self, turn_env, caplog):
"""The other failure path, so one grep covers both."""
def _boom(*a, **k):
raise RuntimeError("connection reset mid-stream")
session = _session(agent=types.SimpleNamespace(
session_id="agent-sid-1",
run_conversation=_boom,
clear_interrupt=lambda: None,
))
with caplog.at_level(logging.INFO, logger="tui_gateway.server"):
_run(session)
msg = _finished(caplog)
assert "status=error" in msg
assert "failure_reason=RuntimeError" in msg
assert "connection reset mid-stream" in msg
def test_successful_turn_stays_exactly_as_it_was(self, turn_env, caplog):
"""No cost to the common case: a clean turn gains no new fields."""
session = _session(agent=_agent_returning({"final_response": "done"}))
with caplog.at_level(logging.INFO, logger="tui_gateway.server"):
_run(session)
msg = _finished(caplog)
assert "status=complete" in msg
assert "cause=" not in msg
assert "failure_reason=" not in msg
class TestContentDiscipline:
"""#86865's rule — the record logs identities, never content."""
SECRETISH_PROMPT = "please rotate QDRANT_API_KEY=hunter2-super-secret now"
def test_prompt_is_never_logged_even_when_the_turn_fails(self, turn_env, caplog):
session = _session(agent=_agent_returning({
"final_response": "",
"error": "provider rejected the request",
"failed": True,
}))
with caplog.at_level(logging.INFO, logger="tui_gateway.server"):
_run(session, self.SECRETISH_PROMPT)
msg = _finished(caplog)
assert "hunter2" not in msg
assert "QDRANT_API_KEY" not in msg
def test_secrets_echoed_back_by_the_provider_are_redacted(self, turn_env, caplog):
"""The load-bearing safety test.
A 4xx body frequently quotes the request. Without redaction, adding the
cause to a log record would take a header the user never chose to log
and write it to disk — turning a diagnostics improvement into a secret
leak. This is why the cause goes through ``redact_sensitive_text`` and
not ``str()``.
"""
session = _session(agent=_agent_returning({
"final_response": "",
"error": (
"400 from provider; request headers were "
"Authorization: Bearer sk-proj-abcdefghijklmnopqrstuvwxyz0123456789"
),
"failed": True,
}))
with caplog.at_level(logging.INFO, logger="tui_gateway.server"):
_run(session)
msg = _finished(caplog)
assert "sk-proj-abcdefghijklmnopqrstuvwxyz0123456789" not in msg
# The diagnostic value survives the redaction — this is the point.
assert "400 from provider" in msg
def test_a_huge_provider_body_cannot_flood_the_log(self, turn_env, caplog):
"""An HTML error page or a full request echo is a log-volume problem."""
session = _session(agent=_agent_returning({
"final_response": "",
"error": "upstream said: " + ("x" * 9000),
"failed": True,
}))
with caplog.at_level(logging.INFO, logger="tui_gateway.server"):
_run(session)
msg = _finished(caplog)
assert len(msg) < 700
assert "upstream said" in msg
assert "…" in msg, "truncation should be visible, not silent"
def test_a_multiline_traceback_stays_one_record(self, turn_env, caplog):
"""One accepted prompt, one finished record — including its cause.
A cause spanning lines would break every log pipeline that treats the
bookend as a single greppable line, which is the only reason it is
useful for an intermittent bug like this one.
"""
def _boom(*a, **k):
raise RuntimeError("first line\nsecond line\n\tthird")
session = _session(agent=types.SimpleNamespace(
session_id="agent-sid-1",
run_conversation=_boom,
clear_interrupt=lambda: None,
))
with caplog.at_level(logging.INFO, logger="tui_gateway.server"):
_run(session)
msg = _finished(caplog)
assert "\n" not in msg
assert "first line second line third" in msg
class TestDetailHelperDirectly:
"""``_turn_failure_detail`` in isolation — the branches the paths can't reach."""
def test_nothing_to_say_produces_nothing(self):
assert server._turn_failure_detail("", None) == ""
assert server._turn_failure_detail(None) == ""
def test_fragment_carries_its_own_leading_space(self):
"""The bookend appends it unconditionally, so it must self-format."""
out = server._turn_failure_detail("boom")
assert out.startswith(" ")
def test_an_exception_with_no_message_still_names_its_type(self):
assert "KeyError" in server._turn_failure_detail(KeyError())
def test_a_broken_redactor_fails_closed(self, monkeypatch):
"""If redaction cannot run, the raw message must not reach the log.
Failing open here would be worse than logging nothing: the whole reason
the cause is safe to log is that it went through the redactor.
"""
import agent.redact
def _explode(*a, **k):
raise RuntimeError("redactor unavailable")
monkeypatch.setattr(agent.redact, "redact_sensitive_text", _explode)
out = server._turn_failure_detail("Bearer sk-proj-supersecretvalue")
assert "supersecretvalue" not in out
assert "unredactable" in out
tui_gateway/server.py
+61 -1
View File
@@ -9977,6 +9977,54 @@ def _fail_inflight_turn(
session["inflight_turn"] = turn
_TURN_FAILURE_DETAIL_LIMIT = 240
def _turn_failure_detail(error: Any, reason: Any = None) -> str:
"""Render why a turn failed, for the ``tui turn finished`` bookend.
Returns ``""`` when there is nothing to say, otherwise a fragment that
already carries its own leading space, so the caller can append it to the
record unconditionally.
#86865 added the bookend to trace compression rotations, so it logs
identities and a coarse ``status`` and deliberately logs no content.
#89117 is what the missing cause costs: a report consisting of two lines
reading ``status=error error_retained=True duration=0.9s`` with no way to
tell a provider 4xx from a budget wall from a crashed finalizer. The
returned-error path -- the one a 0.9 s failure almost always takes --
emits no other log line at all; only the exception path prints to stderr,
which is why the quiet failures are the ones that get filed.
Content discipline follows #86865's: the prompt is never logged, and the
provider's message is redacted and truncated before it reaches a log file,
because a 4xx body can quote the request that produced it.
"""
reason_text = str(reason or "").strip()
message = str(error or "").strip()
if isinstance(error, BaseException):
message = message or type(error).__name__
if not message and not reason_text:
return ""
try:
from agent.redact import redact_sensitive_text
message = redact_sensitive_text(message, force=True)
except Exception:
# A redactor that cannot run must not be able to leak the raw
# message into the log by failing open.
message = "<unredactable>"
message = " ".join(message.split())
if len(message) > _TURN_FAILURE_DETAIL_LIMIT:
message = message[:_TURN_FAILURE_DETAIL_LIMIT] + "\u2026"
out = ""
if reason_text:
out += " failure_reason=%s" % " ".join(reason_text.split())
if message:
out += " cause=%r" % message
return out
# ── Auto-continue: resume a turn killed by a process/machine death ────
#
# A turn that concludes — success, handled error, interrupt — clears its
@@ -12988,6 +13036,11 @@ def _run_prompt_submit(
# True once a failed turn's snapshot was retained for resume replay —
# tells the finally below to skip the normal inflight clear.
turn_error_retained = False
# One-line cause for the "tui turn finished" bookend below. The record
# fires from a `finally`, where neither `result` nor the caught
# exception is reliably in scope, so both failure paths stash their
# cause here on the way past.
turn_error_detail = ""
# Durable crash marker: written before the turn runs, retired the
# moment its outcome reaches the client (see _retire_turn_marker).
# Any concluded turn — success, handled error, interrupt — retires
@@ -13507,6 +13560,10 @@ def _run_prompt_submit(
error_surface=_error_surface,
)
turn_error_retained = True
turn_error_detail = _turn_failure_detail(
(result.get("error") if isinstance(result, dict) else raw),
(result.get("failure_reason") if isinstance(result, dict) else None),
)
else:
_clear_inflight_turn(session)
if status == "error":
@@ -13735,6 +13792,7 @@ def _run_prompt_submit(
retire_marker=terminal_receipt_committed,
)
turn_error_retained = True
turn_error_detail = _turn_failure_detail(e, type(e).__name__)
except Exception as emit_exc:
print(
f"[gateway-turn] terminal error emit failed: "
@@ -13810,7 +13868,8 @@ def _run_prompt_submit(
# without reaching this finally.
logger.info(
"tui turn finished: ui_session=%s session_key=%s "
"agent_session_id=%s status=%s error_retained=%s duration=%.1fs",
"agent_session_id=%s status=%s error_retained=%s duration=%.1fs"
"%s",
sid,
session.get("session_key") or "",
getattr(agent, "session_id", "") or "",
@@ -13825,6 +13884,7 @@ def _run_prompt_submit(
else ("error" if turn_error_retained else "complete"),
turn_error_retained,
time.monotonic() - _turn_started_monotonic,
turn_error_detail,
)
# Backstop for turns that never reached a terminal frame (the
# frame paths retire the marker as they emit).