Windows10 - Timeout Exception Raised while connecting

[jppdpf]

• bleak version: 0.12.1
• Python version: 3.9
• Operating System: Windows 10

Description

I'm trying to run the "service_explorer" example script.
It's a regular crash, doesn't happen every time the script is executed but when it happens it persists on the next executions.

What I Did

I have tried to increase the timeout in the BleakClient() constructor to 120 seconds but I get same error.
I also tried to connect to NRF Connect Android app just to make sure that it wasn't some bad configuration on my GATT Server( which is in a Xamarin Application).

StackTrace

C:\Git\dev\bleak_onemoretry\venv\Scripts\python.exe C:/Git/dev/bleak_onemoretry/run_service_explorer.py
Traceback (most recent call last):
  File "C:\Users\jfy\AppData\Local\Programs\Python\Python39\lib\asyncio\locks.py", line 226, in wait
    await fut
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "C:\Users\jfy\AppData\Local\Programs\Python\Python39\lib\asyncio\tasks.py", line 492, in wait_for
    fut.result()
asyncio.exceptions.CancelledError

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "C:\Git\dev\bleak_onemoretry\run_service_explorer.py", line 71, in <module>
    loop.run_until_complete(run(ADDRESS, True))
  File "C:\Users\jfy\AppData\Local\Programs\Python\Python39\lib\asyncio\base_events.py", line 642, in run_until_complete
    return future.result()
  File "C:\Git\dev\bleak_onemoretry\run_service_explorer.py", line 35, in run
    async with BleakClient(address, timeout=120) as client:
  File "C:\Git\dev\bleak_onemoretry\venv\lib\site-packages\bleak\backends\client.py", line 61, in __aenter__
    await self.connect()
  File "C:\Git\dev\bleak_onemoretry\venv\lib\site-packages\bleak\backends\winrt\client.py", line 219, in connect
    await asyncio.wait_for(event.wait(), timeout=timeout)
  File "C:\Users\jfy\AppData\Local\Programs\Python\Python39\lib\asyncio\tasks.py", line 494, in wait_for
    raise exceptions.TimeoutError() from exc
asyncio.exceptions.TimeoutError

Thank you!

[dlech]

Have you tried the suggested troubleshooting? https://bleak.readthedocs.io/en/latest/troubleshooting.html

[jppdpf]

I will try it right now.

[jppdpf]

In the morning I got the timeout exception on disconnecting, while using the service explorer example.
In the afternoon I got on connect and using the connect example.

Using cached doesn't seem to interfere since I got the error in both cases(true or false).

I tried to make sense when using Wireshark, but i didn't know what i was looking for.

Thank you very much, please let me know if there's something more I can do.

bth_hci_logs.zip

Stacktrace of the disconnect, service explorer

(venv) PS C:\Git\dev\bleak_onemoretry> python .\run_service_explorer_og.py
2021-07-22 11:30:01,478 bleak.backends.winrt.scanner DEBUG: Received 5C:53:B4:79:58:08: Unknown.
2021-07-22 11:30:01,479 bleak.backends.winrt.scanner DEBUG: Received 5C:53:B4:79:58:08: Unknown.
2021-07-22 11:30:01,480 bleak.backends.winrt.scanner DEBUG: 1 devices found. Watcher status: 3.
2021-07-22 11:30:01,481 bleak.backends.winrt.client DEBUG: Connecting to BLE device @ 5C:53:B4:79:58:08
2021-07-22 11:30:04,911 bleak.backends.winrt.client DEBUG: _ConnectionStatusChanged_Handler: 1
2021-07-22 11:30:04,915 bleak.backends.winrt.client DEBUG: Get Services...
2021-07-22 11:30:05,053 bleak.backends.winrt.client INFO: Services resolved for BleakClientWinRT (5C:53:B4:79:58:08)
Connected: True
[Service] 00001801-0000-1000-8000-00805f9b34fb (Handle: 1): Generic Attribute Profile
        [Characteristic] 00002a05-0000-1000-8000-00805f9b34fb (Handle: 2):  (indicate), Value: None
