New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Issue 805797 link

Starred by 1 user

Issue metadata

Status: Duplicate
Merged: issue 800998
Owner: ----
Closed: Jan 2018
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 1
Type: Bug-Regression



Sign in to add a comment

veyron_(mickey|minnie): Suspend repeatedly fails due to wake events from gpio-keys.11

Project Member Reported by trumbull@chromium.org, Jan 25 2018

Issue description

Seeing a trend in reports from users that when their Chromebooks go to sleep mode from lid close or idle, they actually shut down instead. When they resume, it's like turning the Chromebook back on after a full shut down.

The majority of these reports are tracked here: https://pulse.corp.google.com/#/feedbackneutron?base_params=18g64jkm

Of 17 reports on M64 Beta in the past 28 days, 11 were from Veyron_minnie. Also reported on Veyron_speedy, Fizz, Kevin, and Link

Sleep Mode causes shutdown - Sample Reports
- https://listnr.corp.google.com/report/84853085642
- https://listnr.corp.google.com/report/84937102624

May be related --> Reports about Inability to wake from Sleep:
- https://listnr.corp.google.com/report/84955233540
- https://listnr.corp.google.com/report/84969198527

Not sure if this is somehow related to  https://crbug.com/803727 
 

Comment 1 by derat@chromium.org, Jan 25 2018

Cc: ravisadineni@chromium.org bleung@chromium.org tbroch@chromium.org snanda@chromium.org
Labels: -Type-Bug -Pri-2 M-65 ReleaseBlock-Stable Pri-1 Type-Bug-Regression
Status: Untriaged (was: Unconfirmed)
Summary: Suspend repeatedly fails due to wake events from gpio-keys.11 (was: Users report that Sleep Mode causes shutdown)
I looked at the powerd.PREVIOUS logs from these two feedback reports:

- https://listnr.corp.google.com/report/84853085642
- https://listnr.corp.google.com/report/84937102624

In both cases, powerd is intentionally shutting the system down after too many failed suspend attempts:

...
[0116/064602:INFO:daemon.cc(595)] Reading wakeup count from /sys/power/wakeup_count
[0116/064602:INFO:daemon.cc(599)] Read wakeup count 452
[0116/064602:INFO:suspender.cc(458)] Starting suspend
[0116/064602:INFO:main.cc(244)] Running "/usr/bin/powerd_setuid_helper --action=mosys_eventlog --mosys_eventlog_code=0xa7"
[0116/064603:INFO:main.cc(244)] Running "/usr/bin/powerd_setuid_helper --action=suspend  --suspend_wakeup_count_valid --suspend_wakeup_count=452"
[0116/064603:ERROR:main.cc(250)] Command failed with exit status 2
[0116/064603:INFO:daemon.cc(687)] powerd_suspend returned 2
[0116/064603:INFO:main.cc(225)] Launching "/usr/bin/powerd_setuid_helper --action=mosys_eventlog --mosys_eventlog_code=0xa8"
[0116/064603:WARNING:suspender.cc(544)] Suspend attempt #9 canceled due to wake event
...
[0116/064603:INFO:daemon.cc(595)] Reading wakeup count from /sys/power/wakeup_count
[0116/064603:INFO:daemon.cc(599)] Read wakeup count 453
[0116/064603:INFO:suspender.cc(458)] Starting suspend
[0116/064603:INFO:main.cc(244)] Running "/usr/bin/powerd_setuid_helper --action=mosys_eventlog --mosys_eventlog_code=0xa7"
[0116/064605:INFO:main.cc(244)] Running "/usr/bin/powerd_setuid_helper --action=suspend  --suspend_wakeup_count_valid --suspend_wakeup_count=453"
[0116/064606:ERROR:main.cc(250)] Command failed with exit status 3
[0116/064606:INFO:daemon.cc(687)] powerd_suspend returned 3
...
[0116/064606:INFO:daemon.cc(595)] Reading wakeup count from /sys/power/wakeup_count
[0116/064606:INFO:daemon.cc(599)] Read wakeup count 454
[0116/064606:INFO:suspender.cc(458)] Starting suspend
[0116/064606:INFO:main.cc(244)] Running "/usr/bin/powerd_setuid_helper --action=mosys_eventlog --mosys_eventlog_code=0xa7"
[0116/064609:INFO:main.cc(244)] Running "/usr/bin/powerd_setuid_helper --action=suspend  --suspend_wakeup_count_valid --suspend_wakeup_count=454"
[0116/064609:ERROR:main.cc(250)] Command failed with exit status 2
[0116/064609:INFO:daemon.cc(687)] powerd_suspend returned 2
[0116/064609:INFO:main.cc(225)] Launching "/usr/bin/powerd_setuid_helper --action=mosys_eventlog --mosys_eventlog_code=0xa8"
[0116/064609:ERROR:suspender.cc(572)] Unsuccessfully attempted to suspend 11 times; shutting down
[0116/064609:INFO:daemon.cc(1590)] Shutting down, reason: suspend-failed

The wakeup count keeps increasing:

2017-12-26T22:21:26.324426-08:00 NOTICE powerd_suspend[11450]: Going to suspend-to-RAM state: args=--suspend_duration=-1 --nosuspend_to_idle --wakeup_count=1600
2017-12-26T22:21:26.481361-08:00 NOTICE powerd_suspend[11505]: Aborting suspend, wake event received
2017-12-26T22:21:26.482353-08:00 INFO kernel: [ 2055.966666] last active wakeup source: gpio-keys.11
2017-12-26T22:21:26.488787-08:00 NOTICE powerd_suspend[11507]: wakeup_count is 1601
2017-12-26T22:21:26.491243-08:00 NOTICE powerd_suspend[11508]: Cancel suspend at kernel
2017-12-26T22:21:26.499654-08:00 NOTICE powerd_suspend[11513]: Resume finished
2017-12-26T22:21:26.610316-08:00 INFO laptop-mode[11551]: Laptop mode 
2017-12-26T22:21:26.612805-08:00 INFO laptop-mode[11552]: enabled, 
2017-12-26T22:21:26.614992-08:00 INFO laptop-mode[11553]: active [unchanged]
2017-12-26T22:21:27.936690-08:00 NOTICE powerd_suspend[11589]: Going to suspend-to-RAM state: args=--suspend_duration=-1 --nosuspend_to_idle --wakeup_count=1601
2017-12-26T22:21:28.117415-08:00 NOTICE powerd_suspend[11645]: Finalizing suspend
2017-12-26T22:21:28.132384-08:00 INFO kernel: [ 2057.610661] PM: suspend entry 2017-12-27 06:21:28.123039161 UTC
2017-12-26T22:21:28.243224-08:00 INFO kernel: [ 2057.610687] PM: Syncing filesystems ... done.
2017-12-26T22:21:28.243326-08:00 DEBUG kernel: [ 2057.724288] PM: Preparing system for mem sleep
2017-12-26T22:21:28.243395-08:00 NOTICE kernel: [ 2057.726589] Freezing user space processes ... 
2017-12-26T22:21:28.243448-08:00 INFO kernel: [ 2057.730485] PM: Wakeup pending, aborting suspend
2017-12-26T22:21:28.243468-08:00 INFO kernel: [ 2057.730512] last active wakeup source: gpio-keys.11
2017-12-26T22:21:28.243474-08:00 NOTICE kernel: [ 2057.730526] 
2017-12-26T22:21:28.243485-08:00 ERR kernel: [ 2057.730535] Freezing of tasks aborted after 0.003 seconds
2017-12-26T22:21:28.252352-08:00 NOTICE kernel: [ 2057.730548] Restarting tasks ... done.
2017-12-26T22:21:28.252405-08:00 INFO kernel: [ 2057.733534] PM: suspend exit 2017-12-27 06:21:28.245915703 UTC
2017-12-26T22:21:28.253506-08:00 NOTICE powerd_suspend[11654]: Warning: Device or resource busy on write to /sys/power/state
2017-12-26T22:21:28.255761-08:00 NOTICE powerd_suspend[11655]: --- begin /sys/kernel/debug/suspend_stats ---
2017-12-26T22:21:28.268753-08:00 NOTICE powerd_suspend[11659]: success: 0
2017-12-26T22:21:28.268814-08:00 NOTICE powerd_suspend[11659]: fail: 2
2017-12-26T22:21:28.268852-08:00 NOTICE powerd_suspend[11659]: failed_freeze: 2
2017-12-26T22:21:28.268892-08:00 NOTICE powerd_suspend[11659]: failed_prepare: 0
2017-12-26T22:21:28.268929-08:00 NOTICE powerd_suspend[11659]: failed_suspend: 0
2017-12-26T22:21:28.268965-08:00 NOTICE powerd_suspend[11659]: failed_suspend_late: 0
2017-12-26T22:21:28.268999-08:00 NOTICE powerd_suspend[11659]: failed_suspend_noirq: 0
2017-12-26T22:21:28.269038-08:00 NOTICE powerd_suspend[11659]: failed_resume: 0
2017-12-26T22:21:28.269074-08:00 NOTICE powerd_suspend[11659]: failed_resume_early: 0
2017-12-26T22:21:28.269110-08:00 NOTICE powerd_suspend[11659]: failed_resume_noirq: 0
2017-12-26T22:21:28.269143-08:00 NOTICE powerd_suspend[11659]: failures:
2017-12-26T22:21:28.269177-08:00 NOTICE powerd_suspend[11659]:   last_failed_dev: 
2017-12-26T22:21:28.269213-08:00 NOTICE powerd_suspend[11659]:   last_failed_errno: -16
2017-12-26T22:21:28.269249-08:00 NOTICE powerd_suspend[11659]:    -16
2017-12-26T22:21:28.270877-08:00 NOTICE powerd_suspend[11659]:   last_failed_step: freeze
2017-12-26T22:21:28.270944-08:00 NOTICE powerd_suspend[11659]:    freeze
2017-12-26T22:21:28.273414-08:00 NOTICE powerd_suspend[11660]: --- end /sys/kernel/debug/suspend_stats ---
2017-12-26T22:21:28.286951-08:00 NOTICE powerd_suspend[11663]: wakeup_count is 1602
2017-12-26T22:21:28.302743-08:00 NOTICE powerd_suspend[11669]: Resume finished
2017-12-26T22:21:28.422912-08:00 INFO laptop-mode[11706]: Laptop mode 
2017-12-26T22:21:28.425790-08:00 INFO laptop-mode[11707]: enabled, 
2017-12-26T22:21:28.428642-08:00 INFO laptop-mode[11708]: active [unchanged]
2017-12-26T22:21:30.238002-08:00 NOTICE powerd_suspend[11746]: Going to suspend-to-RAM state: args=--suspend_duration=-1 --nosuspend_to_idle --wakeup_count=1602
2017-12-26T22:21:30.405719-08:00 NOTICE powerd_suspend[11800]: Aborting suspend, wake event received
2017-12-26T22:21:30.412386-08:00 INFO kernel: [ 2059.891090] last active wakeup source: gpio-keys.11
2017-12-26T22:21:30.413721-08:00 NOTICE powerd_suspend[11802]: wakeup_count is 1603
2017-12-26T22:21:30.416351-08:00 NOTICE powerd_suspend[11803]: Cancel suspend at kernel
2017-12-26T22:21:30.427220-08:00 NOTICE powerd_suspend[11809]: Resume finished

