From 246477a80986f2af64fd00181eeb4ed5c5b6330c Mon Sep 17 00:00:00 2001 From: ethernet Date: Tue, 18 Aug 2026 12:05:28 -0400 Subject: [PATCH] fix(gateway): /goal no longer lies when state.db init is slow MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A fresh state.db init (schema DDL, FTS tables, first config import) measures ~300ms warm on a fast machine. The gateway constructs GoalManager on the event-loop thread, and a cold cache ran that init behind a 0.25s bootstrap grace window: on a slow CI box the /goal set path's waits expired and save_goal silently no-oped — the reply said "Goal set (7-turn budget)..." but nothing persisted, and a fresh GoalManager read back no state (first assertion passes, second fails). Two changes, one per caller shape: - Async callers (_get_goal_manager_for_event, _get_heartbeat_manager_for_event, _post_turn_goal_continuation, and the heartbeat poller) warm the SessionDB cache off-loop through the context-preserving executor before constructing the manager (shared _warm_goals_session_db helper). The loop never blocks and the first write lands at any init duration. A bare to_thread would lose the per-turn profile home override under multiplex; the executor hop keeps it (same pattern as the goal judge path). - Sync callers (heartbeat persistence, _goal_still_active_for_session) cannot await, so the bootstrap windows stay: the call that starts the bootstrap waits a one-time init window (1.5s) instead of the short per-call window (0.25s), giving healthy cold inits room to land while a contended migration still degrades to None with only a bounded one-time stall. The bootstrap thread binds the caller's home as a contextvar override so a multiplexed worker cannot cache the default profile's DB under another profile's key. save_goal and heartbeat save_state now log at WARNING when they drop a write, because the reply has already told the user the state was set. Regression test pins the contract: init past the window, write persists, loop gap under 2s (the flake-policy floor for wall-clock bounds; the slow-init margin grew to match, so the test still tells on-loop from off-loop). Independent diagnosis + measurement by jackulau (#88965 review); the off-loop warm-up shape follows their harness table. Simplify-code review (4-agent) contributed the helper extraction and the poller warm-up. --- gateway/run.py | 35 +++++++ hermes_cli/goals.py | 73 +++++++++++--- hermes_cli/heartbeat.py | 6 ++ hermes_cli/loops.py | 31 +++--- tests/gateway/test_goal_max_turns_config.py | 96 +++++++++++++++++-- tests/gateway/test_loop_command.py | 6 +- .../test_goals_db_bootstrap_off_loop.py | 32 +++++-- tests/hermes_cli/test_loops.py | 6 +- tests/tui_gateway/test_loop_command.py | 6 +- 9 files changed, 232 insertions(+), 59 deletions(-) diff --git a/gateway/run.py b/gateway/run.py index 9970c20780..04c80279c8 100644 --- a/gateway/run.py +++ b/gateway/run.py @@ -20998,6 +20998,23 @@ class GatewayRunner(GatewayAuthorizationMixin, GatewayKanbanWatchersMixin, Gatew except Exception: return 20 + async def _warm_goals_session_db(self, ctx: str) -> None: + """Warm the goals SessionDB cache off-loop (best-effort). + + A cold cache runs the state.db init on the loop thread behind the + bootstrap windows. That freezes the loop for the init duration. + The executor hop keeps the profile home override alive under + multiplex, so the warm cache belongs to the caller's profile. + On failure the caller falls back to the bootstrap windows, so a + dropped warm-up is a bounded stall, never a crash. + """ + try: + from hermes_cli.goals import _get_session_db as _warm_goals_db + + await self._run_in_executor_with_context(_warm_goals_db) + except Exception as exc: + logger.warning("%s: session DB warm-up failed: %s", ctx, exc) + async def _get_goal_manager_for_event(self, event: "MessageEvent"): """Return a GoalManager bound to the session for this gateway event. @@ -21009,6 +21026,10 @@ class GatewayRunner(GatewayAuthorizationMixin, GatewayKanbanWatchersMixin, Gatew except Exception as exc: logger.debug("goal manager unavailable: %s", exc) return None, None + # Warm the SessionDB cache off-loop. A cold cache freezes the + # loop for the init duration and drops the first write: the + # /goal reply claims the goal was set. + await self._warm_goals_session_db("goal manager") try: # Session lookups on behalf of an internal event must not advance # the user-activity clock that drives idle/daily reset policy @@ -21036,6 +21057,9 @@ class GatewayRunner(GatewayAuthorizationMixin, GatewayKanbanWatchersMixin, Gatew except Exception as exc: logger.debug("heartbeat manager unavailable: %s", exc) return None, None + # Warm the SessionDB cache off-loop. A cold cache can drop the + # first /heartbeat write while the reply claims it was set. + await self._warm_goals_session_db("heartbeat manager") try: # Same reset-policy contract as _get_goal_manager_for_event: # internal events look up the session without touching activity. @@ -21086,6 +21110,11 @@ class GatewayRunner(GatewayAuthorizationMixin, GatewayKanbanWatchersMixin, Gatew watch = getattr(self, "_heartbeat_watch", None) if not watch: continue + # Warm the cache off-loop once per poll. A watch can only + # be registered through the warmed /heartbeat command, so + # this covers only the degraded path where that warm-up + # failed. + await self._warm_goals_session_db("heartbeat poll") for quick_key, (source, session_id) in list(watch.items()): try: # Busy sessions coalesce their tick to the next idle poll. @@ -21217,6 +21246,12 @@ class GatewayRunner(GatewayAuthorizationMixin, GatewayKanbanWatchersMixin, Gatew max_turns = self._goal_max_turns_from_config() + # Warm the SessionDB cache off-loop. A cold cache runs the + # state.db init on the loop thread at the turn boundary (the + # 2026-08-14 crash-loop seam). A slow init can drop the goal + # read and silently end the goal loop. + await self._warm_goals_session_db("goal continuation") + mgr = GoalManager(session_id=sid, default_max_turns=max_turns) if not mgr.is_active(): return diff --git a/hermes_cli/goals.py b/hermes_cli/goals.py index 9a685ff8d3..39870322af 100644 --- a/hermes_cli/goals.py +++ b/hermes_cli/goals.py @@ -666,20 +666,47 @@ _DB_CACHE: Dict[str, Any] = {} _DB_BOOTSTRAP_LOCK = threading.Lock() _DB_BOOTSTRAP_INFLIGHT: Dict[str, threading.Event] = {} -# How long a loop-thread caller waits for the background bootstrap before -# degrading to None. Normal SessionDB init is ~10-100ms, so the common case -# still returns a real DB (no silently dropped goal writes); a contended -# init (locked state.db mid-migration) blows past this and the caller -# degrades, with the loop stalled far under the watchdog's probe window. +# How long a loop-thread caller waits for an ALREADY-RUNNING bootstrap +# before degrading to None. Normal SessionDB init is ~10-100ms, so a call +# that arrives mid-bootstrap usually picks the cached instance up within +# this window. A contended init (locked state.db mid-migration) blows past +# it and the caller degrades. The loop stalls far under the watchdog's +# probe window. _DB_BOOTSTRAP_LOOP_WAIT_S = 0.25 +# The call that STARTS the bootstrap (cold cache, nothing in flight) +# waits this long instead of the short window above. A fresh state.db +# init measures ~300ms warm on a fast machine: schema DDL, FTS table +# creation, and the first hermes_cli.config import (journal-mode +# resolution). It is longer on a slow CI box, and it is well past 0.25s. +# The old window dropped the first /goal write. The response said +# "Goal set" but nothing persisted. The longer window is a bounded +# one-time stall. Only the kick call pays it. Every later call keeps +# the short window, so a contended migration never stalls the loop +# repeatedly. +_DB_BOOTSTRAP_INIT_WAIT_S = 1.5 + def _bootstrap_session_db(home: str, done: threading.Event) -> None: """Construct SessionDB off-loop and populate the cache (worker thread).""" try: + from hermes_constants import ( + reset_hermes_home_override, + set_hermes_home_override, + ) from hermes_state import SessionDB - db = SessionDB() + # Bind the caller's home for this thread. The cache key is the + # caller's scoped home, so the constructed SessionDB must point at + # that home's state.db too. Without the override, a multiplexed + # worker thread resolves the process env (the default profile's + # HERMES_HOME). It then caches the wrong profile's DB under this + # profile's key. + token = set_hermes_home_override(home) + try: + db = SessionDB() + finally: + reset_hermes_home_override(token) except Exception as exc: # pragma: no cover logger.debug("GoalManager: background SessionDB() raised (%s)", exc) db = None @@ -704,8 +731,12 @@ def _get_session_db() -> Optional[Any]: seconds — on the gateway's loop thread that starves the loop-liveness watchdog, which hard-exits the process (exit 75) and crash-loops the gateway (enterprise field report, 2026-08-14). On a cache miss with a running - loop we kick a one-shot background bootstrap and return None; every - caller already degrades gracefully on None, and a later call returns the + loop we kick a one-shot background bootstrap and wait a bounded grace + window for it. The kick call waits the one-time init window + (``_DB_BOOTSTRAP_INIT_WAIT_S``), so a healthy cold init completes and + the first write is not dropped. Later calls wait only the short window + (``_DB_BOOTSTRAP_LOOP_WAIT_S``). On timeout we return None. Every + caller degrades gracefully on None, and a later call returns the cached instance. """ try: @@ -745,12 +776,20 @@ def _get_session_db() -> Optional[Any]: name="goals-sessiondb-bootstrap", daemon=True, ).start() - # Grace window: a healthy init finishes in tens of ms, so waiting - # briefly keeps goal/heartbeat persistence working on the very first - # loop-thread call instead of silently dropping it. A contended init - # (the crash-loop scenario) exceeds the window and we degrade to - # None — a bounded stall far below the watchdog's probe timeout. - done.wait(_DB_BOOTSTRAP_LOOP_WAIT_S) + # This call starts the bootstrap, so it pays the one-time + # init cost. Wait long enough for a healthy cold init + # (~300ms warm, more on slow CI) to finish. This keeps the + # first goal/heartbeat write from being silently dropped. + wait = _DB_BOOTSTRAP_INIT_WAIT_S + else: + # Bootstrap already running: brief grace window only. A + # healthy init usually finishes in tens of ms, so this + # still picks the cached instance up. A contended init + # (the crash-loop scenario) exceeds the window and we + # degrade to None. The stall is bounded, far below the + # watchdog's probe timeout. + wait = _DB_BOOTSTRAP_LOOP_WAIT_S + done.wait(wait) return _DB_CACHE.get(home) try: @@ -799,6 +838,12 @@ def save_goal(session_id: str, state: GoalState) -> None: return db = _get_session_db() if db is None: + logger.warning( + "GoalManager: goal for %s not persisted — session DB " + "unavailable (bootstrap window exceeded, in-memory state " + "still active)", + session_id, + ) return try: db.set_meta(_meta_key(session_id), state.to_json()) diff --git a/hermes_cli/heartbeat.py b/hermes_cli/heartbeat.py index bf0df9f5b6..872fbdd806 100644 --- a/hermes_cli/heartbeat.py +++ b/hermes_cli/heartbeat.py @@ -184,6 +184,12 @@ def save_heartbeat(session_id: str, state: HeartbeatState) -> None: return db = _get_session_db() if db is None: + logger.warning( + "HeartbeatManager: heartbeat for %s not persisted — session " + "DB unavailable (bootstrap window exceeded, in-memory state " + "still active)", + session_id, + ) return try: db.set_meta(_meta_key(session_id), state.to_json()) diff --git a/hermes_cli/loops.py b/hermes_cli/loops.py index f496907c2d..87e07a6842 100644 --- a/hermes_cli/loops.py +++ b/hermes_cli/loops.py @@ -369,30 +369,23 @@ def _meta_key(session_id: str) -> str: return f"{_META_PREFIX}{session_id}" -_DB_CACHE: Dict[str, Any] = {} - - def _get_session_db() -> Optional[Any]: - """One SessionDB per HERMES_HOME (same pattern as goals._get_session_db).""" - try: - from hermes_constants import get_hermes_home - from hermes_state import SessionDB + """One SessionDB per HERMES_HOME. - home = str(get_hermes_home()) + Delegates to the goals module's cached SessionDB so goals, loops, + and heartbeats share one connection (same pattern as + ``hermes_cli/heartbeat.py``). The delegation also inherits the + off-loop bootstrap and the window logic: a cold cache on the loop + thread never runs ``SessionDB()`` inline. The previous copy here + did, which froze the loop for the init duration and dropped the + first ``loop:*`` write (the /goal bug class, #88965). + """ + try: + from hermes_cli.goals import _get_session_db as _goals_db except Exception as exc: # pragma: no cover logger.debug("LoopManager: SessionDB bootstrap failed (%s)", exc) return None - - cached = _DB_CACHE.get(home) - if cached is not None: - return cached - try: - db = SessionDB() - except Exception as exc: # pragma: no cover - logger.debug("LoopManager: SessionDB() raised (%s)", exc) - return None - _DB_CACHE[home] = db - return db + return _goals_db() def load_loop(session_id: str) -> Optional[LoopState]: diff --git a/tests/gateway/test_goal_max_turns_config.py b/tests/gateway/test_goal_max_turns_config.py index 9dda0e44d3..f98eddb1d1 100644 --- a/tests/gateway/test_goal_max_turns_config.py +++ b/tests/gateway/test_goal_max_turns_config.py @@ -1,3 +1,6 @@ +import asyncio +import time + import pytest from gateway.config import GatewayConfig, Platform, PlatformConfig @@ -22,15 +25,8 @@ class _FakeSessionStore: return "agent:main:discord:channel:goal-config" -@pytest.mark.asyncio -async def test_gateway_goal_uses_goals_max_turns_from_full_config(tmp_path, monkeypatch): - """Gateway /goal should honor top-level goals.max_turns from config.yaml.""" - home = tmp_path / ".hermes" - home.mkdir() - (home / "config.yaml").write_text("goals:\n max_turns: 7\n", encoding="utf-8") - monkeypatch.setenv("HERMES_HOME", str(home)) - goals._DB_CACHE.clear() - +def _make_runner() -> GatewayRunner: + """GatewayRunner skeleton for the /goal command path (no adapters).""" runner = object.__new__(GatewayRunner) runner.config = GatewayConfig( platforms={Platform.DISCORD: PlatformConfig(enabled=True, token="token")} @@ -38,8 +34,11 @@ async def test_gateway_goal_uses_goals_max_turns_from_full_config(tmp_path, monk runner.session_store = _FakeSessionStore() runner.adapters = {} runner._queued_events = {} + return runner - event = MessageEvent( + +def _make_goal_event() -> MessageEvent: + return MessageEvent( text="/goal ship the benchmark", message_type=MessageType.TEXT, source=SessionSource( @@ -51,6 +50,20 @@ async def test_gateway_goal_uses_goals_max_turns_from_full_config(tmp_path, monk message_id="msg-goal-config", ) + +@pytest.mark.asyncio +async def test_gateway_goal_uses_goals_max_turns_from_full_config(tmp_path, monkeypatch): + """Gateway /goal should honor top-level goals.max_turns from config.yaml.""" + home = tmp_path / ".hermes" + home.mkdir() + (home / "config.yaml").write_text("goals:\n max_turns: 7\n", encoding="utf-8") + monkeypatch.setenv("HERMES_HOME", str(home)) + goals._DB_CACHE.clear() + + runner = _make_runner() + + event = _make_goal_event() + response = await GatewayRunner._handle_goal_command(runner, event) try: @@ -60,3 +73,66 @@ async def test_gateway_goal_uses_goals_max_turns_from_full_config(tmp_path, monk assert state.max_turns == 7 finally: goals._DB_CACHE.clear() + + +@pytest.mark.asyncio +async def test_goal_command_slow_db_init_keeps_loop_free_and_persists(tmp_path, monkeypatch): + """A slow state.db init (cold cache, first /goal of the process) + must not freeze the event loop or silently drop the goal write. + The cache is warmed off-loop, so the reply is honest at any init + duration. Review follow-up (#88965): the bootstrap window alone + froze the loop for the init duration and still dropped the write + past ~1.5s.""" + import hermes_state + + # Past the init window: the window-only path expires its wait and + # drops the write, so this test discriminates warm-up from windows. + # The margin is 2.5s so the loop-gap ceiling below can be 2.0s (the + # flake-policy floor) and an on-loop init still exceeds it. + INIT_S = goals._DB_BOOTSTRAP_INIT_WAIT_S + 2.5 + + class _SlowSessionDB(hermes_state.SessionDB): + def __init__(self, *a, **k): + time.sleep(INIT_S) + super().__init__(*a, **k) + + monkeypatch.setattr(hermes_state, "SessionDB", _SlowSessionDB) + + home = tmp_path / ".hermes" + home.mkdir() + (home / "config.yaml").write_text("goals:\n max_turns: 7\n", encoding="utf-8") + monkeypatch.setenv("HERMES_HOME", str(home)) + goals._DB_CACHE.clear() + + runner = _make_runner() + event = _make_goal_event() + + gaps = {"max": 0.0} + stop = asyncio.Event() + + async def _ticker(): + last = time.monotonic() + while not stop.is_set(): + await asyncio.sleep(0.05) + now = time.monotonic() + gaps["max"] = max(gaps["max"], now - last) + last = now + + ticker = asyncio.create_task(_ticker()) + await asyncio.sleep(0.15) + try: + response = await GatewayRunner._handle_goal_command(runner, event) + + assert "⊙ Goal set (7-turn budget): ship the benchmark" in response + state = goals.GoalManager("sid-gateway-goal-config").state + assert state is not None, "goal write must persist even with a slow init" + # 2.0s is the loose-bound floor from the flake policy. The init + # (4.0s) runs off-loop, so an on-loop regression exceeds this + # ceiling and a loaded runner does not. + assert gaps["max"] < 2.0, ( + f"event loop frozen for {gaps['max']:.2f}s while the init ran off-loop" + ) + finally: + stop.set() + await ticker + goals._DB_CACHE.clear() diff --git a/tests/gateway/test_loop_command.py b/tests/gateway/test_loop_command.py index 73d63317f7..f18d1c5d5c 100644 --- a/tests/gateway/test_loop_command.py +++ b/tests/gateway/test_loop_command.py @@ -10,7 +10,7 @@ from gateway.config import GatewayConfig, Platform, PlatformConfig from gateway.platforms.base import MessageEvent, MessageType from gateway.run import GatewayRunner from gateway.session import SessionSource -from hermes_cli import loops +from hermes_cli import goals, loops class _FakeSessionEntry: @@ -33,9 +33,9 @@ def loop_env(tmp_path, monkeypatch): home = tmp_path / ".hermes" home.mkdir() monkeypatch.setenv("HERMES_HOME", str(home)) - loops._DB_CACHE.clear() + goals._DB_CACHE.clear() yield home - loops._DB_CACHE.clear() + goals._DB_CACHE.clear() def _make_runner(): diff --git a/tests/hermes_cli/test_goals_db_bootstrap_off_loop.py b/tests/hermes_cli/test_goals_db_bootstrap_off_loop.py index c77387db34..12b747eab9 100644 --- a/tests/hermes_cli/test_goals_db_bootstrap_off_loop.py +++ b/tests/hermes_cli/test_goals_db_bootstrap_off_loop.py @@ -109,30 +109,48 @@ def test_worker_thread_constructs_inline(monkeypatch): def test_slow_construction_does_not_block_the_loop(monkeypatch): - """A SessionDB whose init blocks (locked-DB migration) must not stall - the event loop past the watchdog probe window: bounded grace wait, - then degrade to None.""" + """A SessionDB whose init blocks (locked-DB migration) must not + stall the event loop. The kick call is bounded by the one-time init + window. Every later call is bounded by the short per-call window. + Both calls degrade to None.""" import hermes_state class _BlockingDB: def __init__(self): - time.sleep(2.0) # simulated contended migration + # Far past both wait windows. The margin keeps the "still + # None" assertions from racing the bootstrap thread on a + # loaded runner (negative-timing race, flake policy). + time.sleep(6.0) # simulated contended migration def get_meta(self, key): return None monkeypatch.setattr(hermes_state, "SessionDB", _BlockingDB) elapsed = None + elapsed2 = None result = "UNSET" + result2 = "UNSET" async def main(): - nonlocal elapsed, result + nonlocal elapsed, elapsed2, result, result2 t0 = time.monotonic() result = goals._get_session_db() elapsed = time.monotonic() - t0 + t0 = time.monotonic() + result2 = goals._get_session_db() + elapsed2 = time.monotonic() - t0 asyncio.run(main()) assert result is None, "contended init must degrade to None" - assert elapsed is not None and elapsed < 1.0, ( - f"loop-thread call blocked for {elapsed:.2f}s — watchdog territory" + # The slack on each ceiling is 2.0s, the loose-bound floor from the + # flake policy. The windows are 1.5s and 0.25s, so the two ceilings + # stay far apart and a loaded runner does not cross either one. + assert elapsed is not None and elapsed < goals._DB_BOOTSTRAP_INIT_WAIT_S + 2.0, ( + f"kick call blocked for {elapsed:.2f}s — past the one-time init window" + ) + # The in-flight call waits the short window, not the init window. + # A contended migration must not stall the loop repeatedly. + assert result2 is None, "contended init must keep degrading to None" + assert elapsed2 is not None and elapsed2 < goals._DB_BOOTSTRAP_LOOP_WAIT_S + 2.0, ( + f"in-flight call blocked for {elapsed2:.2f}s — watchdog territory" ) diff --git a/tests/hermes_cli/test_loops.py b/tests/hermes_cli/test_loops.py index dba5ed39a4..99dc26d4ec 100644 --- a/tests/hermes_cli/test_loops.py +++ b/tests/hermes_cli/test_loops.py @@ -23,11 +23,11 @@ def hermes_home(tmp_path, monkeypatch): monkeypatch.setattr(Path, "home", lambda: tmp_path) monkeypatch.setenv("HERMES_HOME", str(home)) - from hermes_cli import loops + from hermes_cli import goals - loops._DB_CACHE.clear() + goals._DB_CACHE.clear() yield home - loops._DB_CACHE.clear() + goals._DB_CACHE.clear() # ────────────────────────────────────────────────────────────────────── diff --git a/tests/tui_gateway/test_loop_command.py b/tests/tui_gateway/test_loop_command.py index 41522bcc49..f437e26974 100644 --- a/tests/tui_gateway/test_loop_command.py +++ b/tests/tui_gateway/test_loop_command.py @@ -25,11 +25,11 @@ def hermes_home(tmp_path, monkeypatch): monkeypatch.setattr(Path, "home", lambda: tmp_path) monkeypatch.setenv("HERMES_HOME", str(home)) - from hermes_cli import loops + from hermes_cli import goals - loops._DB_CACHE.clear() + goals._DB_CACHE.clear() yield home - loops._DB_CACHE.clear() + goals._DB_CACHE.clear() @pytest.fixture()