Bug 207169 - Bluetooth: hci0: command 0x200c tx timeout cause suspend failed
Summary: Bluetooth: hci0: command 0x200c tx timeout cause suspend failed
Status: NEW
Alias: None
Product: Drivers
Classification: Unclassified
Component: Bluetooth (show other bugs)
Hardware: All Linux
: P1 normal
Assignee: linux-bluetooth@vger.kernel.org
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2020-04-09 11:23 UTC by youling257
Modified: 2020-06-28 14:46 UTC (History)
5 users (show)

See Also:
Kernel Version: 5.7
Tree: Mainline
Regression: No


Attachments
debug.txt (71.22 KB, text/plain)
2020-04-09 22:48 UTC, youling257
Details
dynamic_debug.txt (404.04 KB, text/plain)
2020-04-10 01:57 UTC, youling257
Details

Description youling257 2020-04-09 11:23:10 UTC
linux kernel 5.7 coming soon, build test linux kernel master branch.

Bluetooth: hci0: command 0x200c tx timeout cause suspend failed on my Bay trail and Cherry trail device.

[  820.671581] Bluetooth: hci0: command 0x200c tx timeout
[  820.672571] PM: suspend exit

my Bay trail device has a rtl8723bs bluetooth, my Cherry trail has a bcm43430 bluetooth.
Comment 1 youling257 2020-04-09 11:26:07 UTC
if rmmod hci_uart and modprobe hci_uart, can suspend success, test on my Bay trail and Cherry trail device.
Comment 2 youling257 2020-04-09 16:40:02 UTC
open bluetooth,failed to suspend;close bluetooth,can suspend.
this problem is because "Bluetooth: Handle LE devices during suspend""Bluetooth: Handle BR/EDR devices during suspend".

To handle LE devices, we must first disable passive scanning and
disconnect all connected devices
To handle BR/EDR devices, we first disable page scan and disconnect all
connected devices.
Comment 3 youling257 2020-04-09 16:49:16 UTC
[RFC PATCH v4 0/5] Bluetooth: Handle system suspend gracefully
This patch series prepares the Bluetooth controller for system suspend
by disconnecting all devices and preparing the event filter and LE
whitelist with devices that can wake the system from suspend

please add support for byt/cht rtl8723bs and brcm bluetooth, make can wake up byt/cht by use bluetooth keyboard.
Comment 4 youling257 2020-04-09 22:48:46 UTC
Created attachment 288317 [details]
debug.txt

dynamic_debug log
Comment 5 Abhishek Pandit-Subedi 2020-04-09 22:54:07 UTC
Sorry I wasn't clearer over email -- I wanted you to upload dmesg and syslog with dynamic debug enabled when you reproduce the issue.

What you've uploaded looks like just the control file for bluetooth.

--

Please upload /var/log/messages (or /var/log/syslog) and dmesg after reproducing the issue.
Comment 6 youling257 2020-04-10 01:39:09 UTC
my userspace is Androidx86 run on mainline kernel, no the var/log/syslog.
the dmesg is only 
[43444.643546] PM: suspend entry (s2idle)
[43444.742826] Filesystems sync: 0.099 seconds
[43446.770899] Bluetooth: hci0: command 0x0c1a tx timeout
[43448.819138] Bluetooth: hci0: command 0x200c tx timeout
[43448.820028] PM: suspend exit

(In reply to Abhishek Pandit-Subedi from comment #5)
> Sorry I wasn't clearer over email -- I wanted you to upload dmesg and syslog
> with dynamic debug enabled when you reproduce the issue.
> 
> What you've uploaded looks like just the control file for bluetooth.
> 
> --
> 
> Please upload /var/log/messages (or /var/log/syslog) and dmesg after
> reproducing the issue.
Comment 7 youling257 2020-04-10 01:46:39 UTC
kernel CONFIG_DYNAMIC_DEBUG is not set
echo 'file hci_core.c +p' > <debugfs>/dynamic_debug/control
echo 'file hci_request.c +p' > <debugfs>/dynamic_debug/control
echo 'file hci_event.c +p' > <debugfs>/dynamic_debug/control

dmesg
[43794.611052] PM: suspend entry (s2idle)                                                                                                                      [43794.730811] Filesystems sync: 0.119 seconds
[43794.737310] hci0 opcode 0x0c1a plen 1                                                                                                                       [43794.737318] skb len 4
[43794.737322] hci0 opcode 0x200c plen 2                                                                                                                       [43794.737325] skb len 5
[43794.737327] length 2                                                                                                                                        [43794.737353] hci0 cmd_cnt 1 cmd queued 2                                                                                                                     [43794.737361] hci0 type 1 len 4
[43794.739427] hci0
[43796.787139] hci0: Timed out waiting for suspend                                                                                                             [43796.787145] hci0: Bit 4 is set
[43796.787384] hci0 opcode 0x0c05 plen 1
[43796.787395] skb len 4                                                                                                                                       [43796.787404] hci0 opcode 0x200c plen 2
[43796.787409] skb len 5                                                                                                                                       [43796.787416] hci0: LE passive scan with whitelist = 1
[43796.787421] hci0 opcode 0x200b plen 7                                                                                                                       [43796.787426] skb len 10
[43796.787432] hci0 opcode 0x200c plen 2
[43796.787437] skb len 5                                                                                                                                       [43796.787442] length 4
[43796.787463] hci0 cmd_cnt 0 cmd queued 5                                                                                                                     [43796.787941] Bluetooth: hci0: command 0x0c1a tx timeout
[43796.788058] hci0 cmd_cnt 1 cmd queued 5                                                                                                                     [43796.788071] hci0 type 1 len 5
[43796.790264] hci0
[43798.835055] Bluetooth: hci0: command 0x200c tx timeout
[43798.835154] hci0: Timed out waiting for suspend                                                                                                             [43798.835161] hci0 cmd_cnt 1 cmd queued 4
[43798.835167] hci0: Bit 5 is set                                                                                                                              
[43798.835176] hci0 type 1 len 4
[43798.835471] PM: suspend exit                                                                                                                                [43798.836044] hci0
Comment 8 youling257 2020-04-10 01:57:06 UTC
Created attachment 288321 [details]
dynamic_debug.txt

cat /sys/kernel/debug/dynamic_debug/control
Comment 9 Abhishek Pandit-Subedi 2020-04-10 17:55:34 UTC
I saw something similar to this during testing where the bluetooth was being powered down during suspend and commands were timing out. 

However, there is a fix for that in the suspend notifier: https://github.com/torvalds/linux/blob/master/net/bluetooth/hci_core.c#L3324

I wonder if there is a race there.

---

youling:

Does your system power down the Bluetooth on suspend? You can confirm by running "dbus-monitor --system path=/org/bluez/hci0" and looking for the "powered" property to be changed during suspend.

Does your system use rfkill? (And when does it do so?)

If you power down bluetooth well ahead of attempting suspend, does suspend succeed? (i.e. bluetoothctl power off and wait for it to complete successfully)
Comment 10 youling257 2020-04-10 19:12:23 UTC
bluetooth power down suspend succeed.
bluetooth power on suspend failed.
Comment 11 Abhishek Pandit-Subedi 2020-04-10 20:19:00 UTC
Ok -- I think there might be a race between the suspend notifier and the power down mgmt request.

Could you try this patch and see if it fixes it? If yes, I will send the same fix upstream:

diff --git a/net/bluetooth/hci_request.c b/net/bluetooth/hci_request.c                                                                                                                                                                                                                                                                                             
index 649e1e5ed446..03c1b3689c16 100644                                                                                                                                                                                                                                                                                                                            
--- a/net/bluetooth/hci_request.c                                                                                                                                                                                                                                                                                                                                  
+++ b/net/bluetooth/hci_request.c                                                                                                                                                                                                                                                                                                                                  
@@ -1032,6 +1032,16 @@ void hci_req_prepare_suspend(struct hci_dev *hdev, enum suspended_state next)                                                                                                                                                                                                                                                               
                goto done;                                                                                                                                                                                                                                                                                                                                         
        }                                                                                                                                                                                                                                                                                                                                                          
                                                                                                                                                                                                                                                                                                                                                                   
+       /* Do nothing if powered down */                                                                                                                                                                                                                                                                                                                           
+       if (!hdev_is_powered(hdev))                                                                                                                                                                                                                                                                                                                                
+               goto done;                                                                                                                                                                                                                                                                                                                                         
+                                                                                                                                                                                                                                                                                                                                                                  
+       /* If pending power down, return but mark powering down request */                                                                                                                                                                                                                                                                                         
+       if (mgmt_powering_down(hdev)) {                                                                                                                                                                                                                                                                                                                            
+               set_bit(SUSPEND_POWERING_DOWN, hdev->suspend_tasks);                                                                                                                                                                                                                                                                                               
+               goto done;                                                                                                                                                                                                                                                                                                                                         
+       }                                                                                                                                                                                                                                                                                                                                                          
+                                                                                                                                                                                                                                                                                                                                                                  
        hdev->suspend_state = next;                                                                                                                                                                                                                                                                                                                                
        hci_req_init(&req, hdev);
Comment 12 youling257 2020-04-11 04:40:30 UTC
(In reply to Abhishek Pandit-Subedi from comment #11)
> Ok -- I think there might be a race between the suspend notifier and the
> power down mgmt request.
> 
> Could you try this patch and see if it fixes it? If yes, I will send the
> same fix upstream:
> 
> diff --git a/net/bluetooth/hci_request.c b/net/bluetooth/hci_request.c      
> 
> index 649e1e5ed446..03c1b3689c16 100644                                     
> 
> --- a/net/bluetooth/hci_request.c                                           
> 
> +++ b/net/bluetooth/hci_request.c                                           
> 
> @@ -1032,6 +1032,16 @@ void hci_req_prepare_suspend(struct hci_dev *hdev,
> enum suspended_state next)                                                  
> 
>                 goto done;                                                  
> 
>         }                                                                   
> 
>                                                                             
> 
> +       /* Do nothing if powered down */                                    
> 
> +       if (!hdev_is_powered(hdev))                                         
> 
> +               goto done;                                                  
> 
> +                                                                           
> 
> +       /* If pending power down, return but mark powering down request */  
> 
> +       if (mgmt_powering_down(hdev)) {                                     
> 
> +               set_bit(SUSPEND_POWERING_DOWN, hdev->suspend_tasks);        
> 
> +               goto done;                                                  
> 
> +       }                                                                   
> 
> +                                                                           
> 
>         hdev->suspend_state = next;                                         
> 
>         hci_req_init(&req, hdev);

test this patch, still failed suspend if bluetooth power on.
Comment 13 Abhishek Pandit-Subedi 2020-04-13 00:40:07 UTC
From comment #7, I see that the very first command sent in the suspend notifier is failing. If the patch in comment #11 isn't fixing it, then it's unlikely to be a race with the power down mgmt command.

The only other way I can see this getting triggered is if your module is getting powered down or RFKILL-ed during suspend. Can you look through your distro's suspend targets and see what it's doing when entering suspend?
Comment 14 youling257 2020-04-13 04:55:28 UTC
(In reply to Abhishek Pandit-Subedi from comment #13)
> From comment #7, I see that the very first command sent in the suspend
> notifier is failing. If the patch in comment #11 isn't fixing it, then it's
> unlikely to be a race with the power down mgmt command.
> 
> The only other way I can see this getting triggered is if your module is
> getting powered down or RFKILL-ed during suspend. Can you look through your
> distro's suspend targets and see what it's doing when entering suspend?

my system no the rfkill-ed.
echo mem > /sys/power/state
[  856.966615] PM: suspend entry (s2idle)
[  857.000790] Filesystems sync: 0.034 seconds
[  857.003094] Freezing user space processes ... (elapsed 0.004 seconds) done.
[  857.007551] OOM killer disabled.
[  857.007622] Freezing remaining freezable tasks ... (elapsed 0.002 seconds) done.
[  857.009814] printk: Suspending console(s) (use no_console_suspend to debug)
[  857.648295] RTW:  suspend start
[  857.648654] serial 00:02: disabled
[  857.648669] rtc_cmos 00:00: suspend, ctrl 02
[  857.650086] RTW: rtw_dev_unload: driver not in IPS
[  857.658935] RTW: rtw suspend success in 11 ms
[  860.502796] RTW: resume start
[  860.503943] RTW: == SDIO Card Info ==
[  860.503951] RTW:   clock: 50000000 Hz
[  860.503954] RTW:   timing spec :
[  860.503957] sd high-speed
[  860.503963] RTW:   sd3_bus_mode: FALSE
[  860.503966] RTW: ================
[  860.527141] rtc_cmos 00:00: resume, ctrl 02
[  861.760713] RTW: wlan0- hw port(0) mac_addr =8c:18:d9:27:71:71
[  861.767760] RTW: rtw_resume_common:0 in 1265 ms
[  861.913396] OOM killer enabled.
[  861.913433] Restarting tasks ... done.
[  861.927357] PM: suspend exit

Note You need to log in before you can comment on or make changes to this bug.