felhom.eu/REPORT-r172-hub-wal.md

REPORT — hub v0.88.0: the WAL that never was (R-172), plus R-173 found

Session artefact naming: written as REPORT-r172-hub-wal.md, not REPORT.md, per this repo's parallel-session rule — the shared REPORT.md belongs to the controller boot-recovery session that ran immediately before this one and must not be clobbered.

Repo: felhom.eu (hub v0.87.0 → v0.88.0) · Trigger: a HOST STALE banner the operator spotted on hub.felhom.eu after the previous session finished.

---

1. What the alarm actually was

Not the agent, not the guest. The agent was up 2 days, never restarted, and actively reconciling; the controller was reporting normally (the header read "Last report just now", 0.190.0, 10/10 containers). The failure was the hub writing the host report:

20:26:34 [ERROR] Failed to save host-report from demo-felhom-8363b5: database is locked (5) (SQLITE_BUSY)
20:41:32 [ERROR] Failed to save host-report from demo-felhom-8363b5: database is locked (5) (SQLITE_BUSY)
20:42:32 [INFO]  Host staleness: demo-felhom-8363b5 ok → stale (host_stale)
20:42:33 [INFO]  Operator email sent for demo-felhom/host_stale

The chain, and the margin is exactly one retry wide: reports are every 15 min, staleness fires at 30 min, the hub returns 500 on SQLITE_BUSY without retrying, and the agent logs keeping current interval and waits a full interval without retrying either. Two consecutive collisions = a false alarm. It had already fired once that day (19:12:32, recovered 19:20:32).

Was it caused by the preceding session? Partly amplified, not caused. 13 collisions in one pod lifetime; the first at 15:56 CEST, ~3 h before that session's first deploy. 7 of 13 fell inside its window of ~13 controller restarts, which raises write concurrency — so the burst made a pre-existing fault more likely, and the fault was not new.

2. Root cause — the pragmas were never applied

The DSN was ?_journal_mode=WAL&_busy_timeout=5000. That is mattn/go-sqlite3 syntax. The driver is modernc.org/sqlite v1.45.0, whose applyQueryParams (confirmed at source in the module cache) reads only _pragma, _time_format, _time_integer_format, _txlock and _inttotime — and silently ignores everything else. No error, no warning.

So the hub ran in the default rollback-journal mode with busy_timeout=0 for its entire life while its own source said WAL. In rollback-journal mode a reader excludes a writer, so rendering an operator page can block a host report — which is precisely the observed 500.

The observable that proved it before any code changed: a 128 MB /data/hub.db with no -wal/-shm file beside it while the database was open. In WAL mode those must exist.

This is the project's recurring class — a configuration asserting an invariant the code does not provide — and it is the second one this week.

3. The fix

?_pragma=journal_mode(WAL)&_pragma=busy_timeout(5000)&_txlock=immediate

Parameter	Why it is not optional
journal_mode(WAL)	readers and one writer proceed concurrently, so a page render can no longer block a report; it is a property of the database FILE and persists once set
busy_timeout(5000)	writers still serialise; without a timeout SQLite returns SQLITE_BUSY immediately rather than waiting
_txlock=immediate	the one that is easy to miss. database/sql's Begin() is DEFERRED, so a read-then-write transaction must upgrade its lock, and a failed upgrade is SQLITE_BUSY_SNAPSHOT — which busy_timeout does not retry. This store has 10+ db.Begin() sites and they are all write paths (customer delete/reset, wg, appliance, pbsdr, telemetry, log bundles). WAL + busy_timeout alone would have shipped half a fix with a known un-retryable path left open

Retry options (b) and (c) from R-172 were deliberately NOT taken. With readers no longer blocking writers and the upgrade path covered, a SQLITE_BUSY reaching a handler should now be rare enough to be a real signal; a retry would hide it. Revisit only on evidence.

4. Tests and the red-proof

Every assertion reads the value back from the DATABASE, never the DSN string — a string assertion would have passed happily for the entire life of the bug. Six tests in internal/store/pragma_test.go:

Test	Asserts
TestStorePragmasAreActuallyApplied	runtime journal_mode = wal, busy_timeout ≥ 5000
TestStoreWALFilesExistWhileOpen	-wal/-shm exist beside an open DB — the production signature, pinned
TestStoreReaderDoesNotBlockWriter	the CONSEQUENCE: a write during a held read succeeds
TestStoreConcurrentWritersDoNotReturnBusy	8 concurrent writers all wait rather than error
TestStoreTransactionUpgradeDoesNotReturnBusySnapshot	6 racing read-then-write transactions all commit
TestSQLiteDriverIgnoresMattnStyleParams	guards the ROOT CAUSE: fails if the pragmas are "tidied" back to mattn form; skips itself with instructions if a future driver starts honouring them

