diff --git a/hermes_cli/web_server.py b/hermes_cli/web_server.py index 14af2cde45eaa..1ed365fe4fe20 100644 --- a/hermes_cli/web_server.py +++ b/hermes_cli/web_server.py @@ -304,6 +304,27 @@ def _resolve_restart_drain_timeout() -> float: return DEFAULT_GATEWAY_RESTART_DRAIN_TIMEOUT +def _eager_reconcile_own_session_db() -> None: + """One writable open of this process's own state.db at startup. + + ``SessionDB.__init__`` runs ``_init_schema`` → ``_reconcile_columns``, + bringing a store left behind by `hermes update` current before the + dashboard's first session-list poll, with the open-time lock patience + (jittered retries) absorbing transient contention. Never raises: a + store this cannot fix is still served through the read-probe heal in + :func:`_open_session_db_at_path`, which retries on every poll. + """ + try: + from hermes_state import SessionDB, _default_db_path + + SessionDB(db_path=Path(_default_db_path()), read_only=False).close() + except Exception as exc: + _log.warning( + "startup schema reconcile of state.db failed (%s); session " + "reads will retry the heal per poll", exc, + ) + + @asynccontextmanager async def _lifespan(app: "FastAPI"): app.state.event_channels = {} # dict[str, set] @@ -315,6 +336,23 @@ async def _lifespan(app: "FastAPI"): # event loop during lifespan startup — see _get_event_state's docstring. app.state.chat_argv_lock = asyncio.Lock() + # Bring this profile's state.db schema current BEFORE the first + # session-list poll (#79531/#80037). Migrations used to run lazily on + # the first writable open — typically the user's first new session — + # so a store left behind by `hermes update` kept 500ing every + # /api/sessions poll (and the read-probe heal, while it retries per + # poll, can lose repeatedly to lock contention from orphaned sibling + # backends). One writable open here runs _init_schema → + # _reconcile_columns with the full open-time lock patience. Runs in a + # daemon thread so a locked store never delays the server socket (the + # Desktop ready-probe times out at 10s, GH-73083); reads that land + # before it finishes are still covered by the read-probe heal. + threading.Thread( + target=_eager_reconcile_own_session_db, + daemon=True, + name="statedb-eager-reconcile", + ).start() + # Import hermes_cli.gateway eagerly *before* the lifespan yield so the # GIL-heavy .pyc compilation and Defender scan cost is absorbed during # backend initialisation — before the server socket accepts probes. diff --git a/hermes_state_schema.py b/hermes_state_schema.py index 77d6db87b557f..4a9fdac093370 100644 --- a/hermes_state_schema.py +++ b/hermes_state_schema.py @@ -566,12 +566,35 @@ def _reconcile_columns(self, cursor: sqlite3.Cursor) -> None: f'ALTER TABLE "{table_name}" ADD COLUMN "{safe_name}" {col_type}' ) except sqlite3.OperationalError as exc: - # Expected: "duplicate column name" from a race or - # re-run. Unexpected: "Cannot add a NOT NULL column - # with default value NULL" from a schema mistake. - # Log at DEBUG so it's visible in agent.log. - logger.debug( - "reconcile %s.%s: %s", table_name, col_name, exc, + message = str(exc).lower() + if "duplicate column" in message: + # Expected: a sibling process won the race to ADD + # this column between our PRAGMA diff and the + # ALTER. The store ends up correct either way. + logger.debug( + "reconcile %s.%s: %s", table_name, col_name, exc, + ) + continue + if "locked" in message or "busy" in message: + # Lock contention (e.g. an orphaned sibling + # backend holding the write lock, #79531). This + # used to be swallowed at DEBUG, leaving the + # store half-reconciled: startup "succeeded" and + # every session-list read then failed with + # "no such column" until an unrelated writable + # open. Re-raise instead so the open-time lock + # patience in _connect_and_init_with_lock_patience + # retries the WHOLE init (executescript is + # idempotent CREATE IF NOT EXISTS) with jittered + # backoff rather than serving a stale schema. + raise + # Anything else ("Cannot add a NOT NULL column with + # default value NULL", ...) is a schema mistake that + # permanently strands the store behind SCHEMA_SQL — + # be loud, don't bury it at DEBUG. + logger.warning( + "reconcile %s.%s failed; store remains behind " + "SCHEMA_SQL: %s", table_name, col_name, exc, ) def _heal_gateway_routing_pk(self, cursor: sqlite3.Cursor) -> None: diff --git a/tests/hermes_cli/test_web_server.py b/tests/hermes_cli/test_web_server.py index ee655e0a3b7a9..e44c37579cb9b 100644 --- a/tests/hermes_cli/test_web_server.py +++ b/tests/hermes_cli/test_web_server.py @@ -476,6 +476,70 @@ def test_profiles_sidebar_heals_stale_schema_store(self): "sidebar-stale" ] + def test_startup_eager_reconcile_heals_stale_store(self): + """The lifespan's eager reconcile brings a stale store current. + + #79531/#80037: after `hermes update` an old-schema state.db used to + stay stale until the first NEW session forced a writable open — + every /api/sessions poll 500ed with "no such column" in between. + The lifespan now schedules one writable open at startup; this + exercises that worker directly against a store missing + sessions.last_read_at and asserts the schema is brought current. + """ + import sqlite3 + + from hermes_cli import web_server + from hermes_constants import get_hermes_home + from hermes_state import SessionDB + + db_path = get_hermes_home() / "state.db" + seed = SessionDB(db_path=db_path) + try: + seed.create_session("eager-stale", source="cli") + finally: + seed.close() + + legacy = sqlite3.connect(str(db_path)) + try: + legacy.execute("ALTER TABLE sessions DROP COLUMN last_read_at") + legacy.commit() + finally: + legacy.close() + + web_server._eager_reconcile_own_session_db() + + healed = sqlite3.connect(str(db_path)) + try: + columns = { + row[1] for row in healed.execute("PRAGMA table_info(sessions)") + } + finally: + healed.close() + assert "last_read_at" in columns + + # The healed store serves the full rich listing. + db = SessionDB(db_path=db_path, read_only=True) + try: + rows = db.list_sessions_rich(limit=10, compact_rows=True) + finally: + db.close() + assert [r["id"] for r in rows] == ["eager-stale"] + + def test_startup_eager_reconcile_never_raises(self, monkeypatch): + """A store the eager reconcile cannot open must not break startup.""" + import sqlite3 as sqlite3_module + + import hermes_state + + from hermes_cli import web_server + + def boom(*args, **kwargs): + raise sqlite3_module.OperationalError("database is locked") + + monkeypatch.setattr(hermes_state, "SessionDB", boom) + # Must swallow — reads fall back to the per-poll probe heal. + web_server._eager_reconcile_own_session_db() + def test_heal_gives_up_when_reconcile_cannot_fix_the_store(self, monkeypatch): """A probe failure reconciliation can't cure must not retry forever. diff --git a/tests/test_hermes_state.py b/tests/test_hermes_state.py index 892756049386b..f7721090e32db 100644 --- a/tests/test_hermes_state.py +++ b/tests/test_hermes_state.py @@ -1598,6 +1598,153 @@ def test_schema_sql_is_source_of_truth(self, db): ) +class TestReconcileColumnsErrorHandling: + """_reconcile_columns must not bury migration failures (#79531/#80037). + + A locked ALTER used to be swallowed at DEBUG: startup "succeeded" with a + half-reconciled schema and every session-list read then 500ed with + "no such column" until an unrelated writable open. The contract now: + duplicate-column races stay quiet, lock/busy propagates (so the open-time + lock patience retries the whole init), everything else warns. + """ + + class _FailingAlterCursor: + """Pass through to a real cursor, failing ALTER TABLE with ``exc``.""" + + def __init__(self, real_cursor, exc): + self._real = real_cursor + self._exc = exc + + def execute(self, sql, *args, **kwargs): + if sql.lstrip().upper().startswith("ALTER TABLE"): + raise self._exc + return self._real.execute(sql, *args, **kwargs) + + def __getattr__(self, name): + return getattr(self._real, name) + + def _db_missing_column(self, tmp_path): + """A store whose sessions table lacks last_read_at.""" + db_path = tmp_path / "state.db" + seed = SessionDB(db_path=db_path) + seed.close() + conn = sqlite3.connect(str(db_path)) + try: + conn.execute("ALTER TABLE sessions DROP COLUMN last_read_at") + conn.commit() + finally: + conn.close() + return db_path + + def test_locked_alter_propagates(self, tmp_path): + """database-is-locked must escape _reconcile_columns, not vanish. + + Propagation is what lets _connect_and_init_with_lock_patience retry + the whole init with jittered backoff instead of serving a store + that is silently behind SCHEMA_SQL. + """ + db_path = self._db_missing_column(tmp_path) + conn = sqlite3.connect(str(db_path)) + try: + stale = SessionDB.__new__(SessionDB) + stale._conn = conn + cursor = self._FailingAlterCursor( + conn.cursor(), + sqlite3.OperationalError("database is locked"), + ) + with pytest.raises(sqlite3.OperationalError, match="locked"): + stale._reconcile_columns(cursor) + finally: + conn.close() + + def test_duplicate_column_race_stays_quiet(self, tmp_path, caplog): + """A duplicate-column race is expected and must not warn or raise.""" + import logging + + db_path = self._db_missing_column(tmp_path) + conn = sqlite3.connect(str(db_path)) + try: + stale = SessionDB.__new__(SessionDB) + stale._conn = conn + cursor = self._FailingAlterCursor( + conn.cursor(), + sqlite3.OperationalError( + "duplicate column name: last_read_at" + ), + ) + with caplog.at_level(logging.WARNING, logger="hermes_state"): + stale._reconcile_columns(cursor) + finally: + conn.close() + assert not [ + r for r in caplog.records if "reconcile" in r.getMessage() + ] + + def test_other_alter_failures_warn(self, tmp_path, caplog): + """Schema mistakes (e.g. un-ADDable NOT NULL) log at WARNING.""" + import logging + + db_path = self._db_missing_column(tmp_path) + conn = sqlite3.connect(str(db_path)) + try: + stale = SessionDB.__new__(SessionDB) + stale._conn = conn + cursor = self._FailingAlterCursor( + conn.cursor(), + sqlite3.OperationalError( + "Cannot add a NOT NULL column with default value NULL" + ), + ) + with caplog.at_level(logging.WARNING, logger="hermes_state"): + stale._reconcile_columns(cursor) + finally: + conn.close() + warnings = [ + r + for r in caplog.records + if r.levelno >= logging.WARNING + and "reconcile" in r.getMessage() + ] + assert warnings, "un-ADDable column failure must be logged at WARNING+" + + def test_locked_alter_is_retried_by_open_lock_patience(self, tmp_path, monkeypatch): + """End-to-end: a transiently locked ALTER heals on open retry. + + The lock-patience wrapper retries on OperationalError raised out of + _connect_and_init; before this fix _reconcile_columns caught the + error internally so the retry never saw it and the store stayed + stale forever. + """ + db_path = self._db_missing_column(tmp_path) + + original = SessionDB._reconcile_columns + calls = {"n": 0} + + def flaky_reconcile(self, cursor): + calls["n"] += 1 + if calls["n"] == 1: + raise sqlite3.OperationalError("database is locked") + return original(self, cursor) + + monkeypatch.setattr(SessionDB, "_reconcile_columns", flaky_reconcile) + # Keep the retry fast — patience budget is 20s by default. + monkeypatch.setattr(SessionDB, "_WRITE_RETRY_SLOW_MIN_S", 0.001) + monkeypatch.setattr(SessionDB, "_WRITE_RETRY_SLOW_MAX_S", 0.005) + + healed = SessionDB(db_path=db_path) + try: + cols = { + r[1] + for r in healed._conn.execute( + 'PRAGMA table_info("sessions")' + ).fetchall() + } + finally: + healed.close() + assert calls["n"] >= 2, "lock patience must retry the init" + assert "last_read_at" in cols + + class TestTitleUniqueness: """Tests for unique title enforcement and title-based lookups."""