KeyError: 'org.bluez.Device1'

[zevv]

• raspberry pi 4B
• debian bookworm
• bleak 0.20.2-1 from python3-bleak package
• bluetoothctl: 5.66

I'm having a very hard time getting my code to run stable; i'm basically round-robin polling about 60 bluetooth devices (For details of my setup see #1500)

Apart from the occasional problem at the kernel/driver level, my code often runs into the error below:

ERROR:root:A message handler raised an exception: 'org.bluez.Device1'.
Traceback (most recent call last):
  File "src/dbus_fast/message_bus.py", line 811, in dbus_fast.message_bus.BaseMessageBus._process_message
  File "/usr/lib/python3/dist-packages/bleak/backends/bluezdbus/manager.py", line 854, in _parse_msg
    condition_callback()
  File "/usr/lib/python3/dist-packages/bleak/backends/bluezdbus/manager.py", line 709, in callback
    self._properties[device_path][defs.DEVICE_INTERFACE][property_name]
    ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^
KeyError: 'org.bluez.Device1'

I can't seem to relate this to anything I'm doing as none of my code is in the traceback - what could be the cause of above message, and how do I avoid this situation?

Thank you

[dlech]

Enabling debug logs should at least show us the order in which things are happening to try to see where the issue is. (It could be helpful to compare with the "good" debug logs from the other issue to see what the difference is.)

[zevv]

Of course, I should have made an shared the debug log in the first place, will do this today. thank you.

[zevv]

Log attached below; it's quite large but fortunately the problem popped up within the first few minutes.

It starts with a discovery and then finds the first devices. The program attempts to connect and poll these, but the first few ones fail: my guess is that people just carried in a box with 40 devices into the building but are not properly within range yet. These failed attempts are expected and should not matter. (Timeouts,

A bit later (approx line 2475) some devices are properly connected and polled, all is well until line 7657 where the first error pops up:

Feb 13 08:34:41 2024-02-13 08:34:41,141 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_C8_47_80_0B_52_79): ['org.bluez.Device1', {'Connected': <dbus_fast.signature.Variant ('b', False)>}, []]
Feb 13 08:34:41 DEBUG:bleak.backends.bluezdbus.manager:received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_C8_47_80_0B_52_79): ['org.bluez.Device1', {'Connected': <dbus_fast.signature.Variant ('b', False)>}, []]
Feb 13 08:34:41 ERROR:root:A message handler raised an exception: 'org.bluez.Device1'.
Feb 13 08:34:41 Traceback (most recent call last):
Feb 13 08:34:41   File "src/dbus_fast/message_bus.py", line 811, in dbus_fast.message_bus.BaseMessageBus._process_message
Feb 13 08:34:41   File "/usr/lib/python3/dist-packages/bleak/backends/bluezdbus/manager.py", line 854, in _parse_msg
Feb 13 08:34:41     condition_callback()
Feb 13 08:34:41   File "/usr/lib/python3/dist-packages/bleak/backends/bluezdbus/manager.py", line 709, in callback
Feb 13 08:34:41     self._properties[device_path][defs.DEVICE_INTERFACE][property_name]
Feb 13 08:34:41     ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^
Feb 13 08:34:41 KeyError: 'org.bluez.Device1

This repeats once or twice, until a few seconds later it repeats over and over and all communication basically stopped.

log.txt

[Siecje]

If device_path is in self._properties then will self._properties[device_path][defs.DEVICE_INTERFACE] always exist?

Is there any reason _check_device() doesn't also check for the defs.DEVICE_INTERFACE key?

https://github.com/hbldh/bleak/blob/17d43740e4439512d7283c4af0469389018ef4f6/bleak/backends/bluezdbus/manager.py#L211-L217

Or raise BleakError inside _wait_condition()?

https://github.com/hbldh/bleak/blob/17d43740e4439512d7283c4af0469389018ef4f6/bleak/backends/bluezdbus/manager.py#L826

[zevv]

apart from how the error is or should be handled inside bleak: is there something i am doing wrong to cause this in the first place?

[dlech]

If device_path is in self._properties then will self._properties[device_path][defs.DEVICE_INTERFACE] always exist?

Is there any reason _check_device() doesn't also check for the defs.DEVICE_INTERFACE key?

It looks like you have spotted the bug. We can add the check you suggest to be safe but I think we also want to del self._properties[device_path] when all interfaces have been removed in the "InterfacesRemoved" handler to avoid having leftover dictionary entries. This avoids wasting memory for people who have noisy devices with private addresses that change frequently.

[dlech]

apart from how the error is or should be handled inside bleak: is there something i am doing wrong to cause this in the first place?

No, I don't think so. It is normal for devices to disappear from BlueZ after some time.

[zevv]

Thank you. Let me know if there is anything I can run to test, repro-wise or fix-wise.

[dlech]

Let me know if there is anything I can run to test, repro-wise or fix-wise.

You could test the proposed fix in https://github.com/hbldh/bleak/pull/1511

[zevv]

Installed the PR branch, testing will have to wait until tomorrow morning when all the devices are back online.

Thanks.

[zevv]

1511 looks good so far.