elm: suspend-failed forced shutdown. Bluetooth: btmrvl_main.c:btmrvl_enable_hs() Host sleep enable command failed |
|||||||||||
Issue descriptionChrome Version: 68.0.3440.59 beta OS: 10718.50.0 What steps will reproduce the problem? (1) close lid after logging in (2) open lid What is the expected result? wake from suspend ... user logged in. What happens instead? device boots. Please use labels and text to provide additional information. From feedback:85555841352 Device repeatedly attempts to suspend but re-wakes due to a failure suspending bluetooth module (marvell). Details below. eventlog -------- 180 | 2018-07-15 20:18:41 | Sleep 181 | 2018-07-15 20:18:41 | Wake 182 | 2018-07-15 20:18:52 | Sleep 183 | 2018-07-15 21:33:54 | Wake 184 | 2018-07-15 21:42:28 | Sleep 185 | 2018-07-15 21:42:28 | Wake 186 | 2018-07-15 21:42:38 | Sleep 187 | 2018-07-15 21:59:42 | Wake 188 | 2018-07-15 22:06:57 | Sleep 189 | 2018-07-15 22:06:57 | Wake 190 | 2018-07-15 22:07:07 | Sleep 191 | 2018-07-16 08:18:37 | Sleep 192 | 2018-07-16 08:18:37 | Wake 193 | 2018-07-16 08:18:47 | Sleep 194 | 2018-07-16 22:34:28 | Wake 195 | 2018-07-16 23:01:57 | Sleep 196 | 2018-07-16 23:01:57 | Wake 197 | 2018-07-16 23:02:07 | Sleep 198 | 2018-07-17 07:25:55 | Wake 199 | 2018-07-17 07:31:09 | Sleep 200 | 2018-07-17 07:31:10 | Wake 201 | 2018-07-17 07:31:20 | Sleep 202 | 2018-07-17 22:40:36 | Wake 203 | 2018-07-17 22:53:33 | Sleep 204 | 2018-07-17 22:53:33 | Wake 205 | 2018-07-17 22:53:43 | Sleep 206 | 2018-07-17 22:53:50 | Wake 207 | 2018-07-17 22:54:00 | Sleep 208 | 2018-07-17 22:54:06 | Wake 209 | 2018-07-17 22:54:16 | Sleep 210 | 2018-07-17 22:54:21 | Wake 211 | 2018-07-17 22:54:31 | Sleep 212 | 2018-07-17 22:54:37 | Wake 213 | 2018-07-17 22:54:47 | Sleep 214 | 2018-07-17 22:54:53 | Wake 215 | 2018-07-17 22:55:03 | Sleep 216 | 2018-07-17 22:55:09 | Wake 217 | 2018-07-17 22:55:19 | Sleep 218 | 2018-07-17 22:55:24 | Wake 219 | 2018-07-17 22:55:34 | Sleep 220 | 2018-07-17 22:55:40 | Wake 221 | 2018-07-17 22:55:50 | Sleep 222 | 2018-07-17 22:55:56 | Wake 223 | 2018-07-17 22:56:06 | Sleep 224 | 2018-07-17 22:56:11 | Wake 225 | 2018-07-18 07:24:42 | System boot | 0 powerd.PREVIOUS [0717/225332:INFO:state_controller.cc(1025)] Ready to perform lid-closed action (suspend) [0717/225332:INFO:suspender.cc(377)] Starting request 71958535 [0717/225332:INFO:daemon.cc(606)] Reading wakeup count from /sys/power/wakeup_count [0717/225332:INFO:daemon.cc(610)] Read wakeup count 5366 [0717/225332:INFO:internal_backlight_controller.cc(688)] Setting brightness to 0 (0%) over 0 ms [0717/225332:INFO:suspend_delay_controller.cc(137)] Announcing suspend request 71958535 with 3 pending delay(s) and 0 outstanding delay(s) from previous request [0717/225332:INFO:suspend_delay_controller.cc(86)] Got notification that delay 71958531 (btdispatch) is ready for suspend request 71958535 from :1.29 [0717/225332:INFO:suspend_delay_controller.cc(86)] Got notification that delay 71958529 (shill) is ready for suspend request 71958535 from :1.8 [0717/225332:INFO:daemon.cc(1307)] Received updated external policy: ac_dim=30s ac_screen_off=40s ac_lock=50s ac_idle_warn=0s ac_idle=30m battery_dim=30s battery_screen_off=40s battery_lock=50s battery_idle_warn=0s battery_idle=6m30s ac_idle=suspend battery_idle=suspend lid_closed=suspend use_audio=1 use_video=1 presentation_factor=2.0 user_activity_factor=2.0 wait_for_initial_user_activity=0 force_nonzero_brightness_for_user_activity=1 (Prefs) [0717/225332:INFO:state_controller.cc(876)] Updated settings: dim=30s screen_off=40s lock=50s idle_warn=0s idle=6m30s (suspend) lid_closed=suspend use_audio=1 use_video=1 wake_locks= [0717/225333:INFO:daemon.cc(1289)] Chrome is using normal display mode [0717/225333:INFO:suspend_delay_controller.cc(86)] Got notification that delay 71958532 (chrome) is ready for suspend request 71958535 from :1.40 [0717/225333:INFO:suspend_delay_controller.cc(223)] Notifying observers that suspend is ready [0717/225333:INFO:suspender.cc(450)] Starting suspend [0717/225333:INFO:main.cc(259)] Running "/usr/bin/powerd_setuid_helper --action=mosys_eventlog --mosys_eventlog_code=0xa7" [0717/225333:INFO:main.cc(259)] Running "/usr/bin/powerd_setuid_helper --action=suspend --suspend_wakeup_count_valid --suspend_wakeup_count=5366" [0717/225333:ERROR:main.cc(265)] Command failed with exit status 2 [0717/225333:INFO:daemon.cc(698)] powerd_suspend returned 2 [0717/225333:INFO:main.cc(240)] Launching "/usr/bin/powerd_setuid_helper --action=mosys_eventlog --mosys_eventlog_code=0xa8" [0717/225333:WARNING:suspender.cc(547)] Suspend attempt #1 canceled due to wake event [0717/225343:INFO:suspender.cc(450)] Starting suspend [0717/225343:INFO:main.cc(259)] Running "/usr/bin/powerd_setuid_helper --action=mosys_eventlog --mosys_eventlog_code=0xa7" [0717/225343:INFO:main.cc(259)] Running "/usr/bin/powerd_setuid_helper --action=suspend" [0717/225350:ERROR:main.cc(265)] Command failed with exit status 3 [0717/225350:INFO:daemon.cc(698)] powerd_suspend returned 3 ... [0717/225611:ERROR:main.cc(265)] Command failed with exit status 3 [0717/225611:INFO:daemon.cc(698)] powerd_suspend returned 3 [0717/225611:INFO:main.cc(240)] Launching "/usr/bin/powerd_setuid_helper --action=mosys_eventlog --mosys_eventlog_code=0xa8" [0717/225611:ERROR:suspender.cc(539)] Unsuccessfully attempted to suspend 11 times; shutting down [0717/225611:INFO:display_power_setter.cc(81)] Asking DisplayService to turn all displays off [0717/225611:INFO:daemon.cc(1425)] Shutting down, reason: suspend-failed syslog ------ 2018-07-17T22:55:08.974303-07:00 ERR kernel: [ 4843.501811] Bluetooth: btmrvl_main.c:btmrvl_enable_hs() Host sleep enable command failed 2018-07-17T22:55:08.974307-07:00 ERR kernel: [ 4843.501824] Bluetooth: btmrvl_sdio.c:btmrvl_sdio_suspend() HS not actived, suspend failed! 2018-07-17T22:55:08.974311-07:00 ERR kernel: [ 4843.501845] dpm_run_callback(): pm_generic_suspend+0x0/0x48 returns -16 2018-07-17T22:55:08.974315-07:00 INFO kernel: [ 4843.501855] call mmc2:0001:2+ returned -16 after 4881847 usecs 2018-07-17T22:55:08.974319-07:00 ERR kernel: [ 4843.501868] PM: Device mmc2:0001:2 failed to suspend async: error -16 2018-07-17T22:55:08.974323-07:00 ERR kernel: [ 4843.502111] PM: Some devices failed to suspend, or early wake event detected ... 2018-07-17T22:55:08.984093-07:00 INFO kernel: [ 4843.587899] PM: resume of devices complete after 85.771 msecs 2018-07-17T22:55:08.984099-07:00 DEBUG kernel: [ 4843.590988] PM: Finishing wakeup. 2018-07-17T22:55:08.996741-07:00 WARNING kernel: [ 4843.590995] Restarting tasks ... done. 2018-07-17T22:55:09.005659-07:00 NOTICE powerd_suspend[21560]: Warning: Device or resource busy on write to /sys/power/state 2018-07-17T22:55:09.007395-07:00 NOTICE powerd_suspend[21561]: --- begin /sys/kernel/debug/suspend_stats --- 2018-07-17T22:55:09.019070-07:00 NOTICE powerd_suspend[21565]: success: 6 2018-07-17T22:55:09.019151-07:00 NOTICE powerd_suspend[21565]: fail: 6 2018-07-17T22:55:09.019227-07:00 NOTICE powerd_suspend[21565]: failed_freeze: 0 2018-07-17T22:55:09.019286-07:00 NOTICE powerd_suspend[21565]: failed_prepare: 0 2018-07-17T22:55:09.019344-07:00 NOTICE powerd_suspend[21565]: failed_suspend: 6 2018-07-17T22:55:09.019402-07:00 NOTICE powerd_suspend[21565]: failed_suspend_late: 0 2018-07-17T22:55:09.019461-07:00 NOTICE powerd_suspend[21565]: failed_suspend_noirq: 0 2018-07-17T22:55:09.019518-07:00 NOTICE powerd_suspend[21565]: failed_resume: 0 2018-07-17T22:55:09.019576-07:00 NOTICE powerd_suspend[21565]: failed_resume_early: 0 2018-07-17T22:55:09.019633-07:00 NOTICE powerd_suspend[21565]: failed_resume_noirq: 0 2018-07-17T22:55:09.019689-07:00 NOTICE powerd_suspend[21565]: failures: 2018-07-17T22:55:09.019749-07:00 NOTICE powerd_suspend[21565]: last_failed_dev: mmc2:0001:2 2018-07-17T22:55:09.019806-07:00 NOTICE powerd_suspend[21565]: mmc2:0001:2 2018-07-17T22:55:09.019864-07:00 NOTICE powerd_suspend[21565]: last_failed_errno: -16 2018-07-17T22:55:09.019918-07:00 NOTICE powerd_suspend[21565]: -16 2018-07-17T22:55:09.019977-07:00 NOTICE powerd_suspend[21565]: last_failed_step: suspend 2018-07-17T22:55:09.020032-07:00 NOTICE powerd_suspend[21565]: suspend 2018-07-17T22:55:09.024587-07:00 NOTICE powerd_suspend[21566]: --- end /sys/kernel/debug/suspend_stats --- 2018-07-17T22:55:09.037136-07:00 NOTICE powerd_suspend[21570]: wakeup_count is 5371 2018-07-17T22:55:09.046251-07:00 NOTICE powerd_suspend[21574]: Skipping enable BT HCI mode change event on non-Intel BT 2018-07-17T22:55:09.050610-07:00 NOTICE powerd_suspend[21577]: Resume finished
,
Jul 23
This bug needs to be fixed and merged back within the next week or it will start blocking our R68 stable release.
,
Jul 25
Whom owns BT on Elm?
,
Jul 25
Once upon it time it was wnhuang. Now I assume it is chromeos-BT team. Assigning to Miao to help route.
,
Jul 27
If we need to do anything about this, it needs to be done by Monday afternoon, our stable RC builds on Monday night.
,
Jul 30
This is currently blocking the 68 stable release, we intend to build tonight, so if at all possible this should be resolved in the next few hours. Raising priority.
,
Aug 1
Ping again for update, this is holding back the MTK devices.
,
Aug 2
Ping again for update, this is holding back the MTK devices.
,
Aug 2
Can you help triage this Sameer?
,
Aug 2
Sameer, please help get some traction on this issue.
,
Aug 2
,
Aug 2
FWIW my manual testing on elm EVT2 (10718.71.0 test) is NOT showing the failure with BT enabled a) no devices paired. b) a device paired and active (BT headset: Google over ear / GID6B) Perhaps its isolated failure ... lets get a test on PVT device in normal mode to confirm.
,
Aug 3
As a followup on #12, I also tested with on elm DVT (10718.71.0 test). a) BT enabled with no device paired or connected. b) a device paired/connected I didn't observed System boot in /var/log/eventlog.txt as well.
,
Aug 3
,
Aug 3
,
Aug 3
Bernie & others, is the feedback 85555841352 the only known report of this issue? If so, removing RBS would be the right thing to do here.
,
Sep 20
When Bluetooth is enabled on my Acer R13 (elm) it's very often that after a longer sleep phase i will be greated with a booting device. That never happens when bluetooth is disabled. elm 11021.19.0 70.0.3538.22 devloper mode enabled. I see this behaviour for months now.
,
Sep 20
Hi Mario, Thanks for the comment, hopefully these details allow for easier repro of the failure. Could you please file feedback the next time this reboot occurs and reference this issue in the feedback report by adding text 'feedback for crbug.com/865093' thanks
,
Oct 9
,
Oct 16
I send a feedback with the added text. I hope it helps. It's starting to occur more often. I switched to newblue but that didn't help.
,
Nov 6
Any progress on this? My elm reboots on a daily basis now when bluetooth is enabled.
,
Dec 7
I enabled bluetooth with 72.0.3623.3 and had no reboot after sleep for over a week. I would consider this good news. |
|||||||||||
►
Sign in to add a comment |
|||||||||||
Comment 1 by tbroch@chromium.org
, Jul 18