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.

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

KeyError: 'org.bluez.Device1' #1507

Closed
zevv opened this issue Feb 12, 2024 · 11 comments · Fixed by #1511
Closed

KeyError: 'org.bluez.Device1' #1507

zevv opened this issue Feb 12, 2024 · 11 comments · Fixed by #1511
Labels
Backend: BlueZ Issues and PRs relating to the BlueZ backend bug Something isn't working

Comments

@zevv
Copy link

zevv commented Feb 12, 2024

  • 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
Copy link
Collaborator

dlech commented Feb 13, 2024

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

zevv commented Feb 13, 2024

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

@zevv
Copy link
Author

zevv commented Feb 13, 2024

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

Siecje commented Feb 13, 2024

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?

def _check_device(self, device_path: str) -> None:
"""
Raises:
BleakError: if device is not present in BlueZ
"""
if device_path not in self._properties:
raise BleakError(f"device '{device_path.split('/')[-1]}' not found")

Or raise BleakError inside _wait_condition()?

self._properties[device_path][defs.DEVICE_INTERFACE][property_name]

@zevv
Copy link
Author

zevv commented Feb 13, 2024

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

dlech commented Feb 14, 2024

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 dlech added bug Something isn't working Backend: BlueZ Issues and PRs relating to the BlueZ backend labels Feb 14, 2024
@dlech
Copy link
Collaborator

dlech commented Feb 14, 2024

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

zevv commented Feb 14, 2024

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

@dlech
Copy link
Collaborator

dlech commented Feb 14, 2024

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

You could test the proposed fix in #1511

@zevv
Copy link
Author

zevv commented Feb 14, 2024

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

Thanks.

Siecje added a commit to Siecje/bleak that referenced this issue Feb 15, 2024
Siecje added a commit to Siecje/bleak that referenced this issue Feb 15, 2024
@zevv
Copy link
Author

zevv commented Feb 16, 2024

#1511 looks good so far.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Backend: BlueZ Issues and PRs relating to the BlueZ backend bug Something isn't working
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants