search

home-assistant / core

:house_with_garden: Open source home automation that puts local control and privacy first.
https://www.home-assistant.io
Apache License 2.0
70.46k stars 29.39k forks source link

Bluetooth sensor updates once just after HA restart or reloading an integration, then never again. #90307

Closed hejllukas closed 1 year ago

hejllukas commented 1 year ago

The problem

I use HA OS 9.5 on Raspberry PI 3B+. I have the Airthing Wave Plus sensor connected via the embedded Bluetooth in the RPI using the Airthings BLE integration.

Since upgrading to HA 2023.1.1, I have had the issue that HA only updates sensor data when I reload the integration or restart the whole HA. Any further automatic updating of sensor data no longer works, probably due to some Bluetooth failure during connection or communication.

This Bluetooth failure in HA even causes the Bluetooth in the sensor to get stuck and not want to communicate even with my phone, where I have the official Airthings app. Even the LightBlue app can't see the sensor. But when I turn off the RPI with HA or reload the integration, both the official Airthings app and the LightBlue app can see the sensor normally, and HA updates the sensor data once. But when HA tries to update the sensor data again (after 5 minutes), it somehow fails, and the sensor's Bluetooth gets stuck again. So it almost looks like HA somehow doesn't close a Bluetooth connection, and therefore my phone is unable to connect to the sensor.

According to the information I've been able to search, it looks like there is some issue with MTU and its caching for Bluetooth connections because almost exactly the same issue was previously reported for ESPHome and the Bluetooth proxies https://github.com/esphome/issues/issues/4041 and https://github.com/esphome/issues/issues/3951. They fixed these issues in the following PR https://github.com/esphome/esphome/pull/4322. But in my case, I don't use the Bluetooth proxy.

Based on information in that https://github.com/esphome/issues/issues/3951, I have tested that everything starts working again if I downgrade HA to version 2022.11.5. But after I upgrade to any newer version, within a few days, the issue returns again. So I have to stay on HA version 2022.11.5.

I also found that this issue isn't related to just Airthings devices because at least there https://github.com/jdeath/rd200v2/issues/11, another user has exactly the same problem, but with a completely different device. This user also runs HA on a Raspberry PI, uses the embedded Bluetooth adapter, and doesn't use a Bluetooth proxy.

Could You please look at this issue? Alternatively, is there any way to get this to work on a Raspberry PI with a newer HA than 2022.11.5?

I attached one continuous part of the log file in which I just replaced the MAC address of the sensor and removed lines related to other (non-Bluetooth) devices. If needed, I'm able to provide more information (if I will know how) or help with testing or so.

What version of Home Assistant Core has the issue?

core-2023.3.6

What was the last working version of Home Assistant Core?

core-2022.11.5

What type of installation are you running?

Home Assistant OS

Integration causing the issue

No response

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?

2023-03-25 19:21:26.667 INFO (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (B8:27:AA:BB:CC:DD): Bluetooth scanner has gone quiet for 90s, restarting
2023-03-25 19:21:26.839 WARNING (MainThread) [bluetooth_auto_recovery.recover] Bluetooth adapter hci0 [B8:27:AA:BB:CC:DD] successfully turned back ON
2023-03-25 19:21:44.184 INFO (MainThread) [custom_components.airthings_ble] Fetching airthings_ble data recovered
2023-03-25 19:23:20.153 INFO (MainThread) [custom_components.airthings_ble] Fetching airthings_ble data recovered
2023-03-25 19:49:26.797 INFO (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (B8:27:AA:BB:CC:DD): Bluetooth scanner has gone quiet for 90s, restarting
2023-03-25 19:49:28.808 ERROR (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (B8:27:AA:BB:CC:DD): Error stopping scanner: [org.bluez.Error.InProgress] Operation already in progress
2023-03-25 19:51:26.806 INFO (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (B8:27:AA:BB:CC:DD): Bluetooth scanner has gone quiet for 90s, restarting
2023-03-25 19:51:26.814 ERROR (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (B8:27:AA:BB:CC:DD): Error stopping scanner: [org.bluez.Error.InProgress] Operation already in progress
2023-03-25 19:51:31.836 WARNING (MainThread) [bluetooth_auto_recovery.recover] Bluetooth adapter hci0 [B8:27:AA:BB:CC:DD] could not be reset due to timeout
2023-03-25 19:52:33.312 ERROR (MainThread) [custom_components.airthings_ble] Error fetching airthings_ble data: Unable to fetch data: 'NoneType' object has no attribute 'address'
2023-03-25 19:53:26.817 INFO (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (B8:27:AA:BB:CC:DD): Bluetooth scanner has gone quiet for 90s, restarting
2023-03-25 19:53:26.825 ERROR (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (B8:27:AA:BB:CC:DD): Error stopping scanner: [org.bluez.Error.NotReady] Resource Not Ready
2023-03-25 19:53:31.853 WARNING (MainThread) [bluetooth_auto_recovery.recover] Bluetooth adapter hci0 [B8:27:AA:BB:CC:DD] could not be reset due to timeout
2023-03-25 19:53:31.868 ERROR (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (B8:27:AA:BB:CC:DD): Failed to restart Bluetooth scanner: hci0 (B8:27:AA:BB:CC:DD): Failed to start Bluetooth: [org.bluez.Error.NotReady] Resource Not Ready
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/bluetooth/scanner.py", line 219, in _async_start
    await self.scanner.start()  # type: ignore[no-untyped-call]
  File "/usr/local/lib/python3.10/site-packages/bleak/__init__.py", line 156, in start
    await self._backend.start()
  File "/usr/local/lib/python3.10/site-packages/bleak/backends/bluezdbus/scanner.py", line 191, in start
    self._stop = await manager.active_scan(
  File "/usr/local/lib/python3.10/site-packages/bleak/backends/bluezdbus/manager.py", line 357, in active_scan
    assert_reply(reply)
  File "/usr/local/lib/python3.10/site-packages/bleak/backends/bluezdbus/utils.py", line 20, in assert_reply
    raise BleakDBusError(reply.error_name, reply.body)
bleak.exc.BleakDBusError: [org.bluez.Error.NotReady] Resource Not Ready

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/bluetooth/scanner.py", line 346, in _async_restart_scanner
    await self._async_start()
  File "/usr/src/homeassistant/homeassistant/components/bluetooth/scanner.py", line 301, in _async_start
    raise ScannerStartError(
homeassistant.components.bluetooth.scanner.ScannerStartError: hci0 (B8:27:AA:BB:CC:DD): Failed to start Bluetooth: [org.bluez.Error.NotReady] Resource Not Ready
2023-03-25 19:53:56.818 INFO (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (B8:27:AA:BB:CC:DD): Bluetooth scanner has gone quiet for 90s, restarting
2023-03-25 19:54:01.842 WARNING (MainThread) [bluetooth_auto_recovery.recover] Bluetooth adapter hci0 [B8:27:AA:BB:CC:DD] could not be reset due to timeout
2023-03-25 19:54:06.872 WARNING (MainThread) [bluetooth_auto_recovery.recover] Bluetooth adapter hci0 [B8:27:AA:BB:CC:DD] could not be reset due to timeout
2023-03-25 19:54:06.888 ERROR (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (B8:27:AA:BB:CC:DD): Failed to restart Bluetooth scanner: hci0 (B8:27:AA:BB:CC:DD): Failed to start Bluetooth: [org.bluez.Error.NotReady] Resource Not Ready
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/bluetooth/scanner.py", line 219, in _async_start
    await self.scanner.start()  # type: ignore[no-untyped-call]
  File "/usr/local/lib/python3.10/site-packages/bleak/__init__.py", line 156, in start
    await self._backend.start()
  File "/usr/local/lib/python3.10/site-packages/bleak/backends/bluezdbus/scanner.py", line 191, in start
    self._stop = await manager.active_scan(
  File "/usr/local/lib/python3.10/site-packages/bleak/backends/bluezdbus/manager.py", line 357, in active_scan
    assert_reply(reply)
  File "/usr/local/lib/python3.10/site-packages/bleak/backends/bluezdbus/utils.py", line 20, in assert_reply
    raise BleakDBusError(reply.error_name, reply.body)
bleak.exc.BleakDBusError: [org.bluez.Error.NotReady] Resource Not Ready

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/bluetooth/scanner.py", line 346, in _async_restart_scanner
    await self._async_start()
  File "/usr/src/homeassistant/homeassistant/components/bluetooth/scanner.py", line 301, in _async_start
    raise ScannerStartError(
homeassistant.components.bluetooth.scanner.ScannerStartError: hci0 (B8:27:AA:BB:CC:DD): Failed to start Bluetooth: [org.bluez.Error.NotReady] Resource Not Ready
2023-03-25 19:54:26.819 INFO (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (B8:27:AA:BB:CC:DD): Bluetooth scanner has gone quiet for 90s, restarting
2023-03-25 19:54:29.060 WARNING (MainThread) [bluetooth_auto_recovery.recover] Bluetooth adapter hci0 [B8:27:AA:BB:CC:DD] successfully turned back ON
2023-03-25 19:54:46.171 INFO (MainThread) [custom_components.airthings_ble] Fetching airthings_ble data recovered
2023-03-25 19:57:48.175 INFO (MainThread) [custom_components.airthings_ble] Fetching airthings_ble data recovered
2023-03-25 20:22:26.939 INFO (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (B8:27:AA:BB:CC:DD): Bluetooth scanner has gone quiet for 90s, restarting
2023-03-25 20:22:28.968 ERROR (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (B8:27:AA:BB:CC:DD): Error stopping scanner: [org.bluez.Error.InProgress] Operation already in progress
2023-03-25 20:23:26.310 ERROR (MainThread) [custom_components.airthings_ble] Error fetching airthings_ble data: Unable to fetch data: 'NoneType' object has no attribute 'address'
2023-03-25 20:24:26.949 INFO (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (B8:27:AA:BB:CC:DD): Bluetooth scanner has gone quiet for 90s, restarting
2023-03-25 20:24:26.957 ERROR (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (B8:27:AA:BB:CC:DD): Error stopping scanner: [org.bluez.Error.InProgress] Operation already in progress
2023-03-25 20:24:31.978 WARNING (MainThread) [bluetooth_auto_recovery.recover] Bluetooth adapter hci0 [B8:27:AA:BB:CC:DD] could not be reset due to timeout
2023-03-25 20:25:34.442 ERROR (MainThread) [custom_components.airthings_ble] Error fetching airthings_ble data: Unable to fetch data: 'NoneType' object has no attribute 'address'
2023-03-25 20:26:26.959 INFO (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (B8:27:AA:BB:CC:DD): Bluetooth scanner has gone quiet for 90s, restarting
2023-03-25 20:26:26.970 ERROR (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (B8:27:AA:BB:CC:DD): Error stopping scanner: [org.bluez.Error.NotReady] Resource Not Ready
2023-03-25 20:26:29.187 WARNING (MainThread) [bluetooth_auto_recovery.recover] Bluetooth adapter hci0 [B8:27:AA:BB:CC:DD] successfully turned back ON
2023-03-25 20:28:34.141 INFO (MainThread) [custom_components.airthings_ble] Fetching airthings_ble data recovered
2023-03-25 20:30:42.165 INFO (MainThread) [custom_components.airthings_ble] Fetching airthings_ble data recovered
2023-03-25 20:49:57.065 INFO (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (B8:27:AA:BB:CC:DD): Bluetooth scanner has gone quiet for 90s, restarting
2023-03-25 20:49:59.079 ERROR (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (B8:27:AA:BB:CC:DD): Error stopping scanner: [org.bluez.Error.InProgress] Operation already in progress
2023-03-25 20:51:57.076 INFO (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (B8:27:AA:BB:CC:DD): Bluetooth scanner has gone quiet for 90s, restarting
2023-03-25 20:51:57.087 ERROR (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (B8:27:AA:BB:CC:DD): Error stopping scanner: [org.bluez.Error.InProgress] Operation already in progress
2023-03-25 20:52:02.116 WARNING (MainThread) [bluetooth_auto_recovery.recover] Bluetooth adapter hci0 [B8:27:AA:BB:CC:DD] could not be reset due to timeout
2023-03-25 20:53:57.087 INFO (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (B8:27:AA:BB:CC:DD): Bluetooth scanner has gone quiet for 90s, restarting
2023-03-25 20:53:57.096 ERROR (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (B8:27:AA:BB:CC:DD): Error stopping scanner: [org.bluez.Error.NotReady] Resource Not Ready
2023-03-25 20:54:02.118 WARNING (MainThread) [bluetooth_auto_recovery.recover] Bluetooth adapter hci0 [B8:27:AA:BB:CC:DD] could not be reset due to timeout
2023-03-25 20:54:07.148 WARNING (MainThread) [bluetooth_auto_recovery.recover] Bluetooth adapter hci0 [B8:27:AA:BB:CC:DD] could not be reset due to timeout
2023-03-25 20:54:07.164 ERROR (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (B8:27:AA:BB:CC:DD): Failed to restart Bluetooth scanner: hci0 (B8:27:AA:BB:CC:DD): Failed to start Bluetooth: [org.bluez.Error.NotReady] Resource Not Ready
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/bluetooth/scanner.py", line 219, in _async_start
    await self.scanner.start()  # type: ignore[no-untyped-call]
  File "/usr/local/lib/python3.10/site-packages/bleak/__init__.py", line 156, in start
    await self._backend.start()
  File "/usr/local/lib/python3.10/site-packages/bleak/backends/bluezdbus/scanner.py", line 191, in start
    self._stop = await manager.active_scan(
  File "/usr/local/lib/python3.10/site-packages/bleak/backends/bluezdbus/manager.py", line 357, in active_scan
    assert_reply(reply)
  File "/usr/local/lib/python3.10/site-packages/bleak/backends/bluezdbus/utils.py", line 20, in assert_reply
    raise BleakDBusError(reply.error_name, reply.body)
bleak.exc.BleakDBusError: [org.bluez.Error.NotReady] Resource Not Ready

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/bluetooth/scanner.py", line 346, in _async_restart_scanner
    await self._async_start()
  File "/usr/src/homeassistant/homeassistant/components/bluetooth/scanner.py", line 301, in _async_start
    raise ScannerStartError(
homeassistant.components.bluetooth.scanner.ScannerStartError: hci0 (B8:27:AA:BB:CC:DD): Failed to start Bluetooth: [org.bluez.Error.NotReady] Resource Not Ready
2023-03-25 20:54:27.088 INFO (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (B8:27:AA:BB:CC:DD): Bluetooth scanner has gone quiet for 90s, restarting
2023-03-25 20:54:27.261 WARNING (MainThread) [bluetooth_auto_recovery.recover] Bluetooth adapter hci0 [B8:27:AA:BB:CC:DD] successfully turned back ON
2023-03-25 20:54:55.152 INFO (MainThread) [custom_components.airthings_ble] Fetching airthings_ble data recovered
2023-03-25 20:55:17.162 INFO (MainThread) [custom_components.airthings_ble] Fetching airthings_ble data recovered
2023-03-25 20:56:52.185 INFO (MainThread) [custom_components.airthings_ble] Fetching airthings_ble data recovered
2023-03-25 21:15:21.454 ERROR (MainThread) [custom_components.airthings_ble] Error fetching airthings_ble data: Unable to fetch data:
2023-03-25 22:47:27.673 INFO (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (B8:27:AA:BB:CC:DD): Bluetooth scanner has gone quiet for 90s, restarting
2023-03-25 22:47:27.684 ERROR (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (B8:27:AA:BB:CC:DD): Error stopping scanner: [org.bluez.Error.InProgress] Operation already in progress
2023-03-25 22:48:22.311 ERROR (MainThread) [custom_components.airthings_ble] Error fetching airthings_ble data: Unable to fetch data: 'NoneType' object has no attribute 'address'
2023-03-25 22:49:27.682 INFO (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (B8:27:AA:BB:CC:DD): Bluetooth scanner has gone quiet for 90s, restarting
2023-03-25 22:49:27.691 ERROR (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (B8:27:AA:BB:CC:DD): Error stopping scanner: [org.bluez.Error.InProgress] Operation already in progress
2023-03-25 22:49:32.711 WARNING (MainThread) [bluetooth_auto_recovery.recover] Bluetooth adapter hci0 [B8:27:AA:BB:CC:DD] could not be reset due to timeout
2023-03-25 22:49:32.906 WARNING (MainThread) [bluetooth_auto_recovery.recover] Bluetooth adapter hci0 [B8:27:AA:BB:CC:DD] successfully turned back ON
2023-03-25 22:53:35.152 INFO (MainThread) [custom_components.airthings_ble] Fetching airthings_ble data recovered

Additional information

No response

bdraco commented 1 year ago

You might have better luck with https://github.com/home-assistant/operating-system/releases/tag/10.0.rc1

hejllukas commented 1 year ago

Thank you. I tried updating HA OS to 10.0.rc1 with leaving HA Core at 2023.3.6. Unfortunately, this issue is still there. The only difference is that the stack trace in scanner.py (that is in the attached log in the first message) no longer appears in the log.

bdraco commented 1 year ago

I expect your adapter is getting overloaded.

https://www.home-assistant.io/integrations/bluetooth/

Cypress based adapters Raspberry Pi 3B+ (CYW43455) Raspberry Pi 4B (CYW43455) These adapters are connected via the UART bus which may limit their performance.

You can try switching to passive scanning to reduce the load on it.

https://www.home-assistant.io/integrations/bluetooth/#passive-scanning

If its not enough to get it stable you'll likely need to replace it with one on the high performance list that is USB and not UART connected:

https://www.home-assistant.io/integrations/bluetooth/#known-working-high-performance-adapters

or an ethernet connected esp32 proxy:

https://www.home-assistant.io/integrations/bluetooth/#remote-adapters-bluetooth-proxies

hejllukas commented 1 year ago

Thank you for your response. I tried to switch on passive scanning, and it behaves exactly the same. I was thinking about an overloaded adapter, as you wrote, and you are probably right. I use the RPI Bluetooth adapter for two devices, one updates data just once, and another sometimes randomly stops updating data and starts to work only after restarting HA. Also, when I try to count the number of Bluetooth devices inside my house (not connected to RPI or HA), it is quite a big number.

So thank you for pointing me to known working Bluetooth adapters. I checked resellers in my country, and I ordered ORICO BTA-409. I should get it tomorrow, so I will try to use it instead of the RPI Bluetooth adapter and report back. And If everything will be ok, I will close this issue.

hejllukas commented 1 year ago

I tried the new bluetooth adapter for 24 hours, and everything is working without any issues. Even the stability of the second device improved. With RPI bluetooth adapter, there were a few missed data updates for a second sensor, and because of that, sometimes the current values weren't shown. Now both sensors run for 24 hours without any issues or missed data updates.

Thank you very much for your help and for pointing me to where the real problem was.

So I'm closing this issue.