search

hbldh / bleak

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

bleak.exc.BleakDBusError #946

Open michapr opened 1 year ago

michapr commented 1 year ago

Description

Want to integrate eq3 thermostat and testing the connection. eq3cli --mac 00:1A:22:08:BF:D6

Scan was working, see the MAC address.

What I Did

Have placed the device about 2 meters from BT - USB stick, made scan, was working. (also tried bluetoothctl power off / bluetoothctl power on - with no changes in result)

 eq3cli --mac 00:1A:22:08:BF:D6
WARNING:bleak.backends.bluezdbus.client:Failed to cancel connection (/org/bluez/hci0/dev_00_1A_22_08_BF_D6):
WARNING:bleak.backends.bluezdbus.client:Failed to cancel connection (/org/bluez/hci0/dev_00_1A_22_08_BF_D6):
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/dist-packages/eq3bt/bleakconnection.py", line 51, in __enter__
    self._loop.run_until_complete(self._conn.connect())
  File "/usr/lib/python3.9/asyncio/base_events.py", line 642, in run_until_complete
    return future.result()
  File "/usr/local/lib/python3.9/dist-packages/bleak/backends/bluezdbus/client.py", line 167, in connect
    assert_reply(reply)
  File "/usr/local/lib/python3.9/dist-packages/bleak/backends/bluezdbus/utils.py", line 22, in assert_reply
    raise BleakDBusError(reply.error_name, reply.body)
bleak.exc.BleakDBusError: [org.bluez.Error.Failed] Disconnected early

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.9/dist-packages/eq3bt/bleakconnection.py", line 57, in __enter__
    self._loop.run_until_complete(self._conn.connect())
  File "/usr/lib/python3.9/asyncio/base_events.py", line 642, in run_until_complete
    return future.result()
  File "/usr/local/lib/python3.9/dist-packages/bleak/backends/bluezdbus/client.py", line 167, in connect
    assert_reply(reply)
  File "/usr/local/lib/python3.9/dist-packages/bleak/backends/bluezdbus/utils.py", line 22, in assert_reply
    raise BleakDBusError(reply.error_name, reply.body)
bleak.exc.BleakDBusError: [org.bluez.Error.Failed] Disconnected early

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

Traceback (most recent call last):
  File "/usr/local/bin/eq3cli", line 8, in <module>
    sys.exit(cli())
  File "/usr/local/lib/python3.9/dist-packages/click/core.py", line 1130, in __call__
    return self.main(*args, **kwargs)
  File "/usr/local/lib/python3.9/dist-packages/click/core.py", line 1055, in main
    rv = self.invoke(ctx)
  File "/usr/local/lib/python3.9/dist-packages/click/core.py", line 1635, in invoke
    rv = super().invoke(ctx)
  File "/usr/local/lib/python3.9/dist-packages/click/core.py", line 1404, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/usr/local/lib/python3.9/dist-packages/click/core.py", line 760, in invoke
    return __callback(*args, **kwargs)
  File "/usr/local/lib/python3.9/dist-packages/click/decorators.py", line 26, in new_func
    return f(get_current_context(), *args, **kwargs)
  File "/usr/local/lib/python3.9/dist-packages/eq3bt/eq3cli.py", line 47, in cli
    thermostat.update()
  File "/usr/local/lib/python3.9/dist-packages/eq3bt/eq3btsmart.py", line 217, in update
    self._conn.make_request(PROP_WRITE_HANDLE, value)
  File "/usr/local/lib/python3.9/dist-packages/eq3bt/bleakconnection.py", line 106, in make_request
    with self:
  File "/usr/local/lib/python3.9/dist-packages/eq3bt/bleakconnection.py", line 60, in __enter__
    raise BackendException(
eq3bt.BackendException: unable to connect to device using bleak

Any idea what can be the reason? (was working before with old Home Assistant installation at same Raspberry with same adapter - but software was updated)

Thanks!

TechHummel commented 1 year ago

Hi and thank you for opening an issue. I also face issues when trying to use bleak to connect to the eq3 thermostats. 

import asyncio
from bleak import BleakClient

mac = "x"

async def on_notification(handle, data):
    """Handle Callback from a Bluetooth (GATT) request."""
    # The notification handles are off-by-one compared to gattlib and bluepy
    pass

async def main(address):
    client = BleakClient(address)
    try:
        await client.connect(timeout=30.0)
        print("Connected succesful!")
        # 0x421 - 1, copied from eq3bt
        await client.start_notify(0x421 - 1, on_notification)
    finally:
        await client.disconnect()
        print("Disconnected!")

asyncio.run(main(mac))

Windows 11

2022-08-18 22:50:28,830 bleak.backends.winrt.scanner DEBUG: Received 00:1A:22:06:1B:EB: Unknown.
2022-08-18 22:50:28,835 bleak.backends.winrt.scanner DEBUG: 5 devices found. Watcher status: 3.
2022-08-18 22:50:28,835 bleak.backends.winrt.client DEBUG: Connecting to BLE device @ 00:1A:22:06:1B:EB
2022-08-18 22:50:33,808 bleak.backends.winrt.client DEBUG: session_status_changed_event_handler: id: <_bleak_winrt_Windows_Devices_Bluetooth.BluetoothDeviceId object at 0x00000217E39FACF0>, error: 0, status: 1
2022-08-18 22:50:33,810 bleak.backends.winrt.client DEBUG: Get Services...
2022-08-18 22:50:36,748 bleak.backends.winrt.client INFO: Services resolved for BleakClientWinRT (00:1A:22:06:1B:EB)
Connected succesful!
2022-08-18 22:50:36,783 bleak.backends.winrt.client DEBUG: Disconnecting from BLE device...
2022-08-18 22:50:40,051 bleak.backends.winrt.client DEBUG: session_status_changed_event_handler: id: <_bleak_winrt_Windows_Devices_Bluetooth.BluetoothDeviceId object at 0x00000217E39FDEB0>, error: 0, status: 0
Disconnected!
Traceback (most recent call last):
  File "c:\Users\user\VsCode\eq3bt\test.py", line 39, in <module>
    asyncio.run(main(mac))
  File "C:\Program Files\WindowsApps\PythonSoftwareFoundation.Python.3.9_3.9.3568.0_x64__qbz5n2kfra8p0\lib\asyncio\runners.py", line 44, in run
    return loop.run_until_complete(main)
  File "C:\Program Files\WindowsApps\PythonSoftwareFoundation.Python.3.9_3.9.3568.0_x64__qbz5n2kfra8p0\lib\asyncio\base_events.py", line 647, in run_until_complete
    return future.result()
  File "c:\Users\user\VsCode\eq3bt\test.py", line 33, in main
    await client.start_notify(0x421 - 1, on_notification)
  File "C:\Users\user\VsCode\eq3bt\.venv\lib\site-packages\bleak\backends\winrt\client.py", line 767, in start_notify
    await characteristic_obj.write_client_characteristic_configuration_descriptor_async(
OSError: [WinError -2140864507] The attribute must first be authenticated before it can be read or written [translated]

windows_11_eq3bt.pcapng.gz

Debian

Doesn't crash but hangs instead. Adapter set to hci1 via parameter (not shown in code).

bluetoothd -v: 5.55

2022-08-18 23:18:59,482 bleak.backends.bluezdbus.client DEBUG: Connecting to device @ 00:1A:22:06:1B:EB with hci1
2022-08-18 23:18:59,486 bleak.backends.bluezdbus.scanner DEBUG: cached devices: {}
2022-08-18 23:19:00,356 bleak.backends.bluezdbus.scanner DEBUG: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci1): ['org.bluez.Adapter1', {'Discovering': <dbus_next.signature.Variant ('b', True)>}, []]
2022-08-18 23:19:00,364 bleak.backends.bluezdbus.scanner DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci1/dev_00_1A_22_06_1B_EB', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.Device1': {'Address': <dbus_next.signature.Variant ('s', 00:1A:22:06:1B:EB)>, 'AddressType': <dbus_next.signature.Variant ('s', public)>, 'Name': <dbus_next.signature.Variant ('s', CC-RT-BLE)>, 'Alias': <dbus_next.signature.Variant ('s', CC-RT-BLE)>, 'Paired': <dbus_next.signature.Variant ('b', False)>, 'Trusted': <dbus_next.signature.Variant ('b', False)>, 'Blocked': <dbus_next.signature.Variant ('b', False)>, 'LegacyPairing': <dbus_next.signature.Variant ('b', False)>, 'RSSI': <dbus_next.signature.Variant ('n', -63)>, 'Connected': <dbus_next.signature.Variant ('b', False)>, 'UUIDs': <dbus_next.signature.Variant ('as', ['3e135142-654f-9090-134a-a6ff5bb77046'])>, 'Adapter': <dbus_next.signature.Variant ('o', /org/bluez/hci1)>, 'ManufacturerData': <dbus_next.signature.Variant ('a{qv}', {0: <dbus_next.signature.Variant ('ay', b'\x00\x00\x00\x00\x00\x00\x00\x00\x00')>})>, 'ServicesResolved': <dbus_next.signature.Variant ('b', False)>}, 'org.freedesktop.DBus.Properties': {}}]
2022-08-18 23:19:00,371 bleak.backends.bluezdbus.scanner DEBUG: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci1/dev_00_1A_22_06_1B_EB): ['org.bluez.Device1', {}, ['RSSI']]
2022-08-18 23:19:00,371 bleak.backends.bluezdbus.scanner DEBUG: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci1): ['org.bluez.Adapter1', {'Discovering': <dbus_next.signature.Variant ('b', False)>}, []]
2022-08-18 23:19:02,363 bleak.backends.bluezdbus.client DEBUG: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci1/dev_00_1A_22_06_1B_EB): ['org.bluez.Device1', {'Connected': <dbus_next.signature.Variant ('b', True)>}, []]
2022-08-18 23:19:02,534 bleak.backends.bluezdbus.client DEBUG: Connection successful (/org/bluez/hci1/dev_00_1A_22_06_1B_EB)
2022-08-18 23:19:02,535 bleak.backends.bluezdbus.client DEBUG: Waiting for ServicesResolved (/org/bluez/hci1/dev_00_1A_22_06_1B_EB)
2022-08-18 23:19:03,325 bleak.backends.bluezdbus.client DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci1/dev_00_1A_22_06_1B_EB/service0200', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattService1': {'UUID': <dbus_next.signature.Variant ('s', 00001801-0000-1000-8000-00805f9b34fb)>, 'Device': <dbus_next.signature.Variant ('o', /org/bluez/hci1/dev_00_1A_22_06_1B_EB)>, 'Primary': <dbus_next.signature.Variant ('b', True)>, 'Includes': <dbus_next.signature.Variant ('ao', [])>}, 'org.freedesktop.DBus.Properties': {}}]
2022-08-18 23:19:03,326 bleak.backends.bluezdbus.client DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci1/dev_00_1A_22_06_1B_EB/service0200/char0210', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattCharacteristic1': {'UUID': <dbus_next.signature.Variant ('s', 00002a05-0000-1000-8000-00805f9b34fb)>, 'Service': <dbus_next.signature.Variant ('o', /org/bluez/hci1/dev_00_1A_22_06_1B_EB/service0200)>, 'Value': <dbus_next.signature.Variant ('ay', b'')>, 'Notifying': <dbus_next.signature.Variant ('b', False)>, 'Flags': <dbus_next.signature.Variant ('as', ['read', 'indicate'])>}, 'org.freedesktop.DBus.Properties': {}}]
2022-08-18 23:19:03,328 bleak.backends.bluezdbus.client DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci1/dev_00_1A_22_06_1B_EB/service0200/char0210/desc0220', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattDescriptor1': {'UUID': <dbus_next.signature.Variant ('s', 00002902-0000-1000-8000-00805f9b34fb)>, 'Characteristic': <dbus_next.signature.Variant ('o', /org/bluez/hci1/dev_00_1A_22_06_1B_EB/service0200/char0210)>, 'Value': <dbus_next.signature.Variant ('ay', b'')>}, 'org.freedesktop.DBus.Properties': {}}]
2022-08-18 23:19:03,329 bleak.backends.bluezdbus.client DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci1/dev_00_1A_22_06_1B_EB/service0300', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattService1': {'UUID': <dbus_next.signature.Variant ('s', 0000180a-0000-1000-8000-00805f9b34fb)>, 'Device': <dbus_next.signature.Variant ('o', /org/bluez/hci1/dev_00_1A_22_06_1B_EB)>, 'Primary': <dbus_next.signature.Variant ('b', True)>, 'Includes': <dbus_next.signature.Variant ('ao', [])>}, 'org.freedesktop.DBus.Properties': {}}]
2022-08-18 23:19:03,330 bleak.backends.bluezdbus.client DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci1/dev_00_1A_22_06_1B_EB/service0300/char0310', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattCharacteristic1': {'UUID': <dbus_next.signature.Variant ('s', 00002a29-0000-1000-8000-00805f9b34fb)>, 'Service': <dbus_next.signature.Variant ('o', /org/bluez/hci1/dev_00_1A_22_06_1B_EB/service0300)>, 'Value': <dbus_next.signature.Variant ('ay', b'')>, 'Flags': <dbus_next.signature.Variant ('as', ['read'])>}, 'org.freedesktop.DBus.Properties': {}}]
2022-08-18 23:19:03,332 bleak.backends.bluezdbus.client DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci1/dev_00_1A_22_06_1B_EB/service0300/char0320', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattCharacteristic1': {'UUID': <dbus_next.signature.Variant ('s', 00002a24-0000-1000-8000-00805f9b34fb)>, 'Service': <dbus_next.signature.Variant ('o', /org/bluez/hci1/dev_00_1A_22_06_1B_EB/service0300)>, 'Value': <dbus_next.signature.Variant ('ay', b'')>, 'Flags': <dbus_next.signature.Variant ('as', ['read'])>}, 'org.freedesktop.DBus.Properties': {}}]
2022-08-18 23:19:03,334 bleak.backends.bluezdbus.client DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci1/dev_00_1A_22_06_1B_EB/service0400', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattService1': {'UUID': <dbus_next.signature.Variant ('s', 3e135142-654f-9090-134a-a6ff5bb77046)>, 'Device': <dbus_next.signature.Variant ('o', /org/bluez/hci1/dev_00_1A_22_06_1B_EB)>, 'Primary': <dbus_next.signature.Variant ('b', True)>, 'Includes': <dbus_next.signature.Variant ('ao', [])>}, 'org.freedesktop.DBus.Properties': {}}]
2022-08-18 23:19:03,335 bleak.backends.bluezdbus.client DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci1/dev_00_1A_22_06_1B_EB/service0400/char0410', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattCharacteristic1': {'UUID': <dbus_next.signature.Variant ('s', 3fa4585a-ce4a-3bad-db4b-b8df8179ea09)>, 'Service': <dbus_next.signature.Variant ('o', /org/bluez/hci1/dev_00_1A_22_06_1B_EB/service0400)>, 'Value': <dbus_next.signature.Variant ('ay', b'')>, 'Flags': <dbus_next.signature.Variant ('as', ['read', 'write'])>}, 'org.freedesktop.DBus.Properties': {}}]
2022-08-18 23:19:03,337 bleak.backends.bluezdbus.client DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci1/dev_00_1A_22_06_1B_EB/service0400/char0420', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattCharacteristic1': {'UUID': <dbus_next.signature.Variant ('s', d0e8434d-cd29-0996-af41-6c90f4e0eb2a)>, 'Service': <dbus_next.signature.Variant ('o', /org/bluez/hci1/dev_00_1A_22_06_1B_EB/service0400)>, 'Value': <dbus_next.signature.Variant ('ay', b'')>, 'Notifying': <dbus_next.signature.Variant ('b', False)>, 'Flags': <dbus_next.signature.Variant ('as', ['read', 'write', 'notify'])>, 'NotifyAcquired': <dbus_next.signature.Variant ('b', False)>}, 'org.freedesktop.DBus.Properties': {}}]
2022-08-18 23:19:03,338 bleak.backends.bluezdbus.client DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci1/dev_00_1A_22_06_1B_EB/service0400/char0420/desc0430', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattDescriptor1': {'UUID': <dbus_next.signature.Variant ('s', 00002902-0000-1000-8000-00805f9b34fb)>, 'Characteristic': <dbus_next.signature.Variant ('o', /org/bluez/hci1/dev_00_1A_22_06_1B_EB/service0400/char0420)>, 'Value': <dbus_next.signature.Variant ('ay', b'')>}, 'org.freedesktop.DBus.Properties': {}}]
2022-08-18 23:19:03,339 bleak.backends.bluezdbus.client DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci1/dev_00_1A_22_06_1B_EB/serviceff00', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattService1': {'UUID': <dbus_next.signature.Variant ('s', 9e5d1e47-5c13-43a0-8635-82ad38a1386f)>, 'Device': <dbus_next.signature.Variant ('o', /org/bluez/hci1/dev_00_1A_22_06_1B_EB)>, 'Primary': <dbus_next.signature.Variant ('b', True)>, 'Includes': <dbus_next.signature.Variant ('ao', [])>}, 'org.freedesktop.DBus.Properties': {}}]
2022-08-18 23:19:03,341 bleak.backends.bluezdbus.client DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci1/dev_00_1A_22_06_1B_EB/serviceff00/charff01', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattCharacteristic1': {'UUID': <dbus_next.signature.Variant ('s', e3dd50bf-f7a7-4e99-838e-570a086c666b)>, 'Service': <dbus_next.signature.Variant ('o', /org/bluez/hci1/dev_00_1A_22_06_1B_EB/serviceff00)>, 'Value': <dbus_next.signature.Variant ('ay', b'')>, 'Notifying': <dbus_next.signature.Variant ('b', False)>, 'Flags': <dbus_next.signature.Variant ('as', ['write', 'notify', 'indicate'])>, 'NotifyAcquired': <dbus_next.signature.Variant ('b', False)>}, 'org.freedesktop.DBus.Properties': {}}]
2022-08-18 23:19:03,342 bleak.backends.bluezdbus.client DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci1/dev_00_1A_22_06_1B_EB/serviceff00/charff01/descff03', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattDescriptor1': {'UUID': <dbus_next.signature.Variant ('s', 00002902-0000-1000-8000-00805f9b34fb)>, 'Characteristic': <dbus_next.signature.Variant ('o', /org/bluez/hci1/dev_00_1A_22_06_1B_EB/serviceff00/charff01)>, 'Value': <dbus_next.signature.Variant ('ay', b'')>}, 'org.freedesktop.DBus.Properties': {}}]
2022-08-18 23:19:03,343 bleak.backends.bluezdbus.client DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci1/dev_00_1A_22_06_1B_EB/serviceff00/charff04', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattCharacteristic1': {'UUID': <dbus_next.signature.Variant ('s', 92e86c7a-d961-4091-b74f-2409e72efe36)>, 'Service': <dbus_next.signature.Variant ('o', /org/bluez/hci1/dev_00_1A_22_06_1B_EB/serviceff00)>, 'Value': <dbus_next.signature.Variant ('ay', b'')>, 'Flags': <dbus_next.signature.Variant ('as', ['write'])>}, 'org.freedesktop.DBus.Properties': {}}]
2022-08-18 23:19:03,344 bleak.backends.bluezdbus.client DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci1/dev_00_1A_22_06_1B_EB/serviceff00/charff06', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattCharacteristic1': {'UUID': <dbus_next.signature.Variant ('s', 347f7608-2e2d-47eb-913b-75d4edc4de3b)>, 'Service': <dbus_next.signature.Variant ('o', /org/bluez/hci1/dev_00_1A_22_06_1B_EB/serviceff00)>, 'Value': <dbus_next.signature.Variant ('ay', b'')>, 'Flags': <dbus_next.signature.Variant ('as', ['read'])>}, 'org.freedesktop.DBus.Properties': {}}]
2022-08-18 23:19:03,345 bleak.backends.bluezdbus.client DEBUG: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci1/dev_00_1A_22_06_1B_EB): ['org.bluez.Device1', {'UUIDs': <dbus_next.signature.Variant ('as', ['00001800-0000-1000-8000-00805f9b34fb', '00001801-0000-1000-8000-00805f9b34fb', '0000180a-0000-1000-8000-00805f9b34fb', '3e135142-654f-9090-134a-a6ff5bb77046', '9e5d1e47-5c13-43a0-8635-82ad38a1386f'])>, 'ServicesResolved': <dbus_next.signature.Variant ('b', True)>}, []]
Connected succesful!
2022-08-18 23:19:34,245 bleak.backends.bluezdbus.client DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci1/dev_00_1A_22_06_1B_EB/service0200/char0210/desc0220', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.GattDescriptor1']]
2022-08-18 23:19:34,247 bleak.backends.bluezdbus.client DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci1/dev_00_1A_22_06_1B_EB/service0200/char0210', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.GattCharacteristic1']]
2022-08-18 23:19:34,248 bleak.backends.bluezdbus.client DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci1/dev_00_1A_22_06_1B_EB/service0200', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.GattService1']]
2022-08-18 23:19:34,249 bleak.backends.bluezdbus.client DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci1/dev_00_1A_22_06_1B_EB/service0300/char0310', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.GattCharacteristic1']]
2022-08-18 23:19:34,249 bleak.backends.bluezdbus.client DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci1/dev_00_1A_22_06_1B_EB/service0300/char0320', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.GattCharacteristic1']]
2022-08-18 23:19:34,250 bleak.backends.bluezdbus.client DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci1/dev_00_1A_22_06_1B_EB/service0300', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.GattService1']]
2022-08-18 23:19:34,250 bleak.backends.bluezdbus.client DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci1/dev_00_1A_22_06_1B_EB/service0400/char0410', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.GattCharacteristic1']]
2022-08-18 23:19:34,250 bleak.backends.bluezdbus.client DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci1/dev_00_1A_22_06_1B_EB/service0400/char0420/desc0430', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.GattDescriptor1']]
2022-08-18 23:19:34,250 bleak.backends.bluezdbus.client DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci1/dev_00_1A_22_06_1B_EB/service0400/char0420', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.GattCharacteristic1']]
2022-08-18 23:19:34,251 bleak.backends.bluezdbus.client DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci1/dev_00_1A_22_06_1B_EB/service0400', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.GattService1']]
2022-08-18 23:19:34,251 bleak.backends.bluezdbus.client DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci1/dev_00_1A_22_06_1B_EB/serviceff00/charff01/descff03', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.GattDescriptor1']]
2022-08-18 23:19:34,251 bleak.backends.bluezdbus.client DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci1/dev_00_1A_22_06_1B_EB/serviceff00/charff01', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.GattCharacteristic1']]
2022-08-18 23:19:34,252 bleak.backends.bluezdbus.client DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci1/dev_00_1A_22_06_1B_EB/serviceff00/charff04', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.GattCharacteristic1']]
2022-08-18 23:19:34,252 bleak.backends.bluezdbus.client DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci1/dev_00_1A_22_06_1B_EB/serviceff00/charff06', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.GattCharacteristic1']]
2022-08-18 23:19:34,252 bleak.backends.bluezdbus.client DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci1/dev_00_1A_22_06_1B_EB/serviceff00', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.GattService1']]
^C2022-08-18 23:20:17,975 bleak.backends.bluezdbus.client DEBUG: Disconnecting (/org/bluez/hci1/dev_00_1A_22_06_1B_EB)
unhandled exception during asyncio.run() shutdown
task: <Task finished name='Task-1' coro=<main() done, defined at /home/user/eq3bt_mod/eq3bt/test2.py:12> exception=BleakDBusError('org.freedesktop.DBus.Error.UnknownObject', 'Method "Disconnect" with signature "" on interface "org.bluez.Device1" doesn\'t exist\n')>
Traceback (most recent call last):
  File "/usr/lib/python3.9/asyncio/runners.py", line 44, in run
    return loop.run_until_complete(main)
  File "/usr/lib/python3.9/asyncio/base_events.py", line 629, in run_until_complete
    self.run_forever()
  File "/usr/lib/python3.9/asyncio/base_events.py", line 596, in run_forever
    self._run_once()
  File "/usr/lib/python3.9/asyncio/base_events.py", line 1854, in _run_once
    event_list = self._selector.select(timeout)
  File "/usr/lib/python3.9/selectors.py", line 469, in select
    fd_event_list = self._selector.poll(timeout, max_ev)
