diff --git a/hermes_state_wal.py b/hermes_state_wal.py index 414722cbb8..5e3e5ffeae 100644 --- a/hermes_state_wal.py +++ b/hermes_state_wal.py @@ -32,6 +32,11 @@ _WAL_SIZE_LIMIT_BYTES = 64 * 1024 * 1024 # 64 MiB # line would repeat per connection). Tests clear these via ``hermes_state_wal.``. _wal_fallback_warned_paths: set[str] = set() _wal_fallback_warned_lock = threading.Lock() + +# Dedup WARNING for the #104596 probe-unknown guard (WAL path touching nothing +# while ownership is not provably exclusive). +_wal_probe_unknown_paths: set[str] = set() +_wal_probe_unknown_lock = threading.Lock() _wal_reset_bug_warned_paths: set[str] = set() _wal_reset_bug_warned_lock = threading.Lock() _delete_overridden_warned_paths: set[str] = set() @@ -214,6 +219,19 @@ def apply_wal_with_fallback(conn: sqlite3.Connection, *, db_label: str = "state. # Probe failed (locked/busy): ownership not provably exclusive. Fail loudly. raise sqlite3.OperationalError(_CANNOT_VERIFY_DELETE_MSG) return _verify_configured_delete(_set_journal_mode_no_wait(conn, "DELETE")) + if current_mode is None: + # #104596: the probe failed (locked/busy under load) and the on-disk mode is unknown. A fresh 0-page + # DB probes "delete" cleanly, so None here means the probe could not read a real file — most often + # because a sibling connection (same process or another) holds it, in WAL, with live -wal/-shm sidecars. + # Emitting the set-pragma inside _enable_wal would re-run WAL-init and UNLINK those sidecars under the + # holder: two -shm generations that cannot see each other's locks -> split-brain corruption + # (btreeInitPage error 11). Ownership is not provably exclusive, so touch nothing: an already-WAL DB + # keeps working (this connection inherits the mode from the on-disk header, exactly like the early + # return above), the rare true-DELETE file degrades to DELETE with the warning below, and a new DB + # reaches _enable_wal on its next open. Mirrors the vulnerable-gate path's indeterminate handling. + _log_once("wal_probe_unknown", db_label) + _apply_wal_companions(conn) + return "wal" return _enable_wal(conn, db_label, require_wal, current_mode) @@ -389,6 +407,17 @@ _ONCE_LOGS = { "downgrade under open connections can corrupt the DB). To apply journal_mode=DELETE, stop all connections to " "this DB and run a one-time offline 'PRAGMA journal_mode=DELETE' on the file. This message fires once per " "process per database."), + "wal_probe_unknown": (_wal_probe_unknown_lock, "_wal_probe_unknown_paths", logging.WARNING, + # #104596: the read-only probe failed (locked/busy under load). A fresh 0-page DB probes "delete" cleanly, + # so None means the probe could not read a real file — most often because a sibling connection holds it, in + # WAL, with live -wal/-shm sidecars. Emitting the set-pragma here re-runs WAL-init and unlinks those + # sidecars under the holder: two -shm generations that cannot see each other's locks -> split-brain + # corruption. Keep the WARNING (not ERROR): the connection still inherits WAL from the on-disk header, so + # the common case is harmless — only the rare true-DELETE file degrades (silently, to DELETE). + "%s: could not verify the on-disk journal mode (database is locked / busy under load); refusing to issue a " + "journal-mode set-pragma while ownership is not provably exclusive (it could unlink the -wal/-shm sidecars " + "a sibling connection still holds open — split-brain corruption, #104596). Assuming the configured " + "journal_mode=wal and leaving the file untouched. This message fires once per process per database."), } diff --git a/tests/test_journal_mode_config.py b/tests/test_journal_mode_config.py index d2fff91c1a..a78f9427e1 100644 --- a/tests/test_journal_mode_config.py +++ b/tests/test_journal_mode_config.py @@ -42,6 +42,102 @@ def _reset_configured_delete_override_warned_paths(): hermes_state_wal._delete_overridden_warned_paths.clear() +def test_wal_probe_unknown_never_emits_set_pragma(monkeypatch, tmp_path, caplog): + """#104596: probe failure (None) must not reach the WAL set-pragma. + + The DELETE branch refuses to flip modes when the on-disk mode cannot be + verified (ownership not provably exclusive). The configured-WAL branch + used to fall through to ``_enable_wal`` and emit ``PRAGMA + journal_mode=WAL`` anyway; when a sibling connection holds the DB in WAL + with live -wal/-shm sidecars, WAL-init unlinks those sidecars under the + holder -> two -shm generations -> split-brain corruption (btreeInitPage + error 11). The guard must touch nothing and assume the configured mode. + """ + import logging + + from hermes_state_wal import apply_wal_with_fallback + + _configure_mode(monkeypatch, tmp_path, "wal") + _disable_vulnerable_gate(monkeypatch) + hermes_state_wal._wal_probe_unknown_paths.clear() + + class _SpyConnection(sqlite3.Connection): + def __init__(self, *args, **kwargs): + super().__init__(*args, **kwargs) + self.emitted: list[str] = [] + + def execute(self, sql, *args, **kwargs): # type: ignore[override] + if "journal_mode" in sql.lower() and "=" in sql.lower(): + self.emitted.append(str(sql)) + return super().execute(sql, *args, **kwargs) + + db_path = tmp_path / "probe-unknown.db" + sibling = sqlite3.connect(str(db_path)) + try: + # A DB that is genuinely WAL on disk; the sibling holds the sidecars. + assert ( + sibling.execute("PRAGMA journal_mode=WAL").fetchone()[0].lower() + == "wal" + ) + # The probe fails under load (locked/busy) -> on-disk mode unknown. + monkeypatch.setattr( + "hermes_state_wal._on_disk_journal_mode", lambda _conn: None + ) + conn = sqlite3.connect(str(db_path), factory=_SpyConnection) + try: + with caplog.at_level(logging.WARNING, logger="hermes_state_wal"): + result = apply_wal_with_fallback( + conn, db_label="probe-unknown.db" + ) + assert result == "wal" # assumed configured mode + assert conn.emitted == [] # no set-pragma while ownership unproven + # The sibling's on-disk WAL state is untouched. + assert ( + sibling.execute("PRAGMA journal_mode").fetchone()[0].lower() + == "wal" + ) + assert any( + "could not verify the on-disk journal mode" in r.getMessage() + for r in caplog.records + ) + finally: + conn.close() + finally: + sibling.close() + + +def test_wal_probe_unknown_warns_once_per_database(monkeypatch, tmp_path, caplog): + """Dedupe contract: one WARNING per (process, db_label).""" + import logging + + from hermes_state_wal import apply_wal_with_fallback + + _configure_mode(monkeypatch, tmp_path, "wal") + _disable_vulnerable_gate(monkeypatch) + hermes_state_wal._wal_probe_unknown_paths.clear() + + monkeypatch.setattr( + "hermes_state_wal._on_disk_journal_mode", lambda _conn: None + ) + db_path = tmp_path / "warn.db" + conn = sqlite3.connect(str(db_path)) + try: + with caplog.at_level(logging.WARNING, logger="hermes_state_wal"): + assert apply_wal_with_fallback(conn, db_label="warn.db") == "wal" + assert apply_wal_with_fallback(conn, db_label="warn.db") == "wal" + assert ( + apply_wal_with_fallback(conn, db_label="other.db") == "wal" + ) + hits = [ + r + for r in caplog.records + if "could not verify the on-disk journal mode" in r.getMessage() + ] + assert len(hits) == 2 # warn.db once, other.db once + finally: + conn.close() + + def test_database_journal_mode_has_a_canonical_default(): from hermes_cli.config import DEFAULT_CONFIG diff --git a/tests/test_sqlite_wal_reset_gate.py b/tests/test_sqlite_wal_reset_gate.py index 6d3b0e96dc..09354c59cb 100644 --- a/tests/test_sqlite_wal_reset_gate.py +++ b/tests/test_sqlite_wal_reset_gate.py @@ -350,14 +350,28 @@ class TestNoDowngradeUnderConcurrentOpeners: finally: check.close() - def test_nfs_fallback_reraises_when_mode_unreadable(self, tmp_path, monkeypatch): - """The filesystem-incompat fallback must not downgrade when the on-disk - mode cannot be verified (possible concurrent openers).""" + def test_probe_unreadable_touches_nothing(self, tmp_path, monkeypatch, caplog): + """#104596: when the on-disk mode cannot be verified (possible + concurrent openers — same-process siblings holding live -wal/-shm + sidecars), the WAL path must not emit the set-pragma at all. + + Previously it fell through to ``PRAGMA journal_mode=WAL``; on an + incompatible filesystem that raised, but on a WAL DB whose sidecars + a sibling connection still holds, WAL-init silently unlinked them -> + two -shm generations -> split-brain corruption (btreeInitPage error + 11). The guard now refuses to touch anything while ownership is + unproven: it assumes the configured WAL mode, logs one warning per + database, and returns without issuing the set-pragma — strictly more + conservative than the old raise (which still required emitting the + dangerous pragma first). + """ + import logging + monkeypatch.setattr( hermes_state_wal, "is_sqlite_wal_reset_vulnerable", lambda version_info=None: False, ) - hermes_state_wal._wal_fallback_warned_paths.clear() + hermes_state_wal._wal_probe_unknown_paths.clear() class _LockedProbeConnection(sqlite3.Connection): def execute(self, sql, *args, **kwargs): # type: ignore[override] @@ -372,8 +386,15 @@ class TestNoDowngradeUnderConcurrentOpeners: str(tmp_path / "nfs.db"), factory=_LockedProbeConnection ) try: - with pytest.raises(sqlite3.OperationalError, match="locking protocol"): - apply_wal_with_fallback(conn, db_label="nfs.db") + with caplog.at_level(logging.WARNING, logger="hermes_state_wal"): + result = apply_wal_with_fallback(conn, db_label="nfs.db") + # The set-pragma never ran (it would have raised "locking + # protocol" above); the configured WAL mode is assumed instead. + assert result == "wal" + assert any( + "could not verify the on-disk journal mode" in r.getMessage() + for r in caplog.records + ) finally: conn.close()