core: bluetooth integration constant state of initializing / retrying setup (bluetooth is broken with some adapters on newer linux kernels, kernel must be manually patched, workaround is to switch to ESPHome proxies instead)

Mod Issue Summary - Read First

See https://lore.kernel.org/linux-bluetooth/0de3f0d0d5eb6d83cfc8d90cbb2b1ba1@agner.ch/T/#mb094e06d495879436ce9a8722ad7ad87527ea74b

A summary:


The problem

Bluetooth integration in perpetual state of initializing / retrying setup. Deleting integration, restarting HA and configuring after auto discovered, several times, does not resolve.

What version of Home Assistant Core has the issue?

core-2023.4.6

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

Link to integration documentation on our website

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

Diagnostics information

home-assistant_bluetooth_2023-05-02T22-28-03.303Z.log

Example YAML snippet

No response

Anything in the logs that might be useful for us?

Retrying setup: hci0 (XXXXX): Failed to start Bluetooth: [org.bluez.Error.InProgress] Operation already in progress

Logger: bluetooth_auto_recovery.recover
Source: components/bluetooth/util.py:78
First occurred: 5:36:41 PM (28 occurrences)
Last logged: 5:52:42 PM

Bluetooth adapter hci0 [XXXXXXXX] could not be reset due to timeout


Logger: homeassistant.config_entries
Source: config_entries.py:1242
First occurred: 5:44:58 PM (4 occurrences)
Last logged: 5:51:51 PM

Config entry 'XXXXX' for bluetooth integration not ready yet: hci0 (XXXXX): Failed to start Bluetooth: [org.bluez.Error.InProgress] Operation already in progress; Retrying in background

Additional information

Home Assistant Yellow

System Information

version core-2023.4.6
installation_type Home Assistant OS
dev false
hassio true
docker true
user root
virtualenv false
python_version 3.10.10
os_name Linux
os_version 6.1.21-v8
arch aarch64
timezone America/Chicago
config_dir /config
Home Assistant Community Store
GitHub API ok
GitHub Content ok
GitHub Web ok
GitHub API Calls Remaining 4929
Installed Version 1.32.1
Stage running
Available Repositories 1278
Downloaded Repositories 10
Home Assistant Cloud
logged_in true
subscription_expiration May 3, 2023 at 7:00 PM
relayer_connected true
relayer_region us-east-1
remote_enabled true
remote_connected true
alexa_enabled false
google_enabled false
remote_server us-east-1-7.ui.nabu.casa
can_reach_cert_server ok
can_reach_cloud_auth ok
can_reach_cloud ok
Home Assistant Supervisor
host_os Home Assistant OS 10.1
update_channel stable
supervisor_version supervisor-2023.04.1
agent_version 1.5.1
docker_version 23.0.3
disk_total 234.0 GB
disk_used 9.6 GB
healthy true
supported true
board yellow
supervisor_api ok
version_api ok
installed_addons Mosquitto broker (6.2.1), Studio Code Server (5.5.7), Terminal & SSH (9.7.0), Network UPS Tools (0.11.2)
Dashboards
dashboards 3
resources 6
views 6
mode storage
Recorder
oldest_recorder_run April 24, 2023 at 3:54 AM
current_recorder_run May 2, 2023 at 5:36 PM
estimated_db_size 652.32 MiB
database_engine sqlite
database_version 3.38.5

About this issue

  • Original URL
  • State: open
  • Created a year ago
  • Reactions: 8
  • Comments: 71 (7 by maintainers)

Most upvoted comments

Same here - HA Core 2023.11.1 - Beelink mini S12 -

Running 2023.6.2 and still seeing this issue. Constantly initializing and retrying setup but never actually finishing/working.

I’ve been having the same problem for a week

Also having an issue with Bluetooth, since I upgraded to 2024.1.4 (the issue is still present in 2024.1.5).

I’m on a Rasberry Pi 4

Core 2024.1.5 Supervisor 2023.12.1 Operating System 11.4 Frontend 20240104.0

CleanShot 2024-01-20 at 23 32 32

CleanShot 2024-01-20 at 23 32 16

The same for me on 2023.7.2, Fedora 38, HA running in a container.

I’ve tried it with multiple different BT adapters as well.

Adding how I was finally able to get HA Yellow running HAOS to correctly use the on-board bluetooth.

  1. Shutdown the Yellow.
  2. Remove USB stick for Root Access.
  3. Restart the yellow.
  4. Re-Add the newly discovered Bluetooth adapter with a MAC address in the UI.

