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

Timeout Error #1359

Closed
wangtao2213405054 opened this issue Jul 4, 2023 · 13 comments · Fixed by #1406
Closed

Timeout Error #1359

wangtao2213405054 opened this issue Jul 4, 2023 · 13 comments · Fixed by #1406
Labels
3rd party issue The issue is with the Bluetooth stack, the BLE device, or other 3rd party code not with Bleak itself Backend: WinRT Issues or PRs relating to the WinRT backend

Comments

@wangtao2213405054
Copy link

wangtao2213405054 commented Jul 4, 2023

  • bleak version: 0.20.0
  • Python version: 3.11.4
  • Operating System: Windows 10 22H2 19045.3086
  • BlueZ version (bluetoothctl -v) in case of Linux:

Description

Please understand that I am writing using a translation tool.

I represented the searched Bluetooth device in a list box and tried to connect to the device by selecting it. However, processes stuck in bleak= > 0.20.0, and timeout in bleak==0.19.5

What I Did

This code is a part of the whole code.

async def test():
    async with BleakClient('EB:5E:24:41:79:57') as client:
        pass

asyncio.run(test())

Logs

2023-07-04 14:46:04,328 scanner.py[line:104] DEBUG Received 34:9A:A8:91:49:DE: .
2023-07-04 14:46:04,330 scanner.py[line:104] DEBUG Received CC:DB:5C:8E:24:5B: 73429496.
2023-07-04 14:46:04,335 scanner.py[line:104] DEBUG Received 72:84:65:01:2E:B8: .
2023-07-04 14:46:04,341 scanner.py[line:104] DEBUG Received 00:0A:45:19:71:80: LE_ATH-M50xBT2.
2023-07-04 14:46:04,342 scanner.py[line:104] DEBUG Received 00:0A:45:19:71:80: .
2023-07-04 14:46:04,345 scanner.py[line:104] DEBUG Received 00:0A:45:19:71:80: LE_ATH-M50xBT2.
2023-07-04 14:46:04,347 scanner.py[line:104] DEBUG Received 00:0A:45:19:71:80: .
2023-07-04 14:46:04,350 scanner.py[line:104] DEBUG Received 4A:45:49:26:63:02: .
2023-07-04 14:46:04,352 scanner.py[line:104] DEBUG Received D2:DE:11:CD:48:DB: .
2023-07-04 14:46:04,354 scanner.py[line:104] DEBUG Received 2A:77:25:E3:48:3E: .
2023-07-04 14:46:04,356 scanner.py[line:104] DEBUG Received D0:4E:00:4D:91:BA: 73429419.
2023-07-04 14:46:04,440 scanner.py[line:104] DEBUG Received FC:A8:9B:08:CE:BB: .
2023-07-04 14:46:04,443 scanner.py[line:104] DEBUG Received 7B:45:79:DB:1B:8B: .
2023-07-04 14:46:04,445 scanner.py[line:104] DEBUG Received 7B:45:79:DB:1B:8B: .
2023-07-04 14:46:04,447 scanner.py[line:104] DEBUG Received 7B:0D:3B:F5:BD:12: .
2023-07-04 14:46:04,447 scanner.py[line:104] DEBUG Received 7B:0D:3B:F5:BD:12: .
2023-07-04 14:46:04,449 scanner.py[line:104] DEBUG Received 2C:9F:EC:17:FB:86: .
2023-07-04 14:46:04,453 scanner.py[line:104] DEBUG Received 1E:49:0A:1A:99:AC: .
2023-07-04 14:46:04,457 scanner.py[line:104] DEBUG Received 2B:27:96:75:B9:BC: .
2023-07-04 14:46:04,464 scanner.py[line:104] DEBUG Received 02:3C:C5:B4:DE:DD: .
2023-07-04 14:46:04,466 scanner.py[line:104] DEBUG Received 0B:72:9D:8D:F8:F7: .
2023-07-04 14:46:04,469 scanner.py[line:104] DEBUG Received 01:3C:1F:82:0C:A8: .
2023-07-04 14:46:04,562 scanner.py[line:104] DEBUG Received 0E:E5:48:DF:4C:0E: .
2023-07-04 14:46:04,570 scanner.py[line:104] DEBUG Received CA:2D:12:27:75:7E: .
2023-07-04 14:46:04,576 scanner.py[line:104] DEBUG Received 0B:72:9D:8D:F8:F7: .
2023-07-04 14:46:04,678 scanner.py[line:104] DEBUG Received 0B:72:9D:8D:F8:F7: .
2023-07-04 14:46:04,681 scanner.py[line:104] DEBUG Received 58:85:32:F7:EB:B0: .
2023-07-04 14:46:04,683 scanner.py[line:104] DEBUG Received 58:85:32:F7:EB:B0: .
2023-07-04 14:46:04,684 scanner.py[line:104] DEBUG Received 55:D2:27:3E:64:62: .
2023-07-04 14:46:04,690 scanner.py[line:104] DEBUG Received 2C:17:03:17:61:60: .
2023-07-04 14:46:04,692 scanner.py[line:104] DEBUG Received 52:19:1A:D1:4C:F9: .
2023-07-04 14:46:04,693 scanner.py[line:104] DEBUG Received 52:19:1A:D1:4C:F9: .
2023-07-04 14:46:04,695 scanner.py[line:104] DEBUG Received 00:0A:45:19:71:80: LE_ATH-M50xBT2.
2023-07-04 14:46:04,696 scanner.py[line:104] DEBUG Received 00:0A:45:19:71:80: .
2023-07-04 14:46:04,701 scanner.py[line:104] DEBUG Received 68:05:48:53:B2:37: .
2023-07-04 14:46:04,702 scanner.py[line:104] DEBUG Received 68:05:48:53:B2:37: .
2023-07-04 14:46:04,708 scanner.py[line:104] DEBUG Received 2E:32:42:97:AD:CE: .
2023-07-04 14:46:04,796 scanner.py[line:104] DEBUG Received 0C:40:3E:73:10:98: .
2023-07-04 14:46:04,800 scanner.py[line:104] DEBUG Received 3D:89:17:14:52:3A: .
2023-07-04 14:46:04,808 scanner.py[line:104] DEBUG Received 66:BC:4E:CE:F0:7D: .
2023-07-04 14:46:04,810 scanner.py[line:104] DEBUG Received 66:BC:4E:CE:F0:7D: .
2023-07-04 14:46:04,812 scanner.py[line:104] DEBUG Received 01:A0:D9:F3:C6:BF: .
2023-07-04 14:46:04,819 scanner.py[line:104] DEBUG Received 1E:49:0A:1A:99:AC: .
2023-07-04 14:46:04,915 scanner.py[line:104] DEBUG Received 47:D2:00:4B:9E:A0: .
2023-07-04 14:46:04,917 scanner.py[line:104] DEBUG Received 10:C2:A0:AD:59:B4: .
2023-07-04 14:46:04,919 scanner.py[line:104] DEBUG Received E1:BF:35:8C:FD:DD: .
2023-07-04 14:46:04,922 scanner.py[line:104] DEBUG Received 2A:77:25:E3:48:3E: .
2023-07-04 14:46:04,925 scanner.py[line:104] DEBUG Received 72:1D:93:61:2C:BA: .
2023-07-04 14:46:04,926 scanner.py[line:104] DEBUG Received 22:27:D7:8B:7F:6F: .
2023-07-04 14:46:04,932 scanner.py[line:104] DEBUG Received 64:68:84:D9:49:6C: .
2023-07-04 14:46:04,933 scanner.py[line:104] DEBUG Received 64:68:84:D9:49:6C: .
2023-07-04 14:46:04,936 scanner.py[line:104] DEBUG Received 47:E2:34:DE:59:0C: .
2023-07-04 14:46:04,937 scanner.py[line:104] DEBUG Received 47:E2:34:DE:59:0C: .
2023-07-04 14:46:05,031 scanner.py[line:104] DEBUG Received 22:27:D7:8B:7F:6F: .
2023-07-04 14:46:05,035 scanner.py[line:104] DEBUG Received 7C:61:B8:2D:19:51: .
2023-07-04 14:46:05,037 scanner.py[line:104] DEBUG Received 7C:61:B8:2D:19:51: .
2023-07-04 14:46:05,043 scanner.py[line:104] DEBUG Received 00:0A:45:19:71:80: LE_ATH-M50xBT2.
2023-07-04 14:46:05,043 scanner.py[line:104] DEBUG Received 00:0A:45:19:71:80: .
2023-07-04 14:46:05,045 scanner.py[line:104] DEBUG Received 6D:0C:16:DA:3D:0A: .
2023-07-04 14:46:05,047 scanner.py[line:104] DEBUG Received 6D:0C:16:DA:3D:0A: .
2023-07-04 14:46:05,051 scanner.py[line:104] DEBUG Received FE:8B:54:D5:59:18: 73429418.
2023-07-04 14:46:05,053 scanner.py[line:104] DEBUG Received FE:8B:54:D5:59:18: .
2023-07-04 14:46:05,056 scanner.py[line:104] DEBUG Received EB:5E:24:41:79:57: 73429481.
2023-07-04 14:46:05,058 scanner.py[line:104] DEBUG Received EB:5E:24:41:79:57: .
2023-07-04 14:46:05,060 scanner.py[line:211] DEBUG 40 devices found. Watcher status: 3.
2023-07-04 14:46:05,061 client.py[line:253] DEBUG Connecting to BLE device @ EB:5E:24:41:79:57
2023-07-04 14:46:05,097 client.py[line:627] DEBUG getting services (service_cache_mode=None, cache_mode=None)...
2023-07-04 14:46:05,097 client.py[line:651] DEBUG calling get_gatt_services_async
2023-07-04 14:46:05,268 client.py[line:327] DEBUG session_status_changed_event_handler: id: <_bleak_winrt_Windows_Devices_Bluetooth.BluetoothDeviceId object at 0x03D21DD0>, error: 0, status: 1
2023-07-04 14:46:05,292 client.py[line:344] DEBUG max_pdu_size_changed_handler: 247
2023-07-04 14:46:05,626 client.py[line:687] DEBUG returned from get_gatt_services_async
2023-07-04 14:46:05,626 client.py[line:699] DEBUG calling get_characteristics_async
2023-07-04 14:46:05,652 client.py[line:267] DEBUG EB:5E:24:41:79:57: services changed
2023-07-04 14:46:05,688 client.py[line:267] DEBUG EB:5E:24:41:79:57: services changed
2023-07-04 14:46:05,701 client.py[line:707] DEBUG returned from get_characteristics_async
2023-07-04 14:46:05,701 client.py[line:716] DEBUG calling get_descriptors_async
2023-07-04 14:46:05,704 client.py[line:724] DEBUG returned from get_descriptors_async
2023-07-04 14:46:05,704 client.py[line:716] DEBUG calling get_descriptors_async
2023-07-04 14:46:05,706 client.py[line:724] DEBUG returned from get_descriptors_async
2023-07-04 14:46:05,707 client.py[line:716] DEBUG calling get_descriptors_async
2023-07-04 14:46:05,709 client.py[line:724] DEBUG returned from get_descriptors_async
2023-07-04 14:46:05,709 client.py[line:699] DEBUG calling get_characteristics_async
2023-07-04 14:46:05,722 client.py[line:267] DEBUG EB:5E:24:41:79:57: services changed
2023-07-04 14:46:05,749 client.py[line:267] DEBUG EB:5E:24:41:79:57: services changed
2023-07-04 14:46:05,755 client.py[line:707] DEBUG returned from get_characteristics_async
2023-07-04 14:46:05,755 client.py[line:716] DEBUG calling get_descriptors_async
2023-07-04 14:46:05,757 client.py[line:724] DEBUG returned from get_descriptors_async
2023-07-04 14:46:05,758 client.py[line:699] DEBUG calling get_characteristics_async
2023-07-04 14:46:15,392 client.py[line:327] DEBUG session_status_changed_event_handler: id: <_bleak_wi
nrt_Windows_Devices_Bluetooth.BluetoothDeviceId object at 0x03D21950>, error: 0, status: 0
2023-07-04 14:46:15,393 client.py[line:344] DEBUG max_pdu_size_changed_handler: 23
2023-07-04 14:46:15,393 client.py[line:739] DEBUG disposing service objects

Wireshark Logs
log.zip

@dlech
Copy link
Collaborator

dlech commented Jul 4, 2023

Is this still a problem using the develop branch?

@wangtao2213405054
Copy link
Author

Sorry, I haven't tried it in the develop branch yet. I'll try it tomorrow

@wangtao2213405054
Copy link
Author

wangtao2213405054 commented Jul 5, 2023

Yes, this problem still occurs with the develop branch 0.21.0a1

Logs

2023-07-05 09:30:15,464 scanner.py[line:104] DEBUG Received 19:2A:67:F8:59:50: .
2023-07-05 09:30:15,466 scanner.py[line:104] DEBUG Received DB:0E:5B:57:7B:03: .
2023-07-05 09:30:15,473 scanner.py[line:104] DEBUG Received CC:B9:63:21:EB:3E: 73429475.
2023-07-05 09:30:15,483 scanner.py[line:104] DEBUG Received 05:6E:A0:AB:9E:83: .
2023-07-05 09:30:15,595 scanner.py[line:104] DEBUG Received 2D:39:93:FE:9C:F8: .
2023-07-05 09:30:15,695 scanner.py[line:104] DEBUG Received 39:5B:FA:E3:CF:BB: .
2023-07-05 09:30:15,697 scanner.py[line:104] DEBUG Received EB:5E:24:41:79:57: 73429481.
2023-07-05 09:30:15,699 scanner.py[line:211] DEBUG 7 devices found. Watcher status: 3.
2023-07-05 09:30:15,699 client.py[line:248] DEBUG Connecting to BLE device @ EB:5E:24:41:79:57
2023-07-05 09:30:15,742 client.py[line:626] DEBUG getting services (service_cache_mode=None, cache_mode=None)...
2023-07-05 09:30:15,920 client.py[line:326] DEBUG session_status_changed_event_handler: id: BluetoothLE#BluetoothLE70:cd:0d:32:eb:31-eb:5e:24:41:79:57, error: 0, status: 1
2023-07-05 09:30:15,939 client.py[line:343] DEBUG max_pdu_size_changed_handler: 247
2023-07-05 09:30:16,328 client.py[line:262] DEBUG EB:5E:24:41:79:57: services changed
2023-07-05 09:30:16,354 client.py[line:262] DEBUG EB:5E:24:41:79:57: services changed
2023-07-05 09:30:16,381 client.py[line:262] DEBUG EB:5E:24:41:79:57: services changed
2023-07-05 09:30:16,408 client.py[line:262] DEBUG EB:5E:24:41:79:57: services changed
2023-07-05 09:30:26,039 client.py[line:731] DEBUG disposing service objects
2023-07-05 09:30:26,039 client.py[line:343] DEBUG max_pdu_size_changed_handler: 23

Wireshark Logs
log.zip

@dlech
Copy link
Collaborator

dlech commented Jul 5, 2023

I don't see any problem here. Since there is nothing in the program to keep the device connected, it connects and disconnects as expected. If you replace pass with await asyncio.Event().wait(), then it should stay connected forever.

@wangtao2213405054
Copy link
Author

I'm sorry that the above code caused you misunderstanding. After my debugging, the program did not run to the pass code line but directly stuck.

Here's my new example, which works fine on Linux:

async def receive_bluetooth_data(address):
    async with bleak.BleakClient(address, timeout=20) as client:
        await client.write_gatt_char(
            '6e400002-b5a3-f393-e0a9-e50e24dcca9e',
            bytearray([0x7E, 0x01, 0x00, 0x04, 0x00, 0x00, 0x00, 0x00, 0x04, 0x00, 0x00, 0x00, 0x05, 0x01, 0x20, 0x00, 0x00, 0x25, 0x7E])
        )

        await client.start_notify('6e400003-b5a3-f393-e0a9-e50e24dcca9e', callback)

        # 保持异步循环运行
        while True:
            await asyncio.sleep(1)


async def callback(sender: int, data: bytearray):
    # 处理接收到的数据
    print("Received data:", list(data))

loop = asyncio.get_event_loop()
device_address = "EB:5E:24:41:79:57"
loop.run_until_complete(receive_bluetooth_data(device_address))

