search

embassy-rs / trouble

A Rust Host BLE stack with a future goal of qualification.
Apache License 2.0
95 stars 12 forks source link

Service discovery request resolves to empty list #123

Open peteskubiak opened 1 week ago

peteskubiak commented 1 week ago

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:

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
lulf commented 6 days ago

Several issues are fixed, so we should try to get main branch working on esp32 first.

lulf commented 6 days ago

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.

lulf commented 6 days ago

@peteskubiak Now with #124 merged, could you retry your testing?

peteskubiak commented 6 days ago

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:

  1. Scan for devices until "Trouble" device is found
  2. Report service UUIDs and service data from advertising packet
  3. Connect to "Trouble" device
  4. 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
lulf commented 6 days ago

@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?

peteskubiak commented 6 days ago

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(())
}
lulf commented 6 days ago

@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:

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.

lulf commented 5 days ago

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

peteskubiak commented 4 days ago

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.

lulf commented 4 days ago

Which versions/revisions of esp crates are you using?

peteskubiak commented 4 days ago

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"
peteskubiak commented 4 days ago

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).

peteskubiak commented 4 days ago

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" }
lulf commented 3 days ago

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.

lulf commented 3 days ago

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.

peteskubiak commented 1 day ago

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.

lulf commented 9 hours ago

@peteskubiak Maybe you have already done this, so apologies if you have, but in case you didn't, try these things:

  1. make sure the redirect is run as sudo as well: 
    sudo sh -c "echo -n 200 > /sys/kernel/debug/bluetooth/hci0/supervision_timeout"
  2. If you're still getting permission denied, do a sudo ls /sys/kernel/debug/bluetooth to make sure your BLE adapter is in fact hci0, and adjust path accordingly.
  3. 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.
peteskubiak commented 8 hours ago

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"

lulf commented 3 hours ago

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.