ouyangbo/hermes-agent
1
0
Fork 0
Code Issues Pull Requests Actions 9 Packages Projects Releases Wiki Activity

fix(state): escalate silent WAL→DELETE fallback to ERROR + opt-in require_wal

Browse Source 
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.
This commit is contained in:
Connor Black
2026-06-18 03:33:47 -04:00
committed by Teknium
parent f50d80e8eb
commit 0f60cdac27
4 changed files with 283 additions and 34 deletions
Download Patch File Download Diff File Expand all files Collapse all files
hermes_cli/kanban_db.py
+1 -1
View File
@@ -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})")
hermes_state.py
+57 -18
View File
@@ -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,
tests/hermes_cli/test_kanban_db.py
+61
View File
@@ -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.
tests/test_hermes_state_wal_fallback.py
+164 -15
View File
@@ -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: