From c4aea323175e6dad1ed1294cb4193126405fcfe0 Mon Sep 17 00:00:00 2001 From: Teknium <127238744+teknium1@users.noreply.github.com> Date: Thu, 6 Aug 2026 07:09:54 -0700 Subject: [PATCH] fix(db): never downgrade journal mode on a database with concurrent openers MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The WAL-reset-vulnerability gate (#70055 lineage) could flip a LIVE WAL database to journal_mode=DELETE while another process was writing to it. Observed on state.db (Aug 5): a pytest process on the repo .venv (SQLite 3.50.4, vulnerable) opened the live ~/.hermes/state.db while the gateway (SQLite 3.53.1, WAL) held it, downgraded the journal mode, and destroyed the gateway's committed-but-uncheckpointed WAL transactions (disk rows went 10 -> 0 while memory held 185). cron/executions.db already had the "leave WAL in place, no live downgrade under concurrent openers" rule via the on-disk WAL probe; state.db and every other store shared the hole whenever the mode PROBE itself was blocked by a concurrent opener's locks ("could not read the mode" was treated as "not WAL" -> flip anyway). Generalized in the single journal-mode owner (apply_wal_with_fallback), covering ALL call sites (state.db, kanban.db, projects.db, cron/executions.db, delivery_ledger, async_delegation, verification_evidence, discord recovery, response_store.db, memory_store.db): - _set_journal_mode_no_wait(): the only journal-mode switch primitive for non-WAL targets. Forces busy_timeout=0 around the pragma so SQLite's own exclusivity requirement for leaving WAL becomes the concurrent-opener detector — any other opener (this process or another) makes the flip fail immediately instead of waiting out a busy timeout and sneaking the flip in under a live writer. - Vulnerable-SQLite gate: an unreadable journal mode (probe blocked) now means "ownership not provably exclusive" — leave the mode untouched and warn, never flip. A lock conflict on the flip itself likewise leaves the mode alone. - Configured journal_mode=delete: refuses (raises) rather than downgrading blind when the mode cannot be verified under a concurrent opener. - Filesystem-incompat fallback: re-raises instead of downgrading when the on-disk mode cannot be verified. - New/exclusively-owned DBs on vulnerable builds behave exactly as before (DELETE gate retained per #70055). Behavioral tests use a REAL second process (and a real second connection holding an exclusive lock) with the blocked-state assertions running WHILE the holder owns the DB, plus exclusive-ownership downgrade-still-happens coverage. --- hermes_state.py | 138 +++++++++++---- tests/test_sqlite_wal_reset_gate.py | 266 ++++++++++++++++++++++++++++ 2 files changed, 373 insertions(+), 31 deletions(-) diff --git a/hermes_state.py b/hermes_state.py index bf9a24d31d35b..0991f3cd2ff23 100644 --- a/hermes_state.py +++ b/hermes_state.py @@ -720,20 +720,29 @@ def apply_wal_with_fallback( # Read-only probe — no flock, no checkpoint, no WAL/SHM unlink. # Skipping the set-pragma prevents WAL-init from unlinking files other connections hold open. - try: - current_mode = conn.execute("PRAGMA journal_mode").fetchone() - if current_mode and current_mode[0] == "wal": - _apply_macos_checkpoint_barrier(conn) - _enforce_macos_synchronous_full(conn) - return "wal" - except sqlite3.OperationalError: - pass + current_mode = _on_disk_journal_mode(conn) + if current_mode == "wal": + _apply_macos_checkpoint_barrier(conn) + _enforce_macos_synchronous_full(conn) + return "wal" # #68545: honor the canonical database.journal_mode setting. Existing # on-disk WAL databases were returned above and are never live-downgraded. if configured == "delete": - row = conn.execute("PRAGMA journal_mode=DELETE").fetchone() - actual = str(row[0]).lower() if row else "" + if current_mode is None: + # The mode probe failed (database locked / busy): another + # process may hold this DB open in WAL. Ownership is not + # provably exclusive, so flipping journal modes here could + # destroy committed-but-uncheckpointed WAL transactions of a + # concurrent writer. Fail loudly instead of downgrading — the + # operator explicitly requested DELETE and we cannot verify it. + raise sqlite3.OperationalError( + "could not verify journal mode before applying configured " + "journal_mode=delete (database is locked — possible " + "concurrent openers); refusing to downgrade a database " + "this process does not exclusively own" + ) + actual = _set_journal_mode_no_wait(conn, "DELETE") if actual != "delete": raise sqlite3.OperationalError( f"could not set configured journal_mode=delete (got {actual or 'no result'})" @@ -805,18 +814,56 @@ def apply_wal_with_fallback( _enforce_macos_synchronous_full(conn) return "wal" break - # Don't downgrade if another process already set WAL on disk. + # Don't downgrade if another process already set WAL on disk, or if + # the mode cannot be verified at all (probe blocked by a concurrent + # opener's locks) — ownership is not provably exclusive either way. existing = _on_disk_journal_mode(conn) - if existing == "wal": + if existing == "wal" or existing is None: 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") + _set_journal_mode_no_wait(conn, "DELETE") return "delete" +def _set_journal_mode_no_wait(conn: sqlite3.Connection, mode: str) -> str: + """Execute ``PRAGMA journal_mode=`` without waiting on other openers. + + This is the ONLY place a journal-mode switch pragma may be issued for a + non-WAL target. It temporarily forces ``busy_timeout=0`` so SQLite's own + exclusivity requirement becomes a concurrent-opener detector: leaving WAL + mode requires exclusive access to the database, so if ANY other connection + (this process or another) holds the DB open, the pragma fails immediately + with ``database is locked`` instead of waiting out a busy timeout and + sneaking the flip in between a concurrent writer's transactions — which is + exactly how committed-but-uncheckpointed WAL transactions get destroyed. + + Callers must treat a raised ``OperationalError`` as "not exclusively + owned: leave the journal mode alone", never as a retryable condition. + + Returns the resulting journal mode as reported by SQLite (lowercase), or + ``""`` when SQLite returned no row. + """ + previous_timeout = 0 + try: + row = conn.execute("PRAGMA busy_timeout").fetchone() + if row and row[0] is not None: + previous_timeout = int(row[0]) + except (sqlite3.OperationalError, TypeError, ValueError): + previous_timeout = 0 + conn.execute("PRAGMA busy_timeout=0") + try: + row = conn.execute(f"PRAGMA journal_mode={mode}").fetchone() + return str(row[0]).strip().lower() if row and row[0] is not None else "" + finally: + try: + conn.execute(f"PRAGMA busy_timeout={previous_timeout}") + except sqlite3.OperationalError: + pass + + def _apply_delete_for_wal_reset_bug( conn: sqlite3.Connection, *, @@ -826,16 +873,17 @@ def _apply_delete_for_wal_reset_bug( """Avoid enabling WAL when the linked SQLite has the WAL-reset bug. - Already-WAL on disk: leave WAL alone (no live downgrade) and warn. - - Otherwise: set DELETE and warn. + - Mode unreadable (probe blocked by a concurrent opener's locks): + ownership is not provably exclusive — leave the journal mode alone + and warn. Never treat "could not read the mode" as "not WAL": that + exact confusion let a vulnerable-SQLite process flip a live WAL + state.db to DELETE under a concurrent WAL writer, destroying its + committed-but-uncheckpointed transactions. + - Otherwise: set DELETE (refusing to wait out concurrent openers) and + warn. - For an explicit operator request, verify SQLite accepted DELETE. """ - current = "" - try: - row = conn.execute("PRAGMA journal_mode").fetchone() - if row and row[0] is not None: - current = str(row[0]).strip().lower() - except sqlite3.OperationalError: - current = "" + current = _on_disk_journal_mode(conn) if current == "wal": # Do not TRUNCATE / journal_mode=DELETE while other processes may @@ -845,14 +893,33 @@ def _apply_delete_for_wal_reset_bug( _enforce_macos_synchronous_full(conn) return "wal" + if current is None: + # The mode probe itself failed — another opener's locks are the + # most likely cause, and the DB may well be in WAL under a live + # writer. Never flip a journal mode we cannot even read. + if require_delete: + raise sqlite3.OperationalError( + "could not verify journal mode before applying configured " + "journal_mode=delete (database is locked — possible " + "concurrent openers); refusing to downgrade a database " + "this process does not exclusively own" + ) + _log_wal_reset_bug_once(db_label, kept_wal=True, indeterminate=True) + return "wal" + actual = "" try: - row = conn.execute("PRAGMA journal_mode=DELETE").fetchone() - if row and row[0] is not None: - actual = str(row[0]).strip().lower() - except sqlite3.OperationalError: + actual = _set_journal_mode_no_wait(conn, "DELETE") + except sqlite3.OperationalError as exc: if require_delete: raise + lowered = str(exc).lower() + if "locked" in lowered or "busy" in lowered: + # A concurrent opener appeared between the probe and the flip + # (or already held the DB): SQLite refused the exclusive lock. + # Leave the journal mode exactly as it is. + _log_wal_reset_bug_once(db_label, kept_wal=True, indeterminate=True) + return current or "delete" # Best-effort for the automatic vulnerable-runtime fallback: DELETE is # normally already the default for new file-backed databases. if require_delete and actual != "delete": @@ -896,18 +963,27 @@ def _log_wal_reset_bug_once( db_label: str, *, kept_wal: bool, + indeterminate: bool = False, ) -> None: """Log once per (process, db_label) about the WAL-reset vulnerability path.""" with _wal_reset_bug_warned_lock: if db_label in _wal_reset_bug_warned_paths: return _wal_reset_bug_warned_paths.add(db_label) - action = ( - "is already in WAL mode — leaving WAL in place (no live " - "downgrade under concurrent openers)" - if kept_wal - else "using journal_mode=DELETE instead of enabling WAL" - ) + if indeterminate: + action = ( + "journal mode could not be verified or exclusively switched " + "(database is locked — possible concurrent openers); leaving the " + "journal mode untouched (no live downgrade under concurrent " + "openers)" + ) + elif kept_wal: + action = ( + "is already in WAL mode — leaving WAL in place (no live " + "downgrade under concurrent openers)" + ) + else: + action = "using journal_mode=DELETE instead of enabling WAL" # Check whether this is a Hermes-managed install (uv-managed venv) # so the warning doesn't promise a repair path that doesn't exist # for git/pip/system Python installs (#75153). diff --git a/tests/test_sqlite_wal_reset_gate.py b/tests/test_sqlite_wal_reset_gate.py index e78525c671cb4..a717b6bb5e8ce 100644 --- a/tests/test_sqlite_wal_reset_gate.py +++ b/tests/test_sqlite_wal_reset_gate.py @@ -10,6 +10,9 @@ Existing on-disk WAL databases are left alone (no live downgrade). from __future__ import annotations import sqlite3 +import subprocess +import sys +import time from types import SimpleNamespace import pytest @@ -116,6 +119,269 @@ class TestApplyWalWalResetGate: assert len(warnings) == 2 +_HOLDER_SCRIPT = """ +import sqlite3, sys, time, os +db, ready, done = sys.argv[1], sys.argv[2], sys.argv[3] +conn = sqlite3.connect(db, timeout=30.0) +conn.execute("INSERT INTO t VALUES (777)") +conn.commit() # committed but (in WAL) very likely un-checkpointed +with open(ready, "w") as fh: + fh.write("ready") +deadline = time.time() + 60 +while not os.path.exists(done) and time.time() < deadline: + time.sleep(0.05) +conn.close() +""" + + +class TestNoDowngradeUnderConcurrentOpeners: + """The Aug 2026 state.db incident class: a vulnerable-SQLite process must + never flip journal modes on a database it does not exclusively own. + + A concurrent WAL writer's committed-but-uncheckpointed transactions are + destroyed by a live WAL→DELETE flip (observed: disk rows went 10 → 0 + while the writer's memory held 185).""" + + def test_second_process_opener_keeps_wal_when_vulnerable( + self, tmp_path, monkeypatch, caplog + ): + """A REAL second process holds the WAL DB open while the vulnerable + gate runs — WAL must be left in place and its committed rows survive. + + All blocked-state assertions run WHILE the holder owns the DB.""" + monkeypatch.setattr( + hermes_state, "is_sqlite_wal_reset_vulnerable", lambda version_info=None: True + ) + db = tmp_path / "live_wal.db" + seed = sqlite3.connect(str(db)) + try: + seed.execute("PRAGMA journal_mode=WAL") + seed.execute("CREATE TABLE t (x INTEGER)") + seed.execute("INSERT INTO t VALUES (1)") + seed.commit() + finally: + seed.close() + + ready = tmp_path / "holder.ready" + done = tmp_path / "holder.done" + holder = subprocess.Popen( + [sys.executable, "-c", _HOLDER_SCRIPT, str(db), str(ready), str(done)] + ) + try: + deadline = time.time() + 30 + while not ready.exists() and time.time() < deadline: + time.sleep(0.02) + assert ready.exists(), "holder subprocess never became ready" + + conn = sqlite3.connect(str(db), timeout=30.0) + try: + with caplog.at_level("WARNING", logger="hermes_state"): + mode = apply_wal_with_fallback(conn, db_label="live_wal.db") + # Asserted while the second opener still holds the DB: + assert holder.poll() is None, "holder must still be alive here" + assert mode == "wal" + assert ( + conn.execute("PRAGMA journal_mode").fetchone()[0].lower() + == "wal" + ) + # The concurrent opener's committed row must have survived. + rows = {r[0] for r in conn.execute("SELECT x FROM t")} + assert rows == {1, 777} + assert not any( + "instead of enabling WAL" in r.getMessage() + for r in caplog.records + ) + finally: + conn.close() + finally: + done.write_text("done") + holder.wait(timeout=30) + + check = sqlite3.connect(str(db)) + try: + assert check.execute("PRAGMA journal_mode").fetchone()[0].lower() == "wal" + assert {r[0] for r in check.execute("SELECT x FROM t")} == {1, 777} + finally: + check.close() + + def test_unreadable_mode_keeps_journal_mode_when_vulnerable( + self, tmp_path, monkeypatch, caplog + ): + """An exclusive-locking holder blocks even the journal-mode read. + + Ownership is then not provably exclusive: the gate must leave the + journal mode untouched instead of treating 'could not read the mode' + as 'not WAL' and flipping anyway (the incident's exact confusion). + Assertions run WHILE the holder's exclusive lock is live.""" + monkeypatch.setattr( + hermes_state, "is_sqlite_wal_reset_vulnerable", lambda version_info=None: True + ) + db = tmp_path / "locked_wal.db" + seed = sqlite3.connect(str(db)) + try: + seed.execute("PRAGMA journal_mode=WAL") + seed.execute("CREATE TABLE t (x INTEGER)") + seed.execute("INSERT INTO t VALUES (1)") + seed.commit() + finally: + seed.close() + + holder = sqlite3.connect(str(db)) + try: + holder.execute("PRAGMA locking_mode=EXCLUSIVE") + holder.execute("BEGIN IMMEDIATE") + holder.execute("INSERT INTO t VALUES (2)") + + conn = sqlite3.connect(str(db), timeout=0.2) + try: + # Sanity: the probe really is blocked right now. + with pytest.raises(sqlite3.OperationalError): + conn.execute("PRAGMA journal_mode").fetchone() + with caplog.at_level("WARNING", logger="hermes_state"): + mode = apply_wal_with_fallback(conn, db_label="locked_wal.db") + assert mode == "wal" + assert any( + "concurrent openers" in r.getMessage() for r in caplog.records + ) + assert not any( + "instead of enabling WAL" in r.getMessage() + for r in caplog.records + ) + finally: + conn.close() + finally: + holder.rollback() + holder.close() + + check = sqlite3.connect(str(db)) + try: + assert check.execute("PRAGMA journal_mode").fetchone()[0].lower() == "wal" + finally: + check.close() + + def test_exclusively_owned_fresh_db_still_downgrades( + self, tmp_path, monkeypatch, caplog + ): + """No concurrent openers → the vulnerable-SQLite DELETE gate still + applies exactly as before.""" + monkeypatch.setattr( + hermes_state, "is_sqlite_wal_reset_vulnerable", lambda version_info=None: True + ) + conn = sqlite3.connect(str(tmp_path / "exclusive.db")) + try: + with caplog.at_level("WARNING", logger="hermes_state"): + mode = apply_wal_with_fallback(conn, db_label="exclusive.db") + assert mode == "delete" + assert ( + conn.execute("PRAGMA journal_mode").fetchone()[0].lower() == "delete" + ) + assert any( + "instead of enabling WAL" in r.getMessage() for r in caplog.records + ) + finally: + conn.close() + + def test_flip_lock_conflict_leaves_mode_alone(self, tmp_path, caplog, monkeypatch): + """If the DELETE flip itself hits another opener's lock (opener arrived + between probe and flip), the gate returns the observed mode instead of + raising or waiting the lock out.""" + monkeypatch.setattr( + hermes_state, "is_sqlite_wal_reset_vulnerable", lambda version_info=None: True + ) + + class _FlipLockedConnection(sqlite3.Connection): + def execute(self, sql, *args, **kwargs): # type: ignore[override] + if "journal_mode=delete" in sql.lower().replace(" ", ""): + raise sqlite3.OperationalError("database is locked") + return super().execute(sql, *args, **kwargs) + + conn = sqlite3.connect( + str(tmp_path / "race.db"), factory=_FlipLockedConnection + ) + try: + with caplog.at_level("WARNING", logger="hermes_state"): + mode = apply_wal_with_fallback(conn, db_label="race.db") + assert mode == "delete" # observed pre-flip mode, not a forced flip + assert any( + "concurrent openers" in r.getMessage() for r in caplog.records + ) + finally: + conn.close() + + def test_configured_delete_refuses_when_probe_blocked( + self, tmp_path, monkeypatch + ): + """Operator-configured DELETE on a non-vulnerable build must also + refuse to downgrade when the mode probe is blocked by a concurrent + opener's exclusive lock — raise, never flip blind.""" + monkeypatch.setattr( + hermes_state, + "is_sqlite_wal_reset_vulnerable", + lambda version_info=None: False, + ) + monkeypatch.setattr(hermes_state, "resolve_journal_mode", lambda: "delete") + db = tmp_path / "cfg_delete.db" + seed = sqlite3.connect(str(db)) + try: + seed.execute("PRAGMA journal_mode=WAL") + seed.execute("CREATE TABLE t (x INTEGER)") + seed.commit() + finally: + seed.close() + + holder = sqlite3.connect(str(db)) + try: + holder.execute("PRAGMA locking_mode=EXCLUSIVE") + holder.execute("BEGIN IMMEDIATE") + holder.execute("INSERT INTO t VALUES (1)") + + conn = sqlite3.connect(str(db), timeout=0.2) + try: + with pytest.raises( + sqlite3.OperationalError, match="refusing to downgrade" + ): + apply_wal_with_fallback(conn, db_label="cfg_delete.db") + finally: + conn.close() + finally: + holder.rollback() + holder.close() + + check = sqlite3.connect(str(db)) + try: + assert check.execute("PRAGMA journal_mode").fetchone()[0].lower() == "wal" + 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).""" + monkeypatch.setattr( + hermes_state, + "is_sqlite_wal_reset_vulnerable", + lambda version_info=None: False, + ) + hermes_state._wal_fallback_warned_paths.clear() + + class _LockedProbeConnection(sqlite3.Connection): + def execute(self, sql, *args, **kwargs): # type: ignore[override] + normalized = sql.lower().replace(" ", "") + if "journal_mode=wal" in normalized: + raise sqlite3.OperationalError("locking protocol") + if normalized == "pragmajournal_mode": + raise sqlite3.OperationalError("database is locked") + return super().execute(sql, *args, **kwargs) + + conn = sqlite3.connect( + 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") + finally: + conn.close() + + def test_doctor_warns_without_adding_issues(monkeypatch, tmp_path, capsys):