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

pair() only works when bluetoothctl is running #1434

Open
abmantis opened this issue Oct 6, 2023 · 5 comments
Open

pair() only works when bluetoothctl is running #1434

abmantis opened this issue Oct 6, 2023 · 5 comments
Labels
Backend: BlueZ Issues and PRs relating to the BlueZ backend

Comments

@abmantis
Copy link

abmantis commented Oct 6, 2023

  • bleak version: 0.21.1
  • Python version: 3.11.5
  • Operating System: Arch Linux
  • BlueZ version (bluetoothctl -v) in case of Linux: 5.69

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
Copy link
Author

abmantis commented Oct 6, 2023 •
edited
Loading

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 ?

This was referenced Oct 6, 2023
Closed
Merged
@dlech
Copy link
Collaborator

dlech commented Oct 6, 2023

I guess we need #1100 ?

Yes.

@abmantis abmantis mentioned this issue Oct 7, 2023
Merged
20 tasks
@hosse005
Copy link

@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
Copy link
Author

@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
Copy link

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...

@userx14 userx14 mentioned this issue Feb 14, 2024
Closed
@RobertWojtowicz RobertWojtowicz mentioned this issue Jun 17, 2024
Closed
@dlech dlech added the Backend: BlueZ Issues and PRs relating to the BlueZ backend label Oct 5, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
Backend: BlueZ Issues and PRs relating to the BlueZ backend
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@dlech @abmantis @hosse005 @makingglitches