diff --git a/src/asset_sync.rs b/src/asset_sync.rs index bfe96d98..f0997978 100644 --- a/src/asset_sync.rs +++ b/src/asset_sync.rs @@ -196,14 +196,66 @@ fn artifacts_intact(cache: &CacheDirs, files: &[FileEntry]) -> bool { }) } +/// Where `fetch_and_reassemble`'s download-phase `elapsed` reads "now" from (#796). +/// +/// Production always uses [`DownloadClock::WALL`] — the real monotonic clock — and behaviour is +/// byte-for-byte unchanged from before this type existed: `WALL.now()` is `Instant::now()`. The +/// pinned variant exists only so a test can assert the "elapsed is scoped to THIS phase, not +/// carried over from a prior one" property (#708) EXACTLY, instead of proving it by sleeping real +/// wall time and asserting a soft upper bound on how long the actual download loop's own work took +/// — which is what made `elapsed_does_not_carry_over_from_a_slow_prior_download` fail under +/// remote-builder contention: the assertion raced the machine's load, not the code path it names. +/// +/// `DownloadClock` lives in its own private submodule (`download_clock`) rather than merely being +/// a private-field struct in this file. A private tuple field is visible everywhere IN THE MODULE +/// that declares it — and that module used to be all ~1300 lines of `asset_sync.rs`, including +/// every production function here, so nothing actually stopped `sync_set` (or any future call +/// site added to this file) from writing `DownloadClock(Some(t))` directly and silently zeroing +/// every real download's `elapsed`/rate. That was checked directly: pointing `sync_set` at a +/// pinned clock instead of `WALL` compiled clean and the whole `--lib` suite still passed. Scoping +/// the field to `download_clock` instead makes that unreachable rather than merely undone: outside +/// this submodule the only ways to name a `DownloadClock` are `WALL` and the `#[cfg(test)]`-gated +/// `frozen_at`, so in a non-test build `WALL` is the *only* constructible value — the compiler +/// rejects the mutation above (verified: `sync_set` calling `DownloadClock(Some(Instant::now()))` +/// fails with `E0423: cannot initialize a tuple struct which contains private fields`) instead of +/// accepting it. +mod download_clock { + /// `None` is the real wall clock ([`DownloadClock::WALL`]); `Some` is a pinned instant, only + /// ever constructible via the `#[cfg(test)]` [`DownloadClock::frozen_at`]. See the module doc + /// for why the field stays private to this submodule rather than to all of `asset_sync.rs`. + #[derive(Clone, Copy)] + pub(super) struct DownloadClock(Option); + + impl DownloadClock { + pub(super) const WALL: DownloadClock = DownloadClock(None); + + /// A clock pinned at `t` — test fixtures only. See the module doc for why this is gated. + #[cfg(test)] + pub(super) fn frozen_at(t: std::time::Instant) -> Self { + DownloadClock(Some(t)) + } + + pub(super) fn now(self) -> std::time::Instant { + self.0.unwrap_or_else(std::time::Instant::now) + } + } +} +use download_clock::DownloadClock; + /// Downloads whatever chunks in `files` aren't already in the CAS, then reassembles every file. /// Shared by both the normal (server digest Changed) sync path and the repair path taken when an /// unchanged digest's own artifacts turn out to be missing/corrupt (#601). -fn fetch_and_reassemble( +/// +/// Takes an explicit [`DownloadClock`] (#796) rather than reading `Instant::now()` directly, so a +/// test can pin what `elapsed` reads "now" as instead of racing the real clock against machine +/// load. Every production call site (both inside this file) passes [`DownloadClock::WALL`], which +/// is exactly `Instant::now()` — behaviour there is unchanged. +fn fetch_and_reassemble_with_clock( t: &dyn Transport, cache: &CacheDirs, files: &[FileEntry], progress: &mut dyn FnMut(SyncProgress), + clock: DownloadClock, ) -> anyhow::Result<()> { let missing = missing_chunks(files, cache); let total = missing.len(); @@ -214,7 +266,7 @@ fn fetch_and_reassemble( // is empty (every chunk already cached) this loop body never runs at all, so `progress` is never // called with `Downloading` — the caller sees no download tick, not a misleading "0 B/s" one // (#708 requirement 2: "nothing to download" must not render like a stall). - let start = std::time::Instant::now(); + let start = clock.now(); for (i, hash) in missing.iter().enumerate() { let data = t.get_chunk(hash)?; // The server is content-addressed: a chunk's bytes must hash to its id. @@ -224,7 +276,12 @@ fn fetch_and_reassemble( } cache.cas_put(&data)?; bytes += data.len() as u64; - progress(SyncProgress::Downloading { done: i + 1, total, bytes, elapsed: start.elapsed() }); + progress(SyncProgress::Downloading { + done: i + 1, + total, + bytes, + elapsed: clock.now().saturating_duration_since(start), + }); } for entry in files { reassemble(cache, entry)?; @@ -406,6 +463,19 @@ fn sync_set( set: &str, cache: &CacheDirs, progress: &mut dyn FnMut(SyncProgress), +) -> anyhow::Result<()> { + sync_set_with_clock(t, set, cache, progress, DownloadClock::WALL) +} + +/// The real body of `sync_set` — separated out so a test can supply a pinned [`DownloadClock`] +/// instead of racing the real one (#796). `sync_set` is the only production entry point (via +/// [`sync_set_observed`]) and always passes [`DownloadClock::WALL`]. +fn sync_set_with_clock( + t: &dyn Transport, + set: &str, + cache: &CacheDirs, + progress: &mut dyn FnMut(SyncProgress), + clock: DownloadClock, ) -> anyhow::Result<()> { let prev = cache.synced(set); // Only offer the server our digest when we also still have the file list it refers to — that @@ -447,7 +517,7 @@ fn sync_set( return Ok(()); // content AND local artifacts both unchanged — genuine no-op } progress(SyncProgress::Verifying); - if let Err(repair_err) = fetch_and_reassemble(t, cache, &files, progress) { + if let Err(repair_err) = fetch_and_reassemble_with_clock(t, cache, &files, progress, clock) { // The recorded chunk list can itself be stale even though the digest is not: the // digest (`set_digest`) hashes only `path\0`, never chunk ids, so a // server that re-chunks a file (different FastCDC params, a re-bake, ...) while @@ -458,7 +528,8 @@ fn sync_set( // than keep repairing with data the server can no longer serve. cache.clear_synced(set); return match t.get_manifest(set, None)? { - ManifestFetch::Changed(m) => sync_changed_manifest(t, set, cache, m, progress), + ManifestFetch::Changed(m) => + sync_changed_manifest_with_clock(t, set, cache, m, progress, clock), ManifestFetch::Unchanged => Err(repair_err.context(format!( "repair of set {set} failed, and a fresh (unconditional) manifest fetch \ still reports Unchanged — server cannot supply working chunk data" @@ -467,7 +538,7 @@ fn sync_set( } Ok(()) // digest/file-list unchanged from what's already recorded — nothing new to persist } - ManifestFetch::Changed(m) => sync_changed_manifest(t, set, cache, m, progress), + ManifestFetch::Changed(m) => sync_changed_manifest_with_clock(t, set, cache, m, progress, clock), } } @@ -558,12 +629,17 @@ pub fn login_observed( /// files, and records the new synced state. Shared by the normal (digest Changed) path and the /// repair-failure fallback above (#601 D-2), both of which end up with a manifest they need to /// fully (re)apply. -fn sync_changed_manifest( +/// +/// Takes an explicit [`DownloadClock`] (#796), forwarded to `fetch_and_reassemble_with_clock`; see +/// that function's doc. Both call sites (inside `sync_set_with_clock`) pass through whatever clock +/// they themselves were given, so a pinned test clock reaches all the way down. +fn sync_changed_manifest_with_clock( t: &dyn Transport, set: &str, cache: &CacheDirs, manifest: Manifest, progress: &mut dyn FnMut(SyncProgress), + clock: DownloadClock, ) -> anyhow::Result<()> { // Defense against a lying/corrupt server: the manifest must hash to its claimed digest. let recomputed = set_digest(&manifest.files); @@ -572,7 +648,7 @@ fn sync_changed_manifest( } progress(SyncProgress::Verifying); - fetch_and_reassemble(t, cache, &manifest.files, progress)?; + fetch_and_reassemble_with_clock(t, cache, &manifest.files, progress, clock)?; // Record the synced identity so a future unchanged fetch (304) can skip the whole set. cache.set_synced(set, &manifest.digest, &manifest.files); @@ -1226,9 +1302,21 @@ mod download_rate_tests { // instead of from the start of THIS call, a slow first sync would make a fast SECOND sync's // very first tick already look like it had been running for a long time — a stale-rate bug // by another name (the rate would be computed against the wrong clock, not just the wrong - // phase). Reproduce with two back-to-back sync_set calls against two different manifests - // (so the second one also has real work to do), inserting a real sleep before the first - // call begins so any global/leaked clock would show up as inflated elapsed on the second. + // phase). Reproduce with two back-to-back sync_set_with_clock calls against two different + // manifests (so the second one also has real work to do). + // + // #796: this used to reproduce "slow prior work" with a real `std::thread::sleep`, which + // meant the assertion afterward ("elapsed stays under a soft bound") was really a bet on how + // long the download loop's OWN real wall-clock work took on this run — and that bet lost + // under remote-builder contention with nothing wrong in the code under test. There is no + // sleep anywhere in this test now: "slow prior work" is simulated by pinning the FIRST + // sync's `DownloadClock` far ahead of an arbitrary reference instant, and "more time passing + // between syncs" by pinning the SECOND sync's clock further ahead still. Because each 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` — + // deterministically, independent of how fast or slow the machine actually runs the loop + // body. The property under test (fresh `start` per call) is what the assertion measures now, + // not machine speed. let dir = tempfile::tempdir().unwrap(); let cache = CacheDirs::with_root(dir.path()); @@ -1245,23 +1333,28 @@ mod download_rate_tests { chunks: chunks1, }; - std::thread::sleep(Duration::from_millis(150)); // simulate time passing before ANY sync runs + // Simulated: "10 seconds had already passed" before this sync starts — no real sleep, just + // a clock pinned 10s ahead of an arbitrary reference instant. + let reference = std::time::Instant::now(); + let slow_prior_pin = reference + Duration::from_secs(10); - let mut first_elapsed = Duration::ZERO; - sync_set(&t1, "s1", &cache, &mut |p| { + let mut first_elapsed = Duration::MAX; // deliberately not ZERO, so a missed tick still fails + sync_set_with_clock(&t1, "s1", &cache, &mut |p| { if let SyncProgress::Downloading { elapsed, .. } = p { first_elapsed = elapsed; } - }).unwrap(); - assert!(first_elapsed < Duration::from_millis(100), - "first sync's own elapsed should be small (just its own download loop), got {first_elapsed:?}"); - - // A SECOND sleep, between the two syncs, is the actual discriminator: if `start` were ever - // hoisted to something that persists across calls (a `static`/`OnceLock`, a field on some - // long-lived context) instead of being captured fresh inside THIS call to - // `fetch_and_reassemble`, this sleep would show up added into the second sync's `elapsed` - // even though the second sync's own download loop never ran during it. - std::thread::sleep(Duration::from_millis(150)); + }, DownloadClock::frozen_at(slow_prior_pin)).unwrap(); + assert_eq!(first_elapsed, Duration::ZERO, + "first sync's own elapsed must be EXACTLY zero against a clock pinned at a single \ + instant — got {first_elapsed:?}, which can only happen if `start` was read from a \ + DIFFERENT clock reading than the tick that reported it"); + + // Simulated: 5 MORE seconds pass between the two syncs. If `start` were ever hoisted to + // something that persists across calls (a `static`/`OnceLock`, a field on some long-lived + // context) instead of being captured fresh inside THIS call to `fetch_and_reassemble_with_clock`, + // the leaked `start` would still be `slow_prior_pin` while `clock.now()` on the second call's + // ticks reads `second_pin` — a `elapsed` of 5s, not zero. + let second_pin = slow_prior_pin + Duration::from_secs(5); // Second, independent manifest/content — its phase starts fresh. let b = vec![2u8; 5]; @@ -1276,15 +1369,16 @@ mod download_rate_tests { chunks: chunks2, }; - let mut second_elapsed = Duration::ZERO; - sync_set(&t2, "s2", &cache, &mut |p| { + let mut second_elapsed = Duration::MAX; + sync_set_with_clock(&t2, "s2", &cache, &mut |p| { if let SyncProgress::Downloading { elapsed, .. } = p { second_elapsed = elapsed; } - }).unwrap(); - assert!(second_elapsed < Duration::from_millis(100), - "second sync's elapsed must NOT carry over the 300ms slept before/between syncs — got \ - {second_elapsed:?}, which would mean the clock is global/shared, not phase-scoped"); + }, DownloadClock::frozen_at(second_pin)).unwrap(); + assert_eq!(second_elapsed, Duration::ZERO, + "second sync's elapsed must be EXACTLY zero — a nonzero value would mean `start` was \ + NOT captured fresh from THIS call's own clock reading (the #708 carry-over bug this \ + test is named for), got {second_elapsed:?}"); } }