coral: sometimes fails to suspend when lid is closed |
|
Issue descriptionhttps://listnr.corp.google.com/report/77044575667 reports that a coral device is frequently failing to suspend when its lid is closed while on battery power (as evidenced by its power LED remaining blue). From powerd.PREVIOUS: [1021/213103:INFO:suspender.cc(470)] Starting suspend [1021/213103:INFO:main.cc(237)] Running "/usr/bin/powerd_setuid_helper --action=suspend --suspend_wakeup_count_valid --suspend_wakeup_count=192 --suspend_to_idle" [1021/213104:ERROR:main.cc(243)] Command failed with exit status 3 [1021/213104:INFO:daemon.cc(692)] powerd_suspend returned 3 [1021/213104:WARNING:suspender.cc(556)] Suspend attempt #1 canceled due to wake event [1021/213114:INFO:suspender.cc(470)] Starting suspend [1021/213114:INFO:main.cc(237)] Running "/usr/bin/powerd_setuid_helper --action=suspend --suspend_to_idle" [1021/213115:ERROR:main.cc(243)] Command failed with exit status 3 [1021/213115:INFO:daemon.cc(692)] powerd_suspend returned 3 [1021/213115:WARNING:suspender.cc(556)] Suspend attempt #2 canceled due to wake event [1021/213125:INFO:suspender.cc(470)] Starting suspend [1021/213125:INFO:main.cc(237)] Running "/usr/bin/powerd_setuid_helper --action=suspend --suspend_to_idle" [1021/213126:ERROR:main.cc(243)] Command failed with exit status 3 [1021/213126:INFO:daemon.cc(692)] powerd_suspend returned 3 [1021/213126:WARNING:suspender.cc(556)] Suspend attempt #3 canceled due to wake event [1021/213131:INFO:state_controller.cc(89)] Dimming screen after 30s [1021/213131:INFO:internal_backlight_controller.cc(693)] Setting resume brightness to 7115 (63%) [1021/213136:INFO:suspender.cc(470)] Starting suspend [1021/213136:INFO:main.cc(237)] Running "/usr/bin/powerd_setuid_helper --action=suspend --suspend_to_idle" [1021/213137:ERROR:main.cc(243)] Command failed with exit status 3 [1021/213137:INFO:daemon.cc(692)] powerd_suspend returned 3 [1021/213137:WARNING:suspender.cc(556)] Suspend attempt #4 canceled due to wake event [1021/213140:INFO:state_controller.cc(89)] Turning screen off after 40s [1021/213140:INFO:internal_backlight_controller.cc(693)] Setting resume brightness to 7115 (63%) [1021/213147:INFO:suspender.cc(470)] Starting suspend [1021/213147:INFO:main.cc(237)] Running "/usr/bin/powerd_setuid_helper --action=suspend --suspend_to_idle" [1021/213148:ERROR:main.cc(243)] Command failed with exit status 3 [1021/213148:INFO:daemon.cc(692)] powerd_suspend returned 3 [1021/213148:WARNING:suspender.cc(556)] Suspend attempt #5 canceled due to wake event [1021/213150:INFO:state_controller.cc(89)] Locking screen after 50s [1021/213158:INFO:suspender.cc(470)] Starting suspend [1021/213158:INFO:main.cc(237)] Running "/usr/bin/powerd_setuid_helper --action=suspend --suspend_to_idle" [1021/213200:ERROR:main.cc(243)] Command failed with exit status 3 [1021/213200:INFO:daemon.cc(692)] powerd_suspend returned 3 [1021/213200:WARNING:suspender.cc(556)] Suspend attempt #6 canceled due to wake event [1021/213210:INFO:suspender.cc(470)] Starting suspend [1021/213210:INFO:main.cc(237)] Running "/usr/bin/powerd_setuid_helper --action=suspend --suspend_to_idle" [1021/213211:ERROR:main.cc(243)] Command failed with exit status 3 [1021/213211:INFO:daemon.cc(692)] powerd_suspend returned 3 [1021/213211:WARNING:suspender.cc(556)] Suspend attempt #7 canceled due to wake event [1021/213221:INFO:suspender.cc(470)] Starting suspend [1021/213221:INFO:main.cc(237)] Running "/usr/bin/powerd_setuid_helper --action=suspend --suspend_to_idle" [1021/213222:ERROR:main.cc(243)] Command failed with exit status 3 [1021/213222:INFO:daemon.cc(692)] powerd_suspend returned 3 [1021/213222:WARNING:suspender.cc(556)] Suspend attempt #8 canceled due to wake event [1021/213232:INFO:suspender.cc(470)] Starting suspend [1021/213232:INFO:main.cc(237)] Running "/usr/bin/powerd_setuid_helper --action=suspend --suspend_to_idle" [1021/213233:ERROR:main.cc(243)] Command failed with exit status 3 [1021/213233:INFO:daemon.cc(692)] powerd_suspend returned 3 [1021/213233:WARNING:suspender.cc(556)] Suspend attempt #9 canceled due to wake event [1021/213243:INFO:suspender.cc(470)] Starting suspend [1021/213243:INFO:main.cc(237)] Running "/usr/bin/powerd_setuid_helper --action=suspend --suspend_to_idle" [1021/213244:ERROR:main.cc(243)] Command failed with exit status 3 [1021/213244:INFO:daemon.cc(692)] powerd_suspend returned 3 [1021/213244:WARNING:suspender.cc(556)] Suspend attempt #10 canceled due to wake event [1021/213254:INFO:suspender.cc(470)] Starting suspend [1021/213254:INFO:main.cc(237)] Running "/usr/bin/powerd_setuid_helper --action=suspend --suspend_to_idle" [1021/213255:ERROR:main.cc(243)] Command failed with exit status 3 [1021/213255:INFO:daemon.cc(692)] powerd_suspend returned 3 [1021/213255:ERROR:suspender.cc(584)] Unsuccessfully attempted to suspend 11 times; shutting down The syslog file from the feedback report has some of the later attempts, e.g.: 2017-10-21T21:32:33.384164+08:00 NOTICE powerd_suspend[10332]: Warning: Device or resource busy on write to /sys/power/state 2017-10-21T21:32:33.387924+08:00 NOTICE powerd_suspend[10335]: --- begin /sys/kernel/debug/suspend_stats --- 2017-10-21T21:32:33.404277+08:00 NOTICE powerd_suspend[10350]: success: 1 2017-10-21T21:32:33.404386+08:00 NOTICE powerd_suspend[10350]: fail: 11 2017-10-21T21:32:33.404428+08:00 NOTICE powerd_suspend[10350]: failed_freeze: 0 2017-10-21T21:32:33.404466+08:00 NOTICE powerd_suspend[10350]: failed_prepare: 0 2017-10-21T21:32:33.404504+08:00 NOTICE powerd_suspend[10350]: failed_suspend: 0 2017-10-21T21:32:33.404549+08:00 NOTICE powerd_suspend[10350]: failed_suspend_late: 0 2017-10-21T21:32:33.404592+08:00 NOTICE powerd_suspend[10350]: failed_suspend_noirq: 11 2017-10-21T21:32:33.404629+08:00 NOTICE powerd_suspend[10350]: failed_resume: 0 2017-10-21T21:32:33.404671+08:00 NOTICE powerd_suspend[10350]: failed_resume_early: 0 2017-10-21T21:32:33.404713+08:00 NOTICE powerd_suspend[10350]: failed_resume_noirq: 0 2017-10-21T21:32:33.404755+08:00 NOTICE powerd_suspend[10350]: failures: 2017-10-21T21:32:33.404795+08:00 NOTICE powerd_suspend[10350]: last_failed_dev: 2017-10-21T21:32:33.404836+08:00 NOTICE powerd_suspend[10350]: last_failed_errno: -16 2017-10-21T21:32:33.404876+08:00 NOTICE powerd_suspend[10350]: -16 2017-10-21T21:32:33.404918+08:00 NOTICE powerd_suspend[10350]: last_failed_step: suspend_noirq 2017-10-21T21:32:33.404959+08:00 NOTICE powerd_suspend[10350]: suspend_noirq 2017-10-21T21:32:33.410132+08:00 NOTICE powerd_suspend[10354]: --- end /sys/kernel/debug/suspend_stats --- ... 2017-10-21T21:32:33.426648+08:00 NOTICE powerd_suspend[10365]: wakeup_count is 192 2017-10-21T21:32:33.443982+08:00 NOTICE powerd_suspend[10374]: Resume finished ...
,
Dec 26 2017
I see the same pattern on Asus Flip on beta Version 64.0.3282.41 (Official Build) beta (32-bit). Closing the lid used to work, but it started failing about a month ago. When you close the lid either as logged in user or guest, the side panel light stays lit instead of blinking. After 30sec to 1min, the system shuts down instead of going to sleep. 2017-12-26T16:45:44.822736-05:00 NOTICE powerd_suspend[13465]: Going to suspend-to-RAM state: args=--suspend_duration=-1 --nosuspend_to_idle --wakeup_count=3549 2017-12-26T16:45:45.013516-05:00 NOTICE powerd_suspend[13521]: Finalizing suspend 2017-12-26T16:45:45.021474-05:00 INFO kernel: [ 6840.687634] PM: suspend entry 2017-12-26 21:45:45.019157504 UTC 2017-12-26T16:45:45.083389-05:00 INFO kernel: [ 6840.687663] PM: Syncing filesystems ... done. 2017-12-26T16:45:45.083461-05:00 DEBUG kernel: [ 6840.748683] PM: Preparing system for mem sleep 2017-12-26T16:45:45.083543-05:00 NOTICE kernel: [ 6840.749264] Freezing user space processes ... 2017-12-26T16:45:45.083566-05:00 INFO kernel: [ 6840.751609] PM: Wakeup pending, aborting suspend 2017-12-26T16:45:45.083570-05:00 INFO kernel: [ 6840.751638] last active wakeup source: gpio-keys.11 2017-12-26T16:45:45.083575-05:00 NOTICE kernel: [ 6840.751655] 2017-12-26T16:45:45.083585-05:00 ERR kernel: [ 6840.751664] Freezing of tasks aborted after 0.002 seconds 2017-12-26T16:45:45.091472-05:00 NOTICE kernel: [ 6840.751681] Restarting tasks ... done. 2017-12-26T16:45:45.091522-05:00 INFO kernel: [ 6840.753753] PM: suspend exit 2017-12-26 21:45:45.085279796 UTC 2017-12-26T16:45:45.093607-05:00 NOTICE powerd_suspend[13527]: Warning: Device or resource busy on write to /sys/power/state 2017-12-26T16:45:45.096070-05:00 NOTICE powerd_suspend[13528]: --- begin /sys/kernel/debug/suspend_stats --- 2017-12-26T16:45:45.108908-05:00 NOTICE powerd_suspend[13532]: success: 0 2017-12-26T16:45:45.108975-05:00 NOTICE powerd_suspend[13532]: fail: 4 2017-12-26T16:45:45.109024-05:00 NOTICE powerd_suspend[13532]: failed_freeze: 4 2017-12-26T16:45:45.109065-05:00 NOTICE powerd_suspend[13532]: failed_prepare: 0 2017-12-26T16:45:45.109105-05:00 NOTICE powerd_suspend[13532]: failed_suspend: 0 2017-12-26T16:45:45.109145-05:00 NOTICE powerd_suspend[13532]: failed_suspend_late: 0 2017-12-26T16:45:45.109189-05:00 NOTICE powerd_suspend[13532]: failed_suspend_noirq: 0 2017-12-26T16:45:45.109233-05:00 NOTICE powerd_suspend[13532]: failed_resume: 0 2017-12-26T16:45:45.109274-05:00 NOTICE powerd_suspend[13532]: failed_resume_early: 0 2017-12-26T16:45:45.109314-05:00 NOTICE powerd_suspend[13532]: failed_resume_noirq: 0 2017-12-26T16:45:45.109352-05:00 NOTICE powerd_suspend[13532]: failures: 2017-12-26T16:45:45.109394-05:00 NOTICE powerd_suspend[13532]: last_failed_dev: 2017-12-26T16:45:45.111043-05:00 NOTICE powerd_suspend[13532]: last_failed_errno: -16 2017-12-26T16:45:45.111098-05:00 NOTICE powerd_suspend[13532]: -16 2017-12-26T16:45:45.111142-05:00 NOTICE powerd_suspend[13532]: last_failed_step: freeze 2017-12-26T16:45:45.111657-05:00 NOTICE powerd_suspend[13532]: freeze 2017-12-26T16:45:45.114185-05:00 NOTICE powerd_suspend[13533]: --- end /sys/kernel/debug/suspend_stats --- 2017-12-26T16:45:45.126325-05:00 NOTICE powerd_suspend[13536]: wakeup_count is 3550 2017-12-26T16:45:45.140004-05:00 NOTICE powerd_suspend[13542]: Resume finished 2017-12-26T16:45:45.250468-05:00 INFO laptop-mode[13580]: Laptop mode 2017-12-26T16:45:45.254031-05:00 INFO laptop-mode[13581]: enabled, 2017-12-26T16:45:45.256395-05:00 INFO laptop-mode[13582]: active [unchanged] 2017-12-26T16:45:47.137713-05:00 NOTICE powerd_suspend[13621]: Going to suspend-to-RAM state: args=--suspend_duration=-1 --nosuspend_to_idle --wakeup_count=3550 2017-12-26T16:45:47.331471-05:00 INFO kernel: [ 6842.999805] last active wakeup source: spi0.0 2017-12-26T16:45:47.333966-05:00 NOTICE powerd_suspend[13675]: Aborting suspend, wake event received 2017-12-26T16:45:47.342834-05:00 NOTICE powerd_suspend[13677]: wakeup_count is 3555 2017-12-26T16:45:47.346514-05:00 NOTICE powerd_suspend[13678]: Cancel suspend at kernel 2017-12-26T16:45:47.358524-05:00 NOTICE powerd_suspend[13684]: Resume finished
,
Jan 5 2018
Hi Rick, thanks for report and sorry to here about the standby regression. Could you try and repeat the failure after logging in as a guest and if successful file a feedback report (alt-shift-i) and include strings crbug.com/777586 and @tbroch in the feedback body.
,
Feb 6 2018
I think that #2 (gpio-keys.11) is issue 800998 . Not sure about the original issue, though. Ravi, have you investigated?
,
Feb 6 2018
Is Asus Flip minnie ? On minnie it was the issue where irq from bluetooth scan(as bt is wake capable and wake enabled) results increase in wakeup_count. I think the fix for this which rajat is driving is for the bt deamon to look for a suspend Imminent signal and stop scanning. Will have to look at the coral issue sometime this week.
,
Feb 6 2018
> Is Asus Flip minnie ? Yes, it is -- see https://www.chromium.org/chromium-os/developer-information-for-chrome-os-devices. Let's use this issue to track the initial report about coral. |
|
►
Sign in to add a comment |
|
Comment 1 by tbroch@chromium.org
, Nov 3 2017Owner: ravisadineni@chromium.org
Status: Assigned (was: Untriaged)