core icon indicating copy to clipboard operation
core copied to clipboard
Published 4 months ago • verified publisher icon home-assistant

Failed to start Bluetooth: [org.bluez.Error.InProgress] Operation already in progress using VMWare and HAOS on Windows 11

Open magiva opened this issue 3 years ago • 21 comments

The problem

I have 2 bluetooth adapters on a micro pc running windows 11 with vmware hasos i disabled the internal bluetooth (same issuse with both) and also disabled the power saving of the bt device.

image

hasos "sees" both bluetooth devices but wont init either of them.

Home Assistant 2022.12.0 Supervisor 2022.11.2 Operating System 9.3 Frontend 20221207.0 - latest

What version of Home Assistant Core has the issue?

2022.12.0

What was the last working version of Home Assistant Core?

na

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_2022-12-08T09-03-51.765Z.log

Example YAML snippet

No response

Anything in the logs that might be useful for us?

2022-12-08 10:01:36.485 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 0x7faf8daa9f00>>, 'scanning_mode': 'active', 'adapter': 'hci1'}
2022-12-08 10:01:36.486 DEBUG (MainThread) [homeassistant.components.bluetooth.scanner] hci1 (00:E0:4C:C0:C0:33): Starting bluetooth discovery attempt: (1/3)
2022-12-08 10:01:36.496 DEBUG (MainThread) [homeassistant.components.bluetooth.scanner] hci1 (00:E0:4C:C0:C0:33): adapter stopped responding; executing reset
2022-12-08 10:01:36.497 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Power cycling Bluetooth adapter hci1
2022-12-08 10:01:36.501 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding cmd_code as type CmdCode
2022-12-08 10:01:36.501 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding controller_idx as type Controller
2022-12-08 10:01:36.501 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding param_len as type ParamLen
2022-12-08 10:01:36.502 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding event_code as type EvtCode
2022-12-08 10:01:36.502 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding controller_idx as type Controller
2022-12-08 10:01:36.502 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding param_len as type ParamLen
2022-12-08 10:01:36.502 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding command_opcode as type CmdCode
2022-12-08 10:01:36.503 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding status as type Status
2022-12-08 10:01:36.504 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding num_controllers as type IntUL
2022-12-08 10:01:36.504 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding controller_index[i] as type IntUL
2022-12-08 10:01:36.504 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]=[1]>
2022-12-08 10:01:36.505 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding cmd_code as type CmdCode
2022-12-08 10:01:36.506 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding controller_idx as type Controller
2022-12-08 10:01:36.506 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding param_len as type ParamLen
2022-12-08 10:01:36.507 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding event_code as type EvtCode
2022-12-08 10:01:36.507 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding controller_idx as type Controller
2022-12-08 10:01:36.507 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding param_len as type ParamLen
2022-12-08 10:01:36.507 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding command_opcode as type CmdCode
2022-12-08 10:01:36.507 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding status as type Status
2022-12-08 10:01:36.507 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding address as type Address
2022-12-08 10:01:36.507 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding bluetooth_version as type IntUL
2022-12-08 10:01:36.507 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding manufacturer as type IntUL
2022-12-08 10:01:36.508 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding supported_settings as type IntUL
2022-12-08 10:01:36.508 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding current_settings as type CurrentSettings
2022-12-08 10:01:36.509 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding class_of_device as type IntUL
2022-12-08 10:01:36.509 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding name as type Name
2022-12-08 10:01:36.509 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding short_name as type IntUL
2022-12-08 10:01:36.509 DEBUG (MainThread) [btsocket.btmgmt_protocol] Socket Read: <event_code=CommandCompleteEvent, controller_idx=1, param_len=283> <command_opcode=ReadControllerInformation, status=Success> <address=00:E0:4C:C0:C0:33, bluetooth_version=4, manufacturer=6502, 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-08 10:01:36.509 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Response(header=<event_code=CommandCompleteEvent, controller_idx=1, param_len=283>, event_frame=<command_opcode=ReadControllerInformation, status=Success>, cmd_response_frame=<address=00:E0:4C:C0:C0:33, bluetooth_version=4, manufacturer=6502, 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-08 10:01:36.509 WARNING (MainThread) [bluetooth_auto_recovery.recover] hci1 (00:E0:4C:C0:C0:33) have no BT LE capabilities and will be ignored.
2022-12-08 10:01:36.510 ERROR (MainThread) [bluetooth_auto_recovery.recover] hci1 seems not to exist (anymore), check BT interface mac address in your settings; Available adapters: {} 
2022-12-08 10:01:36.511 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Executing USB reset for Bluetooth adapter hci1
2022-12-08 10:01:39.030 ERROR (SyncWorker_4) [homeassistant.components.command_line] Command failed (with return code 1): cat /sys/class/thermal/thermal_zone0/temp
2022-12-08 10:01:39.052 DEBUG (MainThread) [homeassistant.components.bluetooth.scanner] hci1 (00:E0:4C:C0:C0:33): adapter reset result: True
2022-12-08 10:01:39.052 DEBUG (MainThread) [homeassistant.components.bluetooth.scanner] hci1 (00:E0:4C:C0:C0:33): Starting bluetooth discovery attempt: (2/3)
2022-12-08 10:01:39.053 DEBUG (MainThread) [homeassistant.components.bluetooth.scanner] hci1 (00:E0:4C:C0:C0:33): 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 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 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-08 10:02:59.055 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 0x7faf8cb0c4c0>>, 'scanning_mode': 'active', 'adapter': 'hci1'}
2022-12-08 10:02:59.056 DEBUG (MainThread) [homeassistant.components.bluetooth.scanner] hci1 (00:E0:4C:C0:C0:33): Starting bluetooth discovery attempt: (1/3)
2022-12-08 10:02:59.059 DEBUG (MainThread) [homeassistant.components.bluetooth.scanner] hci1 (00:E0:4C:C0:C0:33): adapter stopped responding; executing reset
2022-12-08 10:02:59.060 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Power cycling Bluetooth adapter hci1
2022-12-08 10:02:59.062 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding cmd_code as type CmdCode
2022-12-08 10:02:59.063 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding controller_idx as type Controller
2022-12-08 10:02:59.063 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding param_len as type ParamLen
2022-12-08 10:02:59.063 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding event_code as type EvtCode
2022-12-08 10:02:59.063 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding controller_idx as type Controller
2022-12-08 10:02:59.063 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding param_len as type ParamLen
2022-12-08 10:02:59.063 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding command_opcode as type CmdCode
2022-12-08 10:02:59.063 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding status as type Status
2022-12-08 10:02:59.063 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding num_controllers as type IntUL
2022-12-08 10:02:59.063 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding controller_index[i] as type IntUL
2022-12-08 10:02:59.064 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]=[1]>
2022-12-08 10:02:59.064 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding cmd_code as type CmdCode
2022-12-08 10:02:59.064 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding controller_idx as type Controller
2022-12-08 10:02:59.064 DEBUG (MainThread) [btsocket.btmgmt_protocol] Encoding param_len as type ParamLen
2022-12-08 10:02:59.064 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding event_code as type EvtCode
2022-12-08 10:02:59.065 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding controller_idx as type Controller
2022-12-08 10:02:59.065 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding param_len as type ParamLen
2022-12-08 10:02:59.065 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding command_opcode as type CmdCode
2022-12-08 10:02:59.065 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding status as type Status
2022-12-08 10:02:59.065 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding address as type Address
2022-12-08 10:02:59.066 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding bluetooth_version as type IntUL
2022-12-08 10:02:59.066 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding manufacturer as type IntUL
2022-12-08 10:02:59.066 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding supported_settings as type IntUL
2022-12-08 10:02:59.066 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding current_settings as type CurrentSettings
2022-12-08 10:02:59.066 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding class_of_device as type IntUL
2022-12-08 10:02:59.066 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding name as type Name
2022-12-08 10:02:59.067 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding short_name as type IntUL
2022-12-08 10:02:59.067 DEBUG (MainThread) [btsocket.btmgmt_protocol] Socket Read: <event_code=CommandCompleteEvent, controller_idx=1, param_len=283> <command_opcode=ReadControllerInformation, status=Success> <address=00:E0:4C:C0:C0:33, bluetooth_version=4, manufacturer=6502, 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-08 10:02:59.067 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Response(header=<event_code=CommandCompleteEvent, controller_idx=1, param_len=283>, event_frame=<command_opcode=ReadControllerInformation, status=Success>, cmd_response_frame=<address=00:E0:4C:C0:C0:33, bluetooth_version=4, manufacturer=6502, 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-08 10:02:59.067 WARNING (MainThread) [bluetooth_auto_recovery.recover] hci1 (00:E0:4C:C0:C0:33) have no BT LE capabilities and will be ignored.
2022-12-08 10:02:59.067 ERROR (MainThread) [bluetooth_auto_recovery.recover] hci1 seems not to exist (anymore), check BT interface mac address in your settings; Available adapters: {} 
2022-12-08 10:02:59.068 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Executing USB reset for Bluetooth adapter hci1

2022-12-08 10:03:01.642 DEBUG (MainThread) [homeassistant.components.bluetooth.scanner] hci1 (00:E0:4C:C0:C0:33): adapter reset result: True
2022-12-08 10:03:01.642 DEBUG (MainThread) [homeassistant.components.bluetooth.scanner] hci1 (00:E0:4C:C0:C0:33): Starting bluetooth discovery attempt: (2/3)
2022-12-08 10:03:01.644 DEBUG (MainThread) [homeassistant.components.bluetooth.scanner] hci1 (00:E0:4C:C0:C0:33): 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 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 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

Additional information

No response

magiva avatar Dec 08 '22 09:12 magiva

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 close Closes the issue.
  • @home-assistant rename Awesome new title Change the title of the issue.
  • @home-assistant reopen Reopen the issue.
  • @home-assistant unassign bluetooth Removes 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 Dec 08 '22 09:12 home-assistant[bot]

also...in the console window for hasos it constantly fills up with this

image

magiva avatar Dec 08 '22 09:12 magiva

I have exactly the same error on a rpi4 with HA OS From today, yesterday everything was ok. I restore a backup, but nothing change

garagara93 avatar Dec 08 '22 15:12 garagara93

Please post diagnostics.

Thanks

bdraco avatar Dec 09 '22 00:12 bdraco

is there more diagnostics from me that you need?

magiva avatar Dec 09 '22 05:12 magiva

Same problem here. Attaching debug log: home-assistant_bluetooth_2022-12-09T14-04-53.005Z.log

arodenbu avatar Dec 09 '22 14:12 arodenbu

Thanks for the log, however I need diagnostics:

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

bdraco avatar Dec 09 '22 18:12 bdraco

Initially there were no diagnostics available. I rebooted the whole system via a terminal and now it seems to be working and there is diagnostics available. All seems to be working now though config_entry-bluetooth-a4b11982b53eb9e0e9265c46fd9d1f61.json.txt

arodenbu avatar Dec 09 '22 22:12 arodenbu

Everything looks good now.

Home Assistant OS 9.4 has some newer firmware for the Raspberry Pis that might help make sure it doesn't get in a bad state again.

bdraco avatar Dec 09 '22 22:12 bdraco

that's great and I'm glad for you.... but this thread is from a vmware hassos. maybe all the same route cause though

On Fri, 9 Dec 2022, 23:45 J. Nick Koston, @.***> wrote:

Everything looks good now.

Home Assistant OS 9.4 has some newer firmware for the Raspberry Pis that might help make sure it doesn't get in a bad state again.

— Reply to this email directly, view it on GitHub https://github.com/home-assistant/core/issues/83529#issuecomment-1344858473, or unsubscribe https://github.com/notifications/unsubscribe-auth/ABZMQZKUHNKIVMRMDYPKHZ3WMOZAJANCNFSM6AAAAAASX4D324 . You are receiving this because you authored the thread.Message ID: @.***>

magiva avatar Dec 09 '22 22:12 magiva

how can you do diagnostics on bluetooth, the option isnt there image image

magiva avatar Dec 10 '22 08:12 magiva

how can you do diagnostics on bluetooth, the option isnt there image image

same problem

hknkbp avatar Dec 11 '22 02:12 hknkbp

That is the issue with diagnostics. If the device does not initialize, there is no diag to be run. I know this topic is around virtualization, but the log messages are exactly the same. I had to do a cold reboot (power off and restart) of the Pi. It’s stable now. Perhaps (long shot) a restart of the container or the host itself will help. One additional item. With me, the error started in the middle of the night out of itself.

S1KRR avatar Dec 11 '22 10:12 S1KRR

yeah i think the base is the same, linux etc. unfortunatley a power cycle did not fix or change the issue

magiva avatar Dec 11 '22 16:12 magiva

With me, the error started in the middle of the night out of itself.

Exactly the same here. Just at midnight problem appeared out of nowhere. Running 2022.12.1 since a couple of days, have the feeling it is related to that. Restart haven't solved the issue. I will try to update now to 12.3

tkrhiman avatar Dec 13 '22 00:12 tkrhiman

i updated to

Home Assistant 2022.12.5 Supervisor 2022.11.2 Operating System 9.4 Frontend 20221213.0 - latest

no change, bluetooth still fails Config entry '00:E0:4C:C0:C0:03' for bluetooth integration not ready yet: hci0 (00:E0:4C:C0:C0:03): Failed to start Bluetooth: [org.bluez.Error.InProgress] Operation already in progress; Retrying in background

magiva avatar Dec 14 '22 09:12 magiva

Try a cold reboot

bdraco avatar Dec 14 '22 09:12 bdraco

:) yes ive done that too

On Wed, 14 Dec 2022 at 10:46, J. Nick Koston @.***> wrote:

Try a cold reboot

— Reply to this email directly, view it on GitHub https://github.com/home-assistant/core/issues/83529#issuecomment-1350747100, or unsubscribe https://github.com/notifications/unsubscribe-auth/ABZMQZJGSBN457P2W6EFG63WNGJPTANCNFSM6AAAAAASX4D324 . You are receiving this because you authored the thread.Message ID: @.***>

magiva avatar Dec 14 '22 10:12 magiva

Everything looks good now.

Home Assistant OS 9.4 has some newer firmware for the Raspberry Pis that might help make sure it doesn't get in a bad state again.

I'm fully updated as of today, which includes 9.4 and no change to it working

Home Assistant 2022.12.8 Supervisor 2022.11.2 Operating System 9.4 Frontend 20221213.1 - latest

magiva avatar Dec 22 '22 10:12 magiva

Maybe related issue https://github.com/home-assistant/operating-system/issues/2142

bdraco avatar Feb 01 '23 02:02 bdraco

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates. Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍 This issue has now been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.

issue-triage-workflows[bot] avatar May 02 '23 03:05 issue-triage-workflows[bot]