From 4d9ec9be5049669ddec3d6e166605d2a6fd390a3 Mon Sep 17 00:00:00 2001 From: nikkoxgonzales Date: Thu, 10 Sep 2026 07:11:19 +0800 Subject: [PATCH] fix(db): survive DELETE fallback failure in WAL setup --- hermes_state_wal.py | 27 ++++- tests/test_hermes_state_wal_fallback.py | 145 ++++++++++++++++++++++-- 2 files changed, 161 insertions(+), 11 deletions(-) diff --git a/hermes_state_wal.py b/hermes_state_wal.py index c01a0bbc41..fe3bf0b85f 100644 --- a/hermes_state_wal.py +++ b/hermes_state_wal.py @@ -33,6 +33,10 @@ _WAL_SIZE_LIMIT_BYTES = 64 * 1024 * 1024 # 64 MiB _wal_fallback_warned_paths: set[str] = set() _wal_fallback_warned_lock = threading.Lock() +# Dedup for the both-pragmas-failed WARNING (WAL *and* DELETE rejected, e.g. APFS external SSDs under contention). +_wal_delete_fallback_failed_paths: set[str] = set() +_wal_delete_fallback_failed_lock = threading.Lock() + # Dedup for the probe-unknown WARNING (on-disk journal mode unreadable, nothing touched). _wal_probe_unknown_paths: set[str] = set() _wal_probe_unknown_lock = threading.Lock() @@ -291,7 +295,20 @@ def _enable_wal(conn: sqlite3.Connection, db_label: str, require_wal: bool, curr if require_wal: raise WalUnsupportedError(str(exc)) from exc _log_wal_fallback_once(db_label, exc) - _set_journal_mode_no_wait(conn, "DELETE") + try: + _set_journal_mode_no_wait(conn, "DELETE") + except sqlite3.OperationalError as delete_exc: + # Filesystems that reject BOTH pragmas (APFS external SSDs under heavy contention raise + # "disk I/O error" on DELETE too). The connection keeps its current mode — typically the + # SQLite default DELETE — and stays usable for reads/writes, so propagating would crash + # every DB-init caller (SessionDB, kanban_db, ResponseStore) for no benefit. Log once + # per db_label and return the mode actually in effect, read back rather than guessed. + _log_once("wal_delete_fallback_failed", db_label, exc, delete_exc) + try: + read_back = _mode_from_row(conn.execute("PRAGMA journal_mode").fetchone()) + except sqlite3.OperationalError: + read_back = "" + return read_back or "delete" return "delete" @@ -398,6 +415,14 @@ _ONCE_LOGS = { "%s: WAL journal_mode unsupported on this filesystem (%s) — falling back to journal_mode=DELETE (slower " "rollback-journal mode; reduces concurrency but works on NFS/SMB/FUSE/ZFS). See " "https://www.sqlite.org/wal.html for details. This message fires once per process per database."), + "wal_delete_fallback_failed": (_wal_delete_fallback_failed_lock, "_wal_delete_fallback_failed_paths", logging.WARNING, + # Both pragmas rejected (observed on APFS external SSDs under heavy contention): the connection keeps + # whatever mode it has (typically the SQLite default DELETE) and stays usable for reads/writes, so this + # is WARNING, not ERROR — propagating would crash every DB-init caller. Deduped per db_label because + # kanban_db.connect() runs on every kanban operation. + "%s: both WAL and DELETE journal_mode failed (WAL: %s; DELETE: %s) — continuing with the connection's " + "current journal mode (reads/writes still work). Typically seen on APFS external SSDs under heavy " + "contention. This message fires once per process per database."), "delete_overridden": (_delete_overridden_warned_lock, "_delete_overridden_warned_paths", logging.ERROR, # Never-live-downgrade keeps WAL; without this the operator never learns their delete had no effect. "%s: database.journal_mode=delete is configured but the on-disk database is already WAL; keeping WAL (a live " diff --git a/tests/test_hermes_state_wal_fallback.py b/tests/test_hermes_state_wal_fallback.py index 96e4d0bd33..f993dea24a 100644 --- a/tests/test_hermes_state_wal_fallback.py +++ b/tests/test_hermes_state_wal_fallback.py @@ -85,8 +85,10 @@ def _reset_last_init_error(): def _reset_wal_fallback_warned_paths(): """Reset the WAL-fallback warned-paths set so dedup doesn't leak between tests.""" hermes_state_wal._wal_fallback_warned_paths.clear() + hermes_state_wal._wal_delete_fallback_failed_paths.clear() yield hermes_state_wal._wal_fallback_warned_paths.clear() + hermes_state_wal._wal_delete_fallback_failed_paths.clear() @pytest.fixture(autouse=True) @@ -350,6 +352,128 @@ class TestApplyWalWithFallback: f"{[r.getMessage() for r in errors]}" ) + def test_falls_back_when_delete_pragma_also_fails(self, tmp_path, caplog): + """WAL-incompat FS that ALSO rejects DELETE — must not crash callers (#30816). + + ``PRAGMA journal_mode=WAL`` raises a recognized WAL-incompat marker + (``locking protocol``), so the DELETE fallback engages — but DELETE + *also* raises (``disk I/O error``, observed on APFS external SSDs + under heavy contention). The connection's default journal_mode is + already DELETE, so it is still usable; propagating would crash + SessionDB / kanban_db / ResponseStore init. Returns ``"delete"`` + and logs one WARNING per db_label. + + Fault injection only: the APFS trigger itself is not reproducible on + Linux — this drives the same code path with a failing DELETE pragma. + """ + delete_attempts = [0] + + class _DeletePragmaFailsConnection(sqlite3.Connection): + def execute(self, sql, *args, **kwargs): # type: ignore[override] + lowered = sql.lower().replace(" ", "") + if "journal_mode=wal" in lowered: + raise sqlite3.OperationalError("locking protocol") + if "journal_mode=delete" in lowered: + delete_attempts[0] += 1 + raise sqlite3.OperationalError("disk I/O error") + return super().execute(sql, *args, **kwargs) + + conn = sqlite3.connect( + str(tmp_path / "apfs.db"), + factory=_DeletePragmaFailsConnection, + isolation_level=None, + ) + with caplog.at_level("WARNING", logger="hermes_state"): + mode = apply_wal_with_fallback(conn, db_label="apfs-test.db") + + assert mode == "delete" + assert delete_attempts[0] == 1 + + msgs = [r.getMessage() for r in caplog.records if r.levelname in ("WARNING", "ERROR")] + assert any("apfs-test.db" in m and "WAL" in m for m in msgs) + delete_warnings = [ + m for m in msgs if "apfs-test.db" in m and "both WAL and DELETE journal_mode failed" in m + ] + assert len(delete_warnings) == 1 + assert "disk I/O error" in delete_warnings[0] + + # Connection is still usable for non-journal_mode SQL + conn.execute("CREATE TABLE t (x INTEGER)") + conn.execute("INSERT INTO t VALUES (1)") + assert list(conn.execute("SELECT x FROM t"))[0][0] == 1 + conn.close() + + def test_both_pragmas_fail_but_readback_reports_actual_mode(self, tmp_path, caplog): + """When both PRAGMA writes fail, the return value is read back from the + connection — not a hardcoded ``"delete"`` guess. + + The connection here already runs ``journal_mode=MEMORY`` (set before + the failure injection); both WAL and DELETE writes then fail, so the + function must report the actual ``"memory"`` mode. + """ + + class _WritesFailReadsSucceedConnection(sqlite3.Connection): + def execute(self, sql, *args, **kwargs): # type: ignore[override] + lowered = sql.lower().replace(" ", "") + if "journal_mode=wal" in lowered: + raise sqlite3.OperationalError("locking protocol") + if "journal_mode=delete" in lowered: + raise sqlite3.OperationalError("disk I/O error") + return super().execute(sql, *args, **kwargs) + + conn = sqlite3.connect( + str(tmp_path / "readback.db"), + factory=_WritesFailReadsSucceedConnection, + isolation_level=None, + ) + conn.execute("PRAGMA journal_mode=MEMORY") + with caplog.at_level("WARNING", logger="hermes_state"): + mode = apply_wal_with_fallback(conn, db_label="readback.db") + + assert mode == "memory" + msgs = [r.getMessage() for r in caplog.records if r.levelname in ("WARNING", "ERROR")] + assert any( + "readback.db" in m and "both WAL and DELETE journal_mode failed" in m + for m in msgs + ) + conn.close() + + def test_delete_fallback_failure_warning_deduplicated_per_db_label(self, tmp_path, caplog): + """Repeated both-fail calls with the same db_label log exactly ONE WARNING. + + kanban_db.connect() runs on every kanban operation; without dedup, + APFS-external-SSD users would see hundreds of identical warnings. + """ + + class _BothPragmasFailConnection(sqlite3.Connection): + def execute(self, sql, *args, **kwargs): # type: ignore[override] + lowered = sql.lower().replace(" ", "") + if "journal_mode=wal" in lowered: + raise sqlite3.OperationalError("locking protocol") + if "journal_mode=delete" in lowered: + raise sqlite3.OperationalError("disk I/O error") + return super().execute(sql, *args, **kwargs) + + with caplog.at_level("WARNING", logger="hermes_state"): + for i in range(3): + conn = sqlite3.connect( + str(tmp_path / f"apfs-dup-{i}.db"), + factory=_BothPragmasFailConnection, + isolation_level=None, + ) + assert apply_wal_with_fallback(conn, db_label="apfs-shared.db") == "delete" + conn.close() + + delete_warnings = [ + r for r in caplog.records + if r.levelname == "WARNING" + and "apfs-shared.db" in r.getMessage() + and "both WAL and DELETE journal_mode failed" in r.getMessage() + ] + assert len(delete_warnings) == 1, ( + f"Expected 1 deduplicated DELETE-failed warning, got {len(delete_warnings)}" + ) + def test_error_fires_independently_per_db_label(self, tmp_path, caplog): """Different db_labels each get their own one error (not globally dedup'd).""" with caplog.at_level("ERROR", logger="hermes_state"): @@ -427,20 +551,21 @@ class TestGetLastInitError: def test_captures_cause_on_failed_init(self, tmp_path): """When SessionDB() raises, the cause is preserved for slash commands. - Simulates a filesystem where BOTH WAL and DELETE journal modes fail — - e.g. a read-only mount where no ``PRAGMA journal_mode=X`` works (the - read-only mode probe still succeeds, as on a real mount). The - fallback tries DELETE and also gets rejected; the exception bubbles - out of ``SessionDB.__init__`` and the cause is captured. + Simulates a filesystem failure unrelated to the WAL fallback path — + e.g. ``foreign_keys=ON`` rejected by a read-only or seriously + damaged DB. (Both-pragmas-fail no longer raises since #30816: the + DELETE fallback is guarded and returns the mode in effect.) The + exception bubbles out of ``SessionDB.__init__`` and the cause is + captured for /resume to surface. """ target = tmp_path / "broken.db" real_connect = sqlite3.connect - class _BothPragmasFailConnection(sqlite3.Connection): + class _ForeignKeysFailConnection(sqlite3.Connection): def execute(self, sql, *args, **kwargs): # type: ignore[override] - if "journal_mode=" in sql.lower().replace(" ", ""): + if "foreign_keys=on" in sql.lower().replace(" ", ""): raise sqlite3.OperationalError( - "locking protocol: read-only filesystem" + "foreign_keys=ON rejected: read-only filesystem" ) return super().execute(sql, *args, **kwargs) @@ -448,7 +573,7 @@ class TestGetLastInitError: # connect_tracked passes a tracking-augmented factory; drop it and # substitute the double, which connect_tracked will re-augment. kwargs.pop("factory", None) - return real_connect(str(target), factory=_BothPragmasFailConnection, **kwargs) + return real_connect(str(target), factory=_ForeignKeysFailConnection, **kwargs) with patch("hermes_state.sqlite3.connect", side_effect=gated_connect): with pytest.raises(sqlite3.OperationalError): @@ -457,7 +582,7 @@ class TestGetLastInitError: cause = get_last_init_error() assert cause is not None assert "OperationalError" in cause - assert "locking protocol" in cause + assert "read-only filesystem" in cause class TestFormatSessionDbUnavailable: