search

hbldh / bleak

A cross platform Bluetooth Low Energy Client for Python using asyncio
MIT License
1.6k stars 280 forks source link

Spontaneous disconnection after a few seconds #1198

Open integerfn opened 1 year ago

integerfn commented 1 year ago

Description

I'm trying to connect to a BLE peripheral implemented on an nRF device. I'm able to connect, but then the connection drops after about 4 seconds, every single time.

The nRF peripheral supports BLE 5, 2M PHY and is configured without security, i.e. characteristics are open, no pairing or bonding is required or supported.

What I Did

I started running old communication scripts that used to run on bleak 0.12, and at first it seemed to work, but only when the whole thing lasted less than a few seconds. Longer scripts started failing because of the disconnection.

After that, I tried running the example scripts from the repo and got the same problem in all of them. For example, the enable_notifications.py script is very similar to what our communication scripts do, so I ran that one, and it crashes because it loses connection before getting to the stop_notify call.

Connecting from nRF Connect on my phone works without issue.

As an added note here, which may or may not be relevant, Bleak 0.12 used to work fine with our device while it supported pairing. When I removed the security, it stopped working (it never connects). So I started moving to newer versions, but none of them seemed to work, until 0.19.5. This one does connect, but has this spontaneous disconnection issue.

Logs

Here's the output of running the enable_notifications.py script, with the custom MAC address and characteristic UUID.

