Sleeping on main thread prevents dispatching of events

[geNAZt]

Hi,

i'm currently running a debian 11 install with bluez 5.55 on it (the default package version from debian repo) and want to implement a small geofencing application.

Currently i'm stuck in bluer not getting any pairing requests from bluez.

This is the rust code:

use bluer::{id, agent::{Agent, RequestAuthorization, ReqResult, RequestConfirmation, AuthorizeService, DisplayPinCode, DisplayPasskey}, Uuid, UuidExt};
use core::time;
use std::{thread, str::FromStr, fmt};
use log::{info};

#[derive(Clone, Copy)]
struct UuidOrShort(pub Uuid);

impl FromStr for UuidOrShort {
    type Err = String;

    fn from_str(s: &str) -> std::result::Result<Self, Self::Err> {
        match s.parse::<Uuid>() {
            Ok(uuid) => Ok(Self(uuid)),
            Err(_) => match u16::from_str_radix(s, 16) {
                Ok(short) => Ok(Self(Uuid::from_u16(short))),
                Err(_) => Err(s.to_string()),
            },
        }
    }
}

impl From<UuidOrShort> for Uuid {
    fn from(u: UuidOrShort) -> Self {
        u.0
    }
}

impl From<Uuid> for UuidOrShort {
    fn from(u: Uuid) -> Self {
        Self(u)
    }
}

impl fmt::Display for UuidOrShort {
    fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
        if let Some(s) = self.0.as_u16() {
            write!(f, "{:04x}", s)
        } else {
            write!(f, "{}", self.0)
        }
    }
}

async fn request_authorization(req: RequestAuthorization) -> ReqResult<()> {
    info!("Is device {} on {} allowed to pair? (y/n)", &req.device, &req.adapter);
    Ok(())
}

async fn request_confirmation(req: RequestConfirmation) -> ReqResult<()> {
    info!("Is device {} on {} allowed to pair? (y/n)", &req.device, &req.adapter);
    Ok(())
}

async fn authorize_service(req: AuthorizeService) -> ReqResult<()> {
    let service_id = match id::Service::try_from(req.service) {
        Ok(name) => format!("{} ({})", name, UuidOrShort(req.service)),
        Err(_) => format!("{}", UuidOrShort(req.service)),
    };
    info!("Is device {} on {} allowed to use service {}? (y/n)", &req.device, &req.adapter, service_id);
    Ok(())
}

async fn display_pin_code(req: DisplayPinCode) -> ReqResult<()> {
    info!("PIN code for device {} on {} is \"{}\"", &req.device, &req.adapter, req.pincode);
    Ok(())
}

async fn display_passkey(req: DisplayPasskey) -> ReqResult<()> {
    info!("Passkey for device {} on {} is \"{:06}\"", &req.device, &req.adapter, req.passkey);
    Ok(())
}

#[tokio::main(flavor = "current_thread")]
async fn main() -> bluer::Result<()> {
    env_logger::init();
    let session = bluer::Session::new().await?;
    let adapter = session.default_adapter().await?;
    info!("Free pairing devices for {}", adapter.name());
    adapter.set_powered(true).await?;

    let agent = Agent {
        request_default: true,
        display_pin_code: Some(Box::new(|req| Box::pin(display_pin_code(req)))),
        display_passkey: Some(Box::new(|req| Box::pin(display_passkey(req)))),
        request_confirmation: Some(Box::new(move |req| {
            Box::pin(request_confirmation(req))
        })),
        request_authorization: Some(Box::new(move |req| {
            Box::pin(request_authorization(req))
        })),
        authorize_service: Some(Box::new(|req| Box::pin(authorize_service(req)))),
        ..Default::default()
    };
    let _agent_handle = session.register_agent(agent).await?;

    adapter.set_pairable_timeout(0).await?;
    adapter.set_pairable(true).await?;
    adapter.set_discoverable_timeout(0).await?;
    adapter.set_discoverable(true).await?;

    thread::sleep(time::Duration::from_secs(600));

    Ok(())
}

