From 23ca96052cb0c646760f7a46fa72dfebbf7435e1 Mon Sep 17 00:00:00 2001 From: Jack Lau <72348727+jackulau@users.noreply.github.com> Date: Tue, 18 Aug 2026 09:07:12 -0500 Subject: [PATCH] fix(tui_gateway): name the cause in the turn-finished record 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] : ` 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 `` 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. --- .../test_turn_finished_failure_cause.py | 290 ++++++++++++++++++ tui_gateway/server.py | 62 +++- 2 files changed, 351 insertions(+), 1 deletion(-) create mode 100644 tests/tui_gateway/test_turn_finished_failure_cause.py diff --git a/tests/tui_gateway/test_turn_finished_failure_cause.py b/tests/tui_gateway/test_turn_finished_failure_cause.py new file mode 100644 index 0000000000..4a238f977a --- /dev/null +++ b/tests/tui_gateway/test_turn_finished_failure_cause.py @@ -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] : `` 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 diff --git a/tui_gateway/server.py b/tui_gateway/server.py index ab5dcfe9b5..fddb1cbbd5 100644 --- a/tui_gateway/server.py +++ b/tui_gateway/server.py @@ -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 = "" + 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).