search

citruz / haos-rockpi

Home Assistant OS for Rock Pi 4
Apache License 2.0
56 stars 3 forks source link

Rockpi 4B+ Bluetooth not discovering devices #31

Open alexschultze opened 2 months ago

alexschultze commented 2 months ago

Describe the issue you are experiencing

Version tested: 11.4 and now upgrade to 12.2

Description: Bluetooth is not discovering any devices. The hardware bridge is showing up. WIFI is working and shows access points.

What operating system image do you use?

rockpi-4b-plus

What version of Home Assistant Operating System is installed?

12.4

Did you upgrade the Operating System.

Yes

Steps to reproduce the issue

1.Install HAOS 2.Search for BT devices

Anything in the Supervisor logs that might be useful for us?

-

Anything in the Host logs that might be useful for us?

2024-04-25 22:08:01.341 homeassistant bluetoothd[489]: Path /org/bleak/67/281472178047472 reserved for Adv Monitor app :1.43
2024-04-25 22:08:26.634 homeassistant bluetoothd[489]: Path /org/bleak/67/281472178047472 removed along with Adv Monitor app :1.43
2024-04-25 22:08:26.646 homeassistant bluetoothd[489]: Path /org/bleak/67/281472178645472 reserved for Adv Monitor app :1.43
2024-04-25 22:09:56.662 homeassistant bluetoothd[489]: Path /org/bleak/67/281472178645472 removed along with Adv Monitor app :1.43
2024-04-25 22:09:59.508 homeassistant bluetoothd[489]: Path /org/bleak/67/281472175571808 reserved for Adv Monitor app :1.43
2024-04-25 22:11:56.665 homeassistant bluetoothd[489]: Path /org/bleak/67/281472175571808 removed along with Adv Monitor app :1.43
2024-04-25 22:11:56.701 homeassistant kernel: Bluetooth: hci0: Opcode 0x200c failed: -112
2024-04-25 22:11:56.702 homeassistant kernel: Bluetooth: hci0: Unable to disable scanning: -112
2024-04-25 22:11:56.702 homeassistant kernel: Bluetooth: hci0: stop background scanning failed: -112
2024-04-25 22:11:59.412 homeassistant bluetoothd[489]: Path /org/bleak/67/281472307504176 reserved for Adv Monitor app :1.43
2024-04-25 22:13:56.674 homeassistant bluetoothd[489]: Path /org/bleak/67/281472307504176 removed along with Adv Monitor app :1.43
2024-04-25 22:13:56.738 homeassistant kernel: Bluetooth: hci0: Opcode 0x200c failed: -112
2024-04-25 22:13:56.739 homeassistant kernel: Bluetooth: hci0: Unable to disable scanning: -112
2024-04-25 22:13:56.739 homeassistant kernel: Bluetooth: hci0: stop background scanning failed: -112
2024-04-25 22:13:59.418 homeassistant bluetoothd[489]: Path /org/bleak/67/281472676466480 reserved for Adv Monitor app :1.43
2024-04-25 22:15:56.679 homeassistant bluetoothd[489]: Path /org/bleak/67/281472676466480 removed along with Adv Monitor app :1.43
2024-04-25 22:15:56.711 homeassistant kernel: Bluetooth: hci0: Opcode 0x200c failed: -112
2024-04-25 22:15:56.712 homeassistant kernel: Bluetooth: hci0: Unable to disable scanning: -112
2024-04-25 22:15:56.712 homeassistant kernel: Bluetooth: hci0: stop background scanning failed: -112
2024-04-25 22:15:59.416 homeassistant bluetoothd[489]: Path /org/bleak/67/281472175582224 reserved for Adv Monitor app :1.43
2024-04-25 22:16:42.293 homeassistant dockerd[581]: 2024/04/25 22:16:42 http: superfluous response.WriteHeader call from go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp.(*respWriterWrapper).WriteHeader (wrap.go:98)
2024-04-25 22:16:42.462 homeassistant dockerd[581]: 2024/04/25 22:16:42 http: superfluous response.WriteHeader call from go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp.(*respWriterWrapper).WriteHeader (wrap.go:98)
2024-04-25 22:16:50.147 homeassistant kernel: kauditd_printk_skb: 5 callbacks suppressed
2024-04-25 22:16:50.148 homeassistant kernel: audit: type=1334 audit(1714083410.128:216): prog-id=60 op=LOAD
2024-04-25 22:16:50.155 homeassistant systemd-timesyncd[1413]: Network configuration changed, trying to establish connection.
2024-04-25 22:16:50.229 homeassistant systemd-timesyncd[1413]: Contacted time server 192.168.178.1:123 (192.168.178.1).
2024-04-25 22:16:50.230 homeassistant systemd[1]: Started Journal Gateway Service.

System information

No response

Additional information

Device Info Unknown by AMPAK Technology,Inc. Firmware: homeassistant Hardware: usb:v1D6Bp0246d0548 Bluetooth: 08:FB:EA:E0:74:09

citruz commented 2 months ago

What exactly did you mean with 2.Search for BT devices?

Can you try installing the Terminal add on and running bluetoothctl?

alexschultze commented 2 months ago 
Agent registered
hci0 new_settings: powered bondable ssp br/edr le secure-conn 
[CHG] Controller 08:FB:EA:E0:74:09 Pairable: yes
AdvertisementMonitor path registered
hci0 type 6 discovering off
hci0 type 6 discovering on
hci0 type 6 discovering off
hci0 type 6 discovering on
hci0 type 6 discovering off
hci0 type 6 discovering on
hci0 type 6 discovering off
hci0 type 6 discovering on
hci0 type 6 discovering off
hci0 type 6 discovering on
hci0 type 6 discovering off
hci0 type 6 discovering on

Minor note this is with version 11.4.

[    7.223877] Bluetooth: Core ver 2.22
[    7.267556] Bluetooth: HCI device and connection manager initialized
[    7.275567] Bluetooth: HCI socket layer initialized
[    7.293137] Bluetooth: L2CAP socket layer initialized
[    7.293161] Bluetooth: SCO socket layer initialized
[    8.098470] Bluetooth: HCI UART driver ver 2.3
[    8.103510] Bluetooth: HCI UART protocol H4 registered
[    8.109383] Bluetooth: HCI UART protocol LL registered
[    8.115242] Bluetooth: HCI UART protocol Three-wire (H5) registered
[    8.122905] Bluetooth: HCI UART protocol Intel registered
[    8.129569] Bluetooth: HCI UART protocol Broadcom registered
[    8.136073] Bluetooth: HCI UART protocol QCA registered
[    8.141945] Bluetooth: HCI UART protocol AG6XX registered
[    8.148075] Bluetooth: HCI UART protocol Marvell registered
[    8.486046] Bluetooth: hci0: BCM: chip id 130
[    8.491483] Bluetooth: hci0: BCM: features 0x0f
[    8.499027] Bluetooth: hci0: BCM4345C5
[    8.503228] Bluetooth: hci0: BCM4345C5 (003.006.006) build 0000
[    8.578902] Bluetooth: hci0: BCM4345C5 'brcm/BCM4345C5.hcd' Patch
[    9.590764] Bluetooth: hci0: BCM: features 0x0f
[    9.593604] Bluetooth: hci0: BCM43456 37.4MHz Raspberry Pi BT5.0 [Version: 1052.1108]
[    9.593627] Bluetooth: hci0: BCM4345C5 (003.006.006) build 1108
[   12.207691] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[   12.207715] Bluetooth: BNEP filters: protocol multicast
[   12.207739] Bluetooth: BNEP socket layer initialized
[   12.216846] Bluetooth: MGMT ver 1.22
[   65.363242] Bluetooth: RFCOMM TTY layer initialized
[   65.363304] Bluetooth: RFCOMM socket layer initialized
[   65.363346] Bluetooth: RFCOMM ver 1.11
citruz commented 2 months ago

What exactly did you mean with 2.Search for BT devices? What does the kernel log look like with 12.4? dmesg | grep -i bluetooth and journalctl | grep -i bluetooth

Also, do you have any addon installed that uses bluetooth? Please disable anything that could interfere for testing. In the bluetoothctl log it looks like the controller is continuously toggled on and off?

alexschultze commented 2 months ago

Search for BT device means bluetoothctl & menu scan. I did a regression test using original RADXA images and to ensure it is not a hardware error on my side. RADXA Buster (2022) works and shows BT devices RADXA Bullseye (2023) fails with a BT error message (initialization error) during boot

Output with haos_rockpi-4b-plus-12.2.dev20240414.img.xz will follow.

