Flaky: salvage returns SQLITE_IOERR_SHORT_READ when the fixture pool is not closed #422

New Issue

2026-08-15T01:05:55Z

KofTwentyTwo commented

2026-08-15 01:05:55 +00:00

(Migrated from github.com)

Symptom

recovery::tests::test_stage_2_backup_creation_and_stage_3_table_salvage failed once in CI
at .expect("salvage succeeds") — SqliteRecoveryEngine::salvage returned Err.

Recovered from the CI log (run
31854987472 predecessor 31382964981,
2026-08-10, ubuntu-latest):

thread 'recovery::tests::test_stage_2_backup_creation_and_stage_3_table_salvage' panicked at
crates/nuncio-store/src/recovery.rs:701:14:
salvage succeeds: Query(Database(SqliteError { code: 522, message: "disk I/O error" }))

522 is SQLITE_IOERR_SHORT_READ (10 | 2<<8). The Query variant places it inside
DatabaseEngine::connect_file → migrate(), i.e. step 4 of salvage.

Root cause

The fixture built its engine inside a bare block and let it drop rather than calling
close():

{
    let engine = DatabaseEngine::connect_file(&db_path, &secrets).await.unwrap();
    engine.save_account(&acct).await.unwrap();
    engine.save_filter_rule(&rule).await.unwrap();
}   // <- dropped, never closed
let summary = SqliteRecoveryEngine::salvage(&db_path, &db_path, &backup_dir, &secrets).await...

Dropping an sqlx::Pool does not close its connections synchronously — teardown is spawned
onto the runtime. Salvage then unlinks target_db_path and its -wal/-shm companions
(step 3) and creates a brand-new database at that same path (step 4). SQLite's close-time WAL
handling operates on -wal/-shm by path, so the deferred teardown can land after the
unlink and interact with the new database's companions — leaving the fresh, empty main file
paired with a -wal that describes the old one. Replaying that WAL reads past end-of-file →
SQLITE_IOERR_SHORT_READ.

Note the test passes &db_path as both source and target, so source and target are the same
file — there is no separation to absorb the race.

Why this is a fixture defect, not a production defect

The production caller already does the right thing. DatabaseEngine::close_and_salvage:

engine.close().await;                                   // awaits every connection's teardown
tokio::time::sleep(Duration::from_millis(50)).await;    // settle
let summary = SqliteRecoveryEngine::salvage(path, path, backup_dir, secrets).await?;

and the other branch of open_with_backup_dir that reaches salvage never had a pool at all
(connect_file returned Err). The sibling test
test_database_header_corruption_stage_1_detection also already calls engine.close().await.
This test was the sole caller violating the contract.

