From 0f60cdac27e90a32e57258c6c383f1c126b37510 Mon Sep 17 00:00:00 2001 From: Connor Black Date: Thu, 18 Jun 2026 03:33:47 -0400 Subject: [PATCH] =?UTF-8?q?fix(state):=20escalate=20silent=20WAL=E2=86=92D?= =?UTF-8?q?ELETE=20fallback=20to=20ERROR=20+=20opt-in=20require=5Fwal?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The WAL→DELETE fallback on WAL-incompatible filesystems (NFS / SMB / FUSE / the AgentFS NFS overlay) was logged at WARNING, treating a real loss of concurrency — under the kanban dispatcher + workers a write blocks readers, surfacing as SQLITE_BUSY — as if it were cosmetic. Escalate the deduplicated fallback log to ERROR so the degradation is observable, not silent. Add an opt-in require_wal=True to apply_wal_with_fallback that raises a typed WalUnsupportedError (subclass of sqlite3.OperationalError, so existing DB-init handlers still catch it) instead of degrading to DELETE, for callers that mandate WAL concurrency. All four current callers keep the default require_wal=False so NFS-homed installs keep working unchanged. Tests: 4 new require_wal cases; WARNING→ERROR assertion updates in both test_hermes_state_wal_fallback.py and test_kanban_db.py. --- hermes_cli/kanban_db.py | 2 +- hermes_state.py | 75 +++++++--- tests/hermes_cli/test_kanban_db.py | 61 ++++++++ tests/test_hermes_state_wal_fallback.py | 179 ++++++++++++++++++++++-- 4 files changed, 283 insertions(+), 34 deletions(-) diff --git a/hermes_cli/kanban_db.py b/hermes_cli/kanban_db.py index be9f16f2f2..f558130a80 100644 --- a/hermes_cli/kanban_db.py +++ b/hermes_cli/kanban_db.py @@ -2173,7 +2173,7 @@ def connect( # critical section as schema initialization so concurrent gateway # startup threads do not race before _INITIALIZED_PATHS is populated. # WAL doesn't work on network filesystems (NFS/SMB/FUSE). Shared helper - # falls back to DELETE with one WARNING so kanban stays usable there. + # falls back to DELETE with one ERROR log so kanban stays usable there. # See hermes_state._WAL_INCOMPAT_MARKERS for detection logic. from hermes_state import apply_wal_with_fallback apply_wal_with_fallback(conn, db_label=f"kanban.db ({path.name})") diff --git a/hermes_state.py b/hermes_state.py index c50c91062f..e3dd113c52 100644 --- a/hermes_state.py +++ b/hermes_state.py @@ -537,19 +537,38 @@ def resolve_journal_mode() -> str: return mode if mode in ("wal", "delete") else "wal" +class WalUnsupportedError(sqlite3.OperationalError): + """Raised by :func:`apply_wal_with_fallback` when ``require_wal=True`` and + the filesystem cannot provide WAL journal mode. + + Covers both shapes of WAL refusal on network filesystems (NFS / SMB / FUSE + / the AgentFS NFS overlay): SQLite *raising* ``SQLITE_PROTOCOL`` ("locking + protocol"), and the quieter macOS-NFS case where ``PRAGMA journal_mode=WAL`` + silently returns the still-effective mode without raising. Subclasses + ``sqlite3.OperationalError`` so existing ``except sqlite3.OperationalError`` + DB-init handling still catches it, while callers that specifically mandate + WAL can catch this narrower type. + """ + + def apply_wal_with_fallback( conn: sqlite3.Connection, *, db_label: str = "state.db", + require_wal: bool = False, ) -> str: """Set ``journal_mode=WAL`` on ``conn``, falling back to DELETE on failure. Returns the journal mode actually set (``"wal"`` or ``"delete"``). - On WAL-incompatible filesystems (NFS, SMB, some FUSE, ZFS), SQLite raises - ``OperationalError("locking protocol")`` or ``OperationalError("disk I/O error")`` - when setting WAL. We fall back to DELETE mode — the pre-WAL default, which - works on NFS and ZFS — and log one WARNING explaining why. + On WAL-incompatible filesystems (NFS, SMB, some FUSE, ZFS), SQLite either + raises ``OperationalError("locking protocol")`` / + ``OperationalError("disk I/O error")`` or — on macOS NFS / SMB / + the AgentFS NFS overlay — silently refuses the switch and leaves the DB in + DELETE. Either way the degradation is logged at ERROR level (it is a real + loss of concurrency — a write blocks concurrent readers — not a cosmetic + warning) and, by default, the function falls back to DELETE (the pre-WAL + default, which works on NFS and ZFS) so the feature keeps working. On SQLite builds that still contain the WAL-reset corruption bug (issue #69784), refuse to enable WAL on fresh / non-WAL databases @@ -567,11 +586,17 @@ def apply_wal_with_fallback( the WAL-reset bug as real through 3.51.2 with serious consequences. Until a fixed runtime is delivered, keep new databases out of WAL. - The WARNING is deduplicated per ``db_label``: repeated connections - to the same underlying DB (e.g. kanban_db.connect() which is called - on every kanban operation) log once per process, not once per call. - Different db_labels log independently, so state.db and kanban.db - each get one warning on the same NFS mount. + Callers that genuinely require WAL concurrency (and would rather fail loudly + than run silently degraded) pass ``require_wal=True``; the function then + raises :class:`WalUnsupportedError` instead of returning ``"delete"``. All + current callers deliberately keep the default ``require_wal=False`` so + NFS-homed installs keep working. + + The ERROR is deduplicated per ``db_label``: repeated connections to the + same underlying DB (e.g. kanban_db.connect() which is called on every + kanban operation) log once per process, not once per call. Different + db_labels log independently, so state.db and kanban.db each get one error + on the same NFS mount. Shared by :class:`SessionDB` and ``hermes_cli.kanban_db.connect`` so both databases get identical fallback behavior. @@ -631,14 +656,21 @@ def apply_wal_with_fallback( _apply_macos_checkpoint_barrier(conn) _enforce_macos_synchronous_full(conn) return "wal" - _log_wal_fallback_once( - db_label, - sqlite3.OperationalError( - f"journal_mode=WAL refused without raising (still {mode!r})" - ), + # Silent refusal (macOS NFS / SMB / AgentFS overlay): WAL was not + # honored, but nothing raised. + silent_exc = WalUnsupportedError( + f"journal_mode=WAL refused without raising (still {mode!r})" ) + if require_wal: + raise silent_exc + _log_wal_fallback_once(db_label, silent_exc) return mode or "delete" except sqlite3.OperationalError as exc: + # The require_wal silent-refusal raise above is a WalUnsupportedError + # (an OperationalError subclass) and lands here — propagate it + # unchanged rather than re-running it through the marker logic. + if isinstance(exc, WalUnsupportedError): + raise msg = str(exc).lower() if not any(marker in msg for marker in _WAL_INCOMPAT_MARKERS): # Unrelated OperationalError — don't silently swallow. @@ -647,6 +679,9 @@ def apply_wal_with_fallback( existing = _on_disk_journal_mode(conn) if existing == "wal": raise + if require_wal: + # Caller mandates WAL — fail loudly instead of degrading to DELETE. + raise WalUnsupportedError(str(exc)) from exc _log_wal_fallback_once(db_label, exc) conn.execute("PRAGMA journal_mode=DELETE") return "delete" @@ -729,21 +764,25 @@ def _log_wal_reset_bug_once( def _log_wal_fallback_once(db_label: str, exc: Exception) -> None: - """Log a single WARNING per (process, db_label) about WAL fallback. + """Log a single ERROR per (process, db_label) about WAL fallback. + + ERROR (not WARNING): a DB silently dropped to DELETE means a real loss of + concurrency — under the kanban dispatcher + workers a write blocks readers, + surfacing as SQLITE_BUSY/lock contention — so it must be loud, not cosmetic. Without this dedup, NFS users running kanban (which opens a fresh connection on every operation — see hermes_cli/kanban_db.py) would - fill errors.log with hundreds of identical warnings per hour. + fill errors.log with hundreds of identical errors per hour. """ with _wal_fallback_warned_lock: if db_label in _wal_fallback_warned_paths: return _wal_fallback_warned_paths.add(db_label) - logger.warning( + logger.error( "%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 warning " + "https://www.sqlite.org/wal.html for details. This message " "fires once per process per database.", db_label, exc, diff --git a/tests/hermes_cli/test_kanban_db.py b/tests/hermes_cli/test_kanban_db.py index b626a237ce..67152b2bf4 100644 --- a/tests/hermes_cli/test_kanban_db.py +++ b/tests/hermes_cli/test_kanban_db.py @@ -859,6 +859,67 @@ class TestSharedBoardPaths: # NFS / network-filesystem fallback (see hermes_state.apply_wal_with_fallback) # --------------------------------------------------------------------------- +def test_connect_falls_back_to_delete_on_locking_protocol(tmp_path, monkeypatch, caplog): + """kanban_db.connect() must handle ``locking protocol`` on NFS/SMB. + + Without this fallback, the gateway's kanban dispatcher crashes every + 60s and the kanban migration (``consecutive_failures`` ADD COLUMN) is + retried forever — which is what the real-world user report shows + (see hermes-agent issue #22032). + + NOTE: We do NOT use the ``kanban_home`` fixture here because that + fixture pre-initializes the DB via ``kb.init_db()`` — putting the + file in WAL on disk. The Bug D safety guard now refuses to downgrade + to DELETE when the on-disk header is already WAL, so testing the + NFS-fallback path requires a truly-fresh DB file (NFS scenario in + production: first connection of the first process ever to touch the + file, where downgrading is safe because nobody else has WAL state + yet). + """ + import sqlite3 as _sqlite3 + from unittest.mock import patch as _patch + + home = tmp_path / ".hermes" + home.mkdir() + monkeypatch.setenv("HERMES_HOME", str(home)) + monkeypatch.setattr(Path, "home", lambda: tmp_path) + + # Clear module cache so a fresh connect() is attempted + kb._INITIALIZED_PATHS.clear() + + real_connect = _sqlite3.connect + + class _WalBlockingConnection(_sqlite3.Connection): + def execute(self, sql, *args, **kwargs): # type: ignore[override] + if "journal_mode=wal" in sql.lower().replace(" ", ""): + raise _sqlite3.OperationalError("locking protocol") + return super().execute(sql, *args, **kwargs) + + def wal_blocking_connect(*args, **kwargs): + return real_connect( + *args, factory=_WalBlockingConnection, **kwargs + ) + + with _patch("hermes_cli.kanban_db.sqlite3.connect", side_effect=wal_blocking_connect): + with caplog.at_level("ERROR", logger="hermes_state"): + conn = kb.connect() + + # One fallback error, naming kanban.db + errors = [ + r + for r in caplog.records + if r.levelname == "ERROR" and "kanban.db" in r.getMessage() + ] + assert len(errors) >= 1, ( + f"Expected a kanban.db ERROR, got: {[r.getMessage() for r in caplog.records]}" + ) + + # DB still usable end-to-end — create + list a task + t = kb.create_task(conn, title="post-fallback task") + tasks = kb.list_tasks(conn) + assert any(row.id == t for row in tasks) + conn.close() + def test_unlink_tasks_triggers_recompute_ready(kanban_home): """Regression test for issue #22459. diff --git a/tests/test_hermes_state_wal_fallback.py b/tests/test_hermes_state_wal_fallback.py index b82c6af0b6..2f570b82ee 100644 --- a/tests/test_hermes_state_wal_fallback.py +++ b/tests/test_hermes_state_wal_fallback.py @@ -21,6 +21,7 @@ import pytest import hermes_state from hermes_state import ( SessionDB, + WalUnsupportedError, apply_wal_with_fallback, format_session_db_unavailable, get_last_init_error, @@ -113,7 +114,34 @@ class TestApplyWalWithFallback: assert cur.fetchone()[0].lower() == "wal" conn.close() + def test_falls_back_to_delete_on_locking_protocol(self, tmp_path, caplog): + """NFS-style ``locking protocol`` error → DELETE mode + one ERROR.""" + conn, _ = _open_blocking(tmp_path / "nfs.db", isolation_level=None) + with caplog.at_level("ERROR", logger="hermes_state"): + mode = apply_wal_with_fallback(conn, db_label="test.db") + assert mode == "delete" + errors = [r for r in caplog.records if r.levelname == "ERROR"] + assert len(errors) == 1 + msg = errors[0].getMessage() + assert "test.db" in msg + assert "journal_mode=DELETE" in msg + assert "locking protocol" in msg + + # Post-fallback the DB is still usable for real writes + 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_falls_back_on_not_authorized(self, tmp_path): + """Some FUSE mounts block WAL pragma outright ('not authorized').""" + conn, _ = _open_blocking( + tmp_path / "fuse.db", reason="not authorized", isolation_level=None + ) + mode = apply_wal_with_fallback(conn) + assert mode == "delete" + conn.close() def test_falls_back_when_wal_silently_refused(self, tmp_path, caplog): """macOS NFS / SMB / AgentFS-NFS can REFUSE the WAL switch WITHOUT @@ -130,16 +158,14 @@ class TestApplyWalWithFallback: conn = sqlite3.connect( str(tmp_path / "macnfs.db"), factory=factory, isolation_level=None ) - with caplog.at_level("WARNING", logger="hermes_state"): + with caplog.at_level("ERROR", logger="hermes_state"): mode = apply_wal_with_fallback(conn, db_label="kanban.db") assert mode == "delete", "must report the true mode, not a false 'wal'" - assert ( - conn.execute("PRAGMA journal_mode").fetchone()[0].lower() == "delete" - ) - warnings = [r for r in caplog.records if r.levelname == "WARNING"] - assert len(warnings) == 1, "silent no-op must still emit exactly one WARNING" - assert "kanban.db" in warnings[0].getMessage() + assert conn.execute("PRAGMA journal_mode").fetchone()[0].lower() == "delete" + errors = [r for r in caplog.records if r.levelname == "ERROR"] + assert len(errors) == 1, "silent no-op must still emit exactly one ERROR" + assert "kanban.db" in errors[0].getMessage() conn.close() def test_reraises_on_disk_io_error(self, tmp_path): @@ -162,6 +188,52 @@ class TestApplyWalWithFallback: apply_wal_with_fallback(conn) conn.close() + def test_does_not_downgrade_when_disk_says_wal(self, tmp_path): + """Refuse to downgrade an already-WAL DB even if the set-pragma path + would have raised a downgrade-eligible marker. + + With the WAL-skip patch, the read-only probe short-circuits before + ``PRAGMA journal_mode=WAL`` ever runs on an already-WAL connection, + so the set-pragma path is unreachable here and ``attempts`` stays 0. + Either outcome (skip-via-probe OR re-raise-on-disk-check) preserves + the property this test guards: we never silently DELETE-downgrade + a WAL-mode file. The on-disk guard remains in place as + belt-and-suspenders for any future code path that bypasses the + probe. + """ + # Prime the file in WAL mode using a normal connection + primer = sqlite3.connect(str(tmp_path / "already-wal.db"), isolation_level=None) + try: + primer.execute("PRAGMA journal_mode=WAL") + primer.execute("CREATE TABLE t (x INTEGER)") + primer.execute("INSERT INTO t VALUES (1)") + assert primer.execute("PRAGMA journal_mode").fetchone()[0].lower() == "wal" + finally: + primer.close() + + # New connection whose set-WAL pragma would raise "locking protocol" + # if it were ever called. With the WAL-skip patch the probe sees + # journal_mode=wal and returns early, so set-WAL is never attempted. + conn, attempts = _open_blocking( + tmp_path / "already-wal.db", + reason="locking protocol", + isolation_level=None, + ) + result = apply_wal_with_fallback(conn) + assert result == "wal", ( + "must report wal mode (either skipped via probe or refused downgrade)" + ) + assert attempts[0] == 0, ( + "set-WAL pragma must not run when the on-disk header already says wal" + ) + conn.close() + + # And the file is STILL WAL on disk — nothing got rewritten + check = sqlite3.connect(str(tmp_path / "already-wal.db")) + try: + assert check.execute("PRAGMA journal_mode").fetchone()[0].lower() == "wal" + finally: + check.close() def test_reraises_unrelated_operational_error(self, tmp_path): """Non-WAL-compat errors must NOT be silently swallowed by the fallback.""" @@ -174,10 +246,37 @@ class TestApplyWalWithFallback: apply_wal_with_fallback(conn) conn.close() + def test_error_deduplicated_per_db_label(self, tmp_path, caplog): + """Repeated calls with the same db_label log exactly ONE error. - def test_warning_fires_independently_per_db_label(self, tmp_path, caplog): - """Different db_labels each get their own one warning (not globally dedup'd).""" - with caplog.at_level("WARNING", logger="hermes_state"): + Prevents log spam when NFS users run kanban (which opens a fresh + connection on every operation — see hermes_cli/kanban_db.py). + Regression guard: the fix for #22032 ran apply_wal_with_fallback() + on every kb.connect() call; without dedup, errors.log fills with + hundreds of identical errors per hour. + """ + with caplog.at_level("ERROR", logger="hermes_state"): + # Three separate connections to "the same DB" via the same label + for i in range(3): + conn, _ = _open_blocking(tmp_path / f"dup-{i}.db", isolation_level=None) + mode = apply_wal_with_fallback(conn, db_label="shared.db") + assert mode == "delete" + conn.close() + + # Exactly one error across all three calls + errors = [ + r + for r in caplog.records + if r.levelname == "ERROR" and "shared.db" in r.getMessage() + ] + assert len(errors) == 1, ( + f"Expected 1 deduplicated error, got {len(errors)}: " + f"{[r.getMessage() for r in errors]}" + ) + + 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"): conn1, _ = _open_blocking(tmp_path / "a.db", isolation_level=None) apply_wal_with_fallback(conn1, db_label="state.db") conn1.close() @@ -186,16 +285,66 @@ class TestApplyWalWithFallback: apply_wal_with_fallback(conn2, db_label="kanban.db") conn2.close() - warnings = [r for r in caplog.records if r.levelname == "WARNING"] - labels_warned = { - lbl for r in warnings for lbl in ("state.db", "kanban.db") + errors = [r for r in caplog.records if r.levelname == "ERROR"] + labels_logged = { + lbl + for r in errors + for lbl in ("state.db", "kanban.db") if lbl in r.getMessage() } - assert labels_warned == {"state.db", "kanban.db"}, ( - f"Each db_label should warn once; got {labels_warned}" + assert labels_logged == {"state.db", "kanban.db"}, ( + f"Each db_label should log once; got {labels_logged}" ) +class TestRequireWal: + """``require_wal=True`` turns either WAL-refusal shape into a hard + ``WalUnsupportedError`` for callers that mandate WAL concurrency, instead + of silently degrading to DELETE. The default callers (SessionDB / + kanban_db.connect) keep ``require_wal=False`` so NFS-homed installs work. + """ + + def test_happy_path_unaffected_by_require_wal(self, tmp_path): + """On a WAL-capable FS, require_wal=True still simply returns 'wal'.""" + conn = sqlite3.connect(str(tmp_path / "ok.db"), isolation_level=None) + try: + assert apply_wal_with_fallback(conn, require_wal=True) == "wal" + finally: + conn.close() + + def test_raises_on_raising_marker(self, tmp_path): + """NFS-style raising refusal + require_wal=True → WalUnsupportedError.""" + conn, _ = _open_blocking(tmp_path / "nfs.db", isolation_level=None) + try: + with pytest.raises(WalUnsupportedError, match="locking protocol"): + apply_wal_with_fallback(conn, db_label="state.db", require_wal=True) + finally: + conn.close() + + def test_raises_on_silent_refusal(self, tmp_path): + """macOS-NFS silent no-op + require_wal=True → WalUnsupportedError, + not a false 'delete' return.""" + factory = _make_silent_noop_factory("delete") + conn = sqlite3.connect( + str(tmp_path / "macnfs.db"), factory=factory, isolation_level=None + ) + try: + with pytest.raises(WalUnsupportedError, match="refused without raising"): + apply_wal_with_fallback(conn, db_label="kanban.db", require_wal=True) + finally: + conn.close() + + def test_error_is_operationalerror_subclass(self, tmp_path): + """WalUnsupportedError must stay catchable as sqlite3.OperationalError + so existing DB-init handlers (e.g. SessionDB.__init__) still catch it.""" + conn, _ = _open_blocking(tmp_path / "nfs.db", isolation_level=None) + try: + with pytest.raises(sqlite3.OperationalError): + apply_wal_with_fallback(conn, require_wal=True) + finally: + conn.close() + + class TestGetLastInitError: