diff --git a/hermes_state.py b/hermes_state.py index 31ead8fd68..ef190d1909 100644 --- a/hermes_state.py +++ b/hermes_state.py @@ -40,7 +40,7 @@ from hermes_state_errors import ( _DELETED_WAL_GENERATION_MSG, _DISK_IO_ERROR_MARKER, _STATE_DB_CORRUPT_MSG, _STATE_DB_GENERATION_KEY, _STATE_DB_REPLACED_MSG, DeletedWalGenerationError, SessionCompressionInProgressError, StateDbCorruptError, StateDbReplacedError, _is_no_more_rows, classify_persistence_error, is_malformed_db_error, - is_malformed_schema_error, + is_malformed_schema_error, is_sqlite_lock_error, ) from hermes_state_guard import ( _STATE_DB_GUARD_BYPASS_ENV, _in_test_context, _is_production_state_db, _real_platform_state_root, @@ -711,7 +711,9 @@ class SessionDB( # SQLITE_IOERR to a mode=ro reader (it can't do the -shm recovery the read # needs). Closes in milliseconds: retry a bounded number of times before # classifying the store as failed (#100436; see _READ_ONLY_IOERR_RETRY_ATTEMPTS). - transient = _DISK_IO_ERROR_MARKER in str(ioerr).lower() + # A DELETE-mode writer's commit outlasting the busy timeout is the same "busy, + # not broken" class; each retry waits the busy timeout again. + transient = is_sqlite_lock_error(ioerr) or _DISK_IO_ERROR_MARKER in str(ioerr).lower() if attempt >= _READ_ONLY_IOERR_RETRY_ATTEMPTS or not transient: raise time.sleep(_READ_ONLY_IOERR_RETRY_BACKOFF_S) @@ -801,8 +803,7 @@ class SessionDB( self._connect_and_init() return except sqlite3.OperationalError as exc: - err = str(exc).lower() - if "locked" not in err and "busy" not in err: + if not is_sqlite_lock_error(exc): raise self._close_connection_quietly(self._conn) now = time.monotonic() @@ -1041,7 +1042,7 @@ class SessionDB( continue err_msg = str(exc).lower() if isinstance(exc, sqlite3.OperationalError): - if "locked" in err_msg or "busy" in err_msg: + if is_sqlite_lock_error(exc): if self._sleep_before_write_retry(deadline, patience_s): continue # Say what actually happened, not disk/permission damage. The holder goes to diff --git a/hermes_state_errors.py b/hermes_state_errors.py index 0ea726ba08..4528a31755 100644 --- a/hermes_state_errors.py +++ b/hermes_state_errors.py @@ -34,6 +34,28 @@ _TRANSIENT_SQLITE_MARKERS = ( ) +# Lock contention by result code. SQLite keeps SQLITE_BUSY when FTS5's xConnect loses the race +# on its %_config read but replaces the text with "vtable constructor failed: messages_fts", +# so a phrase match read a busy store as a hard failure. +_SQLITE_LOCK_CODES = (sqlite3.SQLITE_BUSY, sqlite3.SQLITE_LOCKED) + + +def _sqlite_primary_code(exc_or_str) -> "int | None": + """Primary result code (extended codes keep it in the low byte); None when unknown.""" + code = getattr(exc_or_str, "sqlite_errorcode", None) + return code & 0xFF if isinstance(code, int) else None + + +def is_sqlite_lock_error(exc_or_str) -> bool: + """SQLITE_BUSY / SQLITE_LOCKED: wait and retry, never treat as damage. A known result code + decides; only without one (our own re-raised messages, RPC-wrapped strings) does the text.""" + code = _sqlite_primary_code(exc_or_str) + if code is not None: + return code in _SQLITE_LOCK_CODES + text = str(exc_or_str).lower() + return "locked" in text or "busy" in text + + def _is_no_more_rows(exc: sqlite3.Error) -> bool: """Transient engine error on contended WAL appends (retries like locked/busy); message-scoped because some builds raise it as InterfaceError.""" @@ -43,8 +65,8 @@ def _is_no_more_rows(exc: sqlite3.Error) -> bool: def is_transient_sqlite_error(exc: BaseException) -> bool: """"Busy right now", not "damaged": one predicate so retry and the HTTP 503-vs-500 split cannot drift apart.""" - return isinstance(exc, sqlite3.OperationalError) and any( - marker in str(exc).lower() for marker in _TRANSIENT_SQLITE_MARKERS + return isinstance(exc, sqlite3.OperationalError) and ( + is_sqlite_lock_error(exc) or any(marker in str(exc).lower() for marker in _TRANSIENT_SQLITE_MARKERS) ) @@ -263,6 +285,8 @@ def classify_persistence_error(exc_or_str) -> str: # naming messages_fts*) is index damage, never whole-file corruption (#97794). if is_fts_scoped_corruption_error(exc_or_str): return "fts_index" + if _sqlite_primary_code(exc_or_str) in _SQLITE_LOCK_CODES: + return "locked" text = str(exc_or_str).lower() for markers, cause in _PERSISTENCE_CAUSE_BY_PHRASE: if any(marker in text for marker in markers): diff --git a/hermes_state_holders.py b/hermes_state_holders.py index aa8a40bccf..9143a9b3cd 100644 --- a/hermes_state_holders.py +++ b/hermes_state_holders.py @@ -15,6 +15,8 @@ import sys from pathlib import Path from typing import Callable, List, Optional, Sequence, Set, Tuple +from hermes_state_errors import is_sqlite_lock_error + try: # Hard dependency, but tolerate scaffold-phase imports before pip install. import psutil except ImportError: # pragma: no cover - stripped/scaffold installs only @@ -536,8 +538,7 @@ def live_writer_holds_db( probe.execute("ROLLBACK") return False except sqlite3.OperationalError as exc: - lowered = str(exc).lower() - return "locked" in lowered or "busy" in lowered + return is_sqlite_lock_error(exc) except sqlite3.DatabaseError: # Malformed/unreadable with no holder on the scan: nobody else has it open, so repair may run. return False diff --git a/hermes_state_schema.py b/hermes_state_schema.py index a100b6b143..ffd06529fb 100644 --- a/hermes_state_schema.py +++ b/hermes_state_schema.py @@ -28,6 +28,7 @@ from hermes_state_common import ( ) from hermes_state_fts import _drop_orphan_fts_shadow_tables from hermes_state_holders import _read_proc_argv +from hermes_state_errors import is_sqlite_lock_error # Pre-split logger identity so log filtering/capture is unchanged. logger = logging.getLogger("hermes_state") @@ -767,7 +768,7 @@ class SessionSchemaMixin: # A sibling process won the ADD race; store is correct. logger.debug("reconcile %s.%s: %s", table_name, col_name, exc) continue - if "locked" in message or "busy" in message: + if is_sqlite_lock_error(exc): # Swallowing lock contention left the store half-reconciled ("no such # column" on every read). Re-raise so the lock-patience wrapper retries init. raise diff --git a/hermes_state_wal.py b/hermes_state_wal.py index 114853c313..eb8b39e43d 100644 --- a/hermes_state_wal.py +++ b/hermes_state_wal.py @@ -16,6 +16,7 @@ import time from typing import Any, Dict, Optional from hermes_cli.sqlite_runtime import is_sqlite_wal_reset_vulnerable as _is_sqlite_wal_reset_vulnerable +from hermes_state_errors import is_sqlite_lock_error # Log-record parity with the origin module (caplog tests pin "hermes_state"). logger = logging.getLogger("hermes_state") @@ -451,7 +452,7 @@ def _apply_delete_for_wal_reset_bug(conn: sqlite3.Connection, *, db_label: str, except sqlite3.OperationalError as exc: if require_delete: raise - if "locked" in str(exc).lower() or "busy" in str(exc).lower(): + if is_sqlite_lock_error(exc): # A concurrent opener appeared between probe and flip: leave the mode as is. _log_wal_reset_bug_once(db_label, kept_wal=True, indeterminate=True) return current or "delete" diff --git a/tests/hermes_state/test_write_lock_patience.py b/tests/hermes_state/test_write_lock_patience.py index 5702200544..994f89d44e 100644 --- a/tests/hermes_state/test_write_lock_patience.py +++ b/tests/hermes_state/test_write_lock_patience.py @@ -148,3 +148,86 @@ class TestOpenLockPatience: SessionDB(db_path=bad_path) # Must fail well before a full patience window (loose bound). assert time.monotonic() - t0 < 15.0 + + +def _use_delete_journal_mode(monkeypatch, tmp_path): + home = tmp_path / "hermes-home" + home.mkdir() + (home / "config.yaml").write_text("database:\n journal_mode: delete\n", encoding="utf-8") + monkeypatch.setenv("HERMES_HOME", str(home)) + + +def _hold_exclusive(db_path, hold_s, started_evt): + """DELETE mode: only EXCLUSIVE shuts readers out (a sibling's commit or VACUUM).""" + conn = sqlite3.connect(str(db_path), timeout=1.0, isolation_level=None) + try: + conn.execute("BEGIN EXCLUSIVE") + started_evt.set() + time.sleep(hold_s) + conn.execute("COMMIT") + finally: + conn.close() + + +@pytest.mark.parametrize("read_only", [False, True], ids=["writer", "read_only"]) +def test_open_waits_out_lock_lost_inside_fts_constructor(tmp_path, monkeypatch, read_only): + """A DELETE-mode sibling taking the lock between schema load and the messages_fts probe + makes SQLite report SQLITE_BUSY as "vtable constructor failed: messages_fts" (FTS5's + xConnect reads %_config). The open must wait that out like any other lock, not fail.""" + _use_delete_journal_mode(monkeypatch, tmp_path) + db_path = tmp_path / "state.db" + seed = SessionDB(db_path=db_path) + assert not seed._wal_active + seed.create_session("s", "cli") + seed.append_message(session_id="s", role="user", content="needle") + seed.close() + + started = threading.Event() + holder = threading.Thread(target=_hold_exclusive, args=(db_path, 2.5, started)) + real_probe = SessionDB._fts_table_probe + + def probe_after_sibling_takes_lock(self, cursor, table_name): + if table_name == "messages_fts" and not holder.is_alive() and not started.is_set(): + cursor.execute("SELECT count(*) FROM sqlite_master").fetchall() # schema cached + holder.start() + assert started.wait(5.0) + return real_probe(self, cursor, table_name) + + monkeypatch.setattr(SessionDB, "_fts_table_probe", probe_after_sibling_takes_lock) + try: + db = SessionDB(db_path=db_path, read_only=read_only) + finally: + if started.is_set(): + holder.join(timeout=10.0) + try: + assert started.is_set(), "the lock race was never placed" + assert db._fts_enabled is True + assert [m["content"] for m in db.get_messages("s")] == ["needle"] + finally: + db.close() + + +def test_lock_lost_inside_fts_constructor_classifies_as_busy(tmp_path): + """When patience does run out, the same error must read as "busy" (HTTP 503, "locked" + guidance), not as an internal error: SQLite keeps SQLITE_BUSY but not the wording.""" + from hermes_state_errors import classify_persistence_error, is_transient_sqlite_error + + db_path = tmp_path / "fts.db" + setup = sqlite3.connect(str(db_path)) + setup.execute("PRAGMA journal_mode=DELETE") + setup.execute("CREATE VIRTUAL TABLE messages_fts USING fts5(content)") + setup.commit() + setup.close() + reader = sqlite3.connect(str(db_path), timeout=0.05) + holder = sqlite3.connect(str(db_path), isolation_level=None) + try: + reader.execute("SELECT count(*) FROM sqlite_master").fetchall() + holder.execute("BEGIN EXCLUSIVE") + with pytest.raises(sqlite3.OperationalError) as excinfo: + reader.execute("SELECT * FROM messages_fts LIMIT 0").fetchall() + finally: + holder.close() + reader.close() + assert "vtable constructor failed" in str(excinfo.value) + assert is_transient_sqlite_error(excinfo.value) + assert classify_persistence_error(excinfo.value) == "locked" diff --git a/website/docs/developer-guide/session-storage.md b/website/docs/developer-guide/session-storage.md index e3c45ccd6d..7faf21d767 100644 --- a/website/docs/developer-guide/session-storage.md +++ b/website/docs/developer-guide/session-storage.md @@ -327,6 +327,15 @@ PENDING/RESERVED/SHARED). The open-descriptor scan cannot make this distinction because every Hermes process has the DB open. Look for that line in `~/.hermes/logs/errors.log` next to the `database is locked` failure. +Lock contention is recognised by SQLite result code (`SQLITE_BUSY` / +`SQLITE_LOCKED`, `hermes_state_errors.is_sqlite_lock_error`), not by message +text. In rollback-journal (`delete`) mode a lock lost inside FTS5's table +constructor arrives as `SQLITE_BUSY` with the text `vtable constructor failed: +messages_fts`; it is treated like `database is locked`. Opening a writable +`SessionDB` waits up to `_WRITE_PATIENCE_S`; a read-only open retries the busy +timeout a bounded number of times. If the lock outlasts that, the dashboard +answers 503 (busy), not 500. + ## Common Operations