rust/bt-pacs: Add debug logging to PACS
Add debug! and trace! logging to PACS characteristic decoding and
reading to improve visibility into audio capability handling.
Debugging PACS against a real peer requires seeing what was read from
each characteristic and how it was interpreted; without it a malformed
record is indistinguishable from a missing one.
- Log PAC record decoding, including record counts and codec ids
- Log audio location and audio context decoding results
- Add try_read implementations that log the handle being read and the
number of bytes returned, sharing a read_characteristic_value
helper that handles truncated reads
- Implement Decodable for AudioContexts and log the decoded contexts
- Depend on the log crate
- Add unit tests for Verbose and -v/-vv flags in the debug CLI
Test: cargo test -p bt-pacs
cargo test --workspace
Change-Id: I5187de3d249bf40d68ffe11ce11012516a6a6964
Reviewed-on: https://bluetooth-review.googlesource.com/c/bluetooth/+/4121
diff --git a/rust/bt-pacs/Cargo.toml b/rust/bt-pacs/Cargo.toml
index c260971..e9b051a 100644
--- a/rust/bt-pacs/Cargo.toml
+++ b/rust/bt-pacs/Cargo.toml
@@ -12,6 +12,7 @@
### Others
futures.workspace = true
+log.workspace = true
pin-project.workspace = true
thiserror.workspace = true
parking_lot.workspace = true
diff --git a/rust/bt-pacs/src/debug.rs b/rust/bt-pacs/src/debug.rs
index 9b815d7..ce95664 100644
--- a/rust/bt-pacs/src/debug.rs
+++ b/rust/bt-pacs/src/debug.rs
@@ -48,7 +48,6 @@
let chrs = service.discover_characteristics(None).await?;
for chr in chrs {
- let mut buf = [0; 120];
match chr.uuid {
SourcePac::UUID => {
let source_pac = SourcePac::try_read::<T>(chr, &service).await?;
@@ -64,24 +63,18 @@
println!("{locations:?}");
}
SourceAudioLocations::UUID => {
- let (bytes, _trunc) =
- service.read_characteristic(&chr.handle, 0, &mut buf).await?;
- let locations = SourceAudioLocations::from_chr(chr, &buf[..bytes])
- .map_err(bt_gatt::types::Error::other)?;
+ let locations =
+ SourceAudioLocations::try_read::<T>(chr, &service).await?;
println!("{locations:?}");
}
AvailableAudioContexts::UUID => {
- let (bytes, _trunc) =
- service.read_characteristic(&chr.handle, 0, &mut buf).await?;
- let contexts = AvailableAudioContexts::from_chr(chr, &buf[..bytes])
- .map_err(bt_gatt::types::Error::other)?;
+ let contexts =
+ AvailableAudioContexts::try_read::<T>(chr, &service).await?;
println!("{contexts:?}");
}
SupportedAudioContexts::UUID => {
- let (bytes, _trunc) =
- service.read_characteristic(&chr.handle, 0, &mut buf).await?;
- let contexts = SupportedAudioContexts::from_chr(chr, &buf[..bytes])
- .map_err(bt_gatt::types::Error::other)?;
+ let contexts =
+ SupportedAudioContexts::try_read::<T>(chr, &service).await?;
println!("{contexts:?}");
}
_x => println!("Unrecognized Chr {}", chr.uuid.recognize()),
@@ -92,3 +85,70 @@
}
}
}
+
+#[cfg(test)]
+mod tests {
+ use super::*;
+ use bt_common::debug_command::CliCommand;
+ use bt_gatt::test_utils::{FakeClient, FakeTypes};
+ use log::LevelFilter;
+
+ fn setup_fake_pacs_debug() -> PacsDebug<FakeTypes> {
+ PacsDebug::new(FakeClient::new())
+ }
+
+ #[test]
+ fn verbosity_controls_and_flags() {
+ let debug = setup_fake_pacs_debug();
+
+ 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 for scoped flags testing
+ log::set_max_level(LevelFilter::Info);
+
+ // Executing Print 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(PacsCmd::Print, vec!["-v".to_string()]));
+ assert!(res.is_ok());
+
+ // Persistent verbosity remains Info after scoped execution completes
+ assert_eq!(log::max_level(), LevelFilter::Info);
+
+ // Executing Print with -vv flag elevates to Trace
+ let res = futures::executor::block_on(debug.run(PacsCmd::Print, vec!["-vv".to_string()]));
+ assert!(res.is_ok());
+ assert_eq!(log::max_level(), LevelFilter::Info);
+ }
+}
diff --git a/rust/bt-pacs/src/lib.rs b/rust/bt-pacs/src/lib.rs
index d27ad26..cbb71e6 100644
--- a/rust/bt-pacs/src/lib.rs
+++ b/rust/bt-pacs/src/lib.rs
@@ -9,7 +9,11 @@
use bt_common::generic_audio::{AudioLocation, ContextType};
use bt_common::packet_encoding::{Decodable, Encodable};
use bt_common::Uuid;
-use bt_gatt::{client::FromCharacteristic, Characteristic};
+use bt_gatt::{
+ client::{FromCharacteristic, PeerService},
+ types::Error as GattError,
+ Characteristic,
+};
use std::collections::HashSet;
@@ -71,7 +75,14 @@
let metadata = results.into_iter().filter_map(Result::ok).collect();
idx += consumed;
- (Ok(Self { codec_id, codec_specific_capabilities, metadata }), idx)
+ let pac_record = Self { codec_id, codec_specific_capabilities, metadata };
+ log::trace!(
+ "Decoded PacRecord: codec_id={:?}, capabilities={}, metadata={}",
+ pac_record.codec_id,
+ pac_record.codec_specific_capabilities.len(),
+ pac_record.metadata.len()
+ );
+ (Ok(pac_record), idx)
}
}
@@ -126,6 +137,7 @@
return Err(bt_common::packet_encoding::Error::UnexpectedDataLength);
}
let num_of_pac_records = value[0] as usize;
+ log::trace!("Decoding {} PAC records from {} bytes", num_of_pac_records, value.len());
let mut next_idx = 1;
let mut capabilities = Vec::with_capacity(num_of_pac_records);
for _ in 0..num_of_pac_records {
@@ -133,9 +145,27 @@
capabilities.push(cap?);
next_idx += consumed;
}
+ log::debug!("Successfully decoded {} PAC records", capabilities.len());
Ok(capabilities)
}
+async fn read_characteristic_value<T: bt_gatt::GattTypes>(
+ handle: &bt_gatt::types::Handle,
+ service: &T::PeerService,
+) -> Result<Vec<u8>, GattError> {
+ let mut buf = [0; 128];
+ let (bytes, mut truncated) = service.read_characteristic(handle, 0, &mut buf).await?;
+ let mut vec = Vec::with_capacity(bytes);
+ vec.extend_from_slice(&buf[..bytes]);
+ while truncated {
+ let (bytes, still_truncated) =
+ service.read_characteristic(handle, vec.len() as u16, &mut buf).await?;
+ vec.extend_from_slice(&buf[..bytes]);
+ truncated = still_truncated;
+ }
+ Ok(vec)
+}
+
/// One Sink Published Audio Capability Characteristic, or Sink PAC, exposed on
/// a service. More than one Sink PAC can exist on a given PACS service. If
/// multiple are exposed, they are returned separately and can be notified by
@@ -156,6 +186,7 @@
) -> Result<Self, bt_common::packet_encoding::Error> {
let handle = characteristic.handle;
let capabilities = pac_records_from_bytes(value)?;
+ log::trace!("Parsed SinkPac (handle: {:?}) with {} records", handle, capabilities.len());
Ok(Self { handle, capabilities })
}
@@ -163,6 +194,21 @@
self.capabilities = pac_records_from_bytes(new_value)?;
Ok(self)
}
+
+ fn try_read<T: bt_gatt::GattTypes>(
+ characteristic: Characteristic,
+ service: &T::PeerService,
+ ) -> impl futures::Future<Output = Result<Self, GattError>> {
+ async move {
+ if characteristic.uuid != Self::UUID {
+ return Err(GattError::ScanFailed("Wrong UUID".to_owned()));
+ }
+ log::debug!("Reading Sink PAC characteristic (handle {:?})", characteristic.handle);
+ let raw = read_characteristic_value::<T>(&characteristic.handle, service).await?;
+ log::trace!("Read {} bytes from Sink PAC characteristic", raw.len());
+ Self::from_chr(characteristic, &raw).map_err(Into::into)
+ }
+ }
}
/// One Sink Published Audio Capability Characteristic, or Sink PAC, exposed on
@@ -185,6 +231,7 @@
) -> Result<Self, bt_common::packet_encoding::Error> {
let handle = characteristic.handle;
let capabilities = pac_records_from_bytes(value)?;
+ log::trace!("Parsed SourcePac (handle: {:?}) with {} records", handle, capabilities.len());
Ok(Self { handle, capabilities })
}
@@ -192,6 +239,21 @@
self.capabilities = pac_records_from_bytes(new_value)?;
Ok(self)
}
+
+ fn try_read<T: bt_gatt::GattTypes>(
+ characteristic: Characteristic,
+ service: &T::PeerService,
+ ) -> impl futures::Future<Output = Result<Self, GattError>> {
+ async move {
+ if characteristic.uuid != Self::UUID {
+ return Err(GattError::ScanFailed("Wrong UUID".to_owned()));
+ }
+ log::debug!("Reading Source PAC characteristic (handle {:?})", characteristic.handle);
+ let raw = read_characteristic_value::<T>(&characteristic.handle, service).await?;
+ log::trace!("Read {} bytes from Source PAC characteristic", raw.len());
+ Self::from_chr(characteristic, &raw).map_err(Into::into)
+ }
+ }
}
#[derive(Debug, PartialEq, Clone, Default)]
@@ -209,10 +271,26 @@
let locations =
AudioLocation::from_bits(u32::from_le_bytes([buf[0], buf[1], buf[2], buf[3]]))
.collect();
+ log::trace!("Decoded AudioLocations: {:?}", locations);
(Ok(AudioLocations { locations }), 4)
}
}
+impl AudioLocations {
+ pub async fn try_read<T: bt_gatt::GattTypes>(
+ characteristic: Characteristic,
+ service: &T::PeerService,
+ ) -> Result<Self, GattError> {
+ log::debug!("Reading Audio Locations characteristic (handle {:?})", characteristic.handle);
+ let raw = read_characteristic_value::<T>(&characteristic.handle, service).await?;
+ log::trace!("Read {} bytes from Audio Locations characteristic", raw.len());
+ let (res, _) = Self::decode(&raw);
+ let locations = res.map_err(GattError::other)?;
+ log::debug!("Parsed Audio Locations: {:?}", locations);
+ Ok(locations)
+ }
+}
+
impl Encodable for AudioLocations {
type Error = bt_common::packet_encoding::Error;
@@ -255,6 +333,7 @@
) -> Result<Self, bt_common::packet_encoding::Error> {
let handle = characteristic.handle;
let locations = AudioLocations::decode(value).0?;
+ log::trace!("Parsed SourceAudioLocations (handle: {:?}): {:?}", handle, locations);
Ok(Self { handle, locations })
}
@@ -262,6 +341,24 @@
self.locations = AudioLocations::decode(new_value).0?;
Ok(self)
}
+
+ fn try_read<T: bt_gatt::GattTypes>(
+ characteristic: Characteristic,
+ service: &T::PeerService,
+ ) -> impl futures::Future<Output = Result<Self, GattError>> {
+ async move {
+ if characteristic.uuid != Self::UUID {
+ return Err(GattError::ScanFailed("Wrong UUID".to_owned()));
+ }
+ log::debug!(
+ "Reading Source Audio Locations characteristic (handle {:?})",
+ characteristic.handle
+ );
+ let raw = read_characteristic_value::<T>(&characteristic.handle, service).await?;
+ log::trace!("Read {} bytes from Source Audio Locations characteristic", raw.len());
+ Self::from_chr(characteristic, &raw).map_err(Into::into)
+ }
+ }
}
#[derive(Debug, PartialEq, Clone)]
@@ -288,6 +385,7 @@
) -> Result<Self, bt_common::packet_encoding::Error> {
let handle = characteristic.handle;
let locations = AudioLocations::decode(value).0?;
+ log::trace!("Parsed SinkAudioLocations (handle: {:?}): {:?}", handle, locations);
Ok(Self { handle, locations })
}
@@ -295,6 +393,24 @@
self.locations = AudioLocations::decode(new_value).0?;
Ok(self)
}
+
+ fn try_read<T: bt_gatt::GattTypes>(
+ characteristic: Characteristic,
+ service: &T::PeerService,
+ ) -> impl futures::Future<Output = Result<Self, GattError>> {
+ async move {
+ if characteristic.uuid != Self::UUID {
+ return Err(GattError::ScanFailed("Wrong UUID".to_owned()));
+ }
+ log::debug!(
+ "Reading Sink Audio Locations characteristic (handle {:?})",
+ characteristic.handle
+ );
+ let raw = read_characteristic_value::<T>(&characteristic.handle, service).await?;
+ log::trace!("Read {} bytes from Sink Audio Locations characteristic", raw.len());
+ Self::from_chr(characteristic, &raw).map_err(Into::into)
+ }
+ }
}
#[derive(Debug, PartialEq, Clone)]
@@ -322,11 +438,13 @@
return (Err(bt_common::packet_encoding::Error::UnexpectedDataLength), 2);
}
let encoded = u16::from_le_bytes([buf[0], buf[1]]);
- if encoded == 0 {
- (Ok(Self::NotAvailable), 2)
+ let contexts = if encoded == 0 {
+ Self::NotAvailable
} else {
- (Ok(Self::Available(ContextType::from_bits(encoded).collect())), 2)
- }
+ Self::Available(ContextType::from_bits(encoded).collect())
+ };
+ log::trace!("Decoded AvailableContexts: {:?}", contexts);
+ (Ok(contexts), 2)
}
}
@@ -391,6 +509,12 @@
}
let sink = AvailableContexts::decode(&value[0..2]).0?;
let source = AvailableContexts::decode(&value[2..4]).0?;
+ log::trace!(
+ "Decoded AvailableAudioContexts for handle {:?}: sink={:?}, source={:?}",
+ handle,
+ sink,
+ source
+ );
Ok(Self { handle, sink, source })
}
@@ -407,6 +531,24 @@
self.source = source;
Ok(self)
}
+
+ fn try_read<T: bt_gatt::GattTypes>(
+ characteristic: Characteristic,
+ service: &T::PeerService,
+ ) -> impl futures::Future<Output = Result<Self, GattError>> {
+ async move {
+ if characteristic.uuid != Self::UUID {
+ return Err(GattError::ScanFailed("Wrong UUID".to_owned()));
+ }
+ log::debug!(
+ "Reading Available Audio Contexts characteristic (handle {:?})",
+ characteristic.handle
+ );
+ let raw = read_characteristic_value::<T>(&characteristic.handle, service).await?;
+ log::trace!("Read {} bytes from Available Audio Contexts characteristic", raw.len());
+ Self::from_chr(characteristic, &raw).map_err(Into::into)
+ }
+ }
}
#[derive(Debug, Clone)]
@@ -455,6 +597,12 @@
}
let sink = ContextType::from_bits(u16::from_le_bytes([value[0], value[1]])).collect();
let source = ContextType::from_bits(u16::from_le_bytes([value[2], value[3]])).collect();
+ log::trace!(
+ "Decoded SupportedAudioContexts for handle {:?}: sink={:?}, source={:?}",
+ handle,
+ sink,
+ source
+ );
Ok(Self { handle, sink, source })
}
@@ -471,6 +619,24 @@
ContextType::from_bits(u16::from_le_bytes([new_value[2], new_value[3]])).collect();
Ok(self)
}
+
+ fn try_read<T: bt_gatt::GattTypes>(
+ characteristic: Characteristic,
+ service: &T::PeerService,
+ ) -> impl futures::Future<Output = Result<Self, GattError>> {
+ async move {
+ if characteristic.uuid != Self::UUID {
+ return Err(GattError::ScanFailed("Wrong UUID".to_owned()));
+ }
+ log::debug!(
+ "Reading Supported Audio Contexts characteristic (handle {:?})",
+ characteristic.handle
+ );
+ let raw = read_characteristic_value::<T>(&characteristic.handle, service).await?;
+ log::trace!("Read {} bytes from Supported Audio Contexts characteristic", raw.len());
+ Self::from_chr(characteristic, &raw).map_err(Into::into)
+ }
+ }
}
#[cfg(test)]
diff --git a/rust/bt-pacs/src/server/types.rs b/rust/bt-pacs/src/server/types.rs
index 1bc9afb..f209c13 100644
--- a/rust/bt-pacs/src/server/types.rs
+++ b/rust/bt-pacs/src/server/types.rs
@@ -125,7 +125,7 @@
}
}
-#[derive(Default)]
+#[derive(Debug, Default, Clone, PartialEq)]
pub struct AudioContexts {
pub(crate) sink: HashSet<ContextType>,
pub(crate) source: HashSet<ContextType>,
@@ -137,6 +137,20 @@
}
}
+impl Decodable for AudioContexts {
+ type Error = bt_common::packet_encoding::Error;
+
+ fn decode(buf: &[u8]) -> (core::result::Result<Self, Self::Error>, usize) {
+ if buf.len() < 4 {
+ return (Err(bt_common::packet_encoding::Error::UnexpectedDataLength), buf.len());
+ }
+ let sink = ContextType::from_bits(u16::from_le_bytes([buf[0], buf[1]])).collect();
+ let source = ContextType::from_bits(u16::from_le_bytes([buf[2], buf[3]])).collect();
+ log::debug!("Decoded AudioContexts: sink={:?}, source={:?}", sink, source);
+ (Ok(AudioContexts { sink, source }), 4)
+ }
+}
+
/// A single PAC characteristic consists of 1 or more PAC records.
pub type PacRecords = Vec<PacRecord>;
@@ -197,3 +211,46 @@
}
}
}
+
+#[cfg(test)]
+mod tests {
+ use super::*;
+
+ use pretty_assertions::assert_eq;
+
+ const AUDIO_CONTEXTS_ENCODED_LEN: usize = 4;
+
+ #[test]
+ fn decode_audio_contexts() {
+ let (decoded, consumed) = AudioContexts::decode(&[0x00, 0x00, 0x00, 0x00]);
+ let contexts = decoded.expect("should decode empty contexts");
+ assert_eq!(consumed, AUDIO_CONTEXTS_ENCODED_LEN);
+ assert!(contexts.sink.is_empty());
+ assert!(contexts.source.is_empty());
+
+ let (decoded, consumed) = AudioContexts::decode(&[0x08, 0x06, 0x06, 0x03, 0xCA, 0xFE]);
+ let contexts = decoded.expect("should decode valid contexts with trailing bytes");
+ assert_eq!(consumed, AUDIO_CONTEXTS_ENCODED_LEN);
+ assert_eq!(
+ contexts.sink,
+ HashSet::from([ContextType::Game, ContextType::Ringtone, ContextType::Alerts])
+ );
+ assert_eq!(
+ contexts.source,
+ HashSet::from([
+ ContextType::Conversational,
+ ContextType::Media,
+ ContextType::Notifications,
+ ContextType::Ringtone,
+ ])
+ );
+ }
+
+ #[test]
+ fn decode_audio_contexts_too_short() {
+ let buf = [0x00, 0x00, 0x02];
+ let (decoded, consumed) = AudioContexts::decode(&buf);
+ assert_eq!(decoded, Err(bt_common::packet_encoding::Error::UnexpectedDataLength));
+ assert_eq!(consumed, buf.len());
+ }
+}
