ouyangbo/hermes-agent
1
0
Fork 0
Code Issues Pull Requests Actions 9 Packages Projects Releases Wiki Activity

fix(gateway): /goal no longer lies when state.db init is slow

Browse Source 
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.
This commit is contained in:
ethernet
2026-08-18 12:05:28 -04:00
committed by Teknium
parent a77ee88ce2
commit 246477a809
9 changed files with 232 additions and 59 deletions
Download Patch File Download Diff File Expand all files Collapse all files
gateway/run.py
+35
View File
@@ -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
hermes_cli/goals.py
+59 -14
View File
@@ -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())
hermes_cli/heartbeat.py
+6
View File
@@ -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())
hermes_cli/loops.py
+12 -19
View File
@@ -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]:
tests/gateway/test_goal_max_turns_config.py
+86 -10
View File
@@ -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()
tests/gateway/test_loop_command.py
+3 -3
View File
@@ -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():
tests/hermes_cli/test_goals_db_bootstrap_off_loop.py
+25 -7
View File
@@ -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"
)
tests/hermes_cli/test_loops.py
+3 -3
View File
@@ -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()
# ──────────────────────────────────────────────────────────────────────
tests/tui_gateway/test_loop_command.py
+3 -3
View File
@@ -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()