Skip to content

Commit 7ce038e

Browse files
pmaxhoganclaude
andauthored
test(chaos): deterministically gate the #144 create-orphan race in the append-only-log soak (#192)
## TL;DR - the orphan race is already fixed; what was missing is a gate that proves it The brief asked for a `fix(core)` closing the #144 create-orphan race behind the `append-only-log` chaos flake. I reproduced the race, then established that **PR #146 (merged 2026-07-24) already closed it**. The stale piece was the scenario itself: it only hit the racy code path by luck, so it neither caught the bug reliably before the fix nor proves the fix now. This PR makes it deterministic. **No core behaviour changes** - hence `test(chaos):`, not `fix(core):`. ## What the race is The first upload of `app.log` is a plain CREATE (no `drive_file_id` yet). An append that lands between the hash and the SPEC s8 post-upload `fstat` makes the executor settle it as changed-after-upload. Pre-#146 that left a LIVE object with no `file_state` row, adoptable only by the startup-gated reconcile pass, so the next mid-session scan planned a SECOND create. The scenario's "after reconcile, expected exactly 1 log object, found N" assertion is exactly that duplicate showing up. Since #146 the executor instead commits a force-rescan `file_state` row pointing at the just-created object and drops the op in one transaction (`settle_post_upload_change` -> `commit_create_result`), so the next scan UPDATEs that object. One object, no restart needed. ## Evidence (M4 Mac, debug build, 4-6 way parallel, `driven-chaos scenario run append-only-log`) I gated the #146 settle behind a temporary env switch to get a true negative control, then removed it. | build | injected remote delay | runs | pass | duplicate-object failures | |---|---|---|---|---| | main (with #146) | none | 690 | 690 | **0** | | main (with #146) | 3 ms | 240 | 240 | **0** | | main (with #146) | 10 ms | 20 | 20 | **0** | | #146 settle reverted | none | 200 | 194 | **6** (3.0%) | | #146 settle reverted | 3 ms | 20 | 0 | **20** (100%, 2-14 objects each) | Two things fall out of that table: 1. The historical ~5-10% flake is reproduced at 3% on this host with the fix reverted, and is gone with the fix in - so the flake really was #144, and #146 really closed it. 2. Without an injected delay the scenario reaches the racy code path only occasionally. A green run therefore did **not** mean the create-orphan path was tested; it usually meant the window never opened. That is the actual remaining defect. ## The change - `AppendOnlyLog` now boots over `InMemoryRemoteStore::with_slow_responses(3 ms)` (`CREATE_RACE_DELAY`), deliberately under the 4 ms `MUTATE_EVERY` mutation cadence, so at least one append lands inside the create's upload window on every run. This is the same widening technique the `mid-upload-*` rows already use with `SLOW_REMOTE`. - Refreshed the two stale comment blocks that still described the pre-#146 world ("leaves an orphan ... which is accepted behaviour"). The reconcile + drain step stays - it now stands in for the app restart that backstops the arms #146 deliberately left to reconcile (crash between upload and settle, versioned create, ambiguous `DeferToReconcile`) rather than papering over a routine duplicate. Cost: +246 ms of wall clock per run of one scenario on the Windows CI runner (measured below). ## Verification on windows-latest (the platform the flake was reported on) The measurements above are from macOS, so here is the CI run of this branch's `chaos hermetic (windows-latest)` job: - `append-only-log`: **pass**, `duration_ms: 523`. Baseline for the same scenario on the same runner image, from an unmodified branch (#193's run): `duration_ms: 277`. So the real cost of forcing the window open is **+246 ms** on the 2-core Windows runner, not the ~150 ms I estimated from the Mac. - Whole suite: **75 PASS / 10 SKIP / 0 FAIL / 0 FLAKY**, so widening this row's window does not destabilise the drain cap or any sibling row. - `chaos fake-drive (windows-latest)` also green (this row is hermetic-only, but the sibling `mutator-fs-append-only-log` runs there: pass, unchanged). ## Verification on macOS - `driven-chaos scenario run append-only-log` x **300 consecutive runs: 300 pass, 0 fail** with this change applied. - `driven-chaos run-all --hermetic`: 54 PASS / 31 SKIP / 0 FAIL / 0 FLAKY. - `driven-chaos run-all --fault-injection`: 25 PASS / 2 SKIP / 0 FAIL / 0 FLAKY. - `SQLX_OFFLINE=true cargo test --workspace`: green. - `cargo clippy --workspace --all-targets -- -D warnings`: clean. - `cargo fmt --all -- --check`: clean. ## Follow-up worth knowing The `driven-append-only-log-chaos-flake` triage note ("re-run the Chaos job, it clears ~85-90% of the time") predates #146 and is now wrong: a duplicate-object failure on this row should be treated as a **real regression**, not a re-run. Co-authored-by: Claude Fable 5 <noreply@anthropic.com>
1 parent 19982cd commit 7ce038e

1 file changed

Lines changed: 58 additions & 12 deletions

File tree

crates/driven-chaos/src/scenarios/mutation.rs

Lines changed: 58 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -100,6 +100,14 @@ const MUTATE_EVERY: Duration = Duration::from_millis(4);
100100
/// jitter, short enough that the scenario stays fast.
101101
const SLOW_REMOTE: Duration = Duration::from_millis(120);
102102

