trouble
trouble copied to clipboard
embassy-rs
Service discovery request resolves to empty list
This issue was identified running the esp32 example on an ESP32-C3-DevKit-RUST-1 board @ 29dabe7 (the esp32 example is currently broken beyond this point, see #122).
Attempts to discover services on the device take a long time to resolve, and when they do they resolve to an empty list.
I have tested this against examples in two different adapter crates running on Ubuntu 20.04:
- Blteplug (which uses bluez-async) running this example
- Bluest (which uses bluer) running a combination of code from the scan and connected examples to scan until the Trouble device is found, connect to it and attempt to discover services
The results from these tests are the same. When the Linux application discover services on the device, I see the following trace from the device:
INFO - [adv] connection established
INFO - [gatt] Read event on Characteristic { cccd_handle: Some(35), handle: 34 } // NOTE: This line doesn't always appear!
ERROR - [gatt] Error processing GATT events: NotFound
INFO - [adv] notifying connection of tick 1
INFO - [adv] notifying connection of tick 2
INFO - [adv] notifying connection of tick 3
(continues)
Service UUIDs can be read from the advertising data, but no service data is associated with them.
Running a bleps-based application on the same dev board, I can successfully discover services with both blteplug and bluest.
Confusingly however, I can connect to the device with the NRFConnect app on my phone and this does seem to be able to resolve the services successfully. I don't know how NRFConnect goes about service discovery, but I don't see either the Read event on Characteristic { cccd_handle: Some(35), handle: 34 } line or the Error processing GATT events: NotFound line. Instead when NRFConnect connects I just see:
INFO - [adv] connection established
INFO - [adv] notifying connection of tick 1
INFO - [adv] notifying connection of tick 2
INFO - [adv] notifying connection of tick 3
INFO - [adv] notifying connection of tick 4
Several issues are fixed, so we should try to get main branch working on esp32 first.
For the record, I tried to run the btleplug example using the nrf-sdc example, so I think this issue is fixed on main:
Peripheral "Trouble" is connected: false
Connecting to peripheral "Trouble"...
Now connected (true) to peripheral "Trouble"...
Discover peripheral "Trouble" services...
Service UUID 0000180f-0000-1000-8000-00805f9b34fb, primary: true
Characteristic { uuid: 00002a19-0000-1000-8000-00805f9b34fb, service_uuid: 0000180f-0000-1000-8000-00805f9b34fb, properties: CharPropFlags(READ | NOTIFY), descriptors: {Descriptor { uuid: 00002902-0000-1000-8000-00805f9b34fb, service_uuid: 0000180f-0000-1000-8000-00805f9b34fb, characteristic_uuid: 00002a19-0000-1000-8000-00805f9b34fb }} }
Disconnecting from peripheral "Trouble"...
I will re-run that once having esp32 working.
Sure thing. First off, I can confirm the esp32 example is now working.
Blteplug test
Trace from the example shows something slightly different:
INFO - [adv] connection established
INFO - [gatt] Read event on Characteristic { cccd_handle: None, handle: 3 }
INFO - [adv] notifying connection of tick 1
INFO - [adv] notifying connection of tick 2
So the error message has disappeared and the read event report is now reporting different values for cccd_handle and handle.
As for blteplug, it connects and attempts to discover services, but doesn't find any:
Peripheral "Trouble" is connected: false
Connecting to peripheral "Trouble"...
Now connected (true) to peripheral "Trouble"...
Discover peripheral "Trouble" services...
Disconnecting from peripheral "Trouble"...
Bluest
The code I've put together to exercise the bluest adapter performs the following tasks:
- Scan for devices until "Trouble" device is found
- Report service UUIDs and service data from advertising packet
- Connect to "Trouble" device
- Attempt service discovery
The trace from my code is the following:
2024-09-25T11:32:05.245597Z INFO ble: starting scan
2024-09-25T11:32:05.636852Z INFO ble: scan started
2024-09-25T11:32:05.647892Z INFO ble: Trouble: [00001800-0000-1000-8000-00805f9b34fb, 0000180f-0000-1000-8000-00805f9b34fb]; {}
2024-09-25T11:32:05.648029Z INFO ble: Found trouble!
2024-09-25T11:32:16.575876Z INFO ble: Conneted to trouble!
2024-09-25T11:32:16.584583Z INFO ble: Discovering services...
2024-09-25T11:32:18.295256Z INFO ble: Services discovered: []
The trace from the TrouBLE example is as follows:
INFO - [adv] advertising
INFO - [adv] connection established
INFO - [gatt] Read event on Characteristic { cccd_handle: Some(35), handle: 34 }
INFO - [gatt] Read event on Characteristic { cccd_handle: None, handle: 3 }
INFO - [gatt] Read event on Characteristic { cccd_handle: None, handle: 5 }
INFO - [gatt] Read event on Characteristic { cccd_handle: None, handle: 3 }
INFO - [adv] notifying connection of tick 1
INFO - [adv] notifying connection of tick 2
Again, the error is no longer reported, but no services are discovered.
NRF Connect
NRF Connect is still able to successfully connect and report all expected services and subscribe to the notify characteristic. As before, there is no Read event on Characteristic {...} trace when connecting with NRF Connect:
INFO - [adv] advertising
INFO - [adv] connection established
INFO - [adv] notifying connection of tick 1
INFO - [adv] notifying connection of tick 2
INFO - [adv] notifying connection of tick 3
INFO - [adv] notifying connection of tick 4
@peteskubiak Thanks for testing!
I only tried btleplug with esp32, and for me it does discover all the services and characteristics as when I tested nrf-sdc. I wonder if this could be related to bluez version on the system, could you share Linux version, version of bluez etc? One thing to keep in mind, bluez does some caching of earlier discoveries, so you might want to try to change the device id to something else than 'Trouble' in case it's caching some old state.
Regarding the Read Event present or not, this event is only returned when a 'read' is requested. In the nrf connect app, you have to press 'read characteristic' icon to trigger a read event. Subscribing to a value will not trigger a a read event, so this is expected. The other examples probably do explicit reads.
Would you mind sharing your 'bluest' code so I can try to reproduce it?
Interesting! Yes my OS version is Ubuntu 20.04.6 LTS and bluez version is 5.53. It could be related to OS/bluez version; the fact that it can discover services on a bleps-based device but not TrouBLE might help to track down the source of the issue...
Testing btleplug and bluest with an updated device ID each time have the same results: no services.
Here's my bluest code:
use bluest::Adapter;
use futures::StreamExt;
use std::error::Error;
use tracing::info;
use tracing::metadata::LevelFilter;
#[tokio::main]
async fn main() -> Result<(), Box<dyn Error>> {
use tracing_subscriber::prelude::*;
use tracing_subscriber::{fmt, EnvFilter};
tracing_subscriber::registry()
.with(fmt::layer())
.with(
EnvFilter::builder()
.with_default_directive(LevelFilter::INFO.into())
.from_env_lossy(),
)
.init();
let adapter = Adapter::default()
.await
.ok_or("Bluetooth adapter not found")?;
adapter.wait_available().await?;
info!("starting scan");
let mut scan = adapter.scan(&[]).await?;
info!("scan started");
let mut trouble = None;
let mut services = Vec::new();
while trouble.is_none() {
if let Some(discovered_device) = scan.next().await {
info!(
"{}{}: {:?}; {:?}",
discovered_device
.device
.name()
.as_deref()
.unwrap_or("(unknown)"),
discovered_device
.rssi
.map(|x| format!(" ({}dBm)", x))
.unwrap_or_default(),
discovered_device.adv_data.services,
discovered_device.adv_data.service_data
);
// NOTE: Doing simple string comparison to identity device
if discovered_device.device.name().unwrap() == *"Trouble3" {
trouble = Some(discovered_device.device);
services.extend(discovered_device.adv_data.services);
info!("Found trouble!");
}
}
}
adapter.connect_device(trouble.as_ref().unwrap()).await?;
info!("Connected to trouble!");
info!("Discovering services...");
info!(
"Services discovered: {:?}",
trouble.as_ref().unwrap().services().await?
);
adapter.disconnect_device(&trouble.unwrap()).await?;
Ok(())
}
@peteskubiak Thanks! What seems to happen is that bluez aborts the connection due to the supervision timeout (bluez sets this to 420ms). I've used the bluetoothctl tool manually to connect, and I'm getting a le-connection-abort-by-local.
Sometimes it gets a bit further and starts making GATT requests, but ultimately it sends up disconnecting sometimes.
I've tried the following as well:
- Running the wifi_ble example in esp-hal repo, same behavior
- Running the wifi_embassy_ble example in esp-hal repo, same behavior
- Running the nrf-sdc examples, this works every time
So I think this might not be related to trouble, but some timing handling in the esp32 hci controller and/or the hci integration, since the bleps examples exhibit the same behavior. Do you have a bleps example that works for you? I've been running the examples from main in esp-hal, maybe you could try those as well.
I tried on a different machine, debian based, and in that case all the esp examples worked, all services discovered etc. If you have a bleps-based example that works for you, I'd be interested to test it on these two systems to understand more what's different.
You can also try to increase the supervision timeout to see if that helps, echo -n 200 > /sys/kernel/debug/bluetooth/hci0/supervision_timeout
Ahh that would explain the long pause when attempting to connect to the TrouBLE example. Here is the hacked together bleps example I've been using - I've stuck it into one file for easy sharing, please excuse the scrappy code!
//! Embassy BLE Example
//!
#![no_std]
#![no_main]
use bleps::ad_structure::{
create_advertising_data, AdStructure, BR_EDR_NOT_SUPPORTED, LE_GENERAL_DISCOVERABLE,
};
use bleps::async_attribute_server::AttributeServer;
use bleps::asynch::Ble;
use bleps::att::Uuid;
use bleps::attribute_server::{NotificationData, WorkResult};
use bleps::event::EventType;
use bleps::no_rng::NoRng;
use bleps::PollResult;
use embassy_executor::Spawner;
use embassy_time::{Duration, Timer};
use esp_backtrace as _;
use esp_hal::clock::{ClockControl, Clocks};
use esp_hal::peripherals::{Peripherals, BT, RADIO_CLK, SYSTIMER};
use esp_hal::rng::Rng;
use esp_hal::system::SystemControl;
use esp_hal::timer::timg::TimerGroup;
use esp_hal::timer::{systimer, ErasedTimer, PeriodicTimer};
use esp_hal_embassy::main;
use esp_wifi::ble::controller::asynch::BleConnector;
use esp_wifi::{initialize, EspWifiInitFor};
use log::info;
#[global_allocator]
static ALLOCATOR: esp_alloc::EspHeap = esp_alloc::EspHeap::empty();
#[main]
async fn main(_spawner: Spawner) -> ! {
// Initialize the logger
esp_println::logger::init_logger(log::LevelFilter::Info);
init_heap();
// Initialize the hardware
let b = Board::init();
// Initialize the BLE stack
let ble_init = initialize(
EspWifiInitFor::Ble,
b.timer,
b.rng,
b.radio_clocks,
&b.clocks,
)
.unwrap();
let connector = BleConnector::new(&ble_init, b.ble);
let mut ble = Ble::new(connector, esp_wifi::current_millis);
let service_uuids = &[bleps::att::Uuid::Uuid16(0x1809)];
let mut rf3 = |_offset: usize, data: &mut [u8]| {
data[..5].copy_from_slice(&b"Hola!"[..]);
5
};
let mut wf3 = |offset: usize, data: &[u8]| {
info!("RECEIVED: Offset {}, data {:?}", offset, data);
};
let mut my_descriptor_read_function = |_offset: usize, data: &mut [u8]| {
data[..5].copy_from_slice(&b"Desc!"[..]);
5
};
let mut notify = |enabled: bool| {
info!("enabled = {enabled}");
};
let mut rf = rf3;
let mut notify2 = notify;
bleps::gatt!([service {
uuid: "937312e0-2354-11eb-9f10-fbc30a62cf38",
characteristics: [
characteristic {
name: "my_characteristic",
description: "Sine wave notifier",
descriptors: [descriptor {
uuid: "dfe57a9f-4495-45ba-9e02-df1a010b618c",
read: my_descriptor_read_function,
},],
uuid: "987312e0-2354-11eb-9f10-fbc30a62cf38",
notify: true,
read: rf3,
write: wf3,
notify_cb: notify,
},
characteristic {
name: "triangle_wave",
description: "Triangle wave notifier",
uuid: "937312e0-2354-11eb-9f10-fbc30a62cf38",
notify: true,
read: rf,
notify_cb: notify2,
}
],
},]);
advertise(&mut ble, service_uuids, "BLEPS DEMO").await;
let mut rng = NoRng;
let mut srv = AttributeServer::new(&mut ble, &mut gatt_attributes, &mut rng);
let mut counter = 0.0;
let mut tri_counter: f32 = 1.0;
let mut tri_adder = 1.0;
loop {
let mut cccd = [0u8; 1];
srv.get_characteristic_value(my_characteristic_notify_enable_handle, 0, &mut cccd);
if cccd[0] == 1 {
match srv
.do_work_with_notification(Some(NotificationData::new(
my_characteristic_handle,
&libm::sinf(counter).to_le_bytes(),
)))
.await
{
Ok(res) => match res {
WorkResult::DidWork => {
info!("Notify {counter}");
}
WorkResult::GotDisconnected => {
info!("Disconnected!");
}
},
Err(_) => todo!(),
}
counter += 0.1;
Timer::after(Duration::from_millis(200)).await;
} else {
let _ = srv.do_work().await;
}
let mut cccd = [0u8; 1];
srv.get_characteristic_value(triangle_wave_notify_enable_handle, 0, &mut cccd);
if cccd[0] == 1 {
match srv
.do_work_with_notification(Some(NotificationData::new(triangle_wave_handle, {
if tri_counter as i32 % 25 == 0 {
tri_adder = -tri_adder;
}
&tri_counter.to_le_bytes()
})))
.await
{
Ok(res) => {
if let WorkResult::GotDisconnected = res {
info!("Disconnected (TW)")
}
}
Err(_) => todo!(),
}
tri_counter += tri_adder;
}
}
}
fn init_heap() {
const HEAP_SIZE: usize = 32 * 1024;
static mut HEAP: core::mem::MaybeUninit<[u8; HEAP_SIZE]> = core::mem::MaybeUninit::uninit();
unsafe {
ALLOCATOR.init(HEAP.as_mut_ptr() as *mut u8, HEAP_SIZE);
}
}
async fn advertise(
ble: &mut Ble<BleConnector<'static>>,
service_uuids: &[Uuid],
name: &str,
) -> bool {
info!("{:?}", ble.init().await);
info!("{:?}", ble.cmd_set_le_advertising_parameters().await);
info!(
"{:?}",
ble.cmd_set_le_advertising_data(
create_advertising_data(&[
AdStructure::Flags(LE_GENERAL_DISCOVERABLE | BR_EDR_NOT_SUPPORTED),
AdStructure::ServiceUuids16(service_uuids),
AdStructure::CompleteLocalName(name),
])
.unwrap()
)
.await
);
info!("{:?}", ble.cmd_set_le_advertise_enable(true).await);
info!("started advertising");
loop {
if let Some(PollResult::Event(event)) = ble.poll().await {
// info!("{:?}", event);
match event {
EventType::DisconnectComplete { reason, .. } => {
info!("Disconnected: {:?}", reason);
break false;
}
EventType::ConnectionComplete { .. } => {
info!("Connected BLE!");
break true;
}
EventType::LongTermKeyRequest { .. } => unimplemented!(),
other => info!("Unhandled event: {:?}", other),
}
};
}
}
struct Board {
pub timer: PeriodicTimer<'static, ErasedTimer>,
pub clocks: Clocks<'static>,
pub rng: Rng,
pub radio_clocks: RADIO_CLK,
pub ble: BT,
}
impl Board {
pub fn init() -> Self {
let p = Peripherals::take();
let system = SystemControl::new(p.SYSTEM);
let clocks = ClockControl::max(system.clock_control).freeze();
let timg0 = TimerGroup::new(p.TIMG0, &clocks);
let timer0: ErasedTimer = timg0.timer0.into();
let timer = PeriodicTimer::new(timer0);
Board::init_embassy(p.SYSTIMER, &clocks);
Self {
timer,
clocks,
rng: Rng::new(p.RNG),
radio_clocks: p.RADIO_CLK,
ble: p.BT,
}
}
/// Initialize the embassy runtime
fn init_embassy(systimer: SYSTIMER, clocks: &Clocks) {
info!("Initializing embassy runtime");
let systimer = systimer::SystemTimer::new(systimer);
let alarms = systimer.split::<esp_hal::timer::systimer::Target>();
esp_hal_embassy::init(clocks, alarms.alarm0);
}
}
Please note - the device will not go back to advertising on disconnect.
Discovery of services seems to work fine with both Btleplug and Bluest with default bluez supervision timeout using this demo. I notice the connection happens considerably more quickly in this case too.
I'm about out of time today but I wonder if bleps is using a different version of esp-hal or one of the other crates, and the controller is being configured differently? I'll have at look at this tomorrow if still relevant.
I haven't had a chance yet to try out changing the supervision timeout, but I'll try that tomorrow too.
Oops yes that's important info too! Excerpt from the Cargo.toml:
[dependencies]
esp-hal = { version = "0.20.1", features = ["async", "log"] }
esp-println = { version = "0.11.0", features = ["log"] }
esp-backtrace = { version = "0.14.0", features = ["exception-handler", "panic-handler", "println"] }
log = { version = "0.4.21" }
esp-alloc = { version = "0.4.0" }
esp-wifi = { version = "0.8.0", features = ["phy-enable-usb", "utils", "ble", "async", "ipv4"] }
bleps = { git = "https://github.com/bjoernQ/bleps", package = "bleps", features = ["macros", "async"] }
embassy-executor = { version = "0.6.0", features = ["task-arena-size-10240"] }
embassy-time = "0.3.1"
esp-hal-embassy = { version = "0.3.0", features = ["integrated-timers"] }
libm = "0.2.8"
So the obvious culprit here is esp-wifi, which is v0.8.0 in the bleps demo and v0.9.1 in the TrouBLE demo. I tried switching the bleps demo to use esp-wifi v0.9.1 and that works (service discovery works consistently). I then tried switching the TrouBLE demo to using v0.8.0 but this will not compile due to dependency issues:
error: failed to select a version for `esp-hal`.
... required by package `esp-wifi v0.8.0`
... which satisfies dependency `esp-wifi = "^0.8.0"` of package `trouble-esp32-examples v0.1.0 (/home/pkubiak/repos/trouble/examples/esp32)`
versions that meet the requirements `^0.20.0` are: 0.20.1
the package `esp-wifi` depends on `esp-hal`, with features: `async` but `esp-hal` does not have these features.
failed to select a version for `esp-hal` which could resolve this conflict
This confused me for a while, because esp-hal clearly does have an async feature as it's included in the list of features for esp-hal in the bleps demo dependencies above.
Then I realised that the esp crates are pinned to an unreleased commit on esp-hal.
Sounds to me like you might be right, that this issue is actually with changes in the development version of the esp-hal and not with Trouble itself. I tried pinning the esp crates to the tip of main in case a fix had been merged but the behaviour is the same (no services discovered).
I tried for a little while to see if I could modify the TrouBLE example to use the release version of esp-hal so we could compare like for like, but as I'm not so familiar with the crate it seemed like it was quickly going to develop into a rabbit-hole.
Instead, I pinned the esp-hal version of the bleps demo to the tip of main by copying the [patches.crate-io] section of TrouBLE's Cargo.toml and updated the bleps demo to conform with the new esp-hal API.
Even with these changes, service discovery is still successful and reliable with the bleps demo.
Here is the bleps demo modified to work with the development version of esp-hal:
#![no_std]
#![no_main]
use bleps::ad_structure::{
create_advertising_data, AdStructure, BR_EDR_NOT_SUPPORTED, LE_GENERAL_DISCOVERABLE,
};
use bleps::async_attribute_server::AttributeServer;
use bleps::asynch::Ble;
use bleps::att::Uuid;
use bleps::attribute_server::{NotificationData, WorkResult};
use bleps::event::EventType;
use bleps::no_rng::NoRng;
use bleps::PollResult;
use embassy_executor::Spawner;
use embassy_time::{Duration, Timer};
use esp_alloc as _;
use esp_backtrace as _;
use esp_hal::clock::CpuClock;
use esp_hal::peripherals::{BT, RADIO_CLK, SYSTIMER};
use esp_hal::rng::Rng;
use esp_hal::timer::timg::{TimerGroup, TimerX};
use esp_hal::timer::{systimer, timg};
use esp_hal_embassy::main;
use esp_wifi::ble::controller::asynch::BleConnector;
use esp_wifi::{initialize, EspWifiInitFor};
use log::info;
#[main]
async fn main(_spawner: Spawner) -> ! {
// Initialize the logger
esp_println::logger::init_logger(log::LevelFilter::Info);
init_heap();
// Initialize the hardware
let b = Board::init();
// Initialize the BLE stack
let ble_init = initialize(EspWifiInitFor::Ble, b.timer, b.rng, b.radio_clocks).unwrap();
let connector = BleConnector::new(&ble_init, b.ble);
let mut ble = Ble::new(connector, esp_wifi::current_millis);
let service_uuids = &[bleps::att::Uuid::Uuid16(0x1809)];
let mut rf3 = |_offset: usize, data: &mut [u8]| {
data[..5].copy_from_slice(&b"Hola!"[..]);
5
};
let mut wf3 = |offset: usize, data: &[u8]| {
info!("RECEIVED: Offset {}, data {:?}", offset, data);
};
let mut my_descriptor_read_function = |_offset: usize, data: &mut [u8]| {
data[..5].copy_from_slice(&b"Desc!"[..]);
5
};
let mut notify = |enabled: bool| {
info!("enabled = {enabled}");
};
let mut rf = rf3;
let mut notify2 = notify;
bleps::gatt!([service {
uuid: "937312e0-2354-11eb-9f10-fbc30a62cf38",
characteristics: [
characteristic {
name: "my_characteristic",
description: "Sine wave notifier",
descriptors: [descriptor {
uuid: "dfe57a9f-4495-45ba-9e02-df1a010b618c",
read: my_descriptor_read_function,
},],
uuid: "987312e0-2354-11eb-9f10-fbc30a62cf38",
notify: true,
read: rf3,
write: wf3,
notify_cb: notify,
},
characteristic {
name: "triangle_wave",
description: "Triangle wave notifier",
uuid: "937312e0-2354-11eb-9f10-fbc30a62cf38",
notify: true,
read: rf,
notify_cb: notify2,
}
],
},]);
advertise(&mut ble, service_uuids, "BLEPS DEMO").await;
let mut rng = NoRng;
let mut srv = AttributeServer::new(&mut ble, &mut gatt_attributes, &mut rng);
let mut counter = 0.0;
let mut tri_counter: f32 = 1.0;
let mut tri_adder = 1.0;
loop {
let mut cccd = [0u8; 1];
srv.get_characteristic_value(my_characteristic_notify_enable_handle, 0, &mut cccd);
if cccd[0] == 1 {
match srv
.do_work_with_notification(Some(NotificationData::new(
my_characteristic_handle,
&libm::sinf(counter).to_le_bytes(),
)))
.await
{
Ok(res) => match res {
WorkResult::DidWork => {
info!("Notify {counter}");
}
WorkResult::GotDisconnected => {
info!("Disconnected!");
}
},
Err(_) => todo!(),
}
counter += 0.1;
Timer::after(Duration::from_millis(200)).await;
} else {
let _ = srv.do_work().await;
}
let mut cccd = [0u8; 1];
srv.get_characteristic_value(triangle_wave_notify_enable_handle, 0, &mut cccd);
if cccd[0] == 1 {
match srv
.do_work_with_notification(Some(NotificationData::new(triangle_wave_handle, {
if tri_counter as i32 % 25 == 0 {
tri_adder = -tri_adder;
}
&tri_counter.to_le_bytes()
})))
.await
{
Ok(res) => {
if let WorkResult::GotDisconnected = res {
info!("Disconnected (TW)")
}
}
Err(_) => todo!(),
}
tri_counter += tri_adder;
}
}
}
fn init_heap() {
esp_alloc::heap_allocator!(72 * 1024);
}
async fn advertise(
ble: &mut Ble<BleConnector<'static>>,
service_uuids: &[Uuid],
name: &str,
) -> bool {
info!("{:?}", ble.init().await);
info!("{:?}", ble.cmd_set_le_advertising_parameters().await);
info!(
"{:?}",
ble.cmd_set_le_advertising_data(
create_advertising_data(&[
AdStructure::Flags(LE_GENERAL_DISCOVERABLE | BR_EDR_NOT_SUPPORTED),
AdStructure::ServiceUuids16(service_uuids),
AdStructure::CompleteLocalName(name),
])
.unwrap()
)
.await
);
info!("{:?}", ble.cmd_set_le_advertise_enable(true).await);
info!("started advertising");
loop {
if let Some(PollResult::Event(event)) = ble.poll().await {
// info!("{:?}", event);
match event {
EventType::DisconnectComplete { reason, .. } => {
info!("Disconnected: {:?}", reason);
break false;
}
EventType::ConnectionComplete { .. } => {
info!("Connected BLE!");
break true;
}
EventType::LongTermKeyRequest { .. } => unimplemented!(),
other => info!("Unhandled event: {:?}", other),
}
};
}
}
struct Board {
pub timer: timg::Timer<TimerX<esp_hal::peripherals::TIMG0, 0>, esp_hal::Blocking>,
pub rng: Rng,
pub radio_clocks: RADIO_CLK,
pub ble: BT,
}
impl Board {
pub fn init() -> Self {
let p = esp_hal::init({
let mut config = esp_hal::Config::default();
config.cpu_clock = CpuClock::max();
config
});
let timg0 = TimerGroup::new(p.TIMG0);
Board::init_embassy(p.SYSTIMER);
Self {
timer: timg0.timer0,
rng: Rng::new(p.RNG),
radio_clocks: p.RADIO_CLK,
ble: p.BT,
}
}
/// Initialize the embassy runtime
fn init_embassy(systimer: SYSTIMER) {
info!("Initializing embassy runtime");
let systimer = systimer::SystemTimer::new(systimer);
let alarms = systimer.split::<esp_hal::timer::systimer::Target>();
esp_hal_embassy::init(alarms.alarm0);
}
}
and the associated Cargo.toml:
[package]
name = "esp32c3-embassy"
version = "0.1.0"
authors = ["James Sizeland", "Pete Kubiak"]
edition = "2021"
license = "MIT OR Apache-2.0"
[dependencies]
esp-hal = { version = "0.20.1", features = ["log"] }
esp-println = { version = "0.11.0", features = ["log"] }
esp-backtrace = { version = "0.14.0", features = [
"exception-handler",
"panic-handler",
"println",
] }
log = { version = "0.4.21" }
esp-alloc = { version = "0.4.0" }
esp-wifi = { version = "0.9.1", features = [
"phy-enable-usb",
"utils",
"ble",
"async",
"ipv4",
] }
bleps = { git = "https://github.com/bjoernQ/bleps", package = "bleps", features = [
"macros",
"async",
] }
embassy-executor = { version = "0.6.0", features = ["task-arena-size-10240"] }
embassy-time = "0.3.1"
esp-hal-embassy = { version = "0.3.0", features = ["integrated-timers"] }
libm = "0.2.8"
[profile.dev]
opt-level = "s"
[profile.release]
codegen-units = 1 # LLVM can perform better optimizations using a single thread
debug = 2 # Debug levels: 0 no info, 1 minimal info, 2 full info
debug-assertions = false # Debug assertions are slow
incremental = false # Incremental compilation off
lto = 'thin' # Use ThinLTO
opt-level = 3 # 0 none, 1 basic, 2 some, 3 full, s size, z size and turn off loop vectorization
overflow-checks = false # Overflow checks are slow
[features]
default = ["esp32c3"]
esp32c3 = [
"esp-hal/esp32c3",
"esp-backtrace/esp32c3",
"esp-hal-embassy/esp32c3",
"esp-println/esp32c3",
# "esp-storage?/esp32c3",
"esp-wifi/esp32c3",
# "esp-hal-smartled/esp32c3",
]
esp32c6 = [
"esp-hal/esp32c6",
"esp-backtrace/esp32c6",
"esp-hal-embassy/esp32c6",
"esp-println/esp32c6",
# "esp-storage?/esp32c6",
"esp-wifi/esp32c6",
# "esp-hal-smartled/esp32c6",
# "esp-ieee802154/esp32c6",
]
[patch.crates-io]
esp-hal = { git = "https://github.com/esp-rs/esp-hal.git", branch = "main" }
esp-hal-embassy = { git = "https://github.com/esp-rs/esp-hal.git", branch = "main" }
esp-wifi = { git = "https://github.com/esp-rs/esp-hal.git", branch = "main" }
esp-println = { git = "https://github.com/esp-rs/esp-hal.git", branch = "main" }
esp-backtrace = { git = "https://github.com/esp-rs/esp-hal.git", branch = "main" }
esp-alloc = { git = "https://github.com/esp-rs/esp-hal.git", branch = "main" }
Thanks, this is really useful. I'm not able to test right now, but I will try to reproduce your findings. In the meantime, could you try to switch this line https://github.com/embassy-rs/trouble/blob/main/examples/esp32/Cargo.toml#L53 to opt-level = 3? I noticed that esp-wifi docs recommend to use this setting, maybe it has an impact on the speed, I'm not sure.
In any case, I will try your example code.
So, I tried your example and it works for me too. I also got the trouble example working after moving the esp32 from above my desk to directly connect to my PC, so it seems to me this is a range/connection timeout issue. If you can try to adjust the supervision timeout on your system, I think that would confirm or refute this hypothesis.
Now as to why this work with bleps and not trouble for you, that has my head scratching. Since connection establishment is really handled by the esp-wifi HCI controller and not trouble or bleps (they only consume the events after the fact), it should not behave differently. The only thing I can think of is that trouble somehow prevents the HCI controller to respond to the connection request, for instance by not polling it quickly enough (If that is required for it to process/respond to connection requests, that could be one explaination).
If you could adjust your ESP_LOGTARGETS and ESP_LOGLEVEL to enable the trace log level for the trouble_host crate (and pull latest changes in main), that might give some more indications what trouble is doing around the time of the connect timeout.
Curiouser and curiouser...
First off, I tried switching to opt-level = 3 but the outcome was the same.
I attempted to change my machine's supervision timeout but unfortunately that seems to be locked down (I get "permission denied" even when using sudo - I assume it's because this is my work machine).
Compiling and running the latest changes to trouble/main with
ESP_LOGLEVEL=trace ESP_LOGTARGETS=trouble_host cargo build -r --target=riscv32imc-unknown-none-elf
espflash flash target/riscv32imc-unknown-none-elf/release/ble_bas_peripheral --monitor
and then attempting to connect gave the following trace:
I (24) boot: ESP-IDF v5.1.2-342-gbcf1645e44 2nd stage bootloader
I (24) boot: compile time Dec 12 2023 10:50:58
I (25) boot: chip revision: v0.4
I (29) boot.esp32c3: SPI Speed : 40MHz
I (34) boot.esp32c3: SPI Mode : DIO
I (38) boot.esp32c3: SPI Flash Size : 4MB
I (43) boot: Enabling RNG early entropy source...
I (48) boot: Partition Table:
I (52) boot: ## Label Usage Type ST Offset Length
I (59) boot: 0 nvs WiFi data 01 02 00009000 00006000
I (67) boot: 1 phy_init RF data 01 01 0000f000 00001000
I (74) boot: 2 factory factory app 00 00 00010000 003f0000
I (82) boot: End of partition table
I (86) esp_image: segment 0: paddr=00010020 vaddr=3c040020 size=0a620h ( 42528) map
I (104) esp_image: segment 1: paddr=0001a648 vaddr=3fc84d10 size=003fch ( 1020) load
I (104) esp_image: segment 2: paddr=0001aa4c vaddr=3fca83e8 size=00078h ( 120) load
I (111) esp_image: segment 3: paddr=0001aacc vaddr=40380000 size=04d10h ( 19728) load
I (125) esp_image: segment 4: paddr=0001f7e4 vaddr=00000000 size=00834h ( 2100)
I (128) esp_image: segment 5: paddr=00020020 vaddr=42000020 size=36754h (223060) map
I (187) boot: Loaded app from partition at offset 0x10000
I (187) boot: Disabling RNG early entropy source...
INFO - [host] filter accept list size: 12
INFO - [host] setting txq to 12
INFO - [host] configuring host buffers (8 packets of size 251)
INFO - [host] initialized
TRACE - [host] enabling advertising
TRACE - [host] connection with handle ConnHandle(1) established to BdAddr([f0, 15, 1c, 31, 15, cc])
TRACE - [link][poll_accept] connection handle ConnHandle(1) in role Peripheral accepted
TRACE - [host] agreed att MTU of 247
INFO - [host] disconnection event on handle 1, reason: Remote User Terminated Connection
TRACE - [link][pool_request_to_send] connection ConnHandle(1) not found
TRACE - [host] disabling advertising
TRACE - [host] enabling advertising
The central side reported that the connection was successful but no services were discovered.
I also tried switching to the fut-split branch and ran that with the same commands, but got exactly the same result.
@peteskubiak Maybe you have already done this, so apologies if you have, but in case you didn't, try these things:
- make sure the redirect is run as sudo as well:
sudo sh -c "echo -n 200 > /sys/kernel/debug/bluetooth/hci0/supervision_timeout" - If you're still getting permission denied, do a
sudo ls /sys/kernel/debug/bluetoothto make sure your BLE adapter is in fact hci0, and adjust path accordingly. - If you're still getting permissions denied, it could be that you don't have bluetooth debug enabled in linux kernel, which you can confirm by
sudo ls /sys/kernel/debug/bluetooth/hci0(or the appropriate adapter path). If there is no supervision_timeout file, it means there is no bluetooth debug enabled in the linux kernel, and supervision timeout cannot be adjusted.
Thanks for all the info! It seems like the debug is enabled, but I have no access to it:
❯ sudo sh -c "echo -n 200 > /sys/kernel/debug/bluetooth/hci0/supervision_timeout"
sh: 1: cannot create /sys/kernel/debug/bluetooth/hci0/supervision_timeout: Operation not permitted
❯ sudo ls /sys/kernel/debug/bluetooth
hci0 l2cap rfcomm rfcomm_dlc sco
❯ sudo ls /sys/kernel/debug/bluetooth/hci0
adv_channel_map device_id inquiry_cache rpa_timeout
adv_max_interval device_list link_keys sc_only_mode
adv_min_interval discov_interleaved_timeout long_term_keys sniff_max_interval
auth_payload_timeout dut_mode manufacturer sniff_min_interval
auto_accept_delay features max_key_size ssp_debug_mode
blacklist force_no_mitm min_encrypt_key_size static_address
blocked_keys force_static_address min_key_size supervision_timeout
conn_info_max_age hardware_error quirk_simultaneous_discovery use_debug_keys
conn_info_min_age hci_revision quirk_strict_duplicate_filter uuids
conn_latency hci_version random_address vendor_diag
conn_max_interval identity remote_oob voice_setting
conn_min_interval identity_resolving_keys resolv_list white_list
dev_class idle_timeout resolv_list_size white_list_size
I tried sudo sh -c "cat /sys/kernel/debug/bluetooth/hci0/supervision_timeout" as well but got another "Operation not permitted"
Thanks, then it's clear that you can't write it, hmm.
This line in your log output seems to indicate that it is indeed the Linux side that terminates the connection:
INFO - [host] disconnection event on handle 1, reason: Remote User Terminated Connection
So it is likely related to supervision timeout not being met by the controller. I think I'd need to experiment a bit more, trying to measure the time between polls etc, creating a minimal reproducer that is independent of trouble and bleps.
@peteskubiak So, I've found 2 things that I've fixed on main now, if you care to try. I measured the timings from connection establish and until discovery was complete for both bleps and trouble, and made the following adjustments to the defaults so that they appear identical in the packet trace. I couldn't find any differences in bleps and trouble timings after that (although I would say the esp32 generally seems sensitive to BLE range).
- Shorten the default advertising interval to match the default of bleps (it used 160ms instead of 240ms which was the trouble default). This should remove any differences in time to establish a connection.
- Prioritize outbound responses in the runner, so that mtu exchange and other things are responded to immediately. I saw in one case the trouble example would respond to the mtu exchange request out of order, which might trip up bluez.
I've just tested with the latest changes on main, but I'm afraid the issue remains. Here is the trace from the peripheral:
TRACE - [host] enabling advertising
TRACE - [host] connection with handle ConnHandle(1) established to BdAddr([f0, 15, 1c, 31, 15, cc])
TRACE - [link][poll_accept] connection handle ConnHandle(1) in role Peripheral accepted
TRACE - [host] agreed att MTU of 247
INFO - [host] disconnection event on handle 1, reason: Remote User Terminated Connection
TRACE - [link][pool_request_to_send] connection ConnHandle(1) not found
TRACE - [host] disabling advertising
TRACE - [host] enabling advertising
Just FYI I haven't actually turned into a ghost, I've just consolidated my organisation account into my personal account. I'm still around to help / test any new developments :)
@petekubiak Let me know when you've been able to retest with your new hardware. Would be great to have this solved before 0.1
Sorry, this completely slipped my mind. I've just retested now that I'm running Ubuntu 22.04 LTS on the same hardware, and the issue has disappeared.
I'm thinking maybe we close this as "can't replicate". Are you happy with that @lulf ?