From f3de4bfd64c0bf4689ec2ab1f56cc339e7eb53d6 Mon Sep 17 00:00:00 2001 From: zackees Date: Thu, 16 Jul 2026 05:33:38 -0700 Subject: [PATCH] fix(rp2040): wait for delayed Windows CDC handoff Fixes #1074 --- crates/fbuild-deploy/src/rp2040.rs | 218 ++++++++++++++++++++++++---- crates/fbuild-serial/src/boards.rs | 27 +++- docs/usb-cdc-control-line-matrix.md | 20 +-- 3 files changed, 225 insertions(+), 40 deletions(-) diff --git a/crates/fbuild-deploy/src/rp2040.rs b/crates/fbuild-deploy/src/rp2040.rs index 96a5e4b3..655c2149 100644 --- a/crates/fbuild-deploy/src/rp2040.rs +++ b/crates/fbuild-deploy/src/rp2040.rs @@ -52,6 +52,7 @@ const BOOTLOADER_TIMEOUT_ENV: &str = "FBUILD_RP2040_BOOTLOADER_TIMEOUT_SECS"; const POST_DEPLOY_TIMEOUT_ENV: &str = "FBUILD_RP2040_POST_DEPLOY_TIMEOUT_SECS"; const UF2_WRITE_TIMEOUT_ENV: &str = "FBUILD_RP2040_UF2_WRITE_TIMEOUT_SECS"; const DEFAULT_UF2_WRITE_TIMEOUT: Duration = Duration::from_secs(60); +const CDC_POLL_INTERVAL: Duration = Duration::from_millis(100); /// Parse an env-supplied stage timeout. Accepts integer seconds in 1..=600; /// an unset variable is silently the default, anything else warns and falls @@ -79,6 +80,15 @@ fn timeout_from_env(var_name: &str, default: Duration) -> Duration { timeout_secs_from(raw.as_deref(), default, var_name) } +fn rp2040_post_deploy_timeout() -> Duration { + let timing = fbuild_serial::boards::BoardFamily::NativeUsbCdcReset1200Bps + .handoff_timing(); + timeout_from_env( + POST_DEPLOY_TIMEOUT_ENV, + Duration::from_millis(u64::from(timing.application_cdc_timeout_ms)), + ) +} + #[derive(Debug, Clone, Copy, PartialEq, Eq)] enum Uf2Target { Flash, @@ -937,10 +947,7 @@ impl Default for Rp2040Deployer { fn default() -> Self { Self { bootloader_timeout: timeout_from_env(BOOTLOADER_TIMEOUT_ENV, Duration::from_secs(10)), - // Windows can take several seconds to enumerate the CDC interface - // after the ROM accepts the UF2. Keep this bounded but generous - // enough for a stock board on a busy USB hub. - post_deploy_timeout: timeout_from_env(POST_DEPLOY_TIMEOUT_ENV, Duration::from_secs(15)), + post_deploy_timeout: rp2040_post_deploy_timeout(), uf2_write_timeout: timeout_from_env(UF2_WRITE_TIMEOUT_ENV, DEFAULT_UF2_WRITE_TIMEOUT), family_id: RP2040_FAMILY_ID, } @@ -1007,10 +1014,41 @@ fn catalogue_pico_cdc_ports(expected_family: u32) -> Result> { /// selection error (`Enumeration`) always fails the deploy. #[derive(Debug)] enum CdcWaitError { - Timeout, + Timeout(CdcWaitTimeout), Enumeration(FbuildError), } +#[derive(Debug)] +struct CdcWaitTimeout { + elapsed: Duration, + previous_port: Option, + requested_serial: Option, + candidates: Vec, +} + +impl CdcWaitTimeout { + fn diagnostics(&self) -> String { + let prior_port = self.previous_port.as_deref().unwrap_or("none"); + let requested_serial = self.requested_serial.as_deref().unwrap_or("none"); + let candidates = if self.candidates.is_empty() { + "none".to_string() + } else { + self.candidates + .iter() + .map(|candidate| match candidate.serial_number.as_deref() { + Some(serial) => format!("{} (serial {serial})", candidate.name), + None => format!("{} (serial unavailable)", candidate.name), + }) + .collect::>() + .join(", ") + }; + format!( + "elapsed {}ms; prior port {prior_port}; requested serial {requested_serial}; catalogue candidates: {candidates}", + self.elapsed.as_millis() + ) + } +} + fn wait_for_cdc_port( previous_port: Option<&str>, requested_serial: Option<&str>, @@ -1018,22 +1056,32 @@ fn wait_for_cdc_port( expected_family: u32, timeout: Duration, ) -> std::result::Result { - wait_for_cdc_port_with(previous_port, requested_serial, before, timeout, || { - catalogue_pico_cdc_ports(expected_family) - }) + let started = Instant::now(); + wait_for_cdc_port_with_clock( + previous_port, + requested_serial, + before, + timeout, + || catalogue_pico_cdc_ports(expected_family), + || started.elapsed(), + std::thread::sleep, + ) } -fn wait_for_cdc_port_with( +fn wait_for_cdc_port_with_clock( previous_port: Option<&str>, requested_serial: Option<&str>, before: &BTreeSet, timeout: Duration, mut catalogue: F, + mut elapsed: E, + mut sleep: S, ) -> std::result::Result where F: FnMut() -> Result>, + E: FnMut() -> Duration, + S: FnMut(Duration), { - let deadline = Instant::now() + timeout; loop { let ports = catalogue().map_err(CdcWaitError::Enumeration)?; match select_cdc_candidate(previous_port, requested_serial, before, &ports) { @@ -1041,10 +1089,16 @@ where Ok(None) => {} Err(error) => return Err(CdcWaitError::Enumeration(error)), } - if Instant::now() >= deadline { - return Err(CdcWaitError::Timeout); + let waited = elapsed(); + if waited >= timeout { + return Err(CdcWaitError::Timeout(CdcWaitTimeout { + elapsed: waited, + previous_port: previous_port.map(str::to_string), + requested_serial: requested_serial.map(str::to_string), + candidates: ports, + })); } - std::thread::sleep(Duration::from_millis(100)); + sleep(CDC_POLL_INTERVAL.min(timeout.saturating_sub(waited))); } } @@ -1070,14 +1124,20 @@ fn resolve_post_flash_cdc( match wait_result { Ok(port) => Ok(PostFlashCdc::Confirmed(port)), Err(CdcWaitError::Enumeration(error)) => Err(error), - Err(CdcWaitError::Timeout) if flash_confirmed => Ok(PostFlashCdc::Unconfirmed(format!( + Err(CdcWaitError::Timeout(diagnostics)) if flash_confirmed => { + tracing::warn!(diagnostics = %diagnostics.diagnostics(), "RP2040 runtime CDC did not return before the confirmed-flash deadline"); + Ok(PostFlashCdc::Unconfirmed(format!( "the firmware was flashed and accepted, but the runtime CDC port did not reappear within {}s; first-plug driver installation can exceed this window — the board is likely healthy (extend the window with {POST_DEPLOY_TIMEOUT_ENV})", window.as_secs() - ))), - Err(CdcWaitError::Timeout) => Err(FbuildError::DeployFailed(format!( + ))) + } + Err(CdcWaitError::Timeout(diagnostics)) => { + tracing::warn!(diagnostics = %diagnostics.diagnostics(), "RP2040 runtime CDC did not return before the unconfirmed-flash deadline"); + Err(FbuildError::DeployFailed(format!( "RP2040 firmware was transferred, but no catalogue-identified runtime CDC port appeared within {}s; verify that the firmware enables USB serial and that FastLED/boards USB data is current (extend the window with {POST_DEPLOY_TIMEOUT_ENV})", window.as_secs() - ))), + ))) + } } } @@ -1990,14 +2050,16 @@ mod tests { #[test] fn cdc_timeout_without_flash_confirmation_is_an_actionable_failure() { - let wait = wait_for_cdc_port_with( + let wait = wait_for_cdc_port_with_clock( Some("COM7"), None, &BTreeSet::from(["COM7".to_string()]), Duration::ZERO, || Ok(Vec::new()), + || Duration::ZERO, + |_| {}, ); - assert!(matches!(wait, Err(CdcWaitError::Timeout))); + assert!(matches!(wait, Err(CdcWaitError::Timeout(_)))); let error = resolve_post_flash_cdc(false, wait, Duration::from_secs(15)).unwrap_err(); let message = error.to_string(); assert!(message.contains("firmware was transferred")); @@ -2008,8 +2070,17 @@ mod tests { #[test] fn cdc_timeout_after_confirmed_flash_downgrades_to_unconfirmed_success() { let outcome = - resolve_post_flash_cdc(true, Err(CdcWaitError::Timeout), Duration::from_secs(15)) - .unwrap(); + resolve_post_flash_cdc( + true, + Err(CdcWaitError::Timeout(CdcWaitTimeout { + elapsed: Duration::from_secs(15), + previous_port: Some("COM7".to_string()), + requested_serial: Some("serial".to_string()), + candidates: Vec::new(), + })), + Duration::from_secs(15), + ) + .unwrap(); let PostFlashCdc::Unconfirmed(note) = outcome else { panic!("expected an unconfirmed-CDC downgrade, got {outcome:?}"); }; @@ -2019,12 +2090,36 @@ mod tests { assert!(note.contains(POST_DEPLOY_TIMEOUT_ENV)); } + #[test] + fn cdc_timeout_diagnostics_identify_the_prior_target_and_catalogue_candidates() { + let diagnostics = CdcWaitTimeout { + elapsed: Duration::from_secs(30), + previous_port: Some("COM12".to_string()), + requested_serial: Some("5303284720C4641C".to_string()), + candidates: vec![PicoCdcPort { + name: "COM27".to_string(), + serial_number: Some("5303284720C4641C".to_string()), + }], + } + .diagnostics(); + + assert!(diagnostics.contains("elapsed 30000ms")); + assert!(diagnostics.contains("prior port COM12")); + assert!(diagnostics.contains("requested serial 5303284720C4641C")); + assert!(diagnostics.contains("COM27 (serial 5303284720C4641C)")); + } + #[test] fn cdc_enumeration_error_fails_even_after_confirmed_flash() { - let wait = - wait_for_cdc_port_with(None, None, &BTreeSet::new(), Duration::from_secs(5), || { - Err(FbuildError::SerialError("enumeration exploded".into())) - }); + let wait = wait_for_cdc_port_with_clock( + None, + None, + &BTreeSet::new(), + Duration::from_secs(5), + || Err(FbuildError::SerialError("enumeration exploded".into())), + || Duration::ZERO, + |_| {}, + ); let error = resolve_post_flash_cdc(true, wait, Duration::from_secs(15)).unwrap_err(); assert!(error.to_string().contains("enumeration exploded")); } @@ -2042,10 +2137,73 @@ mod tests { } } + #[test] + fn delayed_matching_cdc_after_the_legacy_window_returns_its_new_port() { + let mut scans = 0; + let mut elapsed = [Duration::from_secs(16)].into_iter(); + let port = wait_for_cdc_port_with_clock( + Some("COM12"), + Some("5303284720C4641C"), + &BTreeSet::from(["COM12".to_string()]), + Duration::from_secs(30), + || { + scans += 1; + Ok(if scans == 1 { + Vec::new() + } else { + vec![PicoCdcPort { + name: "COM27".to_string(), + serial_number: Some("5303284720C4641C".to_string()), + }] + }) + }, + || elapsed.next().unwrap_or(Duration::from_secs(16)), + |_| {}, + ) + .expect("a matching delayed Pico CDC endpoint must be returned"); + + assert_eq!(port, "COM27"); + assert_eq!(scans, 2); + } + + #[test] + fn final_deadline_catalogue_scan_accepts_a_matching_renumbered_port() { + let mut scans = 0; + let mut elapsed = [Duration::from_secs(30)].into_iter(); + let port = wait_for_cdc_port_with_clock( + Some("COM12"), + Some("5303284720C4641C"), + &BTreeSet::from(["COM12".to_string()]), + Duration::from_secs(30), + || { + scans += 1; + Ok(vec![PicoCdcPort { + name: "COM27".to_string(), + serial_number: Some("5303284720C4641C".to_string()), + }]) + }, + || elapsed.next().unwrap_or(Duration::from_secs(30)), + |_| {}, + ) + .expect("the final catalogue scan must accept a boundary arrival"); + + assert_eq!(port, "COM27"); + assert_eq!(scans, 1); + } + + #[test] + fn rp2040_post_flash_cdc_policy_exceeds_the_legacy_15_second_window() { + assert_eq!(rp2040_post_deploy_timeout(), Duration::from_secs(30)); + } + #[test] fn ambiguous_cdc_selection_is_an_enumeration_error_not_a_timeout() { - let wait = wait_for_cdc_port_with(None, None, &BTreeSet::new(), Duration::ZERO, || { - Ok(vec![ + let wait = wait_for_cdc_port_with_clock( + None, + None, + &BTreeSet::new(), + Duration::ZERO, + || Ok(vec![ PicoCdcPort { name: "COM12".to_string(), serial_number: None, @@ -2054,8 +2212,10 @@ mod tests { name: "COM13".to_string(), serial_number: None, }, - ]) - }); + ]), + || Duration::ZERO, + |_| {}, + ); let error = resolve_post_flash_cdc(true, wait, Duration::from_secs(15)).unwrap_err(); assert!( error diff --git a/crates/fbuild-serial/src/boards.rs b/crates/fbuild-serial/src/boards.rs index bfe5318f..3fa1f772 100644 --- a/crates/fbuild-serial/src/boards.rs +++ b/crates/fbuild-serial/src/boards.rs @@ -290,6 +290,7 @@ impl BoardFamily { post_reset_settle_ms: 200, boot_drain_ms: 0, port_reappear_timeout_ms: 3000, + application_cdc_timeout_ms: 3000, open_retry_count: 5, }, // CDC-ACM bridge (LPC11U35): pyOCD reset settles in ~500 @@ -300,6 +301,7 @@ impl BoardFamily { post_reset_settle_ms: 500, boot_drain_ms: 2000, port_reappear_timeout_ms: 3000, + application_cdc_timeout_ms: 3000, open_retry_count: 3, }, // 1200-bps-touch bootloaders (Teensy HalfKay, SAMD UF2, @@ -308,10 +310,21 @@ impl BoardFamily { // again and reappears at the app VID/PID after flash. // Tolerate up to 5 s reappear + 10 open retries to ride // out the double-enumeration window. - Teensy | NativeUsbCdcReset1200Bps => HandoffTiming { + Teensy => HandoffTiming { post_reset_settle_ms: 100, boot_drain_ms: 500, port_reappear_timeout_ms: 5000, + application_cdc_timeout_ms: 5000, + open_retry_count: 10, + }, + // RP2040/SAMD 1200-bps-touch targets enumerate once for the ROM + // bootloader and again for the application. Windows can defer the + // second driver bind well beyond the bootloader handoff window. + NativeUsbCdcReset1200Bps => HandoffTiming { + post_reset_settle_ms: 100, + boot_drain_ms: 500, + port_reappear_timeout_ms: 5000, + application_cdc_timeout_ms: 30_000, open_retry_count: 10, }, // Arduino auto-reset: the bootloader's "wait for upload" @@ -323,6 +336,7 @@ impl BoardFamily { post_reset_settle_ms: 1500, boot_drain_ms: 0, port_reappear_timeout_ms: 0, + application_cdc_timeout_ms: 0, open_retry_count: 1, }, } @@ -356,6 +370,10 @@ pub struct HandoffTiming { /// to `0` for boards that don't drop the port at all (Arduino /// classic auto-reset). pub port_reappear_timeout_ms: u32, + /// How long to wait for the application CDC endpoint after a successful + /// flash. This can exceed the bootloader reappearance window when Windows + /// defers application-driver binding after the ROM volume disappears. + pub application_cdc_timeout_ms: u32, /// Max retries on transient open failures during the reappear /// window. Higher for boards with longer re-enumeration windows /// (Teensy / RP2040 — HalfKay / BOOTSEL). @@ -1545,6 +1563,7 @@ mod tests { assert_eq!(t.post_reset_settle_ms, 500); assert_eq!(t.boot_drain_ms, 2000); assert_eq!(t.port_reappear_timeout_ms, 3000); + assert_eq!(t.application_cdc_timeout_ms, 3000); assert_eq!(t.open_retry_count, 3); } @@ -1590,6 +1609,12 @@ mod tests { ); } + #[test] + fn handoff_timing_rp2040_allows_delayed_windows_application_cdc() { + let t = BoardFamily::NativeUsbCdcReset1200Bps.handoff_timing(); + assert_eq!(t.application_cdc_timeout_ms, 30_000); + } + #[test] fn new_variants_appear_in_family_for_vid_pid_classification() { // RP2040 → NativeUsbCdcReset1200Bps diff --git a/docs/usb-cdc-control-line-matrix.md b/docs/usb-cdc-control-line-matrix.md index 82b0a660..c514789e 100644 --- a/docs/usb-cdc-control-line-matrix.md +++ b/docs/usb-cdc-control-line-matrix.md @@ -238,16 +238,16 @@ filled in empirically without datasheet archaeology. Mentioned in ## Flash → monitor handoff timing (FastLED/fbuild#691) -| BoardFamily | `post_reset_settle_ms` | `boot_drain_ms` | `port_reappear_timeout_ms` | `open_retry_count` | -|---|---:|---:|---:|---:| -| `Esp32NativeUsbCdc` | 200 | 0 | 3000 | 5 | -| `Esp32ExternalUart` | 200 | 0 | 3000 | 5 | -| `CdcAcmBridge` (LPC11U35) | 500 | 2000 | 3000 | 3 | -| `Teensy` | 100 | 500 | 5000 | 10 | -| `NativeUsbCdcReset1200Bps` (RP2040/SAMD) | 100 | 500 | 5000 | 10 | -| `ArduinoAutoReset` | 1500 | 0 | 0 | 1 | - -Source: `crates/fbuild-serial/src/boards.rs::BoardFamily::handoff_timing`. The LPC11U35 row is from FastLED/FastLED#3339 (the bring-up incident). 1200-bps-touch rows tolerate the double-enumeration window (bootloader VID/PID then app VID/PID). Arduino has zero `port_reappear_timeout_ms` because the USB endpoint lives on the bridge chip and never drops. +| BoardFamily | `post_reset_settle_ms` | `boot_drain_ms` | `port_reappear_timeout_ms` | `application_cdc_timeout_ms` | `open_retry_count` | +|---|---:|---:|---:|---:|---:| +| `Esp32NativeUsbCdc` | 200 | 0 | 3000 | 3000 | 5 | +| `Esp32ExternalUart` | 200 | 0 | 3000 | 3000 | 5 | +| `CdcAcmBridge` (LPC11U35) | 500 | 2000 | 3000 | 3000 | 3 | +| `Teensy` | 100 | 500 | 5000 | 5000 | 10 | +| `NativeUsbCdcReset1200Bps` (RP2040/SAMD) | 100 | 500 | 5000 | 30000 | 10 | +| `ArduinoAutoReset` | 1500 | 0 | 0 | 0 | 1 | + +Source: `crates/fbuild-serial/src/boards.rs::BoardFamily::handoff_timing`. The LPC11U35 row is from FastLED/FastLED#3339 (the bring-up incident). 1200-bps-touch rows tolerate the double-enumeration window (bootloader VID/PID then app VID/PID). RP2040 uses a longer application-CDC window because Windows can defer the application-driver bind after the ROM volume disappears. Arduino has zero `port_reappear_timeout_ms` because the USB endpoint lives on the bridge chip and never drops. ## Ecosystem `upload.protocol` mapping (FastLED/fbuild#906)