gpio-keys.11 appears to be the wakeup source in both cases.

It's probably too late to fix this for M64, unfortunately.
The device is a volumeup/volumedown, powerbtn.  Not sure why we are seeing spurious wakes .

Input driver version is 1.0.1
Input device ID: bus 0x19 vendor 0x1 product 0x1 version 0x100
Input device name: "gpio-keys.11"
Supported events:
  Event type 0 (EV_SYN)
  Event type 1 (EV_KEY)
    Event code 114 (KEY_VOLUMEDOWN)
    Event code 115 (KEY_VOLUMEUP)
    Event code 116 (KEY_POWER)
  Event type 5 (EV_SW)
    Event code 0 (SW_LID)

Flashed the latest release to see if this can be reproduced. No luck.
CHROMEOS_RELEASE_APPID={432FF9F1-4D2E-7E74-6F98-32E56E904BFB}
CHROMEOS_BOARD_APPID={432FF9F1-4D2E-7E74-6F98-32E56E904BFB}
CHROMEOS_CANARY_APPID={90F229CE-83E2-4FAF-8479-E368A34938B1}
DEVICETYPE=CHROMEBOOK
CHROMEOS_ARC_VERSION=4564826
CHROMEOS_ARC_ANDROID_SDK_VERSION=25
GOOGLE_RELEASE=10176.61.0
CHROMEOS_DEVSERVER=
CHROMEOS_RELEASE_BUILDER_PATH=veyron_minnie-release/R64-10176.61.0
CHROMEOS_RELEASE_BUILD_NUMBER=10176
CHROMEOS_RELEASE_BRANCH_NUMBER=61
CHROMEOS_RELEASE_CHROME_MILESTONE=64
CHROMEOS_RELEASE_PATCH_NUMBER=0
CHROMEOS_RELEASE_TRACK=testimage-channel
CHROMEOS_RELEASE_DESCRIPTION=10176.61.0 (Official Build) dev-channel veyron_minnie test
CHROMEOS_RELEASE_BUILD_TYPE=Official Build
CHROMEOS_RELEASE_NAME=Chrome OS
CHROMEOS_RELEASE_BOARD=veyron_minnie
CHROMEOS_RELEASE_VERSION=10176.61.0
CHROMEOS_AUSERVER=https://tools.google.com/service/update2

 Might be the button is stuck or the device is rested on the side (resulting in the button press) ?

Comment 5 by tbroch@chromium.org, Jan 25 2018

Summary: veyron: Suspend repeatedly fails due to wake events from gpio-keys.11 (was: Suspend repeatedly fails due to wake events from gpio-keys.11)

Comment 6 by tbroch@chromium.org, Jan 25 2018

Summary: veyron_(mickey|minnie): Suspend repeatedly fails due to wake events from gpio-keys.11 (was: veyron: Suspend repeatedly fails due to wake events from gpio-keys.11)
Interesting observation.. the issue is not reproducible if there is no user signed in. But reproducible when the user is signed in.
Turns out it is the Bluetooth.  Veyron uses the gpio-keys to report bluetooth wakeup as well as power-btn wakeup. 
https://chromium.googlesource.com/chromiumos/third_party/kernel/+/chromeos-3.14/arch/arm/boot/dts/rk3288-veyron.dtsi#42

Verified this by turning the Bluetooth off and the issue goes away. Turning the bluetooth on will cause the suspend to fail again.

 

Comment 9 by rajatja@google.com, Jan 26 2018

Mergedinto: 800998
Status: Duplicate (was: Untriaged)

Sign in to add a comment