KeyboardInterrupt

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/user/eq3bt_mod/eq3bt/test2.py", line 18, in main
    await client.start_notify(0x421 - 1, on_notification)
  File "/home/user/eq3bt_mod/eq3bt/bleak/backends/bluezdbus/client.py", line 923, in start_notify
    reply = await self._bus.call(
  File "/home/user/eq3bt_mod/eq3bt/.venv/lib/python3.9/site-packages/dbus_next/aio/message_bus.py", line 305, in call
    await future
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/user/eq3bt_mod/eq3bt/test2.py", line 20, in main
    await client.disconnect()
  File "/home/user/eq3bt_mod/eq3bt/bleak/backends/bluezdbus/client.py", line 415, in disconnect
    assert_reply(reply)
  File "/home/user/eq3bt_mod/eq3bt/bleak/backends/bluezdbus/utils.py", line 23, in assert_reply
    raise BleakDBusError(reply.error_name, reply.body)
bleak.exc.BleakDBusError: [org.freedesktop.DBus.Error.UnknownObject] Method "Disconnect" with signature "" on interface "org.bluez.Device1" doesn't exist

Traceback (most recent call last):
  File "/home/user/eq3bt_mod/eq3bt/test2.py", line 23, in <module>
    asyncio.run(main(mac))
  File "/usr/lib/python3.9/asyncio/runners.py", line 44, in run
    return loop.run_until_complete(main)
  File "/usr/lib/python3.9/asyncio/base_events.py", line 629, in run_until_complete
    self.run_forever()
  File "/usr/lib/python3.9/asyncio/base_events.py", line 596, in run_forever
    self._run_once()
  File "/usr/lib/python3.9/asyncio/base_events.py", line 1854, in _run_once
    event_list = self._selector.select(timeout)
  File "/usr/lib/python3.9/selectors.py", line 469, in select
    fd_event_list = self._selector.poll(timeout, max_ev)
KeyboardInterrupt

debian_eq3bt.zip

Thanks!

dlech commented 1 year ago

@TechHummel, your problems do not seem to match the description of the issue here so should be discussed elsehwere. I would suggest starting a new discussion for that rather than a new issue for this unless you are 90% certain there is actually a bug in Bleak.

michapr commented 1 year ago

Hi,

I have got now a bit different error message - maybe it can help to findout the issue?

Difference: bleak.exc.BleakDBusError: [org.bluez.Error.Failed] Operation already in progress 

eq3cli --mac 00:1A:22:08:BF:D6
Traceback (most recent call last):
  File "/usr/lib/python3.10/site-packages/eq3bt/bleakconnection.py", line 51, in __enter__
    self._loop.run_until_complete(self._conn.connect())
  File "/usr/lib/python3.10/asyncio/base_events.py", line 641, in run_until_complete
    return future.result()
  File "/usr/lib/python3.10/site-packages/bleak/backends/bluezdbus/client.py", line 167, in connect
    assert_reply(reply)
  File "/usr/lib/python3.10/site-packages/bleak/backends/bluezdbus/utils.py", line 22, in assert_reply
    raise BleakDBusError(reply.error_name, reply.body)
bleak.exc.BleakDBusError: [org.bluez.Error.Failed] Operation already in progress

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3.10/site-packages/eq3bt/bleakconnection.py", line 57, in __enter__
    self._loop.run_until_complete(self._conn.connect())
  File "/usr/lib/python3.10/asyncio/base_events.py", line 641, in run_until_complete
    return future.result()
  File "/usr/lib/python3.10/site-packages/bleak/backends/bluezdbus/client.py", line 167, in connect
    assert_reply(reply)
  File "/usr/lib/python3.10/site-packages/bleak/backends/bluezdbus/utils.py", line 22, in assert_reply
    raise BleakDBusError(reply.error_name, reply.body)
bleak.exc.BleakDBusError: [org.bluez.Error.Failed] Cancelled
dlech commented 1 year ago

@michapr, I would suggest logging Bluetooth packets with Wireshark as described on the troubleshooting page in the Bleak docs to see if there is a problem with the remote device, e.g. it isn't properly responding to requests and causing BlueZ to disconnect.

michapr commented 1 year ago

I will try to make it, but all these problems came up only after HA update from 2022.01 to 2022.08 - without any other changes. Not sure, was bleak used here before? Was working a long time before stable (all the heating period ;) ...)