BlueZ returns a src/agent.c:simple_agent_reply() Timed out waiting for reply from agent when not in debug mode.

BlueR trace logs:

[2022-04-08T22:44:43Z TRACE bluer::session] Connected to D-Bus with unique name :1.1911
[2022-04-08T22:44:43Z TRACE mio::poll] registering event source with poller: token=Token(1), interests=READABLE
[2022-04-08T22:44:43Z TRACE bluer::session] Starting event loop for :1.1911
[2022-04-08T22:44:43Z INFO  ble_fencer] Free pairing devices for hci0
[2022-04-08T22:44:43Z TRACE bluer::adapter] /org/bluez/hci0: org.bluez.Adapter1.Powered := true
[2022-04-08T22:44:43Z TRACE bluer::agent] Publishing agent at /org/bluez/bluer/agent/af0e3da48d3b4568a49ccc8b8a9bb289 with capability DisplayYesNo
[2022-04-08T22:44:43Z TRACE bluer::agent] Registering agent at /org/bluez/bluer/agent/af0e3da48d3b4568a49ccc8b8a9bb289
[2022-04-08T22:44:43Z TRACE bluer::agent] Requesting default agent for /org/bluez/bluer/agent/af0e3da48d3b4568a49ccc8b8a9bb289
[2022-04-08T22:44:43Z TRACE bluer::adapter] /org/bluez/hci0: org.bluez.Adapter1.PairableTimeout := 0
[2022-04-08T22:44:43Z TRACE bluer::adapter] /org/bluez/hci0: org.bluez.Adapter1.Pairable := true
[2022-04-08T22:44:43Z TRACE bluer::adapter] /org/bluez/hci0: org.bluez.Adapter1.DiscoverableTimeout := 0
[2022-04-08T22:44:43Z TRACE bluer::adapter] /org/bluez/hci0: org.bluez.Adapter1.Discoverable := true

BlueZ journalctl with debug on:

