Conversation
A burst of fresh connections to a database that is still in DELETE mode all run `PRAGMA journal_mode=WAL`; only one can win the exclusive header transition. SQLite answers the losers with SQLITE_BUSY *immediately* on this lock-upgrade path — the connection's busy_timeout is not consulted — so `apply_wal_with_fallback` raised "database is locked" and the opener failed, even though a peer was establishing WAL at that very moment. Measured on macOS with SQLite 3.53.1 (16 concurrent fresh openers, 40 trials): 81 of 640 opens through `apply_wal_with_fallback` failed on unpatched main, with a maximum observed wait of 13 ms — i.e. the 5 s busy timeout never engaged. Fix: `_set_wal_with_busy_convergence` retries only SQLITE_BUSY, with jitter, inside one bounded monotonic window (1 s). After each BUSY it re-probes the on-disk journal mode, so a loser converges on the peer's WAL instead of retrying the pragma. Exhaustion re-raises the original SQLITE_BUSY. It never downgrades to DELETE and deliberately does not retry SQLITE_LOCKED, WAL-incompatible storage errors, or other faults, so the existing NFS/SMB/ZFS fallback and the WAL-reset gate are untouched. With the fix the same measurement opens 640 of 640 in WAL, maximum wait 54 ms. Tests cover the four contracts: peer-established WAL is accepted after one BUSY, a bounded retry may establish WAL locally, deadline exhaustion fails closed without ever issuing journal_mode=DELETE, and SQLITE_LOCKED is not treated as the convergence race. Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01VEiv7g2yvXE19vwSr3oRLt
|
Reviewing the WAL convergence change: the bounded retry + re-probe via _on_disk_journal_mode is the right shape for this race. One point to harden: the deadline path at exhaustion re-raises last_busy, but if the peer established WAL between the failed execute and the deadline check, a second immediate retry could succeed. Currently that success is lost — the loop exits instead of doing one final re-probe. Suggested tweak: before re-raising on deadline exhaustion, do one last _on_disk_journal_mode check; if it shows 'wal', return ('wal',). Otherwise re-raise as today. This makes the failure mode slightly less sensitive to timing. Otherwise the behavior contract is clear, the new tests pin the invariants, and the sibling call paths look covered. |
|
Production feedback — we deployed this PR's change set on an ARM (Graviton) server running Hermes multi-process (gateway + dashboard + CLI; 9 concurrent state.db handles) on EBS ext4. The WAL initialization race described in the PR body is confirmed as the root cause of a cascading failure:
This is P1 in a multi-process setup: two distinct failures cascade into a full work stoppage. On EBS with commit=30 the window for the race is wider because fsync is deferred. Would you consider bumping this to P1, or referencing the owner-route loss issue (#100507 / #96313) in the PR description so the cascade is visible? |
What does this PR do?
Fixes a startup race in
apply_wal_with_fallback(hermes_state.py): when several fresh connections open a database that is still inDELETEjournal mode at the same time — a gateway plus dashboard plus CLI, or a burst ofSessionDB()opens from the web server — they all issuePRAGMA journal_mode=WAL, and only one can win the exclusive header transition. SQLite answers the losers withSQLITE_BUSYimmediately on this lock-upgrade path; the connection'sbusy_timeoutis not consulted. Today that exception escapesapply_wal_with_fallbackasOperationalError: database is lockedand the open fails, even though a peer is establishing WAL at that very moment.The fix adds
_set_wal_with_busy_convergence: retry onlySQLITE_BUSY(checked viasqlite_errorcode, with a message fallback for runtimes without it), with 10–50 ms jitter, inside one bounded monotonic window (1 s). After each BUSY it re-probes the on-disk journal mode, so a loser converges on the peer's WAL instead of hammering the pragma. Exhaustion re-raises the originalSQLITE_BUSY. It never downgrades toDELETE, and it deliberately does not retrySQLITE_LOCKED, WAL-incompatible storage errors, or anything else — the NFS/SMB/ZFS fallback and the WAL-reset gate are untouched. This is the right shape because the failure is not "WAL unsupported here" (the fallback's domain) but "someone else is switching the file to WAL right now".Related Issue
No existing issue or PR covers this (searched issues and PRs for WAL initialization / concurrent openers /
database is lockedonjournal_mode). Adjacent context: #55305 (concurrent-connection state.db corruption on ZFS) is a different failure class and already closed.Type of Change
Changes Made
hermes_state.py:_is_sqlite_busy,_set_wal_with_busy_convergence, and the three tuning constants;apply_wal_with_fallbackcalls the convergence setter where it used to call the pragma directly.tests/test_hermes_state_wal_fallback.py: four tests for the contracts — peer-established WAL is accepted after one BUSY; a bounded retry may establish WAL locally; deadline exhaustion fails closed without ever issuingjournal_mode=DELETE;SQLITE_LOCKEDis not treated as the convergence race.How to Test
main(macOS, SQLite 3.53.1, Python 3.11): 16 processes each open a fresh connection to a new database, wait on a barrier, then callapply_wal_with_fallback(conn). Over 40 trials, 81 of 640 opens raiseddatabase is locked, with a maximum observed wait of 13 ms — the 5 s busy timeout never engaged. A barePRAGMA journal_mode=WALin the same harness fails 97–152 of 640 attempts on SQLite 3.53.1 and 3.53.4.scripts/run_tests.sh -j 3 tests/test_hermes_state_wal_fallback.py tests/test_hermes_state.py tests/test_journal_mode_config.py tests/test_sqlite_wal_reset_gate.py— all pass except the one pre-existing, unrelatedtest_hermes_state.pyfailure noted below.scripts/run_tests.sh -j 3(full suite) on this branch: 3613 files, 43,399 passed, 113 failed, 416 skipped, 1 flaky file (tests/cron/test_script_claim_heartbeat.py, passed on retry). Every one of the 32 files with failures was rerun on unpatchedmain(254158f4) in the same virtualenv and fails there with identical counts (host-specific: systemd-scope tests on macOS,hermes updateflows, CUA driver / wake-word / voice hardware, Unix-socket path length under the parallel runner); none involvehermes_state.py's WAL path. Full classification table available on request.Pre-existing on
mainat254158f4, unrelated to this change and reproduced with the patch reverted:tests/test_hermes_state.py::TestFTS5Search::test_search_projection_skips_context_enrichment_queriesfails on macOS (context_query_count() == 0where1is expected). Happy to follow up separately.Checklist
Code
fix(state): …)scripts/run_tests.sh, the repo's parallelpytest tests/runner) — see "How to Test" for the one pre-existing unrelated failure onmainDocumentation & Housekeeping
cli-config.yaml.example: N/A (no config keys)CONTRIBUTING.md/AGENTS.md: N/Asqlite_errorcode(3.11+) with a message fallback for older runtimes.Prepared with AI assistance (Claude); root cause, measurements and tests were run on the author's machine as described above.