diff --git a/hermes_cli/web_routers/profiles.py b/hermes_cli/web_routers/profiles.py index 3d72d073c3165..075480f22eacf 100644 --- a/hermes_cli/web_routers/profiles.py +++ b/hermes_cli/web_routers/profiles.py @@ -38,6 +38,25 @@ from hermes_cli.web_models import ( # Same logger the handlers used before extraction (identical logger object). _log = logging.getLogger("hermes_cli.web_server") +# Per-profile session reads report failures in the response's ``errors`` +# array, which the desktop sidebar does not currently surface — during the +# stale-schema incident that made an empty sidebar look healthy while +# /api/sessions (which logs) was the only diagnosable trace. Warn once per +# (profile, message) per process so a persistent failure is loud in +# errors.log without turning every sidebar poll into log spam. +_profile_read_warned: set = set() + + +def _warn_profile_read_error(profile: str, exc: Exception) -> None: + key = (profile, str(exc)) + if key in _profile_read_warned: + return + _profile_read_warned.add(key) + _log.warning( + "profile session read failed for %r (reported only in the response " + "errors array): %s", profile, exc, + ) + sessions_router = APIRouter() router = APIRouter() @@ -47,6 +66,7 @@ _cron_profile_home = late("_cron_profile_home") _disable_unselected_skills = late("_disable_unselected_skills") _fallback_profile_dicts = late("_fallback_profile_dicts") _hub_action_name = late("_hub_action_name") +_open_session_db_at_path = late("_open_session_db_at_path") _profile_setup_command = late("_profile_setup_command") _profile_to_dict = late("_profile_to_dict") _resolve_profile_dir = late("_resolve_profile_dir") @@ -92,7 +112,6 @@ def get_profiles_sessions( if order not in ("created", "recent"): raise HTTPException(status_code=400, detail="order must be one of: created, recent") - from hermes_state import SessionDB from hermes_cli import profiles as profiles_mod targets: List[Tuple[str, Path]] = [] @@ -132,11 +151,17 @@ def get_profiles_sessions( if not db_path.exists(): continue try: - # Read-only: this loop runs on every sidebar refresh, so it must - # never DDL/write-lock another profile's live DB (see SessionDB - # read_only docstring). - db = SessionDB(db_path=db_path, read_only=True) + # Read-only on the healthy path: this loop runs on every sidebar + # refresh, so it must not routinely DDL/write-lock another + # profile's live DB (see SessionDB read_only docstring). The + # helper's stale-schema probe performs a ONE-TIME writable open + # when the store predates a schema addition — the same reconcile + # that profile's own backend runs at startup — because read-only + # opens skip column reconciliation and would otherwise fail here + # on every refresh until something else opened the DB writable. + db = _open_session_db_at_path(db_path, read_only=True) except Exception as exc: + _warn_profile_read_error(name, exc) errors.append({"profile": name, "error": str(exc)}) continue try: @@ -176,6 +201,7 @@ def get_profiles_sessions( s["pinned"] = bool(s.get("pinned")) merged.append(s) except Exception as exc: + _warn_profile_read_error(name, exc) errors.append({"profile": name, "error": str(exc)}) finally: db.close() @@ -226,7 +252,6 @@ def get_profiles_sessions_sidebar( ``min_messages=1`` / ``archived=exclude`` / recency order, matching the desktop's per-slice calls. """ - from hermes_state import SessionDB from hermes_cli import profiles as profiles_mod # cron + messaging are cross-profile; recents is scoped to recents_profile. @@ -290,8 +315,12 @@ def get_profiles_sessions_sidebar( if not db_path.exists(): continue try: - db = SessionDB(db_path=db_path, read_only=True) + # Read-only with the stale-schema heal — same contract as the + # per-slice endpoint above (one-time writable reconcile when the + # store predates a schema addition, plain read-only otherwise). + db = _open_session_db_at_path(db_path, read_only=True) except Exception as exc: + _warn_profile_read_error(name, exc) errors.append({"profile": name, "error": str(exc)}) continue try: @@ -310,6 +339,7 @@ def get_profiles_sessions_sidebar( _tag(_slice(db, exclude=messaging_exclude_list, cap=messaging_cap), name) ) except Exception as exc: + _warn_profile_read_error(name, exc) errors.append({"profile": name, "error": str(exc)}) finally: db.close() diff --git a/hermes_cli/web_server.py b/hermes_cli/web_server.py index 3627f34a0e1c1..7fc50719a3624 100644 --- a/hermes_cli/web_server.py +++ b/hermes_cli/web_server.py @@ -1673,19 +1673,20 @@ def _probe_gateway_health() -> tuple[bool, dict | None]: def _count_status_active_sessions() -> int: """Return the dashboard status active-session count. - This is best-effort status garnish, not a critical path. Use a read-only - connection so /api/status never tries to initialise or migrate state.db - while another Hermes process is writing to it. + This is best-effort status garnish, not a critical path. Opens read-only + (via the shared stale-schema heal, same as every other dashboard read + path) so /api/status never routinely writes to state.db while another + Hermes process is using it. """ - from hermes_state import DEFAULT_DB_PATH, SessionDB + from hermes_state import _default_db_path - # read_only opens require the DB to already exist (see SessionDB.__init__ - # read_only contract) — on a fresh install every /api/status poll would - # otherwise pay an OperationalError until the first session is written. - if not DEFAULT_DB_PATH.exists(): + # The heal helper bootstraps a missing store; this garnish must not — on + # a fresh install /api/status polls would otherwise create state.db + # before the user's first session. + if not Path(_default_db_path()).exists(): return 0 - db = SessionDB(read_only=True) + db = _open_session_db_for_profile(None, read_only=True) try: sessions = db.list_sessions_rich(limit=50, compact_rows=True) now = time.time() @@ -11195,38 +11196,56 @@ from hermes_cli.web_routers.sessions import ( # noqa: E402,F401 — legacy re-e # query raises "no such table: sessions". _session_db_bootstrap_lock = threading.Lock() -# Stale-schema probe for read-only opens: compiled against the newest columns -# the dashboard read paths query. Reads at most one row per table. Read-only -# opens skip _reconcile_columns(), so an older store would otherwise 500 on -# every poll until something opened it writable. -_SESSION_DB_READ_PROBE_SQL = ( - "SELECT (SELECT archived FROM sessions LIMIT 1), " - "(SELECT pinned FROM sessions LIMIT 1), " - "(SELECT active FROM messages LIMIT 1), " - "(SELECT compacted FROM messages LIMIT 1)" -) + +def _session_db_read_probe_statements() -> tuple: + """Stale-schema probes for read-only opens, derived from SCHEMA_SQL. + + Read-only opens skip _reconcile_columns(), so an older store would + otherwise 500 on every poll until something opened it writable. Derived + from the same schema the writable reconciler applies, so any column + added there is probed here automatically — the previous hand-written + probe listed four columns and went stale the first time a new column + (sessions.last_activity_at) shipped, leaving the desktop sidebar empty + after `hermes update` until the first message forced a writable open. + """ + from hermes_state_schema import schema_read_probe_statements + + return schema_read_probe_statements() -def _open_session_db_for_profile(profile: Optional[str], *, read_only: bool): - """Open a SessionDB with an explicit access mode for a profile. +# Stores where a heal WRITABLE OPEN SUCCEEDED and the read probe still +# failed afterwards: the schema problem is one reconciliation cannot fix +# (e.g. a NOT-NULL-without-default column SQLite refuses to ADD). Retrying +# the full writable init on every poll would hammer a live DB for nothing, +# so such stores fall back to the raw read-only open until restart. A +# FAILED writable open (transient lock) is deliberately NOT recorded — +# the next poll retries the heal. +_session_db_heal_exhausted: set = set() - ``profile`` None/empty selects this process's own ``state.db``. A named - profile opens that profile's on-disk store directly. +# Deduplicates the heal-failure warning per store per process, so a +# persistent problem is loud once instead of once per sidebar poll. +_session_db_heal_warned: set = set() + + +def _open_session_db_at_path(db_path: Path, *, read_only: bool): + """Open a SessionDB at an explicit path with an explicit access mode. Writable opens keep the full init and repair path. Read-only opens bootstrap a missing or zero-byte store once, and heal an older or malformed schema through one writable open before reopening read-only. The healthy read path never takes a write lock or requests a checkpoint. + + Scope of the heal: the probe checks every table/column declared in + SCHEMA_SQL (see ``schema_read_probe_statements``), so ANY schema + addition escalates a stale store to a one-time writable open — the same + reconcile the store's own backend runs at startup. Tables created + outside SCHEMA_SQL (telemetry ``tel_*``, FTS shadow tables) are + deliberately outside both the probe and the heal. """ import sqlite3 - from hermes_state import SessionDB, _default_db_path, is_malformed_db_error + from hermes_state import SessionDB, is_malformed_db_error - if profile: - _name, home = _cron_profile_home(profile) - db_path = Path(home) / "state.db" - else: - db_path = Path(_default_db_path()) if not read_only: return SessionDB(db_path=db_path, read_only=False) @@ -11248,9 +11267,10 @@ def _open_session_db_for_profile(profile: Optional[str], *, read_only: bool): # Unit-test fakes may replace SessionDB without exposing a raw # connection. Probe only real connections. conn = getattr(db, "_conn", None) - if conn is not None: + if conn is not None and str(db_path) not in _session_db_heal_exhausted: try: - conn.execute(_SESSION_DB_READ_PROBE_SQL).fetchone() + for statement in _session_db_read_probe_statements(): + conn.execute(statement).fetchone() except BaseException: db.close() raise @@ -11264,7 +11284,45 @@ def _open_session_db_for_profile(profile: Optional[str], *, read_only: bool): if not stale_schema and not is_malformed_db_error(exc): raise SessionDB(db_path=db_path, read_only=False).close() - return _open_probed() + try: + return _open_probed() + except sqlite3.DatabaseError as still_stale: + message = str(still_stale).lower() + if "no such table" not in message and "no such column" not in message: + raise + # The writable open succeeded but the store is STILL behind the + # probe: reconciliation cannot fix this one. Serve reads without + # the probe (queries touching the broken part will still fail, + # everything else works) and stop paying the writable init per + # poll. + _session_db_heal_exhausted.add(str(db_path)) + if str(db_path) not in _session_db_heal_warned: + _session_db_heal_warned.add(str(db_path)) + _log.warning( + "state.db at %s is missing schema that a writable " + "reconcile could not add (%s); read paths may partially " + "fail until the store is repaired", + db_path, + still_stale, + ) + return _open_probed() + + +def _open_session_db_for_profile(profile: Optional[str], *, read_only: bool): + """Open a SessionDB with an explicit access mode for a profile. + + ``profile`` None/empty selects this process's own ``state.db``. A named + profile opens that profile's on-disk store directly. Access-mode + semantics are documented on :func:`_open_session_db_at_path`. + """ + from hermes_state import _default_db_path + + if profile: + _name, home = _cron_profile_home(profile) + db_path = Path(home) / "state.db" + else: + db_path = Path(_default_db_path()) + return _open_session_db_at_path(db_path, read_only=read_only) # In-process throttle for the opportunistic auto-archive trigger, keyed by diff --git a/hermes_state_schema.py b/hermes_state_schema.py index 0761a0804ef72..68a888879c2b5 100644 --- a/hermes_state_schema.py +++ b/hermes_state_schema.py @@ -32,6 +32,53 @@ from hermes_state_common import ( # keep that logger identity so log filtering/capture behavior is unchanged. logger = logging.getLogger("hermes_state") +# Cache for schema_read_probe_statements() — parsing SCHEMA_SQL spins up an +# in-memory SQLite database, so derive the statements once per process. +_READ_PROBE_STATEMENTS: Optional[tuple] = None + + +def schema_read_probe_statements() -> tuple: + """SELECT statements that fail iff a live store is behind SCHEMA_SQL. + + Read-only opens skip ``_reconcile_columns()`` by design (no DDL against + another profile's live DB), so a store created before a schema addition + keeps 500ing on read paths until something opens it writable. Callers + that heal on staleness (see ``_open_session_db_at_path`` in + ``hermes_cli/web_server.py``) run these probes right after a read-only + open: any missing table raises "no such table" and any missing column + raises "no such column", both at prepare time. + + Derived from SCHEMA_SQL — the same source of truth the writable + reconciler diffs against — so a column added there is covered here + automatically. A hand-maintained probe list went stale within days of + shipping (it never learned ``sessions.last_activity_at``, so the sidebar + served an empty session list after `hermes update` until the user's + first message forced a writable open). + + Each statement is ``LIMIT 0``: column resolution happens at prepare + time, so the probe reads zero rows. Column references are qualified + with the table name — an unqualified double-quoted identifier that + fails to resolve silently degrades to a string literal (SQLite's + double-quoted-string misfeature), which would make the probe pass on + exactly the stale store it exists to catch. + """ + global _READ_PROBE_STATEMENTS + if _READ_PROBE_STATEMENTS is None: + tables = SessionSchemaMixin._parse_schema_columns(SCHEMA_SQL) + _READ_PROBE_STATEMENTS = tuple( + 'SELECT {} FROM "{}" LIMIT 0'.format( + ", ".join( + '"{}"."{}"'.format( + table.replace('"', '""'), col.replace('"', '""') + ) + for col in cols + ), + table.replace('"', '""'), + ) + for table, cols in sorted(tables.items()) + ) + return _READ_PROBE_STATEMENTS + class SessionSchemaMixin: """See module docstring — mixin for SessionDB (Schema cluster).""" diff --git a/tests/hermes_cli/test_web_server.py b/tests/hermes_cli/test_web_server.py index 462e8881f8e8c..5154fcffbf8c1 100644 --- a/tests/hermes_cli/test_web_server.py +++ b/tests/hermes_cli/test_web_server.py @@ -398,7 +398,9 @@ class TestWebServerEndpoints: assert response.json()["sessions"] == [] assert response.json()["total"] == 0 - @pytest.mark.parametrize("missing_column", ["archived", "pinned"]) + @pytest.mark.parametrize( + "missing_column", ["archived", "pinned", "last_activity_at"] + ) def test_get_sessions_heals_stale_schema_store(self, missing_column): import sqlite3 @@ -434,6 +436,109 @@ class TestWebServerEndpoints: healed.close() assert missing_column in columns + def test_profiles_sidebar_heals_stale_schema_store(self): + """The desktop's batched sidebar route must heal a stale store too. + + The shipped regression (#72424 aftermath): a store predating + ``sessions.last_activity_at`` made every per-profile read raise + "no such column", which this endpoint swallowed into its ``errors`` + array — the desktop rendered "No sessions yet" after `hermes update` + until the user's first message forced a writable open elsewhere. + """ + import sqlite3 + + 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("sidebar-stale", source="cli") + seed.append_message( + session_id="sidebar-stale", role="user", content="hi" + ) + finally: + seed.close() + + legacy = sqlite3.connect(str(db_path)) + try: + legacy.execute("ALTER TABLE sessions DROP COLUMN last_activity_at") + legacy.commit() + finally: + legacy.close() + + response = self.client.get("/api/profiles/sessions/sidebar") + + assert response.status_code == 200 + payload = response.json() + assert payload["errors"] == [] + assert [row["id"] for row in payload["recents"]["sessions"]] == [ + "sidebar-stale" + ] + + def test_heal_gives_up_when_reconcile_cannot_fix_the_store(self, monkeypatch): + """A probe failure reconciliation can't cure must not retry forever. + + The writable heal is a full SessionDB init against a possibly-live + DB. If the store is STILL behind the probe afterwards (schema problem + ADD COLUMN can't express), retrying that init on every sidebar poll + would hammer the DB for nothing: serve reads probe-less instead, warn + once, and never pay the writable open for that store again. + """ + 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("unfixable", source="cli") + finally: + seed.close() + + # A column no SCHEMA_SQL declares: the heal's writable reconcile + # cannot add it, so the re-probe keeps failing. + monkeypatch.setattr( + web_server, + "_session_db_read_probe_statements", + lambda: ('SELECT "sessions"."not_a_real_column" FROM "sessions" LIMIT 0',), + ) + monkeypatch.setattr(web_server, "_session_db_heal_exhausted", set()) + monkeypatch.setattr(web_server, "_session_db_heal_warned", set()) + + writable_opens = [] + + import hermes_state + + original_init = hermes_state.SessionDB.__init__ + + def counting_init(self, *args, **kwargs): + if not kwargs.get("read_only", False): + writable_opens.append(1) + return original_init(self, *args, **kwargs) + + # web_server imports SessionDB inside the function body, so patching + # the class on hermes_state covers every open the helper makes. + monkeypatch.setattr(hermes_state.SessionDB, "__init__", counting_init) + + # First open: probe fails -> one writable heal -> re-probe fails -> + # exhausted. Still returns a usable read-only handle. + db = web_server._open_session_db_for_profile(None, read_only=True) + try: + assert db.list_sessions_rich(limit=10, compact_rows=True) + finally: + db.close() + assert len(writable_opens) == 1 + assert str(db_path) in web_server._session_db_heal_exhausted + + # Second open: probe skipped, NO further writable opens. + db = web_server._open_session_db_for_profile(None, read_only=True) + try: + assert db.list_sessions_rich(limit=10, compact_rows=True) + finally: + db.close() + assert len(writable_opens) == 1 + def test_get_sessions_zero_byte_store_returns_empty_list(self): from hermes_constants import get_hermes_home diff --git a/tests/test_schema_read_probe.py b/tests/test_schema_read_probe.py new file mode 100644 index 0000000000000..9770a8f050a21 --- /dev/null +++ b/tests/test_schema_read_probe.py @@ -0,0 +1,100 @@ +"""Contract tests for schema_read_probe_statements(). + +Read-only SessionDB opens skip _reconcile_columns() by design, so dashboard +read paths heal stale stores via a probe-then-writable-reopen dance in +``hermes_cli.web_server._open_session_db_at_path``. These tests pin the +probe's contract: it is DERIVED from SCHEMA_SQL (any column added there is +covered automatically — the previous hand-written probe went stale within +days) and it must fail at prepare time on a store missing any declared +column or table. +""" + +import sqlite3 + +import pytest + +from hermes_state_common import DEFERRED_INDEX_SQL, SCHEMA_SQL +from hermes_state_schema import SessionSchemaMixin, schema_read_probe_statements + + +def _fresh_schema_conn() -> sqlite3.Connection: + conn = sqlite3.connect(":memory:") + conn.executescript(SCHEMA_SQL) + conn.executescript(DEFERRED_INDEX_SQL) + return conn + + +class TestSchemaReadProbeStatements: + def test_probes_cover_every_declared_column(self): + """Invariant: every column SCHEMA_SQL declares appears in a probe. + + This is the anti-staleness contract — a column added to SCHEMA_SQL + must be probed without anyone remembering to update a list. + """ + expected = SessionSchemaMixin._parse_schema_columns(SCHEMA_SQL) + statements = schema_read_probe_statements() + by_table = {} + for statement in statements: + for table in expected: + if f'FROM "{table}"' in statement: + by_table[table] = statement + for table, cols in expected.items(): + assert table in by_table, f"no probe statement for table {table}" + for col in cols: + assert f'"{table}"."{col}"' in by_table[table], ( + f"column {table}.{col} declared in SCHEMA_SQL but not probed" + ) + + def test_probes_pass_on_fresh_schema(self): + conn = _fresh_schema_conn() + try: + for statement in schema_read_probe_statements(): + conn.execute(statement).fetchone() + finally: + conn.close() + + def test_probes_fail_on_missing_column(self): + """The shipped regression: a store predating sessions.last_activity_at + + (#72424) passed the old hand-written probe, then 500'd inside + list_sessions_rich on every sidebar poll until the user's first + message forced a writable open. + """ + conn = _fresh_schema_conn() + try: + conn.execute("ALTER TABLE sessions DROP COLUMN last_activity_at") + # The failure must come from the sessions probe naming the exact + # column — not incidentally from some other statement — so a + # probe-generation bug that misassigns columns to tables can't + # sneak through. + sessions_probe = next( + s + for s in schema_read_probe_statements() + if 'FROM "sessions"' in s + ) + with pytest.raises(sqlite3.OperationalError) as excinfo: + conn.execute(sessions_probe) + assert "no such column: sessions.last_activity_at" in str( + excinfo.value + ) + finally: + conn.close() + + def test_probes_fail_on_missing_table(self): + conn = sqlite3.connect(":memory:") + try: + conn.executescript(SCHEMA_SQL) + conn.executescript("DROP TABLE gateway_routing") + gateway_probe = next( + s + for s in schema_read_probe_statements() + if 'FROM "gateway_routing"' in s + ) + with pytest.raises(sqlite3.OperationalError) as excinfo: + conn.execute(gateway_probe) + assert "no such table" in str(excinfo.value).lower() + finally: + conn.close() + + def test_probe_statements_are_cached(self): + assert schema_read_probe_statements() is schema_read_probe_statements()