TechHummel commented 1 year ago

eq3bt before 2022.08 relied on bluepy. Homeassistant 2022.07 removed bluepy support which is why eq3bt switched to bleak (for homeassistant).

michapr commented 1 year ago

@TechHummel Have you found a work around for a stable connection in HA?

@dlech did not try with Wireshark - but I can say that the connection to BLE thermostat should be fine (device is near the USB stick) and it was working before 100% stable with bluepy based integration....

dlech commented 1 year ago

The "Operation already in progress" error sounds like #971 (or possibly #1036).

TechHummel commented 1 year ago

@michapr I'm afraid I haven't! I can't get the thermostats to work with bleak at all. I tried using a newer version of bluez which I didn't manage to get working (dependency issues). I'm out of ideas for now.

sqall01 commented 1 year ago

I just upgraded my python-eq3bt version to 0.2 (which uses bleak) and have the same issue. I am not able to get it to work with my thermostats. I get the same errors as @michapr gets. It happened for me on my development machine running xubuntu 20.04. Luckily, I have the option to downgrade python-eq3bt to 0.11.2 which uses bluepy and which works fine.

Would a Wireshark dump with bluepy help to solve this problem?

dlech commented 1 year ago

20.04. Luckily, I have the option to downgrade python-eq3bt to 0.11.2 which uses bluepy and which works fine.

