diff --git a/crates/ble/src/click.rs b/crates/ble/src/click.rs index 9516f4e..f1167c0 100644 --- a/crates/ble/src/click.rs +++ b/crates/ble/src/click.rs @@ -464,6 +464,11 @@ impl Actor { continue; } + // Said out loud: a rider reporting that a pod "keeps dropping" needs + // the log to show whether the radio link actually ended, and this is + // the moment it did. The stream ending is BlueZ's only notice. + tracing::warn!(address = %self.selector.describe(), "click: notification stream ended — link dropped"); + // Release anything still held, so a paddle held through a dropout // cannot latch (see ButtonTracker::reset). self.release_held(); diff --git a/src-tauri/src/controller.rs b/src-tauri/src/controller.rs index c60610e..d54105b 100644 --- a/src-tauri/src/controller.rs +++ b/src-tauri/src/controller.rs @@ -45,9 +45,20 @@ use bikecontrol_ble::{Backoff, FtmsError, PodSelector}; use serde::{Deserialize, Serialize}; use tokio::sync::{mpsc, oneshot, watch}; -/// How long a controller may stay silent before we call it stale. The pod sends -/// a battery heartbeat every ~5 s even when idle, so 20 s is four missed beats. -const STALE_AFTER: Duration = Duration::from_secs(20); +/// How long a connected pod may stay silent before the screen says so. +/// +/// This used to be 20 s, on the stated grounds that "the pod sends a battery +/// heartbeat every ~5 s even when idle". **Nothing confirms that** — §2.3.1 +/// establishes the battery frame's *format*, never its cadence, and a two-minute +/// capture with both pods connected recorded six frames from one pod and none at +/// all from the other. A Click's whole character is to be quiet. +/// +/// So the old window was shorter than an ordinary gap between shifts, and a pod +/// that was working perfectly was declared stale for the crime of not being +/// pressed. Three minutes is longer than any silence a working link plausibly +/// explains, and the silence is logged when it fires so the next ride's log can +/// replace this guess with the pods' real cadence. +const STALE_AFTER: Duration = Duration::from_secs(180); /// Upper bound on closing the controller links at exit. Shorter than the /// trainer's: there is no reset sequence here, only an unsubscribe and a /// disconnect, and this budget is spent on the same window close (NFR-9). @@ -687,15 +698,23 @@ async fn run( _ = housekeeping.tick() => { for (id, slot) in [(PodId::Minus, &minus), (PodId::Plus, &plus)] { + let silence = slot.last_seen.map(|t| t.elapsed()); let silent = slot.client.is_some() - && slot.last_seen.is_some_and(|t| t.elapsed() > STALE_AFTER); + && silence.is_some_and(|s| s > STALE_AFTER); if silent { - // Not an error: the BLE layer is already retrying. Say - // so rather than show a connected pod that is not - // talking. + // A guess, and marked as one in the log. The link may be + // perfectly alive and the rider simply not shifting; the + // truth about a dropped link comes from the BLE layer, + // which says `Disconnected` when the stream ends. The + // first frame to arrive takes this back. status_tx.send_modify(|s| { let p = s.get_mut(id); if p.state == PodState::Connected { + tracing::info!( + pod = id.as_str(), + silent_s = silence.map(|s| s.as_secs()), + "controller: pod has gone quiet; showing it as reconnecting" + ); p.state = PodState::Reconnecting; } }); @@ -861,6 +880,23 @@ fn handle_event( } Ok(event) => { slot.last_seen = Some(tokio::time::Instant::now()); + // A frame is proof the link is up, and it is the *only* proof that + // ever arrives — the pod does not announce that it has started + // talking again. Without this, the staleness sweep below was a one- + // way door: a pod flipped to `Reconnecting` for going quiet stayed + // there for the rest of the ride, shifting perfectly while the + // screen said it was lost. `Disconnected` and `GaveUp` are excluded + // because they are the link reporting its own end. + if !matches!(event, ClickEvent::Disconnected | ClickEvent::GaveUp { .. }) { + status_tx.send_modify(|s| { + let p = s.get_mut(pod); + if p.state == PodState::Reconnecting { + tracing::info!(pod = pod.as_str(), "controller: pod talking again"); + p.state = PodState::Connected; + p.error = None; + } + }); + } apply(pod, event, buttons, status_tx, input_tx); } // Lagged means we fell behind the pod, not that it left. One of the @@ -899,6 +935,11 @@ fn apply( p.error = None; }), ClickEvent::Disconnected => { + // Loud, because this is the one report of a genuinely dropped link — + // everything else on this screen is inference. A ride that says it + // keeps losing a pod is either this line repeating or it is not, + // and those two want opposite fixes. + tracing::info!(pod = pod.as_str(), "controller: link dropped; the BLE layer is retrying"); // The BLE layer releases what it was holding before it says this, // so the merge is usually already clear; doing it again costs // nothing and covers the edge it cannot (see `Buttons::forget`). @@ -914,6 +955,10 @@ fn apply( }) } ClickEvent::Battery { percent } => { + // Logged for its *timing*, not its value: how often a pod volunteers + // one is what `STALE_AFTER` is guessing at, and one ride's log + // settles it. + tracing::debug!(pod = pod.as_str(), percent, "controller: battery"); status_tx.send_modify(|s| s.get_mut(pod).battery_percent = Some(percent)) } ClickEvent::Button { button, pressed } => { @@ -1215,6 +1260,69 @@ mod tests { assert_eq!(status_rx.borrow().plus.buttons_seen, 2); } + /// A pod flipped to `Reconnecting` for going quiet must come back the + /// moment it says anything. Without this the flag was a one-way door: the + /// card read "Reconnecting…" for the rest of the ride while the paddle + /// shifted perfectly, which is indistinguishable from losing the pod. + #[test] + fn a_quiet_pod_that_speaks_again_is_connected_again() { + let (status_tx, status_rx) = watch::channel(ControllerStatus::default()); + let (input_tx, _) = tokio::sync::broadcast::channel(8); + let mut slot = Slot::default(); + let mut buttons = Buttons::default(); + + // What the staleness sweep does to a pod nobody has pressed. + status_tx.send_modify(|s| { + let p = s.get_mut(PodId::Minus); + p.state = PodState::Reconnecting; + }); + + handle_event( + PodId::Minus, + Ok(ClickEvent::Battery { percent: 90 }), + &mut slot, + &mut buttons, + &status_tx, + &input_tx, + ); + + assert_eq!(status_rx.borrow().minus.state, PodState::Connected); + assert_eq!(status_rx.borrow().minus.battery_percent, Some(90)); + } + + #[test] + fn the_link_reporting_its_own_end_is_not_taken_as_proof_of_life() { + // `Disconnected` arrives on the same stream as everything else, so the + // rule above has to exclude it or a drop would announce itself as a + // recovery. + let (status_tx, status_rx) = watch::channel(ControllerStatus::default()); + let (input_tx, _) = tokio::sync::broadcast::channel(8); + let mut slot = Slot::default(); + let mut buttons = Buttons::default(); + status_tx.send_modify(|s| s.get_mut(PodId::Plus).state = PodState::Connected); + + handle_event( + PodId::Plus, + Ok(ClickEvent::Disconnected), + &mut slot, + &mut buttons, + &status_tx, + &input_tx, + ); + assert_eq!(status_rx.borrow().plus.state, PodState::Reconnecting); + } + + #[test] + fn a_pod_is_not_called_stale_before_a_rider_could_plausibly_shift_twice() { + // The window this replaced was 20 s, which is shorter than an ordinary + // gap between shifts on a flat road — so a working pod was declared + // lost for not being pressed. + assert!( + STALE_AFTER >= Duration::from_secs(120), + "a Click is quiet by nature: {STALE_AFTER:?} will fire on a healthy pod" + ); + } + #[test] fn a_swap_relabels_the_pods_without_releasing_what_is_held() { let mut b = Buttons::default();