DatabaseEngine::close()'s own doc comment already describes this exact hazard class
("...that teardown is not guaranteed to complete synchronously within this call on every
platform, and can instead complete moments later on a background thread — which then races any
code that inspects or replaces the main database file shortly after close() returns").

Fix

close() awaits pool.close(), so the window ceases to exist rather than merely narrowing —
no sleep and no retry were added.

Test: engine.close().await before the fixture block ends.
SqliteRecoveryEngine::salvage: documented the precondition (caller must have fully closed
any engine holding target_db_path) so the next caller does not repeat it.

PR: #PLACEHOLDER

Ruled out during investigation

Not reproducible on macOS/APFS. ~800 local attempts, all clean: 300 sequential in-process
fixture iterations; 480 iterations across 8 concurrent tasks on a 4-worker multi-thread
runtime; 15 iterations with a 4 MB WAL to stretch the close-time checkpoint across
connect_file; and a hand-built deterministic probe that unlinks the db + -wal + -shm,
opens a fresh engine at the same path, then drops the old engine mid-migrate. CI is
ubuntu-latest; the unix VFS timing differs, which is consistent with this reproducing there
and not here.
Not the tracing callsite-Interest race that caused the other failures that day — that
manifests as empty/partial log capture, and this test asserts nothing about logs.
Not backup-path collision or tempdir reuse. backup_dir is a fresh per-test tempdir, so
the 1-second-granularity nuncio_corrupted_{secs}.db filename cannot collide across tests.
Not key provisioning. MockKeyring stores into a per-instance Arc<Mutex<HashMap>>, so
DatabaseError::KeyProvisioning is unreachable here and there is no cross-test interference
through the vault.
Not the backup-copy path. Only three ? sites exist in salvage; the two inside
backup_corrupted_db_to (create_dir_all, fs::copy) produce
RecoveryFailed, not the observed Query. Every read in steps 2–3 swallows its error
(unwrap_or_default / is_ok()), so it cannot return Err at all.

Residual risk

The Query error variant genuinely only reaches the caller from connect_file's migrate().
With the precondition now honoured by every caller, no known path leaves a live pool on
target_db_path. If this recurs after this change, the next candidate is a genuine
environmental I/O fault on the runner (disk pressure in TMPDIR) rather than a lifecycle
race — and the .expect already surfaces the concrete DatabaseError variant and SQLite
extended code, which is how this was diagnosed.

## Symptom `recovery::tests::test_stage_2_backup_creation_and_stage_3_table_salvage` failed once in CI at `.expect("salvage succeeds")` — `SqliteRecoveryEngine::salvage` returned `Err`. Recovered from the CI log (run [31854987472 predecessor `31382964981`](https://github.com/KofTwentyTwo/nuncio/actions/runs/31382964981), 2026-08-10, `ubuntu-latest`): ``` thread 'recovery::tests::test_stage_2_backup_creation_and_stage_3_table_salvage' panicked at crates/nuncio-store/src/recovery.rs:701:14: salvage succeeds: Query(Database(SqliteError { code: 522, message: "disk I/O error" })) ``` `522` is `SQLITE_IOERR_SHORT_READ` (`10 | 2<<8`). The `Query` variant places it inside `DatabaseEngine::connect_file` → `migrate()`, i.e. step 4 of salvage. ## Root cause The fixture built its engine inside a bare block and let it **drop** rather than calling `close()`: ```rust { let engine = DatabaseEngine::connect_file(&db_path, &secrets).await.unwrap(); engine.save_account(&acct).await.unwrap(); engine.save_filter_rule(&rule).await.unwrap(); } // <- dropped, never closed let summary = SqliteRecoveryEngine::salvage(&db_path, &db_path, &backup_dir, &secrets).await... ``` Dropping an `sqlx::Pool` does **not** close its connections synchronously — teardown is spawned onto the runtime. Salvage then unlinks `target_db_path` and its `-wal`/`-shm` companions (step 3) and creates a brand-new database at that same path (step 4). SQLite's close-time WAL handling operates on `-wal`/`-shm` **by path**, so the deferred teardown can land after the unlink and interact with the *new* database's companions — leaving the fresh, empty main file paired with a `-wal` that describes the old one. Replaying that WAL reads past end-of-file → `SQLITE_IOERR_SHORT_READ`. Note the test passes `&db_path` as *both* source and target, so source and target are the same file — there is no separation to absorb the race. ## Why this is a fixture defect, not a production defect The production caller already does the right thing. `DatabaseEngine::close_and_salvage`: ```rust engine.close().await; // awaits every connection's teardown tokio::time::sleep(Duration::from_millis(50)).await; // settle let summary = SqliteRecoveryEngine::salvage(path, path, backup_dir, secrets).await?; ``` and the other branch of `open_with_backup_dir` that reaches `salvage` never had a pool at all (`connect_file` returned `Err`). The sibling test `test_database_header_corruption_stage_1_detection` also already calls `engine.close().await`. This test was the sole caller violating the contract. `DatabaseEngine::close()`'s own doc comment already describes this exact hazard class ("...that teardown is not guaranteed to complete synchronously within this call on every platform, and can instead complete moments later on a background thread — which then races any code that inspects or replaces the main database file shortly after `close()` returns"). ## Fix `close()` awaits `pool.close()`, so the window ceases to exist rather than merely narrowing — no sleep and no retry were added. - Test: `engine.close().await` before the fixture block ends. - `SqliteRecoveryEngine::salvage`: documented the precondition (caller must have fully closed any engine holding `target_db_path`) so the next caller does not repeat it. PR: #PLACEHOLDER ## Ruled out during investigation - **Not reproducible on macOS/APFS.** ~800 local attempts, all clean: 300 sequential in-process fixture iterations; 480 iterations across 8 concurrent tasks on a 4-worker multi-thread runtime; 15 iterations with a 4 MB WAL to stretch the close-time checkpoint across `connect_file`; and a hand-built deterministic probe that unlinks the db + `-wal` + `-shm`, opens a fresh engine at the same path, then drops the old engine mid-migrate. CI is `ubuntu-latest`; the unix VFS timing differs, which is consistent with this reproducing there and not here. - **Not the `tracing` callsite-`Interest` race** that caused the other failures that day — that manifests as empty/partial log capture, and this test asserts nothing about logs. - **Not backup-path collision or tempdir reuse.** `backup_dir` is a fresh per-test tempdir, so the 1-second-granularity `nuncio_corrupted_{secs}.db` filename cannot collide across tests. - **Not key provisioning.** `MockKeyring` stores into a per-instance `Arc<Mutex<HashMap>>`, so `DatabaseError::KeyProvisioning` is unreachable here and there is no cross-test interference through the vault. - **Not the backup-copy path.** Only three `?` sites exist in `salvage`; the two inside `backup_corrupted_db_to` (`create_dir_all`, `fs::copy`) produce `RecoveryFailed`, not the observed `Query`. Every read in steps 2–3 swallows its error (`unwrap_or_default` / `is_ok()`), so it cannot return `Err` at all. ## Residual risk The `Query` error variant genuinely only reaches the caller from `connect_file`'s `migrate()`. With the precondition now honoured by every caller, no known path leaves a live pool on `target_db_path`. If this recurs *after* this change, the next candidate is a genuine environmental I/O fault on the runner (disk pressure in `TMPDIR`) rather than a lifecycle race — and the `.expect` already surfaces the concrete `DatabaseError` variant and SQLite extended code, which is how this was diagnosed.

KofTwentyTwo commented

2026-08-15 01:06:18 +00:00

(Migrated from github.com)

PR: #423

KofTwentyTwo commented

2026-08-15 01:14:16 +00:00

(Migrated from github.com)

Root-caused and fixed in #423 (9daec8a), merged to dev.

The CI log had the answer all along — the .expect printed the variant: Query(Database(SqliteError { code: 522, message: "disk I/O error" })). 522 is SQLITE_IOERR_SHORT_READ, and Query places it in connect_file -> migrate().

The fixture dropped its engine instead of calling close().await. A dropped sqlx::Pool tears connections down asynchronously; salvage then unlinks db/-wal/-shm and recreates at the same path, so the deferred teardown lands after the unlink and pairs a fresh empty main file with a -wal describing the old one. Replay reads past EOF.

Fixture defect, not production: close_and_salvage already closes, and the sibling stage-1 test already did. The fix awaits teardown rather than narrowing the window — no sleep, no retry, no weakened assertion.

Honest caveat: there is no regression test that fails without the fix. The race is OS-timing dependent (never reproduced across ~800 local attempts on macOS/APFS; CI is ubuntu-latest) and a probabilistic regression test would be worse than none. If it ever recurs, the remaining candidate is a genuine environmental I/O fault on the runner.

Root-caused and fixed in #423 (`9daec8a`), merged to `dev`. The CI log had the answer all along — the `.expect` printed the variant: `Query(Database(SqliteError { code: 522, message: "disk I/O error" }))`. 522 is `SQLITE_IOERR_SHORT_READ`, and `Query` places it in `connect_file` -> `migrate()`. The fixture **dropped** its engine instead of calling `close().await`. A dropped `sqlx::Pool` tears connections down asynchronously; salvage then unlinks `db`/`-wal`/`-shm` and recreates at the same path, so the deferred teardown lands after the unlink and pairs a fresh empty main file with a `-wal` describing the old one. Replay reads past EOF. Fixture defect, not production: `close_and_salvage` already closes, and the sibling stage-1 test already did. The fix **awaits** teardown rather than narrowing the window — no sleep, no retry, no weakened assertion. **Honest caveat:** there is no regression test that fails without the fix. The race is OS-timing dependent (never reproduced across ~800 local attempts on macOS/APFS; CI is ubuntu-latest) and a probabilistic regression test would be worse than none. If it ever recurs, the remaining candidate is a genuine environmental I/O fault on the runner.

Sign in to join this conversation.

1 Participants

Notifications

Due Date

No due date set.

Dependencies

No dependencies set.

Reference: KofTwentyTwo/nuncio#422