Red-proof — restore the DSN that shipped. Observed FAIL, then reverted with a passing control:

journal_mode = "delete", want "wal"
hub.db-wal is missing beside an OPEN database
a write FAILED while a read was open: database is locked (5) (SQLITE_BUSY)   ← the live error, exactly

go build ./... && go vet ./... && go test ./... in hub/ → rc=0. scripts/repo_gates.py --fast → all 5 gates OK.

5. Operational consequence — handled, not discovered later

A WAL database cannot be copied by taking hub.db alone. A committed transaction may still live in hub.db-wal, so a bare cat yields a copy that opens cleanly and silently omits the newest writes — the worst possible shape for a credential lookup. The break-glass root-password retrieval in documentation/operations/nodes.md used exactly that command, and _recovery-inventory-2026-07-28.md records it as a past action that reads like a recipe. Both are now WAL-aware: copy the -wal alongside, || true because an absent -wal is legitimate, and shred both (the WAL holds the same secrets).

Not hypothetical: the live -wal measured 729,272 bytes during verification, all of which a bare cat would have dropped.

6. Live verification

• Image built and pushed; manifests/hub.yaml 0.87.0 → 0.88.0 (the only thing ArgoCD deploys from), hard-refresh + deliberate sync (auto-sync is OFF). ArgoCD Synced / Healthy.
• /data/ now shows hub.db-wal and hub.db-shm beside the open DB — the exact observable whose absence proved the bug.
• Zero SQLITE_BUSY since the rollout.
• Host report landed at 21:11:33; staleness checker reports 2 ok, 0 stale — demo-felhom-8363b5 is back to ok.
• PRAGMA integrity_check → ok, journal_mode → wal, all tables intact (hosts 4, customer_configs 6, host_recovery 4, host_reports 2756, events 2293). Read via the new WAL-aware copy recipe and shredded afterwards.

7. A mistake I made, and it caused a real outage

I OOM-killed the hub pod three times with a 60-concurrent page-render load test intended to prove the fix under contention. The pod's limit is 256 Mi; 60 simultaneous renders of a heavy customer page exceeded it (OOMKilled, exit 137, readiness probe timeouts). The hub was unavailable for parts of ~6 minutes and recovered on its own.

Three things worth stating plainly:

1. It was not the WAL change. WAL's extra footprint is the 32 KB -shm mapping; the OOM was template rendering under concurrency I created.
2. I should not have run it. DooPlex is Tier 2 — precious, and the hub is part of the recovery chain. A synthetic load test at that concurrency against a memory-limited pod on that box was the wrong call; the unit tests already proved the property, and the live proof needed was the -wal file plus a clean report — both of which I already had.
3. It did produce one piece of genuine evidence, which does not excuse it: after three hard kills the WAL replayed cleanly and integrity_check returned ok, which is a real (if unplanned) demonstration of WAL crash-safety on this volume.

No data was lost. The pod is Ready, restart count 3, serving normally.

8. Backlog

• R-172 → CLOSED, with the root cause recorded as the pragmas were never applied, not as tuning.
• R-173 → NEW. While checking who copies hub.db for the WAL change, I found pvc/hub-data carries recurring-job-group.longhorn.io/default: disabled, and backup-daily + backup-weekly are the only recurring jobs and both target default. The hub database has no volume-level backup — and it holds host_recovery (every box's break-glass root password), host_escrow + host_escrow_superseded, host_pbs_secrets, customer_configs, dr_recipe and the wg peers. Filed rather than fixed: whether the exclusion is deliberate is a question for the operator, and the manual hot copy recorded in _recovery-inventory is not a backup. grep established the ID free.

9. Observations — noticed, NOT acted on

1. The hub returns HTTP 500 for a transient lock, which is what turned a retryable condition into an alarm. Left as-is deliberately (§3) so a surviving SQLITE_BUSY stays visible.
2. The agent does not retry a failed report, so one collision costs a full 15-minute interval — half the staleness budget. Same reasoning; if collisions recur, this is the cheaper of the two retry fixes.
3. store.New sets no SetMaxOpenConns, so database/sql may open unbounded connections against a single-writer database. Not changed here — WAL plus the immediate-lock covers the observed failure, and bounding the pool changes latency characteristics that nothing currently measures.