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..54f73d8a 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,47 @@ 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. + /// + /// 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"); + 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); + 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