From be046f341ceefa4aea5fae276ed17d024f5b7f82 Mon Sep 17 00:00:00 2001 From: Duncan Tourolle Date: Thu, 20 Aug 2026 19:16:26 +0200 Subject: [PATCH] Make the BLE layer say what it actually received MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Chasing a paddle that shifted on one platform and not the other cost several rebuilds, and most of that was spent unable to tell two very different situations apart: a pod that was sending nothing, and a pod whose frames we were receiving and quietly discarding. The logs looked identical because every decoder in this path fails by dropping. `click.rs` now logs every notification with its length and bytes before anything tries to interpret it, and the unhandled-frame line in `controller.rs` carries the payload rather than just the type byte — which is the least useful part of a frame you could not parse, since it is usually the framing that is wrong and not the content. The default log filter gains `bikecontrol_ble=debug`. It was `info`, which silenced the entire crate that owns every BLE conversation — subscribe failures included. Survivable on desktop where RUST_LOG can override it; not on Android, which has no environment to set and is exactly where the subscribe was failing. Adds `probe listen`, which decodes nothing on purpose: the GATT tree with descriptors (the CCCD value is where a subscribe goes wrong, and `inspect` stops short of it), then a subscribe to every notifying characteristic across all services, reporting each as ok or FAILED. Each notification prints characteristic, length and raw bytes, and the summary names the characteristics that stayed silent — the difference between a quiet device and listening in the wrong place. That last part is what settled this one: it recorded 304 button frames from a pod the app was reporting as dead. Co-Authored-By: Claude Opus 5 --- crates/ble/src/click.rs | 7 ++ crates/probe/src/cli.rs | 26 ++++- crates/probe/src/commands.rs | 182 +++++++++++++++++++++++++++++++++++ crates/probe/src/main.rs | 5 + src-tauri/src/controller.rs | 8 +- src-tauri/src/lib.rs | 7 +- 6 files changed, 232 insertions(+), 3 deletions(-) diff --git a/crates/ble/src/click.rs b/crates/ble/src/click.rs index f1167c0..49f46f5 100644 --- a/crates/ble/src/click.rs +++ b/crates/ble/src/click.rs @@ -26,6 +26,7 @@ use tokio::sync::{broadcast, mpsc, oneshot}; use crate::client::{Backoff, InFlight, DISCONNECT_TIMEOUT}; use crate::error::FtmsError; +use crate::indoor_bike_data::hex; use crate::scan::{self, ScanKind}; use crate::zwift::{self, Button, ButtonTracker, PodId}; @@ -541,6 +542,12 @@ impl Actor { /// Decode one notification into events. fn handle(&mut self, raw: &[u8]) { + // Every frame, before anything decides what it means (NFR-8). The + // decoders below all fail by dropping, so without this a pod that is + // talking and a pod that is silent produce identical logs — which is + // exactly the ambiguity that made a working paddle look like dead + // hardware. + tracing::debug!(len = raw.len(), raw = %hex(raw), "click: frame"); if zwift::is_ride_on_reply(raw) { tracing::debug!("click: RideOn acknowledged"); return; diff --git a/crates/probe/src/cli.rs b/crates/probe/src/cli.rs index ca16d0a..4d7b8cc 100644 --- a/crates/probe/src/cli.rs +++ b/crates/probe/src/cli.rs @@ -21,6 +21,9 @@ SUBCOMMANDS: monitor Stream Indoor Bike Data as raw hex alongside decoded fields set Take control and apply a target, then reset the trainer to zero zwift Talk to Zwift's custom service: handshake, then log every frame + listen Raw GATT: dump services, characteristics and descriptors, then + subscribe to everything and print each notification's + characteristic, length and bytes, undecoded TARGET (for `set`): gradient= SetTargetInclination (0x03), e.g. gradient=4.5 @@ -33,7 +36,9 @@ OPTIONS: scan 6, monitor 30, set 15, zwift 60) --all `scan`: list every peripheral, not just fitness machines --name use in place of to match on advertised name - --no-handshake `zwift`: subscribe and listen without writing RideOn + --no-handshake `zwift`, `listen`: subscribe and listen without writing RideOn. + `listen` greets by default, because a Click that has not been + greeted sends nothing and an empty capture proves nothing --buttons `zwift`: collapse the ~10 Hz button stream to one line per press and release, for mapping bits to physical buttons -v, --verbose debug-level logging, including every raw BLE frame (NFR-8) @@ -70,6 +75,20 @@ pub enum Command { simulation: bool, hold: Duration, }, + /// Raw GATT interrogation: the whole tree including descriptors, then every + /// notifying characteristic dumped as unparsed bytes. + /// + /// Deliberately knows nothing about FTMS or Zwift. When a device works on + /// one platform and not another, the question is which characteristic + /// carried what and how long it was — and any decoding layer is exactly + /// what you cannot trust while asking it. + Listen { + device: Device, + duration: Duration, + /// Write the Zwift `RideOn` handshake first. A Click streams nothing + /// until it is greeted, so listening alone hears silence from one. + handshake: bool, + }, /// Phase 3 / TASK-0: exercise Zwift's custom service on whatever advertises /// it — a Click, or the trainer itself. Zwift { @@ -190,6 +209,11 @@ pub fn parse>(argv: I) -> Result { hold: Duration::from_secs(secs.unwrap_or(15)), } } + "listen" => Command::Listen { + device: device(&positional, 1)?, + duration: Duration::from_secs(secs.unwrap_or(60)), + handshake: !no_handshake, + }, "zwift" => Command::Zwift { device: device(&positional, 1)?, duration: Duration::from_secs(secs.unwrap_or(60)), diff --git a/crates/probe/src/commands.rs b/crates/probe/src/commands.rs index 4dfaa3a..76812e5 100644 --- a/crates/probe/src/commands.rs +++ b/crates/probe/src/commands.rs @@ -1131,3 +1131,185 @@ mod tests { assert_eq!(properties(CharPropFlags::empty()), "(none)"); } } + +// --------------------------------------------------------------------------- +// listen +// --------------------------------------------------------------------------- + +/// Raw GATT interrogation, with no idea what any of it means. +/// +/// Every other subcommand decodes something. This one deliberately does not: +/// it prints the tree, subscribes to everything that will have it, and reports +/// each notification as a characteristic, a length and some bytes. +/// +/// That combination is what a cross-platform disagreement needs. When a device +/// behaves on one backend and not another, the useful questions are *which* +/// characteristic carried the data and *how many bytes arrived* — and a decoder +/// answers neither, because its failure mode is to drop the frame silently and +/// leave you looking at nothing. A length printed next to a truncated payload +/// says more than a parse error ever does. +pub async fn listen( + device: &Device, + duration: Duration, + do_handshake: bool, + scan_timeout: Duration, +) -> Result<()> { + let peripheral = connect(device, scan_timeout).await?; + + if let Some(d) = scan::describe(&peripheral).await { + println!("Connected to {} ({})", d.address, d.label()); + if let Some(kind) = d.zwift_kind() { + println!("Advertised as: {}", kind.describe()); + } + println!(); + } + + // The whole tree first, so the capture below can be read months later + // without the device to hand. + println!("=== GATT tree ===\n"); + let mut notifying: Vec = Vec::new(); + for service in peripheral.services() { + println!( + "service {}{}{}", + service.uuid, + named(service.uuid), + if service.primary { " [primary]" } else { "" } + ); + for ch in &service.characteristics { + let subscribable = ch + .properties + .intersects(CharPropFlags::NOTIFY | CharPropFlags::INDICATE); + println!( + " char {}{}\n properties: {}{}", + ch.uuid, + named(ch.uuid), + properties(ch.properties), + if subscribable { " <- will subscribe" } else { "" } + ); + // Descriptors are the part `inspect` omits, and the CCCD is exactly + // where a subscribe goes wrong: its value says whether the platform + // enabled notification, indication, or nothing at all. + for d in &ch.descriptors { + match peripheral.read_descriptor(d).await { + Ok(v) => println!( + " descriptor {}{} = {}", + d.uuid, + named(d.uuid), + hex(&v) + ), + Err(e) => println!( + " descriptor {}{} ", + d.uuid, + named(d.uuid) + ), + } + } + if subscribable { + notifying.push(ch.clone()); + } + } + println!(); + } + + if notifying.is_empty() { + println!("!! Nothing here notifies or indicates. There is nothing to listen to."); + disconnect(&peripheral).await; + return Ok(()); + } + + let mut notifications = peripheral.notifications().await?; + let start = Instant::now(); + + println!("=== Subscribing ===\n"); + let mut live = 0usize; + for ch in ¬ifying { + match peripheral.subscribe(ch).await { + Ok(()) => { + live += 1; + println!(" ok {}{}", ch.uuid, named(ch.uuid)); + } + // Reported rather than fatal: one characteristic refusing is itself + // the finding, and the others may still carry what we came for. + Err(e) => println!(" FAILED {}{} — {e}", ch.uuid, named(ch.uuid)), + } + } + println!("\n{live} of {} subscribed.\n", notifying.len()); + + let mut frames: u64 = 0; + if do_handshake { + let service = zwift::SERVICES + .iter() + .find_map(|want| peripheral.services().into_iter().find(|s| s.uuid == *want)); + match service.as_ref().and_then(writable) { + Some(sync_rx) => { + frames += handshake(&peripheral, &sync_rx, &mut notifications, start).await?; + } + None => println!( + "No writable Zwift characteristic — greeting skipped. A Click will stay\n\ + silent; anything that streams unprompted will not care.\n" + ), + } + } else { + println!("--no-handshake: writing nothing.\n"); + } + + println!( + "Listening for {} s. Press buttons; Ctrl-C to stop early.\n", + duration.saturating_sub(start.elapsed()).as_secs() + ); + println!(" time # characteristic len bytes"); + + let deadline = tokio::time::sleep(duration.saturating_sub(start.elapsed())); + tokio::pin!(deadline); + + // Per characteristic, so a summary can show which ones ever spoke — the + // difference between "the pod is silent" and "we were listening in the + // wrong place". + let mut counts: std::collections::BTreeMap = Default::default(); + + loop { + tokio::select! { + _ = &mut deadline => break, + _ = tokio::signal::ctrl_c() => { + println!("\nInterrupted."); + break; + } + n = notifications.next() => { + let Some(n) = n else { + println!("\nNotification stream ended (the device disconnected)."); + break; + }; + frames += 1; + let entry = counts.entry(n.uuid).or_insert((0, 0)); + entry.0 += 1; + entry.1 = entry.1.max(n.value.len()); + println!( + " {:6.2}s #{:<4} {}{:<8} {:>3} {} {}", + start.elapsed().as_secs_f32(), + frames, + n.uuid, + named(n.uuid), + n.value.len(), + hex(&n.value), + as_text(&n.value), + ); + } + } + } + + println!("\n=== {frames} frames ===\n"); + for (uuid, (count, longest)) in &counts { + println!(" {uuid}{} {count} frames, longest {longest} bytes", named(*uuid)); + } + for ch in ¬ifying { + if !counts.contains_key(&ch.uuid) { + println!(" {}{} silent", ch.uuid, named(ch.uuid)); + } + } + + for ch in ¬ifying { + let _ = peripheral.unsubscribe(ch).await; + } + disconnect(&peripheral).await; + Ok(()) +} diff --git a/crates/probe/src/main.rs b/crates/probe/src/main.rs index f32f9a5..c686b28 100644 --- a/crates/probe/src/main.rs +++ b/crates/probe/src/main.rs @@ -49,6 +49,11 @@ async fn main() -> Result<()> { simulation, hold, } => commands::set(&device, target, simulation, hold, SCAN_TIMEOUT).await, + cli::Command::Listen { + device, + duration, + handshake, + } => commands::listen(&device, duration, handshake, SCAN_TIMEOUT).await, cli::Command::Zwift { device, duration, diff --git a/src-tauri/src/controller.rs b/src-tauri/src/controller.rs index d54105b..8efc024 100644 --- a/src-tauri/src/controller.rs +++ b/src-tauri/src/controller.rs @@ -995,9 +995,15 @@ fn apply( pod: pod.into(), }); } - ClickEvent::Unknown { kind, .. } => { + ClickEvent::Unknown { kind, raw } => { + // The bytes, not just the type. A frame we cannot read is the one + // case where the type byte is the least useful part of it — it is + // very often the *framing* that is wrong rather than the content, + // and without the payload there is nothing to tell the two apart + // (NFR-8). tracing::debug!( pod = pod.as_str(), + raw = %raw.iter().map(|b| format!("{b:02x}")).collect::(), "controller: unhandled frame type 0x{kind:02x}" ) } diff --git a/src-tauri/src/lib.rs b/src-tauri/src/lib.rs index d7a9710..dc1e79c 100644 --- a/src-tauri/src/lib.rs +++ b/src-tauri/src/lib.rs @@ -28,7 +28,12 @@ use crate::state::AppState; /// Set up `tracing` for whatever this platform calls "somewhere I can read it". fn init_tracing() { let filter = tracing_subscriber::EnvFilter::try_from_default_env() - .unwrap_or_else(|_| "info,bikecontrol_app_lib=debug".into()); + // `bikecontrol_ble` belongs here as much as the shell does: it owns every + // BLE conversation, so leaving it at `info` silences exactly the frames + // NFR-8 says must be loggable — subscribe failures, bad button frames, + // the lot. That is survivable on desktop, where RUST_LOG can override + // it, and not on Android, where there is no environment to set. + .unwrap_or_else(|_| "info,bikecontrol_app_lib=debug,bikecontrol_ble=debug".into()); // Android has no stdout: the default writer would drop every line. See // `android::Logcat`.