Would a Wireshark dump with bluepy help to solve this problem?

Absolutely. And another dump of the Bleak version to compare it to.

sqall01 commented 1 year ago

Here are the details:

Python 3.8.10 (default, Jun 22 2022, 20:18:18)

Bluepy environment:

Package        Version
-------------- -------
bluepy         1.3.0  
click          8.1.3  
click-datetime 0.2    
construct      2.10.68
pip            20.0.2 
pkg-resources  0.0.0  
python-eq3bt   0.1.12 
setuptools     44.0.0 
wheel          0.34.2

Bleak environment:

Package       Version
------------- -------
async-timeout 4.0.2  
bleak         0.18.1 
click         8.1.3  
construct     2.10.68
dbus-fast     1.17.0 
pip           20.0.2 
pkg-resources 0.0.0  
python-eq3bt  0.2    
setuptools    44.0.0 
wheel         0.34.2

I executed for both the same commands while capturing:

from eq3bt import Thermostat
test = Thermostat("00:1a:22:07:64:82")
test.update()

I also noticed that when executing the commands via bleak, the Bluetooth manager asks for permission to pair with the thermostat. Using bluepy it was not asking it. Here is notably, I captured the bluepy trace before the bleak trace. And the thermostat was not paired according to the Bluetooth manager before and after I used bluepy. After I used bleak, the thermostat appeared as paired.

