diff --git a/ci/platform_boundary_research.tsv b/ci/platform_boundary_research.tsv index 735e488d..37b4383e 100644 --- a/ci/platform_boundary_research.tsv +++ b/ci/platform_boundary_research.tsv @@ -75,6 +75,6 @@ crates/fbuild-toolchain/src/toolchain/esp_qemu.rs 570 attr_cfg #[cfg(not(windows crates/fbuild-toolchain/src/toolchain/esp_qemu.rs 728 attr_cfg #[cfg(windows)] host_executable host_mechanic crates/fbuild-toolchain/src/toolchain/esp_qemu.rs 755 attr_cfg #[cfg(windows)] host_executable host_mechanic crates/fbuild-toolchain/src/toolchain/esp_qemu_runtime.rs 224 attr_cfg #[cfg_attr(not(target_os=),allow(dead_code))] host_executable host_artifact_policy -crates/fbuild-toolchain/src/toolchain/esp_qemu_runtime.rs 246 attr_cfg #[cfg(not(target_os=))] host_executable host_artifact_policy -crates/fbuild-toolchain/src/toolchain/esp_qemu_runtime.rs 252 attr_cfg #[cfg(target_os=)] host_executable host_artifact_policy +crates/fbuild-toolchain/src/toolchain/esp_qemu_runtime.rs 266 attr_cfg #[cfg(not(target_os=))] host_executable host_artifact_policy +crates/fbuild-toolchain/src/toolchain/esp_qemu_runtime.rs 272 attr_cfg #[cfg(target_os=)] host_executable host_artifact_policy crates/fbuild-toolchain/tests/qemu_linux_runtime.rs 18 attr_cfg #![cfg(target_os=)] host_executable host_artifact_policy diff --git a/crates/fbuild-core/src/subprocess.rs b/crates/fbuild-core/src/subprocess.rs index 37f0c643..06f3fd6b 100644 --- a/crates/fbuild-core/src/subprocess.rs +++ b/crates/fbuild-core/src/subprocess.rs @@ -411,6 +411,78 @@ pub fn run_command_blocking( block_on(run_command(args, cwd, env, timeout)) } +/// How many times [`run_command_blocking_retrying_exec_busy`] will try to +/// spawn before giving up. +/// +/// Three is enough for the window this exists to cross. The race is another +/// thread holding a writable descriptor across a `fork`, which lasts as long +/// as it takes that child to reach `exec` — microseconds, not milliseconds. +const EXEC_BUSY_ATTEMPTS: u32 = 3; + +/// Base backoff between spawn attempts; multiplied by the attempt number. +const EXEC_BUSY_BACKOFF: Duration = Duration::from_millis(25); + +/// Whether an OS spawn error is "the file is open for writing somewhere". +/// +/// `ETXTBSY` on Unix. The kernel refuses to `exec` a file while any process +/// holds a writable descriptor for it — and "any process" includes a `fork`ed +/// child of this one that has not reached `exec` yet, which is how the race +/// happens without anyone writing to the file at all. +pub fn is_exec_busy(error: &std::io::Error) -> bool { + error.kind() == std::io::ErrorKind::ExecutableFileBusy +} + +/// [`run_command_blocking`], but retrying a spawn that fails with `ETXTBSY`. +/// +/// Opt-in rather than the default for every subprocess in fbuild, because +/// retrying an exec is a behavior change and only some callers have the +/// write-then-exec shape that provokes it: a file this process just created +/// or extracted and is now running. +/// +/// Only `ETXTBSY` is retried. Every other spawn error is returned on the +/// first attempt — a missing binary should fail immediately, not three times +/// slowly. +/// +/// FastLED/fbuild#1366. +pub fn run_command_blocking_retrying_exec_busy( + args: &[&str], + cwd: Option<&Path>, + env: Option<&[(&str, &str)]>, + timeout: Option, +) -> Result { + block_on(run_command_retrying_exec_busy(args, cwd, env, timeout)) +} + +/// Async form of [`run_command_blocking_retrying_exec_busy`]. +pub async fn run_command_retrying_exec_busy( + args: &[&str], + cwd: Option<&Path>, + env: Option<&[(&str, &str)]>, + timeout: Option, +) -> Result { + if args.is_empty() { + return Err(FbuildError::Other("empty command".to_string())); + } + let timeout = resolve_default_timeout(timeout); + let mut attempt = 1; + loop { + let mut cmd = build_command( + args, cwd, env, /*capture=*/ true, /*stdin_piped=*/ false, + )?; + match process::spawn_tokio_contained(&mut cmd) { + Ok(child) => return wait_and_capture(child, args, timeout).await, + Err(error) if is_exec_busy(&error) && attempt < EXEC_BUSY_ATTEMPTS => { + // `tokio::time::sleep`, not `std::thread::sleep`: this runs on + // a tokio worker and blocking it would stall every other task + // on that thread (FastLED/fbuild#844). + tokio::time::sleep(EXEC_BUSY_BACKOFF * attempt).await; + attempt += 1; + } + Err(error) => return Err(spawn_err(args, error)), + } + } +} + /// Blocking variant of [`run_command_with_stdin`]. pub fn run_command_with_stdin_blocking( args: &[&str], @@ -639,6 +711,134 @@ fn compute_env(program: &str, overlay: Option<&[(&str, &str)]>) -> Option bool { + crate::platform::host::current().os() == crate::platform::host::HostOs::Linux + } + + /// Build an executable no-op script and return its path. + /// + /// Uses the neutral `platform::fs` facade rather than a per-OS + /// permissions extension trait, so this file stays free of raw host + /// mechanics (the platform-boundary ledger, #1306). + fn write_runnable_script(dir: &std::path::Path, name: &str) -> std::io::Result { + use std::io::Write; + let script = dir.join(name); + { + let mut file = std::fs::File::create(&script)?; + file.write_all( + b"#!/bin/sh +exit 0 +", + )?; + } + crate::platform::fs::set_executable(&script)?; + Ok(script.to_string_lossy().into_owned()) + } + + /// A held write handle blocks `exec`, and no amount of retrying helps. + /// + /// This is the mechanism behind FastLED/fbuild#1366 made reproducible. + /// Linux refuses to `exec` a file while *any* process holds it open for + /// writing — including this one — so the flake, which in CI came from a + /// sibling thread's `fork` inheriting the descriptor, needs no thread + /// timing to reproduce. Fully deterministic: the handle outlives the whole + /// retry budget. + #[tokio::test(flavor = "multi_thread")] + async fn a_held_write_handle_blocks_exec_for_the_whole_retry_budget() { + if !host_enforces_exec_busy() { + return; + } + let tmp = tempfile::TempDir::new().expect("tempdir"); + let path = write_runnable_script(tmp.path(), "held_open.sh").expect("script"); + + let held = std::fs::OpenOptions::new() + .write(true) + .open(&path) + .expect("reopen for write"); + + let result = run_command_retrying_exec_busy(&[path.as_str()], None, None, None).await; + assert!( + result.is_err(), + "exec must fail while a writable handle is open, got {result:?}" + ); + drop(held); + } + + /// The retry earns its place: a handle released mid-window lets a later + /// attempt through, where a single attempt would have failed. + /// + /// This is the property that actually fixes #1366 — the CI race window is + /// the microseconds between another thread's `fork` and its `exec`, so a + /// second attempt is all it takes. The 10 ms hold is deliberately tiny + /// against the ~75 ms retry budget: a loaded runner can delay the release + /// several times over and this still passes, so it cannot become the flake + /// it exists to prevent. + #[tokio::test(flavor = "multi_thread")] + async fn a_handle_released_mid_window_lets_the_retry_through() { + if !host_enforces_exec_busy() { + return; + } + let tmp = tempfile::TempDir::new().expect("tempdir"); + let path = write_runnable_script(tmp.path(), "released.sh").expect("script"); + + let held = std::fs::OpenOptions::new() + .write(true) + .open(&path) + .expect("reopen for write"); + + // The releaser signals *before* it sleeps, and the probe does not + // start until that signal arrives. Spawning detached and hoping would + // leave the task's timer unarmed until an arbitrary later point — on a + // loaded runner it could start after the retry budget had already + // elapsed, holding the handle through all three attempts. That would + // make this the flake it exists to prevent. + // + // A tokio task rather than a thread with `std::thread::sleep`, which + // the workspace bans for blocking a runtime worker (#844). + let (armed_tx, armed_rx) = tokio::sync::oneshot::channel(); + let releaser = tokio::spawn(async move { + let _ = armed_tx.send(()); + tokio::time::sleep(Duration::from_millis(10)).await; + drop(held); + }); + armed_rx.await.expect("releaser task must start"); + + let result = run_command_retrying_exec_busy(&[path.as_str()], None, None, None).await; + releaser.await.expect("releaser task must finish"); + assert!( + result.is_ok(), + "a retry must outlast a transient writable handle, got {result:?}" + ); + } + #[tokio::test] async fn run_echo() { let args = if crate::platform::host::is_windows() { diff --git a/crates/fbuild-toolchain/src/toolchain/esp_qemu_runtime.rs b/crates/fbuild-toolchain/src/toolchain/esp_qemu_runtime.rs index 90cb54fe..846fbb51 100644 --- a/crates/fbuild-toolchain/src/toolchain/esp_qemu_runtime.rs +++ b/crates/fbuild-toolchain/src/toolchain/esp_qemu_runtime.rs @@ -228,9 +228,29 @@ enum QemuProbe { /// The dynamic linker could not satisfy a dependency (exit code 127). /// Carries the linker's own line when it could be recovered. MissingSharedLibrary(String), - /// Probe could not be interpreted (spawn failure, or some other - /// non-127 exit). Treated as non-fatal: the real run reports it with - /// full context. + /// The probe produced no exit code to interpret: the binary could not be + /// executed, or the run failed or timed out before one was available. + /// + /// Distinct from [`QemuProbe::Inconclusive`] (which *did* get an exit + /// code, just not one that means anything) because the two say different + /// things about the runtime bundle. Collapsing "never produced a result" + /// into the bundle's own failure mode is what made a failed `exec` report + /// itself as a missing shared library, sending readers after QEMU + /// dependencies for a problem that was never there + /// (FastLED/fbuild#1366). + /// + /// Deliberately *not* split further into spawn-vs-timeout. The error + /// crossing this boundary is already flattened to a string by + /// `subprocess::spawn_err`, so telling them apart here would mean matching + /// on message text — and inventing a distinction the code cannot actually + /// make is precisely the bug above. The carried string is the underlying + /// error, which says which it was. + /// + /// Treated as non-fatal exactly like `Inconclusive`: the real run reports + /// it with full context. + ProbeFailed(String), + /// Probe could not be interpreted (some other non-127 exit). Treated as + /// non-fatal: the real run reports it with full context. Inconclusive, } @@ -261,7 +281,12 @@ fn probe_qemu_binary(qemu_binary: &Path, lib_dir: Option<&Path>) -> QemuProbe { .as_deref() .map(|value| vec![("LD_LIBRARY_PATH", value)]); - let probe_result = fbuild_core::subprocess::run_command_blocking( + // Retrying variant: fbuild probes binaries it has just downloaded and + // extracted, and `exec` on a file any process still holds open for + // writing fails with `ETXTBSY` — including a `fork`ed child of this + // process that has not reached its own `exec` yet. See + // FastLED/fbuild#1366. + let probe_result = fbuild_core::subprocess::run_command_blocking_retrying_exec_busy( &[&qemu_binary.to_string_lossy(), "--version"], None, // cwd env.as_deref(), @@ -279,7 +304,8 @@ fn probe_qemu_binary(qemu_binary: &Path, lib_dir: Option<&Path>) -> QemuProbe { .unwrap_or_else(|| out.stderr.trim().to_string()); QemuProbe::MissingSharedLibrary(detail) } - Ok(_) | Err(_) => QemuProbe::Inconclusive, + Err(error) => QemuProbe::ProbeFailed(error.to_string()), + Ok(_) => QemuProbe::Inconclusive, } } } @@ -298,6 +324,17 @@ fn probe_qemu_binary(qemu_binary: &Path, lib_dir: Option<&Path>) -> QemuProbe { pub(crate) async fn ensure_qemu_can_start(qemu_binary: &Path, project_dir: &Path) -> Result<()> { let missing = match probe_qemu_binary(qemu_binary, None) { QemuProbe::Started | QemuProbe::Inconclusive => return Ok(()), + QemuProbe::ProbeFailed(detail) => { + // Not a runtime-library problem, so downloading the bundle would + // fix nothing. Say what actually happened and let the real run + // report it with full context. + tracing::warn!( + "QEMU probe at {} produced no usable result: {}", + qemu_binary.display(), + detail + ); + return Ok(()); + } QemuProbe::MissingSharedLibrary(detail) => detail, }; @@ -316,6 +353,19 @@ pub(crate) async fn ensure_qemu_can_start(qemu_binary: &Path, project_dir: &Path match probe_qemu_binary(qemu_binary, Some(lib_dir.as_path())) { QemuProbe::Started | QemuProbe::Inconclusive => Ok(()), + // Non-fatal for the same reason `Inconclusive` is: the probe learned + // nothing about the runtime bundle. Logged rather than swallowed, + // because "could not execute the binary at all" is a different problem + // from "started and could not find a .so", and the next thing to fail + // will be the real run (FastLED/fbuild#1366). + QemuProbe::ProbeFailed(detail) => { + tracing::warn!( + "QEMU probe at {} produced no usable result even with the runtime bundle applied: {}", + qemu_binary.display(), + detail + ); + Ok(()) + } QemuProbe::MissingSharedLibrary(still_missing) => Err(FbuildError::PackageError(format!( "QEMU at {} cannot start even with the fbuild runtime bundle at {} applied.\n\ {}\n\