2023-01-11 12:22:42,055 bleak.backends.winrt.scanner DEBUG: Received 78:EE:F5:EB:5E:59: .
2023-01-11 12:22:42,752 bleak.backends.winrt.scanner DEBUG: Received D9:1E:8E:E3:E1:D8: .
2023-01-11 12:22:42,752 bleak.backends.winrt.scanner DEBUG: skipping callback, waiting for scan response
2023-01-11 12:22:42,754 bleak.backends.winrt.scanner DEBUG: Received D9:1E:8E:E3:E1:D8: .
2023-01-11 12:22:42,756 bleak.backends.winrt.scanner DEBUG: 2 devices found. Watcher status: 3.
2023-01-11 12:22:42,756 bleak.backends.winrt.client DEBUG: Connecting to BLE device @ d9:1e:8e:e3:e1:d8
2023-01-11 12:22:42,852 bleak.backends.winrt.client DEBUG: getting services (service_cache_mode=None, cache_mode=None)...
2023-01-11 12:22:43,367 bleak.backends.winrt.client DEBUG: session_status_changed_event_handler: id: <_bleak_winrt_Windows_Devices_Bluetooth.BluetoothDeviceId object at 0x000001B48FEE5BD0>, error: BluetoothError.SUCCESS, status: GattSessionStatus.ACTIVE
2023-01-11 12:22:43,376 bleak.backends.winrt.client DEBUG: max_pdu_size_changed_handler: 247
2023-01-11 12:22:43,698 bleak.backends.winrt.client DEBUG: d9:1e:8e:e3:e1:d8: services changed
2023-01-11 12:22:43,698 bleak.backends.winrt.client DEBUG: d9:1e:8e:e3:e1:d8: restarting get services due to services changed event
2023-01-11 12:22:43,734 bleak.backends.winrt.client DEBUG: d9:1e:8e:e3:e1:d8: services changed
2023-01-11 12:22:43,748 bleak.backends.winrt.client DEBUG: getting services (service_cache_mode=<BluetoothCacheMode.CACHED: 0>, cache_mode=None)...
2023-01-11 12:22:43,749 bleak.backends.winrt.client DEBUG: d9:1e:8e:e3:e1:d8: restarting get services due to services changed event
2023-01-11 12:22:43,771 bleak.backends.winrt.client DEBUG: d9:1e:8e:e3:e1:d8: services changed
2023-01-11 12:22:43,813 bleak.backends.winrt.client DEBUG: getting services (service_cache_mode=<BluetoothCacheMode.CACHED: 0>, cache_mode=None)...
2023-01-11 12:22:43,814 bleak.backends.winrt.client DEBUG: d9:1e:8e:e3:e1:d8: restarting get services due to services changed event
2023-01-11 12:22:43,849 bleak.backends.winrt.client DEBUG: d9:1e:8e:e3:e1:d8: services changed
2023-01-11 12:22:43,890 bleak.backends.winrt.client DEBUG: getting services (service_cache_mode=<BluetoothCacheMode.CACHED: 0>, cache_mode=None)...
2023-01-11 12:22:43,891 bleak.backends.winrt.client DEBUG: d9:1e:8e:e3:e1:d8: restarting get services due to services changed event
2023-01-11 12:22:43,939 bleak.backends.winrt.client DEBUG: getting services (service_cache_mode=<BluetoothCacheMode.CACHED: 0>, cache_mode=None)...
Connected: True
2023-01-11 12:22:47,387 bleak.backends.winrt.client DEBUG: max_pdu_size_changed_handler: 23
2023-01-11 12:22:47,387 bleak.backends.winrt.client DEBUG: session_status_changed_event_handler: id: <_bleak_winrt_Windows_Devices_Bluetooth.BluetoothDeviceId object at 0x000001B48FEE5F90>, error: BluetoothError.SUCCESS, status: GattSessionStatus.CLOSED
2023-01-11 12:22:47,388 bleak.backends.winrt.client DEBUG: closing requester
2023-01-11 12:22:47,393 bleak.backends.winrt.client DEBUG: closing session
Traceback (most recent call last):
  File "C:/Users/redacted/dev/stm32/scripts/test.py", line 44, in <module>
    asyncio.run(
  File "C:\Users\redacted\AppData\Local\Programs\Python\Python38\lib\asyncio\runners.py", line 44, in run
    return loop.run_until_complete(main)
  File "C:\Users\redacted\AppData\Local\Programs\Python\Python38\lib\asyncio\base_events.py", line 616, in run_until_complete
    return future.result()
  File "C:/Users/redacted/dev/stm32/scripts/test.py", line 40, in main
    await client.stop_notify(char_uuid)
  File "C:\Users\redacted\dev\stm32\scripts\venv\lib\site-packages\bleak\__init__.py", line 667, in stop_notify
    await self._backend.stop_notify(char_specifier)
  File "C:\Users\redacted\dev\stm32\scripts\venv\lib\site-packages\bleak\backends\winrt\client.py", line 919, in stop_notify
    raise BleakError("Not connected")
bleak.exc.BleakError: Not connected
2023-01-11 12:22:49,303 bleak.backends.winrt.client DEBUG: Disconnecting from BLE device...

Process finished with exit code 1

Here's the output of the nRF firmware. The disconnection reason, 0x13, only means that the PC ended the connection, but it adds no further information.

00> [00:00:18.576,416] <info> app: Restarted advertising.
00> 
00> [00:02:14.182,067] <debug> nrf_ble_gatt: Requesting to update ATT MTU to 247 bytes on connection 0x1.
00> 
00> [00:02:14.182,312] <debug> nrf_ble_gatt: Updating data length to 251 on connection 0x1.
00> 
00> [00:02:14.182,556] <info> app: Restarted advertising.
00> 
00> [00:02:14.182,800] <info> app: Connected. Conn_handle=1
00> 
00> [00:02:14.182,983] <info> app: Connection parameters. Conn interval min: 12x1.25ms, max: 12x1.25ms, slave latency: 5, sup tout: 400x10ms
00> 
00> [00:02:14.211,120] <debug> nrf_ble_gatt: Peer on connection 0x1 requested an ATT MTU of 527 bytes.
00> 
00> [00:02:14.211,425] <debug> nrf_ble_gatt: Updating ATT MTU to 247 bytes (desired: 247) on connection 0x1.
00> 
00> [00:02:14.226,074] <debug> nrf_ble_gatt: ATT MTU updated to 247 bytes on connection 0x1 (response).
00> 
00> [00:02:14.226,379] <info> app: ATT MTU exchange completed on connection 1. MTU set to 247 bytes.
00> 
00> [00:02:14.271,484] <debug> nrf_ble_gatt: Data length updated to 251 on connection 0x1.
00> 
00> [00:02:14.271,667] <debug> nrf_ble_gatt: max_rx_octets: 251
00> 
00> [00:02:14.271,789] <debug> nrf_ble_gatt: max_tx_octets: 251
00> 
00> [00:02:14.271,911] <debug> nrf_ble_gatt: max_rx_time: 2120
00> 
00> [00:02:14.272,033] <debug> nrf_ble_gatt: max_tx_time: 2120
00> 
00> [00:02:14.272,155] <info> app: Data length updated to 251 bytes.
00> 
00> [00:02:14.569,335] <info> app: PHY update. Status: 0. TX: 2. RX 2.
00> 
00> [00:02:18.201,660] <info> app: BLE_GAP_EVT_DISCONNECTED: conn_handle=1, reason=13
00> 
00> [00:02:18.201,904] <info> app: Restarted advertising.

Thank your for your time!

dlech commented 1 year ago

Can you please try the branch from #1143?

integerfn commented 1 year ago

I tried that and got the same result.

I downlaoded the code from that branch from here, pasted the folder on the same folder as my script, uninstalled bleak (but not bleak-winrt, which still is 1.2.0) and ran the script again, to the same result.

I also noticed I was running an example from master, instead of develop, so it was kind of outdated. Now I pulled the example code from develop, but still got the same result.

dlech commented 1 year ago

I tried that and got the same result.

If you got the exact same logs, then you did not run the correct code. The pull request branch should no longer have "restarting get services due to services changed event" in the logs.

integerfn commented 1 year ago

Well yes, by the same result I meant that it crashes with the same message at the same moment. Here are the logs 

2023-01-12 09:39:08,145 asyncio  DEBUG: Using proactor: IocpProactor
2023-01-12 09:39:08,146 __main__ INFO: starting scan...
2023-01-12 09:39:08,331 bleak.backends.winrt.scanner DEBUG: Received 11:F5:E7:20:E3:38: .
2023-01-12 09:39:08,333 bleak.backends.winrt.scanner DEBUG: Received 3F:90:F1:26:A2:56: .
2023-01-12 09:39:08,336 bleak.backends.winrt.scanner DEBUG: Received 14:4B:66:E6:C9:83: .
2023-01-12 09:39:08,428 bleak.backends.winrt.scanner DEBUG: Received 3F:90:F1:26:A2:56: .
2023-01-12 09:39:08,431 bleak.backends.winrt.scanner DEBUG: Received 11:F5:E7:20:E3:38: .
2023-01-12 09:39:08,553 bleak.backends.winrt.scanner DEBUG: Received 21:2D:46:AA:5F:27: .
2023-01-12 09:39:08,669 bleak.backends.winrt.scanner DEBUG: Received 08:01:74:61:7E:12: .
2023-01-12 09:39:08,675 bleak.backends.winrt.scanner DEBUG: Received 2A:69:FD:62:B6:4B: .
2023-01-12 09:39:08,679 bleak.backends.winrt.scanner DEBUG: Received 09:8F:8E:3B:CD:CD: .
2023-01-12 09:39:08,680 bleak.backends.winrt.scanner DEBUG: Received 3D:B2:25:38:38:CC: .
2023-01-12 09:39:08,783 bleak.backends.winrt.scanner DEBUG: Received 2A:69:FD:62:B6:4B: .
2023-01-12 09:39:08,799 bleak.backends.winrt.scanner DEBUG: Received 09:8F:8E:3B:CD:CD: .
2023-01-12 09:39:08,897 bleak.backends.winrt.scanner DEBUG: Received 3D:B2:25:38:38:CC: .
2023-01-12 09:39:08,908 bleak.backends.winrt.scanner DEBUG: Received 4F:FC:07:AB:DA:D6: .
2023-01-12 09:39:08,908 bleak.backends.winrt.scanner DEBUG: skipping callback, waiting for scan response
2023-01-12 09:39:08,909 bleak.backends.winrt.scanner DEBUG: Received 4F:FC:07:AB:DA:D6: .
2023-01-12 09:39:08,913 bleak.backends.winrt.scanner DEBUG: Received 29:08:BE:4B:DA:37: .
2023-01-12 09:39:08,917 bleak.backends.winrt.scanner DEBUG: Received 00:6B:FF:A5:3D:DB: .
2023-01-12 09:39:09,018 bleak.backends.winrt.scanner DEBUG: Received 58:90:5D:FA:CC:B3: .
2023-01-12 09:39:09,019 bleak.backends.winrt.scanner DEBUG: skipping callback, waiting for scan response
2023-01-12 09:39:09,019 bleak.backends.winrt.scanner DEBUG: Received 58:90:5D:FA:CC:B3: .
2023-01-12 09:39:09,021 bleak.backends.winrt.scanner DEBUG: Received 5A:D1:CF:B8:03:AC: .
2023-01-12 09:39:09,022 bleak.backends.winrt.scanner DEBUG: Received 3D:90:40:A4:78:F1: .
2023-01-12 09:39:09,025 bleak.backends.winrt.scanner DEBUG: Received 00:6B:FF:A5:3D:DB: .
2023-01-12 09:39:09,035 bleak.backends.winrt.scanner DEBUG: Received D0:03:DF:CD:51:31: .
2023-01-12 09:39:09,148 bleak.backends.winrt.scanner DEBUG: Received 7C:0A:3F:55:69:3D: .
2023-01-12 09:39:09,150 bleak.backends.winrt.scanner DEBUG: Received E5:9C:16:E3:43:C5: .
2023-01-12 09:39:09,264 bleak.backends.winrt.scanner DEBUG: Received 11:F5:E7:20:E3:38: .
2023-01-12 09:39:09,370 bleak.backends.winrt.scanner DEBUG: Received 11:F5:E7:20:E3:38: .
2023-01-12 09:39:09,375 bleak.backends.winrt.scanner DEBUG: Received 21:2D:46:AA:5F:27: .
2023-01-12 09:39:09,380 bleak.backends.winrt.scanner DEBUG: Received F2:21:9B:1C:E9:AE: .
2023-01-12 09:39:09,380 bleak.backends.winrt.scanner DEBUG: skipping callback, waiting for scan response
2023-01-12 09:39:09,387 bleak.backends.winrt.scanner DEBUG: Received 08:01:74:61:7E:12: .
2023-01-12 09:39:09,524 bleak.backends.winrt.scanner DEBUG: Received 48:6F:D9:C1:57:DE: .
2023-01-12 09:39:09,524 bleak.backends.winrt.scanner DEBUG: skipping callback, waiting for scan response
2023-01-12 09:39:09,526 bleak.backends.winrt.scanner DEBUG: Received 48:6F:D9:C1:57:DE: .
2023-01-12 09:39:09,528 bleak.backends.winrt.scanner DEBUG: Received 09:8F:8E:3B:CD:CD: .
2023-01-12 09:39:09,619 bleak.backends.winrt.scanner DEBUG: Received 3D:B2:25:38:38:CC: .
2023-01-12 09:39:09,629 bleak.backends.winrt.scanner DEBUG: Received 09:8F:8E:3B:CD:CD: .
2023-01-12 09:39:09,731 bleak.backends.winrt.scanner DEBUG: Received 4F:FC:07:AB:DA:D6: .
2023-01-12 09:39:09,732 bleak.backends.winrt.scanner DEBUG: Received 4F:FC:07:AB:DA:D6: .
2023-01-12 09:39:09,733 bleak.backends.winrt.scanner DEBUG: Received 09:8F:8E:3B:CD:CD: .
2023-01-12 09:39:09,855 bleak.backends.winrt.scanner DEBUG: Received 3D:90:40:A4:78:F1: .
2023-01-12 09:39:09,860 bleak.backends.winrt.scanner DEBUG: Received 00:6B:FF:A5:3D:DB: .
2023-01-12 09:39:09,962 bleak.backends.winrt.scanner DEBUG: Received 00:6B:FF:A5:3D:DB: .
2023-01-12 09:39:09,965 bleak.backends.winrt.scanner DEBUG: Received D0:03:DF:CD:51:31: .
2023-01-12 09:39:09,973 bleak.backends.winrt.scanner DEBUG: Received 29:08:BE:4B:DA:37: .
2023-01-12 09:39:09,981 bleak.backends.winrt.scanner DEBUG: Received D9:1E:8E:E3:E1:D8: .
2023-01-12 09:39:09,981 bleak.backends.winrt.scanner DEBUG: skipping callback, waiting for scan response
2023-01-12 09:39:09,982 bleak.backends.winrt.scanner DEBUG: Received D9:1E:8E:E3:E1:D8: .
2023-01-12 09:39:09,984 bleak.backends.winrt.scanner DEBUG: 19 devices found. Watcher status: 3.
2023-01-12 09:39:09,984 __main__ INFO: connecting to device...
2023-01-12 09:39:09,991 bleak.backends.winrt.client DEBUG: Connecting to BLE device @ D9:1E:8E:E3:E1:D8
2023-01-12 09:39:10,048 bleak.backends.winrt.client DEBUG: getting services (service_cache_mode=None, cache_mode=None)...
2023-01-12 09:39:10,048 bleak.backends.winrt.client DEBUG: calling get_gatt_services_async
2023-01-12 09:39:10,183 bleak.backends.winrt.client DEBUG: max_pdu_size_changed_handler: 247
2023-01-12 09:39:10,183 bleak.backends.winrt.client DEBUG: session_status_changed_event_handler: id: <_bleak_winrt_Windows_Devices_Bluetooth.BluetoothDeviceId object at 0x0000015E974ADC30>, error: BluetoothError.SUCCESS, status: GattSessionStatus.ACTIVE
2023-01-12 09:39:10,454 bleak.backends.winrt.client DEBUG: returned from get_gatt_services_async
2023-01-12 09:39:10,454 bleak.backends.winrt.client DEBUG: calling get_characteristics_async
2023-01-12 09:39:10,487 bleak.backends.winrt.client DEBUG: D9:1E:8E:E3:E1:D8: services changed
2023-01-12 09:39:10,525 bleak.backends.winrt.client DEBUG: D9:1E:8E:E3:E1:D8: services changed
2023-01-12 09:39:10,537 bleak.backends.winrt.client DEBUG: returned from get_characteristics_async
2023-01-12 09:39:10,538 bleak.backends.winrt.client DEBUG: calling get_descriptors_async
2023-01-12 09:39:10,540 bleak.backends.winrt.client DEBUG: returned from get_descriptors_async
2023-01-12 09:39:10,541 bleak.backends.winrt.client DEBUG: calling get_descriptors_async
2023-01-12 09:39:10,543 bleak.backends.winrt.client DEBUG: returned from get_descriptors_async
2023-01-12 09:39:10,543 bleak.backends.winrt.client DEBUG: calling get_descriptors_async
2023-01-12 09:39:10,545 bleak.backends.winrt.client DEBUG: returned from get_descriptors_async
2023-01-12 09:39:10,546 bleak.backends.winrt.client DEBUG: calling get_descriptors_async
2023-01-12 09:39:10,547 bleak.backends.winrt.client DEBUG: returned from get_descriptors_async
2023-01-12 09:39:10,547 bleak.backends.winrt.client DEBUG: calling get_characteristics_async
2023-01-12 09:39:10,563 bleak.backends.winrt.client DEBUG: D9:1E:8E:E3:E1:D8: services changed
2023-01-12 09:39:10,599 bleak.backends.winrt.client DEBUG: D9:1E:8E:E3:E1:D8: services changed
2023-01-12 09:39:10,603 bleak.backends.winrt.client DEBUG: returned from get_characteristics_async
2023-01-12 09:39:10,603 bleak.backends.winrt.client DEBUG: calling get_characteristics_async
2023-01-12 09:39:10,679 bleak.backends.winrt.client DEBUG: returned from get_characteristics_async
2023-01-12 09:39:10,680 bleak.backends.winrt.client DEBUG: calling get_descriptors_async
2023-01-12 09:39:10,682 bleak.backends.winrt.client DEBUG: returned from get_descriptors_async
2023-01-12 09:39:10,682 bleak.backends.winrt.client DEBUG: calling get_descriptors_async
2023-01-12 09:39:10,707 bleak.backends.winrt.client DEBUG: returned from get_descriptors_async
2023-01-12 09:39:10,707 bleak.backends.winrt.client DEBUG: calling get_characteristics_async
2023-01-12 09:39:10,768 bleak.backends.winrt.client DEBUG: returned from get_characteristics_async
2023-01-12 09:39:10,769 bleak.backends.winrt.client DEBUG: calling get_descriptors_async
2023-01-12 09:39:10,843 bleak.backends.winrt.client DEBUG: returned from get_descriptors_async
2023-01-12 09:39:10,843 __main__ INFO: Connected
2023-01-12 09:39:13,998 bleak.backends.winrt.client DEBUG: session_status_changed_event_handler: id: <_bleak_winrt_Windows_Devices_Bluetooth.BluetoothDeviceId object at 0x0000015E974AD9D0>, error: BluetoothError.SUCCESS, status: GattSessionStatus.CLOSED
2023-01-12 09:39:13,999 bleak.backends.winrt.client DEBUG: max_pdu_size_changed_handler: 23
2023-01-12 09:39:13,999 bleak.backends.winrt.client DEBUG: closing requester
2023-01-12 09:39:14,010 bleak.backends.winrt.client DEBUG: closing session
2023-01-12 09:39:15,874 bleak.backends.winrt.client DEBUG: Disconnecting from BLE device...
Traceback (most recent call last):
  File "C:/Users/redacted/dev/stm32/scripts/test.py", line 98, in <module>
    asyncio.run(main(args))
  File "C:\Users\redacted\AppData\Local\Programs\Python\Python38\lib\asyncio\runners.py", line 44, in run
    return loop.run_until_complete(main)
  File "C:\Users\redacted\AppData\Local\Programs\Python\Python38\lib\asyncio\base_events.py", line 616, in run_until_complete
    return future.result()
  File "C:/Users/redacted/dev/stm32/scripts/test.py", line 52, in main
    await client.stop_notify(args.characteristic)
  File "C:\Users\redacted\dev\stm32\scripts\bleak\__init__.py", line 704, in stop_notify
    await self._backend.stop_notify(char_specifier)
  File "C:\Users\redacted\dev\stm32\scripts\bleak\backends\winrt\client.py", line 957, in stop_notify
    raise BleakError("Not connected")
bleak.exc.BleakError: Not connected

Process finished with exit code 1

Edit: I also tried communicating with a device that has Just Works security enabled and it works, these are the logs:

2023-01-12 10:04:43,910 asyncio  DEBUG: Using proactor: IocpProactor
2023-01-12 10:04:43,911 __main__ INFO: starting scan...
2023-01-12 10:04:44,066 bleak.backends.winrt.scanner DEBUG: Received 3D:10:0C:01:2E:15: .
2023-01-12 10:04:44,073 bleak.backends.winrt.scanner DEBUG: Received 39:35:2A:43:F5:9E: .
2023-01-12 10:04:44,307 bleak.backends.winrt.scanner DEBUG: Received 2A:6B:3D:E4:AC:18: .
2023-01-12 10:04:44,419 bleak.backends.winrt.scanner DEBUG: Received D9:1E:8E:E3:E1:D8: .
2023-01-12 10:04:44,419 bleak.backends.winrt.scanner DEBUG: skipping callback, waiting for scan response
2023-01-12 10:04:44,421 bleak.backends.winrt.scanner DEBUG: Received D9:1E:8E:E3:E1:D8: .
2023-01-12 10:04:44,433 bleak.backends.winrt.scanner DEBUG: Received 7F:8A:A8:11:0B:E0: .
2023-01-12 10:04:44,433 bleak.backends.winrt.scanner DEBUG: skipping callback, waiting for scan response
2023-01-12 10:04:44,434 bleak.backends.winrt.scanner DEBUG: Received 7F:8A:A8:11:0B:E0: .
2023-01-12 10:04:44,436 bleak.backends.winrt.scanner DEBUG: Received 11:18:6E:3A:CF:59: .
2023-01-12 10:04:44,556 bleak.backends.winrt.scanner DEBUG: Received 4E:8B:5E:A2:92:B0: .
2023-01-12 10:04:44,568 bleak.backends.winrt.scanner DEBUG: Received 26:5E:11:E2:8C:D5: .
2023-01-12 10:04:44,665 bleak.backends.winrt.scanner DEBUG: Received 07:3A:1F:C4:8C:70: .
2023-01-12 10:04:44,667 bleak.backends.winrt.scanner DEBUG: Received 1E:99:E8:3F:04:A4: .
2023-01-12 10:04:44,669 bleak.backends.winrt.scanner DEBUG: Received 26:5E:11:E2:8C:D5: .
2023-01-12 10:04:44,779 bleak.backends.winrt.scanner DEBUG: Received D0:03:DF:CD:51:31: .
2023-01-12 10:04:44,913 bleak.backends.winrt.scanner DEBUG: Received 3D:10:0C:01:2E:15: .
2023-01-12 10:04:45,016 bleak.backends.winrt.scanner DEBUG: Received 39:35:2A:43:F5:9E: .
2023-01-12 10:04:45,018 bleak.backends.winrt.scanner DEBUG: Received D6:EC:4B:73:BC:41: .
2023-01-12 10:04:45,018 bleak.backends.winrt.scanner DEBUG: skipping callback, waiting for scan response
2023-01-12 10:04:45,020 bleak.backends.winrt.scanner DEBUG: Received D6:EC:4B:73:BC:41: .
2023-01-12 10:04:45,022 bleak.backends.winrt.scanner DEBUG: Received 3D:10:0C:01:2E:15: .
2023-01-12 10:04:45,023 bleak.backends.winrt.scanner DEBUG: 12 devices found. Watcher status: 3.
2023-01-12 10:04:45,024 __main__ INFO: connecting to device...
2023-01-12 10:04:45,031 bleak.backends.winrt.client DEBUG: Connecting to BLE device @ D6:EC:4B:73:BC:41
2023-01-12 10:04:45,147 bleak.backends.winrt.client DEBUG: getting services (service_cache_mode=None, cache_mode=None)...
2023-01-12 10:04:45,147 bleak.backends.winrt.client DEBUG: calling get_gatt_services_async
2023-01-12 10:04:45,191 bleak.backends.winrt.client DEBUG: returned from get_gatt_services_async
2023-01-12 10:04:45,191 bleak.backends.winrt.client DEBUG: calling get_characteristics_async
2023-01-12 10:04:45,211 bleak.backends.winrt.client DEBUG: returned from get_characteristics_async
2023-01-12 10:04:45,212 bleak.backends.winrt.client DEBUG: calling get_descriptors_async
2023-01-12 10:04:45,213 bleak.backends.winrt.client DEBUG: returned from get_descriptors_async
2023-01-12 10:04:45,214 bleak.backends.winrt.client DEBUG: calling get_descriptors_async
2023-01-12 10:04:45,215 bleak.backends.winrt.client DEBUG: returned from get_descriptors_async
2023-01-12 10:04:45,216 bleak.backends.winrt.client DEBUG: calling get_descriptors_async
2023-01-12 10:04:45,217 bleak.backends.winrt.client DEBUG: returned from get_descriptors_async
2023-01-12 10:04:45,217 bleak.backends.winrt.client DEBUG: calling get_descriptors_async
2023-01-12 10:04:45,219 bleak.backends.winrt.client DEBUG: returned from get_descriptors_async
2023-01-12 10:04:45,219 bleak.backends.winrt.client DEBUG: calling get_characteristics_async
2023-01-12 10:04:45,234 bleak.backends.winrt.client DEBUG: returned from get_characteristics_async
2023-01-12 10:04:45,234 bleak.backends.winrt.client DEBUG: calling get_descriptors_async
2023-01-12 10:04:45,236 bleak.backends.winrt.client DEBUG: returned from get_descriptors_async
2023-01-12 10:04:45,237 bleak.backends.winrt.client DEBUG: calling get_characteristics_async
2023-01-12 10:04:45,252 bleak.backends.winrt.client DEBUG: returned from get_characteristics_async
2023-01-12 10:04:45,253 bleak.backends.winrt.client DEBUG: calling get_descriptors_async
2023-01-12 10:04:45,256 bleak.backends.winrt.client DEBUG: returned from get_descriptors_async
2023-01-12 10:04:45,256 bleak.backends.winrt.client DEBUG: calling get_descriptors_async
2023-01-12 10:04:45,259 bleak.backends.winrt.client DEBUG: returned from get_descriptors_async
2023-01-12 10:04:45,259 bleak.backends.winrt.client DEBUG: calling get_characteristics_async
2023-01-12 10:04:45,273 bleak.backends.winrt.client DEBUG: returned from get_characteristics_async
2023-01-12 10:04:45,274 bleak.backends.winrt.client DEBUG: calling get_descriptors_async
2023-01-12 10:04:45,277 bleak.backends.winrt.client DEBUG: returned from get_descriptors_async
2023-01-12 10:04:51,047 bleak.backends.winrt.client DEBUG: session_status_changed_event_handler: id: <_bleak_winrt_Windows_Devices_Bluetooth.BluetoothDeviceId object at 0x000002D23ACFDB90>, error: BluetoothError.SUCCESS, status: GattSessionStatus.ACTIVE
2023-01-12 10:04:51,048 __main__ INFO: Connected
2023-01-12 10:04:51,057 bleak.backends.winrt.client DEBUG: max_pdu_size_changed_handler: 247
2023-01-12 10:04:56,415 bleak.backends.winrt.client DEBUG: Disconnecting from BLE device...
2023-01-12 10:04:59,508 bleak.backends.winrt.client DEBUG: max_pdu_size_changed_handler: 23
2023-01-12 10:04:59,509 bleak.backends.winrt.client DEBUG: session_status_changed_event_handler: id: <_bleak_winrt_Windows_Devices_Bluetooth.BluetoothDeviceId object at 0x000002D23ACFDC50>, error: BluetoothError.SUCCESS, status: GattSessionStatus.CLOSED
2023-01-12 10:04:59,510 bleak.backends.winrt.client DEBUG: closing requester
2023-01-12 10:04:59,510 bleak.backends.winrt.client DEBUG: closing session

Process finished with exit code 0
integerfn commented 1 year ago

I debugged a little bit with Wireshark and Pycharm. Perhaps you already knew this, but I found that when this line is reached: bleak.backends.winrt.client DEBUG: Disconnecting from BLE device..., disconnection has already happened. This line is printed from BleakClientWinRT.disconnect, but this only happens because stop_notify raised an exception (because it was disconnected). This causes the context manager to execute the __aexit__ method and call the disconnect method.

From the Wireshark log, the disconnect starts from the Host as an HCI_CMD to the controller. So it looks like the windows host code is deciding to disconnect, but I'm not sure why.

dlech commented 1 year ago

Can you share the wireshark logs?

integerfn commented 1 year ago

Sure, cap1.zip.

I tried one more thing: I changed the firmware on the nRF to support pairing and bonding again, and it started working with 0.19.5. So that seems to be the difference that breaks it. We have worked without pairing before, using the dotnet backend in windows, I believe, so this should be possible, as far as I know. We need this device to work without pairing, so enabling pairing is just a workaround for now.

integerfn commented 1 year ago

Hi again! Have you had a chance to look at this? Were the logs helpful? Is there any more input I can provide? Like logs or tests, etc.? Or perhaps a workaround to try?

Thanks!

dlech commented 1 year ago

Does this still happen with the current develop branch? Can you share the code to reproduce the problem? It sound like there is nothing keeping the BleakClient async context manager open, so the disconnect method is called.

integerfn commented 1 year ago

So now it's working with the develop branch, with the "bleak-winrt-fix-leaking-services" branch I had pulled on 2023/01/11 and with the 0.19.5 installed with pip. I was just running the "enable_notifications.py" example, nothing fancy. The firmware on the nordic chip is the same as before, a few custom characteristics without pairing or security. Might have been a Windows issue? I'll update again if I can reproduce it.

852432070 commented 1 year ago

So now it's working with the develop branch, with the "bleak-winrt-fix-leaking-services" branch I had pulled on 2023/01/11 and with the 0.19.5 installed with pip. I was just running the "enable_notifications.py" example, nothing fancy. The firmware on the nordic chip is the same as before, a few custom characteristics without pairing or security. Might have been a Windows issue? I'll update again if I can reproduce it.

Meeting the same problem, and I have no idea about this. I think it's caused by Windows issue too. If you have any progress about this, please tell me. By the way, my BT module is a product of intel, what's yours? Is this possible that the problem is caused by BT module driver?

integerfn commented 1 year ago

So now it's working with the develop branch, with the "bleak-winrt-fix-leaking-services" branch I had pulled on 2023/01/11 and with the 0.19.5 installed with pip. I was just running the "enable_notifications.py" example, nothing fancy. The firmware on the nordic chip is the same as before, a few custom characteristics without pairing or security. Might have been a Windows issue? I'll update again if I can reproduce it.

Meeting the same problem, and I have no idea about this. I think it's caused by Windows issue too. If you have any progress about this, please tell me. By the way, my BT module is a product of intel, what's yours? Is this possible that the problem is caused by BT module driver?

It's possible, I've encountered several issues that go away after a reset or a driver update. I have an Intel AX201, and the bluetooth driver version is 22.190.0.2. Perhaps try updating? My other suspicion is regarding the Windows resgistry. Many times "Remove Device" from the control panel is not enough and some traces are left in the registry or somewhere else and some information persists. It could be possible that, since Windows had been paired before to the same MAC address, it still believed that it needed pairing/security and it encountered a discrepancy with the device capabilities (which didn't suppor security anymore), so it aborted the connection. Cleaning the registry manually, resetting the PC and even trying on a different PC that hasn't ever been paired with the device could be helpful.

dlech commented 1 year ago

So far, most people who have reported problems on Windows and included Bluetooth radio info have mentioned they have an Intel Bluetooth chip.

852432070 commented 1 year ago

So far, most people who have reported problems on Windows and included Bluetooth radio info have mentioned they have an Intel Bluetooth chip.

Unfortunately, I tested the same code on another device with a Realtek BT Adapter, and that seems runs into the same situation.

dlech commented 1 year ago

You haven't shared any code. Are we sure that the code isn't just telling the device to disconnect in your case (e.g. using the BleakClient context manager with nothing to keep it waiting)?

852432070 commented 1 year ago

You haven't shared any code. Are we sure that the code isn't just telling the device to disconnect in your case (e.g. using the BleakClient context manager with nothing to keep it waiting)?

import asyncio
import platform
import sys
import logging
from bleak import BleakClient
from bleak.uuids import uuid16_dict
from bleak.backends.winrt.client import logger as bleak_log

ADDRESS = (
    "70:66:55:26:8B:0C"
    if platform.system() != "Darwin"
    else "B9EA5233-37EF-4DD6-87A8-2A875E821C46"
)

uuid = "00002a1c-0000-1000-8000-00805f9b34fb"

def temper_callback(sender: int, data: bytearray):
    temperture = int.from_bytes(data[1:5], sys.byteorder)
    print(f"{sender}: {temperture}")

def disconnected_callback():
    print("device disconnected!")

async def main(address):
    bleak_log.setLevel(logging.DEBUG)
    ch = logging.StreamHandler()
    ch.setLevel(logging.DEBUG)
    ch.setFormatter(logging.Formatter('---BLEAK:%(levelname)s %(message)s'))     
    bleak_log.addHandler(ch)
    bleak_log.disabled = False
    async with BleakClient(address, winrt=dict(use_cached_services=True)) as client:
        print(f"Connected: {client.is_connected}")
        client.set_disconnected_callback(disconnected_callback)

        await client.start_notify(uuid, temper_callback)
        await asyncio.sleep(1000)
        await client.stop_notify(uuid)

if __name__ == "__main__":
    asyncio.run(main(sys.argv[1] if len(sys.argv) == 2 else ADDRESS))

In my case, I just start a indication that callback every time a temperature data is generated. As you can see, I use a asyncio.sleep(1000) to keep the indication work for a long time, but for each time it just lasts for about 30 secs. Is there any step I missed to keep the connection alive?

All logs are also attached below.

---BLEAK:DEBUG Connecting to BLE device @ 70:66:55:26:8B:0C
---BLEAK:DEBUG getting services (service_cache_mode=<BluetoothCacheMode.CACHED: 0>, cache_mode=<BluetoothCacheMode.CACHED: 0>)...
---BLEAK:DEBUG session_status_changed_event_handler: id: <_bleak_winrt_Windows_Devices_Bluetooth.BluetoothDeviceId object at 0x000001AAC60DF5B0>, error: 0, status: 1
---BLEAK:DEBUG max_pdu_size_changed_handler: 65
---BLEAK:DEBUG 70:66:55:26:8B:0C: services changed
---BLEAK:DEBUG 70:66:55:26:8B:0C: restarting get services due to services changed event
---BLEAK:DEBUG 70:66:55:26:8B:0C: services changed
---BLEAK:DEBUG getting services (service_cache_mode=<BluetoothCacheMode.CACHED: 0>, cache_mode=<BluetoothCacheMode.CACHED: 0>)...
---BLEAK:DEBUG 70:66:55:26:8B:0C: restarting get services due to services changed event
---BLEAK:DEBUG 70:66:55:26:8B:0C: services changed
---BLEAK:DEBUG getting services (service_cache_mode=<BluetoothCacheMode.CACHED: 0>, cache_mode=<BluetoothCacheMode.CACHED: 0>)...
---BLEAK:DEBUG 70:66:55:26:8B:0C: restarting get services due to services changed event
---BLEAK:DEBUG 70:66:55:26:8B:0C: services changed
---BLEAK:DEBUG getting services (service_cache_mode=<BluetoothCacheMode.CACHED: 0>, cache_mode=<BluetoothCacheMode.CACHED: 0>)...
---BLEAK:DEBUG 70:66:55:26:8B:0C: restarting get services due to services changed event
---BLEAK:DEBUG getting services (service_cache_mode=<BluetoothCacheMode.CACHED: 0>, cache_mode=<BluetoothCacheMode.CACHED: 0>)...
Connected: True
C:\Users\nxf97306\Desktop\ble-gatt\test\test.py:33: FutureWarning: This method will be removed future version, pass the callback to the BleakClient constructor instead.
  client.set_disconnected_callback(disconnected_callback)
00002a1c-0000-1000-8000-00805f9b34fb (Handle: 18): Temperature Measurement: 20
00002a1c-0000-1000-8000-00805f9b34fb (Handle: 18): Temperature Measurement: 21
00002a1c-0000-1000-8000-00805f9b34fb (Handle: 18): Temperature Measurement: 22
00002a1c-0000-1000-8000-00805f9b34fb (Handle: 18): Temperature Measurement: 23
00002a1c-0000-1000-8000-00805f9b34fb (Handle: 18): Temperature Measurement: 24
00002a1c-0000-1000-8000-00805f9b34fb (Handle: 18): Temperature Measurement: 20
00002a1c-0000-1000-8000-00805f9b34fb (Handle: 18): Temperature Measurement: 21
00002a1c-0000-1000-8000-00805f9b34fb (Handle: 18): Temperature Measurement: 22
00002a1c-0000-1000-8000-00805f9b34fb (Handle: 18): Temperature Measurement: 23
00002a1c-0000-1000-8000-00805f9b34fb (Handle: 18): Temperature Measurement: 24
00002a1c-0000-1000-8000-00805f9b34fb (Handle: 18): Temperature Measurement: 20
00002a1c-0000-1000-8000-00805f9b34fb (Handle: 18): Temperature Measurement: 21
00002a1c-0000-1000-8000-00805f9b34fb (Handle: 18): Temperature Measurement: 22
00002a1c-0000-1000-8000-00805f9b34fb (Handle: 18): Temperature Measurement: 23
00002a1c-0000-1000-8000-00805f9b34fb (Handle: 18): Temperature Measurement: 24
00002a1c-0000-1000-8000-00805f9b34fb (Handle: 18): Temperature Measurement: 20
00002a1c-0000-1000-8000-00805f9b34fb (Handle: 18): Temperature Measurement: 21
00002a1c-0000-1000-8000-00805f9b34fb (Handle: 18): Temperature Measurement: 22
00002a1c-0000-1000-8000-00805f9b34fb (Handle: 18): Temperature Measurement: 23
00002a1c-0000-1000-8000-00805f9b34fb (Handle: 18): Temperature Measurement: 24
00002a1c-0000-1000-8000-00805f9b34fb (Handle: 18): Temperature Measurement: 20
00002a1c-0000-1000-8000-00805f9b34fb (Handle: 18): Temperature Measurement: 21
00002a1c-0000-1000-8000-00805f9b34fb (Handle: 18): Temperature Measurement: 22
00002a1c-0000-1000-8000-00805f9b34fb (Handle: 18): Temperature Measurement: 23
00002a1c-0000-1000-8000-00805f9b34fb (Handle: 18): Temperature Measurement: 24
00002a1c-0000-1000-8000-00805f9b34fb (Handle: 18): Temperature Measurement: 20
00002a1c-0000-1000-8000-00805f9b34fb (Handle: 18): Temperature Measurement: 21
00002a1c-0000-1000-8000-00805f9b34fb (Handle: 18): Temperature Measurement: 22
00002a1c-0000-1000-8000-00805f9b34fb (Handle: 18): Temperature Measurement: 23
---BLEAK:DEBUG session_status_changed_event_handler: id: <_bleak_winrt_Windows_Devices_Bluetooth.BluetoothDeviceId object at 0x000001AAC61141B0>, error: 0, status: 0
---BLEAK:DEBUG max_pdu_size_changed_handler: 23
---BLEAK:DEBUG 70:66:55:26:8B:0C: services changed
Exception in callback BleakClientWinRT.connect.<locals>.handle_session_status_changed(<_bleak_winrt...001AAC6114930>) at c:\Users\nxf97306\Desktop\ble-gatt\bt_gui_env\Lib\site-packages\bleak\backends\winrt\client.py:301
handle: <Handle BleakClientWinRT.connect.<locals>.handle_session_status_changed(<_bleak_winrt...001AAC6114930>) at c:\Users\nxf97306\Desktop\ble-gatt\bt_gui_env\Lib\site-packages\bleak\backends\winrt\client.py:301>
Traceback (most recent call last):
  File "C:\Users\nxf97306\AppData\Local\Programs\Python\Python311\Lib\asyncio\events.py", line 80, in _run
    self._context.run(self._callback, *self._args)
  File "c:\Users\nxf97306\Desktop\ble-gatt\bt_gui_env\Lib\site-packages\bleak\backends\winrt\client.py", line 313, in handle_session_status_changed
    self._disconnected_callback(self)
TypeError: disconnected_callback() takes 0 positional arguments but 1 was given
---BLEAK:WARNING 70:66:55:26:8B:0C: unhandled services changed event
---BLEAK:DEBUG 70:66:55:26:8B:0C: services changed
---BLEAK:WARNING 70:66:55:26:8B:0C: unhandled services changed event
---BLEAK:DEBUG 70:66:55:26:8B:0C: services changed
---BLEAK:WARNING 70:66:55:26:8B:0C: unhandled services changed event
---BLEAK:DEBUG 70:66:55:26:8B:0C: services changed
---BLEAK:WARNING 70:66:55:26:8B:0C: unhandled services changed event
---BLEAK:DEBUG 70:66:55:26:8B:0C: services changed
---BLEAK:WARNING 70:66:55:26:8B:0C: unhandled services changed event
---BLEAK:DEBUG session_status_changed_event_handler: id: <_bleak_winrt_Windows_Devices_Bluetooth.BluetoothDeviceId object at 0x000001AAC6115550>, error: 0, status: 1
---BLEAK:DEBUG max_pdu_size_changed_handler: 65
---BLEAK:DEBUG 70:66:55:26:8B:0C: services changed
---BLEAK:WARNING 70:66:55:26:8B:0C: unhandled services changed event
---BLEAK:DEBUG 70:66:55:26:8B:0C: services changed
---BLEAK:WARNING 70:66:55:26:8B:0C: unhandled services changed event
dlech commented 1 year ago

You could try logging Bluetooth packets to see what triggers the disconnect, it could be either the remote device or Windows.