core: Bluetooth crashes with [org.bluez.Error.NotReady] Resource Not Ready

The problem

  • I was able to create the bluetooth integration via UI
  • on startup, the integration crashes grafik
  • restarting HA or rebooting the host (Raspberry Pi 4) does not change anything

What version of Home Assistant Core has the issue?

core-2022.12.1

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

No response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

2022-12-09 16:49:08.473 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 0x7f808f2440>>, 'scanning_mode': 'active', 'adapter': 'hci0'}
2022-12-09 16:49:08.476 DEBUG (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (DC:A6:32:F6:AB:EC): Starting bluetooth discovery attempt: (1/3)
2022-12-09 16:49:08.482 DEBUG (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (DC:A6:32:F6:AB:EC): adapter stopped responding; executing reset
2022-12-09 16:49:08.483 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Power cycling Bluetooth adapter hci0
2022-12-09 16:49:08.489 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding cmd_code as type CmdCode
2022-12-09 16:49:08.489 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding controller_idx as type Controller
2022-12-09 16:49:08.493 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding param_len as type ParamLen
2022-12-09 16:49:08.495 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding event_code as type EvtCode
2022-12-09 16:49:08.497 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding controller_idx as type Controller
2022-12-09 16:49:08.500 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding param_len as type ParamLen
2022-12-09 16:49:08.502 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding command_opcode as type CmdCode
2022-12-09 16:49:08.503 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding status as type Status
2022-12-09 16:49:08.504 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding num_controllers as type IntUL
2022-12-09 16:49:08.506 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding controller_index[i] as type IntUL
2022-12-09 16:49:08.507 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-09 16:49:08.508 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding cmd_code as type CmdCode
2022-12-09 16:49:08.510 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding controller_idx as type Controller
2022-12-09 16:49:08.512 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding param_len as type ParamLen
2022-12-09 16:49:08.514 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding event_code as type EvtCode
2022-12-09 16:49:08.515 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding controller_idx as type Controller
2022-12-09 16:49:08.516 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding param_len as type ParamLen
2022-12-09 16:49:08.517 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding command_opcode as type CmdCode
2022-12-09 16:49:08.519 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding status as type Status
2022-12-09 16:49:08.520 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding address as type Address
2022-12-09 16:49:08.522 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding bluetooth_version as type IntUL
2022-12-09 16:49:08.523 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding manufacturer as type IntUL
2022-12-09 16:49:08.524 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding supported_settings as type IntUL
2022-12-09 16:49:08.525 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding current_settings as type CurrentSettings
2022-12-09 16:49:08.525 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding class_of_device as type IntUL
2022-12-09 16:49:08.526 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding name as type Name
2022-12-09 16:49:08.527 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding short_name as type IntUL
2022-12-09 16:49:08.527 DEBUG (MainThread) [btsocket.btmgmt_protocol] Socket Read: <event_code=CommandCompleteEvent, controller_idx=0, param_len=283> <command_opcode=ReadControllerInformation, status=Success> <address=DC:A6:32:F6:AB:EC, 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'homeassistant', short_name=0>
2022-12-09 16:49:08.529 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=DC:A6:32:F6:AB:EC, 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'homeassistant', short_name=0>)
2022-12-09 16:49:08.530 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding cmd_code as type CmdCode
2022-12-09 16:49:08.531 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding controller_idx as type Controller
2022-12-09 16:49:08.532 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding param_len as type ParamLen
2022-12-09 16:49:08.536 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding event_code as type EvtCode
2022-12-09 16:49:08.536 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding controller_idx as type Controller
2022-12-09 16:49:08.538 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding param_len as type ParamLen
2022-12-09 16:49:08.539 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding command_opcode as type CmdCode
2022-12-09 16:49:08.540 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding status as type Status
2022-12-09 16:49:08.540 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding address as type Address
2022-12-09 16:49:08.541 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding bluetooth_version as type IntUL
2022-12-09 16:49:08.541 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding manufacturer as type IntUL
2022-12-09 16:49:08.541 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding supported_settings as type IntUL
2022-12-09 16:49:08.541 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding current_settings as type CurrentSettings
2022-12-09 16:49:08.542 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding class_of_device as type IntUL
2022-12-09 16:49:08.542 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding name as type Name
2022-12-09 16:49:08.543 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding short_name as type IntUL
2022-12-09 16:49:08.545 DEBUG (MainThread) [btsocket.btmgmt_protocol] Socket Read: <event_code=CommandCompleteEvent, controller_idx=0, param_len=283> <command_opcode=ReadControllerInformation, status=Success> <address=DC:A6:32:F6:AB:EC, 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'homeassistant', short_name=0>
2022-12-09 16:49:08.547 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Current power state of bluetooth adapter hci0 is OFF, trying to turn it back ON
2022-12-09 16:49:08.547 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding powered as type IntUL
2022-12-09 16:49:08.548 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding cmd_code as type CmdCode
2022-12-09 16:49:08.549 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding controller_idx as type Controller
2022-12-09 16:49:08.551 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding param_len as type ParamLen
2022-12-09 16:49:13.556 WARNING (MainThread) [bluetooth_auto_recovery.recover] Bluetooth adapter hci0 could not be reset due to timeout
2022-12-09 16:49:13.560 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Executing USB reset for Bluetooth adapter hci0
2022-12-09 16:49:13.565 DEBUG (MainThread) [bluetooth_auto_recovery.recover] hci0 is not a USB devices while attempting USB reset: ttyS0 is not a USB device
2022-12-09 16:49:13.565 DEBUG (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (DC:A6:32:F6:AB:EC): adapter reset result: False
2022-12-09 16:49:13.565 DEBUG (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (DC:A6:32:F6:AB:EC): Starting bluetooth discovery attempt: (2/3)
2022-12-09 16:49:13.568 DEBUG (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (DC:A6:32:F6:AB:EC): 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 228, in _async_start
    await self.scanner.start()  # type: ignore[no-untyped-call]
  File "/usr/local/lib/python3.10/site-packages/bleak/__init__.py", line 156, in start
    await self._backend.start()
  File "/usr/local/lib/python3.10/site-packages/bleak/backends/bluezdbus/scanner.py", line 191, in start
    self._stop = await manager.active_scan(
  File "/usr/local/lib/python3.10/site-packages/bleak/backends/bluezdbus/manager.py", line 357, in active_scan
    assert_reply(reply)
  File "/usr/local/lib/python3.10/site-packages/bleak/backends/bluezdbus/utils.py", line 20, in assert_reply
    raise BleakDBusError(reply.error_name, reply.body)

Additional information

Environment: Raspberry 4 (64 bit) with Home Assistant Operating System 9.3 (Supervisor 2022.11.2)

About this issue

  • Original URL
  • State: closed
  • Created 2 years ago
  • Comments: 33 (13 by maintainers)

Commits related to this issue

Most upvoted comments

Can confirm this is fixed with core 2022.12.4

@tjorim so I don’t get the wrong one, when you say CSR you do mean the ones with the CSR in model number e.g. Avantree BTDG-40S (CSR8510A10)