diff --git a/tests/tui_gateway/test_prompt_accept_logging.py b/tests/tui_gateway/test_prompt_accept_logging.py new file mode 100644 index 0000000000..e60b36e69e --- /dev/null +++ b/tests/tui_gateway/test_prompt_accept_logging.py @@ -0,0 +1,183 @@ +"""Desktop/TUI turn-dispatch observability (#86647). + +During the #79278/#86647 persistent-mute investigation the decisive evidence +was an *absence*: a Desktop request left no INFO record in ``agent.log`` or +``gateway.log`` at all (``0 platform=desktop`` across the whole file), so a +muted window was structurally indistinguishable from a request that never +arrived. This suite pins the two-record contract that fixes that: + +* ``_run_prompt_submit`` logs one ``tui prompt accepted`` INFO record before + the turn thread starts, carrying the UI session id, the gateway + ``session_key``, and the agent's live ``session_id`` (rotated independently + by compression — the triple is what a rotation-mute trace needs). +* The turn's ``finally`` logs exactly one ``tui turn finished`` bookend on + every path (success, returned error, exception), re-reading + ``agent.session_id`` so a mid-turn compression rotation shows up as an + accepted/finished pair with different agent ids. +* No prompt content is ever logged. +""" + +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": False, + "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 _records(caplog, needle): + return [r for r in caplog.records if needle in r.getMessage()] + + +SECRETISH_PROMPT = "please rotate QDRANT_API_KEY=hunter2-super-secret now" + + +def test_accepted_and_finished_records_on_success(turn_env, caplog): + agent = types.SimpleNamespace( + session_id="agent-sid-1", + run_conversation=lambda *a, **k: {"final_response": "done"}, + clear_interrupt=lambda: None, + ) + session = _session(agent=agent, running=True) + + with caplog.at_level(logging.INFO, logger="tui_gateway.server"): + server._run_prompt_submit("rid", "ui-sid", session, SECRETISH_PROMPT) + + accepted = _records(caplog, "tui prompt accepted") + finished = _records(caplog, "tui turn finished") + assert len(accepted) == 1 + assert len(finished) == 1 + + msg = accepted[0].getMessage() + # The full id triple a rotation-mute trace needs. + assert "ui_session=ui-sid" in msg + assert "session_key=gw-session-key" in msg + assert "agent_session_id=agent-sid-1" in msg + # Prompt content is never logged — only its length. + assert "hunter2" not in msg + assert "QDRANT_API_KEY" not in msg + assert f"chars={len(SECRETISH_PROMPT)}" in msg + + fin = finished[0].getMessage() + assert "ui_session=ui-sid" in fin + assert "status=complete" in fin + assert "hunter2" not in fin + + +def test_finished_record_reflects_mid_turn_rotation(turn_env, caplog): + """Compression rotating agent.session_id mid-turn must be visible as an + accepted/finished pair with different agent ids — that pair IS the + rotation trace #86647 asks for.""" + + agent = types.SimpleNamespace(session_id="parent-sid", clear_interrupt=lambda: None) + + def _rotate_and_finish(*a, **k): + agent.session_id = "continuation-sid" # what _compress_context does + return {"final_response": "done"} + + agent.run_conversation = _rotate_and_finish + session = _session(agent=agent, running=True) + + with caplog.at_level(logging.INFO, logger="tui_gateway.server"): + server._run_prompt_submit("rid", "ui-sid", session, "go") + + accepted = _records(caplog, "tui prompt accepted")[0].getMessage() + finished = _records(caplog, "tui turn finished")[0].getMessage() + assert "agent_session_id=parent-sid" in accepted + assert "agent_session_id=continuation-sid" in finished + + +def test_finished_record_fires_on_exception_path(turn_env, caplog): + def _boom(*a, **k): + raise RuntimeError("connection reset mid-stream") + + agent = types.SimpleNamespace( + session_id="agent-sid-1", + run_conversation=_boom, + clear_interrupt=lambda: None, + ) + session = _session(agent=agent, running=True) + + with caplog.at_level(logging.INFO, logger="tui_gateway.server"): + server._run_prompt_submit("rid", "ui-sid", session, "go") + + finished = _records(caplog, "tui turn finished") + assert len(finished) == 1 + msg = finished[0].getMessage() + assert "status=error" in msg + assert "error_retained=True" in msg + + +def test_finished_record_fires_on_returned_error(turn_env, caplog): + agent = types.SimpleNamespace( + session_id="agent-sid-1", + run_conversation=lambda *a, **k: { + "final_response": "", + "error": "provider 402: billing wall", + "failed": True, + }, + clear_interrupt=lambda: None, + ) + session = _session(agent=agent, running=True) + + with caplog.at_level(logging.INFO, logger="tui_gateway.server"): + server._run_prompt_submit("rid", "ui-sid", session, "go") + + finished = _records(caplog, "tui turn finished") + assert len(finished) == 1 + assert "status=error" in finished[0].getMessage() diff --git a/tui_gateway/server.py b/tui_gateway/server.py index c34e42fc64..5f86003dad 100644 --- a/tui_gateway/server.py +++ b/tui_gateway/server.py @@ -10307,6 +10307,25 @@ def _run_prompt_submit( agent.clear_interrupt() except Exception: pass + # Desktop/TUI observability (#86647): this is the ONE INFO record proving + # a Desktop/TUI prompt was accepted by THIS process, and it ties together + # every id a rotation-mute trace needs — the UI session id, the gateway + # session_key, and the agent's live session_id (which compression rotates + # independently of the other two). Before this line a Desktop request left + # no trace in agent.log at all ("0 platform=desktop" — see #86647), so a + # muted window was structurally indistinguishable from a request that + # never arrived. No prompt content is logged. + _turn_started_monotonic = time.monotonic() + logger.info( + "tui prompt accepted: ui_session=%s session_key=%s agent_session_id=%s " + "kind=%s chars=%s images=%d", + sid, + session.get("session_key") or "", + getattr(agent, "session_id", "") or "", + display_kind or "user", + len(text) if isinstance(text, str) else "-", + len(images), + ) _emit("message.start", sid) def run(): @@ -11067,6 +11086,32 @@ def _run_prompt_submit( session["last_active"] = time.time() if not turn_error_retained: _clear_inflight_turn(session) + # Closing bookend of the "tui prompt accepted" record above — + # fires on every path (success, returned error, exception, + # interrupt), so one accepted prompt always produces exactly one + # finished record. agent.session_id is re-read here because + # compression may have rotated it mid-turn: an accepted/finished + # pair whose agent_session_id changed IS a rotation trace + # (#86647). A missing finished record means the turn thread died + # 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", + sid, + session.get("session_key") or "", + getattr(agent, "session_id", "") or "", + ( + result.get("interrupted") + and "interrupted" + or result.get("error") + and "error" + or "complete" + ) + if isinstance(result, dict) + else ("error" if turn_error_retained else "complete"), + turn_error_retained, + time.monotonic() - _turn_started_monotonic, + ) # Backstop for turns that never reached a terminal frame (the # frame paths retire the marker as they emit). _retire_turn_marker(session, marker_key)