Windows - irregular connection timing

[Nilsandren]

Hi!

I am using bleak (latest stable) for windows and nordic devices as peripherals. The peripheral has a 3 second advertising interval. I have a problem with connection timeouts (sometimes I managed to connect to the peripheral, but sometimes it got a timeout for a few tries in a row). In my code, I will try to connect multiple times.

I found this reported issue #350, and tried to play around with the timeout mentioned there in the file bleak/bleak/backends/dotnet/client.py :

await asyncio.wait_for(event.wait(), timeout=10)

Using the default of 10 seconds, I would say that the success rate of connecting to the peripheral is about 1 out of 4-5 times. When Increasing this value to around 30 seconds the success rate is about 4 out of 5 times. However, I can't seem to find any pattern in the time it takes to connect to the device (it could be anything between 2 seconds to 30 seconds).

Do anyone have any advise on how to further investigate why time to connect is varying this much? Is the backend perhaps retrying multiple times? I have debug log activated but nothing is logged between connection attempt until success:

2021-02-22 13:48:16,610 DEBUG Connecting to BLE device @ DF:DB:08:20:5D:F7
2021-02-22 13:48:39,346 DEBUG _ConnectionStatusChanged_Handler: 1

I wasn't sure if this should be reported as an issue or not, but I thought it could be more fitting here. When using an iphone or android the connection time is much quicker and more consistent.

bleak version: 0.10.0
Python version: 3.7.8
Operating System: Win10

[hbldh]

There are multiple reports of this, and I haven't been able to discern why or remedy it.

Could you please add some more logging in the bleak/backends/dotnet/client.py file?

• Line 176: logger.debug("Obtained BluetoothLEDevice object")
• Line 218: logger.debug("Adding ConnectionStatusChanged event handler")
• Line 231: logger.debug("Asking for GattSession")
• Line 237: logger.debug("Obtained a GattSession")
• Line 240: logger.debug("Waiting for _ConnectionStatusChanged_Handler to fire...")

This is an example from my usage of Bleak in Windows:

2021-02-25 19:57:37,391 bleak.backends.dotnet.scanner DEBUG: Received 24:71:89:CC:09:05: Unknown.
2021-02-25 19:57:37,420 bleak.backends.dotnet.scanner DEBUG: Received 24:71:89:CC:09:05: CC2650 SensorTag.
2021-02-25 19:57:37,421 bleak.backends.dotnet.client DEBUG: Connecting to BLE device @ 24:71:89:cc:09:05
2021-02-25 19:57:38,796 bleak.backends.dotnet.client DEBUG: _ConnectionStatusChanged_Handler: 1
2021-02-25 19:57:38,798 bleak.backends.dotnet.client DEBUG: Get Services...
2021-02-25 19:57:39,522 bleak.backends.dotnet.client INFO: Services resolved for BleakClientDotNet (24:71:89:cc:09:05)
2021-02-25 19:57:39,522 bleak    INFO: Connected: True
2021-02-25 19:57:39,645 bleak.backends.dotnet.client DEBUG: Read Characteristic 00002a23-0000-1000-8000-00805f9b34fb : bytearray(b'\x05\t\xcc\x00\x00\x89q$')
System ID: 24:71:89:00:00:cc:09:05
2021-02-25 19:57:39,765 bleak.backends.dotnet.client DEBUG: Read Characteristic 00002a24-0000-1000-8000-00805f9b34fb : bytearray(b'CC2650 SensorTag')
Model Number: CC2650 SensorTag
2021-02-25 19:57:39,890 bleak.backends.dotnet.client DEBUG: Read Characteristic 00002a00-0000-1000-8000-00805f9b34fb : bytearray(b'SensorTag 2.0')
Device Name: SensorTag 2.0
2021-02-25 19:57:40,005 bleak.backends.dotnet.client DEBUG: Read Characteristic 00002a29-0000-1000-8000-00805f9b34fb : bytearray(b'Texas Instruments')
Manufacturer Name: Texas Instruments
2021-02-25 19:57:45,947 bleak.backends.dotnet.client DEBUG: Disconnecting from BLE device...
2021-02-25 19:57:49,006 bleak.backends.dotnet.client DEBUG: _ConnectionStatusChanged_Handler: 0

