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.
This commit is contained in:
@@ -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)
|
||||
}
|
||||
}
|
||||
@@ -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)
|
||||
}
|
||||
|
||||
Reference in New Issue
Block a user