mirror of
https://github.com/NousResearch/hermes-agent.git
synced 2026-07-19 15:18:03 +00:00
feat(agent): explain long provider waits on the live status line (#64775)
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 <model> — 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.
This commit is contained in:
parent
2fc0e3d1aa
commit
569b912d7d
4 changed files with 203 additions and 7 deletions
|
|
@ -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"
|
||||
)
|
||||
|
|
|
|||
|
|
@ -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
|
||||
|
||||
|
|
|
|||
24
run_agent.py
24
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
|
||||
|
|
|
|||
123
tests/run_agent/test_wait_state_visibility.py
Normal file
123
tests/run_agent/test_wait_state_visibility.py
Normal file
|
|
@ -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]
|
||||
Loading…
Add table
Add a link
Reference in a new issue