Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Service discovery request resolves to empty list #123

Open
ghost opened this issue Sep 24, 2024 · 24 comments
Open

Service discovery request resolves to empty list #123

ghost opened this issue Sep 24, 2024 · 24 comments
Milestone

Comments

@ghost
Copy link

ghost commented Sep 24, 2024

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
Copy link
Member

lulf commented Sep 24, 2024

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

@lulf
Copy link
Member

lulf commented Sep 24, 2024

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
Copy link
Member

lulf commented Sep 25, 2024

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

@ghost
Copy link
Author

ghost commented Sep 25, 2024

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
Copy link
Member

lulf commented Sep 25, 2024

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

@ghost
Copy link
Author

ghost commented Sep 25, 2024

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
Copy link
Member

lulf commented Sep 25, 2024

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

@lulf
Copy link
Member

lulf commented Sep 25, 2024

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

@ghost
Copy link
Author

ghost commented Sep 26, 2024

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
Copy link
Member

lulf commented Sep 26, 2024

Which versions/revisions of esp crates are you using?

@ghost
Copy link
Author

ghost commented Sep 27, 2024

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"

@ghost
Copy link
Author

ghost commented Sep 27, 2024

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

@ghost
Copy link
Author

ghost commented Sep 27, 2024

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
Copy link
Member

lulf commented Sep 27, 2024

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
Copy link
Member

lulf commented Sep 27, 2024

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.

@ghost
Copy link
Author

ghost commented Sep 30, 2024

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
Copy link
Member

lulf commented Oct 1, 2024

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

@ghost
Copy link
Author

ghost commented Oct 1, 2024

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
Copy link
Member

lulf commented Oct 1, 2024

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.

@lulf
Copy link
Member

lulf commented Oct 2, 2024

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

@ghost
Copy link
Author

ghost commented Oct 2, 2024

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

@petekubiak
Copy link
Collaborator

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

@lulf
Copy link
Member

lulf commented Nov 20, 2024

@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

@lulf lulf added this to the 0.1 milestone Nov 20, 2024
@petekubiak
Copy link
Collaborator

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants