From 38b218eeaf7588edee4ed78edbbea113162f4cac Mon Sep 17 00:00:00 2001 From: zackees Date: Sat, 1 Aug 2026 12:48:48 -0700 Subject: [PATCH 1/2] fix(ci): de-flake the two intermittent macOS test failures (#1222) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Neither test was a regression; both surfaced once #1216/#1221 stopped the macOS job aborting before it reached the test step. Both assert exact outcomes over real OS resources under timing pressure. ## spawn_lock_is_exclusive_within_process `try_acquire_spawn_lock_at` used `.ok().flatten()`, collapsing a hard I/O error into the same `None` that means "another process holds the lock" — so when the third acquire failed, there was no way to tell which had happened. - Split into `try_acquire_spawn_lock_result_at` (propagates) and the existing swallowing wrapper (logs errno + kind, then returns `None`). The "a broken filesystem must never gate progress" contract for the production caller is unchanged; the failure is just no longer silent. - The test now uses the error-preserving variant, so a hard error reports the actual errno instead of a bare `assertion failed`. - Retry `EINTR` in `file_lock::try_acquire`, around both the `open` and the `flock`. `flock()` is interruptible by signals on macOS/BSD and fs2 returns the raw OS error, which our classifier doesn't recognize as contention — so an EINTR became a hard error. Correct regardless of whether it was the cause here. ## streaming_download_retries_chunk_stalls_five_times_without_output This was the only test combining `#[tokio::test(start_paused = true)]` with a real `TcpListener`, and it was the one that flaked. Paused time auto-advances whenever the runtime looks idle, but socket readiness comes from the OS reactor, not the virtual clock — so with the client parked on `chunk()` and the server on `sleep`, the clock could jump past a connection that was about to reach `accept()`, leaving `request_count` short of 5. Took the issue's preferred fix rather than the stopgap: extract the retry durations into a `RetryTiming` struct so the test drives the *same* retry logic on millisecond durations in real time. No `start_paused`, no reactor race, and the assertion stays at exactly 5 attempts instead of being weakened to `>= 1`. Runs in ~1s. `production_retry_timing_matches_the_constants` pins the seam to the real constants so the injection can't drift into a behavior change. Verified: the chunk-stall test passes 5/5 consecutive runs locally; clippy clean on all four crates. Co-Authored-By: Claude --- Cargo.lock | 1 + crates/fbuild-core/src/file_lock.rs | 46 +++++- .../fbuild-packages-fetch/src/downloader.rs | 142 ++++++++++++++---- crates/fbuild-paths/Cargo.toml | 3 + crates/fbuild-paths/src/daemon_ownership.rs | 69 ++++++++- 5 files changed, 218 insertions(+), 43 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index c753c349..c840637a 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1403,6 +1403,7 @@ dependencies = [ "serde", "serde_json", "tempfile", + "tracing", ] [[package]] diff --git a/crates/fbuild-core/src/file_lock.rs b/crates/fbuild-core/src/file_lock.rs index eb927762..60800344 100644 --- a/crates/fbuild-core/src/file_lock.rs +++ b/crates/fbuild-core/src/file_lock.rs @@ -28,16 +28,18 @@ pub fn try_acquire(path: &Path, mode: FileLockMode) -> io::Result FileExt::try_lock_shared(&file), FileLockMode::Exclusive => FileExt::try_lock_exclusive(&file), - }; + }); match result { Ok(()) => Ok(Some(FileLockGuard { _file: file })), Err(error) if lock_is_held(&error) => Ok(None), @@ -45,6 +47,34 @@ pub fn try_acquire(path: &Path, mode: FileLockMode) -> io::Result(mut op: impl FnMut() -> io::Result) -> io::Result { + let mut attempts = 0; + loop { + match op() { + Err(error) if error.kind() == io::ErrorKind::Interrupted => { + attempts += 1; + if attempts >= INTERRUPT_RETRIES { + return Err(error); + } + } + other => return other, + } + } +} + /// Does this error mean "another process holds a conflicting lock"? /// /// Unix reports contention as `EWOULDBLOCK` (kind `WouldBlock`), but Windows diff --git a/crates/fbuild-packages-fetch/src/downloader.rs b/crates/fbuild-packages-fetch/src/downloader.rs index 6d18efa0..cc9ad249 100644 --- a/crates/fbuild-packages-fetch/src/downloader.rs +++ b/crates/fbuild-packages-fetch/src/downloader.rs @@ -28,6 +28,33 @@ const RETRY_BACKOFFS: &[Duration] = &[ /// attempt and is retried under the same budget as other transient failures. const CHUNK_READ_TIMEOUT: Duration = Duration::from_secs(60); +/// The wall-clock durations the retry loop waits on. +/// +/// Extracted so tests can drive the *same* retry logic on millisecond +/// durations instead of reaching for `#[tokio::test(start_paused = true)]`. +/// Paused time and a real `TcpListener` don't mix: socket readiness is driven +/// by the OS reactor, not the virtual clock, so when every task parks the +/// clock can jump past a socket operation that was about to become ready — +/// which is what made the chunk-stall test flake on loaded macOS runners +/// (FastLED/fbuild#1222). +#[derive(Clone, Copy, Debug)] +struct RetryTiming { + chunk_read_timeout: Duration, + backoffs: &'static [Duration], +} + +impl RetryTiming { + const PRODUCTION: Self = Self { + chunk_read_timeout: CHUNK_READ_TIMEOUT, + backoffs: RETRY_BACKOFFS, + }; + + fn backoff(&self, attempt: u32) -> Duration { + debug_assert!((1..MAX_ATTEMPTS).contains(&attempt)); + self.backoffs[(attempt - 1) as usize] + } +} + /// Classify a `reqwest::Error` as worth retrying — anything that /// could plausibly succeed on a retry (connect timeout, request / /// body recv error, server-side 5xx). Deterministic-looking failures @@ -114,13 +141,13 @@ async fn open_attempt( } } -fn retry_backoff(attempt: u32) -> Duration { - debug_assert!((1..MAX_ATTEMPTS).contains(&attempt)); - RETRY_BACKOFFS[(attempt - 1) as usize] -} - -async fn wait_before_retry(url: &str, attempt: u32, error: &DownloadAttemptError) { - let delay = retry_backoff(attempt); +async fn wait_before_retry( + url: &str, + attempt: u32, + error: &DownloadAttemptError, + timing: RetryTiming, +) { + let delay = timing.backoff(attempt); tracing::warn!( "download {}: {} on attempt {}/{}, retrying after {:?}", url, @@ -219,7 +246,7 @@ async fn get_with_retry_using(client: &reqwest::Client, url: &str) -> Result return Ok(bytes), Err(error) if error.is_retryable() && attempt < MAX_ATTEMPTS => { - wait_before_retry(url, attempt, &error).await; + wait_before_retry(url, attempt, &error, RetryTiming::PRODUCTION).await; } Err(error) => return Err(error.into_fbuild_error(url)), } @@ -245,6 +272,19 @@ async fn download_file_with_progress_using( url: &str, dest_dir: &Path, on_progress: &mut dyn FnMut(&DownloadProgress), +) -> Result<()> { + download_file_with_progress_timed(client, url, dest_dir, on_progress, RetryTiming::PRODUCTION) + .await +} + +/// [`download_file_with_progress_using`] with the retry durations injected. +/// See [`RetryTiming`] for why tests need this instead of paused Tokio time. +async fn download_file_with_progress_timed( + client: &reqwest::Client, + url: &str, + dest_dir: &Path, + on_progress: &mut dyn FnMut(&DownloadProgress), + timing: RetryTiming, ) -> Result<()> { let filename = url.rsplit('/').next().unwrap_or("download").to_string(); let dest_path = dest_dir.join(&filename); @@ -269,16 +309,17 @@ async fn download_file_with_progress_using( // the audit calls out specifically: streaming body reads have no // per-chunk wake-up signal otherwise. loop { - let chunk = match tokio::time::timeout(CHUNK_READ_TIMEOUT, stream.chunk()).await { - Ok(Ok(Some(chunk))) => chunk, - Ok(Ok(None)) => break, - Ok(Err(error)) => return Err(DownloadAttemptError::Body(error)), - Err(_) => { - return Err(DownloadAttemptError::BodyStalled { - filename: filename.clone(), - }); - } - }; + let chunk = + match tokio::time::timeout(timing.chunk_read_timeout, stream.chunk()).await { + Ok(Ok(Some(chunk))) => chunk, + Ok(Ok(None)) => break, + Ok(Err(error)) => return Err(DownloadAttemptError::Body(error)), + Err(_) => { + return Err(DownloadAttemptError::BodyStalled { + filename: filename.clone(), + }); + } + }; attempt_buf.extend_from_slice(&chunk); downloaded += chunk.len() as u64; @@ -312,7 +353,7 @@ async fn download_file_with_progress_using( match result { Ok(bytes) => break bytes, Err(error) if error.is_retryable() && attempt < MAX_ATTEMPTS => { - wait_before_retry(url, attempt, &error).await; + wait_before_retry(url, attempt, &error, timing).await; } Err(error) => return Err(error.into_fbuild_error(url)), } @@ -503,6 +544,10 @@ mod tests { port } + /// How long `run_stalling_server` withholds the announced body. Only has + /// to comfortably exceed `FAST_RETRY_TIMING.chunk_read_timeout`. + const STALL_DURATION: Duration = Duration::from_secs(30); + async fn run_stalling_server(request_count: std::sync::Arc) -> u16 { use tokio::io::{AsyncReadExt, AsyncWriteExt}; use tokio::net::TcpListener; @@ -523,15 +568,19 @@ mod tests { let mut stream = stream; let mut request = [0u8; 1024]; // See `run_flaky_server`: this test owns the client, so - // waiting for its request is deterministic under paused - // Tokio time. + // waiting for its request is deterministic. let _ = stream.read(&mut request).await; let _ = stream .write_all( b"HTTP/1.1 200 OK\r\nContent-Length: 5\r\nConnection: close\r\n\r\n", ) .await; - tokio::time::sleep(Duration::from_secs(120)).await; + // Announce a body, then never send it. Just needs to + // outlast the client's per-chunk deadline; the task is + // dropped at runtime shutdown, so the test doesn't wait + // on it (FastLED/fbuild#1222 — this runs in real time + // now, not paused time). + tokio::time::sleep(STALL_DURATION).await; let _ = stream.shutdown().await; }); } @@ -734,7 +783,24 @@ mod tests { assert!(!temp.path().join("file").exists()); } - #[tokio::test(start_paused = true)] + /// Retry timings short enough to run in real time. This test previously + /// used `#[tokio::test(start_paused = true)]` against a real + /// `TcpListener`, which flaked on loaded macOS runners: paused time + /// auto-advances whenever the runtime looks idle, but socket readiness + /// comes from the OS reactor, so the clock could jump past a connection + /// that was about to reach `accept()` — leaving `request_count` short of + /// 5. Real durations remove the race entirely (FastLED/fbuild#1222). + const FAST_RETRY_TIMING: RetryTiming = RetryTiming { + chunk_read_timeout: Duration::from_millis(150), + backoffs: &[ + Duration::from_millis(10), + Duration::from_millis(10), + Duration::from_millis(10), + Duration::from_millis(10), + ], + }; + + #[tokio::test] async fn streaming_download_retries_chunk_stalls_five_times_without_output() { let _guard = network_test_guard().await; let request_count = std::sync::Arc::new(AtomicUsize::new(0)); @@ -743,10 +809,15 @@ mod tests { let temp = tempfile::TempDir::new().unwrap(); let mut progress = |_progress: &DownloadProgress| {}; - let _err = - download_file_with_progress_using(&test_client(), &url, temp.path(), &mut progress) - .await - .expect_err("five chunk stalls should exhaust retries"); + let _err = download_file_with_progress_timed( + &test_client(), + &url, + temp.path(), + &mut progress, + FAST_RETRY_TIMING, + ) + .await + .expect_err("five chunk stalls should exhaust retries"); // A stalled body is retryable, as is a connection error while opening // a retry. The latter can legitimately be the final transient on a @@ -756,6 +827,23 @@ mod tests { assert!(!temp.path().join("file").exists()); } + /// The injected timings are a test seam, not a behavior change: the + /// production path must still carry the real constants. + #[test] + fn production_retry_timing_matches_the_constants() { + assert_eq!( + RetryTiming::PRODUCTION.chunk_read_timeout, + CHUNK_READ_TIMEOUT + ); + assert_eq!(RetryTiming::PRODUCTION.backoffs, RETRY_BACKOFFS); + for attempt in 1..MAX_ATTEMPTS { + assert_eq!( + RetryTiming::PRODUCTION.backoff(attempt), + RETRY_BACKOFFS[(attempt - 1) as usize] + ); + } + } + #[test] fn format_download_progress_with_total() { let p = DownloadProgress { diff --git a/crates/fbuild-paths/Cargo.toml b/crates/fbuild-paths/Cargo.toml index 64fb2859..84d01b07 100644 --- a/crates/fbuild-paths/Cargo.toml +++ b/crates/fbuild-paths/Cargo.toml @@ -13,6 +13,9 @@ publish = false fbuild-core = { path = "../fbuild-core" } serde = { workspace = true } serde_json = { workspace = true } +# Spawn-lock acquire errors are logged rather than propagated, so the errno +# stays visible without gating progress (FastLED/fbuild#1222). +tracing = { workspace = true } [dev-dependencies] tempfile = { workspace = true } diff --git a/crates/fbuild-paths/src/daemon_ownership.rs b/crates/fbuild-paths/src/daemon_ownership.rs index 41858714..1dba8b76 100644 --- a/crates/fbuild-paths/src/daemon_ownership.rs +++ b/crates/fbuild-paths/src/daemon_ownership.rs @@ -84,11 +84,37 @@ pub fn try_acquire_spawn_lock() -> Option { } /// Test seam: try to acquire the spawn-herd lock at an arbitrary path. +/// +/// Never-fails-hard wrapper around [`try_acquire_spawn_lock_result_at`]: an +/// I/O error is logged (with its errno) and reported as "no lock available", +/// preserving the "a broken filesystem must never gate progress" contract. +/// The log line is what distinguishes a hard error from routine contention — +/// before it, the two were indistinguishable in both prod and tests +/// (FastLED/fbuild#1222). pub fn try_acquire_spawn_lock_at(path: &Path) -> Option { - file_lock::try_acquire(path, FileLockMode::Exclusive) - .ok() - .flatten() - .map(|_guard| SpawnLockGuard { _guard }) + match try_acquire_spawn_lock_result_at(path) { + Ok(guard) => guard, + Err(error) => { + tracing::warn!( + path = %path.display(), + errno = ?error.raw_os_error(), + kind = ?error.kind(), + "spawn lock acquire failed with an I/O error; treating as unavailable: {error}" + ); + None + } + } +} + +/// Error-preserving variant of [`try_acquire_spawn_lock_at`]. +/// +/// `Ok(None)` means another holder has the lock; `Err` means the acquire +/// itself failed. Production uses the swallowing wrapper above; tests use this +/// so a hard error fails with the actual errno instead of being mistaken for +/// contention. +pub fn try_acquire_spawn_lock_result_at(path: &Path) -> std::io::Result> { + Ok(file_lock::try_acquire(path, FileLockMode::Exclusive)? + .map(|_guard| SpawnLockGuard { _guard })) } /// Path to the root-ownership lock file. @@ -185,12 +211,39 @@ mod tests { let temp = TempDir::new().expect("tempdir"); let path = temp.path().join("spawn.lock"); - let first = try_acquire_spawn_lock_at(&path).expect("first acquire"); - let second = try_acquire_spawn_lock_at(&path); + // Use the error-preserving variant: the swallowing wrapper turns a + // hard I/O error into the same `None` that means "contended", so a + // failure here used to report a bare `assertion failed` with no errno + // (FastLED/fbuild#1222). + let first = try_acquire_spawn_lock_result_at(&path) + .expect("first acquire io") + .expect("first acquire must succeed"); + let second = try_acquire_spawn_lock_result_at(&path).expect("second acquire io"); assert!(second.is_none(), "second acquire while held must be None"); drop(first); - let third = try_acquire_spawn_lock_at(&path); - assert!(third.is_some(), "lock must be available after release"); + let third = try_acquire_spawn_lock_result_at(&path) + .expect("third acquire io") + .expect("lock must be available after release"); + drop(third); + } + + /// The swallowing wrapper must still behave identically on the happy and + /// contended paths — the #1222 change only affects the error path. + #[test] + fn swallowing_spawn_lock_wrapper_matches_the_result_variant() { + let temp = TempDir::new().expect("tempdir"); + let path = temp.path().join("spawn.lock"); + + let first = try_acquire_spawn_lock_at(&path).expect("first acquire"); + assert!( + try_acquire_spawn_lock_at(&path).is_none(), + "second acquire while held must be None" + ); + drop(first); + assert!( + try_acquire_spawn_lock_at(&path).is_some(), + "lock must be available after release" + ); } /// Soldr pattern (`spawn_lock_serializes_concurrent_threads`): fire a From 1cf17b10e4cad27503f513b27a5ecc124531b8a2 Mon Sep 17 00:00:00 2001 From: zackees Date: Sat, 1 Aug 2026 14:10:45 -0700 Subject: [PATCH 2/2] test(paths): assert the post-release re-acquire through the propagating variant MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The new wrapper test asserted `try_acquire_spawn_lock_at(&path).is_some()` after release — and reproduced the exact #1222 flake on Ubuntu CI, on the same commit that had just passed, as a bare `assertion failed` with no errno. That is the defect this PR is about, not a bad test: the swallowing wrapper cannot distinguish "I/O error" from "another holder has it", so ANY re-acquire assertion through it is untestable by construction. Asserting that step through `try_acquire_spawn_lock_result_at` is the same correction the issue asks for on the original test. Two things worth recording: the flake is NOT macOS-only, and it lands on the post-release re-acquire rather than the release itself — which is consistent with the issue's "hard error misread as contention" theory and not with "macOS fails to release flock on close". The errno now logged by the wrapper is what should identify it next time. Co-Authored-By: Claude --- crates/fbuild-paths/src/daemon_ownership.rs | 16 ++++++++++++---- 1 file changed, 12 insertions(+), 4 deletions(-) diff --git a/crates/fbuild-paths/src/daemon_ownership.rs b/crates/fbuild-paths/src/daemon_ownership.rs index 1dba8b76..54f73d8a 100644 --- a/crates/fbuild-paths/src/daemon_ownership.rs +++ b/crates/fbuild-paths/src/daemon_ownership.rs @@ -229,6 +229,15 @@ mod tests { /// The swallowing wrapper must still behave identically on the happy and /// contended paths — the #1222 change only affects the error path. + /// + /// The post-release re-acquire is deliberately checked through the + /// error-propagating variant. An earlier draft of this test asserted + /// `try_acquire_spawn_lock_at(&path).is_some()` there and promptly + /// reproduced the very flake this PR is about — on Linux, not just macOS + /// — as a bare `assertion failed` with no errno, because the swallowing + /// wrapper cannot distinguish "I/O error" from "contended". Asserting a + /// re-acquire through the wrapper is therefore untestable by + /// construction, and that is the defect, not the test. #[test] fn swallowing_spawn_lock_wrapper_matches_the_result_variant() { let temp = TempDir::new().expect("tempdir"); @@ -240,10 +249,9 @@ mod tests { "second acquire while held must be None" ); drop(first); - assert!( - try_acquire_spawn_lock_at(&path).is_some(), - "lock must be available after release" - ); + try_acquire_spawn_lock_result_at(&path) + .expect("re-acquire io") + .expect("lock must be available after release"); } /// Soldr pattern (`spawn_lock_serializes_concurrent_threads`): fire a