[Service] 00001800-0000-1000-8000-00805f9b34fb (Handle: 20): Generic Access Profile
2021-07-22 11:30:05,929 bleak.backends.winrt.client DEBUG: Read Characteristic 00002a00-0000-1000-8000-00805f9b34fb : bytearray(b'Redmi 6')
        [Characteristic] 00002a00-0000-1000-8000-00805f9b34fb (Handle: 21):  (read), Value: b'Redmi 6'
2021-07-22 11:30:06,051 bleak.backends.winrt.client DEBUG: Read Characteristic 00002a01-0000-1000-8000-00805f9b34fb : bytearray(b'\x00\x00')
        [Characteristic] 00002a01-0000-1000-8000-00805f9b34fb (Handle: 23):  (read), Value: b'\x00\x00'
2021-07-22 11:30:06,172 bleak.backends.winrt.client DEBUG: Read Characteristic 00002aa6-0000-1000-8000-00805f9b34fb : bytearray(b'\x01')
        [Characteristic] 00002aa6-0000-1000-8000-00805f9b34fb (Handle: 25):  (read), Value: b'\x01'
[Service] 0000180d-0000-1000-8000-00805f9b34fb (Handle: 40): Heart Rate
        [Characteristic] 00002a37-0000-1000-8000-00805f9b34fb (Handle: 41):  (notify), Value: None
2021-07-22 11:30:06,292 bleak.backends.winrt.client DEBUG: Read Descriptor 43 : bytearray(b'\x00\x00')
                [Descriptor] 00002902-0000-1000-8000-00805f9b34fb (Handle: 43): Client Characteristic Configuration) | Value: b'\x00\x00'
2021-07-22 11:30:06,412 bleak.backends.winrt.client DEBUG: Read Characteristic 00002a38-0000-1000-8000-00805f9b34fb : bytearray(b'\x01')
        [Characteristic] 00002a38-0000-1000-8000-00805f9b34fb (Handle: 44):  (read), Value: b'\x01'
        [Characteristic] 00002a39-0000-1000-8000-00805f9b34fb (Handle: 46):  (write), Value: None
[Service] 0000aaa0-0000-1000-8000-aabbccddeeff (Handle: 48): Unknown
2021-07-22 11:30:06,530 bleak.backends.winrt.client DEBUG: Read Characteristic 0000aaa1-0000-1000-8000-aabbccddeeff : bytearray(b'\x1e\x00')
        [Characteristic] 0000aaa1-0000-1000-8000-aabbccddeeff (Handle: 49): Important value (read,notify), Value: b'\x1e\x00'
2021-07-22 11:30:06,712 bleak.backends.winrt.client DEBUG: Read Descriptor 51 : bytearray(b'\x00\x00')
                [Descriptor] 00002902-0000-1000-8000-00805f9b34fb (Handle: 51): Client Characteristic Configuration) | Value: b'\x00\x00'
2021-07-22 11:30:06,830 bleak.backends.winrt.client DEBUG: Read Descriptor 52 : bytearray(b'\x01#4Vx\x9a')
                [Descriptor] 0000aab0-0000-1000-8000-aabbccddeeff (Handle: 52): None) | Value: b'\x01#4Vx\x9a'
2021-07-22 11:30:06,950 bleak.backends.winrt.client DEBUG: Read Descriptor 53 : bytearray(b'Important value')
                [Descriptor] 00002901-0000-1000-8000-00805f9b34fb (Handle: 53): Characteristic User Description) | Value: b'Important value'
