# 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.