rust/bt-broadcast-assistant: Add debug logging
Add debug! and trace! logging throughout Broadcast Assistant,
delegator Peer wrapper, and BASS client to improve visibility into
broadcast source discovery, delegator connection, and BASS operations:
- In assistant: log starting event stream, delegator scanning,
delegator connection, BASS service discovery, and force-discovery
calls.
- In peer: log BASS client wrapper initialization, adding broadcast
sources, updating synchronization, removing sources, sending
broadcast codes, informing remote scan state, and processing BASS
notification events.
- In bt-bass: log BASS client characteristic discovery, BASS
notifications on characteristic handles, and updated receive state.
- Add unit tests in debug.rs verifying AssistantCmd::Verbose verbosity
updates and scoped command execution with -v and -vv flags.
Test: cargo test -p bt-broadcast-assistant -p bt-bass
cargo test --workspace
Change-Id: I9c4e875bd172feec7aaf2861c934e05d6a6a6964
Reviewed-on: https://bluetooth-review.googlesource.com/c/bluetooth/+/4122
diff --git a/rust/bt-bass/src/client.rs b/rust/bt-bass/src/client.rs
index b74c268..e8db074 100644
--- a/rust/bt-bass/src/client.rs
+++ b/rust/bt-bass/src/client.rs
@@ -132,6 +132,12 @@
}
let bascp_handle = *bascp[0].handle();
let brs_chars = Self::discover_brs_characteristics(&gatt_client).await?;
+ log::debug!(
+ "BASS client initialized: control point handle={:?}, {} BRS characteristic(s)",
+ bascp_handle,
+ brs_chars.len()
+ );
+ log::trace!("Discovered BRS characteristics: {:?}", brs_chars);
let mut c = Self {
gatt_client,
audio_scan_control_point: bascp_handle,
@@ -390,6 +396,17 @@
brs
}
+ /// Returns the handle of the Broadcast Audio Scan Control Point
+ /// characteristic.
+ pub fn audio_scan_control_point(&self) -> Handle {
+ self.audio_scan_control_point
+ }
+
+ /// Looks up the Source ID assigned to a Broadcast ID if known.
+ pub fn source_id(&self, broadcast_id: &BroadcastId) -> Option<SourceId> {
+ self.broadcast_sources.lock().source_id(broadcast_id)
+ }
+
#[cfg(any(test, feature = "test-utils"))]
pub fn insert_broadcast_receive_state(&mut self, handle: Handle, brs: BroadcastReceiveState) {
self.broadcast_sources.lock().update_state(handle, brs);
diff --git a/rust/bt-bass/src/client/event.rs b/rust/bt-bass/src/client/event.rs
index 3586568..e5b194a 100644
--- a/rust/bt-bass/src/client/event.rs
+++ b/rust/bt-bass/src/client/event.rs
@@ -150,10 +150,26 @@
let char_handle = notification.handle;
let (Ok(new_state), _) = BroadcastReceiveState::decode(notification.value.as_slice())
else {
+ log::trace!("Failed to decode BASS notification on handle {:?}", char_handle);
self.event_queue.push_back(Ok(Event::UnknownPacket));
continue;
};
+ log::debug!(
+ "Processing BASS notification for characteristic handle {:?}: {:?}",
+ char_handle,
+ new_state
+ );
+ if let BroadcastReceiveState::NonEmpty(ref state) = new_state {
+ let bad_code = matches!(state.big_encryption(), EncryptionStatus::BadCode(_));
+ log::trace!(
+ "Updated BroadcastReceiveState: PA sync state={:?}, BIG encryption={:?}, bad code flag={}",
+ state.pa_sync_state(),
+ state.big_encryption(),
+ bad_code
+ );
+ }
+
let maybe_prev_state = {
let mut lock = self.broadcast_sources.lock();
lock.update_state(char_handle, new_state.clone())
diff --git a/rust/bt-broadcast-assistant/src/assistant.rs b/rust/bt-broadcast-assistant/src/assistant.rs
index 98883db..9c56a44 100644
--- a/rust/bt-broadcast-assistant/src/assistant.rs
+++ b/rust/bt-broadcast-assistant/src/assistant.rs
@@ -137,6 +137,7 @@
if self.is_started() {
return Err(Error::AlreadyStarted);
}
+ log::debug!("Starting Broadcast Assistant event stream and scanning for broadcast sources");
let scan_result_stream = self.central.scan(&Self::scan_filters());
self.broadcast_source_scan_started.store(true, Ordering::Relaxed);
@@ -152,6 +153,7 @@
);
})
.ok();
+ log::trace!("Periodic advertising support available: {}", periodic_advertising.is_some());
Ok(EventStream::<T>::new(
scan_result_stream,
@@ -172,6 +174,10 @@
"Cannot scan for scan delegators while scanning for broadcast sources"
)));
}
+ log::debug!(
+ "Scanning for scan delegators with filter for BASS service UUID {:?}",
+ BROADCAST_AUDIO_SCAN_SERVICE
+ );
// Scan for service data with Broadcast Audio Scan Service UUID to look
// for Broadcast Sink collocated with the Scan Delegator (see BAP spec
// v1.0.1 Section 3.9.2 for details).
@@ -182,22 +188,33 @@
where
<T as bt_gatt::GattTypes>::NotificationStream: std::marker::Send,
{
+ log::debug!("Connecting to scan delegator peer {:?}", peer_id);
let client = self.central.connect(peer_id).await?;
+ log::trace!("Discovering BASS service on peer {:?}", peer_id);
let service_handles = client.find_service(BROADCAST_AUDIO_SCAN_SERVICE).await?;
+ log::trace!(
+ "Found {} service handle(s) matching BASS UUID for peer {:?}",
+ service_handles.len(),
+ peer_id
+ );
for handle in service_handles {
if handle.uuid() != BROADCAST_AUDIO_SCAN_SERVICE || !handle.is_primary() {
continue;
}
+ log::trace!("Connecting to primary BASS service handle on peer {:?}", peer_id);
let service = handle.connect().await?;
+ log::trace!("Creating BroadcastAudioScanServiceClient for peer {:?}", peer_id);
let bass = BroadcastAudioScanServiceClient::<T>::create(service)
.await
.map_err(|e| Error::BassClient(peer_id, e))?;
+ log::debug!("Creating Peer wrapper for peer {:?}", peer_id);
let connected_peer =
Peer::<T>::new(peer_id, client, bass, self.broadcast_sources.clone());
return Ok(connected_peer);
}
+ log::debug!("Failed to find primary BASS service on peer {:?}", peer_id);
Err(Error::ConnectionFailure(peer_id, BROADCAST_AUDIO_SCAN_SERVICE))
}
@@ -210,6 +227,13 @@
address_type: bt_common::core::AddressType,
advertising_sid: bt_common::core::AdvertisingSetId,
) -> Result<BroadcastSource, Error> {
+ log::debug!(
+ "Force discovering broadcast source for peer {:?}, sid {:?}, address {:?} ({:?})",
+ peer_id,
+ advertising_sid,
+ address,
+ address_type,
+ );
let broadcast_source = BroadcastSource {
address: Some(address),
address_type: Some(address_type),
@@ -219,10 +243,11 @@
broadcast_name: None,
};
- Ok(self
+ let (merged, changed) = self
.broadcast_sources
- .merge_broadcast_source_data(&(peer_id, advertising_sid), &broadcast_source)
- .0)
+ .merge_broadcast_source_data(&(peer_id, advertising_sid), &broadcast_source);
+ log::trace!("Force discovered source (changed={}): {:?}", changed, merged);
+ Ok(merged)
}
// Manually adds broadcast source information for debugging purposes.
@@ -233,11 +258,18 @@
advertising_sid: bt_common::core::AdvertisingSetId,
big_metadata: Vec<Vec<bt_common::generic_audio::metadata_ltv::Metadata>>,
) -> Result<BroadcastSource, Error> {
+ log::debug!(
+ "Force discovering broadcast source metadata for peer {:?}, sid {:?}, {} BIG(s)",
+ peer_id,
+ advertising_sid,
+ big_metadata.len(),
+ );
use bt_bap::types::{BroadcastAudioSourceEndpoint, BroadcastIsochronousGroup};
use bt_common::core::CodecId;
let mut big = Vec::new();
for metadata in big_metadata {
+ log::trace!("BIG metadata: {:?}", metadata);
let group = BroadcastIsochronousGroup {
codec_id: CodecId::Assigned(bt_common::core::CodingFormat::ALawLog), // mock.
codec_specific_configs: vec![],
@@ -258,10 +290,11 @@
broadcast_name: None,
};
- Ok(self
+ let (merged, changed) = self
.broadcast_sources
- .merge_broadcast_source_data(&(peer_id, advertising_sid), &broadcast_source)
- .0)
+ .merge_broadcast_source_data(&(peer_id, advertising_sid), &broadcast_source);
+ log::trace!("Force discovered metadata (changed={}): {:?}", changed, merged);
+ Ok(merged)
}
// Gets the broadcast sources currently known by the broadcast
diff --git a/rust/bt-broadcast-assistant/src/assistant/peer.rs b/rust/bt-broadcast-assistant/src/assistant/peer.rs
index 8587e38..b2bd347 100644
--- a/rust/bt-broadcast-assistant/src/assistant/peer.rs
+++ b/rust/bt-broadcast-assistant/src/assistant/peer.rs
@@ -4,7 +4,7 @@
use bt_gatt::pii::GetPeerAddr;
use futures::stream::FusedStream;
-use futures::Stream;
+use futures::{Stream, StreamExt};
use std::sync::Arc;
use thiserror::Error;
@@ -14,6 +14,7 @@
use bt_bass::client::BroadcastAudioScanServiceClient;
#[cfg(any(test, feature = "debug"))]
use bt_bass::types::BroadcastReceiveState;
+use bt_bass::types::EncryptionStatus;
use bt_bass::types::{BisSync, PaSync};
use bt_common::core::{AdvertisingSetId, PeriodicAdvertisingInterval};
use bt_common::packet_encoding::Error as PacketError;
@@ -65,6 +66,21 @@
bass: BroadcastAudioScanServiceClient<T>,
broadcast_sources: Arc<DiscoveredBroadcastSources>,
) -> Self {
+ if log::log_enabled!(log::Level::Debug) {
+ let brs_count = bass.known_broadcast_sources().len();
+ let bascp = bass.audio_scan_control_point();
+ log::debug!(
+ "Initializing BASS client for peer {:?}: discovered {} Broadcast Receive State characteristic(s), Audio Scan Control Point handle {:?}",
+ peer_id,
+ brs_count,
+ bascp,
+ );
+ log::trace!(
+ "Peer {:?} initial Broadcast Receive States: {:?}",
+ peer_id,
+ bass.known_broadcast_sources()
+ );
+ }
Peer { peer_id, _client: client, bass, broadcast_sources }
}
@@ -77,7 +93,36 @@
pub fn take_event_stream(
&mut self,
) -> Result<impl Stream<Item = Result<BassEvent, BassClientError>> + FusedStream, Error> {
- self.bass.take_event_stream().ok_or(Error::UnavailableBassEventStream)
+ let peer_id = self.peer_id;
+ log::debug!("Taking BASS event stream for peer {:?}", peer_id);
+ let stream = self.bass.take_event_stream().ok_or(Error::UnavailableBassEventStream)?;
+ Ok(stream.inspect(move |res| match res {
+ Ok(BassEvent::AddedBroadcastSource(bid, pa_sync_state, enc)) => {
+ let bad_code = matches!(enc, EncryptionStatus::BadCode(_));
+ log::trace!(
+ "BASS notification for peer {:?}: BroadcastId {:?}, PA sync state {:?}, BIG encryption {:?}, bad code flag: {}",
+ peer_id,
+ bid,
+ pa_sync_state,
+ enc,
+ bad_code
+ );
+ }
+ Ok(BassEvent::InvalidBroadcastCode(bid, code)) => {
+ log::trace!(
+ "BASS notification for peer {:?}: BroadcastId {:?}, invalid broadcast code (bad code flag set): {:?}",
+ peer_id,
+ bid,
+ code
+ );
+ }
+ Ok(event) => {
+ log::trace!("BASS notification for peer {:?}: {:?}", peer_id, event);
+ }
+ Err(e) => {
+ log::debug!("BASS notification error for peer {:?}: {:?}", peer_id, e);
+ }
+ }))
}
/// Send broadcast code for a particular broadcast.
@@ -86,6 +131,16 @@
broadcast_id: BroadcastId,
broadcast_code: BroadcastCode,
) -> Result<(), Error> {
+ if log::log_enabled!(log::Level::Debug) {
+ let source_id = self.bass.source_id(&broadcast_id);
+ log::debug!(
+ "Sending broadcast code for peer {:?}, broadcast_id {:?} (source_id: {:?})",
+ self.peer_id,
+ broadcast_id,
+ source_id,
+ );
+ log::trace!("Broadcast code for peer {:?}: {:?}", self.peer_id, broadcast_code);
+ }
self.bass.set_broadcast_code(broadcast_id, broadcast_code).await.map_err(Into::into)
}
@@ -108,6 +163,14 @@
pa_sync: PaSync,
bis_sync: HashMap<u8, BisSync>,
) -> Result<(), Error> {
+ log::debug!(
+ "Adding broadcast source from peer {:?}, sid {:?} to delegator {:?} (pa_sync: {:?}, bis_sync: {:?})",
+ source_peer_id,
+ advertising_sid,
+ self.peer_id,
+ pa_sync,
+ bis_sync,
+ );
let mut broadcast_source = self
.broadcast_sources
.get_by_key(source_peer_id, advertising_sid)
@@ -120,20 +183,45 @@
broadcast_source.with_address(broadcast_addr).with_address_type(broadcast_addr_type);
if !broadcast_source.is_ready_to_add() {
+ log::debug!(
+ "Broadcast source from peer {:?}, sid {:?} is not ready to add: {:?}",
+ source_peer_id,
+ advertising_sid,
+ broadcast_source
+ );
return Err(Error::NotEnoughInfo(source_peer_id));
}
+ let broadcast_id = broadcast_source.broadcast_id.unwrap();
+ let address_type = broadcast_source.address_type.unwrap();
+ let address = broadcast_source.address.unwrap();
+ let pa_interval = broadcast_source
+ .periodic_advertising_interval
+ .unwrap_or(PeriodicAdvertisingInterval::unknown());
+ let subgroups =
+ broadcast_source.endpoint_to_big_subgroups(bis_sync).map_err(Error::PacketError)?;
+
+ log::trace!(
+ "add_broadcast_source to delegator {:?}: source address={:?} ({:?}), sid={:?}, broadcast_id={:?}, pa_sync={:?}, pa_interval={:?}, subgroups (with metadata and BIS sync)={:?}",
+ self.peer_id,
+ address,
+ address_type,
+ advertising_sid,
+ broadcast_id,
+ pa_sync,
+ pa_interval,
+ subgroups,
+ );
+
self.bass
.add_broadcast_source(
- broadcast_source.broadcast_id.unwrap(),
- broadcast_source.address_type.unwrap(),
- broadcast_source.address.unwrap(),
+ broadcast_id,
+ address_type,
+ address,
advertising_sid,
pa_sync,
- broadcast_source
- .periodic_advertising_interval
- .unwrap_or(PeriodicAdvertisingInterval::unknown()),
- broadcast_source.endpoint_to_big_subgroups(bis_sync).map_err(Error::PacketError)?,
+ pa_interval,
+ subgroups,
)
.await
.map_err(Into::into)
@@ -154,12 +242,30 @@
pa_sync: PaSync,
bis_sync: HashMap<u8, BisSync>,
) -> Result<(), Error> {
+ if log::log_enabled!(log::Level::Debug) {
+ let source_id = self.bass.source_id(&broadcast_id);
+ log::debug!(
+ "Updating broadcast source sync for peer {:?}, broadcast_id {:?} (source_id: {:?}): pa_sync={:?}, bis_sync={:?}",
+ self.peer_id,
+ broadcast_id,
+ source_id,
+ pa_sync,
+ bis_sync,
+ );
+ }
let pa_interval = self
.broadcast_sources
.get_by_broadcast_id(&broadcast_id)
.map(|bs| bs.periodic_advertising_interval)
.unwrap_or(None);
+ log::trace!(
+ "update_broadcast_source_sync for peer {:?}, broadcast_id {:?}: pa_interval={:?}",
+ self.peer_id,
+ broadcast_id,
+ pa_interval,
+ );
+
self.bass
.modify_broadcast_source(broadcast_id, pa_sync, pa_interval, bis_sync, None)
.await
@@ -173,18 +279,29 @@
/// * `broadcast_id` - broadcast id of the braodcast source that's to be
/// removed from the scan delegator
pub async fn remove_broadcast_source(&self, broadcast_id: BroadcastId) -> Result<(), Error> {
+ if log::log_enabled!(log::Level::Debug) {
+ let source_id = self.bass.source_id(&broadcast_id);
+ log::debug!(
+ "Removing broadcast source for peer {:?}, broadcast_id {:?} (source_id: {:?})",
+ self.peer_id,
+ broadcast_id,
+ source_id,
+ );
+ }
self.bass.remove_broadcast_source(broadcast_id).await.map_err(Into::into)
}
/// Sends a command to inform the scan delegator peer that we have
/// started scanning for broadcast sources on behalf of it.
pub async fn inform_remote_scan_started(&self) -> Result<(), Error> {
+ log::debug!("Informing scan delegator peer {:?} that remote scan started", self.peer_id);
self.bass.remote_scan_started().await.map_err(Into::into)
}
/// Sends a command to inform the scan delegator peer that we have
/// stopped scanning for broadcast sources on behalf of it.
pub async fn inform_remote_scan_stopped(&self) -> Result<(), Error> {
+ log::debug!("Informing scan delegator peer {:?} that remote scan stopped", self.peer_id);
self.bass.remote_scan_stopped().await.map_err(Into::into)
}
diff --git a/rust/bt-broadcast-assistant/src/debug.rs b/rust/bt-broadcast-assistant/src/debug.rs
index 6afa9eb..bacd4eb 100644
--- a/rust/bt-broadcast-assistant/src/debug.rs
+++ b/rust/bt-broadcast-assistant/src/debug.rs
@@ -531,6 +531,10 @@
mod tests {
use super::*;
+ use bt_common::debug_command::CliCommand;
+ use bt_gatt::test_utils::{FakeCentral, FakeGetPeerAddr, FakeTypes};
+ use log::LevelFilter;
+
#[test]
fn test_parse_peer_id() {
// In hex string.
@@ -627,4 +631,87 @@
let code = "";
assert!(passcode_to_broadcast_code(code).is_err());
}
+
+ #[test]
+ fn verbose_command_updates_and_displays_verbosity() {
+ let debug: AssistantDebug<FakeTypes, _> =
+ AssistantDebug::new(FakeCentral::new(), FakeGetPeerAddr);
+
+ log::set_max_level(LevelFilter::Info);
+
+ // Verbose with no args displays current verbosity without changing it
+ let res = futures::executor::block_on(debug.run(CliCommand::Verbose, vec![]));
+ assert!(res.is_ok());
+ assert_eq!(log::max_level(), LevelFilter::Info);
+
+ // Update verbosity to Debug
+ let res =
+ futures::executor::block_on(debug.run(CliCommand::Verbose, vec!["debug".to_string()]));
+ assert!(res.is_ok());
+ assert_eq!(log::max_level(), LevelFilter::Debug);
+
+ // Update verbosity to Trace
+ let res =
+ futures::executor::block_on(debug.run(CliCommand::Verbose, vec!["trace".to_string()]));
+ assert!(res.is_ok());
+ assert_eq!(log::max_level(), LevelFilter::Trace);
+
+ // Update verbosity to Off
+ let res =
+ futures::executor::block_on(debug.run(CliCommand::Verbose, vec!["off".to_string()]));
+ assert!(res.is_ok());
+ assert_eq!(log::max_level(), LevelFilter::Off);
+
+ // Invalid level does not change verbosity
+ let res = futures::executor::block_on(
+ debug.run(CliCommand::Verbose, vec!["invalid_level".to_string()]),
+ );
+ assert!(res.is_ok());
+ assert_eq!(log::max_level(), LevelFilter::Off);
+
+ // Reset back to Info
+ log::set_max_level(LevelFilter::Info);
+ }
+
+ #[test]
+ fn run_commands_with_verbosity_flags() {
+ let debug: AssistantDebug<FakeTypes, _> =
+ AssistantDebug::new(FakeCentral::new(), FakeGetPeerAddr);
+
+ log::set_max_level(LevelFilter::Info);
+
+ // Executing Info with -v flag:
+ // 1. debug.run() strips the flag before run_command.
+ // 2. Temporarily elevates max log level during execution.
+ // 3. Executes successfully.
+ let res =
+ futures::executor::block_on(debug.run(AssistantCmd::Info, vec!["-v".to_string()]));
+ assert!(res.is_ok());
+
+ // Persistent verbosity remains Info after scoped execution completes
+ assert_eq!(log::max_level(), LevelFilter::Info);
+
+ // Executing Info with -vv flag elevates to Trace
+ let res =
+ futures::executor::block_on(debug.run(AssistantCmd::Info, vec!["-vv".to_string()]));
+ assert!(res.is_ok());
+ assert_eq!(log::max_level(), LevelFilter::Info);
+
+ // Executing an argument-sensitive command (4 positional arguments + -v)
+ // verifies that -v is cleanly stripped and doesn't cause positional
+ // argument parsing to fail with an incorrect argument count.
+ let res = futures::executor::block_on(debug.run(
+ AssistantCmd::ForceDiscoverBroadcastSource,
+ vec![
+ "1".to_string(),
+ "00:11:22:33:44:55".to_string(),
+ "Random".to_string(),
+ "1".to_string(),
+ "-v".to_string(),
+ ],
+ ));
+ assert!(res.is_ok());
+ assert_eq!(debug.assistant.known_broadcast_sources().len(), 1);
+ assert_eq!(log::max_level(), LevelFilter::Info);
+ }
}