2021-07-22 11:30:07,072 bleak.backends.winrt.client DEBUG: Read Descriptor 54 : bytearray(b"\x06\x00\x01\'\x01\x00\x01")
                [Descriptor] 00002904-0000-1000-8000-00805f9b34fb (Handle: 54): Characteristic Presentation Format) | Value: b"\x06\x00\x01'\x01\x00\x01"
        [Characteristic] 0000aaa2-0000-1000-8000-aabbccddeeff (Handle: 55):  (write-without-response,write,indicate), Value: None
2021-07-22 11:30:07,192 bleak.backends.winrt.client DEBUG: Read Descriptor 57 : bytearray(b'\x00\x00')
                [Descriptor] 00002902-0000-1000-8000-00805f9b34fb (Handle: 57): Client Characteristic Configuration) | Value: b'\x00\x00'
[Service] 0000181c-0000-1000-8000-00805f9b34fb (Handle: 58): User Data
2021-07-22 11:30:07,309 bleak.backends.winrt.client DEBUG: Read Characteristic 00002a8a-0000-1000-8000-00805f9b34fb : bytearray(b'Natenczas')
        [Characteristic] 00002a8a-0000-1000-8000-00805f9b34fb (Handle: 59):  (read,write), Value: b'Natenczas'
2021-07-22 11:30:07,431 bleak.backends.winrt.client DEBUG: Read Characteristic 00002a90-0000-1000-8000-00805f9b34fb : bytearray(b'Wojski')
        [Characteristic] 00002a90-0000-1000-8000-00805f9b34fb (Handle: 61):  (read,write), Value: b'Wojski'
2021-07-22 11:30:07,551 bleak.backends.winrt.client DEBUG: Read Characteristic 00002a8c-0000-1000-8000-00805f9b34fb : bytearray(b'\x00')
        [Characteristic] 00002a8c-0000-1000-8000-00805f9b34fb (Handle: 63):  (read,write), Value: b'\x00'
[Service] be7caab0-1537-450d-b563-128a4221eac0 (Handle: 65): Unknown
2021-07-22 11:30:07,671 bleak.backends.winrt.client DEBUG: Read Characteristic 54aef4f1-728c-491b-9b0c-3f2dc87c9571 : bytearray(b'lido')
        [Characteristic] 54aef4f1-728c-491b-9b0c-3f2dc87c9571 (Handle: 66):  (read), Value: b'lido'
2021-07-22 11:30:07,674 bleak.backends.winrt.client DEBUG: Disconnecting from BLE device...
2021-07-22 11:30:10,791 bleak.backends.winrt.client DEBUG: _ConnectionStatusChanged_Handler: 0
Traceback (most recent call last):
  File "C:\Users\jfy\AppData\Local\Programs\Python\Python39\lib\asyncio\locks.py", line 226, in wait
    await fut
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "C:\Users\jfy\AppData\Local\Programs\Python\Python39\lib\asyncio\tasks.py", line 492, in wait_for
    fut.result()
asyncio.exceptions.CancelledError

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "C:\Git\dev\bleak_onemoretry\run_service_explorer_og.py", line 71, in <module>
    loop.run_until_complete(run(ADDRESS, True))
  File "C:\Users\jfy\AppData\Local\Programs\Python\Python39\lib\asyncio\base_events.py", line 642, in run_until_complete
    return future.result()
  File "C:\Git\dev\bleak_onemoretry\run_service_explorer_og.py", line 65, in run
    log.error(f"\t\t[Descriptor] {descriptor}) | Value: {e}")
  File "C:\Git\dev\bleak_onemoretry\venv\lib\site-packages\bleak\backends\client.py", line 65, in __aexit__
    await self.disconnect()
  File "C:\Git\dev\bleak_onemoretry\venv\lib\site-packages\bleak\backends\winrt\client.py", line 262, in disconnect
    await asyncio.wait_for(event.wait(), timeout=10)
  File "C:\Users\jfy\AppData\Local\Programs\Python\Python39\lib\asyncio\tasks.py", line 494, in wait_for
    raise exceptions.TimeoutError() from exc
asyncio.exceptions.TimeoutError