alexschultze commented 2 months ago 
➜  ~ bluetoothctl                                                                                                                                                 
Agent registered                                                                                                                                                  
hci0 new_settings: powered bondable ssp br/edr le secure-conn                                                                                                     
[CHG] Controller 08:FB:EA:E0:74:09 Pairable: yes                                                                                                                  
AdvertisementMonitor path registered                                                                                                                              
hci0 type 6 discovering off                                                                                                                                       
[CHG] Controller 08:FB:EA:E0:74:09 Discovering: no                                                                                                                
hci0 class of device changed: 0x000000                                                                                                                            
hci0 new_settings: bondable ssp br/edr le secure-conn                                                                                                             
[CHG] Controller 08:FB:EA:E0:74:09 Class: 0x00000000 (0)                                                                                                          
[CHG] Controller 08:FB:EA:E0:74:09 Powered: no                                                                                                                    
[CHG] Controller 08:FB:EA:E0:74:09 Discovering: no                                                                                                                
[CHG] Controller 08:FB:EA:E0:74:09 PowerState: on                                                                                                                 
hci0 class of device changed: 0x6c0000                                                                                                                            
[CHG] Controller 08:FB:EA:E0:74:09 Class: 0x006c0000 (7077888)                                                                                                    
hci0 name changed: homeassistant                                                                                                                                  
hci0 new_settings: powered bondable ssp br/edr le secure-conn                                                                                                     
[CHG] Controller 08:FB:EA:E0:74:09 Powered: yes                                                                                                                   
[bluetooth]#                                                                                                                                                      
hci0 type 6 discovering on                                                                                                                                        
[CHG] Controller 08:FB:EA:E0:74:09 Discovering: yes                                                                                                               
hci0 type 6 discovering off                                                                                                                                       
hci0 type 6 discovering on                                                                                                                                        
hci0 type 6 discovering off                                                                                                                                       
hci0 type 6 discovering o
➜  ~ dmesg | grep -i bluetooth                                                                                                                                    
[    9.069220] Bluetooth: Core ver 2.22                                                                                                                           
[    9.078404] Bluetooth: Starting self testing                                                                                                                   
[    9.137487] Bluetooth: ECDH test passed in 19275 usecs                                                                                                         
[    9.171725] Bluetooth: SMP test passed in 1869 usecs                                                                                                           
[    9.188462] Bluetooth: Finished self testing                                                                                                                   
[    9.199144] NET: Registered PF_BLUETOOTH protocol family                                                                                                       
[    9.207538] Bluetooth: HCI device and connection manager initialized                                                                                           
[    9.215528] Bluetooth: HCI socket layer initialized                                                                                                            
[    9.221306] Bluetooth: L2CAP socket layer initialized                                                                                                          
[    9.226994] Bluetooth: SCO socket layer initialized                                                                                                            
[    9.371870] Bluetooth: HCI UART driver ver 2.3                                                                                                                 
[    9.385948] Bluetooth: HCI UART protocol H4 registered                                                                                                         
[    9.385953] Bluetooth: HCI UART protocol BCSP registered                                                                                                       
[    9.392934] Bluetooth: HCI UART protocol LL registered                                                                                                         
[    9.401382] Bluetooth: HCI UART protocol ATH3K registered                                                                                                      
[    9.409655] Bluetooth: HCI UART protocol Three-wire (H5) registered                                                                                            
[    9.439565] Bluetooth: HCI UART protocol Intel registered                                                                                                      
[    9.473534] Bluetooth: HCI UART protocol Broadcom registered                                                                                                   
[    9.484325] Bluetooth: HCI UART protocol QCA registered                                                                                                        
[    9.490243] Bluetooth: HCI UART protocol AG6XX registered                                                                                                      
[    9.490264] Bluetooth: HCI UART protocol Marvell registered                                                                                                    
[    9.865885] Bluetooth: hci0: BCM: chip id 130                                                                                                                  
[    9.871370] Bluetooth: hci0: BCM: features 0x0f                                                                                                                
[    9.879116] Bluetooth: hci0: BCM4345C5                                                                                                                         
[    9.888783] Bluetooth: hci0: BCM4345C5 (003.006.006) build 0000                                                                                                
[   22.677445] Bluetooth: hci0: BCM4345C5 'brcm/BCM4345C5.hcd' Patch                                                                                              
[   23.847432] Bluetooth: hci0: BCM: features 0x0f                                                                                                                
[   23.855761] Bluetooth: hci0: BCM43456 37.4MHz Raspberry Pi BT5.0 [Version: 1052.1108]                                                                          
[   23.864622] Bluetooth: hci0: BCM4345C5 (003.006.006) build 1108                                                                                                
[   32.936363] Bluetooth: BNEP (Ethernet Emulation) ver 1.3                                                                                                       
[   32.936395] Bluetooth: BNEP filters: protocol multicast                                                                                                        
[   32.936421] Bluetooth: BNEP socket layer initialized                                                                                                           
[   32.943264] Bluetooth: MGMT ver 1.22                                                                                                                           
[  100.009151] Bluetooth: RFCOMM TTY layer initialized                                                                                                            
[  100.009212] Bluetooth: RFCOMM socket layer initialized                                                                                                         
[  100.009270] Bluetooth: RFCOMM ver 1.11

journalctl gives command not found.

During installation of HAOS i checked bluetoothctl via the terminal and it showed some devices. So my assumptions that it is a not a low-level driver issue.

config_entry-bluetooth-5c7b1f87d891c7a3f50abbfe80241527.json

alexschultze commented 2 months ago

After a longer journey enabling SSH here is the output of journalctl:

May 01 11:03:02 homeassistant kernel: Bluetooth: Core ver 2.22
May 01 11:03:02 homeassistant kernel: Bluetooth: Starting self testing
May 01 11:03:03 homeassistant kernel: Bluetooth: ECDH test passed in 15142 usecs
May 01 11:03:03 homeassistant kernel: Bluetooth: SMP test passed in 11321 usecs
May 01 11:03:03 homeassistant kernel: Bluetooth: Finished self testing
May 01 11:03:03 homeassistant kernel: NET: Registered PF_BLUETOOTH protocol family
May 01 11:03:03 homeassistant kernel: Bluetooth: HCI device and connection manager initialized
May 01 11:03:03 homeassistant kernel: Bluetooth: HCI socket layer initialized
May 01 11:03:03 homeassistant kernel: Bluetooth: L2CAP socket layer initialized
May 01 11:03:03 homeassistant kernel: Bluetooth: SCO socket layer initialized
May 01 11:03:03 homeassistant kernel: Bluetooth: HCI UART driver ver 2.3
May 01 11:03:03 homeassistant kernel: Bluetooth: HCI UART protocol H4 registered
May 01 11:03:03 homeassistant kernel: Bluetooth: HCI UART protocol BCSP registered
May 01 11:03:03 homeassistant kernel: Bluetooth: HCI UART protocol LL registered
May 01 11:03:03 homeassistant kernel: Bluetooth: HCI UART protocol ATH3K registered
May 01 11:03:03 homeassistant kernel: Bluetooth: HCI UART protocol Three-wire (H5) registered
May 01 11:03:03 homeassistant kernel: Bluetooth: HCI UART protocol Intel registered
May 01 11:03:03 homeassistant kernel: Bluetooth: HCI UART protocol Broadcom registered
May 01 11:03:03 homeassistant kernel: Bluetooth: HCI UART protocol QCA registered
May 01 11:03:03 homeassistant kernel: Bluetooth: HCI UART protocol AG6XX registered
May 01 11:03:03 homeassistant kernel: Bluetooth: HCI UART protocol Marvell registered
May 01 11:03:03 homeassistant kernel: Bluetooth: hci0: BCM: chip id 130
May 01 11:03:03 homeassistant kernel: Bluetooth: hci0: BCM: features 0x0f
May 01 11:03:03 homeassistant kernel: Bluetooth: hci0: BCM4345C5
May 01 11:03:03 homeassistant kernel: Bluetooth: hci0: BCM4345C5 (003.006.006) build 0000
May 01 11:03:03 homeassistant kernel: Bluetooth: hci0: BCM4345C5 'brcm/BCM4345C5.hcd' Patch
May 01 11:03:04 homeassistant kernel: Bluetooth: hci0: BCM: features 0x0f
May 01 11:03:04 homeassistant kernel: Bluetooth: hci0: BCM43456 37.4MHz Raspberry Pi BT5.0 [Version: 1052.1108]
May 01 11:03:04 homeassistant kernel: Bluetooth: hci0: BCM4345C5 (003.006.006) build 1108
May 01 11:03:07 homeassistant systemd[1]: Mounting Bluetooth persistent state...
May 01 11:03:07 homeassistant systemd[1]: Mounted Bluetooth persistent state.
May 01 11:03:10 homeassistant (uetoothd)[491]: bluetooth.service: ConfigurationDirectory 'bluetooth' already exists but the mode is different. (File system: 755 ConfigurationDirectoryMode: 555)
May 01 11:03:10 homeassistant systemd[1]: Starting Bluetooth service...
May 01 11:03:10 homeassistant bluetoothd[491]: Bluetooth daemon 5.72
May 01 11:03:10 homeassistant bluetoothd[491]: Starting SDP server
May 01 11:03:10 homeassistant kernel: Bluetooth: BNEP (Ethernet Emulation) ver 1.3
May 01 11:03:10 homeassistant kernel: Bluetooth: BNEP filters: protocol multicast
May 01 11:03:10 homeassistant kernel: Bluetooth: BNEP socket layer initialized
May 01 11:03:10 homeassistant bluetoothd[491]: Bluetooth management interface 1.22 initialized
May 01 11:03:10 homeassistant bluetoothd[491]: src/adapter.c:reset_adv_monitors_complete() Failed to reset Adv Monitors: Failed (0x03)
May 01 11:03:10 homeassistant bluetoothd[491]: Battery Provider Manager created
May 01 11:03:10 homeassistant kernel: Bluetooth: MGMT ver 1.22
May 01 11:03:11 homeassistant systemd[1]: Started Bluetooth service.
May 01 11:03:11 homeassistant bluetoothd[491]: profiles/audio/bap.c:bap_adapter_probe() BAP requires ISO Socket which is not enabled
May 01 11:03:11 homeassistant bluetoothd[491]: bap: Operation not supported (95)
May 01 11:03:11 homeassistant bluetoothd[491]: Failed to clear UUIDs: Failed (0x03)
May 01 11:03:11 homeassistant bluetoothd[491]: Failed to add UUID: Failed (0x03)
May 01 11:03:11 homeassistant bluetoothd[491]: Failed to add UUID: Failed (0x03)
May 01 11:03:11 homeassistant bluetoothd[491]: Failed to add UUID: Failed (0x03)
May 01 11:03:11 homeassistant bluetoothd[491]: Adv Monitor Manager created with supported features:0x00000000, enabled features:0x00000000, max number of supported monitors:32, max number of supported patterns:16
May 01 11:03:11 homeassistant systemd[1]: Reached target Bluetooth Support.
May 01 11:03:18 homeassistant systemd[1]: Remove Bluetooth cache entries was skipped because of an unmet condition check (ConditionPathExistsGlob=/var/lib/bluetooth/*/cache).
May 01 11:04:00 homeassistant bluetoothd[491]: Endpoint registered: sender=:1.34 path=/MediaEndpoint/A2DPSink/sbc
May 01 11:04:00 homeassistant kernel: Bluetooth: RFCOMM TTY layer initialized
May 01 11:04:00 homeassistant kernel: Bluetooth: RFCOMM socket layer initialized
May 01 11:04:00 homeassistant kernel: Bluetooth: RFCOMM ver 1.11
May 01 11:04:00 homeassistant bluetoothd[491]: Endpoint registered: sender=:1.34 path=/MediaEndpoint/A2DPSource/sbc
May 01 11:04:00 homeassistant bluetoothd[491]: Endpoint registered: sender=:1.34 path=/MediaEndpoint/A2DPSink/sbc_xq_453
May 01 11:04:00 homeassistant bluetoothd[491]: Endpoint registered: sender=:1.34 path=/MediaEndpoint/A2DPSource/sbc_xq_453
May 01 11:04:00 homeassistant bluetoothd[491]: Endpoint registered: sender=:1.34 path=/MediaEndpoint/A2DPSink/sbc_xq_512
May 01 11:04:00 homeassistant bluetoothd[491]: Endpoint registered: sender=:1.34 path=/MediaEndpoint/A2DPSource/sbc_xq_512
May 01 11:04:00 homeassistant bluetoothd[491]: Endpoint registered: sender=:1.34 path=/MediaEndpoint/A2DPSink/sbc_xq_552
May 01 11:04:00 homeassistant bluetoothd[491]: Endpoint registered: sender=:1.34 path=/MediaEndpoint/A2DPSource/sbc_xq_552
alexschultze commented 2 months ago

Fully disabling the bluetooth integration (removing default_config from configuration.yaml), there still is the same effect in bluetoothctl with the alternating "scan on/scan off"

alexschultze commented 2 months ago

More journalctl info with DEBUG enabled.

May 01 11:55:03 homeassistant bluetoothd[488]: Starting SDP server
May 01 11:55:03 homeassistant kernel: Bluetooth: BNEP (Ethernet Emulation) ver 1.3
May 01 11:55:03 homeassistant kernel: Bluetooth: BNEP filters: protocol multicast
May 01 11:55:03 homeassistant kernel: Bluetooth: BNEP socket layer initialized
May 01 11:55:03 homeassistant bluetoothd[488]: Bluetooth management interface 1.22 initialized
May 01 11:55:03 homeassistant bluetoothd[488]: src/adapter.c:reset_adv_monitors_complete() Failed to reset Adv Monitors: Failed (0x03)
May 01 11:55:03 homeassistant bluetoothd[488]: Battery Provider Manager created
May 01 11:55:03 homeassistant kernel: Bluetooth: MGMT ver 1.22
May 01 11:55:03 homeassistant systemd[1]: Started Bluetooth service.
May 01 11:55:03 homeassistant systemd[1]: Reached target Bluetooth Support.
May 01 11:55:03 homeassistant bluetoothd[488]: profiles/audio/bap.c:bap_adapter_probe() BAP requires ISO Socket which is not enabled
May 01 11:55:03 homeassistant bluetoothd[488]: bap: Operation not supported (95)
May 01 11:55:03 homeassistant bluetoothd[488]: Failed to clear UUIDs: Failed (0x03)
May 01 11:55:03 homeassistant bluetoothd[488]: Failed to add UUID: Failed (0x03)
May 01 11:55:03 homeassistant bluetoothd[488]: Failed to add UUID: Failed (0x03)
May 01 11:55:03 homeassistant bluetoothd[488]: Failed to add UUID: Failed (0x03)
May 01 11:55:03 homeassistant bluetoothd[488]: Adv Monitor Manager created with supported features:0x00000000, enabled features:0x00000000, max number of supported monitors:32, max number of supported patterns:16
May 01 11:55:10 homeassistant systemd[1]: Remove Bluetooth cache entries was skipped because of an unmet condition check (ConditionPathExistsGlob=/var/lib/bluetooth/*/cache).
May 01 11:55:57 homeassistant bluetoothd[488]: Endpoint registered: sender=:1.33 path=/MediaEndpoint/A2DPSink/sbc
May 01 11:55:57 homeassistant kernel: Bluetooth: RFCOMM TTY layer initialized
May 01 11:55:57 homeassistant kernel: Bluetooth: RFCOMM socket layer initialized
May 01 11:55:57 homeassistant kernel: Bluetooth: RFCOMM ver 1.11
May 01 11:55:57 homeassistant bluetoothd[488]: Endpoint registered: sender=:1.33 path=/MediaEndpoint/A2DPSource/sbc
May 01 11:55:57 homeassistant bluetoothd[488]: Endpoint registered: sender=:1.33 path=/MediaEndpoint/A2DPSink/sbc_xq_453
May 01 11:55:57 homeassistant bluetoothd[488]: Endpoint registered: sender=:1.33 path=/MediaEndpoint/A2DPSource/sbc_xq_453
May 01 11:55:57 homeassistant bluetoothd[488]: Endpoint registered: sender=:1.33 path=/MediaEndpoint/A2DPSink/sbc_xq_512
May 01 11:55:57 homeassistant bluetoothd[488]: Endpoint registered: sender=:1.33 path=/MediaEndpoint/A2DPSource/sbc_xq_512
May 01 11:55:57 homeassistant bluetoothd[488]: Endpoint registered: sender=:1.33 path=/MediaEndpoint/A2DPSink/sbc_xq_552
May 01 11:55:57 homeassistant bluetoothd[488]: Endpoint registered: sender=:1.33 path=/MediaEndpoint/A2DPSource/sbc_xq_552
May 01 11:56:12 homeassistant bluetoothd[488]: Path / reserved for Adv Monitor app :1.40
May 01 11:57:55 homeassistant homeassistant[575]: 2024-05-01 13:57:55.845 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Attempting to recover bluetooth adapter hci0 with mac address 08:FB:EA:E0:74:09
May 01 11:57:55 homeassistant homeassistant[575]: 2024-05-01 13:57:55.846 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Attempting to power cycle bluetooth adapter hci0 [08:FB:EA:E0:74:09]
May 01 11:57:55 homeassistant homeassistant[575]: 2024-05-01 13:57:55.856 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Found adapters from hci: {0: {'dev_id': 0, 'name': 'hci0', 'bdaddr': '08:FB:EA:E0:74:09', 'flags': 5, 'type': 3, 'features': <ifaddr._shared.c_ubyte_Array_8 object at 0xffff98f80b50>, 'pkt_type': 52472, 'link_policy': 5, 'link_mode': 32768, 'acl_mtu': 1021, 'acl_pkts': 8, 'sco_mtu': 64, 'sco_pkts': 1, 'stat': <bluetooth_adapters.systems.linux_hci.hci_dev_stats object at 0xffff98f81250>}}
May 01 11:57:55 homeassistant homeassistant[575]: 2024-05-01 13:57:55.857 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Found adapter 08:FB:EA:E0:74:09 in hci device as 0
May 01 11:57:55 homeassistant homeassistant[575]: 2024-05-01 13:57:55.857 DEBUG (MainThread) [bluetooth_auto_recovery.recover] hci0 (08:FB:EA:E0:74:09) idx is 0
May 01 11:57:55 homeassistant homeassistant[575]: 2024-05-01 13:57:55.863 DEBUG (MainThread) [bluetooth_auto_recovery.recover] rfkill_idx of hci0 is 1
May 01 11:57:55 homeassistant homeassistant[575]: 2024-05-01 13:57:55.863 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Attempting to power cycle bluetooth adapter hci0 [08:FB:EA:E0:74:09]
May 01 11:57:55 homeassistant homeassistant[575]: 2024-05-01 13:57:55,879 - btsocket.btmgmt_protocol - DEBUG - Decoding bluetooth_version as type IntUL
May 01 11:57:55 homeassistant homeassistant[575]: 2024-05-01 13:57:55,889 - btsocket.btmgmt_protocol - DEBUG - Socket Read: <event_code=CommandCompleteEvent, controller_idx=0, param_len=283> <command_opcode=ReadControllerInformation, status=Success> <address=08:FB:EA:E0:74:09, bluetooth_version=9, manufacturer=15, supported_settings=130815, current_settings={Powered: True, Connectable: False, FastConnectable: False, Discoverable: False, Bondable: True, 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=7077888, name=b'homeassistant', short_name=0>
May 01 11:57:55 homeassistant homeassistant[575]: 2024-05-01 13:57:55.879 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding bluetooth_version as type IntUL
May 01 11:57:55 homeassistant homeassistant[575]: 2024-05-01 13:57:55,929 - btsocket.btmgmt_protocol - DEBUG - Decoding bluetooth_version as type IntUL
May 01 11:57:55 homeassistant homeassistant[575]: 2024-05-01 13:57:55.889 DEBUG (MainThread) [btsocket.btmgmt_protocol] Socket Read: <event_code=CommandCompleteEvent, controller_idx=0, param_len=283> <command_opcode=ReadControllerInformation, status=Success> <address=08:FB:EA:E0:74:09, bluetooth_version=9, manufacturer=15, supported_settings=130815, current_settings={Powered: True, Connectable: False, FastConnectable: False, Discoverable: False, Bondable: True, 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=7077888, name=b'homeassistant', short_name=0>
May 01 11:57:55 homeassistant homeassistant[575]: 2024-05-01 13:57:55.891 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Current power state of bluetooth adapter is ON.
May 01 11:57:55 homeassistant homeassistant[575]: 2024-05-01 13:57:55,936 - btsocket.btmgmt_protocol - DEBUG - Socket Read: <event_code=CommandCompleteEvent, controller_idx=0, param_len=283> <command_opcode=ReadControllerInformation, status=Success> <address=08:FB:EA:E0:74:09, bluetooth_version=9, manufacturer=15, supported_settings=130815, current_settings={Powered: False, Connectable: False, FastConnectable: False, Discoverable: False, Bondable: True, 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>
May 01 11:57:55 homeassistant homeassistant[575]: 2024-05-01 13:57:55.929 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding bluetooth_version as type IntUL
May 01 11:57:55 homeassistant homeassistant[575]: 2024-05-01 13:57:55.936 DEBUG (MainThread) [btsocket.btmgmt_protocol] Socket Read: <event_code=CommandCompleteEvent, controller_idx=0, param_len=283> <command_opcode=ReadControllerInformation, status=Success> <address=08:FB:EA:E0:74:09, bluetooth_version=9, manufacturer=15, supported_settings=130815, current_settings={Powered: False, Connectable: False, FastConnectable: False, Discoverable: False, Bondable: True, 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>
May 01 11:57:55 homeassistant homeassistant[575]: 2024-05-01 13:57:55.941 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Bouncing Bluetooth adapter hci0
May 01 11:57:55 homeassistant homeassistant[575]: 2024-05-01 13:57:55.944 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Setting hci0 down
May 01 11:57:56 homeassistant homeassistant[575]: 2024-05-01 13:57:56.449 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Setting hci0 up
May 01 11:57:57 homeassistant homeassistant[575]: 2024-05-01 13:57:57.128 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Finished bouncing hci0
May 01 11:57:57 homeassistant homeassistant[575]: 2024-05-01 13:57:57,160 - btsocket.btmgmt_protocol - DEBUG - Decoding bluetooth_version as type IntUL
May 01 11:57:57 homeassistant homeassistant[575]: 2024-05-01 13:57:57,167 - btsocket.btmgmt_protocol - DEBUG - Socket Read: <event_code=CommandCompleteEvent, controller_idx=0, param_len=283> <command_opcode=ReadControllerInformation, status=Success> <address=08:FB:EA:E0:74:09, bluetooth_version=9, manufacturer=15, supported_settings=130815, current_settings={Powered: True, Connectable: False, FastConnectable: False, Discoverable: False, Bondable: True, 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=7077888, name=b'homeassistant', short_name=0>
May 01 11:57:57 homeassistant homeassistant[575]: 2024-05-01 13:57:57.160 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding bluetooth_version as type IntUL
May 01 11:57:57 homeassistant homeassistant[575]: 2024-05-01 13:57:57.167 DEBUG (MainThread) [btsocket.btmgmt_protocol] Socket Read: <event_code=CommandCompleteEvent, controller_idx=0, param_len=283> <command_opcode=ReadControllerInformation, status=Success> <address=08:FB:EA:E0:74:09, bluetooth_version=9, manufacturer=15, supported_settings=130815, current_settings={Powered: True, Connectable: False, FastConnectable: False, Discoverable: False, Bondable: True, 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=7077888, name=b'homeassistant', short_name=0>
May 01 11:57:57 homeassistant homeassistant[575]: 2024-05-01 13:57:57.169 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Power state of bluetooth adapter hci0 [08:FB:EA:E0:74:09] is ON after power cycle
May 01 11:58:20 homeassistant bluetoothd[488]: Adv Monitor app :1.40 disconnected from D-Bus
May 01 11:59:55 homeassistant homeassistant[575]: 2024-05-01 13:59:55.813 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Attempting to recover bluetooth adapter hci0 with mac address 08:FB:EA:E0:74:09
May 01 11:59:55 homeassistant homeassistant[575]: 2024-05-01 13:59:55.814 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Attempting to power cycle bluetooth adapter hci0 [08:FB:EA:E0:74:09]
May 01 11:59:55 homeassistant homeassistant[575]: 2024-05-01 13:59:55.823 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Found adapters from hci: {0: {'dev_id': 0, 'name': 'hci0', 'bdaddr': '08:FB:EA:E0:74:09', 'flags': 5, 'type': 3, 'features': <ifaddr._shared.c_ubyte_Array_8 object at 0xffff8c6f20d0>, 'pkt_type': 52472, 'link_policy': 5, 'link_mode': 32768, 'acl_mtu': 1021, 'acl_pkts': 8, 'sco_mtu': 64, 'sco_pkts': 1, 'stat': <bluetooth_adapters.systems.linux_hci.hci_dev_stats object at 0xffff8c197bd0>}}
May 01 11:59:55 homeassistant homeassistant[575]: 2024-05-01 13:59:55.824 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Found adapter 08:FB:EA:E0:74:09 in hci device as 0
May 01 11:59:55 homeassistant homeassistant[575]: 2024-05-01 13:59:55.824 DEBUG (MainThread) [bluetooth_auto_recovery.recover] hci0 (08:FB:EA:E0:74:09) idx is 0
May 01 11:59:55 homeassistant homeassistant[575]: 2024-05-01 13:59:55.832 DEBUG (MainThread) [bluetooth_auto_recovery.recover] rfkill_idx of hci0 is 1
May 01 11:59:55 homeassistant homeassistant[575]: 2024-05-01 13:59:55.833 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Attempting to power cycle bluetooth adapter hci0 [08:FB:EA:E0:74:09]
May 01 11:59:55 homeassistant homeassistant[575]: 2024-05-01 13:59:55,845 - btsocket.btmgmt_protocol - DEBUG - Decoding bluetooth_version as type IntUL
May 01 11:59:55 homeassistant homeassistant[575]: 2024-05-01 13:59:55,851 - btsocket.btmgmt_protocol - DEBUG - Socket Read: <event_code=CommandCompleteEvent, controller_idx=0, param_len=283> <command_opcode=ReadControllerInformation, status=Success> <address=08:FB:EA:E0:74:09, bluetooth_version=9, manufacturer=15, supported_settings=130815, current_settings={Powered: True, 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=7077888, name=b'homeassistant', short_name=0>
May 01 11:59:55 homeassistant homeassistant[575]: 2024-05-01 13:59:55.845 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding bluetooth_version as type IntUL
May 01 11:59:55 homeassistant homeassistant[575]: 2024-05-01 13:59:55,887 - btsocket.btmgmt_protocol - DEBUG - Decoding bluetooth_version as type IntUL
May 01 11:59:55 homeassistant homeassistant[575]: 2024-05-01 13:59:55,893 - btsocket.btmgmt_protocol - DEBUG - Socket Read: <event_code=CommandCompleteEvent, controller_idx=0, param_len=283> <command_opcode=ReadControllerInformation, status=Success> <address=08:FB:EA:E0:74:09, bluetooth_version=9, manufacturer=15, supported_settings=130815, 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>
May 01 11:59:55 homeassistant homeassistant[575]: 2024-05-01 13:59:55.851 DEBUG (MainThread) [btsocket.btmgmt_protocol] Socket Read: <event_code=CommandCompleteEvent, controller_idx=0, param_len=283> <command_opcode=ReadControllerInformation, status=Success> <address=08:FB:EA:E0:74:09, bluetooth_version=9, manufacturer=15, supported_settings=130815, current_settings={Powered: True, 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=7077888, name=b'homeassistant', short_name=0>
May 01 11:59:55 homeassistant homeassistant[575]: 2024-05-01 13:59:55.852 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Current power state of bluetooth adapter is ON.
May 01 11:59:55 homeassistant homeassistant[575]: 2024-05-01 13:59:55.887 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding bluetooth_version as type IntUL
May 01 11:59:55 homeassistant homeassistant[575]: 2024-05-01 13:59:55.893 DEBUG (MainThread) [btsocket.btmgmt_protocol] Socket Read: <event_code=CommandCompleteEvent, controller_idx=0, param_len=283> <command_opcode=ReadControllerInformation, status=Success> <address=08:FB:EA:E0:74:09, bluetooth_version=9, manufacturer=15, supported_settings=130815, 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>
May 01 11:59:55 homeassistant homeassistant[575]: 2024-05-01 13:59:55.900 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Bouncing Bluetooth adapter hci0
May 01 11:59:55 homeassistant homeassistant[575]: 2024-05-01 13:59:55.900 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Setting hci0 down
May 01 11:59:56 homeassistant homeassistant[575]: 2024-05-01 13:59:56.404 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Setting hci0 up
May 01 11:59:57 homeassistant homeassistant[575]: 2024-05-01 13:59:57.088 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Finished bouncing hci0
May 01 11:59:57 homeassistant homeassistant[575]: 2024-05-01 13:59:57,125 - btsocket.btmgmt_protocol - DEBUG - Decoding bluetooth_version as type IntUL
May 01 11:59:57 homeassistant homeassistant[575]: 2024-05-01 13:59:57,133 - btsocket.btmgmt_protocol - DEBUG - Socket Read: <event_code=CommandCompleteEvent, controller_idx=0, param_len=283> <command_opcode=ReadControllerInformation, status=Success> <address=08:FB:EA:E0:74:09, bluetooth_version=9, manufacturer=15, supported_settings=130815, current_settings={Powered: True, 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=7077888, name=b'homeassistant', short_name=0>
May 01 11:59:57 homeassistant homeassistant[575]: 2024-05-01 13:59:57.125 DEBUG (MainThread) [btsocket.btmgmt_protocol] Decoding bluetooth_version as type IntUL
May 01 11:59:57 homeassistant homeassistant[575]: 2024-05-01 13:59:57.133 DEBUG (MainThread) [btsocket.btmgmt_protocol] Socket Read: <event_code=CommandCompleteEvent, controller_idx=0, param_len=283> <command_opcode=ReadControllerInformation, status=Success> <address=08:FB:EA:E0:74:09, bluetooth_version=9, manufacturer=15, supported_settings=130815, current_settings={Powered: True, 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=7077888, name=b'homeassistant', short_name=0>
May 01 11:59:57 homeassistant homeassistant[575]: 2024-05-01 13:59:57.135 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Power state of bluetooth adapter hci0 [08:FB:EA:E0:74:09] is ON after power cycle
citruz commented 2 months ago

Thanks for the logs! Looks like it's working for two minutes and then decoded to power cycle the adapter.

2024-05-01 13:57:57.169 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Power state of bluetooth adapter hci0 [08:FB:EA:E0:74:09] is ON after power cycle
2024-05-01 13:59:55.813 DEBUG (MainThread) [bluetooth_auto_recovery.recover] Attempting to recover bluetooth adapter hci0 with mac address 08:FB:EA:E0:74:09

It sounds an awful lot like this issue which was widespread after the upgrade to HAOS 10: https://github.com/home-assistant/core/issues/92379 However, the underlying issue in the kernel is long fixed (in 6.1.57 / HAOS 11.1; was patched in earlier versions) and I don't know of any recent issues similar to it. It's very strange that you seem to be the only one experiencing this. The fact that it also fails on Bullseye which should be an old 5.x kernel makes it even more confusing, but maybe that is unrelated.