diff --git a/crates/fbuild-deploy/src/esp32/deployer.rs b/crates/fbuild-deploy/src/esp32/deployer.rs index bd6048b27..ea77cb8ea 100644 --- a/crates/fbuild-deploy/src/esp32/deployer.rs +++ b/crates/fbuild-deploy/src/esp32/deployer.rs @@ -447,37 +447,33 @@ impl Esp32Deployer { // + per-region MD5). On a wedged USB-CDC stack the call could // spin for minutes. A 30s outer cap matches the esptool // subprocess path's timeout and is the documented "fast skip" - // budget. On timeout the blocking task is detached (the - // `Flasher` drops, closing the serial port) and the caller can - // fall back to a full flash via the esptool path. + // budget. The blocking thread cannot be cancelled, so on timeout + // `run_port_bound` waits for it to release the port before the + // caller falls back to esptool (FastLED/fbuild#1614). let chip = self.chip.clone(); let port_str = port.to_string(); let before_reset = self.before_reset.clone(); let after_reset = self.after_reset.clone(); - let join_handle = tokio::task::spawn_blocking(move || { - crate::esp32_native::try_verify_deployment_native( - &chip, - &port_str, - baud, - &before_reset, - &after_reset, - ®ions, - boot_off, - parts_off, - fw_off, - ) - }); - match tokio::time::timeout(std::time::Duration::from_secs(30), join_handle).await { - Ok(Ok(result)) => result, - Ok(Err(e)) => Err(fbuild_core::FbuildError::DeployFailed(format!( - "native verify: blocking task panicked: {}", - e - ))), - Err(_) => Err(fbuild_core::FbuildError::DeployFailed(format!( - "native verify timed out after 30s on {}", - port - ))), - } + crate::esp32_native::run_port_bound( + "native verify", + port, + std::time::Duration::from_secs(30), + crate::esp32_native::PORT_RELEASE_GRACE, + move || { + crate::esp32_native::try_verify_deployment_native( + &chip, + &port_str, + baud, + &before_reset, + &after_reset, + ®ions, + boot_off, + parts_off, + fw_off, + ) + }, + ) + .await } /// Native `write-flash` via the [`espflash`] crate (issue #66). @@ -529,35 +525,31 @@ impl Esp32Deployer { // stub flasher mid-write this hangs the daemon's `/api/deploy` // handler indefinitely. 180s comfortably covers a worst-case // full-image write (~2.4 MB at 460800 baud + erase) while - // bounding the wedge surface; on timeout the blocking task is - // detached (the `Flasher` drops, closing the port) and we - // surface a clear error so the caller can retry / fall back. + // bounding the wedge surface; on timeout `run_port_bound` waits + // for the uncancellable thread to release the port before we + // surface the error (FastLED/fbuild#1614). let chip = self.chip.clone(); let port_str = port.to_string(); let before_reset = self.before_reset.clone(); let after_reset = self.after_reset.clone(); - let join_handle = tokio::task::spawn_blocking(move || { - crate::esp32_native::try_write_deployment_native( - &chip, - &port_str, - baud, - &before_reset, - &after_reset, - ®ions, - /* selective */ false, - ) - }); - match tokio::time::timeout(std::time::Duration::from_secs(180), join_handle).await { - Ok(Ok(result)) => result, - Ok(Err(e)) => Err(fbuild_core::FbuildError::DeployFailed(format!( - "native write: blocking task panicked: {}", - e - ))), - Err(_) => Err(fbuild_core::FbuildError::DeployFailed(format!( - "native write timed out after 180s on {}", - port - ))), - } + crate::esp32_native::run_port_bound( + "native write", + port, + std::time::Duration::from_secs(180), + crate::esp32_native::PORT_RELEASE_GRACE, + move || { + crate::esp32_native::try_write_deployment_native( + &chip, + &port_str, + baud, + &before_reset, + &after_reset, + ®ions, + /* selective */ false, + ) + }, + ) + .await } /// Native `write-flash` for a caller-chosen subset of regions @@ -607,28 +599,24 @@ impl Esp32Deployer { let port_str = port.to_string(); let before_reset = self.before_reset.clone(); let after_reset = self.after_reset.clone(); - let join_handle = tokio::task::spawn_blocking(move || { - crate::esp32_native::try_write_deployment_native( - &chip, - &port_str, - baud, - &before_reset, - &after_reset, - &write_regions, - /* selective */ true, - ) - }); - match tokio::time::timeout(std::time::Duration::from_secs(180), join_handle).await { - Ok(Ok(result)) => result, - Ok(Err(e)) => Err(fbuild_core::FbuildError::DeployFailed(format!( - "native write (selective): blocking task panicked: {}", - e - ))), - Err(_) => Err(fbuild_core::FbuildError::DeployFailed(format!( - "native write (selective) timed out after 180s on {}", - port - ))), - } + crate::esp32_native::run_port_bound( + "native write (selective)", + port, + std::time::Duration::from_secs(180), + crate::esp32_native::PORT_RELEASE_GRACE, + move || { + crate::esp32_native::try_write_deployment_native( + &chip, + &port_str, + baud, + &before_reset, + &after_reset, + &write_regions, + /* selective */ true, + ) + }, + ) + .await } #[cfg(feature = "espflash-native")] diff --git a/crates/fbuild-deploy/src/esp32_native/blocking.rs b/crates/fbuild-deploy/src/esp32_native/blocking.rs new file mode 100644 index 000000000..e92f4ff86 --- /dev/null +++ b/crates/fbuild-deploy/src/esp32_native/blocking.rs @@ -0,0 +1,149 @@ +//! Wall-clock cap for port-owning blocking work (FastLED/fbuild#1614). +//! +//! espflash's `Flasher` is synchronous, so the native verify/write paths +//! run it on `spawn_blocking` under a `tokio::time::timeout`. A timeout +//! only drops the `JoinHandle`: a blocking closure cannot be cancelled, +//! so the thread keeps running — and keeps the serial port open — until +//! espflash gives up on its own. Returning at that point hands the +//! caller's esptool fallback a port that is still held, and it fails +//! with `EBUSY` ("the port is busy or doesn't exist"). +//! +//! [`run_port_bound`] keeps joining the thread for a bounded release +//! grace after the budget expires, so a timeout error means the port has +//! actually been released. If even the grace expires, the error says the +//! port is still held instead of letting the fallback misreport it. + +use std::time::Duration; + +use fbuild_core::{FbuildError, Result}; + +/// How long to keep waiting for a timed-out native operation to release +/// its serial port. espflash bounds every UART read/write (3 s for +/// verify, 10 s for write), so an abandoned connect/sync loop unwinds on +/// its own; on an ESP32-C6 USB-Serial-JTAG bench it took ~40 s past the +/// 30 s verify budget. +pub(crate) const PORT_RELEASE_GRACE: Duration = Duration::from_secs(60); + +/// Run `op` on a blocking thread with a `budget` wall-clock cap. On +/// timeout, wait up to `release_grace` more for the thread to finish so +/// the serial port it owns is closed before returning. +pub(crate) async fn run_port_bound( + what: &str, + port: &str, + budget: Duration, + release_grace: Duration, + op: F, +) -> Result +where + T: Send + 'static, + F: FnOnce() -> Result + Send + 'static, +{ + let mut handle = tokio::task::spawn_blocking(op); + let joined = match tokio::time::timeout(budget, &mut handle).await { + Ok(joined) => joined, + Err(_) => { + tracing::warn!( + port, + "{what} timed out after {}s; waiting up to {}s for it to release the port", + budget.as_secs(), + release_grace.as_secs() + ); + let released = tokio::time::timeout(release_grace, handle).await.is_ok(); + return Err(FbuildError::DeployFailed(if released { + format!("{what} timed out after {}s on {port}", budget.as_secs()) + } else { + format!( + "{what} timed out after {}s on {port}, and {port} is still held by \ + the abandoned operation {}s later", + budget.as_secs(), + release_grace.as_secs() + ) + })); + } + }; + joined.unwrap_or_else(|e| { + Err(FbuildError::DeployFailed(format!( + "{what}: blocking task panicked: {e}" + ))) + }) +} + +#[cfg(test)] +mod tests { + use super::*; + use std::sync::Arc; + use std::sync::atomic::{AtomicBool, Ordering}; + + #[tokio::test] + async fn returns_result_within_budget() { + let out = run_port_bound("op", "p", Duration::from_secs(5), Duration::ZERO, || Ok(7)) + .await + .unwrap(); + assert_eq!(out, 7); + } + + /// The bug: a timeout must not return while the thread (which owns + /// the port) is still running. + #[tokio::test] + async fn timeout_waits_for_the_thread_to_finish() { + let finished = Arc::new(AtomicBool::new(false)); + let flag = finished.clone(); + let err = run_port_bound( + "native verify", + "/dev/ttyACM1", + Duration::from_millis(50), + Duration::from_secs(5), + move || { + std::thread::sleep(Duration::from_millis(300)); + flag.store(true, Ordering::SeqCst); + Ok(()) + }, + ) + .await + .unwrap_err(); + assert!( + finished.load(Ordering::SeqCst), + "returned before the port was released" + ); + let msg = err.to_string(); + assert!( + msg.contains("native verify timed out after 0s on /dev/ttyACM1"), + "{msg}" + ); + assert!(!msg.contains("still held"), "{msg}"); + } + + #[tokio::test] + async fn grace_expiry_reports_the_port_as_still_held() { + let err = run_port_bound( + "native write", + "/dev/ttyACM1", + Duration::from_millis(20), + Duration::from_millis(20), + || { + std::thread::sleep(Duration::from_millis(500)); + Ok(()) + }, + ) + .await + .unwrap_err(); + assert!( + err.to_string().contains("/dev/ttyACM1 is still held"), + "{err}" + ); + } + + #[tokio::test] + async fn panic_is_reported() { + let err = + run_port_bound::<(), _>("op", "p", Duration::from_secs(5), Duration::ZERO, || { + panic!("boom") + }) + .await + .unwrap_err(); + assert!( + err.to_string().contains("op: blocking task panicked"), + "{err}" + ); + } +} diff --git a/crates/fbuild-deploy/src/esp32_native/mod.rs b/crates/fbuild-deploy/src/esp32_native/mod.rs index 9e9de91d8..3f8e97258 100644 --- a/crates/fbuild-deploy/src/esp32_native/mod.rs +++ b/crates/fbuild-deploy/src/esp32_native/mod.rs @@ -54,12 +54,14 @@ //! `collect_selected_write_regions`) is re-exported from this `mod.rs` //! so external callers see the same paths as before. +mod blocking; mod progress; mod transport; mod types; mod verify; mod write; +pub(crate) use blocking::{PORT_RELEASE_GRACE, run_port_bound}; pub use types::{NativeVerifyRegion, NativeWriteRegion}; pub use verify::{collect_standard_regions, try_verify_deployment_native}; pub use write::{