@dlech
Copy link
Collaborator

dlech commented Jul 6, 2023

Where does the new program get stuck? Do you have logs for it?

@wangtao2213405054
Copy link
Author

It's still stuck in the same place, and it doesn't raise a Timeout Error.

Logs

2023-07-06 09:25:59,170 scanner.py[line:104] DEBUG Received 01:51:01:7D:EF:97: .
2023-07-06 09:25:59,172 scanner.py[line:104] DEBUG Received 67:CC:BB:1A:71:C1: .
2023-07-06 09:25:59,215 scanner.py[line:104] DEBUG Received 32:19:7D:FA:6A:D2: .
2023-07-06 09:25:59,226 scanner.py[line:104] DEBUG Received DD:52:0F:61:20:4E: 73429467.
2023-07-06 09:25:59,227 scanner.py[line:104] DEBUG Received DD:52:0F:61:20:4E: .
2023-07-06 09:25:59,297 scanner.py[line:104] DEBUG Received 00:0A:45:19:71:80: LE_ATH-M50xBT2.
2023-07-06 09:25:59,298 scanner.py[line:104] DEBUG Received 00:0A:45:19:71:80: .
2023-07-06 09:25:59,300 scanner.py[line:104] DEBUG Received E1:9F:65:95:81:AF: 73429541.
2023-07-06 09:25:59,303 scanner.py[line:104] DEBUG Received 6C:F5:76:1B:5C:4E: .
2023-07-06 09:25:59,303 scanner.py[line:104] DEBUG Received 6C:F5:76:1B:5C:4E: .
2023-07-06 09:25:59,305 scanner.py[line:104] DEBUG Received 55:92:02:AE:CC:7F: .
2023-07-06 09:25:59,402 scanner.py[line:104] DEBUG Received 66:35:20:FB:7A:40: .
2023-07-06 09:25:59,403 scanner.py[line:104] DEBUG Received 66:35:20:FB:7A:40: .
2023-07-06 09:25:59,405 scanner.py[line:104] DEBUG Received EB:5E:24:41:79:57: 73429481.
2023-07-06 09:25:59,407 scanner.py[line:104] DEBUG Received EB:5E:24:41:79:57: .
2023-07-06 09:25:59,409 scanner.py[line:211] DEBUG 10 devices found. Watcher status: 3.
2023-07-06 09:25:59,409 client.py[line:248] DEBUG Connecting to BLE device @ EB:5E:24:41:79:57
2023-07-06 09:25:59,430 client.py[line:626] DEBUG getting services (service_cache_mode=None, cache_mode=None)...
2023-07-06 09:26:00,268 client.py[line:326] DEBUG session_status_changed_event_handler: id: BluetoothLE#BluetoothLE70:cd:0d:32:eb:31-eb:5e:24:41:79:57, error: 0, status: 1
2023-07-06 09:26:00,292 client.py[line:343] DEBUG max_pdu_size_changed_handler: 247
2023-07-06 09:26:00,654 client.py[line:262] DEBUG EB:5E:24:41:79:57: services changed
2023-07-06 09:26:00,681 client.py[line:262] DEBUG EB:5E:24:41:79:57: services changed
2023-07-06 09:26:00,712 client.py[line:262] DEBUG EB:5E:24:41:79:57: services changed
2023-07-06 09:26:00,738 client.py[line:262] DEBUG EB:5E:24:41:79:57: services changed
2023-07-06 09:26:10,422 client.py[line:326] DEBUG session_status_changed_event_handler: id: BluetoothLE#BluetoothLE70:cd:0d:32:eb:31-eb:5e:24:41:79:57, error: 0, status: 0
2023-07-06 09:26:10,422 client.py[line:343] DEBUG max_pdu_size_changed_handler: 23
2023-07-06 09:26:10,423 client.py[line:731] DEBUG disposing service objects