103+
/// Remote per-request delay used by the `append-only-log` soak to hold the
104+
/// FIRST upload's hash -> upload -> post-upload-`fstat` window open past the
105+
/// mutator's [`MUTATE_EVERY`] cadence, so the issue #144 create-during-upload
106+
/// path is exercised on EVERY run rather than occasionally by luck. Deliberately
107+
/// under `MUTATE_EVERY` so at least one append lands inside the window while the
108+
/// soak still runs its 24 cycles in a fraction of a second.
109+
const CREATE_RACE_DELAY: Duration = Duration::from_millis(3);
110+
103111
// ---------------------------------------------------------------------------
104112
// Shared per-scenario harness
105113
// ---------------------------------------------------------------------------
@@ -959,7 +967,38 @@ impl Scenario for AppendOnlyLog {
959967
}
960968

961969
async fn run_assertions(&self, _handle: &DrivenHandle) -> anyhow::Result<Outcome> {
962-
let h = SoakHarness::boot(Arc::new(InMemoryRemoteStore::new())).await?;
970+
// The property this row actually gates is the issue #144 create-orphan
971+
// race: the FIRST upload of `app.log` is a plain CREATE (no
972+
// `drive_file_id` yet), and an append that lands between the hash and
973+
// the SPEC s8 post-upload `fstat` makes the executor settle it as a
974+
// changed-after-upload. Before #146 that stranded a LIVE object with no
975+
// `file_state` row, so the next scan planned a SECOND create and the
976+
// post-reconcile "exactly 1 object" assertion below found 2+.
977+
//
978+
// Left to incidental timing that window opens only occasionally, which
979+
// is exactly why this row was a ~5-10% flake instead of a gate (it
980+
// failed when the race happened to fire more than once, and passed -
981+
// testing nothing - when it never fired at all). An instant in-memory
982+
// remote makes the hash->upload->recheck window shorter than the 4 ms
983+
// mutation cadence on a fast host, so most runs never reach the code
984+
// under test.
985+
//
986+
// So widen the window deliberately, the same way the `mid-upload-*`
987+
// rows do: a per-request remote delay slightly under `MUTATE_EVERY`
988+
// guarantees at least one append lands inside the create's upload
989+
// window on every run. Measured on an M4 Mac, 4-6 way parallel:
990+
//
991+
// - with the #146 settle commit REVERTED: 0/20 pass at this delay
992+
// (2-14 duplicate objects each) vs 194/200 pass with no delay -
993+
// i.e. the delay converts a 3% flake into a 100% catch.
994+
// - with #146 in place: 260/260 pass at 3-10 ms, 690/690 with no
995+
// delay.
996+
//
997+
// The delay costs ~150 ms of wall clock per run.
998+
let h = SoakHarness::boot(Arc::new(
999+
InMemoryRemoteStore::new().with_slow_responses(CREATE_RACE_DELAY),
1000+
))
1001+
.await?;
9631002
write_file(&h.src_root, "app.log", b"start\n")?;
9641003

9651004
let target = h.src_root.join("app.log");
@@ -977,17 +1016,24 @@ impl Scenario for AppendOnlyLog {
9771016
mutator.stop_and_join();
9781017
drain_to_steady_state(&h).await?;
9791018

980-
// #69: under load the first upload (a CREATE, no drive_file_id yet) can
981-
// race a concurrent append and land as a changed-after-upload. By DESIGN
982-
// s5.6 that leaves BOTH (a) an orphan remote object and (b) a surviving
983-
// create op, reclaimed only by the adopt-by-op-uuid reconcile pass - which
984-
// is startup-gated (`reconcile_once` runs once per process). So mid-session
985-
// a duplicate object + an overdue create op can persist until the next
986-
// restart, which is accepted behaviour. Simulate that restart here: run
987-
// the reconcile pass, then drain - exactly what the next launch does - so
988-
// the strict invariants below assert the engine's REAL post-restart
989-
// contract (one object, no data loss, no overdue op) and still fail loudly
990-
// if a restart does NOT converge.
1019+
// #69/#144: under load the first upload (a CREATE, no drive_file_id yet)
1020+
// races the concurrent append and lands as a changed-after-upload. Since
1021+
// #146 the executor settles that in place - it durably commits a
1022+
// force-rescan `file_state` row pointing at the just-created object and
1023+
// drops the op in one transaction - so the next scan UPDATEs that same
1024+
// object and NO duplicate is ever created mid-session. Before #146 it
1025+
// instead stranded a live orphan with no row, and the only thing that
1026+
// adopted it was the startup-gated reconcile pass (`reconcile_once` runs
1027+
// once per process), so a mid-session scan re-created the path.
1028+
//
1029+
// The reconcile + drain below therefore no longer papers over a routine
1030+
// duplicate; it stands in for the app RESTART that still backstops the
1031+
// arms #146 deliberately left to reconcile (a crash between the upload
1032+
// and the settle commit, a versioned create, an ambiguous
1033+
// `DeferToReconcile`). Running it here means the strict invariants that
1034+
// follow assert the engine's REAL post-restart contract (one object, no
1035+
// data loss, no overdue op) and fail loudly if a restart does NOT
1036+
// converge.
9911037
{
9921038
let clock = Arc::new(FakeClock::new());
9931039
let pacer: Arc<dyn driven_core::pacer::Pacer> = Arc::new(NoopPacer);

0 commit comments

Comments
 (0)