diff --git a/crates/ble/src/scan.rs b/crates/ble/src/scan.rs index d8cf294..391907b 100644 --- a/crates/ble/src/scan.rs +++ b/crates/ble/src/scan.rs @@ -1,7 +1,9 @@ //! BLE discovery (FR-1.1, FR-1.2). -use std::collections::HashMap; -use std::time::Duration; +use std::collections::{HashMap, VecDeque}; +use std::sync::atomic::{AtomicUsize, Ordering}; +use std::sync::Mutex; +use std::time::{Duration, Instant}; use btleplug::api::{Central, Manager as _, Peripheral as _, ScanFilter}; use btleplug::platform::{Adapter, Manager, Peripheral, PeripheralId}; @@ -114,24 +116,129 @@ impl ScanKind { } } +/// How many discovery sessions this process currently has open. +/// +/// The adapter has **one** radio, and four independent supervisors ask it to +/// discover: the device list (`devices::scan_loop`, a 2.5 s pass every ~2.9 s), +/// the trainer client (15 s), the controller (20 s per pod attempt, up to 30 +/// attempts), and the heart rate monitor. Only the first two are coordinated — +/// `DeviceRegistry::connect` suspends the list scan for a trainer connect +/// precisely so the two do not fight (devices.rs) — and a pod search routinely +/// runs its full 20 s because a Click only advertises after a button press. +/// +/// So this counts. Every start and stop below logs the depth and who is +/// holding it; a line reading `depth=2` names both competitors and is the +/// evidence that a failed connect was a contended radio rather than a sleeping +/// peripheral. Diagnostic only — nothing here changes what the radio does. +static DISCOVERY_DEPTH: AtomicUsize = AtomicUsize::new(0); + +/// Android's rule, and the one this app kept breaking: five scan *starts* in +/// any thirty seconds and the platform stops returning results. +const THROTTLE_WINDOW: Duration = Duration::from_secs(30); +const THROTTLE_STARTS: usize = 5; + +/// When each recent session was opened, for the rate check below. +static STARTS: Mutex> = Mutex::new(VecDeque::new()); + +/// Announce a discovery session opening, and return the depth including it. +/// +/// Logs two different problems, because they have different fixes: `depth > 1` +/// is two searches sharing one radio, and a start rate at the platform's limit +/// is the app about to be muted by Android whether or not anything is sharing. +fn discovery_opened(who: &str) -> usize { + let depth = DISCOVERY_DEPTH.fetch_add(1, Ordering::SeqCst) + 1; + + let recent = { + let now = Instant::now(); + let mut starts = STARTS.lock().unwrap_or_else(|e| e.into_inner()); + while starts.front().is_some_and(|t| now.duration_since(*t) > THROTTLE_WINDOW) { + starts.pop_front(); + } + starts.push_back(now); + starts.len() + }; + + if recent >= THROTTLE_STARTS { + tracing::warn!( + who, + recent, + depth, + "discovery: {recent} scan starts in the last 30 s — at Android's limit, \ + where further scans return nothing at all" + ); + } else if depth > 1 { + tracing::warn!( + who, + depth, + recent, + "discovery: sharing the radio with another search — connects may time out" + ); + } else { + tracing::debug!(who, depth, recent, "discovery: start"); + } + depth +} + +fn discovery_closed(who: &str, outcome: &str) { + let depth = DISCOVERY_DEPTH.fetch_sub(1, Ordering::SeqCst).saturating_sub(1); + tracing::debug!(who, depth, outcome, "discovery: stop"); +} + +/// Open a discovery session and leave it open. +/// +/// Paired with [`end`], and sampled meanwhile with [`peek`]. The three exist +/// separately because **starting a scan is the expensive act on Android**, not +/// running one: since Android 7 the platform counts an app's scan *starts* and +/// refuses it with `SCAN_FAILED_SCANNING_TOO_FREQUENTLY` after five in thirty +/// seconds — silently, as far as btleplug is concerned, so the app goes on +/// asking and simply stops being told about anything. +/// +/// A caller that wants a live list therefore has to hold one session and +/// sample it, rather than restart one per refresh. See `devices::scan_loop`. +pub async fn begin(adapter: &Adapter, kind: ScanKind, who: &str) -> Result<(), FtmsError> { + adapter.start_scan(kind.filter()).await?; + discovery_opened(who); + Ok(()) +} + +/// Everything the open session has seen so far. Does not touch the session. +pub async fn peek(adapter: &Adapter, kind: ScanKind) -> Result, FtmsError> { + let peripherals = adapter.peripherals().await?; + Ok(collect(peripherals, kind).await) +} + +/// Close a session opened by [`begin`]. Best effort: a failure to stop is worth +/// a line in the log and nothing more, since the next start subsumes it. +pub async fn end(adapter: &Adapter, who: &str, outcome: &str) { + if let Err(e) = adapter.stop_scan().await { + tracing::debug!(error = %e, "stop_scan failed"); + } + discovery_closed(who, outcome); +} + /// Scan for `duration` and return everything seen. /// /// Devices may be asleep (A-4) — a trainer often does not advertise until it is /// pedalled. An empty result means "nothing was advertising", not "no such /// device exists"; FR-1.8 requires the UI to say so. +/// +/// One session per call, so this is for one-shot callers — the probe tool, a +/// test. Anything refreshing on a timer wants [`begin`]/[`peek`]/[`end`]. pub async fn scan( adapter: &Adapter, duration: Duration, kind: ScanKind, ) -> Result, FtmsError> { - adapter.start_scan(kind.filter()).await?; + begin(adapter, kind, "device list").await?; tokio::time::sleep(duration).await; let peripherals = adapter.peripherals().await?; - // Stopping the scan is best effort; a failure here must not lose results. - if let Err(e) = adapter.stop_scan().await { - tracing::debug!(error = %e, "stop_scan failed"); - } + end(adapter, "device list", "listed").await; + Ok(collect(peripherals, kind).await) +} + +/// Describe, filter and rank what the radio handed back. +async fn collect(peripherals: Vec, kind: ScanKind) -> Vec { let mut out = Vec::with_capacity(peripherals.len()); for p in peripherals { if let Some(d) = describe(&p).await { @@ -143,7 +250,7 @@ pub async fn scan( } } out.sort_by(|a, b| b.rssi.unwrap_or(i16::MIN).cmp(&a.rssi.unwrap_or(i16::MIN))); - Ok(out) + out } /// Convenience wrapper: scan the default adapter for trainers. @@ -261,6 +368,7 @@ pub async fn find_matching( matches: impl Fn(&DiscoveredDevice) -> bool, ) -> Result { adapter.start_scan(kind.filter()).await?; + discovery_opened(what); let deadline = tokio::time::Instant::now() + timeout; let poll = Duration::from_millis(400); @@ -291,6 +399,7 @@ pub async fn find_matching( if let Err(e) = adapter.stop_scan().await { tracing::debug!(error = %e, "stop_scan failed"); } + discovery_closed(what, if found.is_some() { "matched" } else { "timed out" }); found.ok_or_else(|| FtmsError::NotFound(what.to_string())) } diff --git a/src-tauri/src/devices.rs b/src-tauri/src/devices.rs index 0e718c1..7ccd2b1 100644 --- a/src-tauri/src/devices.rs +++ b/src-tauri/src/devices.rs @@ -35,9 +35,27 @@ use crate::heart_rate::{HeartRateHandle, HeartRateStatus}; use crate::known::KnownDevices; use crate::trainer::{TrainerHandle, TrainerStatus}; -/// One pass of the scanner. Long enough for a trainer to advertise, short -/// enough that the list feels live. -const SCAN_WINDOW: Duration = Duration::from_millis(2500); +/// How long one discovery session is held before it is recycled. +/// +/// **This is a rate limit, not a dwell time.** Since Android 7 the platform +/// counts an app's scan *starts* and blocks it with +/// `SCAN_FAILED_SCANNING_TOO_FREQUENTLY` after five in any thirty seconds — and +/// it does so silently, so the app keeps asking and simply stops being told +/// about anything. This loop used to open a session every 2.9 s: **ten starts +/// per thirty seconds, double the limit, all by itself**, before the trainer's +/// 15 s search or a pod's 20 s search asked for one too. A rider who woke their +/// pods first spent the pods' search window pushing the count over, and then +/// the trainer could not be found — not because it was not advertising, but +/// because the app was no longer allowed to hear it. +/// +/// One session per twenty seconds is three starts a minute with the connect +/// paths included, which leaves headroom under the limit on the worst day. +const SCAN_WINDOW: Duration = Duration::from_secs(20); +/// How often the open session is sampled. The list is republished each time, so +/// this — not [`SCAN_WINDOW`] — is how live the screen feels, and it is now +/// four times quicker than the old whole-pass cadence while starting the radio +/// a seventh as often. +const SCAN_SAMPLE: Duration = Duration::from_millis(700); /// Poll interval while scanning is switched off. const IDLE_POLL: Duration = Duration::from_millis(400); /// How long to wait before looking for the adapter again. Longer than the scan @@ -897,30 +915,71 @@ async fn scan_loop(mut on: watch::Receiver, tx: watch::Sender ScanSnapshot { - devices, - error: None, + if let Err(e) = scan::begin(&adapter, ScanKind::All, "device list").await { + // Debug as well as Display, because the useful half of a BLE + // failure is usually in the source chain that Display drops. + // "bluetooth error: JNI call failed" was the *entire* symptom of a + // detached-thread bug; the Debug form said + // `Bluetooth(Other(JniCall(ThreadDetached)))` and would have named + // it outright. + tracing::warn!(error = %e, cause = ?e, "scan failed to start"); + generation += 1; + let _ = tx.send(ScanSnapshot { + devices: Vec::new(), + error: Some(e.to_string()), generation, - }, - Err(e) => { - // Debug as well as Display, because the useful half of a BLE - // failure is usually in the source chain that Display drops. - // "bluetooth error: JNI call failed" was the *entire* symptom of - // a detached-thread bug; the Debug form said - // `Bluetooth(Other(JniCall(ThreadDetached)))` and would have - // named it outright. - tracing::warn!(error = %e, cause = ?e, "scan failed"); - ScanSnapshot { - devices: Vec::new(), - error: Some(e.to_string()), - generation, + }); + tokio::time::sleep(ADAPTER_RETRY).await; + continue; + } + + // Sample the open session until the window is up — or until the scan is + // switched off, which must be honoured *now* rather than at the end of + // the window. A connect suspends this loop precisely so the two do not + // fight over the radio, and a suspension that took twenty seconds to + // land would be no suspension at all. + let window_ends = tokio::time::Instant::now() + SCAN_WINDOW; + let mut outcome = "recycled"; + loop { + tokio::select! { + _ = tokio::time::sleep(SCAN_SAMPLE) => {} + changed = on.changed() => { + if changed.is_err() || !*on.borrow() { + outcome = "suspended"; + break; + } } } - }; - let _ = tx.send(snapshot); + generation += 1; + match scan::peek(&adapter, ScanKind::All).await { + Ok(devices) => { + let _ = tx.send(ScanSnapshot { + devices, + error: None, + generation, + }); + } + Err(e) => { + tracing::warn!(error = %e, cause = ?e, "scan sample failed"); + let _ = tx.send(ScanSnapshot { + devices: Vec::new(), + error: Some(e.to_string()), + generation, + }); + outcome = "failed"; + break; + } + } + if tokio::time::Instant::now() >= window_ends { + break; + } + } + + // Recycled rather than held forever: a peripheral that stops + // advertising stays in the backend's map until the session ends, so + // without this the list would accumulate devices that left the room. + // Twenty seconds is how stale a departed device may look. + scan::end(&adapter, "device list", outcome).await; tokio::time::sleep(IDLE_POLL).await; } }