search

hbldh / bleak

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

Service not detected by Bleak #1171

Closed bdr99 closed 1 year ago

bdr99 commented 1 year ago

Description

I have a device (smart scale) which exposes 3 services: device information (0x180A), battery service (0x180F), and a custom vendor-defined service (0xFFF0). The issue I'm having is that Bleak can only see the first two, and the vendor-defined service doesn't show up. When I check a tool like nRF Connect on my phone, I can see all 3 services. Also and the vendor mobile app for the smart scale is able to connect to the 0xFFF0 service and receive data from the device through it.

I'd greatly appreciate any assistance in finding the reason why Bleak cannot see/connect to this service. Please let me know if there is any other info I can provide.

Here is the output when running examples/service_explorer.py:

2022-12-11 21:21:10,169 __main__ INFO: starting scan...
2022-12-11 21:21:14,636 __main__ INFO: connecting to device...
2022-12-11 21:21:16,150 __main__ INFO: connected
2022-12-11 21:21:16,150 __main__ INFO: [Service] 0000180a-0000-1000-8000-00805f9b34fb (Handle: 1): Device Information
2022-12-11 21:21:16,309 __main__ INFO:   [Characteristic] 00002a27-0000-1000-8000-00805f9b34fb (Handle: 2): Hardware Revision String (read), Value: bytearray(b'1.2')
2022-12-11 21:21:16,489 __main__ INFO:   [Characteristic] 00002a29-0000-1000-8000-00805f9b34fb (Handle: 6): Manufacturer Name String (read), Value: bytearray(b'eufy')
2022-12-11 21:21:16,579 __main__ INFO:   [Characteristic] 00002a25-0000-1000-8000-00805f9b34fb (Handle: 10): Serial Number String (read), Value: bytearray(b'0002LF1101100001')
2022-12-11 21:21:16,668 __main__ INFO:   [Characteristic] 00002a26-0000-1000-8000-00805f9b34fb (Handle: 4): Firmware Revision String (read), Value: bytearray(b'106.112.106')
2022-12-11 21:21:16,758 __main__ INFO:   [Characteristic] 00002a24-0000-1000-8000-00805f9b34fb (Handle: 8): Model Number String (read), Value: bytearray(b'T9148')
2022-12-11 21:21:16,758 __main__ INFO: [Service] 0000180f-0000-1000-8000-00805f9b34fb (Handle: 12): Battery Service
2022-12-11 21:21:16,848 __main__ INFO:   [Characteristic] 00002a19-0000-1000-8000-00805f9b34fb (Handle: 13): Battery Level (read,notify), Value: bytearray(b'd')
2022-12-11 21:21:16,938 __main__ INFO:     [Descriptor] 00002902-0000-1000-8000-00805f9b34fb (Handle: 15): Client Characteristic Configuration, Value: bytearray(b'\x01\x00')
2022-12-11 21:21:16,938 __main__ INFO: disconnecting...
2022-12-11 21:21:19,639 __main__ INFO: disconnected

Here is a screenshot from nRF Connect showing all 3 services: Screenshot_20221211-224659

What I Did

Here is the script I wrote to try to connect to the 0xFFF0 service (which has an 0xFFF4 notify characteristic):

import asyncio
import binascii

from bleak import BleakClient, BleakGATTCharacteristic

SCALE_MAC = "CF:E6:08:09:01:02"
WEIGHT_CHARACTERISTIC_UUID = "0000fff4-0000-1000-8000-00805f9b34fb"

def notification_handler(characteristic: BleakGATTCharacteristic, data: bytearray):
    print(f"{characteristic.description}: {binascii.hexlify(data)}")

async def main():
    async with BleakClient(SCALE_MAC) as client:
        print(f"Connected: {client.is_connected}")

        await client.start_notify(WEIGHT_CHARACTERISTIC_UUID, notification_handler)
        await asyncio.sleep(60.0)
        await client.stop_notify(WEIGHT_CHARACTERISTIC_UUID)  

asyncio.run(main())

Here is the output I get when I run this script:

