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.

Sign up for GitHub

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

Jump to bottom

WinRT backend should allow ADV_IND without SCAN_RESP #1211

Closed
dlech opened this issue Jan 31, 2023 Discussed in #1210 · 10 comments · Fixed by #1228
Closed

WinRT backend should allow ADV_IND without SCAN_RESP #1211

dlech opened this issue Jan 31, 2023 Discussed in #1210 · 10 comments · Fixed by #1228
Labels
Backend: WinRT Issues or PRs relating to the WinRT backend bug Something isn't working

Comments

@dlech
Copy link
Collaborator

dlech commented Jan 31, 2023

Discussed in #1210

Originally posted by zapta January 30, 2023

  • bleak version: 0.19.5
  • Python version: Python 3.10.7
  • Operating System: Windows 10
  • BlueZ version (bluetoothctl -v) in case of Linux:

Description

I have a BLE device which sends adv packets but for some reason doesn't send scan response packets and am resolving it with the vendor espressif/esp-idf#10660 . My question here is regarding Bleak.

If I use the Nordic nRF Connect app on my phone, I see the device in the scan list and can connect to it with no problem even though the device didn't respond to SCAN_REQ (verified with wireshark). However, when I use a python program with Bleak, it doesn't show in the Bleak scan list and if I try to connect directly by specifying the address it Bleak still doesn't connect.

Is there a way to tell Bleak to not require a SCAN_RESP packet and list and connect to the device regardless?

What I Did

I ran a python script with a bleak scanner and captured the traffic with wireshark and a Nordic dongle. The computer with the Bleak scanner did sends a SCAN_REQ, but didn't get back a SCAN_RESP and ignored the device. The wireshark packet file and screen shot are included below.

Logs

C:\projects\esp32\repo\release\windows>set BLEAK_LOGGING=1

C:\projects\esp32\repo\release\windows>analyzer.exe --scan
OS: Windows-10-10.0.19044-SP0
Platform:: uname_result(system='Windows', node='Ryzen', release='10', version='10.0.19044', machine='AMD64')
Python 3.10.7 (tags/v3.10.7:6cc6b13, Sep 5 2022, 14:08:36) [MSC v.1933 64 bit (AMD64)]
Scanning 5 secs for advertising BLE devices ...

