fix(#796): pin the download-phase clock in tests instead of racing wall time - #808
Conversation
…ll time Closes #796. `asset_sync::download_rate_tests::elapsed_does_not_carry_over_from_a_slow_prior_download` flaked under remote-builder contention. It proved the "elapsed is scoped to the CURRENT download phase, not carried over from a prior one" property (#708) by sleeping real wall time (150ms x2) and then asserting the phase's own `elapsed` stayed under a soft 100ms bound — so the assertion was really a bet on how long the download loop's OWN real work took on a given run, not a property of the code. Under load that bet lost with nothing wrong in the code under test. Same shape as #760/245de07: inject the clock instead of widening the tolerance. `fetch_and_reassemble` now takes an explicit `DownloadClock` (a private newtype over `Option<Instant>`, `WALL` for production, `frozen_at` gated `#[cfg(test)]`) and reads `clock.now()` instead of `Instant::now()`/`.elapsed()`. `sync_set` and `sync_changed_manifest` thread the same clock down through `sync_set_with_clock`/`sync_changed_manifest_with_clock`/ `fetch_and_reassemble_with_clock`; their original names stay as thin wrappers that pass `DownloadClock::WALL`, so every production call site and the other ~20 test call sites of `sync_set` are unchanged. `WALL.now()` is exactly `Instant::now()` — production behaviour is byte-for-byte unchanged. The rewritten test never sleeps. It pins the first sync's clock 10s ahead of an arbitrary reference instant (simulating "slow prior work") and the second sync's clock a further 5s ahead (simulating "more time passing between syncs"). Because a pinned clock's `now()` always returns the same instant, a correctly phase-scoped `start = clock.now()` makes every `elapsed` in that call EXACTLY `Duration::ZERO` regardless of how fast or slow the machine actually runs the loop body — the assertions are `assert_eq!(_, Duration::ZERO)`, not a soft bound. The property under test is what the assertion now measures, not machine speed. Confirmed structurally: the fixed test target reports "finished in 0.00s" for a 6-test module including this one. Mutation-checked both directions. Reverted the fix by wrapping `start` in a `OnceLock` (`get_or_init(|| clock.now())`), reproducing the historical leaked/global-clock bug: the first call still passes (its own `get_or_init` sets the value), but the second call's `elapsed` becomes `second_pin - slow_prior_pin` = the simulated 5s gap, not zero. left: 5s right: 0ns Deterministic — not a flake, not machine load, the same 5s every run, because the bug and the check are both expressed against the injected clock. Reverted the mutation; target module is green again (6 passed; 0 failed). Full workspace: 53 `running N tests` headers = 53 `test result:` lines (a lost binary still emits its header, so the equality is the check), 1755 passed + 0 failed + 47 ignored + 0 filtered = 1802 = the header sum, 15 all-zero targets, 0 FAILED lines, 0 `failures:` blocks, 0 non-canonical result lines, 0 warnings. Matches origin/main's f71ef16 baseline of 1755/0/47/0=1802, 53=53, 15 exactly — this change adds no test, removes none, and changes no other test's count. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01HQVEpaaKeXsZcW9VT2roeV
Independent review — PR #808 (issue #796)Reviewed the MERGE of Verdict: APPROVE WITH NON-BLOCKING FINDINGSThe flake fix itself is sound: the rewritten test faithfully reproduces the #708/#796 property with a pinned clock, is mutation-discriminating in both directions (verified independently, not just re-derived from the PR body), and production behaviour really is unchanged. One real coverage gap found — see Finding 1 — but it does not reflect a defect in what's shipping today, so it's non-blocking. Finding 1 (most significant, NON-BLOCKING): the new test no longer exercises
|
…aim actually true The type doc claimed a pinned DownloadClock "cannot reach a real sync" because its field is "private to this module" — but that module was all of asset_sync.rs, so every production function in the file (sync_set included) could already construct DownloadClock(Some(t)) directly, bypassing the #[cfg(test)]-gated frozen_at entirely. Verified directly: pointing sync_set at a pinned clock instead of WALL compiled clean and the whole --lib suite still passed (210 passed / 0 failed) — the exact silent-wrong-elapsed defect the type exists to prevent. Move DownloadClock into a private `download_clock` submodule so the field is private to THAT module instead of to all of asset_sync.rs. Outside the submodule the only ways to name a DownloadClock are WALL and the cfg(test) frozen_at, so in a non-test build WALL is the only constructible value. Reproduced the same mutation against the new code: it now fails to compile with E0423 (cannot initialize a tuple struct which contains private fields). Updated the type doc to state this and cite the verified error instead of the old unenforced reasoning. No behavior change: now() is unchanged, frozen_at is unchanged, the existing elapsed_does_not_carry_over_from_a_slow_prior_download test (which exercises frozen_at) still passes unmodified. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01HQVEpaaKeXsZcW9VT2roeV
Round 2: made the
|
Independent re-review — PR #808, round 2 (
|
Claim (doc, src/asset_sync.rs:199-221) |
Discharged by |
|---|---|
"Production always uses DownloadClock::WALL" |
Only one production call site (:467), sole caller of sync_set_with_clock; both downstream _with_clock fns only forward the clock they're given, never construct a new one (re-verified this round, unchanged from round 1) |
"WALL.now() is Instant::now()" |
git diff — now() body untouched |
"nothing actually stopped sync_set... from writing DownloadClock(Some(t)) directly" (round-1 state) |
This is a claim about the OLD code, matches my round-1 mutation exactly |
"outside this submodule the only ways to name a DownloadClock are WALL and... frozen_at" |
Probes A, B, C + structural read of the submodule body — no fourth route found |
"in a non-test build WALL is the only constructible value" |
Probe B (frozen_at doesn't exist without cfg(test)) |
"the compiler rejects the mutation above... E0423" |
Probe A, verbatim |
No unverified "cannot"/"always"/"only" remains in the doc.
3. now() byte-identical — checked, not trusted
Confirmed directly in the 42ebd0f..151f8df diff (single hunk): the only change to now() is prepending pub(super) to its signature; the body self.0.unwrap_or_else(std::time::Instant::now) is untouched.
4. Figures reconciliation — verified the attribution, not just accepted it
Checked git diff b45e62d~1..b45e62d (the round-1 baseline's tip): exactly 2 added #[test] fns (both plain, no #[should_panic] to hide from a name-grep), 0 removed — matches the round-2 author's "1755 on the bare branch, 1757 on my b45e62d-merged baseline" attribution exactly.
Then went further, per the instruction to re-measure against current origin/main (now 7159140, #802 merged): git diff b45e62d..origin/main shows 11 added #[test] fns, 0 #[should_panic], 0 removed, confined to region_map.rs/collision.rs/water_grid.rs/walker_sim.rs (all pre-existing files, no new test binary/target created).
Base measured on this round: fix-796-wallclock-flake@151f8df merged with origin/main@7159140 (merge commit built and run in full).
Full-workspace test --workspace --locked --no-fail-fast, ~27m22s, Finished present, exit 0:
| Figure | Round-1 baseline (b45e62d) |
This round (151f8df+7159140) |
Delta |
|---|---|---|---|
| passed | 1757 | 1768 | +11 |
| failed | 0 | 0 | 0 |
| ignored | 47 | 47 | 0 |
| filtered | 0 | 0 | 0 |
| total | 1804 | 1815 | +11 |
running N tests headers |
53 | 53 | 0 |
test result: lines |
53 | 53 | 0 |
| non-canonical result lines | 0 | 0 | 0 |
all-zero-target (0/0/0/0/0) results |
15 | 15 | 0 |
FAILED / ^error/panicked/Killed hits |
0 | 0 | 0 |
The +11 passed is an exact match to the b45e62d..origin/main diff in §4 (11 added #[test] fns, 0 removed, 0 #[should_panic]) — nothing attributable to this PR's own diff, which adds/removes zero tests. Headers=results=53 both rounds confirms no new test target was created by either #802 or this PR. All-zero-target count unchanged at 15. Zero failures, zero error/panic/kill signals in either stream (stdout and stderr captured separately this round per the splice-artifact concern — no discrepancy between them).
5. Live-run exception — earned this round
Diffed 42ebd0f..151f8df in full: one hunk, confined to visibility modifiers (pub(super)) and a module wrapper, plus doc comments. No function body changed except now()'s signature (not its logic). Nothing runtime-observable moved — this is a pure compile-time encapsulation change on top of a round-1 change that already had no externally-reachable production entry point to E2E. The "nothing to E2E" exception is genuinely earned, not merely re-asserted.
What I did NOT check
- Did not re-run the round-1 mutation checks (leaked-
start-via-OnceLockRED, frozen-clock-via-sync_setGREEN) — round 2 doesn't touchfetch_and_reassemble_with_clock's body or the test, onlyDownloadClock's visibility, so those results stand unchanged from round 1. - No live/E2E run (see §5 for why).
Closes #796.
What changed and why
asset_sync::download_rate_tests::elapsed_does_not_carry_over_from_a_slow_prior_downloadproves the "elapsed is scoped to the CURRENT download phase, not carried over from a prior one" property (#708). It used to do that by sleeping real wall time (150ms before the first sync, 150ms between the two syncs) and then asserting the phase's ownelapsedstayed under a soft< 100msbound. That assertion was really a bet on how long the download loop's own real work took on this run — not a property of the code — and under remote-builder contention that bet lost with nothing wrong in the code under test.This is the same shape already fixed once in this repo for #760 (commit
245de07): inject/pin the clock instead of widening the tolerance or adding a retry.fetch_and_reassemblenow takes an explicitDownloadClock— a private newtype overOption<Instant>, with aWALLconstant for production and afrozen_atconstructor gated#[cfg(test)]— and readsclock.now()/clock.now().saturating_duration_since(start)instead ofInstant::now()/.elapsed().sync_setandsync_changed_manifestthread the same clock down through newsync_set_with_clock/sync_changed_manifest_with_clock/fetch_and_reassemble_with_clockinternals. The original function names (sync_set,sync_changed_manifest,fetch_and_reassemble... — the last of these had no other caller so it was folded away rather than kept as a dead wrapper) stay as the production entry points and always passDownloadClock::WALL, whosenow()is exactlyInstant::now(). Production behaviour is byte-for-byte unchanged, and every other test call site ofsync_set(~20 of them) is untouched.Mechanism (why this removes the wall-clock dependency structurally, not just usually)
The rewritten test never sleeps. It pins the first sync's clock 10s ahead of an arbitrary reference
Instant, simulating "slow prior work" with no real delay, and pins the second sync's clock a further 5s ahead, simulating "more time passing between syncs." Because a pinned clock'snow()always returns the exact same instant on every call, a correctly phase-scopedstart = clock.now()makes everyelapsedreported during that call exactlyDuration::ZERO— deterministically, independent of how fast or slow the machine actually executes the loop body between the twoclock.now()reads. The assertions changed fromassert!(elapsed < Duration::from_millis(100))toassert_eq!(elapsed, Duration::ZERO), which is only possible because the test now controls "now" instead of reading it from the OS.Confirmed this structurally, not just by re-running: the fixed test module (6 tests, including this one) reports
finished in 0.00s— there is no wall-clock delay left anywhere in the test to measure.Mutation-check, both directions
Fix in place → GREEN:
Bug reintroduced → RED: temporarily wrapped
startin aOnceLock(static ...: OnceLock<Instant>; let start = *ONCE.get_or_init(|| clock.now());), reproducing the historical leaked/global-clock bug this test is named for — astartthat isn't captured fresh on every call.The failing value (
5s) is exactly the simulated gap between the two pinned clocks, reproduced identically every run — a deterministic signal from the injected clock, not noise from machine load. The mutation was then reverted;git diffagainst the committed version is empty at that hunk.Full workspace test run
Finishedline:running [0-9]+ tests?headers: 53test result:lines: 53 (equal — the lost-binary check)test result:lines: 1755 passed + 0 failed + 47 ignored + 0 filtered = 1802, which equals the header-implied total0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out): 15FAILEDlines: 0failures:blocks: 0test result:lines (not startingtest result: ok.): 0This matches
origin/mainatf71ef16exactly (1755/0/47/0 = 1802, 53 = 53, 15 all-zero targets) — this PR adds no test, removes none, and changes no other test's pass/fail/ignore count. The only test whose body changed is the one this issue is about.NOT verified
fetch_and_reassemble/sync_set/sync_changed_manifestare all private tosrc/asset_sync.rs); there is no new externally-observable behavior to run a live client against. Per the agent-fleet skill's exception for dead-storage-shaped internals, the mutation-checked suite is the ceiling here, not live play.std::thread::sleep+ a< 100msbound racing realInstant::now()reads) and the issue's own report of one observed flake.