Bluetooth: A message handler raised an exception: 'org.bluez.Device1'

[huzecong]

The problem

This is the same issue as #76914. I'm using the Switchmate integration and all of a sudden it stopped working. Logs show that it's slow to update, and then the KeyError: 'org.bluez.Device1' error keeps showing up (multiple times per second). The switch entities are still shown as available on Home Assistant, but they cannot be toggled anymore.

A restart could solve this issue, but it would come back after a while.

What's worth noting is that Switchmate is one of the integrations that hasn't migrated to BLEDevice yet; not sure if migrating over could make this go away.

What version of Home Assistant Core has the issue?

2022.9.7

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant OS

Integration causing the issue

Bluetooth, Switchmate

Link to integration documentation on our website

No response

Diagnostics information

No response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

2022-10-04 09:29:19.315 WARNING (MainThread) [homeassistant.helpers.entity] Update of switch.closet_ceiling_light is taking over 10 seconds
2022-10-04 09:54:29.813 ERROR (MainThread) [root] A message handler raised an exception: 'org.bluez.Device1'.
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/dbus_fast/message_bus.py", line 736, in _process_message
    result = handler(msg)
  File "/usr/local/lib/python3.10/site-packages/bleak/backends/bluezdbus/manager.py", line 804, in _parse_msg
    condition_callback()
  File "/usr/local/lib/python3.10/site-packages/bleak/backends/bluezdbus/manager.py", line 664, in callback
    self._properties[device_path][defs.DEVICE_INTERFACE][property_name]
KeyError: 'org.bluez.Device1'

Additional information

I'm running HassOS 9.0 on a Raspberry Pi 4 (rpi4-64).

[homeassistant]

Hey there @bdraco, mind taking a look at this issue as it has been labeled with an integration (bluetooth) you are listed as a code owner for? Thanks! _{^{(message by CodeOwnersMention)}}

---

bluetooth documentation bluetooth source _{^{(message by IssueLinks)}}

[homeassistant]

Hey there @danielhiversen, @qiz-li, mind taking a look at this issue as it has been labeled with an integration (switchmate) you are listed as a code owner for? Thanks! _{^{(message by CodeOwnersMention)}}

---

switchmate documentation switchmate source _{^{(message by IssueLinks)}}

[bdraco]

Please try 2022.10.x when its released tomorrow

[nixi]

I get the same error message and I am not sure when it started but I noticed it yesterday after upgrading to 2022.10 and enabling the ibeacon device tracker. I have since disable the integration but it still spams my log with multiple errors every second.

I have the ble device tracker on since last month. I would be happy to provide more information if requestested.

[bdraco]

Try enabling debug logs for bleak

It looks like the device is failing to register but you are somehow getting property changes for it anyways.

This will likely need to be solved in bleak

[nixi]

Here is some more logs. It is not only the E1:A8:8E:59:73:CD device, there are many more.

2022-10-06 13:28:49.203 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140528029680016] Sending {"id":60,"timestamp":1665055370.0626702,"exception":"","count":2,"first_occurred":1665055370.0521579},{"name":"homeassistant","message":["Error doing job: Task exception was never retrieved"],"level":"ERROR","source":["components/bluetooth_le_tracker/device_tracker.py",169],"timestamp":1665054511.779595,"exception":"Traceback (most recent call last):\n  File \"/usr/src/homeassistant/homeassistant/components/bluetooth_le_tracker/device_tracker.py\", line 154, in _async_see_update_ble_battery\n    async with BleakClient(device) as client:\n  File \"/usr/local/lib/python3.10/site-packages/bleak/__init__.py\", line 354, in __aenter__\n    await self.connect()\n  File \"/usr/src/homeassistant/homeassistant/components/bluetooth/models.py\", line 272, in connect\n    return await super().connect(**kwargs)\n  File \"/usr/local/lib/python3.10/site-packages/bleak/__init__.py\", line 392, in connect\n    return await self._backend.connect(**kwargs)\n  File \"/usr/local/lib/python3.10/site-packages/bleak/backends/bluezdbus/client.py\", line 179, in connect\n    assert_reply(reply)\n  File \"/usr/local/lib/python3.10/site-packages/bleak/backends/bluezdbus/utils.py\", line 22, in assert_reply\n    raise BleakDBusError(reply.error_name, reply.body)\nbleak.exc.BleakDBusError: [org.bluez.Error.Failed] br-connection-canceled\n\nDuring handling of the above exception, another exception occurred:\n\nTraceback (most recent call last):\n  File \"/usr/src/homeassistant/homeassistant/components/bluetooth_le_tracker/device_tracker.py\", line 169, in _async_see_update_ble_battery\n    del devs_track_battery[mac]\nKeyError: 'E1:A8:8E:59:73:CD'\n","count":15,"first_occurred":1665046560.2309468},,"level":"WARNING","source":["runner.py",119],"timestamp":1665046518.7466772,"exception":"","count":1]}
2022-10-06 13:28:49.208 DEBUG (MainThread) [aioesphomeapi.connection] shelly1-f4cfa2ed6948-trainled @ 192.168.11.53: Got message of type <class 'api_pb2.PingResponse'>: 
2022-10-06 13:28:49.220 DEBUG (MainThread) [bleak.backends.bluezdbus.manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_40_29_66_14_C0_F8): ['org.bluez.Device1', {'RSSI': <dbus_fast.signature.Variant ('n', -70)>}, []]
2022-10-06 13:28:49.222 ERROR (MainThread) [root] A message handler raised an exception: 'org.bluez.Device1'.
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/dbus_fast/message_bus.py", line 737, in _process_message
    result = handler(msg)
  File "/usr/local/lib/python3.10/site-packages/bleak/backends/bluezdbus/manager.py", line 804, in _parse_msg
    condition_callback()
  File "/usr/local/lib/python3.10/site-packages/bleak/backends/bluezdbus/manager.py", line 664, in callback
    self._properties[device_path][defs.DEVICE_INTERFACE][property_name]
KeyError: 'org.bluez.Device1'

known_devices.yaml

n0399:
  name: N0399
  mac: BLE_E1:A8:8E:59:73:CD
  icon:
  picture:
  track: true

[huzecong]

I can confirm that I'm no longer seeing this issue so far since I've upgraded to 2022.10. Thanks!

[huzecong]

Update: Unfortunately, the issue still exists :( I'm now seeing the same exceptions as before.