2023-01-30 19:33:32,751 bleak.backends.winrt.scanner DEBUG: Received 30:E2:83:7C:F3:11: .
2023-01-30 19:33:32,752 bleak.backends.winrt.scanner DEBUG: skipping callback, waiting for scan response
2023-01-30 19:33:32,752 bleak.backends.winrt.scanner DEBUG: Received 3A:35:F1:22:AE:BD: .
2023-01-30 19:33:32,849 bleak.backends.winrt.scanner DEBUG: Received 24:D7:EB:15:27:8E: ESP_GATTS_DEMO.
2023-01-30 19:33:32,849 bleak.backends.winrt.scanner DEBUG: skipping callback, waiting for scan response
2023-01-30 19:33:32,983 bleak.backends.winrt.scanner DEBUG: Received 24:D7:EB:15:27:8E: ESP_GATTS_DEMO.
2023-01-30 19:33:32,984 bleak.backends.winrt.scanner DEBUG: skipping callback, waiting for scan response
2023-01-30 19:33:33,568 bleak.backends.winrt.scanner DEBUG: Received 24:D7:EB:15:27:8E: ESP_GATTS_DEMO.
2023-01-30 19:33:33,569 bleak.backends.winrt.scanner DEBUG: skipping callback, waiting for scan response
2023-01-30 19:33:33,797 bleak.backends.winrt.scanner DEBUG: Received 24:D7:EB:15:27:8E: ESP_GATTS_DEMO.
2023-01-30 19:33:33,797 bleak.backends.winrt.scanner DEBUG: skipping callback, waiting for scan response
2023-01-30 19:33:33,799 bleak.backends.winrt.scanner DEBUG: Received 3A:35:F1:22:AE:BD: .
2023-01-30 19:33:34,394 bleak.backends.winrt.scanner DEBUG: Received 24:D7:EB:15:27:8E: ESP_GATTS_DEMO.
2023-01-30 19:33:34,395 bleak.backends.winrt.scanner DEBUG: skipping callback, waiting for scan response
2023-01-30 19:33:34,516 bleak.backends.winrt.scanner DEBUG: Received 3A:35:F1:22:AE:BD: .
2023-01-30 19:33:34,624 bleak.backends.winrt.scanner DEBUG: Received 3A:35:F1:22:AE:BD: .
2023-01-30 19:33:34,887 bleak.backends.winrt.scanner DEBUG: Received 24:D7:EB:15:27:8E: ESP_GATTS_DEMO.
2023-01-30 19:33:34,887 bleak.backends.winrt.scanner DEBUG: skipping callback, waiting for scan response
2023-01-30 19:33:34,984 bleak.backends.winrt.scanner DEBUG: Received 24:D7:EB:15:27:8E: ESP_GATTS_DEMO.
2023-01-30 19:33:34,985 bleak.backends.winrt.scanner DEBUG: skipping callback, waiting for scan response
2023-01-30 19:33:35,568 bleak.backends.winrt.scanner DEBUG: Received 3A:35:F1:22:AE:BD: .
2023-01-30 19:33:35,573 bleak.backends.winrt.scanner DEBUG: Received 24:D7:EB:15:27:8E: ESP_GATTS_DEMO.
2023-01-30 19:33:35,573 bleak.backends.winrt.scanner DEBUG: skipping callback, waiting for scan response
2023-01-30 19:33:36,162 bleak.backends.winrt.scanner DEBUG: Received 24:D7:EB:15:27:8E: ESP_GATTS_DEMO.
2023-01-30 19:33:36,163 bleak.backends.winrt.scanner DEBUG: skipping callback, waiting for scan response
2023-01-30 19:33:36,514 bleak.backends.winrt.scanner DEBUG: Received 3A:35:F1:22:AE:BD: .
2023-01-30 19:33:36,527 bleak.backends.winrt.scanner DEBUG: Received 24:D7:EB:15:27:8E: ESP_GATTS_DEMO.
2023-01-30 19:33:36,527 bleak.backends.winrt.scanner DEBUG: skipping callback, waiting for scan response
2023-01-30 19:33:36,750 bleak.backends.winrt.scanner DEBUG: Received 24:D7:EB:15:27:8E: ESP_GATTS_DEMO.
2023-01-30 19:33:36,751 bleak.backends.winrt.scanner DEBUG: skipping callback, waiting for scan response
2023-01-30 19:33:37,111 bleak.backends.winrt.scanner DEBUG: Received 24:D7:EB:15:27:8E: ESP_GATTS_DEMO.
2023-01-30 19:33:37,112 bleak.backends.winrt.scanner DEBUG: skipping callback, waiting for scan response
2023-01-30 19:33:37,317 bleak.backends.winrt.scanner DEBUG: 1 devices found. Watcher status: 3.
1 device address: 3A:35:F1:22:AE:BD ()

Scanning done.

C:\projects\esp32\repo\release\windows>

Attachments

2023-01-30_18-44-26
bleak_scan.zip
@dlech dlech added bug Something isn't working Backend: WinRT Issues or PRs relating to the WinRT backend labels Jan 31, 2023
@dlech
Copy link
Collaborator Author

dlech commented Jan 31, 2023 •
edited
Loading

Sorry for the noise, I prematurely converted this to a discussion and there is no undo for that.

I did some digging into the Bluetooth spec and it looks like ADV_IND without SCAN_RSP should be allowed so we need to fix that.

@dlech
Copy link
Collaborator Author

dlech commented Jan 31, 2023