I hope this helps.

bluepy.pcapng.zip

bleak.pcapng.zip

dlech commented 1 year ago

We would need to do the capture with bleak again after removing the device from bluez to ensure that it does a full enumeration of services and characteristics to be sure, but I'm guessing that the device has a Services Changed characteristic and for some reason (in violation of the Bluetooth spec) it requires authentication to enable indications on that characteristic, which is why it is being paired. This is something that BlueZ does automatically, so there isn't anything we can do about it in Bleak.

The bluepy library bypasses BlueZ, so it simply connects to the device and writes to a characteristic. It doesn't have all of the overhead of BlueZ enumerating services, negotiating MTU, etc.

I get the same errors as @michapr gets.

Which error specifically? There have been multiple errors reported here.

In spite of all of the overhead, it does appear that Bleak did write to handle 0x0411 and receive a notification from handle 0x0421 just as bluepy did. So perhaps the error can just be ignored?

sqall01 commented 1 year ago

I recaptured everything with a new thermostat that was never connected to my machine.

Here are the commands + errors:

>>> from eq3bt import Thermostat

>>> test = Thermostat("00:1a:22:12:26:ee")

>>> test.update()
Task exception was never retrieved
future: <Task finished name='Task-9' coro=<BleakConnection.on_notification() done, defined at /home/sqall/syncfolder/projekte/alertR/thermostat_service/venv_bleak/lib/python3.8/site-packages/eq3bt/bleakconnection.py:77> exception=TypeError("unsupported operand type(s) for +: 'BleakGATTCharacteristicBlueZDBus' and 'int'")>
Traceback (most recent call last):
  File "/home/sqall/syncfolder/projekte/alertR/thermostat_service/venv_bleak/lib/python3.8/site-packages/eq3bt/bleakconnection.py", line 119, in make_request
    self._loop.run_until_complete(self.wait_for_response(timeout))
  File "/usr/lib/python3.8/asyncio/base_events.py", line 616, in run_until_complete
    return future.result()
  File "/home/sqall/syncfolder/projekte/alertR/thermostat_service/venv_bleak/lib/python3.8/site-packages/eq3bt/bleakconnection.py", line 101, in wait_for_response
    await asyncio.wait_for(self._notifyevent.wait(), timeout)
  File "/usr/lib/python3.8/asyncio/tasks.py", line 494, in wait_for
    return fut.result()
  File "/usr/lib/python3.8/asyncio/locks.py", line 309, in wait
    await fut
