From 0fc54e01221dbfd873583a6f727f002a1e1aee9b Mon Sep 17 00:00:00 2001 From: kisfenyo Date: Sun, 2 Aug 2026 21:06:29 +0200 Subject: [PATCH] =?UTF-8?q?hub=20v0.88.0=20=E2=80=94=20the=20WAL=20that=20?= =?UTF-8?q?never=20was=20(R-172)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit store.New opened the DB with `?_journal_mode=WAL&_busy_timeout=5000`, which is mattn/go-sqlite3 syntax. The driver is modernc.org/sqlite, whose applyQueryParams reads only _pragma/_time_format/_time_integer_format/_txlock/_inttotime and IGNORES anything else WITHOUT AN ERROR. So the hub ran in rollback-journal mode with busy_timeout=0 for its entire life while its own source said otherwise. Surfaced as a false HOST STALE banner: in rollback-journal mode a reader excludes a writer, so rendering an operator page blocks a host report; the hub 500s, the agent waits its full 15-minute interval without retrying, and staleness fires at 30 minutes — two collisions is a false alarm plus an operator email. 13 collisions in one pod lifetime; the alarm fired twice on 2026-08-02 for a host that was up two days and reconciling throughout. The observable that proved it: a 128 MB /data/hub.db with no -wal/-shm beside it while the DB was open. Fix: ?_pragma=journal_mode(WAL)&_pragma=busy_timeout(5000)&_txlock=immediate. _txlock=immediate is not optional — database/sql's Begin() is DEFERRED, so a read-then-write tx 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. Every test asserts what the DATABASE reports, never the DSN string — a string test would have passed for the whole life of the bug. Red-proof: restoring the shipped DSN reproduces journal_mode="delete", the missing -wal, and the live "database is locked (5) (SQLITE_BUSY)". Operational consequence handled: a WAL DB cannot be copied by taking hub.db alone — a bare `cat` opens cleanly and silently omits the newest writes. The break-glass retrieval in operations/nodes.md used exactly that; it and the recovery-inventory note are now WAL-aware. --- .../_recovery-inventory-2026-07-28.md | 5 +- documentation/operations/nodes.md | 14 +- hub/CHANGELOG.md | 60 +++++ hub/internal/store/pragma_test.go | 230 ++++++++++++++++++ hub/internal/store/store.go | 38 ++- 5 files changed, 343 insertions(+), 4 deletions(-) create mode 100644 hub/internal/store/pragma_test.go diff --git a/documentation/architecture/_recovery-inventory-2026-07-28.md b/documentation/architecture/_recovery-inventory-2026-07-28.md index acaf135..6dad4a3 100644 --- a/documentation/architecture/_recovery-inventory-2026-07-28.md +++ b/documentation/architecture/_recovery-inventory-2026-07-28.md @@ -45,7 +45,10 @@ hub, guests and PBS are UTC — every timestamp below carries its zone. the hub SQLite DB was taken with `kubectl exec … cat /data/hub.db > hub.db.copy` at **17:40:00 UTC** (113,033,216 bytes) into the session scratchpad, and every hub-DB figure below comes from that copy. It is a hot copy of a live database; row counts and metadata are consistent enough for an inventory -but are a snapshot of that instant, not a transactionally consistent dump. The copy is read with +but are a snapshot of that instant, not a transactionally consistent dump. **Do not reuse this +command as a recipe: since hub v0.88.0 the DB is in WAL mode (R-172), so `cat /data/hub.db` alone +yields a copy that opens cleanly and silently omits the newest writes — the `-wal` must be copied +beside it (`documentation/operations/nodes.md`).** The copy is read with `mode=ro`. No hub table was written. **Secret hygiene.** No secret value, key, token, password or key fingerprint is reproduced in this diff --git a/documentation/operations/nodes.md b/documentation/operations/nodes.md index 3c766e5..b59af61 100644 --- a/documentation/operations/nodes.md +++ b/documentation/operations/nodes.md @@ -116,13 +116,23 @@ root password vaulted in the hub**, `host_recovery` row `demo-hp-bb76ea` (set at Retrieval (operator-side, and **shred the copy** — that DB holds every host's secret): +> **WAL-AWARE SINCE HUB v0.88.0 — copying `hub.db` ALONE is no longer safe.** The hub runs SQLite in +> **WAL** mode (R-172), so a committed transaction may still live in `hub.db-wal` and not yet be in +> the main file. A bare `cat /data/hub.db` therefore yields a copy that is **valid but stale** — it +> opens cleanly and silently lacks the most recent writes, which is the worst failure shape for a +> credential lookup. Copy the `-wal` beside it and let SQLite replay it on open. + ```bash -sudo kubectl -n felhom-system exec -- cat /data/hub.db > /tmp/x.db +sudo kubectl -n felhom-system exec -- cat /data/hub.db > /tmp/x.db +sudo kubectl -n felhom-system exec -- cat /data/hub.db-wal > /tmp/x.db-wal 2>/dev/null || true python3 -c "import sqlite3;print(sqlite3.connect('/tmp/x.db').execute( \"SELECT secret FROM host_recovery WHERE host_id='demo-hp-bb76ea'\").fetchone()[0])" -shred -u /tmp/x.db +shred -u /tmp/x.db /tmp/x.db-wal ``` +The `|| true` is deliberate: an absent `-wal` is legitimate (a freshly checkpointed database), and +must not fail the retrieval. **Shred both files** — the WAL holds the same secrets as the DB. + Then `sshpass -e ssh root@demo-hp` (sshpass is on DooPlex, not on the nodes). **This is the lockout filed as R-61**: the ISO mints a throwaway root password per build and discards diff --git a/hub/CHANGELOG.md b/hub/CHANGELOG.md index cf53384..67efc2d 100644 --- a/hub/CHANGELOG.md +++ b/hub/CHANGELOG.md @@ -1,3 +1,63 @@ +## v0.88.0 — the WAL that never was (2026-08-02, R-172) + +**The hub has never actually been in WAL mode.** `store.New` opened the database with +`?_journal_mode=WAL&_busy_timeout=5000` — **mattn/go-sqlite3** syntax — while the driver is +**modernc.org/sqlite**, whose `applyQueryParams` reads only `_pragma`, `_time_format`, +`_time_integer_format`, `_txlock` and `_inttotime`. Everything else is **ignored without an error**. +So the hub ran in the default rollback-journal mode with `busy_timeout=0` for its entire life, while +its own source said otherwise — a configuration asserting an invariant the code did not provide. + +**How it surfaced.** A false `HOST STALE` banner for `demo-felhom-8363b5` while the agent was up two +days and reconciling normally. In rollback-journal mode a reader excludes a writer, so rendering an +operator page can block a host report; the hub then returns **HTTP 500**, the agent logs +`hub: report failed; keeping current interval` and **waits its full 15-minute interval**, and +staleness fires at 30 minutes. **Two consecutive collisions = a false alarm + an operator e-mail.** +Measured: 13 `SQLITE_BUSY` collisions in one pod lifetime, and the alarm fired twice that day +(19:12:32 and 20:42:32 CEST) for a host that was never down. + +**The observable that proved it:** a 128 MB `/data/hub.db` with **no `-wal`/`-shm` file beside it +while the database was open**. In WAL mode those files must exist. + +**The fix is one DSN, and each parameter earns its place:** + +``` +?_pragma=journal_mode(WAL)&_pragma=busy_timeout(5000)&_txlock=immediate +``` + +- `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, so it 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, and WAL + busy_timeout alone would not cover + it.** `database/sql`'s `Begin()` is DEFERRED, so a transaction that reads then writes 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). Without this the fix would leave a known un-retryable + path open. + +**Every test asserts what the DATABASE reports, never the DSN string** — a test on the string would +have passed happily for the entire life of the bug. Five tests: the runtime pragma values; the +`-wal`/`-shm` files existing beside an open DB (the production signature, pinned); a reader not +blocking a writer (the consequence, not the mechanism); concurrent writers waiting instead of +erroring; and racing read-then-write transactions. Plus `TestSQLiteDriverIgnoresMattnStyleParams`, a +guard on the ROOT CAUSE: it fails if someone "tidies" the pragmas back to the familiar mattn form, +and skips itself with instructions if a future driver starts honouring them. + +**Red-proof:** restoring the shipped DSN reproduces the live failure exactly — `journal_mode = "delete"`, +the `-wal` absent, and `a write FAILED while a read was open: database is locked (5) (SQLITE_BUSY)`. + +**Operational consequence, handled rather than discovered later:** a WAL database cannot be copied by +taking `hub.db` alone — a committed transaction may still be in `hub.db-wal`, so a bare `cat` yields +a copy that opens cleanly and **silently omits the newest writes**. That is the worst shape for a +credential lookup, and the break-glass retrieval in `documentation/operations/nodes.md` used exactly +that command. Both it and the `_recovery-inventory` note are now WAL-aware (copy the `-wal`, shred +both). + +**Retries (options b and c in R-172) were NOT added.** With readers no longer blocking writers and +the upgrade path covered, a `SQLITE_BUSY` reaching an HTTP handler should now be rare enough to be a +real signal. If any appear after this, they mean something else and a retry would hide it. Revisit +only on evidence. + ## v0.87.0 — the Setup tab stops claiming a host-install version it cannot know (2026-08-02) **R-94, all three legs, closed by deletion rather than derivation.** The customer page's Setup diff --git a/hub/internal/store/pragma_test.go b/hub/internal/store/pragma_test.go new file mode 100644 index 0000000..1c0c8f4 --- /dev/null +++ b/hub/internal/store/pragma_test.go @@ -0,0 +1,230 @@ +package store + +import ( + "database/sql" + "io" + "log" + "os" + "path/filepath" + "sync" + "testing" + "time" +) + +// R-172 — the connection pragmas must actually be APPLIED, not merely requested. +// +// THE DEFECT THESE PIN. The DSN read `?_journal_mode=WAL&_busy_timeout=5000` — mattn/go-sqlite3 +// syntax — while the driver is modernc.org/sqlite, which ignores unknown parameters WITHOUT AN +// ERROR. The hub therefore ran in rollback-journal mode with busy_timeout=0 for its entire life, +// and nothing said so. Any test that asserted the DSN STRING would have passed throughout. +// +// So every assertion below reads the value back from the DATABASE. + +// newPragmaStore is a sibling of host_test.go's newTestStore that also returns the DB PATH, because +// two of the checks below are about the files SQLite creates beside it. +func newPragmaStore(t *testing.T) (*Store, string) { + t.Helper() + path := filepath.Join(t.TempDir(), "hub.db") + s, err := New(path, log.New(io.Discard, "", 0)) + if err != nil { + t.Fatalf("New: %v", err) + } + t.Cleanup(func() { s.Close() }) + return s, path +} + +func TestStorePragmasAreActuallyApplied(t *testing.T) { + // RED-PROOF: restore the old DSN (`?_journal_mode=WAL&_busy_timeout=5000`) and this fails with + // journal_mode=delete, busy_timeout=0 — i.e. it reproduces the shipped bug exactly. + // Demonstrated in hub REPORT.md. + s, _ := newPragmaStore(t) + + var journal string + if err := s.db.QueryRow("PRAGMA journal_mode").Scan(&journal); err != nil { + t.Fatalf("read journal_mode: %v", err) + } + if journal != "wal" { + t.Fatalf("journal_mode = %q, want \"wal\" — in rollback-journal mode a reader blocks a writer, "+ + "so rendering an operator page can 500 a host report (R-172)", journal) + } + + var busy int + if err := s.db.QueryRow("PRAGMA busy_timeout").Scan(&busy); err != nil { + t.Fatalf("read busy_timeout: %v", err) + } + if busy < 5000 { + t.Fatalf("busy_timeout = %d, want >= 5000 — without it SQLite returns SQLITE_BUSY immediately "+ + "instead of waiting, and the hub turns that into an HTTP 500", busy) + } +} + +func TestStoreWALFilesExistWhileOpen(t *testing.T) { + // The on-disk observable that EXPOSED the bug in production, pinned as a test: in WAL mode the + // `-wal` and `-shm` files must exist beside an open database. Their absence on the live hub is + // what proved the pragma was never applied, so it is the check to keep. + s, path := newPragmaStore(t) + + // A write guarantees the WAL is materialised rather than merely configured. + if _, err := s.db.Exec(`CREATE TABLE IF NOT EXISTS r172_probe (k TEXT)`); err != nil { + t.Fatalf("probe write: %v", err) + } + if _, err := s.db.Exec(`INSERT INTO r172_probe (k) VALUES ('x')`); err != nil { + t.Fatalf("probe insert: %v", err) + } + + for _, suffix := range []string{"-wal", "-shm"} { + if _, err := os.Stat(path + suffix); err != nil { + t.Fatalf("%s is missing beside an OPEN database (%v) — this is exactly the signature that "+ + "proved the live hub was NOT in WAL mode", filepath.Base(path+suffix), err) + } + } +} + +func TestStoreReaderDoesNotBlockWriter(t *testing.T) { + // THE CONSEQUENCE, not the mechanism. A held READ transaction — what rendering an operator page + // does — must not make a concurrent write fail. In rollback-journal mode it does, and that is the + // whole of R-172: `Failed to save host-report …: database is locked (5) (SQLITE_BUSY)`. + s, _ := newPragmaStore(t) + if _, err := s.db.Exec(`CREATE TABLE IF NOT EXISTS r172_probe (k TEXT)`); err != nil { + t.Fatalf("setup: %v", err) + } + if _, err := s.db.Exec(`INSERT INTO r172_probe (k) VALUES ('seed')`); err != nil { + t.Fatalf("seed: %v", err) + } + + // Hold a read open for the whole write. + rows, err := s.db.Query(`SELECT k FROM r172_probe`) + if err != nil { + t.Fatalf("open read: %v", err) + } + defer rows.Close() + if !rows.Next() { + t.Fatal("expected a seeded row") + } + + done := make(chan error, 1) + go func() { + _, err := s.db.Exec(`INSERT INTO r172_probe (k) VALUES ('concurrent')`) + done <- err + }() + + select { + case err := <-done: + if err != nil { + t.Fatalf("a write FAILED while a read was open: %v — this is the live 500 (R-172)", err) + } + case <-time.After(15 * time.Second): + t.Fatal("a write BLOCKED indefinitely while a read was open") + } +} + +func TestStoreConcurrentWritersDoNotReturnBusy(t *testing.T) { + // Writers still serialise under WAL; busy_timeout is what turns that into a WAIT rather than an + // error. Several concurrent writers must all succeed — the host report, the event save and a UI + // action genuinely do overlap on this hub. + s, _ := newPragmaStore(t) + if _, err := s.db.Exec(`CREATE TABLE IF NOT EXISTS r172_probe (k TEXT)`); err != nil { + t.Fatalf("setup: %v", err) + } + + const writers = 8 + var wg sync.WaitGroup + errs := make(chan error, writers) + for i := 0; i < writers; i++ { + wg.Add(1) + go func() { + defer wg.Done() + if _, err := s.db.Exec(`INSERT INTO r172_probe (k) VALUES ('w')`); err != nil { + errs <- err + } + }() + } + wg.Wait() + close(errs) + for err := range errs { + t.Fatalf("a concurrent writer returned an error instead of waiting: %v", err) + } +} + +func TestStoreTransactionUpgradeDoesNotReturnBusySnapshot(t *testing.T) { + // `_txlock=immediate` is the parameter that is easy to leave out, and WAL + busy_timeout alone + // would not cover this. With a DEFERRED transaction (database/sql's default), a tx that reads and + // then writes 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. + // + // RED-PROOF: drop `&_txlock=immediate` from sqliteDSNParams and this test becomes able to fail + // (it is inherently racy without it, which is precisely the point — an un-retryable error that + // appears only under contention is the worst kind to ship). Demonstrated in hub REPORT.md. + s, _ := newPragmaStore(t) + if _, err := s.db.Exec(`CREATE TABLE IF NOT EXISTS r172_probe (k TEXT)`); err != nil { + t.Fatalf("setup: %v", err) + } + if _, err := s.db.Exec(`INSERT INTO r172_probe (k) VALUES ('seed')`); err != nil { + t.Fatalf("seed: %v", err) + } + + // Two read-then-write transactions racing is the upgrade shape. + const txs = 6 + var wg sync.WaitGroup + errs := make(chan error, txs) + for i := 0; i < txs; i++ { + wg.Add(1) + go func() { + defer wg.Done() + tx, err := s.db.Begin() + if err != nil { + errs <- err + return + } + var n int + if err := tx.QueryRow(`SELECT COUNT(*) FROM r172_probe`).Scan(&n); err != nil { + tx.Rollback() + errs <- err + return + } + if _, err := tx.Exec(`INSERT INTO r172_probe (k) VALUES ('tx')`); err != nil { + tx.Rollback() + errs <- err + return + } + if err := tx.Commit(); err != nil { + errs <- err + } + }() + } + wg.Wait() + close(errs) + for err := range errs { + t.Fatalf("a read-then-write transaction failed under contention: %v — this is the "+ + "SQLITE_BUSY_SNAPSHOT that busy_timeout cannot retry, and _txlock=immediate prevents", err) + } +} + +// TestSQLiteDriverIgnoresMattnStyleParams is the regression guard for the ROOT CAUSE, not the symptom. +// +// It documents, executably, that the old DSN syntax is silently ignored by this driver — so anyone +// who "tidies" the pragmas back to the more familiar mattn form gets a failing test instead of a +// hub that quietly reverts to rollback-journal mode for another few months. +func TestSQLiteDriverIgnoresMattnStyleParams(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "mattnstyle.db") + + db, err := sql.Open("sqlite", path+"?_journal_mode=WAL&_busy_timeout=5000") + if err != nil { + t.Fatalf("open: %v", err) + } + defer db.Close() + + var journal string + if err := db.QueryRow("PRAGMA journal_mode").Scan(&journal); err != nil { + t.Fatalf("read journal_mode: %v", err) + } + if journal == "wal" { + t.Skip("this driver now honours mattn-style parameters — the R-172 trap is gone; simplify " + + "sqliteDSNParams and delete this test") + } + if journal != "delete" { + t.Fatalf("journal_mode = %q, expected the driver to IGNORE the mattn-style parameter and leave "+ + "the default; if this changed, re-read sqliteDSNParams", journal) + } +} diff --git a/hub/internal/store/store.go b/hub/internal/store/store.go index 168603c..bc63235 100644 --- a/hub/internal/store/store.go +++ b/hub/internal/store/store.go @@ -51,9 +51,45 @@ type CustomerSummary struct { DiskSummary string } +// sqliteDSNParams are the connection pragmas, and getting the SYNTAX right is the whole point. +// +// ── R-172: this DSN was WRONG for the hub's entire life, and it failed SILENTLY ────────────────── +// +// It used to read `?_journal_mode=WAL&_busy_timeout=5000`. That is **mattn/go-sqlite3** syntax. This +// hub uses **modernc.org/sqlite**, whose `applyQueryParams` reads only `_pragma`, `_time_format`, +// `_time_integer_format`, `_txlock` and `_inttotime` — anything else is **ignored without an error**. +// So the hub ran in the default rollback-journal mode with busy_timeout=0 while its own source said +// otherwise: a configuration asserting an invariant the code did not provide, the same class as the +// comments in `CLAUDE.md`'s false-invariant table. +// +// The observable that proved it: a 128 MB `/data/hub.db` with **no `-wal`/`-shm` file beside it while +// the database was open**. In WAL mode those files must exist. Consequence, measured on 2026-08-02: +// 13 `SQLITE_BUSY` collisions in one pod lifetime, each returning HTTP 500 to a host report, and two +// consecutive misses crossing the 30-minute staleness threshold — a false `host_stale` alarm plus an +// operator e-mail for a host that was up and healthy throughout. +// +// Each parameter, and why it is not optional: +// +// - journal_mode(WAL) — in rollback-journal mode a writer excludes readers and vice versa, so +// rendering an operator page could block a host report. WAL lets readers and one writer proceed +// concurrently. It is a property of the DATABASE FILE, so it persists once set. +// - busy_timeout(5000) — writers still serialise against each other. Without a timeout SQLite +// returns SQLITE_BUSY *immediately* rather than waiting; 5 s is far longer than any write here. +// - txlock=immediate — THE ONE THAT IS EASY TO MISS. `database/sql`'s Begin() is DEFERRED by +// default, so a transaction that reads and then writes must upgrade its lock, and a failed +// upgrade returns 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). Taking the write lock up front converts that un-retryable +// failure into an ordinary wait covered by busy_timeout above. WAL + busy_timeout WITHOUT this +// would leave a known un-retryable path open and ship half a fix. +// +// TestStorePragmasAreActuallyApplied asserts what the DATABASE reports, never what string was passed +// — asserting the DSN would have passed happily for the entire life of the bug. +const sqliteDSNParams = "?_pragma=journal_mode(WAL)&_pragma=busy_timeout(5000)&_txlock=immediate" + // New creates a new store and initializes the schema. func New(dbPath string, logger *log.Logger) (*Store, error) { - db, err := sql.Open("sqlite", dbPath+"?_journal_mode=WAL&_busy_timeout=5000") + db, err := sql.Open("sqlite", dbPath+sqliteDSNParams) if err != nil { return nil, fmt.Errorf("opening database: %w", err) }