Okay I think I solved my own version of this issue, startup bluetoothctl and try and run scan le. ❯ bluetoothctl
hci0 new_settings: bondable ssp br/edr le secure-conn Agent registered [CHG] Controller 08:BE:AC:35:85:44 Pairable: yes [bluetooth]# scan le Discovery started [CHG] Controller 08:BE:AC:35:85:44 Discovering: yes [NEW] Device 58:93:D8:8A:EA:D3 58-93-D8-8A-EA-D3 [NEW] Device 49:06:87:AC:7D:EF 49-06-87-AC-7D-EF


And whadya know, Home assistant is happy again.

Props / thanks to @hughobrien for the above. While my specific issue was not directly fixed in the same way, it was useful to be able to log in via SSH, and bluetoothctl to get observability into that layer of the stack, and seeing the fix resolve! Cheers!

FYI, I have just installed HA OS version 12.0rc1. The RPi controller has connected without the passive mode, and my device has been reporting without issues for a few hours now. 🤞

I am having the the problem with Bluetooth on a MacMini from 2012 (core duo 2), fails to initialize. Here is some log that might be useful https://gist.github.com/ssbarnea/eb647871942af5a38fe1e17aa7f32ced - the interesting part is " BleakError while starting bluetooth; attempt: (2/3): [org.bluez.Error.InProgress] Operation already in progress"

I have the same problem. HA Core 2023.8.0 su Docker su Linux Debian. Bluetooth adaptor: ZEXMTE The bluetooth works for a couple of days then this error:

Logger: bluetooth_auto_recovery.recover Source: components/bluetooth/util.py:78 First occurred: 26 agosto 2023 alle ore 07:12:19 (9856 occurrences) Last logged: 20:40:51

Could not reset the power state of the Bluetooth adapter hci0 [8C:88:2B:61:2E:3A] due to timeout after 5 seconds Could not cycle the Bluetooth adapter hci0 [8C:88:2B:61:2E:3A]: [Errno 1] Operation not permitted Bluetooth adapter hci0 [8C:88:2B:61:2E:3A] could not be reset: Closing Bluetooth adapter hci0 [8C:88:2B:61:2E:3A] failed: [Errno 9] Bad file descriptor

I can confirm ESP32 Bluetooth Proxy to be a workable solution for me.

For those who wonder how this is done:

  1. I purchase an ESP32 Development Board
  2. Install driver
  3. Flash the board with https://esphome.github.io/bluetooth-proxies/
  4. Follow the steps in esphome - Add to home assistant
  5. Update to HA OS 10.4, Core 2023.8.2
  6. Reboot Intel NUC
  7. (At this point my bluetooth devices are still connected, but hci0 is still unavailable)
  8. Remove existing Bluetooth device integration
  9. (Bluetooth device is still working)

Mine worked for a couple days, then this week’s update seemed to break. Retrying setup: hci0 (REDACTED): Failed to start Bluetooth: [org.bluez.Error.NotReady] Resource Not Ready

Logger: homeassistant.config_entries
Source: config_entries.py:1287
First occurred: 6:19:30 PM (1 occurrences)
Last logged: 6:19:30 PM

Config entry 'D8:3A:DD:09:0A:FF' for bluetooth integration not ready yet: hci0 (D8:3A:DD:09:0A:FF): Failed to start Bluetooth: [org.bluez.Error.NotReady] Resource Not Ready; Retrying in background
Logger: bluetooth_auto_recovery.recover
Source: components/bluetooth/util.py:78
First occurred: 6:19:25 PM (11 occurrences)
Last logged: 6:21:27 PM

Could not cycle the Bluetooth adapter hci0 [D8:3A:DD:09:0A:FF]: [Errno 110] Operation timed out
Bluetooth adapter hci0 [D8:3A:DD:09:0A:FF] could not be reset due to timeout after 5 seconds
2023-05-26 18:26:03.410 WARNING (MainThread) [bluetooth_auto_recovery.recover] Could not cycle the Bluetooth adapter hci0 [REDACTED]: [Errno 110] Operation timed out
2023-05-26 18:26:08.414 WARNING (MainThread) [bluetooth_auto_recovery.recover] Bluetooth adapter hci0 [REDACTED] could not be reset due to timeout after 5 seconds
2023-05-26 18:26:08.418 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Executing USB reset for Bluetooth adapter hci0
2023-05-26 18:26:08.429 DEBUG (MainThread) [bluetooth_auto_recovery.recover] hci0 is not a USB devices while attempting USB reset: ttyS0 is not a USB device
2023-05-26 18:26:08.431 DEBUG (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (REDACTED): adapter reset result: False
2023-05-26 18:26:08.431 DEBUG (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (REDACTED): Starting bluetooth discovery attempt: (2/3)
2023-05-26 18:26:08.434 DEBUG (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (REDACTED): BleakError while starting bluetooth; attempt: (2/3): [org.bluez.Error.NotReady] Resource Not Ready
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/bluetooth/scanner.py", line 223, in _async_start
    await self.scanner.start()  # type: ignore[no-untyped-call]
  File "/usr/local/lib/python3.10/site-packages/bleak/__init__.py", line 182, 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 22, in assert_reply
    raise BleakDBusError(reply.error_name, reply.body)
bleak.exc.BleakDBusError: [org.bluez.Error.NotReady] Resource Not Ready
2023-05-26 18:26:08.440 WARNING (MainThread) [homeassistant.config_entries] Config entry 'REDACTED' for bluetooth integration not ready yet: hci0 (REDACTED): Failed to start Bluetooth: [org.bluez.Error.NotReady] Resource Not Ready; Retrying in background
2023-05-26 18:26:14.510 DEBUG (MainThread) [homeassistant.components.bluetooth.scanner] Initializing bluetooth scanner with {'detection_callback': <bound method HaScanner._async_detection_callback of <homeassistant.components.bluetooth.scanner.HaScanner object at 0x7f4e9d0700>>, 'scanning_mode': 'active', 'adapter': 'hci0'}
2023-05-26 18:26:14.511 DEBUG (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (REDACTED): Starting bluetooth discovery attempt: (1/3)
2023-05-26 18:26:14.523 DEBUG (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (REDACTED): adapter stopped responding; executing reset
2023-05-26 18:26:14.523 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Attempting to recover bluetooth adapter hci0 with mac address REDACTED
2023-05-26 18:26:14.523 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Attempting to power cycle bluetooth adapter hci0 [REDACTED]
2023-05-26 18:26:14.534 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding cmd_code as type CmdCode
2023-05-26 18:26:14.536 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding controller_idx as type Controller
2023-05-26 18:26:14.537 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding param_len as type ParamLen
2023-05-26 18:26:14.538 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding event_code as type EvtCode
2023-05-26 18:26:14.539 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding controller_idx as type Controller
2023-05-26 18:26:14.540 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding param_len as type ParamLen
2023-05-26 18:26:14.540 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding command_opcode as type CmdCode
2023-05-26 18:26:14.540 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding status as type Status
2023-05-26 18:26:14.541 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding num_controllers as type IntUL
2023-05-26 18:26:14.541 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding controller_index[i] as type IntUL
2023-05-26 18:26:14.542 DEBUG (MainThread) [btsocket.btmgmt_protocol] Socket Read: <event_code=CommandCompleteEvent, controller_idx=65535, param_len=7> <command_opcode=ReadControllerIndexList, status=Success> <num_controllers=1, controller_index[i]=[0]>
2023-05-26 18:26:14.543 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding cmd_code as type CmdCode
2023-05-26 18:26:14.543 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding controller_idx as type Controller
2023-05-26 18:26:14.544 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding param_len as type ParamLen
2023-05-26 18:26:14.545 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding event_code as type EvtCode
2023-05-26 18:26:14.546 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding controller_idx as type Controller
2023-05-26 18:26:14.547 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding param_len as type ParamLen
2023-05-26 18:26:14.547 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding command_opcode as type CmdCode
2023-05-26 18:26:14.547 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding status as type Status
2023-05-26 18:26:14.548 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding address as type Address
2023-05-26 18:26:14.548 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding bluetooth_version as type IntUL
2023-05-26 18:26:14.549 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding manufacturer as type IntUL
2023-05-26 18:26:14.549 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding supported_settings as type IntUL
2023-05-26 18:26:14.550 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding current_settings as type CurrentSettings
2023-05-26 18:26:14.550 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding class_of_device as type IntUL
2023-05-26 18:26:14.550 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding name as type Name
2023-05-26 18:26:14.551 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding short_name as type IntUL
2023-05-26 18:26:14.551 DEBUG (MainThread) [btsocket.btmgmt_protocol] Socket Read: <event_code=CommandCompleteEvent, controller_idx=0, param_len=283> <command_opcode=ReadControllerInformation, status=Success> <address=REDACTED, bluetooth_version=9, manufacturer=305, supported_settings=114431, current_settings={Powered: False, Connectable: False, FastConnectable: False, Discoverable: False, Bondable: False, LinkLevelSecurity: False, SecureSimplePairing: True, BREDR: True, HighSpeed: False, LowEnergy: True, Advertising: False, SecureConnections: True, DebugKeys: False, Privacy: False, ControllerConfiguration: False, StaticAddress: False, PHYConfiguration: False, WidebandSpeech: False}, class_of_device=0, name=b'ha.nbtx.us', short_name=0>
2023-05-26 18:26:14.552 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Response(header=<event_code=CommandCompleteEvent, controller_idx=0, param_len=283>, event_frame=<command_opcode=ReadControllerInformation, status=Success>, cmd_response_frame=<address=REDACTED, bluetooth_version=9, manufacturer=305, supported_settings=114431, current_settings={Powered: False, Connectable: False, FastConnectable: False, Discoverable: False, Bondable: False, LinkLevelSecurity: False, SecureSimplePairing: True, BREDR: True, HighSpeed: False, LowEnergy: True, Advertising: False, SecureConnections: True, DebugKeys: False, Privacy: False, ControllerConfiguration: False, StaticAddress: False, PHYConfiguration: False, WidebandSpeech: False}, class_of_device=0, name=b'ha.nbtx.us', short_name=0>)
2023-05-26 18:26:14.552 DEBUG (MainThread) [bluetooth_auto_recovery.recover] hci0 (REDACTED) idx is 0
2023-05-26 18:26:14.557 DEBUG (MainThread) [bluetooth_auto_recovery.recover] rfkill_idx of hci0 is 1
2023-05-26 18:26:14.557 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Attempting to power cycle bluetooth adapter hci0 [REDACTED]
2023-05-26 18:26:14.557 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding cmd_code as type CmdCode
2023-05-26 18:26:14.558 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding controller_idx as type Controller
2023-05-26 18:26:14.559 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding param_len as type ParamLen
2023-05-26 18:26:14.561 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding event_code as type EvtCode
2023-05-26 18:26:14.561 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding controller_idx as type Controller
2023-05-26 18:26:14.562 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding param_len as type ParamLen
2023-05-26 18:26:14.562 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding command_opcode as type CmdCode
2023-05-26 18:26:14.563 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding status as type Status
2023-05-26 18:26:14.563 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding address as type Address
2023-05-26 18:26:14.564 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding bluetooth_version as type IntUL
2023-05-26 18:26:14.564 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding manufacturer as type IntUL
2023-05-26 18:26:14.565 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding supported_settings as type IntUL
2023-05-26 18:26:14.565 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding current_settings as type CurrentSettings
2023-05-26 18:26:14.566 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding class_of_device as type IntUL
2023-05-26 18:26:14.566 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding name as type Name
2023-05-26 18:26:14.567 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding short_name as type IntUL
2023-05-26 18:26:14.567 DEBUG (MainThread) [btsocket.btmgmt_protocol] Socket Read: <event_code=CommandCompleteEvent, controller_idx=0, param_len=283> <command_opcode=ReadControllerInformation, status=Success> <address=REDACTED, bluetooth_version=9, manufacturer=305, supported_settings=114431, current_settings={Powered: False, Connectable: False, FastConnectable: False, Discoverable: False, Bondable: False, LinkLevelSecurity: False, SecureSimplePairing: True, BREDR: True, HighSpeed: False, LowEnergy: True, Advertising: False, SecureConnections: True, DebugKeys: False, Privacy: False, ControllerConfiguration: False, StaticAddress: False, PHYConfiguration: False, WidebandSpeech: False}, class_of_device=0, name=b'ha.nbtx.us', short_name=0>
2023-05-26 18:26:14.570 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Current power state of bluetooth adapter hci0 [REDACTED] is OFF, trying to turn it back ON
2023-05-26 18:26:14.581 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Bouncing Bluetooth adapter hci0
2023-05-26 18:26:14.581 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Setting hci0 down
2023-05-26 18:26:15.085 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Setting hci0 up
2023-05-26 18:26:17.107 WARNING (MainThread) [bluetooth_auto_recovery.recover] Could not cycle the Bluetooth adapter hci0 [REDACTED]: [Errno 110] Operation timed out
2023-05-26 18:26:17.110 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding powered as type IntUL
2023-05-26 18:26:17.111 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding cmd_code as type CmdCode
2023-05-26 18:26:17.112 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding controller_idx as type Controller
2023-05-26 18:26:17.113 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding param_len as type ParamLen
2023-05-26 18:26:19.153 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding event_code as type EvtCode
2023-05-26 18:26:19.154 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding controller_idx as type Controller
2023-05-26 18:26:19.156 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding param_len as type ParamLen
2023-05-26 18:26:19.156 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding command_opcode as type CmdCode
2023-05-26 18:26:19.157 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding status as type Status
2023-05-26 18:26:19.158 DEBUG (MainThread) [btsocket.btmgmt_protocol] Socket read <event_code=CommandStatusEvent, controller_idx=0, param_len=3> <command_opcode=SetPowered, status=AuthenticationFailed>

Seems like it’s fixed here in the latest update from yesterday… mine is not flapping after the update restart 👍