RuntimeError: Task <Task pending name='Task-7' coro=<Event.wait() running at /usr/lib/python3.8/asyncio/locks.py:309> cb=[_release_waiter(<Future pendi...8e2f51700>()]>)() at /usr/lib/python3.8/asyncio/tasks.py:429]> got Future <Future pending> attached to a different loop

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/sqall/syncfolder/projekte/alertR/thermostat_service/venv_bleak/lib/python3.8/site-packages/eq3bt/bleakconnection.py", line 80, in on_notification
    handle = handle + 1
TypeError: unsupported operand type(s) for +: 'BleakGATTCharacteristicBlueZDBus' and 'int'
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/home/sqall/syncfolder/projekte/alertR/thermostat_service/venv_bleak/lib/python3.8/site-packages/eq3bt/eq3btsmart.py", line 217, in update
    self._conn.make_request(PROP_WRITE_HANDLE, value)
  File "/home/sqall/syncfolder/projekte/alertR/thermostat_service/venv_bleak/lib/python3.8/site-packages/eq3bt/bleakconnection.py", line 119, in make_request
    self._loop.run_until_complete(self.wait_for_response(timeout))
  File "/usr/lib/python3.8/asyncio/base_events.py", line 616, in run_until_complete
    return future.result()
  File "/home/sqall/syncfolder/projekte/alertR/thermostat_service/venv_bleak/lib/python3.8/site-packages/eq3bt/bleakconnection.py", line 101, in wait_for_response
    await asyncio.wait_for(self._notifyevent.wait(), timeout)
  File "/usr/lib/python3.8/asyncio/tasks.py", line 494, in wait_for
    return fut.result()
  File "/usr/lib/python3.8/asyncio/locks.py", line 309, in wait
    await fut
RuntimeError: Task <Task pending name='Task-7' coro=<Event.wait() running at /usr/lib/python3.8/asyncio/locks.py:309> cb=[_release_waiter(<Future pendi...8e2f51700>()]>)() at /usr/lib/python3.8/asyncio/tasks.py:429]> got Future <Future pending> attached to a different loop

>>> test.target_temperature
<Mode.Unknown: -1>

The last command would normally give you the temperature of the thermostat. However, since the connection failed, it gives you this Mode.Unknown object back.

bleak.pcapng.zip

dlech commented 1 year ago

attached to a different loop

This means that your application has more than one asyncio run loop. IMHO, it is best to only have a single run loop for the entire duration of the app. If you must have more than one, you need to be sure to keep objects within the same run loop and not pass them between loops.

(This seems completely unrelated to the other errors in this issue)

sqall01 commented 1 year ago

This was only the error I could simply reproduce by executing the basic commands from python-eq3bt. But it is good to know that in the library there seems to be an issue with the asyncio run loop. I will open an issue on the library's github page.

Errors I had were bleak.exc.BleakDBusError: [org.bluez.Error.Failed] Operation already in progress and eq3bt.BackendException: unable to connect to device using bleak but I do not know how to reliably reproduce them. Perhaps these will also be resolved if the bug in python-eq3bt is resolved.

TechHummel commented 1 year ago

@sqall01 Which version of bluez are you using? Thanks!

sqall01 commented 1 year ago 
ii  bluez                                      5.53-0ubuntu3.6                     amd64        Bluetooth tools and daemons
ii  bluez-cups                                 5.53-0ubuntu3.6                     amd64        Bluetooth printer driver for CUPS
ii  bluez-obexd                                5.53-0ubuntu3.6                     amd64        bluez obex daemon