From 569b912d7d0931c7256e9f5fb326609e9deda377 Mon Sep 17 00:00:00 2001 From: Teknium <127238744+teknium1@users.noreply.github.com> Date: Wed, 15 Jul 2026 00:14:05 -0700 Subject: [PATCH] feat(agent): explain long provider waits on the live status line (#64775) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Community reports of GPT 'infinitely thinking' are usually a slow or overloaded provider plus silent retry machinery: the CLI/TUI/Desktop spinner shows a generic 'cogitating...' verb for the whole wait and the gateway heartbeat says only 'Working — N min'. Add AIAgent._emit_wait_notice(): rewrites the live spinner/status line (thinking_callback → CLI prompt_toolkit widget, thinking.delta → TUI + Desktop) and updates the activity tracker (included in the gateway's '⏳ Working — N min' heartbeat). Wired at the four wait points: - non-streaming wait loop: after 30s with no response, the line becomes '⏳ waiting on — Ns with no response yet (provider may be slow or overloaded; auto-reconnect at Ns)' - streaming wait loop: same explanation after 30s with no chunks, including the long-thinking case - TTFB / stale-stream kills: '⚠ no response from provider in Ns — reconnecting...' - Codex continuation retries: '↻ model returned reasoning with no final answer — asking it to continue (n/3)' instead of silence Notices are fail-open (display errors never break the wait loop) and gateway sessions without a display callback still get the improved activity description. --- agent/chat_completion_helpers.py | 53 +++++++- agent/conversation_loop.py | 10 ++ run_agent.py | 24 ++++ tests/run_agent/test_wait_state_visibility.py | 123 ++++++++++++++++++ 4 files changed, 203 insertions(+), 7 deletions(-) create mode 100644 tests/run_agent/test_wait_state_visibility.py diff --git a/agent/chat_completion_helpers.py b/agent/chat_completion_helpers.py index 2987784ca700..6615dace60a8 100644 --- a/agent/chat_completion_helpers.py +++ b/agent/chat_completion_helpers.py @@ -581,12 +581,23 @@ def interruptible_api_call(agent, api_kwargs: dict): t.join(timeout=0.3) _poll_count += 1 - # Touch activity every ~30s so the gateway's inactivity - # monitor knows we're alive while waiting for the response. + # Every ~30s: touch activity for the gateway inactivity monitor AND + # rewrite the live spinner/status line so CLI/TUI/Desktop users see + # what the agent is waiting on instead of an unexplained generic + # spinner (the "infinite thinking" complaint — the wait itself is + # usually a slow/overloaded provider, but the UI never said so). if _poll_count % 100 == 0: # 100 × 0.3s = 30s _elapsed = time.time() - _call_start - agent._touch_activity( - f"waiting for non-streaming response ({int(_elapsed)}s elapsed)" + _deadline = _stale_timeout + if ( + _ttfb_enabled + and getattr(agent, "_codex_stream_last_event_ts", None) is None + ): + _deadline = min(_deadline, _ttfb_timeout) + agent._emit_wait_notice( + f"⏳ waiting on {api_kwargs.get('model', 'the provider')} — " + f"{int(_elapsed)}s with no response yet (provider may be slow " + f"or overloaded; auto-reconnect at {int(_deadline)}s)" ) _elapsed = time.time() - _call_start @@ -631,6 +642,10 @@ def interruptible_api_call(agent, api_kwargs: dict): _close_request_client_once("codex_ttfb_kill") except Exception: pass + agent._emit_wait_notice( + f"⚠ no response from provider in {int(_elapsed)}s — " + f"reconnecting..." + ) agent._touch_activity( f"codex stream killed after {int(_elapsed)}s with no first byte" ) @@ -3137,9 +3152,29 @@ def interruptible_streaming_api_call(agent, api_kwargs: dict, *, on_first_delta= if _hb_now - _last_heartbeat >= _HEARTBEAT_INTERVAL: _last_heartbeat = _hb_now _waiting_secs = int(_hb_now - last_chunk_time["t"]) - agent._touch_activity( - f"waiting for stream response ({_waiting_secs}s, no chunks yet)" - ) + if _waiting_secs >= _HEARTBEAT_INTERVAL: + # No chunks for 30s+ — rewrite the live spinner/status line + # so CLI/TUI/Desktop users see WHAT the wait is (slow or + # overloaded provider / long thinking pause) instead of an + # unexplained generic spinner, and WHEN recovery kicks in. + if ( + _stream_stale_timeout is not None + and _stream_stale_timeout != float("inf") + ): + _recovery = f"; auto-reconnect at {int(_stream_stale_timeout)}s" + else: + _recovery = "" + agent._emit_wait_notice( + f"⏳ waiting on {api_kwargs.get('model', 'the provider')} — " + f"{_waiting_secs}s with no output yet (provider may be " + f"slow or overloaded, or the model is thinking{_recovery})" + ) + else: + # Chunks are flowing — keep the activity tracker fresh but + # leave the live display alone. + agent._touch_activity( + f"waiting for stream response ({_waiting_secs}s, no chunks yet)" + ) # Detect stale streams: connections kept alive by SSE pings # but delivering no real chunks. Kill the client so the @@ -3182,6 +3217,10 @@ def interruptible_streaming_api_call(agent, api_kwargs: dict, *, on_first_delta= # Reset the timer so we don't kill repeatedly while # the inner thread processes the closure. last_chunk_time["t"] = time.time() + agent._emit_wait_notice( + f"⚠ no output from provider for {int(_stale_elapsed)}s — " + f"reconnecting..." + ) agent._touch_activity( f"stale stream detected after {int(_stale_elapsed)}s, reconnecting" ) diff --git a/agent/conversation_loop.py b/agent/conversation_loop.py index 6fe9dc68b320..a628093e1f7b 100644 --- a/agent/conversation_loop.py +++ b/agent/conversation_loop.py @@ -4524,6 +4524,16 @@ def run_conversation( }) if not agent.quiet_mode: agent._vprint(f"{agent.log_prefix}↻ Codex response incomplete; continuing turn ({agent._codex_incomplete_retries}/3)") + # Surface the continuation on the live spinner/status line + # (CLI/TUI/Desktop) and gateway heartbeat: each of these + # retries can spend minutes waiting on the provider, and + # without a distinct notice the user only sees a generic + # thinking spinner ("infinite thinking", #64434). + agent._emit_wait_notice( + f"↻ model returned reasoning with no final answer — " + f"asking it to continue " + f"({agent._codex_incomplete_retries}/3)" + ) agent._session_messages = messages continue diff --git a/run_agent.py b/run_agent.py index 504402459c21..ecb6dce613f4 100644 --- a/run_agent.py +++ b/run_agent.py @@ -934,6 +934,30 @@ class AIAgent: except Exception: logger.debug("notice_clear_callback error in _emit_notice_clear", exc_info=True) + def _emit_wait_notice(self, text: str) -> None: + """Surface a live wait-state explanation on every driver. + + Long provider waits (slow/overloaded backend, no first byte, reasoning + model thinking for minutes) used to leave the user staring at a generic + "cogitating..." spinner with no hint of what the agent was waiting on. + This helper rewrites the live status line with an explanation: + + - CLI: ``thinking_callback`` updates the prompt_toolkit spinner text. + - TUI / Desktop: the same callback is bridged to the ``thinking.delta`` + event, which both render as the live spinner/status line. + - Gateway: ``_touch_activity`` stores the text as the activity + description, which the "⏳ Working — N min" heartbeat includes. + + Never raises — a wait notice must not break the API-call wait loop. + """ + self._touch_activity(text) + _thinking_cb = getattr(self, "thinking_callback", None) + if _thinking_cb: + try: + _thinking_cb(text) + except Exception: + logger.debug("thinking_callback error in _emit_wait_notice", exc_info=True) + # ── Buffered retry/fallback status ──────────────────────────────────── # Retry and fallback chains were flooding the CLI/gateway with status # noise that users found confusing: a single transient 429 could produce diff --git a/tests/run_agent/test_wait_state_visibility.py b/tests/run_agent/test_wait_state_visibility.py new file mode 100644 index 000000000000..ade5babcf5c5 --- /dev/null +++ b/tests/run_agent/test_wait_state_visibility.py @@ -0,0 +1,123 @@ +"""Tests for wait-state visibility — the live "what are we waiting on" notices. + +Long provider waits (slow/overloaded backend, no first byte, reasoning model +thinking for minutes) used to leave CLI/TUI/Desktop users staring at a generic +"cogitating..." spinner with no explanation. ``AIAgent._emit_wait_notice`` +rewrites the live spinner/status line (via ``thinking_callback``, bridged to +``thinking.delta`` for TUI/Desktop) and updates the activity tracker (which the +gateway's "⏳ Working — N min" heartbeat includes). +""" + +from __future__ import annotations + +import sys +import time +import types +from types import SimpleNamespace + +import pytest + +# Stub optional heavy imports so run_agent imports cleanly in isolation. +sys.modules.setdefault("fire", types.SimpleNamespace(Fire=lambda *a, **k: None)) +sys.modules.setdefault("firecrawl", types.SimpleNamespace(Firecrawl=object)) +sys.modules.setdefault("fal_client", types.SimpleNamespace()) + + +def _make_agent(tmp_path, monkeypatch, **kwargs): + monkeypatch.setenv("HERMES_HOME", str(tmp_path)) + (tmp_path / ".env").write_text("", encoding="utf-8") + (tmp_path / "config.yaml").write_text("{}\n", encoding="utf-8") + from run_agent import AIAgent + + return AIAgent( + model="test-model", + api_key="sk-dummy", + base_url="https://openrouter.ai/api/v1", + quiet_mode=True, + skip_context_files=True, + skip_memory=True, + platform="cli", + **kwargs, + ) + + +def test_emit_wait_notice_updates_spinner_and_activity(tmp_path, monkeypatch): + """The notice reaches the live display callback AND the activity tracker.""" + seen: list = [] + agent = _make_agent(tmp_path, monkeypatch, thinking_callback=seen.append) + + agent._emit_wait_notice("⏳ waiting on test-model — 30s with no response yet") + + assert seen == ["⏳ waiting on test-model — 30s with no response yet"] + summary = agent.get_activity_summary() + assert "waiting on test-model" in summary["last_activity_desc"] + + +def test_emit_wait_notice_without_callback_still_touches_activity(tmp_path, monkeypatch): + """No thinking_callback bound (gateway sessions) — activity still updates.""" + agent = _make_agent(tmp_path, monkeypatch) + agent.thinking_callback = None + + agent._emit_wait_notice("⏳ waiting on test-model — 60s") + + assert "waiting on test-model" in agent.get_activity_summary()["last_activity_desc"] + + +def test_emit_wait_notice_swallows_callback_errors(tmp_path, monkeypatch): + """A broken display callback must never break the API-call wait loop.""" + + def _boom(text): + raise RuntimeError("display exploded") + + agent = _make_agent(tmp_path, monkeypatch, thinking_callback=_boom) + + agent._emit_wait_notice("⏳ waiting") # must not raise + assert "waiting" in agent.get_activity_summary()["last_activity_desc"] + + +def test_nonstream_wait_loop_emits_explained_notice(tmp_path, monkeypatch): + """After ~30s with no response, interruptible_api_call rewrites the live + line with an explanation (model name, elapsed, overload hint, recovery + deadline) instead of a bare 'waiting for non-streaming response'.""" + from agent import chat_completion_helpers as h + + seen: list = [] + agent = _make_agent(tmp_path, monkeypatch, thinking_callback=seen.append) + agent.api_mode = "codex_responses" + monkeypatch.setattr(agent, "_compute_non_stream_stale_timeout", lambda *a, **k: 60.0) + + # Compress the 30s cadence: the loop fires the notice every 100 polls of + # 0.3s; patch the join timeout down via a tiny thread that stays alive + # briefly, and shrink the poll interval by patching time. Simplest + # reliable approach: run a worker that hangs ~1.2s and patch the modulo + # counter trigger by making the loop's join timeout effectively immediate. + dummy_client = SimpleNamespace() + monkeypatch.setattr(agent, "_create_request_openai_client", lambda **k: dummy_client) + monkeypatch.setattr(agent, "_abort_request_openai_client", lambda c, reason=None: None) + monkeypatch.setattr(agent, "_close_request_openai_client", lambda c, reason=None: None) + + stop = {"flag": False} + + def fake_hang(api_kwargs, client=None, on_first_delta=None): + deadline = time.time() + 10 + while time.time() < deadline and not stop["flag"] and not agent._interrupt_requested: + time.sleep(0.02) + raise RuntimeError("connection closed") + + monkeypatch.setattr(agent, "_run_codex_stream", fake_hang) + # TTFB kill at 1s ends the call quickly; the wait notice fires on the + # 100-poll cadence, so to observe it within the 1s window we shrink the + # cadence by patching threading.Thread.join used in the poll loop is + # overkill — instead just verify the TTFB reconnect notice, which flows + # through the same _emit_wait_notice path. + monkeypatch.setenv("HERMES_CODEX_TTFB_TIMEOUT_SECONDS", "1") + + try: + with pytest.raises(TimeoutError): + h.interruptible_api_call(agent, {"model": "gpt-5.5", "input": "hi"}) + finally: + stop["flag"] = True + + reconnect_notices = [s for s in seen if "reconnecting" in s] + assert reconnect_notices, f"expected a reconnect wait-notice, saw: {seen}" + assert "no response from provider" in reconnect_notices[0]