core
core copied to clipboard
home-assistant
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/[email protected]/T/#mb094e06d495879436ce9a8722ad7ad87527ea74b
A summary:
- Bluetooth initialization is unreliable/broken on newer linux kernels for a large sample of adapters
- No fixes are available without patching the kernel and it will likely be a LONG time before debian updates the kernel, if you want to manually compile and patch your kernel, see https://lore.kernel.org/linux-bluetooth/CABBYNZ+5RMqNVMyYKi+gOVaV+K6k8Z-C37KnfGa=qRUORc3dWg@mail.gmail.com/ https://github.com/home-assistant/operating-system/pull/2714
- Newer Home Assistant OS has some patches that solves the problem for some adapters so be sure you have the latest HAOS: https://github.com/home-assistant/operating-system/issues/2485 https://github.com/home-assistant/operating-system/issues/2535
- The recommended workaround if you can't run HAOS or patch the kernel manually is to use an ESPHome proxy instead https://esphome.github.io/bluetooth-proxies/
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 |
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!
Code owner commands
Code owners of bluetooth can trigger bot actions by commenting:
-
@home-assistant closeCloses the issue. -
@home-assistant rename Awesome new titleRenames the issue. -
@home-assistant reopenReopen the issue. -
@home-assistant unassign bluetoothRemoves the current integration label and assignees on the issue, add the integration domain after the command.
(message by CodeOwnersMention)
bluetooth documentation bluetooth source (message by IssueLinks)
![home-assistant[bot] avatar](https://avatars.githubusercontent.com/in/97978?v=4 "Published by a pub.dev verified publisher"){kind=small}
This issue seems to have begun in 2023.05 release. Logs enclosed.
Logger: homeassistant.components.bluetooth.scanner
Source: components/bluetooth/scanner.py:305
Integration: Bluetooth (documentation, issues)
First occurred: 20:10:15 (15 occurrences)
Last logged: 20:17:20
hci0 (XX:XX:XX:XX:XX:XX): Failed to restart Bluetooth scanner: hci0 (XX:XX:XX:XX:XX:XX): Failed to start Bluetooth: [org.bluez.Error.InProgress] Operation already in progress
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 368, 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.InProgress] Operation already in progress
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 350, in _async_restart_scanner
await self._async_start()
File "/usr/src/homeassistant/homeassistant/components/bluetooth/scanner.py", line 305, in _async_start
raise ScannerStartError(
homeassistant.components.bluetooth.scanner.ScannerStartError: hci0 (XX:XX:XX:XX:XX:XX): Failed to start Bluetooth: [org.bluez.Error.InProgress] Operation already in progress
Same here, I'm also getting the following, not sure if related.
OS Version: Home Assistant OS 10.1 Home Assistant Core: 2023.5.1
[core-ssh ~]$ ha core check
Processing... Done.
Error: Testing configuration at /config
INFO:homeassistant.util.package:Attempting install of pybluez==0.22
ERROR:homeassistant.util.package:Unable to install package pybluez==0.22: error: subprocess-exited-with-error
× python setup.py bdist_wheel did not run successfully.
│ exit code: 1
╰─> [19 lines of output]
running bdist_wheel
running build
running build_py
creating build
creating build/lib.linux-aarch64-cpython-311
creating build/lib.linux-aarch64-cpython-311/bluetooth
copying bluetooth/ble.py -> build/lib.linux-aarch64-cpython-311/bluetooth
copying bluetooth/osx.py -> build/lib.linux-aarch64-cpython-311/bluetooth
copying bluetooth/widcomm.py -> build/lib.linux-aarch64-cpython-311/bluetooth
copying bluetooth/btcommon.py -> build/lib.linux-aarch64-cpython-311/bluetooth
copying bluetooth/__init__.py -> build/lib.linux-aarch64-cpython-311/bluetooth
copying bluetooth/msbt.py -> build/lib.linux-aarch64-cpython-311/bluetooth
copying bluetooth/bluez.py -> build/lib.linux-aarch64-cpython-311/bluetooth
running build_ext
building 'bluetooth._bluetooth' extension
creating build/temp.linux-aarch64-cpython-311
creating build/temp.linux-aarch64-cpython-311/bluez
gcc -Wsign-compare -DNDEBUG -g -fwrapv -O3 -Wall -fno-semantic-interposition -fno-builtin-malloc -fno-builtin-calloc -fno-builtin-realloc -fno-builtin-free -DTHREAD_STACK_SIZE=0x100000 -fPIC -I./port3 -I/usr/local/include/python3.11 -c bluez/btmodule.c -o build/temp.linux-aarch64-cpython-311/bluez/btmodule.o
error: command 'gcc' failed: No such file or directory
[end of output]
note: This error originates from a subprocess, and is likely not a problem with pip.
ERROR: Failed building wheel for pybluez
ERROR: Could not build wheels for pybluez, which is required to install pyproject.toml-based projects
[notice] A new release of pip is available: 23.1 -> 23.1.2
[notice] To update, run: pip install --upgrade pip
INFO:homeassistant.util.package:Attempting install of pybluez==0.22
ERROR:homeassistant.util.package:Unable to install package pybluez==0.22: error: subprocess-exited-with-error
× python setup.py bdist_wheel did not run successfully.
│ exit code: 1
╰─> [19 lines of output]
running bdist_wheel
running build
running build_py
creating build
creating build/lib.linux-aarch64-cpython-311
creating build/lib.linux-aarch64-cpython-311/bluetooth
copying bluetooth/ble.py -> build/lib.linux-aarch64-cpython-311/bluetooth
copying bluetooth/osx.py -> build/lib.linux-aarch64-cpython-311/bluetooth
copying bluetooth/widcomm.py -> build/lib.linux-aarch64-cpython-311/bluetooth
copying bluetooth/btcommon.py -> build/lib.linux-aarch64-cpython-311/bluetooth
copying bluetooth/__init__.py -> build/lib.linux-aarch64-cpython-311/bluetooth
copying bluetooth/msbt.py -> build/lib.linux-aarch64-cpython-311/bluetooth
copying bluetooth/bluez.py -> build/lib.linux-aarch64-cpython-311/bluetooth
running build_ext
building 'bluetooth._bluetooth' extension
creating build/temp.linux-aarch64-cpython-311
creating build/temp.linux-aarch64-cpython-311/bluez
gcc -Wsign-compare -DNDEBUG -g -fwrapv -O3 -Wall -fno-semantic-interposition -fno-builtin-malloc -fno-builtin-calloc -fno-builtin-realloc -fno-builtin-free -DTHREAD_STACK_SIZE=0x100000 -fPIC -I./port3 -I/usr/local/include/python3.11 -c bluez/btmodule.c -o build/temp.linux-aarch64-cpython-311/bluez/btmodule.o
error: command 'gcc' failed: No such file or directory
[end of output]
note: This error originates from a subprocess, and is likely not a problem with pip.
ERROR: Failed building wheel for pybluez
ERROR: Could not build wheels for pybluez, which is required to install pyproject.toml-based projects
[notice] A new release of pip is available: 23.1 -> 23.1.2
[notice] To update, run: pip install --upgrade pip
INFO:homeassistant.util.package:Attempting install of pybluez==0.22
ERROR:homeassistant.util.package:Unable to install package pybluez==0.22: error: subprocess-exited-with-error
× python setup.py bdist_wheel did not run successfully.
│ exit code: 1
╰─> [19 lines of output]
running bdist_wheel
running build
running build_py
creating build
creating build/lib.linux-aarch64-cpython-311
creating build/lib.linux-aarch64-cpython-311/bluetooth
copying bluetooth/ble.py -> build/lib.linux-aarch64-cpython-311/bluetooth
copying bluetooth/osx.py -> build/lib.linux-aarch64-cpython-311/bluetooth
copying bluetooth/widcomm.py -> build/lib.linux-aarch64-cpython-311/bluetooth
copying bluetooth/btcommon.py -> build/lib.linux-aarch64-cpython-311/bluetooth
copying bluetooth/__init__.py -> build/lib.linux-aarch64-cpython-311/bluetooth
copying bluetooth/msbt.py -> build/lib.linux-aarch64-cpython-311/bluetooth
copying bluetooth/bluez.py -> build/lib.linux-aarch64-cpython-311/bluetooth
running build_ext
building 'bluetooth._bluetooth' extension
creating build/temp.linux-aarch64-cpython-311
creating build/temp.linux-aarch64-cpython-311/bluez
gcc -Wsign-compare -DNDEBUG -g -fwrapv -O3 -Wall -fno-semantic-interposition -fno-builtin-malloc -fno-builtin-calloc -fno-builtin-realloc -fno-builtin-free -DTHREAD_STACK_SIZE=0x100000 -fPIC -I./port3 -I/usr/local/include/python3.11 -c bluez/btmodule.c -o build/temp.linux-aarch64-cpython-311/bluez/btmodule.o
error: command 'gcc' failed: No such file or directory
[end of output]
note: This error originates from a subprocess, and is likely not a problem with pip.
ERROR: Failed building wheel for pybluez
ERROR: Could not build wheels for pybluez, which is required to install pyproject.toml-based projects
[notice] A new release of pip is available: 23.1 -> 23.1.2
[notice] To update, run: pip install --upgrade pip
Failed config
General Errors:
- Platform error device_tracker.bluetooth_tracker - Requirements for bluetooth_tracker not found: ['pybluez==0.22'].
Successful config (partial)
[core-ssh ~]$
+1
Logger: homeassistant.components.bluetooth.scanner
Source: components/bluetooth/scanner.py:305
Integration: Bluetooth (documentation, issues)
First occurred: 14:10:14 (95 occurrences)
Last logged: 14:57:19
hci0 (E4:5F:01:68:53:51): Failed to restart Bluetooth scanner: hci0 (E4:5F:01:68:53:51): Failed to start Bluetooth: [org.bluez.Error.InProgress] Operation already in progress
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 368, 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.InProgress] Operation already in progress
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 350, in _async_restart_scanner
await self._async_start()
File "/usr/src/homeassistant/homeassistant/components/bluetooth/scanner.py", line 305, in _async_start
raise ScannerStartError(
homeassistant.components.bluetooth.scanner.ScannerStartError: hci0 (E4:5F:01:68:53:51): Failed to start Bluetooth: [org.bluez.Error.InProgress] Operation already in progress
Please see https://github.com/home-assistant/operating-system/issues/2485 https://github.com/home-assistant/operating-system/issues/2535
I fixed this by restoring my Raspberry Pi's /boot/config.txt file back to defaults.
I'm using the Supervised version of HA. I can find a config file in the boot folder, but I don't know what the defaults are. I'm using a debian installation on a Thin Client by the way.
Does anybody know how to fix this?
I'm using the Supervised version of HA. I can find a config file in the boot folder, but I don't know what the defaults are. I'm using a debian installation on a Thin Client by the way.
Does anybody know how to fix this?
Could you please upload here a copy of your /boot/config.txt file? There shouldn't be anything private in it.
I'm using the Supervised version of HA. I can find a config file in the boot folder, but I don't know what the defaults are. I'm using a debian installation on a Thin Client by the way. Does anybody know how to fix this?
Could you please upload here a copy of your /boot/config.txt file? There shouldn't be anything private in it.
I'm using the Supervised version of HA. I can find a config file in the boot folder, but I don't know what the defaults are. I'm using a debian installation on a Thin Client by the way. Does anybody know how to fix this?
Could you please upload here a copy of your /boot/config.txt file? There shouldn't be anything private in it.
Automatically generated file; DO NOT EDIT.
Linux/x86 5.10.178 Kernel Configuration
CONFIG_CC_VERSION_TEXT="gcc-10 (Debian 10.2.1-6) 10.2.1 20210110" CONFIG_CC_IS_GCC=y CONFIG_GCC_VERSION=100201 CONFIG_LD_VERSION=235020000 CONFIG_CLANG_VERSION=0 CONFIG_AS_IS_GNU=y CONFIG_AS_VERSION=23502 CONFIG_LLD_VERSION=0 CONFIG_CC_CAN_LINK=y CONFIG_CC_CAN_LINK_STATIC=y CONFIG_CC_HAS_ASM_GOTO=y CONFIG_CC_HAS_ASM_INLINE=y CONFIG_IRQ_WORK=y CONFIG_BUILDTIME_TABLE_SORT=y CONFIG_THREAD_INFO_IN_TASK=y
3c3
< # Linux/x86 5.10.162 Kernel Configuration
---
> # Linux/x86 5.10.178 Kernel Configuration
9a10,11
> CONFIG_AS_IS_GNU=y
> CONFIG_AS_VERSION=23502
26c28
< CONFIG_BUILD_SALT="5.10.0-21-amd64"
---
> CONFIG_BUILD_SALT="5.10.0-22-amd64"
415c417
< # CONFIG_MICROCODE_OLD_INTERFACE is not set
---
> # CONFIG_MICROCODE_LATE_LOADING is not set
1693d1694
< CONFIG_NET_CLS_TCINDEX=m
just a diff between the 2 boot configs i have in place (standard debian)
[bootconf.txt](https://github.com/home-assistant/core/files/11468300/bootconf.txt)
and here the complete file
Seems like it's fixed here in the latest update from yesterday... mine is not flapping after the update restart 👍
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>
Running 2023.6.2 and still seeing this issue. Constantly initializing and retrying setup but never actually finishing/working.
Just to add my voice to the choir: I've been seeing this since I set up my Yellow about two months ago with the goal of replacing my older RasPi HA setup. Always stay up to date with releases, and this has been a near constant companion.
Same issue for me:
Could not reset the power state of the Bluetooth adapter hci0 due to timeout after 5 seconds Could not cycle the Bluetooth adapter hci0: [Errno 1] Operation not permitted Bluetooth adapter hci0 could not be reset: Closing Bluetooth adapter hci0 failed: [Errno 9] Bad file descriptor.
Home Assistant 2023.7.2
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.
Same issue for me, using an adapter from the recommended documentation: Warmstor WBT-AD01 (CSR8510A10)
Home Assistant 2023.8.1 Supervisor 2023.07.1 Operating System 10.4 Frontend 20230802.0 - latest
Error 1
Logger: bluetooth_auto_recovery.recover Source: components/bluetooth/util.py:78 First occurred: 2:40:08 PM (30 occurrences) Last logged: 2:44:11 PM
Bluetooth adapter hci0 [00:50:56:FB:58:19] could not be reset: Closing Bluetooth adapter hci0 [00:50:56:FB:58:19] failed: [Errno 9] Bad file descriptor Could not determine the power state of the Bluetooth adapter hci0 [00:50:56:FB:58:19] due to timeout after 5 seconds Could not cycle the Bluetooth adapter hci0 [00:50:56:FB:58:19]: [Errno 38] Function not implemented
Error 2
Logger: bluetooth_auto_recovery.recover Source: runner.py:179 First occurred: 2:40:28 PM (7 occurrences) Last logged: 2:44:04 PM
Bluetooth management socket connection lost: [Errno 22] Invalid argument
Error 3
Logger: homeassistant.config_entries Source: config_entries.py:1250 First occurred: 2:42:00 PM (1 occurrences) Last logged: 2:42:00 PM
Config entry '00:50:56:FB:58:19' for bluetooth integration not ready yet: hci0 (00:50:56:FB:58:19): Failed to start Bluetooth: adapter 'hci0' not found; Retrying in background
Newer linux kernels broke bluetooth. HAOS has some patches that will fix some of the adapters but unless you want to patch the kernel, local adapters won't work.
The best option right now is to switch to https://esphome.github.io/bluetooth-proxies/
Newer linux kernels broke bluetooth. HAOS has some patches that will fix some of the adapters but unless you want to patch the kernel, local adapters won't work.
The best option right now is to switch to https://esphome.github.io/bluetooth-proxies/
Yeah I didn't see this issue when I was running Raspberry Pi OS Debian 10 until I upgraded to Debian 11 was when I started getting this problem.
I can confirm ESP32 Bluetooth Proxy to be a workable solution for me.
For those who wonder how this is done:
- I purchase an ESP32 Development Board
- Install driver
- Flash the board with https://esphome.github.io/bluetooth-proxies/
- Follow the steps in esphome - Add to home assistant
- Update to HA OS 10.4, Core 2023.8.2
- Reboot Intel NUC
- (At this point my bluetooth devices are still connected, but hci0 is still unavailable)
- Remove existing Bluetooth device integration
- (Bluetooth device is still working)
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
question
The integrated Bluetooth on the Intel network card is used. When installing HAOS in VMware Workstation Pro in Windows, the HA prompts that a new device has been found, and an error occurs after clicking Configure.
log
Logger: bluetooth_auto_recovery.recover Source: runner.py:186 First occurred: 12:53:30 (31 occurrences) Last logged: 13:28:15
Bluetooth management socket connection lost: [Errno 22] Invalid argument
Logger: bluetooth_auto_recovery.recover Source: components/bluetooth/util.py:78 First occurred: 12:53:28 (124 occurrences) Last logged: 13:28:22
Could not determine the power state of the Bluetooth adapter hci0 [48:F1:7F:65:18:77] due to timeout after 5 seconds Could not cycle the Bluetooth adapter hci0 [48:F1:7F:65:18:77]: [Errno 38] Function not implemented Bluetooth adapter hci0 [48:F1:7F:65:18:77] could not be reset: Closing Bluetooth adapter hci0 [48:F1:7F:65:18:77] failed: [Errno 9] Bad file descriptor
Sep 27 05:20:19 homeassistant systemd[1]: run-docker-runtime\x2drunc-moby-0796d9651f82cbbc4dd7b671837c1afab34aa352a067130b074e6b0afc187146-runc.Nav9wC.mount: Deactivated successfully. Sep 27 05:20:20 homeassistant kernel: debugfs: File 'dut_mode' in directory 'hci0' already present! Sep 27 05:20:20 homeassistant kernel: Bluetooth: hci0: unexpected cc 0x0c12 length: 2 < 3 Sep 27 05:20:20 homeassistant kernel: Bluetooth: hci0: Opcode 0x c12 failed: -38 Sep 27 05:20:25 homeassistant systemd[1]: Stopped target Bluetooth Support. Sep 27 05:20:26 homeassistant kernel: usb 2-2.1: reset full-speed USB device number 4 using uhci_hcd Sep 27 05:20:26 homeassistant systemd[1]: Reached target Bluetooth Support. Sep 27 05:20:26 homeassistant kernel: Bluetooth: hci0: unexpected cc 0x0c12 length: 2 < 3 Sep 27 05:20:26 homeassistant kernel: Bluetooth: hci0: Opcode 0x c12 failed: -38 Sep 27 05:21:49 homeassistant systemd[1]: run-docker-runtime\x2drunc-moby-0796d9651f82cbbc4dd7b671837c1afab34aa352a067130b074e6b0afc187146-runc.AoS8eU.mount: Deactivated successfully. Sep 27 05:21:55 homeassistant kernel: debugfs: File 'dut_mode' in directory 'hci0' already present! Sep 27 05:21:55 homeassistant kernel: Bluetooth: hci0: unexpected cc 0x0c12 length: 2 < 3 Sep 27 05:21:55 homeassistant kernel: Bluetooth: hci0: Opcode 0x c12 failed: -38 Sep 27 05:22:00 homeassistant systemd[1]: Stopped target Bluetooth Support. Sep 27 05:22:01 homeassistant kernel: usb 2-2.1: reset full-speed USB device number 4 using uhci_hcd Sep 27 05:22:01 homeassistant systemd[1]: Reached target Bluetooth Support. Sep 27 05:22:01 homeassistant kernel: Bluetooth: hci0: unexpected cc 0x0c12 length: 2 < 3 Sep 27 05:22:01 homeassistant kernel: Bluetooth: hci0: Opcode 0x c12 failed: -38 Sep 27 05:22:20 homeassistant systemd[1]: run-docker-runtime\x2drunc-moby-0796d9651f82cbbc4dd7b671837c1afab34aa352a067130b074e6b0afc187146-runc.f8Ld6L.mount: Deactivated successfully. Sep 27 05:22:44 homeassistant systemd[1]: run-docker-runtime\x2drunc-moby-9dc6014d7dd4ba6a5d5f48c3dbf210fbd577a2e4a6fa171e13906bd1f5924490-runc.LrE36m.mount: Deactivated successfully. Sep 27 05:23:30 homeassistant kernel: debugfs: File 'dut_mode' in directory 'hci0' already present! Sep 27 05:23:30 homeassistant kernel: Bluetooth: hci0: unexpected cc 0x0c12 length: 2 < 3 Sep 27 05:23:30 homeassistant kernel: Bluetooth: hci0: Opcode 0x c12 failed: -38 Sep 27 05:23:35 homeassistant systemd[1]: Stopped target Bluetooth Support. Sep 27 05:23:36 homeassistant kernel: usb 2-2.1: reset full-speed USB device number 4 using uhci_hcd Sep 27 05:23:36 homeassistant systemd[1]: Reached target Bluetooth Support. Sep 27 05:23:36 homeassistant kernel: Bluetooth: hci0: unexpected cc 0x0c12 length: 2 < 3 Sep 27 05:23:36 homeassistant kernel: Bluetooth: hci0: Opcode 0x c12 failed: -38 Sep 27 05:23:50 homeassistant systemd[1]: run-docker-runtime\x2drunc-moby-0796d9651f82cbbc4dd7b671837c1afab34aa352a067130b074e6b0afc187146-runc.WjDqnN.mount: Deactivated successfully.