Connected: True
Traceback (most recent call last):
  File "/home/brandon/repos/bttest/bttest/main.py", line 29, in <module>
    asyncio.run(main())
  File "/usr/lib/python3.10/asyncio/runners.py", line 44, in run
    return loop.run_until_complete(main)
  File "/usr/lib/python3.10/asyncio/base_events.py", line 646, in run_until_complete
    return future.result()
  File "/home/brandon/repos/bttest/bttest/main.py", line 23, in main
    await client.start_notify(WEIGHT_CHARACTERISTIC_UUID, notification_handler)
  File "/home/brandon/.cache/pypoetry/virtualenvs/bttest-OGrXrS0o-py3.10/lib/python3.10/site-packages/bleak/__init__.py", line 639, in start_notify
    raise BleakError(f"Characteristic {char_specifier} not found!")
bleak.exc.BleakError: Characteristic 0000fff4-0000-1000-8000-00805f9b34fb not found!

Logs

Here are the debug logs from running the above script. bleak_debug.log

dlech commented 1 year ago

I would try removing the device from BlueZ to ensure that this is not a caching issues and also log packets with Wireshark to ensure the device enumeration is actually working correctly over the air.

bdr99 commented 1 year ago

@dlech Thanks for the reply!

I tried removing the device from BlueZ using bluetoothctl remove CF:E6:08:09:01:02 but unfortunately that didn't help, so I don't think it's a caching issue.

I used btmon to capture the traffic and view it in WireShark, and I do see the FFF0 service in the capture. So somehow it is getting lost in between. In this test, client.services only contained the first two services. Do you have any other ideas on what could be happening here?

Here is the WireShark capture: smart_scale_missing_service.log

image

dlech commented 1 year ago

It looks like the info is getting from the device to BlueZ. So, I'm guessing there is a bug in BlueZ maybe? You could try running bluetoothd with the --debug option to see if it gives any useful information.

bdr99 commented 1 year ago

Would you mind explaining how exactly to do that? When I try to run sudo bluetoothd --debug, I get an error saying D-Bus setup failed: Name already in use.

Also, as a side note, I tried running bluetoothctl scan le, followed by bluetoothctl connect CF:E6:08:09:01:02, and finally bluetoothctl info CF:E6:08:09:01:02. This was the output:

Device CF:E6:08:09:01:02 (public)
        Name: eufy T9148
        Alias: eufy T9148
        Paired: no
        Trusted: no
        Blocked: no
        Connected: yes
        LegacyPairing: no
        UUID: Device Information        (0000180a-0000-1000-8000-00805f9b34fb)
        UUID: Battery Service           (0000180f-0000-1000-8000-00805f9b34fb)
        ManufacturerData Key: 0xff5f
        ManufacturerData Value:
  cf e6 08 09 01 02 cf 00 00 3a 02 00 00 00 01 01  .........:......
  00 00 f7                                         ...
        Battery Percentage: 0x5f (95)

So, the service is not showing in bluetoothctl either. Does this help narrow down the problem?

dlech commented 1 year ago

Would you mind explaining how exactly to do that?

sudo systemctl stop bluetooth.service
sudo bluetooth --debug --nodetach

So, the service is not showing in bluetoothctl either. Does this help narrow down the problem?

it indicates that it is indeed a BlueZ problem, not a Bleak problem.

bdr99 commented 1 year ago

Well, this isn't good. I ran bluetoothd in debug mode like you explained, and it segfaulted:

bluetoothd[5518]: src/device.c:device_connect_le() Connection attempt to: CF:E6:08:09:01:02
bluetoothd[5518]: src/adapter.c:connected_callback() hci0 device CF:E6:08:09:01:02 connected eir_len 30
bluetoothd[5518]: src/device.c:att_connect_cb() connect to CF:E6:08:09:01:02: Function not implemented (38)
bluetoothd[5518]: src/adapter.c:dev_disconnected() Device CF:E6:08:09:01:02 disconnected, reason 0
bluetoothd[5518]: src/adapter.c:adapter_remove_connection()
bluetoothd[5518]: plugins/policy.c:disconnect_cb() reason 0
bluetoothd[5518]: src/adapter.c:bonding_attempt_complete() hci0 bdaddr CF:E6:08:09:01:02 type 1 status 0xe
bluetoothd[5518]: src/device.c:device_bonding_complete() bonding (nil) status 0x0e
bluetoothd[5518]: src/device.c:btd_device_set_temporary() temporary 1
bluetoothd[5518]: src/device.c:device_bonding_failed() status 14
bluetoothd[5518]: src/adapter.c:resume_discovery()
bluetoothd[5518]: src/device.c:btd_device_set_temporary() temporary 0
bluetoothd[5518]: src/device.c:device_connect_le() Connection attempt to: CF:E6:08:09:01:02
bluetoothd[5518]: src/adapter.c:connected_callback() hci0 device CF:E6:08:09:01:02 connected eir_len 30
bluetoothd[5518]: src/device.c:att_connect_cb() connect to CF:E6:08:09:01:02: Function not implemented (38)
bluetoothd[5518]: src/adapter.c:dev_disconnected() Device CF:E6:08:09:01:02 disconnected, reason 0
bluetoothd[5518]: src/adapter.c:adapter_remove_connection()
bluetoothd[5518]: plugins/policy.c:disconnect_cb() reason 0
bluetoothd[5518]: src/adapter.c:bonding_attempt_complete() hci0 bdaddr CF:E6:08:09:01:02 type 1 status 0xe
bluetoothd[5518]: src/device.c:device_bonding_complete() bonding (nil) status 0x0e
bluetoothd[5518]: src/device.c:btd_device_set_temporary() temporary 1
bluetoothd[5518]: src/device.c:device_bonding_failed() status 14
bluetoothd[5518]: src/adapter.c:resume_discovery()
bluetoothd[5518]: src/device.c:device_remove() Removing device /org/bluez/hci0/dev_6A_A3_70_EE_49_91
bluetoothd[5518]: src/device.c:btd_device_unref() Freeing device /org/bluez/hci0/dev_6A_A3_70_EE_49_91
bluetoothd[5518]: src/device.c:device_free() 0x55d2e61346a0
bluetoothd[5518]: src/device.c:btd_device_set_temporary() temporary 0
bluetoothd[5518]: src/device.c:device_connect_le() Connection attempt to: CF:E6:08:09:01:02
bluetoothd[5518]: src/adapter.c:connected_callback() hci0 device CF:E6:08:09:01:02 connected eir_len 30
bluetoothd[5518]: attrib/gattrib.c:g_attrib_ref() 0x55d2e61256d0: g_attrib_ref=1
bluetoothd[5518]: src/device.c:load_gatt_db() Restoring CF:E6:08:09:01:02 gatt database from file
bluetoothd[5518]: src/device.c:load_gatt_db() No cache for CF:E6:08:09:01:02
bluetoothd[5518]: src/gatt-client.c:btd_gatt_client_connected() Device connected.
bluetoothd[5518]: src/device.c:gatt_debug() MTU exchange complete, with MTU: 128
bluetoothd[5518]: src/device.c:gatt_debug() Primary services found: 3
bluetoothd[5518]: src/device.c:gatt_debug() start: 0x0001, end: 0x000b, uuid: 0000180a-0000-1000-8000-00805f9b34fb
bluetoothd[5518]: src/device.c:gatt_debug() start: 0x000c, end: 0x000f, uuid: 0000180f-0000-1000-8000-00805f9b34fb
bluetoothd[5518]: src/device.c:gatt_debug() start: 0x0010, end: 0x0018, uuid: 0000fff0-0000-1000-8000-00805f9b34fb
bluetoothd[5518]: src/device.c:device_remove() Removing device /org/bluez/hci0/dev_C8_4A_3D_2E_CE_65
bluetoothd[5518]: src/device.c:btd_device_unref() Freeing device /org/bluez/hci0/dev_C8_4A_3D_2E_CE_65
bluetoothd[5518]: src/device.c:device_free() 0x55d2e6137500
bluetoothd[5518]: src/device.c:gatt_debug() Secondary services found: 3
bluetoothd[5518]: src/device.c:gatt_debug() start: 0x0001, end: 0x000b, uuid: 0000180a-0000-1000-8000-00805f9b34fb
bluetoothd[5518]: src/device.c:gatt_debug() start: 0x000c, end: 0x000f, uuid: 0000180f-0000-1000-8000-00805f9b34fb
bluetoothd[5518]: src/device.c:gatt_debug() start: 0x0010, end: 0x0018, uuid: 0000fff0-0000-1000-8000-00805f9b34fb
bluetoothd[5518]: src/device.c:gatt_debug() Characteristics found: 9
bluetoothd[5518]: src/device.c:gatt_debug() start: 0x0002, end: 0x0003, value: 0x0003, props: 0x02, uuid: 00002a27-0000-1
bluetoothd[5518]: src/device.c:gatt_debug() start: 0x0004, end: 0x0005, value: 0x0005, props: 0x02, uuid: 00002a26-0000-1
bluetoothd[5518]: src/device.c:gatt_debug() start: 0x0006, end: 0x0007, value: 0x0007, props: 0x02, uuid: 00002a29-0000-1
bluetoothd[5518]: src/device.c:gatt_debug() start: 0x0008, end: 0x0009, value: 0x0009, props: 0x02, uuid: 00002a24-0000-1
bluetoothd[5518]: src/device.c:gatt_debug() start: 0x000a, end: 0x000c, value: 0x000b, props: 0x02, uuid: 00002a25-0000-1
bluetoothd[5518]: src/device.c:gatt_debug() start: 0x000d, end: 0x0010, value: 0x000e, props: 0x12, uuid: 00002a19-0000-1
bluetoothd[5518]: src/device.c:gatt_debug() start: 0x0011, end: 0x0012, value: 0x0012, props: 0x08, uuid: 0000fff1-0000-1
bluetoothd[5518]: src/device.c:gatt_debug() start: 0x0013, end: 0x0015, value: 0x0014, props: 0x10, uuid: 0000fff2-0000-1
bluetoothd[5518]: src/device.c:gatt_debug() start: 0x0016, end: 0x0018, value: 0x0017, props: 0x10, uuid: 0000fff4-0000-1
bluetoothd[5518]: src/device.c:gatt_debug() service disappeared: start 0x0001 end 0x000b
bluetoothd[5518]: src/device.c:gatt_service_removed() start: 0x0001, end: 0x000b
[1]    5516 segmentation fault  sudo bluetoothd --debug --nodetach

I understand that this is not a Bleak issue, but I'd still be curious to hear if you are able to tell anything from the above log. Do you think the segfault would be the reason the service is missing from the list?

dlech commented 1 year ago

Since there are not timestamps in the log, so I can't tell when service disappeared happened. If there was a delay and it happened on disconnect, that seems right, if not, it could be a clue.

The device does seem to be misbehaving a bit in that it lists the same services as both primary and secondary services.

bdr99 commented 1 year ago

The service disappeared log happened immediately after the preceding entry, with no delay. In fact, sometimes it doesn't even happen at all, like in the below example:

bluetoothd[5978]: src/device.c:device_connect_le() Connection attempt to: CF:E6:08:09:01:02
bluetoothd[5978]: src/adapter.c:connected_callback() hci0 device CF:E6:08:09:01:02 connected eir_len 30
bluetoothd[5978]: attrib/gattrib.c:g_attrib_ref() 0x560c15e89c70: g_attrib_ref=1
bluetoothd[5978]: src/device.c:load_gatt_db() Restoring CF:E6:08:09:01:02 gatt database from file
bluetoothd[5978]: src/device.c:load_gatt_db() No cache for CF:E6:08:09:01:02
bluetoothd[5978]: src/gatt-client.c:btd_gatt_client_connected() Device connected.
bluetoothd[5978]: src/device.c:gatt_debug() MTU exchange complete, with MTU: 128
bluetoothd[5978]: src/device.c:gatt_debug() Primary services found: 3
bluetoothd[5978]: src/device.c:gatt_debug() start: 0x0001, end: 0x000b, uuid: 0000180a-0000-1000-8000-00805f9b34fb
bluetoothd[5978]: src/device.c:gatt_debug() start: 0x000c, end: 0x000f, uuid: 0000180f-0000-1000-8000-00805f9b34fb
bluetoothd[5978]: src/device.c:gatt_debug() start: 0x0010, end: 0x0018, uuid: 0000fff0-0000-1000-8000-00805f9b34fb
bluetoothd[5978]: src/device.c:gatt_debug() Secondary services found: 3
bluetoothd[5978]: src/device.c:gatt_debug() start: 0x0001, end: 0x000b, uuid: 0000180a-0000-1000-8000-00805f9b34fb
bluetoothd[5978]: src/device.c:gatt_debug() start: 0x000c, end: 0x000f, uuid: 0000180f-0000-1000-8000-00805f9b34fb
bluetoothd[5978]: src/device.c:gatt_debug() start: 0x0010, end: 0x0018, uuid: 0000fff0-0000-1000-8000-00805f9b34fb
bluetoothd[5978]: src/device.c:gatt_debug() Characteristics found: 9
bluetoothd[5978]: src/device.c:gatt_debug() start: 0x0002, end: 0x0003, value: 0x0003, props: 0x02, uuid: 00002a27-0000-1
bluetoothd[5978]: src/device.c:gatt_debug() start: 0x0004, end: 0x0005, value: 0x0005, props: 0x02, uuid: 00002a26-0000-1
bluetoothd[5978]: src/device.c:gatt_debug() start: 0x0006, end: 0x0007, value: 0x0007, props: 0x02, uuid: 00002a29-0000-1
bluetoothd[5978]: src/device.c:gatt_debug() start: 0x0008, end: 0x0009, value: 0x0009, props: 0x02, uuid: 00002a24-0000-1
bluetoothd[5978]: src/device.c:gatt_debug() start: 0x000a, end: 0x000c, value: 0x000b, props: 0x02, uuid: 00002a25-0000-1
bluetoothd[5978]: src/device.c:gatt_debug() start: 0x000d, end: 0x0010, value: 0x000e, props: 0x12, uuid: 00002a19-0000-1
bluetoothd[5978]: src/device.c:gatt_debug() start: 0x0011, end: 0x0012, value: 0x0012, props: 0x08, uuid: 0000fff1-0000-1
bluetoothd[5978]: src/device.c:gatt_debug() start: 0x0013, end: 0x0015, value: 0x0014, props: 0x10, uuid: 0000fff2-0000-1
bluetoothd[5978]: src/device.c:gatt_debug() start: 0x0016, end: 0x0018, value: 0x0017, props: 0x10, uuid: 0000fff4-0000-1
[1]    5976 segmentation fault  sudo bluetoothd --debug --nodetach
bdr99 commented 1 year ago

FYI I opened a BlueZ issue to track this segfault problem. https://github.com/bluez/bluez/issues/438

dlech commented 1 year ago

Cool. If you install the debug symbols package for BlueZ (bluez-dbgsym), it should give more information about where the crash is.

bdr99 commented 1 year ago

@dlech Good idea, but I don't see that package on my system. Are you sure that is the correct package name?

➜  ~ sudo apt install bluez-dbgsym
Reading package lists... Done
Building dependency tree... Done
Reading state information... Done
E: Unable to locate package bluez-dbgsym
dlech commented 1 year ago

I think you might have to add something in the /etc/apt/sources.list.d/ nowadays (the debug symbols packages are no longer in the main repository). https://wiki.ubuntu.com/Debug%20Symbol%20Packages

bdr99 commented 1 year ago

@dlech Thanks, that worked 🙂 I appreciate your help.

One last question... Is there any way to force Bleak to try to connect to a particular service/characteristic, even if it thinks it doesn't exist? That would allow me to work around this issue while I wait for a fix from BlueZ.

dlech commented 1 year ago

If the characteristic doesn't show up in BlueZ, then there is no way for Bleak to use it.

bdr99 commented 1 year ago

Closing this issue since the problem was fixed on the BlueZ side. https://github.com/bluez/bluez/issues/438