search

hbldh / bleak

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

pair() only works when bluetoothctl is running #1434

Open abmantis opened 11 months ago

abmantis commented 11 months ago

Description

client.pair() fails with bleak.exc.BleakDBusError: [org.bluez.Error.AuthenticationFailed] Authentication Failed, unless bluetoothctl is running, or the Gnome Control Center bluetooth page is open.

What I Did

I added the Idasen Desk integration to HA, and after some issue reports from users, I was able to reproduce it locally with the following:

async def getBLEDevice(address: str):
    return await BleakScanner.find_device_by_address(address)

async def connect(ble_device):
    async with BleakClient(ble_device) as client:
        await client.pair()

async def start():
    if args.address is None:
        logger.error("Desk address argument missing")
        return

    ble_device = await getBLEDevice(args.address)
    if ble_device is None:
        logger.error("Desk not found")
        return
    await connect(ble_device)

asyncio.run(start())

Logs

Without bluetootctl running:

2023-10-06 01:49:39,754 [bleak.backends.bluezdbus.manager DEBUG]: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', True)>}, []]
2023-10-06 01:49:39,885 [bleak.backends.bluezdbus.manager DEBUG]: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_F6_77_AD_7C_E9_40): ['org.bluez.Device1', {'RSSI': <dbus_fast.signature.Variant ('n', -53)>, 'TxPower': <dbus_fast.signature.Variant ('n', -8)>}, []]
2023-10-06 01:49:39,889 [bleak.backends.bluezdbus.manager DEBUG]: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_F6_77_AD_7C_E9_40): ['org.bluez.Device1', {}, ['TxPower', 'RSSI']]
2023-10-06 01:49:39,890 [bleak.backends.bluezdbus.manager DEBUG]: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', False)>}, []]
2023-10-06 01:49:44,900 [bleak.backends.bluezdbus.client DEBUG]: Connecting to device @ F6:77:AD:7C:E9:40
2023-10-06 01:49:44,908 [bleak.backends.bluezdbus.client DEBUG]: Connecting to BlueZ path /org/bluez/hci0/dev_F6_77_AD_7C_E9_40
2023-10-06 01:49:45,297 [bleak.backends.bluezdbus.manager DEBUG]: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_F6_77_AD_7C_E9_40): ['org.bluez.Device1', {'Connected': <dbus_fast.signature.Variant ('b', True)>}, []]
2023-10-06 01:49:45,615 [bleak.backends.bluezdbus.client DEBUG]: retry due to le-connection-abort-by-local
2023-10-06 01:49:45,630 [bleak.backends.bluezdbus.manager DEBUG]: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_F6_77_AD_7C_E9_40): ['org.bluez.Device1', {'Connected': <dbus_fast.signature.Variant ('b', False)>}, []]
2023-10-06 01:49:45,630 [bleak.backends.bluezdbus.client DEBUG]: Device disconnected (/org/bluez/hci0/dev_F6_77_AD_7C_E9_40)
2023-10-06 01:49:45,630 [bleak.backends.bluezdbus.client DEBUG]: _cleanup_all(/org/bluez/hci0/dev_F6_77_AD_7C_E9_40)
2023-10-06 01:49:45,632 [bleak.backends.bluezdbus.client DEBUG]: Connecting to BlueZ path /org/bluez/hci0/dev_F6_77_AD_7C_E9_40
2023-10-06 01:49:45,843 [bleak.backends.bluezdbus.manager DEBUG]: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_F6_77_AD_7C_E9_40): ['org.bluez.Device1', {'Connected': <dbus_fast.signature.Variant ('b', True)>}, []]
2023-10-06 01:49:46,749 [bleak.backends.bluezdbus.manager DEBUG]: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_F6_77_AD_7C_E9_40): ['org.bluez.Device1', {'ServicesResolved': <dbus_fast.signature.Variant ('b', True)>}, []]
2023-10-06 01:49:46,753 [bleak.backends.bluezdbus.client DEBUG]: Pairing to BLE device @ F6:77:AD:7C:E9:40
2023-10-06 01:49:46,873 [bleak.backends.bluezdbus.client DEBUG]: Disconnecting ({/org/bluez/hci0/dev_F6_77_AD_7C_E9_40})
2023-10-06 01:49:49,441 [bleak.backends.bluezdbus.manager DEBUG]: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_F6_77_AD_7C_E9_40): ['org.bluez.Device1', {'ServicesResolved': <dbus_fast.signature.Variant ('b', False)>}, []]
2023-10-06 01:49:49,442 [bleak.backends.bluezdbus.manager DEBUG]: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_F6_77_AD_7C_E9_40): ['org.bluez.Device1', {'Connected': <dbus_fast.signature.Variant ('b', False)>}, []]
2023-10-06 01:49:49,442 [bleak.backends.bluezdbus.client DEBUG]: Device disconnected (/org/bluez/hci0/dev_F6_77_AD_7C_E9_40)
2023-10-06 01:49:49,442 [bleak.backends.bluezdbus.client DEBUG]: _cleanup_all(/org/bluez/hci0/dev_F6_77_AD_7C_E9_40)
Traceback (most recent call last):
  File "/home/amfcosta/dev/random/idasen-ha/cli.py", line 93, in <module>
    asyncio.run(start())
  File "/usr/lib/python3.11/asyncio/runners.py", line 190, in run
    return runner.run(main)
           ^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/asyncio/runners.py", line 118, in run
    return self._loop.run_until_complete(task)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/asyncio/base_events.py", line 653, in run_until_complete
    return future.result()
           ^^^^^^^^^^^^^^^
  File "/home/amfcosta/dev/random/idasen-ha/cli.py", line 42, in start
    await connect(ble_device)
  File "/home/amfcosta/dev/random/idasen-ha/cli.py", line 29, in connect
    await client.pair()
  File "/home/amfcosta/dev/random/idasen-ha/.venv/lib/python3.11/site-packages/bleak/__init__.py", line 629, in pair
    return await self._backend.pair(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/amfcosta/dev/random/idasen-ha/.venv/lib/python3.11/site-packages/bleak/backends/bluezdbus/client.py", line 473, in pair
    assert_reply(reply)
  File "/home/amfcosta/dev/random/idasen-ha/.venv/lib/python3.11/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.AuthenticationFailed] Authentication Failed

With bluetoothctl running:

2023-10-06 01:52:10,344 [bleak.backends.bluezdbus.manager DEBUG]: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', True)>}, []]
2023-10-06 01:52:10,385 [bleak.backends.bluezdbus.manager DEBUG]: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_F6_77_AD_7C_E9_40): ['org.bluez.Device1', {'RSSI': <dbus_fast.signature.Variant ('n', -57)>, 'TxPower': <dbus_fast.signature.Variant ('n', -8)>}, []]
2023-10-06 01:52:10,390 [bleak.backends.bluezdbus.manager DEBUG]: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_F6_77_AD_7C_E9_40): ['org.bluez.Device1', {}, ['TxPower', 'RSSI']]
2023-10-06 01:52:10,392 [bleak.backends.bluezdbus.manager DEBUG]: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', False)>}, []]
2023-10-06 01:52:15,401 [bleak.backends.bluezdbus.client DEBUG]: Connecting to device @ F6:77:AD:7C:E9:40
2023-10-06 01:52:15,410 [bleak.backends.bluezdbus.client DEBUG]: Connecting to BlueZ path /org/bluez/hci0/dev_F6_77_AD_7C_E9_40
2023-10-06 01:52:15,764 [bleak.backends.bluezdbus.manager DEBUG]: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_F6_77_AD_7C_E9_40): ['org.bluez.Device1', {'Connected': <dbus_fast.signature.Variant ('b', True)>}, []]
2023-10-06 01:52:16,700 [bleak.backends.bluezdbus.manager DEBUG]: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_F6_77_AD_7C_E9_40): ['org.bluez.Device1', {'ServicesResolved': <dbus_fast.signature.Variant ('b', True)>}, []]
2023-10-06 01:52:16,702 [bleak.backends.bluezdbus.client DEBUG]: Pairing to BLE device @ F6:77:AD:7C:E9:40
2023-10-06 01:52:17,330 [bleak.backends.bluezdbus.manager DEBUG]: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_F6_77_AD_7C_E9_40): ['org.bluez.Device1', {'Bonded': <dbus_fast.signature.Variant ('b', True)>, 'Paired': <dbus_fast.signature.Variant ('b', True)>}, []]
2023-10-06 01:52:17,333 [bleak.backends.bluezdbus.client DEBUG]: Disconnecting ({/org/bluez/hci0/dev_F6_77_AD_7C_E9_40})
2023-10-06 01:52:19,474 [bleak.backends.bluezdbus.manager DEBUG]: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_F6_77_AD_7C_E9_40): ['org.bluez.Device1', {'ServicesResolved': <dbus_fast.signature.Variant ('b', False)>}, []]
2023-10-06 01:52:19,476 [bleak.backends.bluezdbus.manager DEBUG]: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_F6_77_AD_7C_E9_40): ['org.bluez.Device1', {'Connected': <dbus_fast.signature.Variant ('b', False)>}, []]
2023-10-06 01:52:19,477 [bleak.backends.bluezdbus.client DEBUG]: Device disconnected (/org/bluez/hci0/dev_F6_77_AD_7C_E9_40)
2023-10-06 01:52:19,477 [bleak.backends.bluezdbus.client DEBUG]: _cleanup_all(/org/bluez/hci0/dev_F6_77_AD_7C_E9_40)
abmantis commented 11 months ago

I just noticed this on journalctl:

Oct 06 02:19:40 kiwi bluetoothd[770018]: src/device.c:new_auth() No agent available for request type 2
Oct 06 02:19:40 kiwi bluetoothd[770018]: device_confirm_passkey: Operation not permitted

I guess we need #1100 ?

dlech commented 11 months ago

I guess we need #1100 ?

Yes.

hosse005 commented 10 months ago

@abmantis , as a workaround, you could attempt to register the authentication agent you need for your device using bt-agent from the bluez-tools package as outlined in this doc https://technotes.kynetics.com/2018/pairing_agents_bluez/.

abmantis commented 10 months ago

@abmantis , as a workaround, you could attempt to register the authentication agent you need for your device using bt-agent from the bluez-tools package as outlined in this doc https://technotes.kynetics.com/2018/pairing_agents_bluez/.

Interesting. Thanks! I will look into that option.

makingglitches commented 7 months ago

I'm having this issue suddenly too trying to tether and the above works... but on fedora and i have no idea what bleak does...