From 3f828722fd8650a56b04a4a1545ed33df0f0294a Mon Sep 17 00:00:00 2001 From: Zach Vorhies Date: Fri, 2 Oct 2026 11:31:42 -0700 Subject: [PATCH] fix(deploy): wait for timed-out native espflash ops to release the port (#1614) The native verify/write paths ran espflash on spawn_blocking under tokio::time::timeout. A timeout only drops the JoinHandle; the blocking thread keeps running and keeps the serial port open until espflash gives up on its own (~40s past the 30s verify budget on an ESP32-C6). The esptool fallback then failed with EBUSY ("port is busy"). Route all three sites through run_port_bound, which on timeout keeps joining the thread for a bounded release grace so the port is free before the caller falls back, and reports the port as still held if the grace expires. Fixes the comments that claimed the Flasher drops on timeout. Closes #1614 --- crates/fbuild-deploy/src/esp32/deployer.rs | 136 ++++++++-------- .../src/esp32_native/blocking.rs | 149 ++++++++++++++++++ crates/fbuild-deploy/src/esp32_native/mod.rs | 2 + 3 files changed, 213 insertions(+), 74 deletions(-) create mode 100644 crates/fbuild-deploy/src/esp32_native/blocking.rs 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::{