Apr 09 00:44:39 kube bluetoothd[259103]: src/adapter.c:new_settings_callback() Settings: 0x00000acb
Apr 09 00:44:39 kube bluetoothd[259103]: src/adapter.c:settings_changed() Changed settings: 0x00000010
Apr 09 00:44:39 kube bluetoothd[259103]: src/adapter.c:settings_changed() Pending settings: 0x00000000
Apr 09 00:44:43 kube bluetoothd[259103]: src/agent.c:add_default_agent() Default agent set to :1.1911 /org/bluez/bluer/agent/af0e3da48d3b4568a49ccc8b8a9bb289
Apr 09 00:44:43 kube bluetoothd[259103]: src/adapter.c:set_mode() sending set mode command for index 0
Apr 09 00:44:43 kube bluetoothd[259103]: src/agent.c:agent_ref() 0x560e0db50750: ref=1
Apr 09 00:44:43 kube bluetoothd[259103]: src/agent.c:register_agent() agent :1.1911
Apr 09 00:44:43 kube bluetoothd[259103]: src/adapter.c:new_settings_callback() Settings: 0x00000adb
Apr 09 00:44:43 kube bluetoothd[259103]: src/adapter.c:settings_changed() Changed settings: 0x00000010
Apr 09 00:44:43 kube bluetoothd[259103]: src/adapter.c:settings_changed() Pending settings: 0x00000000
Apr 09 00:44:43 kube bluetoothd[259103]: src/adapter.c:set_discoverable() sending set mode command for index 0
Apr 09 00:44:43 kube bluetoothd[259103]: src/adapter.c:set_mode() sending set mode command for index 0
Apr 09 00:44:56 kube bluetoothd[259103]: src/adapter.c:connected_callback() hci0 device A0:4F:85:01:A7:08 connected eir_len 12
Apr 09 00:44:56 kube bluetoothd[259103]: src/device.c:device_create() dst A0:4F:85:01:A7:08
Apr 09 00:44:56 kube bluetoothd[259103]: src/device.c:device_new() address A0:4F:85:01:A7:08
Apr 09 00:44:56 kube bluetoothd[259103]: src/device.c:device_new() Creating device /org/bluez/hci0/dev_A0_4F_85_01_A7_08
Apr 09 00:44:56 kube bluetoothd[259103]: src/device.c:device_set_class() /org/bluez/hci0/dev_A0_4F_85_01_A7_08 0x5A020C
Apr 09 00:44:57 kube bluetoothd[259103]: src/adapter.c:user_confirm_request_callback() hci0 A0:4F:85:01:A7:08 confirm_hint 0
Apr 09 00:44:57 kube bluetoothd[259103]: src/device.c:new_auth() Requesting agent authentication for A0:4F:85:01:A7:08
Apr 09 00:44:57 kube bluetoothd[259103]: src/agent.c:agent_ref() 0x560e0db50750: ref=2
Apr 09 00:44:57 kube bluetoothd[259103]: src/agent.c:agent_request_confirmation() Calling Agent.RequestConfirmation: name=:1.1911, path=/org/bluez/bluer/agent/af0e3da48d3b4568a49ccc8b8a9bb289, passkey=827801
Apr 09 00:45:16 kube bluetoothd[259103]: src/adapter.c:bonding_attempt_complete() hci0 bdaddr A0:4F:85:01:A7:08 type 0 status 0x5
Apr 09 00:45:16 kube bluetoothd[259103]: src/device.c:device_bonding_complete() bonding (nil) status 0x05
Apr 09 00:45:16 kube bluetoothd[259103]: src/agent.c:send_cancel_request() Sending Cancel request to :1.1911, /org/bluez/bluer/agent/af0e3da48d3b4568a49ccc8b8a9bb289
Apr 09 00:45:16 kube bluetoothd[259103]: src/device.c:device_cancel_authentication() Canceling authentication request for A0:4F:85:01:A7:08
Apr 09 00:45:16 kube bluetoothd[259103]: src/agent.c:agent_unref() 0x560e0db50750: ref=1
Apr 09 00:45:16 kube bluetoothd[259103]: src/device.c:device_bonding_failed() status 5
Apr 09 00:45:16 kube bluetoothd[259103]: src/adapter.c:resume_discovery()
Apr 09 00:45:16 kube bluetoothd[259103]: src/adapter.c:dev_disconnected() Device A0:4F:85:01:A7:08 disconnected, reason 3
Apr 09 00:45:16 kube bluetoothd[259103]: src/adapter.c:adapter_remove_connection()
Apr 09 00:45:16 kube bluetoothd[259103]: plugins/policy.c:disconnect_cb() reason 3
Apr 09 00:45:16 kube bluetoothd[259103]: src/adapter.c:bonding_attempt_complete() hci0 bdaddr A0:4F:85:01:A7:08 type 0 status 0xe
Apr 09 00:45:16 kube bluetoothd[259103]: src/device.c:device_bonding_complete() bonding (nil) status 0x0e
Apr 09 00:45:16 kube bluetoothd[259103]: src/device.c:device_bonding_failed() status 14
Apr 09 00:45:16 kube bluetoothd[259103]: src/adapter.c:resume_discovery()
Apr 09 00:45:46 kube bluetoothd[259103]: src/device.c:device_remove() Removing device /org/bluez/hci0/dev_A0_4F_85_01_A7_08
Apr 09 00:45:46 kube bluetoothd[259103]: src/device.c:btd_device_unref() Freeing device /org/bluez/hci0/dev_A0_4F_85_01_A7_08
Apr 09 00:45:46 kube bluetoothd[259103]: src/device.c:device_free() 0x560e0db5a1e0

Is this because i don't run blueZ 5.60? If so would it be possible, maybe with a PR, to get compability with the default debian version?

Thanks :)

[geNAZt]

Just to let everyone know. Sleeping on the main thread is a stupid idea since nothing will get any messages anymore. Using tokio sleep solved the problem for me.