bleak/bleak/backends/winrt/scanner.py

Lines 130 to 140 in 648dc2e

if (raw_data.adv is None or raw_data.scan is None) and (
event_args.advertisement_type
in [
BluetoothLEAdvertisementType.CONNECTABLE_UNDIRECTED,
BluetoothLEAdvertisementType.SCANNABLE_UNDIRECTED,
BluetoothLEAdvertisementType.SCAN_RESPONSE,
]
):
logger.debug("skipping callback, waiting for scan response")
return

We could either remove this check entirely or only skip the first receive packet instead of all.

@zapta
Copy link

zapta commented Feb 1, 2023

I changed the conditions to

        #if (raw_data.adv is None or raw_data.scan is None) and (
        if (raw_data.adv is None) and (
            event_args.advertisement_type
            in [
                BluetoothLEAdvertisementType.CONNECTABLE_UNDIRECTED,
                BluetoothLEAdvertisementType.SCANNABLE_UNDIRECTED,
                BluetoothLEAdvertisementType.SCAN_RESPONSE,
            ]
        ):
            logger.debug("skipping callback, waiting for scan response")
            return

And now the scanning works (good):

/c/projects/esp32/repo/analyzer/src$ ./analyzer.py --scan
OS: Windows-10-10.0.19044-SP0
Platform:: uname_result(system='Windows', node='Ryzen', release='10', version='10.0.19044', machine='AMD64')
Python 3.10.7 (tags/v3.10.7:6cc6b13, Sep  5 2022, 14:08:36) [MSC v.1933 64 bit (AMD64)]
Scanning 5 secs for advertising BLE devices ...

1 device address: 24:D7:EB:15:27:8E  (STP-24D7EB15278E)
2 device address: 2F:EB:75:37:1F:CE  ()
3 device address: 30:E2:83:7C:F3:11  ()

Scanning done.

But still can't connect by address:

/c/projects/esp32/repo/analyzer/src$ ./analyzer.py -d 24:D7:EB:15:27:8E
OS: Windows-10-10.0.19044-SP0
Platform:: uname_result(system='Windows', node='Ryzen', release='10', version='10.0.19044', machine='AMD64')
Python 3.10.7 (tags/v3.10.7:6cc6b13, Sep  5 2022, 14:08:36) [MSC v.1933 64 bit (AMD64)]
User specified device: [24:D7:EB:15:27:8E]
Device address: [24:D7:EB:15:27:8E]
Units: steps
Steps per unit: 1.0
Trying to connect to device [24:D7:EB:15:27:8E]...
INFO:probe:Found device: [24:D7:EB:15:27:8E]
Traceback (most recent call last):
  File "C:\projects\esp32\repo\analyzer\src\analyzer.py", line 214, in <module>
    probe = main_event_loop.run_until_complete(connect_to_probe())
  File "C:\Users\user\AppData\Local\Programs\Python\Python310\lib\asyncio\base_events.py", line 646, in run_until_complete
    return future.result()
  File "C:\projects\esp32\repo\analyzer\src\analyzer.py", line 200, in connect_to_probe
    if not await probe.connect():
  File "C:\projects\esp32\repo\analyzer\src\probe.py", line 105, in connect
    await self.__client.connect(timeout=timeout)
  File "C:\Users\user\AppData\Local\Programs\Python\Python310\lib\site-packages\bleak\__init__.py", line 471, in connect
    return await self._backend.connect(**kwargs)
  File "C:\Users\user\AppData\Local\Programs\Python\Python310\lib\site-packages\bleak\backends\winrt\client.py", line 413, in connect
    self.services = get_services_task.result()
  File "C:\Users\user\AppData\Local\Programs\Python\Python310\lib\site-packages\bleak\backends\winrt\client.py", line 643, in get_services
    services: Sequence[GattDeviceService] = _ensure_success(
  File "C:\Users\user\AppData\Local\Programs\Python\Python310\lib\site-packages\bleak\backends\winrt\client.py", line 120, in _ensure_success
    raise BleakError(f"{fail_msg}: Unreachable")
bleak.exc.BleakError: Could not get GATT services: Unreachable

If you need additional information please let me know.

@dlech
Copy link
Collaborator Author

dlech commented Feb 1, 2023

For OS errors we need OS logs, e.g. wireshark packet capture.

@zapta
Copy link

zapta commented Feb 1, 2023

Below are a screenshot, debug log snapshot, and a zipped wireshark file with the connection attempt using the the patched bleak.

image

C:\projects\esp32\repo\analyzer\src>set BLEAK_LOGGING=1

C:\projects\esp32\repo\analyzer\src>python analyzer.py -d 24:D7:EB:15:27:8E
OS: Windows-10-10.0.19044-SP0
Platform:: uname_result(system='Windows', node='Ryzen', release='10', version='10.0.19044', machine='AMD64')
Python 3.10.7 (tags/v3.10.7:6cc6b13, Sep  5 2022, 14:08:36) [MSC v.1933 64 bit (AMD64)]
User specified device: [24:D7:EB:15:27:8E]
Device address: [24:D7:EB:15:27:8E]
Units: steps
Steps per unit: 1.0
Trying to connect to device [24:D7:EB:15:27:8E]...
2023-01-31 17:48:53,573 bleak.backends.winrt.scanner DEBUG: Received 20:29:16:37:88:37: .
DEBUG:bleak.backends.winrt.scanner:Received 20:29:16:37:88:37: .
2023-01-31 17:48:53,705 bleak.backends.winrt.scanner DEBUG: Received 24:D7:EB:15:27:8E: STP-24D7EB15278E.
DEBUG:bleak.backends.winrt.scanner:Received 24:D7:EB:15:27:8E: STP-24D7EB15278E.
2023-01-31 17:48:53,708 bleak.backends.winrt.scanner DEBUG: 2 devices found. Watcher status: 3.
DEBUG:bleak.backends.winrt.scanner:2 devices found. Watcher status: 3.
INFO:probe:Found device: [24:D7:EB:15:27:8E]
2023-01-31 17:48:53,716 bleak.backends.winrt.client DEBUG: Connecting to BLE device @ 24:D7:EB:15:27:8E
DEBUG:bleak.backends.winrt.client:Connecting to BLE device @ 24:D7:EB:15:27:8E
2023-01-31 17:48:53,752 bleak.backends.winrt.client DEBUG: getting services (service_cache_mode=None, cache_mode=None)...
DEBUG:bleak.backends.winrt.client:getting services (service_cache_mode=None, cache_mode=None)...
2023-01-31 17:48:53,986 bleak.backends.winrt.client DEBUG: session_status_changed_event_handler: id: <_bleak_winrt_Windows_Devices_Bluetooth.BluetoothDeviceId object at 0x000001C72B5A3C70>, error: BluetoothError.SUCCESS, status: GattSessionStatus.ACTIVE
DEBUG:bleak.backends.winrt.client:session_status_changed_event_handler: id: <_bleak_winrt_Windows_Devices_Bluetooth.BluetoothDeviceId object at 0x000001C72B5A3C70>, error: BluetoothError.SUCCESS, status: GattSessionStatus.ACTIVE
2023-01-31 17:48:54,153 bleak.backends.winrt.client DEBUG: session_status_changed_event_handler: id: <_bleak_winrt_Windows_Devices_Bluetooth.BluetoothDeviceId object at 0x000001C72B5A3C90>, error: BluetoothError.SUCCESS, status: GattSessionStatus.CLOSED
DEBUG:bleak.backends.winrt.client:session_status_changed_event_handler: id: <_bleak_winrt_Windows_Devices_Bluetooth.BluetoothDeviceId object at 0x000001C72B5A3C90>, error: BluetoothError.SUCCESS, status: GattSessionStatus.CLOSED
2023-01-31 17:48:54,155 bleak.backends.winrt.client DEBUG: closing requester
DEBUG:bleak.backends.winrt.client:closing requester
2023-01-31 17:48:54,714 bleak.backends.winrt.client DEBUG: session_status_changed_event_handler: id: <_bleak_winrt_Windows_Devices_Bluetooth.BluetoothDeviceId object at 0x000001C72B5A3910>, error: BluetoothError.SUCCESS, status: GattSessionStatus.CLOSED
DEBUG:bleak.backends.winrt.client:session_status_changed_event_handler: id: <_bleak_winrt_Windows_Devices_Bluetooth.BluetoothDeviceId object at 0x000001C72B5A3910>, error: BluetoothError.SUCCESS, status: GattSessionStatus.CLOSED
2023-01-31 17:48:54,714 bleak.backends.winrt.client DEBUG: session_status_changed_event_handler: id: <_bleak_winrt_Windows_Devices_Bluetooth.BluetoothDeviceId object at 0x000001C72B5A3DF0>, error: BluetoothError.SUCCESS, status: GattSessionStatus.ACTIVE
DEBUG:bleak.backends.winrt.client:session_status_changed_event_handler: id: <_bleak_winrt_Windows_Devices_Bluetooth.BluetoothDeviceId object at 0x000001C72B5A3DF0>, error: BluetoothError.SUCCESS, status: GattSessionStatus.ACTIVE
2023-01-31 17:48:54,714 bleak.backends.winrt.client DEBUG: session_status_changed_event_handler: id: <_bleak_winrt_Windows_Devices_Bluetooth.BluetoothDeviceId object at 0x000001C72B5A3F50>, error: BluetoothError.SUCCESS, status: GattSessionStatus.CLOSED
DEBUG:bleak.backends.winrt.client:session_status_changed_event_handler: id: <_bleak_winrt_Windows_Devices_Bluetooth.BluetoothDeviceId object at 0x000001C72B5A3F50>, error: BluetoothError.SUCCESS, status: GattSessionStatus.CLOSED
2023-01-31 17:48:54,714 bleak.backends.winrt.client DEBUG: closing session
DEBUG:bleak.backends.winrt.client:closing session
2023-01-31 17:48:54,714 bleak.backends.winrt.client DEBUG: session_status_changed_event_handler: id: <_bleak_winrt_Windows_Devices_Bluetooth.BluetoothDeviceId object at 0x000001C72B65C1D0>, error: BluetoothError.SUCCESS, status: GattSessionStatus.ACTIVE
DEBUG:bleak.backends.winrt.client:session_status_changed_event_handler: id: <_bleak_winrt_Windows_Devices_Bluetooth.BluetoothDeviceId object at 0x000001C72B65C1D0>, error: BluetoothError.SUCCESS, status: GattSessionStatus.ACTIVE
Traceback (most recent call last):
  File "C:\projects\esp32\repo\analyzer\src\analyzer.py", line 214, in <module>
    probe = main_event_loop.run_until_complete(connect_to_probe())
  File "C:\Users\user\AppData\Local\Programs\Python\Python310\lib\asyncio\base_events.py", line 646, in run_until_complete
    return future.result()
  File "C:\projects\esp32\repo\analyzer\src\analyzer.py", line 200, in connect_to_probe
    if not await probe.connect():
  File "C:\projects\esp32\repo\analyzer\src\probe.py", line 105, in connect
    await self.__client.connect(timeout=timeout)
  File "C:\Users\user\AppData\Local\Programs\Python\Python310\lib\site-packages\bleak\__init__.py", line 471, in connect
    return await self._backend.connect(**kwargs)
  File "C:\Users\user\AppData\Local\Programs\Python\Python310\lib\site-packages\bleak\backends\winrt\client.py", line 413, in connect
    self.services = get_services_task.result()
  File "C:\Users\user\AppData\Local\Programs\Python\Python310\lib\site-packages\bleak\backends\winrt\client.py", line 643, in get_services
    services: Sequence[GattDeviceService] = _ensure_success(
  File "C:\Users\user\AppData\Local\Programs\Python\Python310\lib\site-packages\bleak\backends\winrt\client.py", line 120, in _ensure_success
    raise BleakError(f"{fail_msg}: Unreachable")
bleak.exc.BleakError: Could not get GATT services: Unreachable

C:\projects\esp32\repo\analyzer\src>

wrieshark_bleak_patch_connect.zip

@dlech
Copy link
Collaborator Author

dlech commented Feb 1, 2023

Windows is never initiating the connection (we should CONNECT_REQ in the logs). I would suggest playing around with Windows-specific service caching options or try a different Bluetooth adapter.

It would be helpful if you could share the adapter info as well in case this turns out to be one of the many problematic adapters on Windows. Run the following in PowerShell:

wget https://github.com/Microsoft/busiotools/raw/master/bluetooth/tracing/GetBluetoothRadioInfo.ps1 -UseBasicParsing | iex

@zapta
Copy link

zapta commented Feb 1, 2023 

PS C:\WINDOWS\system32> wget https://github.com/Microsoft/busiotools/raw/master/bluetooth/tracing/GetBluetoothRadioInfo.ps1 -UseBasicParsing | iex                                                                                              

InstanceId        : USB\VID_8087&PID_0029\6&195F3125&0&2
MAC               : DC41A9D9332E
DriverDescription : Intel(R) Wireless Bluetooth(R)
DriverVersion     : 21.50.1.1
ErrorRecovery     : None
ScoType           : Unknown

InstanceId        : USB\VID_8087&PID_0A2A\6&195F3125&0&2
MAC               : 70CF499EC392
DriverDescription : Intel(R) Wireless Bluetooth(R)
DriverVersion     : 20.100.10.7
ErrorRecovery     : None
ScoType           : Unknown

@zapta
Copy link

zapta commented Feb 6, 2023

@dlech, anything that can be done regarding the connection part? I tried to debug it but got into calls to code with no python source code.

If it's OK, I can mail you a couple of devices that don't respond to SCAN REQ.

@dlech
Copy link
Collaborator Author

dlech commented Feb 6, 2023

The connecting issue is most likely due to the Bluetooth chip/driver.

Happy to try it locally if you want to send me something. You can find my email in my github profile.

@zapta
Copy link

zapta commented Feb 9, 2023

Thanks @dlech, I ordered new identical boards and they don't reproduce the issue. I will try to identify the differences (efuses?) and then mail you the one that doesn't respond to SPAN_REQ.

dlech added a commit that referenced this issue Feb 18, 2023
@dlech
winrt/scanner: drop waiting for matching scan rsp
a5f8418 
This removes the logic that skips the detection callback when expecting
a scan response. It is valid for devices to broadcast ADV_IND but not
respond to a SCAN_REQ (there is no flag that means connectable but not
scannable so ADV_IND is the only choice in this case).

Fixes: #1211
@dlech dlech mentioned this issue Feb 18, 2023
Merged
dlech added a commit that referenced this issue Feb 18, 2023
@dlech
winrt/scanner: drop waiting for matching scan rsp
ea7f964 
This removes the logic that skips the detection callback when expecting
a scan response. It is valid for devices to broadcast ADV_IND but not
respond to a SCAN_REQ (there is no flag that means connectable but not
scannable so ADV_IND is the only choice in this case).

Fixes: #1211
This was referenced Mar 15, 2023
Closed
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
Backend: WinRT Issues or PRs relating to the WinRT backend bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

winrt/scanner: drop waiting for matching scan rsp hbldh/bleak
2 participants
@dlech @zapta