fix(state): SessionDB open waits out a lock lost inside the FTS constructor
In rollback-journal (DELETE) mode a sibling process can take the write lock between schema load and the messages_fts probe. FTS5's xConnect then fails its %_config read and SQLite reports SQLITE_BUSY with the text "vtable constructor failed: messages_fts". Every state.db lock classifier matched on the words "locked"/"busy", so: - a writable SessionDB() failed after 1s instead of waiting out the lock with _WRITE_PATIENCE_S, and callers disabled persistence for the run; - a read-only open (dashboard, `hermes sessions list`, cross-profile readers) failed on the first busy timeout with no retry at all; - the error read as not transient (dashboard 500, not 503) and as persistence cause "unknown" instead of "locked". Add hermes_state_errors.is_sqlite_lock_error: SQLITE_BUSY/SQLITE_LOCKED by result code when SQLite supplies one, text only when it does not (our own re-raised messages, RPC-wrapped strings). Route the writer open patience loop, the _execute_write retry, the reconcile re-raise, the WAL->DELETE flip, the maintenance holder probe, is_transient_sqlite_error and classify_persistence_error through it. The read-only open retries a lock inside its existing bounded retry budget, next to the transient IOERR case.
This commit is contained in:
@@ -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,
|
_DELETED_WAL_GENERATION_MSG, _DISK_IO_ERROR_MARKER, _STATE_DB_CORRUPT_MSG, _STATE_DB_GENERATION_KEY,
|
||||||
_STATE_DB_REPLACED_MSG, DeletedWalGenerationError, SessionCompressionInProgressError, StateDbCorruptError,
|
_STATE_DB_REPLACED_MSG, DeletedWalGenerationError, SessionCompressionInProgressError, StateDbCorruptError,
|
||||||
StateDbReplacedError, _is_no_more_rows, classify_persistence_error, is_malformed_db_error,
|
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 (
|
from hermes_state_guard import (
|
||||||
_STATE_DB_GUARD_BYPASS_ENV, _in_test_context, _is_production_state_db, _real_platform_state_root,
|
_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
|
# 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
|
# needs). Closes in milliseconds: retry a bounded number of times before
|
||||||
# classifying the store as failed (#100436; see _READ_ONLY_IOERR_RETRY_ATTEMPTS).
|
# 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:
|
if attempt >= _READ_ONLY_IOERR_RETRY_ATTEMPTS or not transient:
|
||||||
raise
|
raise
|
||||||
time.sleep(_READ_ONLY_IOERR_RETRY_BACKOFF_S)
|
time.sleep(_READ_ONLY_IOERR_RETRY_BACKOFF_S)
|
||||||
@@ -801,8 +803,7 @@ class SessionDB(
|
|||||||
self._connect_and_init()
|
self._connect_and_init()
|
||||||
return
|
return
|
||||||
except sqlite3.OperationalError as exc:
|
except sqlite3.OperationalError as exc:
|
||||||
err = str(exc).lower()
|
if not is_sqlite_lock_error(exc):
|
||||||
if "locked" not in err and "busy" not in err:
|
|
||||||
raise
|
raise
|
||||||
self._close_connection_quietly(self._conn)
|
self._close_connection_quietly(self._conn)
|
||||||
now = time.monotonic()
|
now = time.monotonic()
|
||||||
@@ -1041,7 +1042,7 @@ class SessionDB(
|
|||||||
continue
|
continue
|
||||||
err_msg = str(exc).lower()
|
err_msg = str(exc).lower()
|
||||||
if isinstance(exc, sqlite3.OperationalError):
|
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):
|
if self._sleep_before_write_retry(deadline, patience_s):
|
||||||
continue
|
continue
|
||||||
# Say what actually happened, not disk/permission damage. The holder goes to
|
# Say what actually happened, not disk/permission damage. The holder goes to
|
||||||
|
|||||||
@@ -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:
|
def _is_no_more_rows(exc: sqlite3.Error) -> bool:
|
||||||
"""Transient engine error on contended WAL appends (retries like locked/busy);
|
"""Transient engine error on contended WAL appends (retries like locked/busy);
|
||||||
message-scoped because some builds raise it as InterfaceError."""
|
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:
|
def is_transient_sqlite_error(exc: BaseException) -> bool:
|
||||||
""""Busy right now", not "damaged": one predicate so retry and the HTTP
|
""""Busy right now", not "damaged": one predicate so retry and the HTTP
|
||||||
503-vs-500 split cannot drift apart."""
|
503-vs-500 split cannot drift apart."""
|
||||||
return isinstance(exc, sqlite3.OperationalError) and any(
|
return isinstance(exc, sqlite3.OperationalError) and (
|
||||||
marker in str(exc).lower() for marker in _TRANSIENT_SQLITE_MARKERS
|
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).
|
# naming messages_fts*) is index damage, never whole-file corruption (#97794).
|
||||||
if is_fts_scoped_corruption_error(exc_or_str):
|
if is_fts_scoped_corruption_error(exc_or_str):
|
||||||
return "fts_index"
|
return "fts_index"
|
||||||
|
if _sqlite_primary_code(exc_or_str) in _SQLITE_LOCK_CODES:
|
||||||
|
return "locked"
|
||||||
text = str(exc_or_str).lower()
|
text = str(exc_or_str).lower()
|
||||||
for markers, cause in _PERSISTENCE_CAUSE_BY_PHRASE:
|
for markers, cause in _PERSISTENCE_CAUSE_BY_PHRASE:
|
||||||
if any(marker in text for marker in markers):
|
if any(marker in text for marker in markers):
|
||||||
|
|||||||
@@ -15,6 +15,8 @@ import sys
|
|||||||
from pathlib import Path
|
from pathlib import Path
|
||||||
from typing import Callable, List, Optional, Sequence, Set, Tuple
|
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.
|
try: # Hard dependency, but tolerate scaffold-phase imports before pip install.
|
||||||
import psutil
|
import psutil
|
||||||
except ImportError: # pragma: no cover - stripped/scaffold installs only
|
except ImportError: # pragma: no cover - stripped/scaffold installs only
|
||||||
@@ -536,8 +538,7 @@ def live_writer_holds_db(
|
|||||||
probe.execute("ROLLBACK")
|
probe.execute("ROLLBACK")
|
||||||
return False
|
return False
|
||||||
except sqlite3.OperationalError as exc:
|
except sqlite3.OperationalError as exc:
|
||||||
lowered = str(exc).lower()
|
return is_sqlite_lock_error(exc)
|
||||||
return "locked" in lowered or "busy" in lowered
|
|
||||||
except sqlite3.DatabaseError:
|
except sqlite3.DatabaseError:
|
||||||
# Malformed/unreadable with no holder on the scan: nobody else has it open, so repair may run.
|
# Malformed/unreadable with no holder on the scan: nobody else has it open, so repair may run.
|
||||||
return False
|
return False
|
||||||
|
|||||||
@@ -28,6 +28,7 @@ from hermes_state_common import (
|
|||||||
)
|
)
|
||||||
from hermes_state_fts import _drop_orphan_fts_shadow_tables
|
from hermes_state_fts import _drop_orphan_fts_shadow_tables
|
||||||
from hermes_state_holders import _read_proc_argv
|
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.
|
# Pre-split logger identity so log filtering/capture is unchanged.
|
||||||
logger = logging.getLogger("hermes_state")
|
logger = logging.getLogger("hermes_state")
|
||||||
@@ -767,7 +768,7 @@ class SessionSchemaMixin:
|
|||||||
# A sibling process won the ADD race; store is correct.
|
# A sibling process won the ADD race; store is correct.
|
||||||
logger.debug("reconcile %s.%s: %s", table_name, col_name, exc)
|
logger.debug("reconcile %s.%s: %s", table_name, col_name, exc)
|
||||||
continue
|
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
|
# Swallowing lock contention left the store half-reconciled ("no such
|
||||||
# column" on every read). Re-raise so the lock-patience wrapper retries init.
|
# column" on every read). Re-raise so the lock-patience wrapper retries init.
|
||||||
raise
|
raise
|
||||||
|
|||||||
@@ -16,6 +16,7 @@ import time
|
|||||||
from typing import Any, Dict, Optional
|
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_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").
|
# Log-record parity with the origin module (caplog tests pin "hermes_state").
|
||||||
logger = logging.getLogger("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:
|
except sqlite3.OperationalError as exc:
|
||||||
if require_delete:
|
if require_delete:
|
||||||
raise
|
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.
|
# 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)
|
_log_wal_reset_bug_once(db_label, kept_wal=True, indeterminate=True)
|
||||||
return current or "delete"
|
return current or "delete"
|
||||||
|
|||||||
@@ -148,3 +148,86 @@ class TestOpenLockPatience:
|
|||||||
SessionDB(db_path=bad_path)
|
SessionDB(db_path=bad_path)
|
||||||
# Must fail well before a full patience window (loose bound).
|
# Must fail well before a full patience window (loose bound).
|
||||||
assert time.monotonic() - t0 < 15.0
|
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"
|
||||||
|
|||||||
@@ -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
|
because every Hermes process has the DB open. Look for that line in
|
||||||
`~/.hermes/logs/errors.log` next to the `database is locked` failure.
|
`~/.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
|
## Common Operations
|
||||||
|
|
||||||
|
|||||||
Reference in New Issue
Block a user