My TI SensorTag is discovered quickly, connected to quickly and services are resolved quickly (I think they were cached in Windows here though). Though I think the Sensortag is programmed to be "an active BLE peripheral"...

FWIW, Bleak is not the only one that feels the effects of this: https://docs.microsoft.com/en-us/answers/questions/39802/windows-ble-scanning-interval-issue.html

[hbldh]

Oh. That was pretty stupid of me, not to give you line numbers in the actual release code... Sorry.

• Line 141: (Before device = [...]) logger.debug("Calling find_device_by_address...)
• Line 167: (After self._requester = [...]) logger.debug("Obtained BluetoothLEDevice object")
• Line 209: (Before self._connection_status_changed_token = [...]) logger.debug("Adding ConnectionStatusChanged event handler")
• Line 222: (Before self._session = [...]) logger.debug("Asking for GattSession")
• Line 228: (After self._session = [...]) logger.debug("Obtained a GattSession")
• Line 231: (Before asyncio.wait) logger.debug("Waiting for _ConnectionStatusChanged_Handler to fire...")

Insert them, run e.g. service_explorer.py and report the results here.

I do not think the number of devices nearby can affect the time it takes to connect. Once Windows have discovered the device, then it has everything it needs to connect. But we'll hopefully see something from the log you produce.

[Nilsandren]

I've run service_explorer.py multiple times now with the added logging. It looks like all these logs trigger quickly and then nothing happens for a while after the last log entry added on line 231. Here are logs from one of the executions:

2021-03-02 13:13:34,383 bleak.backends.dotnet.client DEBUG: Connecting to BLE device @ EC:DF:99:7C:16:58
2021-03-02 13:13:34,458 bleak.backends.dotnet.client DEBUG: Obtained BluetoothLEDevice object
2021-03-02 13:13:34,458 bleak.backends.dotnet.client DEBUG: Adding ConnectionStatusChanged event handler
2021-03-02 13:13:34,459 bleak.backends.dotnet.client DEBUG: Asking for GattSession
2021-03-02 13:13:34,463 bleak.backends.dotnet.client DEBUG: Obtained a GattSession
2021-03-02 13:13:34,464 bleak.backends.dotnet.client DEBUG: Waiting for _ConnectionStatusChanged_Handler to fire...
2021-03-02 13:14:01,413 bleak.backends.dotnet.client DEBUG: _ConnectionStatusChanged_Handler: 1
2021-03-02 13:14:01,415 bleak.backends.dotnet.client DEBUG: Get Services...
2021-03-02 13:14:01,545 bleak.backends.dotnet.client INFO: Services resolved for BleakClientDotNet (EC:DF:99:7C:16:58)
Connected: True
[Service] 00001800-0000-1000-8000-00805f9b34fb: Generic Access Profile
2021-03-02 13:14:02,058 bleak.backends.dotnet.client DEBUG: Read Characteristic 00002a00-0000-1000-8000-00805f9b34fb :

And as before, the time between "Waiting for _ConnectionStatusChanged_Handler to fire..." and "DEBUG: _ConnectionStatusChanged_Handler: 1" varies alot (sometimes 1-2 seconds and sometimes up to 50 seconds)

/Nils

[Nilsandren]

Worth mentioning is that it sometimes gets the timeouterror because it doesn't find the logger within 10 seconds before attempting to connect.

[hbldh]

Is this issue present when you connect to other BLE peripherals using Bleak on the same system?

[Nilsandren]

I've only connected to a bt headset with bleak and didn't experience the issue.