[dlech]

Try replacing

if __name__ == "__main__":
    loop = asyncio.get_event_loop()
    loop.set_debug(True)
    loop.run_until_complete(run(ADDRESS, True))

with

if __name__ == "__main__":
    asyncio.run(main(ADDRESS, True))

[jppdpf]

Same result

[dlech]

I guess we need to add some more logging to figure out where the problem is. _ConnectionStatusChanged_Handler: 0 is the event from Windows that is being waited for, so somehow it is not triggering asyncio event that the wait_for() is waiting for.

[linweifu]

I also encountered the same problem.
After debugging, locate the problem to bleak\backends\dotnet\client.py
The GattSession.FromDeviceIdAsync(self._requester.BluetoothDeviceId) function did not trigger the BluetoothConnectionStatus.Connected event, which caused the event.wait() to time out.
Modify the code
Move the get_services(use_cached=use_cached) method to the front of event.wait()

self._session.MaintainConnection = True
await self.get_services(use_cached=use_cached)
await asyncio.wait_for(event.wait(), timeout=timeout)

[dlech]

This is a tough one. Setting GattSession.MaintainConnection to true is supposed to initiate the connection. Getting the services will also initiate the connection, but only if use_cached is true. So it is an improvement, but not a complete solution. Handling the timeout is further complicated by the fact that the connection can't be canceled. (relevant docs)

On the disconnect side of things, the device might not disconnect if something else in the OS is using the device, so that could be causing the timeout that was observered there.

[jppdpf]

I'm not using cached. I have been testing the solution @linweifu came up with, but for me it didn't work.

[TomatoCo]

I'm having the same problem. Code that worked in python 3.7 bleak 0.6.1 windows 10 (like 1903 or so) no longer works in python 3.9 bleak 0.12.1 windows 10 20H2. (I'm picking up an old project again and haven't tried anything inbetween). The Get Model Name demo in the README also no longer works. In both cases I just get timeout errors.

However!

Following on from @linweifu I instead commented out the await asyncio.wait_for(event.wait(), timeout=timeout) line. Line 219 in winrt/client.py and 243 in dotnet/client.py. Now it all works as far as I can tell, both my old code and the demo code from the readme.

[dlech]

I've pushed a bunch of changes to the WinRT backend and to the example code to the develop branch over the past couple days. Can everyone please test again using that branch?

[connorwritescode]

I had the same issue with a fresh install from pip today and resolved with the solution from @TomatoCo

[dlech]

I had the same issue with a fresh install from pip today

Does that mean Bleak v0.13.0?

[connorwritescode]

I had the same issue with a fresh install from pip today

Does that mean Bleak v0.13.0?

Yes

[RohanDicholkar]

Do we have any update on this issue? I am still getting the timeouts on Windows10 with github example connect_by_bledevice. the performance is not consistent. Out of 15 attempts I am able to make connection and read services only for once. Behavior is same even with bigger timeouts.

[dlech]

On Windows, you might have better luck using BleakScanner separately and stopping it and restarting it every few seconds. Sometime Windows seems to ignore devices that are advertising, but stopping and restarting the advertisement watcher causes it to start seeing the advertisements.

[RohanDicholkar]

Hello David, Thanks for quick reply. But I am wondering is the issue with Bleakscanner? I am always getting the scanned devices correctly. Issue is mainly observed while creating “client”. I tried with both the ways, async with BleakClient(device) as client: or BleakClient(device) as client & client.connect() But in both the ways I am unable to connect to the client. I tried with longer timeouts (50Sec). Out of 15 tries, I am able to connect only once. Thus I think the connection is unstable. Are you suggesting to run Bleakscanner in parallel while connecting with the device? Atleast the example code does not say so. Thanks, Rohan

[dlech]

It doesn't look like anyone has done any Bluetooth packet logging on this yet. Usually that offers insight into what is going on under the hood. https://bleak.readthedocs.io/en/latest/troubleshooting.html#windows-10