@wangtao2213405054
Copy link
Author

If I comment out the exception caught by try BaseException at line 728 in /bleak/winrt/client.py/, it throws a Timeout Error.

The exceptions are as follows:

Traceback (most recent call last):
  File "C:\Users\User\AppData\Local\Programs\Python\Python311-32\Lib\site-packages\bleak\backends\winrt\client.py", line 435, in connect
    self.services = await self.get_services(
                    ^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\User\AppData\Local\Programs\Python\Python311-32\Lib\site-packages\bleak\backends\winrt\client.py", line 687, in get_services
    result = await FutureLike(service.get_characteristics_async(*args))
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\User\AppData\Local\Programs\Python\Python311-32\Lib\site-packages\bleak\backends\winrt\client.py", line 1089, in __await__
    yield self  # This tells Task to wait for completion.
    ^^^^^^^^^^
  File "C:\Users\User\AppData\Local\Programs\Python\Python311-32\Lib\site-packages\bleak\backends\winrt\client.py", line 1029, in result
    raise asyncio.CancelledError
asyncio.exceptions.CancelledError

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

Traceback (most recent call last):
  File "C:\Users\User\PycharmProjects\alone-ecu-test\test2.py", line 50, in <module>
    asyncio.run(test())
  File "C:\Users\User\AppData\Local\Programs\Python\Python311-32\Lib\asyncio\runners.py", line 190, in run
    return runner.run(main)
           ^^^^^^^^^^^^^^^^
  File "C:\Users\User\AppData\Local\Programs\Python\Python311-32\Lib\asyncio\runners.py", line 118, in run
    return self._loop.run_until_complete(task)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\User\AppData\Local\Programs\Python\Python311-32\Lib\asyncio\base_events.py", line 653, in run_until_complete
    return future.result()
           ^^^^^^^^^^^^^^^
  File "C:\Users\User\PycharmProjects\alone-ecu-test\test2.py", line 46, in test
    async with BleakClient('EB:5E:24:41:79:57') as client:
  File "C:\Users\User\AppData\Local\Programs\Python\Python311-32\Lib\site-packages\bleak\__init__.py", line 491, in __aenter__
    await self.connect()
  File "C:\Users\User\AppData\Local\Programs\Python\Python311-32\Lib\site-packages\bleak\__init__.py", line 531, in connect
    return await self._backend.connect(**kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\User\AppData\Local\Programs\Python\Python311-32\Lib\site-packages\bleak\backends\winrt\client.py", line 391, in connect
    async with async_timeout(timeout):
  File "C:\Users\User\AppData\Local\Programs\Python\Python311-32\Lib\asyncio\timeouts.py", line 111, in __aexit__
    raise TimeoutError from exc_val
TimeoutError

@dlech
Copy link
Collaborator

dlech commented Jul 6, 2023

If I comment out the exception caught by try BaseException at line 728 in /bleak/winrt/client.py/

That is really strange. If you hit ctrl+c when it is stuck on

2023-07-06 09:26:10,423 client.py[line:731] DEBUG disposing service objects

What is the stack trace? It seems like the .close() method from the Windows API could be hanging forever, which would be a Microsoft problem.

Is the issue reproducible on a different computer?

@wangtao2213405054
Copy link
Author

Yes, I tried another Windows device and it had the same problem

I am running the code in debug mode. The .close() method is normal and does not timeout. This is very confusing

@dlech
Copy link
Collaborator

dlech commented Jul 6, 2023

Do both computers have the same Bluetooth chip and driver version and Windows version?

What happens if you make the timeout longer?

@dlech
Copy link
Collaborator

dlech commented Jul 6, 2023

The wireshark logs show that the device is never responding to a read request of Peripheral Preferred Connection Parameters attribute. So that would explain why Windows might be locking up waiting for the device to respond.

If you have control over the firmware on the device, you could try fixing this attribute.

@dlech dlech added Backend: WinRT Issues or PRs relating to the WinRT backend 3rd party issue The issue is with the Bluetooth stack, the BLE device, or other 3rd party code not with Bleak itself labels Jul 18, 2023
@koji-karube
Copy link

I was having the same problem. And finally found a solution.

When I first encountered this problem, I thought it would be easier to solve it if I stopped using python and redeveloped with UWP's C# API. However, I found a similar stuck problem occurs in UWP, too.

Debugging firmware of Windows 10 device driver is a very daunting task. So I returned from the UWP C# environment to the python interpreter environment, typed "py -m pdb my_script.py" and tried a step run. However, the step execution does not cause the stuck phenomenon. I wondered if some subtle timing was affecting it.

I came across this page through an Internet search and saw "max_pdu_size_changed_handler: 23" at the end of the log data, which I thought looked familiar. My log was also stuck near the same event. I traced that the event occurs when power is turned down by power saving feature of BLE device and communication is interrupted from BLE device. So I set up an experimental environment in which the BLE device would power down for a short period of time.

The debugging target is the client.py file of the BLEAK library. The location of the file differs depending on the installation environment, but at my place it was installed here.

~/AppData/Local/Programs/Python/Python311/Lib/site-packages/bleak/backends/winrt/client.py

And after trying the phenomenon several times, and after some broken communication, I found that the place where the service component is disposed of gets stuck. And it doesn't get stuck on step execution. So I added a wait time just before disposing, and it no longer occur the problem. In my case, the wait time was about 60 msec, so I added a 100 msec wait time to give it a little extra time.

Around line 476 (depending on version)

         await asyncio.sleep(0.1)
         if self.services:
             for service in self.services:
                 service.obj.close()

Around line 745 (depending on version)

            await asyncio.sleep(0.1)
             for service in services:
                 service.close()

In conclusion, this debugging showed that a hold time (or keep-alive time) of more than 60 msec is required from unsolicited disconnection event to GattDeviceService.close(). I was able to avoid the stuck problem by modifying the python BLEAK client source code, but this seems to be a usage issue of Windows' GATT (GattDeviceService class) and not the device driver's issue nor the device firmware's issue.

dlech added a commit that referenced this issue Sep 1, 2023
It appears that GattDeviceService.Close() can hang forever under
certain circumstances.  This change adds a 0.1 second delay before
closing services to see if that helps.

Fixes: #1359
dlech added a commit that referenced this issue Sep 1, 2023
It appears that GattDeviceService.Close() can hang forever under
certain circumstances.  This change adds a 0.1 second delay before
closing services to see if that helps.

Fixes: #1359
@dlech dlech mentioned this issue Sep 2, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
3rd party issue The issue is with the Bluetooth stack, the BLE device, or other 3rd party code not with Bleak itself Backend: WinRT Issues or PRs relating to the WinRT backend
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants