search

hbldh / bleak

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

Device with address XXX was not found. It may have been removed from BlueZ when scanning stopped. #1176

Closed jeremyherbert closed 1 year ago

jeremyherbert commented 1 year ago

Description

I am trying to connect to a xiaomi mijia device running this custom firmware: https://github.com/pvvx/ATC_MiThermometer - I have multiple devices and am able to connect to all devices fine with bluetoothctl, but in bleak only some devices can connect. For the non-working devices I otherwise get the error:

bleak.exc.BleakDeviceNotFoundError: Device with address <some address> was not found. It may have been removed from BlueZ when scanning stopped.

I have changed the bluez autoconnect interval to 22 seconds. Although I am using a Nordic Semi USB-HCI BLE adapter (using Zephyr), I have tried this also on a raspberry pi 4 using the native BLE device and it has the same behaviour.

What I Did

Connecting to the device using bluetoothctl works fine using connect A4:C1:38:C5:62:B4.

In bleak, I am just trying to connect and enumerate the services on the device. I am using this script:

import asyncio
from bleak import BleakScanner, BleakClient

import sys
import logging

logging.basicConfig(stream=sys.stdout, level=logging.DEBUG)

# note:
#   The default configuration of the devices is not connectable by the bluetooth HCI interface in linux.
#   Use a tool such as https://gist.github.com/mironovdm/cb7f47e8d898e9a3977fc888d990e8a9 to increase the
#       default HCI timeout and the devices will be connectable.

async def main():
    devices = await BleakScanner.discover(timeout=10)
    for d in devices:
        print(d)
        print(d.rssi)
        if d.name.startswith("ATC_C562B4"):
            print("Connecting to", d)
            client = BleakClient(d, timeout=30)
            try:
                await client.connect()
                print("connected!")

                for service in client.services:
                    for char in service.characteristics:
                        print(char)
            finally:
                print("Disconnecting from", d)
                await client.disconnect()

            break

asyncio.run(main())

This is the output from the script (the client.connect line fails immediately, not after 30 seconds):

...
DEBUG:bleak.backends.bluezdbus.manager:received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_A4_C1_38_C5_62_B4', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.Device1': {'Address': <dbus_fast.signature.Variant ('s', A4:C1:38:C5:62:B4)>, 'AddressType': <dbus_fast.signature.Variant ('s', public)>, 'Name': <dbus_fast.signature.Variant ('s', ATC_C562B4)>, 'Alias': <dbus_fast.signature.Variant ('s', ATC_C562B4)>, 'Paired': <dbus_fast.signature.Variant ('b', False)>, 'Trusted': <dbus_fast.signature.Variant ('b', False)>, 'Blocked': <dbus_fast.signature.Variant ('b', False)>, 'LegacyPairing': <dbus_fast.signature.Variant ('b', False)>, 'RSSI': <dbus_fast.signature.Variant ('n', -55)>, 'Connected': <dbus_fast.signature.Variant ('b', False)>, 'UUIDs': <dbus_fast.signature.Variant ('as', [])>, 'Adapter': <dbus_fast.signature.Variant ('o', /org/bluez/hci0)>, 'ServiceData': <dbus_fast.signature.Variant ('a{sv}', {'0000181a-0000-1000-8000-00805f9b34fb': <dbus_fast.signature.Variant ('ay', bytearray(b'\xb4b\xc58\xc1\xa4\x90\t\xb4\x15\xbf\x0bYM\x05'))>})>, 'ServicesResolved': <dbus_fast.signature.Variant ('b', False)>}, 'org.freedesktop.DBus.Properties': {}}]
DEBUG:bleak.backends.bluezdbus.manager:received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_A4_C1_38_C5_62_B4): ['org.bluez.Device1', {'RSSI': <dbus_fast.signature.Variant ('n', -51)>, 'ServiceData': <dbus_fast.signature.Variant ('a{sv}', {'0000181a-0000-1000-8000-00805f9b34fb': <dbus_fast.signature.Variant ('ay', bytearray(b'\xb4b\xc58\xc1\xa4\x90\t\xbf\x15\xbe\x0bYO\x05'))>})>}, []]
DEBUG:bleak.backends.bluezdbus.manager:received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_A4_C1_38_C5_62_B4): ['org.bluez.Device1', {'RSSI': <dbus_fast.signature.Variant ('n', -60)>, 'ServiceData': <dbus_fast.signature.Variant ('a{sv}', {'0000181a-0000-1000-8000-00805f9b34fb': <dbus_fast.signature.Variant ('ay', bytearray(b'\xb4b\xc58\xc1\xa4\x91\t\xb3\x15\xbf\x0bYN\x05'))>})>}, []]
DEBUG:bleak.backends.bluezdbus.manager:received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_A4_C1_38_C5_62_B4): ['org.bluez.Device1', {}, ['RSSI']]
DEBUG:bleak.backends.bluezdbus.manager:received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_A4_C1_38_C5_62_B4', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
DEBUG:bleak.backends.bluezdbus.manager:received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', False)>}, []]
A4:C1:38:C5:62:B4: ATC_C562B4
-55
Connecting to A4:C1:38:C5:62:B4: ATC_C562B4
DEBUG:bleak.backends.bluezdbus.client:Connecting to device @ A4:C1:38:C5:62:B4
DEBUG:bleak.backends.bluezdbus.client:Connecting to BlueZ path /org/bluez/hci0/dev_A4_C1_38_C5_62_B4
DEBUG:bleak.backends.bluezdbus.client:_cleanup_all(/org/bluez/hci0/dev_A4_C1_38_C5_62_B4)
Disconnecting from A4:C1:38:C5:62:B4: ATC_C562B4
DEBUG:bleak.backends.bluezdbus.client:Disconnecting (/org/bluez/hci0/dev_A4_C1_38_C5_62_B4)
DEBUG:bleak.backends.bluezdbus.client:already disconnected (/org/bluez/hci0/dev_A4_C1_38_C5_62_B4)
Traceback (most recent call last):
  File "/home/jeremy/PycharmProjects/atc_provision/atc_provision.py", line 36, in <module>
    asyncio.run(main())
  File "/usr/lib/python3.8/asyncio/runners.py", line 44, in run
    return loop.run_until_complete(main)
  File "/usr/lib/python3.8/asyncio/base_events.py", line 616, in run_until_complete
    return future.result()
  File "/home/jeremy/PycharmProjects/atc_provision/atc_provision.py", line 24, in main
    await client.connect()
  File "/home/jeremy/PycharmProjects/atc_provision/venv/lib/python3.8/site-packages/bleak/__init__.py", line 471, in connect
    return await self._backend.connect(**kwargs)
  File "/home/jeremy/PycharmProjects/atc_provision/venv/lib/python3.8/site-packages/bleak/backends/bluezdbus/client.py", line 185, in connect
    raise BleakDeviceNotFoundError(
bleak.exc.BleakDeviceNotFoundError: Device with address A4:C1:38:C5:62:B4 was not found. It may have been removed from BlueZ when scanning stopped.

Logs

I have bluetoothctl running in the background so I can see the scan results. While bleak is scanning, it shows what you would expect (I have truncated the results):

[NEW] Device A4:C1:38:C5:62:B4 ATC_C562B4
...
[CHG] Device A4:C1:38:C5:62:B4 RSSI: -55
[CHG] Device A4:C1:38:C5:62:B4 ServiceData Key: 0000181a-0000-1000-8000-00805f9b34fb
[CHG] Device A4:C1:38:C5:62:B4 ServiceData Value:
  b4 62 c5 38 c1 a4 7c 09 05 16 be 0b 59 92 05     .b.8..|.....Y.. 
...

However, as soon as the scan stops, it prints the following:

[CHG] Device A4:C1:38:C5:62:B4 RSSI is nil
[DEL] Device A4:C1:38:C5:62:B4 ATC_C562B4

in the bluetoothd log, I see the following when the scan is stopped:

Dec 19 20:16:20 ubuntu bluetoothd[864]: src/adapter.c:stop_discovery() sender :1.136
Dec 19 20:16:20 ubuntu bluetoothd[864]: src/adapter.c:stop_discovery_complete() status 0x00
Dec 19 20:16:20 ubuntu bluetoothd[864]: src/adapter.c:trigger_passive_scanning()
Dec 19 20:16:20 ubuntu bluetoothd[864]: src/adapter.c:discovery_remove() owner :1.136
Dec 19 20:16:20 ubuntu bluetoothd[864]: src/device.c:device_set_rssi_with_delta() rssi 0
Dec 19 20:16:20 ubuntu bluetoothd[864]: src/device.c:device_remove() Removing device /org/bluez/hci0/dev_A4_C1_38_C5_62_B4
Dec 19 20:16:20 ubuntu bluetoothd[864]: src/device.c:btd_device_unref() Freeing device /org/bluez/hci0/dev_A4_C1_38_C5_62_B4
Dec 19 20:16:20 ubuntu bluetoothd[864]: src/device.c:device_free() 0x55af68eeaa60

In btmon this is what shows up when the scan is occurring:

> HCI Event: LE Meta Event (0x3e) plen 31                                                                                                                                                                              #322 [hci0] 15.804983
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Connectable undirected - ADV_IND (0x00)
        Address type: Public (0x00)
        Address: A4:C1:38:C5:62:B4 (Telink Semiconductor (Taipei) Co. Ltd.)
        Data length: 19
        Service Data (UUID 0x181a): b462c538c1a48a09c215bf0b590405
        RSSI: -59 dBm (0xc5)
> HCI Event: LE Meta Event (0x3e) plen 24                                                                                                                                                                              #323 [hci0] 15.805938
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Scan response - SCAN_RSP (0x04)
        Address type: Public (0x00)
        Address: A4:C1:38:C5:62:B4 (Telink Semiconductor (Taipei) Co. Ltd.)
        Data length: 12
        Name (complete): ATC_C562B4
        RSSI: -59 dBm (0xc5)
@ MGMT Event: Device Found (0x0012) plen 45                                                                                                                                                                        {0x0002} [hci0] 15.805968
        LE Address: A4:C1:38:C5:62:B4 (Telink Semiconductor (Taipei) Co. Ltd.)
        RSSI: -59 dBm (0xc5)
        Flags: 0x00000000
        Data length: 31
        Service Data (UUID 0x181a): b462c538c1a48a09c215bf0b590405
        Name (complete): ATC_C562B4
@ MGMT Event: Device Found (0x0012) plen 45                                                                                                                                                                        {0x0001} [hci0] 15.805968
        LE Address: A4:C1:38:C5:62:B4 (Telink Semiconductor (Taipei) Co. Ltd.)
        RSSI: -59 dBm (0xc5)
        Flags: 0x00000000
        Data length: 31
        Service Data (UUID 0x181a): b462c538c1a48a09c215bf0b590405
        Name (complete): ATC_C562B4

There isn't anything interesting when the scan terminates however (other than the fact that the connection is never attempted):

@ MGMT Command: Stop Discovery (0x0024) plen 1                                                                                                                                                                     {0x0001} [hci0] 16.564651
        Address type: 0x06
          LE Public
          LE Random
< HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2                                                                                                                                                                 #347 [hci0] 16.564742
        Scanning: Disabled (0x00)
        Filter duplicates: Disabled (0x00)
> HCI Event: Command Complete (0x0e) plen 4                                                                                                                                                                            #348 [hci0] 16.566878
      LE Set Scan Enable (0x08|0x000c) ncmd 1
        Status: Success (0x00)
@ MGMT Event: Command Complete (0x0001) plen 4                                                                                                                                                                     {0x0001} [hci0] 16.567017
      Stop Discovery (0x0024) plen 1
        Status: Success (0x00)
        Address type: 0x06
          LE Public
          LE Random
dlech commented 1 year ago

If you use BleakScanner.find_by_name() instead of BleakScanner.discover() it will return as soon as a device is found and have a better chance of connecting before the device disappears.

jeremyherbert commented 1 year ago

I have tried that with no luck unfortunately. I have also tried Ubuntu 22.04 with bluez 5.64 and I get the same result. Interestingly, I have tried adding TemporaryTimeout=30 to the bluetooth configuration and it doesn't keep the devices alive...

jeremyherbert commented 1 year ago

I worked out what this was after digging through the source code of bluez. The device is deleted immediately if it does not advertise the connectable flag in the advertising data (and indeed this device was not setting it).

jeremyherbert commented 1 year ago

See also: https://github.com/bluez/bluez/issues/445

dlech commented 1 year ago

Glad you figured it out and thanks for following up.

jeremyherbert commented 1 year ago

In case anyone finds this later, the problem is fixed in bluez 5.65 and later.

matzrh commented 1 year ago

@jeremyherbert Would you mind pointing me to a process to upgrade to bluez 5.65 (or 5.66) from 5.55? I am using bullseye Raspbian and 5.66 from debian bookworm requires a newer libc6 library and I do not want to upgrade that 'unofficially', as I am afraid it could break my system or generate all sorts of other dependency issues.

I tried to download the bluez source code (5.55-3.1+rpt2) and apply your patch (not the one from 5.66, but your original one). However, I am dispairing trying to compile it then with dpkg-buildpackage. Do you see an easier way? Or did you upgrade the whole OS when going from 5.55 to 5.65?

matzrh commented 1 year ago

Ok. I am one step further. I could compile and install, but I still get the same error, as before, that the device is not found. I will dig into the patch a bit more, tomorrow. It could not be applied 100%. A pointer for others: I needed to install the following to make bluez compile

sudo apt install libglib2.0-dev libdbus-1-dev elfutils libudev-dev libical-dev libreadline-dev libdw-dev libjson-c-dev libasound2-dev
libell-dev

There were some differences in the patch...will get back to it tomorrow, but probably getting there...

jeremyherbert commented 1 year ago

Sorry, I just did it on Ubuntu 20.04 / 22.04 and the version from the git repo worked fine as-is. I have not tried on rpi.

In terms of my own patch, I did the following on Ubuntu (I guess it should be the same on debian?)

sudo apt install libbluetooth-dev
sudo apt build-dep bluez
sudo apt build-dep linux linux-image-$(uname -r)
sudo apt source bluez

<enter bluez dir and edit bluez source code>

dpkg-buildpackage -rfakeroot -uc -b
sudo dpkg -i bluez_<the version you built>.deb
matzrh commented 1 year ago

Just an update in case someone else gets here to find a solution. I was not successful in adapting the code from 5.55. I tried to implement the official patch from 5.64 to 5.65 (https://git.kernel.org/pub/scm/bluetooth/bluez.git/commit/?id=3fb4e1cca2eaddc413d1ebed9d862084351efdbc) I could only do this only partially, as there is almost 2 years between 5.55 and 5.65 and the changes have been substantial. It did not change anything after I installed it to my system. I ended up using pygatt, instead, which also has issues (gatttool is deprecated), but for the time being, I need to rely on it, until a bullseye testing package with 5.65 or higher comes out. Thanks for everyone here for the support!

r-bt commented 1 year ago

I was able to upgrade from bluez 5.55 to 5.66 on Raspberry Pi OS Bullseye by following the guide at https://gist.github.com/israveri/2d3fef451b2e0ce89f7290eda6366b14 and just changing the version of bluez that I downloaded

zendainc commented 6 months ago

I was able to upgrade from bluez 5.55 to 5.66 on Raspberry Pi OS Bullseye by following the guide at https://gist.github.com/israveri/2d3fef451b2e0ce89f7290eda6366b14 and just changing the version of bluez that I downloaded

Since that gist is no longer available, here are the steps to upgrade from Bluez 5.55 to 5.66 on Raspberry Pi OS Bullseye. This might be useful for anyone else who stumbles across it while looking for an answer, like I did. This is based on a version of the gist from Wayback Machine and adds a missing dependency.

# Install dependancies
sudo apt update -y
sudo apt install libdbus-1-dev libglib2.0-dev libudev-dev libical-dev libreadline-dev -y
sudo apt install -y python3-docutils

# Download and extract Bluez
wget www.kernel.org/pub/linux/bluetooth/bluez-5.66.tar.xz
tar xvf bluez-5.66.tar.xz && cd bluez-5.66

# Build and Install
./configure --prefix=/usr --mandir=/usr/share/man --sysconfdir=/etc --localstatedir=/var --enable-experimental 
make -j4
sudo make install

# Reboot Raspberry Pi
sudo reboot

# Check current version
bluetooth-ctl -v
amirhb29 commented 5 months ago

I built and installed a newer bluez (version 5.66) on my Bullseye Debian system. Still receiving the same error.

dlech commented 5 months ago

This issue has been closed for a long time. So if anyone is getting the same error and would like help, I would suggest starting a new discussion thread and include as much logs as possible (see troubleshooting page in docs).