You could also try #680 to see if it makes a difference.

[jppdpf]

Hi, I stopped seeing this error for a long time but now it surfaced again.
I captured some packets.
Hope it makes sense.
timeout-connecting.zip

[dlech]

In the capture, it looks like Windows never attempts to connect to the device. There are only scanning packets. Does it fix the problem if you reboot your computer?

[jppdpf]

I rebooted both devices, the problem persists.
Currently I'm working with Bleak 0.13.0 and Bleak-winrt 1.0.1.

[dlech]

have you tried bleak 0.14.2?

[jppdpf]

Not yet no. I will update both versions.

[jppdpf]

I rebooted after the update and it started working again.
I appreciate all your work and effort @dlech much thanks!

[anthonymesa]

Hello all! I am dealing with this issue myself and I was hoping there may be more insight on this issue a year later. I am using a Windows 10 laptop, with Python 3.9, Bleak 0.14.2 and Bleak Win-rt 1.1.1. Whenever I try to run this basic code below, I also receive this same error:

import asyncio
from bleak import BleakClient
from bleak import BleakScanner

async def scan():
    dev = await BleakScanner.discover()
    for i in range(0,len(dev)):
        if(dev[i].name == "Anthony's Galaxy S9+"):
          print("found it!")
          async with BleakClient(dev[i].address) as client:
            print("connected!")

asyncio.run(scan())

and here is the error'ed output that I recieve:

found it!
Traceback (most recent call last):
  File "C:\Program Files\Python39\lib\asyncio\locks.py", line 226, in wait
    await fut
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
    fut.result()
asyncio.exceptions.CancelledError

The above exception was the direct cause of the following exception:
Traceback (most recent call last):
  File "D:\amesa\work-not\CSC495FinalProject\4 - BLE Server\jaegerml_hq.py", line 102, in <module>
    asyncio.run(scan())
  File "C:\Program Files\Python39\lib\asyncio\runners.py", line 44, in run
    return loop.run_until_complete(main)
  File "C:\Program Files\Python39\lib\asyncio\base_events.py", line 642, in run_until_complete
    return future.result()
  File "D:\amesa\work-not\CSC495FinalProject\4 - BLE Server\jaegerml_hq.py", line 90, in scan
    async with BleakClient(dev[i].address) as client:
  File "C:\Users\AMesa\AppData\Roaming\Python\Python39\site-packages\bleak\backends\client.py", line 61, in __aenter__    
    await self.connect()
  File "C:\Users\AMesa\AppData\Roaming\Python\Python39\site-packages\bleak\backends\winrt\client.py", line 267, in connect
    await asyncio.wait_for(event.wait(), timeout=timeout)
  File "C:\Program Files\Python39\lib\asyncio\tasks.py", line 489, in wait_for
    raise exceptions.TimeoutError() from exc
asyncio.exceptions.TimeoutError

I tried what was suggested by Linweifu, but I do not have a dotnet folder in my backends folder, just:

• bluezdbus
• corebluetooth
• p4android
• winrt

If any more info is required, please let me know, as I am certainly glad to help!

[zenbooster]

python 3.9.7; Bleak 0.14.3; Windows 10: same error!

import asyncio
import sys

from bleak import BleakClient, BleakScanner

async def main(wanted_name):
    device = await BleakScanner.find_device_by_filter(
        lambda d, ad: d.name and d.name.lower() == wanted_name.lower()
    )
    print(device)
    
    async with BleakClient(device) as client:
        svcs = await client.get_services()
        svcs = client.get_services()
        print("Services:")
        for service in svcs:
            print(service)

if __name__ == "__main__":
    asyncio.run(main('abd8302448845239'))

