Re: QCA6390 bluetooth doesn't work after warm boot or disable/reenable

[Wren Turkal <wt@penguintechs.org>]

Sorry for the double send on the original message. I am still hoping to 
get some help. I have added additional info below.

On 4/4/24 12:14 PM, Wren Turkal wrote:
> Hey there ath11k/bluetooth folks,
> 
> I am having a pretty major problem with QCA6930 for some time (maybe a 
> year or two). I have this bluetooth device:
> 
> 72:00.0 Unassigned class [ff00]: Qualcomm Technologies, Inc QCA6390 
> Wireless Network Adapter
> 
> This device appears to be driven by the ath11k module and others. I hope 
> I am pinging the right lists.
> 
> I am using Fedora Rawhide. Fully updated yesterday. My uname reports this:
> 
> Linux braindead.localdomain 
> 6.9.0-0.rc2.20240402git026e680b0a08.24.fc41.x86_64 #1 SMP 
> PREEMPT_DYNAMIC Tue Apr  2 17:51:18 UTC 2024 x86_64 GNU/Linux

Updated today. Here's the new uname:

Linux braindead.localdomain 
6.9.0-0.rc2.20240405git8cb4a9a82b21.27.fc41.x86_64 #1 SMP 
PREEMPT_DYNAMIC Fri Apr  5 16:48:07 UTC 2024 x86_64 GNU/Linux

I also noticed a new version of bluez. Here is the RPM package version: 
bluez-5.73-3.fc41.x86_64

> My main bluetooth device is  a Logitech MX 3 Mac mouse that uses 
> bluetooth. When bluetooth fails, so does the mouse. I have power cycle 
> my laptop when that happens. I'd love to help find a fix for this.
> 
> The problem is that I cannot disable and re-enable the bluetooth on my 
> system. Bluetooth also doesn't work after a warm boot. I have to power 
> cycle my laptop to recover bluetooth funcitonality. I have tried the 
> following:
> 
> * logging into KDE Plasma (bluetooth stops working)
> * logging into GNOME (works on cold boot, fails on warm boot)

I did notice that the mouse seems to work in Plasma until a few sec 
after I see the background image appears. I suspect that Plasma is 
disabling and reenabling the bluetooth where Gnome does not do that.

> After logging into GNOME during a cold boot, I have also done "systemctl 
> restart bluetooth.service". I get these journal logs during the stop;
> 
> ➜  bt_kernel_bug cat journal-stop-bluetooth-service.log
> Apr 04 10:14:41 braindead.localdomain NetworkManager[1120]: <info> 
> [1712250881.7060] device (F0:5C:77:F2:60:FC): state change: disconnected 
> -> unmanaged (reason 'removed', sys-iface-state: 'removed')
> Apr 04 10:14:41 braindead.localdomain systemd[1]: Starting 
> systemd-rfkill.service - Load/Save RF Kill Switch Status...
> Apr 04 10:14:41 braindead.localdomain systemd[1]: Started 
> systemd-rfkill.service - Load/Save RF Kill Switch Status.
> Apr 04 10:14:41 braindead.localdomain audit[1]: SERVICE_START pid=1 
> uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 
> msg='unit=systemd-rfkill comm="systemd" exe="/usr/lib/systemd/systemd" 
> hostname=? addr=? terminal=? res=success'
> Apr 04 10:14:46 braindead.localdomain systemd[1]: 
> systemd-rfkill.service: Deactivated successfully.
> Apr 04 10:14:46 braindead.localdomain audit[1]: SERVICE_STOP pid=1 uid=0 
> auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 
> msg='unit=systemd-rfkill comm="systemd" exe="/usr/lib/systemd/systemd" 
> hostname=? addr=? terminal=? res=success'
> 
> I get these journal logs during start:
> 
> Apr 04 10:15:05 braindead.localdomain kernel: Bluetooth: hci0: setting 
> up ROME/QCA6390
> Apr 04 10:15:05 braindead.localdomain systemd[1]: Starting 
> systemd-rfkill.service - Load/Save RF Kill Switch Status...
> Apr 04 10:15:05 braindead.localdomain systemd[1]: Started 
> systemd-rfkill.service - Load/Save RF Kill Switch Status.
> Apr 04 10:15:05 braindead.localdomain audit[1]: SERVICE_START pid=1 
> uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 
> msg='unit=systemd-rfkill comm="systemd" exe="/usr/lib/systemd/systemd" 
> hostname=? addr=? terminal=? res=success'
> Apr 04 10:15:05 braindead.localdomain kernel: Bluetooth: hci0: QCA 
> Product ID   :0x00000010
> Apr 04 10:15:05 braindead.localdomain kernel: Bluetooth: hci0: QCA SOC 
> Version  :0x400a0200
> Apr 04 10:15:05 braindead.localdomain kernel: Bluetooth: hci0: QCA ROM 
> Version  :0x00000200
> Apr 04 10:15:05 braindead.localdomain kernel: Bluetooth: hci0: QCA Patch 
> Version:0x00003ac0
> Apr 04 10:15:05 braindead.localdomain kernel: Bluetooth: hci0: QCA 
> controller version 0x02000200
> Apr 04 10:15:05 braindead.localdomain kernel: Bluetooth: hci0: QCA 
> Downloading qca/htbtfw20.tlv
> Apr 04 10:15:06 braindead.localdomain kernel: Bluetooth: hci0: QCA 
> Failed to send TLV segment (-110)
> Apr 04 10:15:06 braindead.localdomain kernel: Bluetooth: hci0: QCA 
> Failed to download patch (-110)
> Apr 04 10:15:06 braindead.localdomain kernel: Bluetooth: hci0: Retry BT 
> power ON:0
> Apr 04 10:15:08 braindead.localdomain kernel: Bluetooth: hci0: command 
> 0xfc00 tx timeout
> Apr 04 10:15:08 braindead.localdomain kernel: Bluetooth: hci0: Reading 
> QCA version information failed (-110)
> Apr 04 10:15:08 braindead.localdomain kernel: Bluetooth: hci0: Retry BT 
> power ON:1
> Apr 04 10:15:10 braindead.localdomain systemd[1]: 
> systemd-rfkill.service: Deactivated successfully.
> Apr 04 10:15:10 braindead.localdomain audit[1]: SERVICE_STOP pid=1 uid=0 
> auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 
> msg='unit=systemd-rfkill comm="systemd" exe="/usr/lib/systemd/systemd" 
> hostname=? addr=? terminal=? res=success'
> Apr 04 10:15:10 braindead.localdomain kernel: Bluetooth: hci0: command 
> 0xfc00 tx timeout
> Apr 04 10:15:10 braindead.localdomain kernel: Bluetooth: hci0: Reading 
> QCA version information failed (-110)
> Apr 04 10:15:10 braindead.localdomain kernel: Bluetooth: hci0: Retry BT 
> power ON:2
> Apr 04 10:15:13 braindead.localdomain bluetoothd[986]: Failed to set 
> mode: Authentication Failed (0x05)
> Apr 04 10:15:13 braindead.localdomain kernel: Bluetooth: hci0: command 
> 0xfc00 tx timeout
> Apr 04 10:15:13 braindead.localdomain kernel: Bluetooth: hci0: Reading 
> QCA version information failed (-110)
> Apr 04 10:15:15 braindead.localdomain chronyd[1065]: Selected source 
> 204.17.205.8 (2.fedora.pool.ntp.org)
> Apr 04 10:15:22 braindead.localdomain systemd[1687]: Created slice 
> background.slice - User Background Tasks Slice.
> Apr 04 10:15:22 braindead.localdomain systemd[1687]: Starting 
> systemd-tmpfiles-clean.service - Cleanup of User's Temporary Files and 
> Directories...
> Apr 04 10:15:22 braindead.localdomain systemd[1687]: Finished 
> systemd-tmpfiles-clean.service - Cleanup of User's Temporary Files and 
> Directories.
> Apr 04 10:15:38 braindead.localdomain audit: BPF prog-id=86 op=LOAD
> Apr 04 10:15:38 braindead.localdomain systemd[1]: Starting 
> plocate-updatedb.service - Update the plocate database...
> Apr 04 10:15:41 braindead.localdomain systemd[1687]: Started 
> vte-spawn-21527424-cb2d-479f-af17-22251e2b37a0.scope - VTE child process 
> 5144 launched by gnome-terminal-server process 4668.
> Apr 04 10:15:53 braindead.localdomain systemd[1]: 
> plocate-updatedb.service: Deactivated successfully.
> Apr 04 10:15:53 braindead.localdomain systemd[1]: Finished 
> plocate-updatedb.service - Update the plocate database.
> Apr 04 10:15:53 braindead.localdomain systemd[1]: 
> plocate-updatedb.service: Consumed 6.802s CPU time.
> Apr 04 10:15:53 braindead.localdomain audit[1]: SERVICE_START pid=1 
> uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 
> msg='unit=plocate-updatedb comm="systemd" exe="/usr/lib/systemd/systemd" 
> hostname=? addr=? terminal=? res=success'
> Apr 04 10:15:53 braindead.localdomain audit[1]: SERVICE_STOP pid=1 uid=0 
> auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 
> msg='unit=plocate-updatedb comm="systemd" exe="/usr/lib/systemd/systemd" 
> hostname=? addr=? terminal=? res=success'
> Apr 04 10:15:54 braindead.localdomain audit: BPF prog-id=86 op=UNLOAD
> Apr 04 10:16:13 braindead.localdomain baloo_file_extractor[5251]: 
> kf.idletime: Could not find any system poller plugin
> Apr 04 10:16:13 braindead.localdomain baloo_file_extractor[5251]: 
> qt.core.qobject.connect: QObject::connect(KAbstractIdleTimePoller, 
> KIdleTime): invalid nullptr parameter
> Apr 04 10:16:13 braindead.localdomain baloo_file_extractor[5251]: 
> qt.core.qobject.connect: QObject::connect(KAbstractIdleTimePoller, 
> KIdleTime): invalid nullptr parameter
> 
> There's a bunch of errors in those logs starting with these two 
> seemingly important lines:
> 
> Apr 04 10:15:06 braindead.localdomain kernel: Bluetooth: hci0: QCA 
> Failed to send TLV segment (-110)
> Apr 04 10:15:06 braindead.localdomain kernel: Bluetooth: hci0: QCA 
> Failed to download patch (-110)

Logs are mostly unchanges when restarting the bluetooth service after a 
cold boot with the bluetooth originally working.

> FWIW, I get similar logs after logging into KDE Plasma. I also get 
> similar logs after a warm boot.
> 
> This appears to be some kind of bug in the initialization of the 
> hardware. Is there any additional information I can provide to help 
> troubleshoot this problem.

I will also say that the bluetooth appears to work throught a 
suspend/resume cycle as long as I don't restart the bluetooth service.

Oh, and my laptop is a Dell 9310 if that helps.

Is there any other info I could collect that might be useful?

I'm pretty new to troubleshooting a problem like this and would be happy 
to have any advice anyone might want to share.

Thanks,
wt

-- 
You're more amazing than you think!