core: Retrying setup: hci0 (49:02:91:02:89:88): Failed to start Bluetooth: [org.bluez.Error.InProgress] Operation already in progress

The problem

Further to https://github.com/home-assistant/core/issues/83673#issuecomment-1356622120 i am on the latest core but i still have an issue with my BT device.

Logger: homeassistant.config_entries
Source: config_entries.py:1113
First occurred: 11:17:54 PM (2 occurrences)
Last logged: 11:19:59 PM

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

Only way i can resolve on a temp basis is by going to terminal and running “bluetoothct1, power off, power on, scan on” and even that doesn’t work sometimes

What version of Home Assistant Core has the issue?

2022.12.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

Link to integration documentation on our website

No response

Diagnostics information

2022-12-19 23:13:29.122 WARNING (SyncWorker_0) [homeassistant.loader] We found a custom integration eufy_security which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant
2022-12-19 23:13:29.125 WARNING (SyncWorker_0) [homeassistant.loader] We found a custom integration whatspie which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant
2022-12-19 23:13:29.130 WARNING (SyncWorker_0) [homeassistant.loader] We found a custom integration tapo_control which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant
2022-12-19 23:13:29.132 WARNING (SyncWorker_0) [homeassistant.loader] We found a custom integration hildebrandglow_dcc which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant
2022-12-19 23:13:29.134 WARNING (SyncWorker_0) [homeassistant.loader] We found a custom integration tapo which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant
2022-12-19 23:13:29.136 WARNING (SyncWorker_0) [homeassistant.loader] We found a custom integration hacs which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant
2022-12-19 23:13:29.138 WARNING (SyncWorker_0) [homeassistant.loader] We found a custom integration sonoff which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant
2022-12-19 23:13:29.141 WARNING (SyncWorker_0) [homeassistant.loader] We found a custom integration localtuya which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant
2022-12-19 23:13:33.861 WARNING (MainThread) [homeassistant.config_entries] Config entry '49:02:91:02:89:88' for bluetooth integration not ready yet: hci0 (49:02:91:02:89:88): Failed to start Bluetooth: [org.bluez.Error.InProgress] Operation already in progress; Retrying in background
2022-12-19 23:13:36.785 ERROR (SyncWorker_7) [homeassistant.components.command_line] Command failed (with return code 1): cat /sys/class/thermal/thermal_zone0/temp
2022-12-19 23:13:42.206 ERROR (MainThread) [homeassistant.components.life360] Amma A: Lost Connection: This user has lost connection to Life360. Visit our troubleshooting guide to help them reconnect.
2022-12-19 23:13:42.208 ERROR (MainThread) [homeassistant.components.life360] Abba: Lost Connection: This user has lost connection to Life360. Visit our troubleshooting guide to help them reconnect.
2022-12-19 23:13:42.209 ERROR (MainThread) [homeassistant.components.life360] Amma: Lost Connection: This user has lost connection to Life360. Visit our troubleshooting guide to help them reconnect.
2022-12-19 23:14:37.049 ERROR (SyncWorker_8) [homeassistant.components.command_line] Command failed (with return code 1): cat /sys/class/thermal/thermal_zone0/temp
2022-12-19 23:15:37.049 ERROR (SyncWorker_6) [homeassistant.components.command_line] Command failed (with return code 1): cat /sys/class/thermal/thermal_zone0/temp
2022-12-19 23:16:37.050 ERROR (SyncWorker_0) [homeassistant.components.command_line] Command failed (with return code 1): cat /sys/class/thermal/thermal_zone0/temp
2022-12-19 23:17:37.050 ERROR (SyncWorker_4) [homeassistant.components.command_line] Command failed (with return code 1): cat /sys/class/thermal/thermal_zone0/temp
2022-12-19 23:17:54.643 WARNING (MainThread) [homeassistant.config_entries] Config entry '49:02:91:02:89:88' for bluetooth integration not ready yet: hci0 (49:02:91:02:89:88): Failed to start Bluetooth: [org.bluez.Error.InProgress] Operation already in progress; Retrying in background
2022-12-19 23:18:37.052 ERROR (SyncWorker_2) [homeassistant.components.command_line] Command failed (with return code 1): cat /sys/class/thermal/thermal_zone0/temp
2022-12-19 23:19:37.053 ERROR (SyncWorker_6) [homeassistant.components.command_line] Command failed (with return code 1): cat /sys/class/thermal/thermal_zone0/temp
2022-12-19 23:19:59.645 WARNING (MainThread) [homeassistant.config_entries] Config entry '49:02:91:02:89:88' for bluetooth integration not ready yet: hci0 (49:02:91:02:89:88): Failed to start Bluetooth: [org.bluez.Error.InProgress] Operation already in progress; Retrying in background
2022-12-19 23:20:37.054 ERROR (SyncWorker_3) [homeassistant.components.command_line] Command failed (with return code 1): cat /sys/class/thermal/thermal_zone0/temp
2022-12-19 23:21:37.055 ERROR (SyncWorker_3) [homeassistant.components.command_line] Command failed (with return code 1): cat /sys/class/thermal/thermal_zone0/temp
2022-12-19 23:22:37.055 ERROR (SyncWorker_6) [homeassistant.components.command_line] Command failed (with return code 1): cat /sys/class/thermal/thermal_zone0/temp
2022-12-19 23:23:37.056 ERROR (SyncWorker_3) [homeassistant.components.command_line] Command failed (with return code 1): cat /sys/class/thermal/thermal_zone0/temp
2022-12-19 23:24:37.058 ERROR (SyncWorker_8) [homeassistant.components.command_line] Command failed (with return code 1): cat /sys/class/thermal/thermal_zone0/temp
2022-12-19 23:25:24.295 WARNING (MainThread) [bluetooth_auto_recovery.recover] Bluetooth adapter hci0 [49:02:91:02:89:88] successfully turned back ON
2022-12-19 23:25:37.059 ERROR (SyncWorker_5) [homeassistant.components.command_line] Command failed (with return code 1): cat /sys/class/thermal/thermal_zone0/temp
2022-12-19 23:25:54.600 WARNING (MainThread) [homeassistant.config_entries] Config entry '49:02:91:02:89:88' for bluetooth integration not ready yet: hci0 (49:02:91:02:89:88): Failed to start Bluetooth: [org.bluez.Error.InProgress] Operation already in progress; Retrying in background
2022-12-19 23:25:58.116 WARNING (MainThread) [homeassistant.config_entries] Config entry '49:02:91:02:89:88' for bluetooth integration not ready yet: hci0 (49:02:91:02:89:88): Failed to start Bluetooth: [org.bluez.Error.InProgress] Operation already in progress; Retrying in background
2022-12-19 23:26:37.059 ERROR (SyncWorker_0) [homeassistant.components.command_line] Command failed (with return code 1): cat /sys/class/thermal/thermal_zone0/temp
2022-12-19 23:27:29.197 WARNING (MainThread) [homeassistant.config_entries] Config entry '49:02:91:02:89:88' for bluetooth integration not ready yet: hci0 (49:02:91:02:89:88): Failed to start Bluetooth: [org.bluez.Error.InProgress] Operation already in progress; Retrying in background
2022-12-19 23:27:37.060 ERROR (SyncWorker_1) [homeassistant.components.command_line] Command failed (with return code 1): cat /sys/class/thermal/thermal_zone0/temp
2022-12-19 23:27:45.804 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 0x7f1fd9d35000>>, 'scanning_mode': 'active', 'adapter': 'hci0'}
2022-12-19 23:27:45.806 DEBUG (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (49:02:91:02:89:88): Starting bluetooth discovery attempt: (1/3)
2022-12-19 23:27:45.831 DEBUG (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (49:02:91:02:89:88): adapter stopped responding; executing reset
2022-12-19 23:27:45.832 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Attempting to recover bluetooth adapter hci0 with mac address 49:02:91:02:89:88
2022-12-19 23:27:45.832 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Attempting to power cycle bluetooth adapter hci0 [49:02:91:02:89:88]
2022-12-19 23:27:45.834 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding cmd_code as type CmdCode
2022-12-19 23:27:45.835 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding controller_idx as type Controller
2022-12-19 23:27:45.836 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding param_len as type ParamLen
2022-12-19 23:27:45.840 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding event_code as type EvtCode
2022-12-19 23:27:45.843 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding controller_idx as type Controller
2022-12-19 23:27:45.853 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding param_len as type ParamLen
2022-12-19 23:27:45.854 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding command_opcode as type CmdCode
2022-12-19 23:27:45.855 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding status as type Status
2022-12-19 23:27:45.858 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding num_controllers as type IntUL
2022-12-19 23:27:45.859 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding controller_index[i] as type IntUL
2022-12-19 23:27:45.861 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]>
2022-12-19 23:27:45.863 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding cmd_code as type CmdCode
2022-12-19 23:27:45.866 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding controller_idx as type Controller
2022-12-19 23:27:45.867 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding param_len as type ParamLen
2022-12-19 23:27:45.869 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding event_code as type EvtCode
2022-12-19 23:27:45.870 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding controller_idx as type Controller
2022-12-19 23:27:45.875 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding param_len as type ParamLen
2022-12-19 23:27:45.876 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding command_opcode as type CmdCode
2022-12-19 23:27:45.879 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding status as type Status
2022-12-19 23:27:45.880 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding address as type Address
2022-12-19 23:27:45.881 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding bluetooth_version as type IntUL
2022-12-19 23:27:45.881 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding manufacturer as type IntUL
2022-12-19 23:27:45.883 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding supported_settings as type IntUL
2022-12-19 23:27:45.883 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding current_settings as type CurrentSettings
2022-12-19 23:27:45.886 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding class_of_device as type IntUL
2022-12-19 23:27:45.887 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding name as type Name
2022-12-19 23:27:45.890 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding short_name as type IntUL
2022-12-19 23:27:45.890 DEBUG (MainThread) [btsocket.btmgmt_protocol] Socket Read: <event_code=CommandCompleteEvent, controller_idx=0, param_len=283> <command_opcode=ReadControllerInformation, status=Success> <address=49:02:91:02:89:88, bluetooth_version=4, manufacturer=15, supported_settings=69887, current_settings={Powered: True, Connectable: False, FastConnectable: False, Discoverable: False, Bondable: False, LinkLevelSecurity: False, SecureSimplePairing: True, BREDR: True, HighSpeed: False, LowEnergy: False, Advertising: False, SecureConnections: False, DebugKeys: False, Privacy: False, ControllerConfiguration: False, StaticAddress: False, PHYConfiguration: False, WidebandSpeech: False}, class_of_device=2883584, name=b'homeassistant', short_name=0>
2022-12-19 23:27:45.891 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=49:02:91:02:89:88, bluetooth_version=4, manufacturer=15, supported_settings=69887, current_settings={Powered: True, Connectable: False, FastConnectable: False, Discoverable: False, Bondable: False, LinkLevelSecurity: False, SecureSimplePairing: True, BREDR: True, HighSpeed: False, LowEnergy: False, Advertising: False, SecureConnections: False, DebugKeys: False, Privacy: False, ControllerConfiguration: False, StaticAddress: False, PHYConfiguration: False, WidebandSpeech: False}, class_of_device=2883584, name=b'homeassistant', short_name=0>)
2022-12-19 23:27:45.892 DEBUG (MainThread) [bluetooth_auto_recovery.recover] hci0 (49:02:91:02:89:88) idx is 0
2022-12-19 23:27:45.895 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Attempting to power cycle bluetooth adapter hci0 [49:02:91:02:89:88]
2022-12-19 23:27:45.895 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding cmd_code as type CmdCode
2022-12-19 23:27:45.899 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding controller_idx as type Controller
2022-12-19 23:27:45.900 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding param_len as type ParamLen
2022-12-19 23:27:45.901 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding event_code as type EvtCode
2022-12-19 23:27:45.901 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding controller_idx as type Controller
2022-12-19 23:27:45.902 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding param_len as type ParamLen
2022-12-19 23:27:45.902 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding command_opcode as type CmdCode
2022-12-19 23:27:45.904 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding status as type Status
2022-12-19 23:27:45.904 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding address as type Address
2022-12-19 23:27:45.905 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding bluetooth_version as type IntUL
2022-12-19 23:27:45.906 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding manufacturer as type IntUL
2022-12-19 23:27:45.906 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding supported_settings as type IntUL
2022-12-19 23:27:45.907 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding current_settings as type CurrentSettings
2022-12-19 23:27:45.908 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding class_of_device as type IntUL
2022-12-19 23:27:45.908 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding name as type Name
2022-12-19 23:27:45.909 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding short_name as type IntUL
2022-12-19 23:27:45.909 DEBUG (MainThread) [btsocket.btmgmt_protocol] Socket Read: <event_code=CommandCompleteEvent, controller_idx=0, param_len=283> <command_opcode=ReadControllerInformation, status=Success> <address=49:02:91:02:89:88, bluetooth_version=4, manufacturer=15, supported_settings=69887, current_settings={Powered: True, Connectable: False, FastConnectable: False, Discoverable: False, Bondable: False, LinkLevelSecurity: False, SecureSimplePairing: True, BREDR: True, HighSpeed: False, LowEnergy: False, Advertising: False, SecureConnections: False, DebugKeys: False, Privacy: False, ControllerConfiguration: False, StaticAddress: False, PHYConfiguration: False, WidebandSpeech: False}, class_of_device=2883584, name=b'homeassistant', short_name=0>
2022-12-19 23:27:45.909 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Current power state of bluetooth adapter is ON.
2022-12-19 23:27:45.910 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding powered as type IntUL
2022-12-19 23:27:45.910 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding cmd_code as type CmdCode
2022-12-19 23:27:45.910 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding controller_idx as type Controller
2022-12-19 23:27:45.910 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding param_len as type ParamLen
2022-12-19 23:27:45.911 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding event_code as type EvtCode
2022-12-19 23:27:45.911 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding controller_idx as type Controller
2022-12-19 23:27:45.912 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding param_len as type ParamLen
2022-12-19 23:27:45.912 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding command_opcode as type CmdCode
2022-12-19 23:27:45.912 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding status as type Status
2022-12-19 23:27:45.912 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding current_settings as type CurrentSettings
2022-12-19 23:27:45.912 DEBUG (MainThread) [btsocket.btmgmt_protocol] Socket Read: <event_code=CommandCompleteEvent, controller_idx=0, param_len=7> <command_opcode=SetPowered, status=Success> <current_settings={Powered: False, Connectable: False, FastConnectable: False, Discoverable: False, Bondable: False, LinkLevelSecurity: False, SecureSimplePairing: True, BREDR: True, HighSpeed: False, LowEnergy: False, Advertising: False, SecureConnections: False, DebugKeys: False, Privacy: False, ControllerConfiguration: False, StaticAddress: False, PHYConfiguration: False, WidebandSpeech: False}>
2022-12-19 23:27:45.913 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding cmd_code as type CmdCode
2022-12-19 23:27:45.913 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding controller_idx as type Controller
2022-12-19 23:27:45.914 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding param_len as type ParamLen
2022-12-19 23:27:45.914 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding event_code as type EvtCode
2022-12-19 23:27:45.914 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding controller_idx as type Controller
2022-12-19 23:27:45.914 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding param_len as type ParamLen
2022-12-19 23:27:45.916 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding class_of_device as type IntUL
2022-12-19 23:27:45.916 DEBUG (MainThread) [btsocket.btmgmt_protocol] Socket read <event_code=ClassOfDeviceChangedEvent, controller_idx=0, param_len=3> <class_of_device=0>
2022-12-19 23:27:45.917 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding event_code as type EvtCode
2022-12-19 23:27:45.917 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding controller_idx as type Controller
2022-12-19 23:27:45.917 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding param_len as type ParamLen
2022-12-19 23:27:45.917 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding command_opcode as type CmdCode
2022-12-19 23:27:45.919 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding status as type Status
2022-12-19 23:27:45.919 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding address as type Address
2022-12-19 23:27:45.919 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding bluetooth_version as type IntUL
2022-12-19 23:27:45.919 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding manufacturer as type IntUL
2022-12-19 23:27:45.920 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding supported_settings as type IntUL
2022-12-19 23:27:45.920 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding current_settings as type CurrentSettings
2022-12-19 23:27:45.920 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding class_of_device as type IntUL
2022-12-19 23:27:45.920 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding name as type Name
2022-12-19 23:27:45.920 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding short_name as type IntUL
2022-12-19 23:27:45.921 DEBUG (MainThread) [btsocket.btmgmt_protocol] Socket Read: <event_code=CommandCompleteEvent, controller_idx=0, param_len=283> <command_opcode=ReadControllerInformation, status=Success> <address=49:02:91:02:89:88, bluetooth_version=4, manufacturer=15, supported_settings=69887, current_settings={Powered: False, Connectable: False, FastConnectable: False, Discoverable: False, Bondable: False, LinkLevelSecurity: False, SecureSimplePairing: True, BREDR: True, HighSpeed: False, LowEnergy: False, Advertising: False, SecureConnections: False, DebugKeys: False, Privacy: False, ControllerConfiguration: False, StaticAddress: False, PHYConfiguration: False, WidebandSpeech: False}, class_of_device=2883584, name=b'homeassistant', short_name=0>
2022-12-19 23:27:45.921 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding powered as type IntUL
2022-12-19 23:27:45.921 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding cmd_code as type CmdCode
2022-12-19 23:27:45.924 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding controller_idx as type Controller
2022-12-19 23:27:45.924 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding param_len as type ParamLen
2022-12-19 23:27:45.974 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding event_code as type EvtCode
2022-12-19 23:27:45.974 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding controller_idx as type Controller
2022-12-19 23:27:45.974 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding param_len as type ParamLen
2022-12-19 23:27:45.975 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding class_of_device as type IntUL
2022-12-19 23:27:45.975 DEBUG (MainThread) [btsocket.btmgmt_protocol] Socket read <event_code=ClassOfDeviceChangedEvent, controller_idx=0, param_len=3> <class_of_device=2883584>
2022-12-19 23:27:45.977 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding event_code as type EvtCode
2022-12-19 23:27:45.978 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding controller_idx as type Controller
2022-12-19 23:27:45.978 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding param_len as type ParamLen
2022-12-19 23:27:45.978 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding command_opcode as type CmdCode
2022-12-19 23:27:45.978 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding status as type Status
2022-12-19 23:27:45.978 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding current_settings as type CurrentSettings
2022-12-19 23:27:45.979 DEBUG (MainThread) [btsocket.btmgmt_protocol] Socket Read: <event_code=CommandCompleteEvent, controller_idx=0, param_len=7> <command_opcode=SetPowered, status=Success> <current_settings={Powered: True, Connectable: False, FastConnectable: False, Discoverable: False, Bondable: False, LinkLevelSecurity: False, SecureSimplePairing: True, BREDR: True, HighSpeed: False, LowEnergy: False, Advertising: False, SecureConnections: False, DebugKeys: False, Privacy: False, ControllerConfiguration: False, StaticAddress: False, PHYConfiguration: False, WidebandSpeech: False}>
2022-12-19 23:27:45.979 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding cmd_code as type CmdCode
2022-12-19 23:27:45.980 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding controller_idx as type Controller
2022-12-19 23:27:45.980 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding param_len as type ParamLen
2022-12-19 23:27:45.981 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding event_code as type EvtCode
2022-12-19 23:27:45.981 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding controller_idx as type Controller
2022-12-19 23:27:45.982 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding param_len as type ParamLen
2022-12-19 23:27:45.982 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding command_opcode as type CmdCode
2022-12-19 23:27:45.982 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding status as type Status
2022-12-19 23:27:45.982 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding address as type Address
2022-12-19 23:27:45.982 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding bluetooth_version as type IntUL
2022-12-19 23:27:45.983 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding manufacturer as type IntUL
2022-12-19 23:27:45.983 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding supported_settings as type IntUL
2022-12-19 23:27:45.983 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding current_settings as type CurrentSettings
2022-12-19 23:27:45.983 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding class_of_device as type IntUL
2022-12-19 23:27:45.983 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding name as type Name
2022-12-19 23:27:45.984 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding short_name as type IntUL
2022-12-19 23:27:45.984 DEBUG (MainThread) [btsocket.btmgmt_protocol] Socket Read: <event_code=CommandCompleteEvent, controller_idx=0, param_len=283> <command_opcode=ReadControllerInformation, status=Success> <address=49:02:91:02:89:88, bluetooth_version=4, manufacturer=15, supported_settings=69887, current_settings={Powered: True, Connectable: False, FastConnectable: False, Discoverable: False, Bondable: False, LinkLevelSecurity: False, SecureSimplePairing: True, BREDR: True, HighSpeed: False, LowEnergy: False, Advertising: False, SecureConnections: False, DebugKeys: False, Privacy: False, ControllerConfiguration: False, StaticAddress: False, PHYConfiguration: False, WidebandSpeech: False}, class_of_device=2883584, name=b'homeassistant', short_name=0>
2022-12-19 23:27:45.984 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Power state of bluetooth adapter hci0 [49:02:91:02:89:88] is ON after power cycle
2022-12-19 23:27:47.488 DEBUG (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (49:02:91:02:89:88): adapter reset result: True
2022-12-19 23:27:47.488 DEBUG (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (49:02:91:02:89:88): Starting bluetooth discovery attempt: (2/3)
2022-12-19 23:27:47.495 DEBUG (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (49:02:91:02:89:88): BleakError while starting bluetooth; attempt: (2/3): [org.bluez.Error.InProgress] Operation already in progress
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/bluetooth/scanner.py", line 229, 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 368, 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.InProgress] Operation already in progress
2022-12-19 23:27:58.006 DEBUG (MainThread) [homeassistant.components.bluetooth] Rediscovered adapters: {'hci0': {'address': '49:02:91:02:89:88', 'sw_version': 'homeassistant', 'hw_version': 'usb:v1D6Bp0246d053F', 'passive_scan': False, 'manufacturer': 'Broadcom Corp', 'product': 'BCM2046B1', 'vendor_id': '0a5c', 'product_id': '2046'}}
2022-12-19 23:27:58.008 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 0x7f1fdc93b220>>, 'scanning_mode': 'active', 'adapter': 'hci0'}
2022-12-19 23:27:58.009 DEBUG (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (49:02:91:02:89:88): Starting bluetooth discovery attempt: (1/3)
2022-12-19 23:27:58.018 DEBUG (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (49:02:91:02:89:88): adapter stopped responding; executing reset
2022-12-19 23:27:58.019 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Attempting to recover bluetooth adapter hci0 with mac address 49:02:91:02:89:88
2022-12-19 23:27:58.019 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Attempting to power cycle bluetooth adapter hci0 [49:02:91:02:89:88]
2022-12-19 23:27:58.023 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding cmd_code as type CmdCode
2022-12-19 23:27:58.024 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding controller_idx as type Controller
2022-12-19 23:27:58.024 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding param_len as type ParamLen
2022-12-19 23:27:58.025 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding event_code as type EvtCode
2022-12-19 23:27:58.026 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding controller_idx as type Controller
2022-12-19 23:27:58.026 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding param_len as type ParamLen
2022-12-19 23:27:58.027 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding command_opcode as type CmdCode
2022-12-19 23:27:58.027 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding status as type Status
2022-12-19 23:27:58.027 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding num_controllers as type IntUL
2022-12-19 23:27:58.028 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding controller_index[i] as type IntUL
2022-12-19 23:27:58.028 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]>
2022-12-19 23:27:58.029 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding cmd_code as type CmdCode
2022-12-19 23:27:58.029 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding controller_idx as type Controller
2022-12-19 23:27:58.030 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding param_len as type ParamLen
2022-12-19 23:27:58.032 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding event_code as type EvtCode
2022-12-19 23:27:58.032 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding controller_idx as type Controller
2022-12-19 23:27:58.032 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding param_len as type ParamLen
2022-12-19 23:27:58.033 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding command_opcode as type CmdCode
2022-12-19 23:27:58.033 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding status as type Status
2022-12-19 23:27:58.033 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding address as type Address
2022-12-19 23:27:58.034 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding bluetooth_version as type IntUL
2022-12-19 23:27:58.034 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding manufacturer as type IntUL
2022-12-19 23:27:58.035 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding supported_settings as type IntUL
2022-12-19 23:27:58.035 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding current_settings as type CurrentSettings
2022-12-19 23:27:58.036 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding class_of_device as type IntUL
2022-12-19 23:27:58.036 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding name as type Name
2022-12-19 23:27:58.036 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding short_name as type IntUL
2022-12-19 23:27:58.037 DEBUG (MainThread) [btsocket.btmgmt_protocol] Socket Read: <event_code=CommandCompleteEvent, controller_idx=0, param_len=283> <command_opcode=ReadControllerInformation, status=Success> <address=49:02:91:02:89:88, bluetooth_version=4, manufacturer=15, supported_settings=69887, current_settings={Powered: True, Connectable: False, FastConnectable: False, Discoverable: False, Bondable: False, LinkLevelSecurity: False, SecureSimplePairing: True, BREDR: True, HighSpeed: False, LowEnergy: False, Advertising: False, SecureConnections: False, DebugKeys: False, Privacy: False, ControllerConfiguration: False, StaticAddress: False, PHYConfiguration: False, WidebandSpeech: False}, class_of_device=2883584, name=b'homeassistant', short_name=0>
2022-12-19 23:27:58.038 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=49:02:91:02:89:88, bluetooth_version=4, manufacturer=15, supported_settings=69887, current_settings={Powered: True, Connectable: False, FastConnectable: False, Discoverable: False, Bondable: False, LinkLevelSecurity: False, SecureSimplePairing: True, BREDR: True, HighSpeed: False, LowEnergy: False, Advertising: False, SecureConnections: False, DebugKeys: False, Privacy: False, ControllerConfiguration: False, StaticAddress: False, PHYConfiguration: False, WidebandSpeech: False}, class_of_device=2883584, name=b'homeassistant', short_name=0>)
2022-12-19 23:27:58.038 DEBUG (MainThread) [bluetooth_auto_recovery.recover] hci0 (49:02:91:02:89:88) idx is 0
2022-12-19 23:27:58.046 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Attempting to power cycle bluetooth adapter hci0 [49:02:91:02:89:88]
2022-12-19 23:27:58.046 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding cmd_code as type CmdCode
2022-12-19 23:27:58.046 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding controller_idx as type Controller
2022-12-19 23:27:58.047 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding param_len as type ParamLen
2022-12-19 23:27:58.047 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding event_code as type EvtCode
2022-12-19 23:27:58.048 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding controller_idx as type Controller
2022-12-19 23:27:58.048 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding param_len as type ParamLen
2022-12-19 23:27:58.048 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding command_opcode as type CmdCode
2022-12-19 23:27:58.049 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding status as type Status
2022-12-19 23:27:58.049 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding address as type Address
2022-12-19 23:27:58.049 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding bluetooth_version as type IntUL
2022-12-19 23:27:58.050 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding manufacturer as type IntUL
2022-12-19 23:27:58.050 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding supported_settings as type IntUL
2022-12-19 23:27:58.050 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding current_settings as type CurrentSettings
2022-12-19 23:27:58.051 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding class_of_device as type IntUL
2022-12-19 23:27:58.051 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding name as type Name
2022-12-19 23:27:58.051 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding short_name as type IntUL
2022-12-19 23:27:58.052 DEBUG (MainThread) [btsocket.btmgmt_protocol] Socket Read: <event_code=CommandCompleteEvent, controller_idx=0, param_len=283> <command_opcode=ReadControllerInformation, status=Success> <address=49:02:91:02:89:88, bluetooth_version=4, manufacturer=15, supported_settings=69887, current_settings={Powered: True, Connectable: False, FastConnectable: False, Discoverable: False, Bondable: False, LinkLevelSecurity: False, SecureSimplePairing: True, BREDR: True, HighSpeed: False, LowEnergy: False, Advertising: False, SecureConnections: False, DebugKeys: False, Privacy: False, ControllerConfiguration: False, StaticAddress: False, PHYConfiguration: False, WidebandSpeech: False}, class_of_device=2883584, name=b'homeassistant', short_name=0>
2022-12-19 23:27:58.054 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Current power state of bluetooth adapter is ON.
2022-12-19 23:27:58.054 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding powered as type IntUL
2022-12-19 23:27:58.054 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding cmd_code as type CmdCode
2022-12-19 23:27:58.055 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding controller_idx as type Controller
2022-12-19 23:27:58.055 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding param_len as type ParamLen
2022-12-19 23:27:58.057 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding event_code as type EvtCode
2022-12-19 23:27:58.057 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding controller_idx as type Controller
2022-12-19 23:27:58.059 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding param_len as type ParamLen
2022-12-19 23:27:58.059 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding command_opcode as type CmdCode
2022-12-19 23:27:58.059 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding status as type Status
2022-12-19 23:27:58.060 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding current_settings as type CurrentSettings
2022-12-19 23:27:58.060 DEBUG (MainThread) [btsocket.btmgmt_protocol] Socket Read: <event_code=CommandCompleteEvent, controller_idx=0, param_len=7> <command_opcode=SetPowered, status=Success> <current_settings={Powered: False, Connectable: False, FastConnectable: False, Discoverable: False, Bondable: False, LinkLevelSecurity: False, SecureSimplePairing: True, BREDR: True, HighSpeed: False, LowEnergy: False, Advertising: False, SecureConnections: False, DebugKeys: False, Privacy: False, ControllerConfiguration: False, StaticAddress: False, PHYConfiguration: False, WidebandSpeech: False}>
2022-12-19 23:27:58.062 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding cmd_code as type CmdCode
2022-12-19 23:27:58.062 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding controller_idx as type Controller
2022-12-19 23:27:58.062 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding param_len as type ParamLen
2022-12-19 23:27:58.063 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding event_code as type EvtCode
2022-12-19 23:27:58.063 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding controller_idx as type Controller
2022-12-19 23:27:58.063 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding param_len as type ParamLen
2022-12-19 23:27:58.064 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding class_of_device as type IntUL
2022-12-19 23:27:58.064 DEBUG (MainThread) [btsocket.btmgmt_protocol] Socket read <event_code=ClassOfDeviceChangedEvent, controller_idx=0, param_len=3> <class_of_device=0>
2022-12-19 23:27:58.064 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding event_code as type EvtCode
2022-12-19 23:27:58.065 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding controller_idx as type Controller
2022-12-19 23:27:58.065 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding param_len as type ParamLen
2022-12-19 23:27:58.065 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding command_opcode as type CmdCode
2022-12-19 23:27:58.065 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding status as type Status
2022-12-19 23:27:58.066 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding address as type Address
2022-12-19 23:27:58.066 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding bluetooth_version as type IntUL
2022-12-19 23:27:58.066 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding manufacturer as type IntUL
2022-12-19 23:27:58.066 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding supported_settings as type IntUL
2022-12-19 23:27:58.067 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding current_settings as type CurrentSettings
2022-12-19 23:27:58.067 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding class_of_device as type IntUL
2022-12-19 23:27:58.067 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding name as type Name
2022-12-19 23:27:58.067 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding short_name as type IntUL
2022-12-19 23:27:58.068 DEBUG (MainThread) [btsocket.btmgmt_protocol] Socket Read: <event_code=CommandCompleteEvent, controller_idx=0, param_len=283> <command_opcode=ReadControllerInformation, status=Success> <address=49:02:91:02:89:88, bluetooth_version=4, manufacturer=15, supported_settings=69887, current_settings={Powered: False, Connectable: False, FastConnectable: False, Discoverable: False, Bondable: False, LinkLevelSecurity: False, SecureSimplePairing: True, BREDR: True, HighSpeed: False, LowEnergy: False, Advertising: False, SecureConnections: False, DebugKeys: False, Privacy: False, ControllerConfiguration: False, StaticAddress: False, PHYConfiguration: False, WidebandSpeech: False}, class_of_device=2883584, name=b'homeassistant', short_name=0>
2022-12-19 23:27:58.070 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding powered as type IntUL
2022-12-19 23:27:58.070 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding cmd_code as type CmdCode
2022-12-19 23:27:58.072 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding controller_idx as type Controller
2022-12-19 23:27:58.072 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding param_len as type ParamLen
2022-12-19 23:27:58.120 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding event_code as type EvtCode
2022-12-19 23:27:58.121 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding controller_idx as type Controller
2022-12-19 23:27:58.122 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding param_len as type ParamLen
2022-12-19 23:27:58.122 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding class_of_device as type IntUL
2022-12-19 23:27:58.122 DEBUG (MainThread) [btsocket.btmgmt_protocol] Socket read <event_code=ClassOfDeviceChangedEvent, controller_idx=0, param_len=3> <class_of_device=2883584>
2022-12-19 23:27:58.127 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding event_code as type EvtCode
2022-12-19 23:27:58.127 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding controller_idx as type Controller
2022-12-19 23:27:58.127 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding param_len as type ParamLen
2022-12-19 23:27:58.127 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding command_opcode as type CmdCode
2022-12-19 23:27:58.128 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding status as type Status
2022-12-19 23:27:58.129 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding current_settings as type CurrentSettings
2022-12-19 23:27:58.132 DEBUG (MainThread) [btsocket.btmgmt_protocol] Socket Read: <event_code=CommandCompleteEvent, controller_idx=0, param_len=7> <command_opcode=SetPowered, status=Success> <current_settings={Powered: True, Connectable: False, FastConnectable: False, Discoverable: False, Bondable: False, LinkLevelSecurity: False, SecureSimplePairing: True, BREDR: True, HighSpeed: False, LowEnergy: False, Advertising: False, SecureConnections: False, DebugKeys: False, Privacy: False, ControllerConfiguration: False, StaticAddress: False, PHYConfiguration: False, WidebandSpeech: False}>
2022-12-19 23:27:58.133 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding cmd_code as type CmdCode
2022-12-19 23:27:58.134 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding controller_idx as type Controller
2022-12-19 23:27:58.134 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding param_len as type ParamLen
2022-12-19 23:27:58.135 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding event_code as type EvtCode
2022-12-19 23:27:58.136 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding controller_idx as type Controller
2022-12-19 23:27:58.137 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding param_len as type ParamLen
2022-12-19 23:27:58.138 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding command_opcode as type CmdCode
2022-12-19 23:27:58.138 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding status as type Status
2022-12-19 23:27:58.139 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding address as type Address
2022-12-19 23:27:58.139 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding bluetooth_version as type IntUL
2022-12-19 23:27:58.140 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding manufacturer as type IntUL
2022-12-19 23:27:58.140 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding supported_settings as type IntUL
2022-12-19 23:27:58.141 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding current_settings as type CurrentSettings
2022-12-19 23:27:58.142 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding class_of_device as type IntUL
2022-12-19 23:27:58.143 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding name as type Name
2022-12-19 23:27:58.143 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding short_name as type IntUL
2022-12-19 23:27:58.144 DEBUG (MainThread) [btsocket.btmgmt_protocol] Socket Read: <event_code=CommandCompleteEvent, controller_idx=0, param_len=283> <command_opcode=ReadControllerInformation, status=Success> <address=49:02:91:02:89:88, bluetooth_version=4, manufacturer=15, supported_settings=69887, current_settings={Powered: True, Connectable: False, FastConnectable: False, Discoverable: False, Bondable: False, LinkLevelSecurity: False, SecureSimplePairing: True, BREDR: True, HighSpeed: False, LowEnergy: False, Advertising: False, SecureConnections: False, DebugKeys: False, Privacy: False, ControllerConfiguration: False, StaticAddress: False, PHYConfiguration: False, WidebandSpeech: False}, class_of_device=2883584, name=b'homeassistant', short_name=0>
2022-12-19 23:27:58.146 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Power state of bluetooth adapter hci0 [49:02:91:02:89:88] is ON after power cycle
2022-12-19 23:27:59.648 DEBUG (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (49:02:91:02:89:88): adapter reset result: True
2022-12-19 23:27:59.648 DEBUG (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (49:02:91:02:89:88): Starting bluetooth discovery attempt: (2/3)
2022-12-19 23:27:59.654 DEBUG (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (49:02:91:02:89:88): BleakError while starting bluetooth; attempt: (2/3): [org.bluez.Error.InProgress] Operation already in progress
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/bluetooth/scanner.py", line 229, 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 368, 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.InProgress] Operation already in progress
2022-12-19 23:27:59.655 WARNING (MainThread) [homeassistant.config_entries] Config entry '49:02:91:02:89:88' for bluetooth integration not ready yet: hci0 (49:02:91:02:89:88): Failed to start Bluetooth: [org.bluez.Error.InProgress] Operation already in progress; Retrying in background

Example YAML snippet

No response

Anything in the logs that might be useful for us?

No response

Additional information

No response

About this issue

  • Original URL
  • State: open
  • Created 2 years ago
  • Reactions: 2
  • Comments: 16

Most upvoted comments

I’m having the same issue with the built-in BT of the Raspberry Pi CM4 on my HA Yellow.

[EDIT]: The issue seams to stop once I configure it to only scan passively. But once I reverse the config, the issue comes back immediately.

Home Assistant 2023.5.0 Supervisor 2023.04.1 Operating System 10.1

+3
TB-SE on May 4, 2023

I’m having this same issue. My rpi bt just suddenly stopped working with this same error. Ice tried deleting and reading the bt integration but it worked for an hour then did this again. On 2023.4.6 (or whatever latest as of this post)

+1
manofpants on Apr 23, 2023
Read more comments on GitHub
← core: RESTful sensors fail to update from HTTPS servers that do not support secure renegotiation since 2023.5.0 when underling OS is using openssl 3+
core: Retrying setup: Invalid response from API: Error occurred while communicating with device →