(base) D:\work\btdimmer>python btdimmer.py
08:65:F0:04:04:E1: abd8302448845239
Traceback (most recent call last):
  File "C:\Users\zenbooster\Anaconda3\lib\asyncio\locks.py", line 226, in wait
    await fut
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "C:\Users\zenbooster\Anaconda3\lib\asyncio\tasks.py", line 492, in wait_for
    fut.result()
asyncio.exceptions.CancelledError

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "D:\work\btdimmer\btdimmer.py", line 20, in <module>
    asyncio.run(main('abd8302448845239'))
  File "C:\Users\zenbooster\Anaconda3\lib\asyncio\runners.py", line 44, in run
    return loop.run_until_complete(main)
  File "C:\Users\zenbooster\Anaconda3\lib\asyncio\base_events.py", line 642, in run_until_complete
    return future.result()
  File "D:\work\btdimmer\btdimmer.py", line 12, in main
    async with BleakClient(device) as client:
  File "C:\Users\zenbooster\Anaconda3\lib\site-packages\bleak\backends\client.py", line 61, in __aenter__
    await self.connect()
  File "C:\Users\zenbooster\Anaconda3\lib\site-packages\bleak\backends\winrt\client.py", line 268, in connect
    await asyncio.wait_for(event.wait(), timeout=timeout)
  File "C:\Users\zenbooster\Anaconda3\lib\asyncio\tasks.py", line 494, in wait_for
    raise exceptions.TimeoutError() from exc
asyncio.exceptions.TimeoutError

(base) D:\work\btdimmer>

[dlech]

Has anyone tried making the timeout longer?

Has anyone tried logging Bluetooth packets?

[anthonymesa]

I will capture packets on my end and upload that, and hopefully that provides some insight. I have tried making the timeouts longer but it unfortunately didn't change the erroneous behavior.

[dlech]

Can you attach the log so we can see the actual data?

[dlech]

From the log above, we can see that Windows is telling the Bluetooth chip to scan with a filter policy set to 0x01 as expected for connecting.

However, there is not command to set the filter list.

Here is an example of such a command that I captured on my Mac.

So, my guess is that there is a problem with the Bluetooth driver on Windows. I would check for driver updates or try a different Bluetooth adapter that uses a different chipset.

[malikmus]

It actually works on linux for me so I guess there's a windows problem here. Tried with updating my bluetooth driver but I still get the timeout error /:

[celiafb]

I'm having the same TimeOut issue. My script works perfectly fine on the Windows desktop I set up a few months ago, but today I tried running it on a new Surface Go device with 3.11.0 Python, and it's not working. Scanner example script works fine, but can't connect to my device.

Traceback (most recent call last):
File "C:\Users\Celia\Scripts\csblesimp-1drv.py", line 97, in
loop.run_until_complete(main())
File "C:\Users\Celia\AppData\Local\Programs\Python\Python311\Lib\asyncio\base_events.py", line 650, in run_until_complete
return future.result()
File "C:\Users\Celia\Scripts\csblesimp-1drv.py", line 81, in main
await data_client(device)
File "C:\Users\Celia\Scripts\csblesimp-1drv.py", line 29, in data_client
async with BleakClient(device) as client:
File "C:\Users\Celia\AppData\Local\Programs\Python\Python311\Lib\site-packages\bleak_init_.py", line 436, in aenter
await self.connect()
File "C:\Users\Celia\AppData\Local\Programs\Python\Python311\Lib\site-packages\bleak_init_.py", line 474, in connect
return await self._backend.connect(**kwargs)
File "C:\Users\Celia\AppData\Local\Programs\Python\Python311\Lib\site-packages\bleak\backends\winrt\client.py", line 382, in connect
async with async_timeout(timeout):
File "C:\Users\Celia\AppData\Local\Programs\Python\Python311\Lib\asyncio\timeouts.py", line 98, in aexit
raise TimeoutError
TimeoutError

[dlech]

This issue has been closed. Please start a new issue and include all requested info like Bleak Version, OS version, Bleak debug logs, Wireshark logs, Bluetooth adapter chipset and driver info.