Bug 207169
| Summary: | Bluetooth: hci0: command 0x200c tx timeout cause suspend failed | ||
|---|---|---|---|
| Product: | Drivers | Reporter: | youling257 |
| Component: | Bluetooth | Assignee: | linux-bluetooth (linux-bluetooth) |
| Status: | NEW --- | ||
| Severity: | normal | CC: | abhishekpandit, jwrdegoede, rui.zhang, youling257, yu.c.chen |
| Priority: | P1 | ||
| Hardware: | All | ||
| OS: | Linux | ||
| Kernel Version: | 5.7 | Subsystem: | |
| Regression: | No | Bisected commit-id: | |
| Attachments: |
debug.txt
dynamic_debug.txt |
||
|
Description
youling257
2020-04-09 11:23:10 UTC
if rmmod hci_uart and modprobe hci_uart, can suspend success, test on my Bay trail and Cherry trail device. 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. [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. Created attachment 288317 [details]
debug.txt
dynamic_debug log
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. 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. 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 Created attachment 288321 [details]
dynamic_debug.txt
cat /sys/kernel/debug/dynamic_debug/control
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) bluetooth power down suspend succeed. bluetooth power on suspend failed. 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);
(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. 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? (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 test linux kernel 5.9 can suspend. [ 140.585885] PM: suspend entry (s2idle) [ 140.624364] Filesystems sync: 0.038 seconds [ 142.648683] Bluetooth: hci0: Timed out waiting for suspend events [ 142.648688] Bluetooth: hci0: Suspend timeout bit: 4 [ 142.648691] Bluetooth: hci0: Suspend notifier action (3) failed: -110 [ 142.648696] Freezing user space processes ... [ 142.650906] Bluetooth: hci0: command 0x0c1a tx timeout [ 142.652280] (elapsed 0.003 seconds) done. [ 142.652290] OOM killer disabled. [ 142.652292] Freezing remaining freezable tasks ... (elapsed 0.002 seconds) done. [ 142.654571] printk: Suspending console(s) (use no_console_suspend to debug) [ 142.720243] rt5640 i2c-10EC5640:00: disabling jack detect before suspend [ 142.740141] RTW: suspend start [ 142.743909] RTW: rtw_dev_unload: driver not in IPS [ 142.759916] RTW: rtw suspend success in 20 ms [ 143.302475] serial 00:02: disabled [ 143.302513] rtc_cmos 00:00: suspend, ctrl 02 [ 153.664622] RTW: resume start [ 153.665044] RTW: == SDIO Card Info == [ 153.665050] RTW: clock: 50000000 Hz [ 153.665053] RTW: timing spec : [ 153.665055] sd high-speed [ 153.665060] RTW: sd3_bus_mode: FALSE [ 153.665063] RTW: ================ [ 153.693327] rtc_cmos 00:00: resume, ctrl 02 [ 153.722253] rt5640 i2c-10EC5640:00: re-enabling jack detect after resume [ 153.729674] rt5640 i2c-10EC5640:00: irq status 0x110 [ 154.994299] RTW: wlan0- hw port(0) mac_addr =8c:18:d9:27:71:71 [ 155.006720] RTW: rtw_resume_common:0 in 1342 ms [ 155.157170] OOM killer enabled. [ 155.157173] Restarting tasks ... done. [ 157.187320] Bluetooth: hci0: Timed out waiting for suspend events [ 157.187324] Bluetooth: hci0: Suspend timeout bit: 5 [ 157.187328] Bluetooth: hci0: Suspend notifier action (4) failed: -110 [ 157.187332] PM: suspend exit [ 157.188315] Bluetooth: hci0: command 0x0c05 tx timeout [ 159.239690] Bluetooth: hci0: command 0x200b tx timeout fixed by "Bluetooth: Allow suspend even when preparation has failed". |