fix(sessions): eager state.db schema migration at backend startup; stop swallowing locked ALTERs

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.

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:

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.
 

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."""