diff --git a/CHANGELOG.md b/CHANGELOG.md index 55e8345..4e05865 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -8,7 +8,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] ### Added -- A synthetic reproducer for the ART-index corruption that took production down in September 2026: `TestARTIndexSurvivesAddedColumnAndBulkReplace` in `internal/storage/art_repro_test.go`, built from the schema with no production bytes — every value is derived from the row number, so it carries no user id, session id or span attribute that belonged to anyone. It rebuilds the trigger rather than a statement from it: `spans` as it stood at schema version 2, without `user_id` and with that era's three ART indexes, filled across the 30-day retention boundary; `storage.Open` then runs the real `schema.sql`, which adds `user_id VARCHAR` to the filled indexed table and puts `idx_spans_user_id` on that added column; a bulk `UPDATE` writes the column, cotel's own retention roll-up supplies the large replace transaction (the `INSERT INTO daily_usage` and the `DELETE FROM spans` are one transaction, so it is the real mutation and not an imitation); then checkpoint, close, reopen, checkpoint, ingest more, repeat. The repetition is the point — the damage accumulates and production ran for weeks after its migration before an open aborted — and so is the restart: this class of fault is only ever reported by the checkpoint that folds the index or the open that reads it back. Each pass asserts the reopen succeeds, both checkpoints fold, all four indexes survive, and an indexed `user_id = ?` agrees with the same predicate written so the index cannot serve it, which is the silent form of the damage: a wrong answer rather than an error. It runs in the ordinary test set rather than behind a build tag, because the moment it most needs to run is a driver or engine bump and that is exactly when an optional test is forgotten; `COTEL_ART_REPRO_SPANS` and `COTEL_ART_REPRO_CYCLES` scale it past the defaults (20 000 spans, 2 cycles, 4.7 s). Against the engine the tree links today — `duckdb-go/v2 v2.10506.0`, `SELECT version()` → `v1.5.6` — it did **not** reproduce, at the defaults or at 200 000 spans over 6 cycles. That measures the half of the forensic volume's release condition that was previously unevaluable, and measures it negative rather than exonerating: upstream reports the same class of fault on 1.5.5 against a ~19 GB database, the file that was damaged here took weeks of ingest to get there, and two clean runs at our scale are not absence ([docs/operations/duckdb-recovery.md](docs/operations/duckdb-recovery.md)) +- A synthetic reproducer for the ART-index corruption that took production down in September 2026: `TestARTIndexSurvivesAddedColumnAndBulkReplace` in `internal/storage/art_repro_test.go`, built from the schema with no production bytes — every value is derived from the row number, so it carries no user id, session id or span attribute that belonged to anyone. It rebuilds the trigger rather than a statement from it: `spans` as it stood at schema version 2 — without `user_id`, and *with* the mid-table `duration_ms` generated column, so that the one ALTER production ran on a long-lived filled table (v9 → v10, six weeks before the abort) runs here too instead of passing over a column the fixture never had, and so the indexes are built over the logical/physical column skew they were built over in production — with that era's three ART indexes, filled across the 30-day retention boundary; `storage.Open` then runs the real `schema.sql`, which adds `user_id VARCHAR` to the filled indexed table and puts `idx_spans_user_id` on that added column; a bulk `UPDATE` writes the column, cotel's own retention roll-up supplies the large replace transaction (the `INSERT INTO daily_usage` and the `DELETE FROM spans` are one transaction, so it is the real mutation and not an imitation); then checkpoint, close, reopen, checkpoint, ingest more, repeat. The repetition is the point — the damage accumulates and production ran for weeks after its migration before an open aborted — and so is the restart: this class of fault is only ever reported by the checkpoint that folds the index or the open that reads it back. Each pass asserts that `duration_ms` was there before the migration and is gone after it (a `DROP COLUMN IF EXISTS` that no-ops must not be able to come back unnoticed), that the reopen succeeds, that both checkpoints fold — a present-but-empty `.wal` counts as folded, so an engine that truncates rather than unlinks is not reported as this defect — that all four indexes survive, that a bare `user_id = ` folded into the scan agrees with the same predicate wrapped in an expression, which is not, and that re-inserting a stored `span_id` is still rejected while an unused one is accepted. The last two are the silent form of the damage: a wrong answer rather than an error. They are phrased that way because no `SELECT` over `spans` is planned as an ART index scan on this engine — measured, including on the primary key and on a textbook unique match with the thresholds raised — so an “indexed probe agrees with an unindexed probe” assertion would have been two sequential scans agreeing; the pushdown pair is what [ADR-0013](docs/decisions/0013-spans-has-no-derived-columns.md)'s wrong answers actually came out of, and unique-constraint enforcement is the one path that provably traverses an ART index. It runs in the ordinary test set rather than behind a build tag, because the moment it most needs to run is a driver or engine bump and that is exactly when an optional test is forgotten; `COTEL_ART_REPRO_SPANS` and `COTEL_ART_REPRO_CYCLES` scale it past the defaults (20 000 spans, 2 cycles, 4.1 s). Against the engine the tree links today — `duckdb-go/v2 v2.10506.0`, `SELECT version()` → `v1.5.6` — it did **not** reproduce, at the defaults or at 200 000 spans over 6 cycles. That measures the half of the forensic volume's release condition that was previously unevaluable, and measures it negative rather than exonerating: upstream reports the same class of fault on 1.5.5 against a ~19 GB database, the file that was damaged here took weeks of ingest to get there, and two clean runs at our scale are not absence ([docs/operations/duckdb-recovery.md](docs/operations/duckdb-recovery.md)) ### Changed - `docker compose build` tags its result `cotel-local:latest` instead of `ghcr.io/flopsstuff/cotel:latest`. Compose treats `image:` next to `build:` as the name to tag the local build with, so the published name was being reused for an artifact that never came from the registry: on the production host — where the deploy is `docker compose build --pull` followed by `up -d`, and `--pull` refreshes the Dockerfile's base images rather than the app image — `Image=ghcr.io/flopsstuff/cotel:latest` named a locally built binary, and built-here and pulled-from-registry were the same string. Three things follow from splitting them. You can read which artifact a host is running off the name. The thing the release pipeline publishes, and which `release.yml` moves only on an explicit dispatch, is no longer shadowed by every merge to `main`. And `docker pull ghcr.io/flopsstuff/cotel:latest` on the production host stops being able to swap the running service's binary at its next restart for content no deploy step validated — it now lands on a name nothing there runs. Production still *builds* its image, deliberately: a pull-only production would mean a merge to `main` no longer changes production, which is a separate decision from this cleanup and would need its own ADR. The operations pages name both images where the distinction matters — the recovery procedure's "match the CLI to the version linked into cotel" step asks `cotel-local:latest` on a host that builds its own image — and they also record that `ghcr.io/flopsstuff/cotel:latest` is now a multi-arch index whose `linux/arm64` entry runs natively on a Pi or Apple Silicon, so the documented `docker run --entrypoint /usr/local/bin/cotel … --db-query` and `--db-import` commands are honest on arm64 without a local build ([docs/operations/duckdb-recovery.md](docs/operations/duckdb-recovery.md), [docs/operations/duckdb-snapshots.md](docs/operations/duckdb-snapshots.md)) diff --git a/docs/operations/duckdb-recovery.md b/docs/operations/duckdb-recovery.md index 24eea04..d969497 100644 --- a/docs/operations/duckdb-recovery.md +++ b/docs/operations/duckdb-recovery.md @@ -368,25 +368,51 @@ exactly the moment nobody remembers an optional test. One pass is: 1. build `spans` as it stood at schema version 2 — every column it has today except - `user_id` — with that era's three ART indexes, and fill it with spans spread over - 60 days, i.e. across the 30-day raw-retention boundary; + `user_id`, plus the mid-table `duration_ms` generated column that only v10 + removed — with that era's three ART indexes, and fill it with spans spread over + 60 days, i.e. across the 30-day raw-retention boundary. Both differences carry a + migration, and the second one carries the migration that matters: `DROP COLUMN IF + EXISTS duration_ms` over a column the fixture never had is a silent no-op, and + v10 is the ALTER production ran on a long-lived filled table six weeks before the + abort, where v2 → v3 ran the day after the database was created. While the column + is there the table also carries the logical/physical column skew of + [ADR-0013](../decisions/0013-spans-has-no-derived-columns), so the indexes are + built over the layout production built them over; 2. open it with `storage.Open`, so the real `schema.sql` runs the real - `ALTER TABLE spans ADD COLUMN user_id VARCHAR` against a filled, indexed table and - then builds `idx_spans_user_id` on that added column; + `ALTER TABLE spans ADD COLUMN user_id VARCHAR` against a filled, indexed table, + drops `duration_ms` out of the middle of it, and then builds `idx_spans_user_id` + on the added column; 3. write the added column for every row with a bulk `UPDATE`, then run cotel's own retention roll-up as the large replace transaction — the `INSERT INTO daily_usage` and the `DELETE FROM spans` are one transaction, so this is the real mutation and not an imitation of it; 4. checkpoint, close, reopen, checkpoint again, ingest a further batch, and repeat. -Each pass asserts four things, and they fail for different reasons: +Each pass asserts the following, and they fail for different reasons: | Assertion | What a failure means | |---|---| +| `duration_ms` is there before the migration and gone after it | the pass never exercised v10's `ALTER TABLE spans DROP COLUMN` — either the fixture stopped being pre-v10, in which case the drop was a no-op, or the drop ran and left the column | | the reopen succeeds | the 1.1.3 `abort()` inside `duckdb_open_ext`, which 1.5.6 raises as a Go error instead | -| both checkpoints fold | the index fold refused — the same signal the startup and shutdown checkpoints give in production, and the earliest honest warning there is | +| both checkpoints fold | the index fold refused — the same signal the startup and shutdown checkpoints give in production, and the earliest honest warning there is. A `.wal` file that is present but zero bytes counts as folded, so an engine that truncates rather than unlinks is not reported as this defect | | all four indexes are present after the restart | an index was lost rather than damaged | -| an indexed `user_id = ?` agrees with the same predicate written so the index cannot serve it | the silent form of this damage: a wrong answer, which no checkpoint and no open reports | +| a bare `user_id = `, which the optimizer folds into the scan, agrees with the same predicate wrapped in an expression, which it does not | the silent form of this damage: a wrong answer, which no checkpoint and no open reports. It is [ADR-0013](../decisions/0013-spans-has-no-derived-columns)'s symptom exactly — a pushed-down equality answered against the wrong column offset, matching nothing | +| re-inserting a stored `span_id` is rejected, and inserting an unused one is accepted | the primary key's unique ART index has lost its own entries, or gained phantom ones. This is the only assertion in the list that provably traverses an ART index — see below | + +**The equality pair compares two sequential scans, not an index against a scan.** On +the linked engine, no `SELECT` over `spans` is planned as an ART index scan: `EXPLAIN` +answers `SEQ_SCAN` / `Type: Sequential Scan` for `user_id = ` and for a +bound `user_id = ?` alike, for an equality on the primary key, and for the textbook +case — a unique match in a 100 000-row table with a fresh index on exactly the probed +column — with `index_scan_max_count` and `index_scan_percentage` raised to admit +everything, and with and without the `storage_compatibility_version` pin cotel opens +with. So an assertion phrased as *indexed probe agrees with unindexed probe* would be +two sequential scans agreeing with each other. What the pair does compare is filter +pushdown against no pushdown, which is the path ADR-0013's wrong answers came out of; +the test asserts that the two probes still plan differently, so the comparison cannot +quietly degenerate into one path checked twice. The unique-constraint probe is the +check that reaches an ART index, because conflict detection consults the primary key's +index on the way in. Size and repetitions are tunable, and turning them up is the first thing to do when the verdict is "did not reproduce": @@ -410,13 +436,23 @@ docker run --rm -u "$(id -u):$(id -g)" -e HOME=/tmp/h -e GOCACHE=/go/.cache/go-b On 2026-10-13, on linux/arm64 under `golang:1.24`, against the engine the tree links today — `duckdb-go/v2 v2.10506.0`, with `SELECT version()` answering `v1.5.6`: -| Parameters | Result | -|---|---| -| 20 000 spans, 2 cycles (the defaults, so `go test ./...` runs this) | did not reproduce, 4.7 s | -| 200 000 spans, 6 cycles — 8 opens, 14 checkpoints, the table peaking at 407 763 rows | did not reproduce, 3 m 40 s | +| Fixture | Parameters | Result | +|---|---|---| +| pre-v3: `duration_ms` absent, so the only ALTER exercised was v2 → v3 and v10's `DROP COLUMN` was a silent no-op | 20 000 spans, 2 cycles | did not reproduce, 4.7 s | +| pre-v3, as above | 200 000 spans, 6 cycles — 8 opens, 14 checkpoints, the table peaking at 407 763 rows | did not reproduce, 3 m 40 s | +| pre-v10: `duration_ms` present and dropped by the migration under test, the indexes built over the column skew | 20 000 spans, 2 cycles (the defaults, so `go test ./...` runs this) | did not reproduce, 4.1 s | +| pre-v10, as above | 200 000 spans, 6 cycles — 8 opens, 14 checkpoints, the table peaking at 407 956 rows | did not reproduce, 2 m 58 s | + +The first two rows are kept because they are what was run, not because they cover +what they were taken to cover: their fixture never had `duration_ms`, so the v10 +`ALTER TABLE spans DROP COLUMN` did nothing, and the only ALTER those two runs put +under an indexed filled table was v2 → v3 — which in production ran the day after +the database was created, on an almost empty table. The bottom two rows are the same +two sizes over the corrected fixture, so they are the ones that exercised the ALTER +production ran six weeks before the abort. No run has reproduced anything. **This is not a demonstration that 1.5.6 is free of the defect, and must not be -quoted as one.** It is two negative runs at one scale on one architecture. Three +quoted as one.** It is four negative runs at two scales on one architecture. Three things bound what they cover: - The production file that was damaged held ~34 700 spans in 147 MB and took weeks diff --git a/internal/storage/art_repro_test.go b/internal/storage/art_repro_test.go index eab2e85..5f30ca5 100644 --- a/internal/storage/art_repro_test.go +++ b/internal/storage/art_repro_test.go @@ -29,6 +29,7 @@ import ( "os" "path/filepath" "strconv" + "strings" "testing" "time" ) @@ -52,10 +53,19 @@ const reproSpanDays = 60 // deep nodes, i.e. the structure the defect damages. const reproUsers = 12 -// preUserIDSchema is `spans` as it stood at schema version 2: every column the -// table has today except user_id, with the three ART indexes of that era. The -// point is to reach the ALTER from a table that was built and filled without -// the column, which is the state production was in. +// preUserIDSchema is `spans` as it stood at schema version 2, taken from that +// era's schema.sql: every column the table has today except user_id, plus +// duration_ms, and the three ART indexes of that era. +// +// Both differences from today's table carry a migration. Starting without +// user_id is what makes the v2 -> v3 ALTER add a column to a filled, indexed +// table. Starting *with* duration_ms is what makes the v9 -> v10 ALTER that +// drops it do anything at all: `DROP COLUMN IF EXISTS` over a column that was +// never there is a silent no-op, and v10 is the ALTER that ran in production on +// a long-lived table six weeks before the open aborted, where v2 -> v3 ran the +// day after the database was created. While the column is present the table +// also carries the logical/physical column skew of ADR-0013, so the indexes are +// built over the layout production built them over. const preUserIDSchema = ` CREATE TABLE schema_version ( version INTEGER PRIMARY KEY, @@ -70,6 +80,9 @@ CREATE TABLE spans ( name VARCHAR NOT NULL, start_time TIMESTAMPTZ NOT NULL, end_time TIMESTAMPTZ NOT NULL, + duration_ms DOUBLE GENERATED ALWAYS AS ( + epoch_ms(end_time) - epoch_ms(start_time) + ), service_name VARCHAR, session_id VARCHAR, model VARCHAR, @@ -163,6 +176,23 @@ func mustExec(t *testing.T, db *sql.DB, what, query string, args ...any) { t.Logf("%s: ok in %s", what, time.Since(start).Round(time.Millisecond)) } +// rowQuerier is the one method spansHasColumn needs, so it can be asked of the +// raw seed connection and of a migrated database alike. +type rowQuerier interface { + QueryRow(query string, args ...any) *sql.Row +} + +func spansHasColumn(t *testing.T, q rowQuerier, col string) bool { + t.Helper() + var n int + if err := q.QueryRow(` + SELECT count(*) FROM information_schema.columns + WHERE table_name = 'spans' AND column_name = ?`, col).Scan(&n); err != nil { + t.Fatalf("read spans columns: %v", err) + } + return n > 0 +} + func indexNames(t *testing.T, ro *ReadDB) []string { t.Helper() rows, err := ro.Query(`SELECT index_name FROM duckdb_indexes() ORDER BY index_name`) @@ -206,6 +236,10 @@ func TestARTIndexSurvivesAddedColumnAndBulkReplace(t *testing.T) { t.Logf("engine %s: %d spans over %d days, then %d replace/restart cycles", engine, spans, reproSpanDays, cycles) mustExec(t, seed, "pre-migration schema", preUserIDSchema) mustExec(t, seed, fmt.Sprintf("seed %d spans", spans), seedSpans, now, reproSpanDays, 0, spans) + if !spansHasColumn(t, seed, "duration_ms") { + t.Fatal("the seeded database has no duration_ms, so it is not pre-v10 and the v10 ALTER " + + "under test would pass over it as a silent no-op: restore the column in preUserIDSchema") + } mustExec(t, seed, "seed checkpoint", "CHECKPOINT") if err := seed.Close(); err != nil { t.Fatalf("close seed: %v", err) @@ -213,8 +247,8 @@ func TestARTIndexSurvivesAddedColumnAndBulkReplace(t *testing.T) { requireNoWAL(t, path, "after seeding") // Phase 2 — the migration, as cotel performs it on the next start: - // schema.sql adds user_id VARCHAR to the filled table, then builds an ART - // index on that added column. + // schema.sql adds user_id VARCHAR to the filled table, drops duration_ms + // off the middle of it, and builds an ART index on the added column. db, err := Open(path) if err != nil { t.Fatalf("REPRODUCED: the open that runs the migration failed: %v", err) @@ -227,6 +261,11 @@ func TestARTIndexSurvivesAddedColumnAndBulkReplace(t *testing.T) { if v, ok := appliedSchemaVersion(db.rw); !ok || v < 10 { t.Fatalf("schema did not migrate: applied version %d (recorded=%v)", v, ok) } + // The version row alone does not say v10's ALTER ran — it would be recorded + // over a no-op just the same. The column is gone only if it executed. + if spansHasColumn(t, db.rw, "duration_ms") { + t.Fatal("duration_ms is still declared after the migration: the v10 ALTER did not drop it") + } t.Logf("indexes after migration: %v", indexNames(t, db.ReadOnly())) // The startup checkpoint cotel runs immediately after schema apply: the @@ -289,12 +328,14 @@ func TestARTIndexSurvivesAddedColumnAndBulkReplace(t *testing.T) { } t.Logf("did not reproduce on %s after %d cycles: every open succeeded, both checkpoints folded "+ - "on every cycle, all four indexes survived, and indexed probes agreed with unindexed ones", + "on every cycle, all four indexes survived, pushed-down equality agreed with the same "+ + "predicate as an expression, and the primary key's index answered both ways", engine, cycles) } // assertIndexesIntact is the verdict after a restart: the four indexes exist, -// no row was lost, and the index on the added column still answers correctly. +// no row was lost, equality on the added column answers correctly, and the +// primary key's ART index still holds its own entries. func assertIndexesIntact(t *testing.T, db *DB, wantSpans int) { t.Helper() want := []string{"idx_spans_name", "idx_spans_session_id", "idx_spans_start_time", "idx_spans_user_id"} @@ -305,7 +346,8 @@ func assertIndexesIntact(t *testing.T, db *DB, wantSpans int) { if n := countSpans(t, db); n != wantSpans { t.Fatalf("after reopen: %d spans, want %d", n, wantSpans) } - assertIndexedProbesAgree(t, db) + assertPushdownProbesAgree(t, db) + assertPrimaryKeyIndexAnswers(t, db) } func countSpans(t *testing.T, db *DB) int { @@ -317,36 +359,133 @@ func countSpans(t *testing.T, db *DB) int { return n } -// assertIndexedProbesAgree compares an equality on the added column — which the -// ART index on it can serve — against the same predicate wrapped in an -// expression, which it cannot. A damaged or mis-addressed index shows up as a -// disagreement; a wrong count here is this defect's silent form, and neither a -// checkpoint nor an open reports it. -func assertIndexedProbesAgree(t *testing.T, db *DB) { +// assertPushdownProbesAgree compares a bare `user_id = ` on the added +// column, which the optimizer folds into the scan, against the same predicate +// wrapped in an expression, which it cannot fold. A wrong count on the first is +// this defect's silent form — the shape ADR-0013 documents, where the pushed +// filter is answered against the wrong column offset and matches nothing — and +// neither a checkpoint nor an open reports it. +// +// It is a comparison of two scans, not of an index against a scan: on the +// engine the tree links, no SELECT plan over `spans` is served by an ART index +// scan, including an equality on the primary key (measured; see the reproducer +// section of docs/operations/duckdb-recovery.md). The pair is therefore worth +// only what the difference between the two plans is worth, so that difference +// is asserted rather than assumed. +func assertPushdownProbesAgree(t *testing.T, db *DB) { t.Helper() ro := db.ReadOnly() for u := 0; u < reproUsers; u++ { want := fmt.Sprintf("user-%d", u) - var indexed, scanned int - if err := ro.QueryRow("SELECT count(*) FROM spans WHERE user_id = ?", want).Scan(&indexed); err != nil { - t.Fatalf("indexed probe %s: %v", want, err) + bare := fmt.Sprintf("SELECT count(*) FROM spans WHERE user_id = '%s'", want) + wrapped := fmt.Sprintf("SELECT count(*) FROM spans WHERE user_id || '' = '%s'", want) + + if u == 0 { + // One pair of plans per restart is enough to show the two probes + // still take different paths through the scan. + filter := fmt.Sprintf("user_id='%s'", want) + if plan := queryPlan(t, ro, bare); !strings.Contains(plan, filter) { + t.Fatalf("%s is no longer pushed into the scan, so it tests the same path as the "+ + "control probe and the pair has nothing left to disagree about; plan: %s", bare, plan) + } + if plan := queryPlan(t, ro, wrapped); strings.Contains(plan, filter) { + t.Fatalf("the control probe %s is now pushed down as a bare equality; plan: %s", wrapped, plan) + } } - if err := ro.QueryRow("SELECT count(*) FROM spans WHERE user_id || '' = ?", want).Scan(&scanned); err != nil { - t.Fatalf("unindexed probe %s: %v", want, err) + + var pushed, scanned int + if err := ro.QueryRow(bare).Scan(&pushed); err != nil { + t.Fatalf("pushdown probe %s: %v", want, err) } - if indexed != scanned { - t.Fatalf("REPRODUCED: user_id = %q matched %d rows through the index, %d by scan", want, indexed, scanned) + if err := ro.QueryRow(wrapped).Scan(&scanned); err != nil { + t.Fatalf("control probe %s: %v", want, err) } - if indexed == 0 { + if pushed != scanned { + t.Fatalf("REPRODUCED: user_id = %q matched %d rows as a pushed-down filter, %d as an expression", want, pushed, scanned) + } + if pushed == 0 { t.Fatalf("probe %s matched nothing by either path; the fixture built no entries for it", want) } } } +// assertPrimaryKeyIndexAnswers exercises the one path on this engine that +// provably traverses an ART index: unique-constraint enforcement. An index that +// has lost entries accepts a span_id that is already stored; one that has gained +// phantom entries rejects a span_id that is not. Neither shows up in a count, a +// checkpoint or an open. +func assertPrimaryKeyIndexAnswers(t *testing.T, db *DB) { + t.Helper() + var stored string + if err := db.ReadOnly().QueryRow("SELECT span_id FROM spans LIMIT 1").Scan(&stored); err != nil { + t.Fatalf("read a stored span_id: %v", err) + } + const insert = `INSERT INTO spans (trace_id, span_id, name, start_time, end_time) + VALUES ('pk-probe', ?, 'pk.probe', now(), now())` + + _, err := db.rw.Exec(insert, stored) + if err == nil { + t.Fatalf("REPRODUCED: re-inserting the stored span_id %q was accepted; the primary key's "+ + "ART index no longer holds its own entries", stored) + } + if !strings.Contains(err.Error(), "Constraint Error") { + t.Fatalf("re-inserting span_id %q failed for some other reason, so the probe proved nothing: %v", stored, err) + } + + fresh := "pk-probe-" + strconv.FormatInt(time.Now().UnixNano(), 10) + if _, err := db.rw.Exec(insert, fresh); err != nil { + t.Fatalf("REPRODUCED: inserting the unused span_id %q was rejected: %v", fresh, err) + } + res, err := db.rw.Exec("DELETE FROM spans WHERE span_id = ?", fresh) + if err != nil { + t.Fatalf("delete probe row %q: %v", fresh, err) + } + if n, err := res.RowsAffected(); err != nil || n != 1 { + t.Fatalf("deleting probe row %q removed %d rows (err %v), want 1", fresh, n, err) + } +} + +// queryPlan returns the physical plan with its box drawing and whitespace +// removed, so a predicate that the renderer wrapped across lines is still one +// substring. +func queryPlan(t *testing.T, ro *ReadDB, query string) string { + t.Helper() + rows, err := ro.Query("EXPLAIN " + query) + if err != nil { + t.Fatalf("explain %s: %v", query, err) + } + defer rows.Close() + var plan strings.Builder + for rows.Next() { + var kind, body string + if err := rows.Scan(&kind, &body); err != nil { + t.Fatalf("scan plan: %v", err) + } + plan.WriteString(body) + } + if err := rows.Err(); err != nil { + t.Fatalf("iterate plan: %v", err) + } + return strings.Map(func(r rune) rune { + if r == ' ' || r == '\n' || (r >= 0x2500 && r <= 0x257f) { + return -1 + } + return r + }, plan.String()) +} + +// requireNoWAL fails when a fold left log entries behind. An empty file is +// allowed: an engine that truncates the WAL rather than unlinking it has folded +// everything, and failing on the inode alone would report the next such engine +// as a reproduction of this defect on the very assertion that guards the fold. func requireNoWAL(t *testing.T, path, when string) { t.Helper() info, err := os.Stat(path + ".wal") if err == nil { + if info.Size() == 0 { + t.Logf("%s: %s is present but empty, so the fold is complete", when, path+".wal") + return + } t.Fatalf("%s: %s is still present (%d bytes); the checkpoint did not fold", when, path+".wal", info.Size()) } if !os.IsNotExist(err) {