Logs present here: https://pantheon.corp.google.com/storage/browser/chromiumos-test-logs/bugfiles/cr/896424

eventlog:

...
25 | 2018-10-17 12:01:02 | System boot | 0
26 | 2018-10-17 12:01:02 | Chrome OS Developer Mode
27 | 2018-10-17 12:12:06 | System boot | 0
28 | 2018-10-17 12:12:06 | Chrome OS Developer Mode
29 | 2018-10-17 12:19:46 | System boot | 0
30 | 2018-10-17 12:19:46 | Chrome OS Developer Mode
31 | 2018-10-17 12:21:37 | System boot | 0
32 | 2018-10-17 12:21:37 | Chrome OS Developer Mode
33 | 2018-10-17 12:25:00 | System boot | 0
34 | 2018-10-17 12:25:00 | Chrome OS Developer Mode
35 | 2018-10-17 12:26:25 | System boot | 0
36 | 2018-10-17 12:26:25 | Chrome OS Developer Mode
37 | 2018-10-17 12:29:04 | Sleep
38 | 2018-10-17 12:29:25 | Wake
39 | 2018-10-17 12:31:00 | System boot | 0
40 | 2018-10-17 12:31:00 | Chrome OS Developer Mode
41 | 2018-10-17 12:31:56 | Sleep
42 | 2018-10-17 12:33:05 | Wake

powerd.PREVIOUS:

...
[1017/123017:INFO:state_controller.cc(916)] Updated settings: dim=10s screen_off=15s lock=0s idle_warn=0s idle=20s (suspend) lid_closed=no-op use_audio=1 use_video=1 wake_locks=
[1017/123017:INFO:daemon.cc(1110)] Received request to stop forcing backlights off
[1017/123017:INFO:suspend_delay_controller.cc(62)] Registering suspend delay 496041987 (shill) of 19500 ms on behalf of :1.8
[1017/123017:INFO:display_power_setter.cc(81)] Asking DisplayService to turn all displays on
[1017/123017:INFO:daemon.cc(1136)] Session state changed to started
[1017/123017:INFO:state_controller.cc(916)] Updated settings: dim=10s screen_off=15s lock=0s idle_warn=0s idle=20s (suspend) lid_closed=no-op use_audio=1 use_video=1 wake_locks=
[1017/123017:INFO:state_controller.cc(1212)] Update operation is UPDATE_STATUS_IDLE
[1017/123017:INFO:suspend_delay_controller.cc(62)] Registering dark suspend delay 496074754 (shill) of 19500 ms on behalf of :1.8
[1017/123017:INFO:audio_client.cc(162)] Updated audio devices: headphones unplugged, HDMI active
[1017/123021:INFO:daemon.cc(750)] On AC (USB_PD, 15.0V, max 2.5A at 15.0V) with battery at 79% (displayed as 82%), 3.971/5.020Ah at 2.090A, 24m21s until full
[1017/123027:INFO:state_controller.cc(100)] Dimming screen after 10s
[1017/123027:INFO:internal_backlight_controller.cc(734)] Setting brightness to 6554 (35.0114%) over 200 ms
[1017/123032:INFO:state_controller.cc(100)] Turning screen off after 15s
[1017/123032:INFO:internal_backlight_controller.cc(734)] Setting brightness to 0 (0%) over 200 ms
[1017/123032:INFO:display_power_setter.cc(81)] Asking DisplayService to turn all displays off
[1017/123032:INFO:daemon.cc(1077)] Chrome is using presentation display mode
[1017/123032:INFO:audio_client.cc(162)] Updated audio devices: headphones unplugged, HDMI inactive
[1017/123037:INFO:state_controller.cc(1061)] Ready to perform idle action (suspend) after 20s
[1017/123037:INFO:suspender.cc(377)] Starting request 496041985
[1017/123037:INFO:daemon.cc(544)] Reading wakeup count from /sys/power/wakeup_count
[1017/123037:INFO:daemon.cc(548)] Read wakeup count 489
[1017/123037:INFO:suspend_delay_controller.cc(137)] Announcing suspend request 496041985 with 3 pending delay(s) and 0 outstanding delay(s) from previous request
[1017/123037:INFO:suspend_delay_controller.cc(86)] Got notification that delay 496041985 (btdispatch) is ready for suspend request 496041985 from :1.31
[1017/123037:INFO:suspend_delay_controller.cc(86)] Got notification that delay 496041987 (shill) is ready for suspend request 496041985 from :1.8
[1017/123037:INFO:daemon.cc(1095)] Received updated external policy: ac_dim=7m ac_screen_off=7m30s ac_lock=7m40s ac_idle_warn=0s ac_idle=30m battery_dim=5m battery_screen_off=5m30s battery_lock=5m40s 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)
[1017/123037:INFO:state_controller.cc(916)] Updated settings: dim=10s screen_off=15s lock=0s idle_warn=0s idle=20s (suspend) lid_closed=no-op use_audio=1 use_video=1 wake_locks=
[1017/123043:INFO:daemon.cc(473)] Power button down
[1017/123043:INFO:main.cc(247)] Launching "sync"
[1017/123043:INFO:activity_logger.cc(20)] User activity reported
[1017/123043:INFO:suspender.cc(339)] Aborting request in response to user activity
[1017/123043:INFO:suspender.cc(416)] Finishing request 496041985 unsuccessfully after 6s
[1017/123043:INFO:state_controller.cc(107)] Undimming screen
[1017/123043:INFO:state_controller.cc(107)] Turning screen on
[1017/123043:INFO:display_power_setter.cc(81)] Asking DisplayService to turn all displays on
[1017/123045:INFO:internal_backlight_controller.cc(734)] Setting brightness to 40718 (80%) over 0 ms
[1017/123045:INFO:daemon.cc(1095)] 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)
[1017/123045:INFO:state_controller.cc(916)] Updated settings: dim=10s screen_off=15s lock=0s idle_warn=0s idle=20s (suspend) lid_closed=no-op use_audio=1 use_video=1 wake_locks=
[1017/123045:INFO:daemon.cc(1077)] Chrome is using presentation display mode
[1017/123045:INFO:daemon.cc(473)] Power button up
[1017/123045:INFO:daemon.cc(972)] Got RequestShutdown message from :1.9 with reason user-request (UI request from ash: power button)
[1017/123045:INFO:display_power_setter.cc(81)] Asking DisplayService to turn all displays off
[1017/123046:INFO:internal_backlight_controller.cc(734)] Setting brightness to 0 (0%) over 0 ms
[1017/123046:INFO:daemon.cc(1191)] Shutting down, reason: user-request
[1017/123046:INFO:main.cc(247)] Launching "/usr/bin/powerd_setuid_helper --action=shut_down --shutdown_reason=user-request"
[1017/123046:INFO:daemon.cc(1077)] Chrome is using presentation display mode
[1017/123046:INFO:daemon.cc(750)] On AC (USB_PD, 14.8V, max 2.5A at 15.0V) with battery at 79% (displayed as 82%), 3.985/5.020Ah at 2.062A, 0s until full (calculating)
[1017/123046:INFO:suspend_delay_controller.cc(75)] Unregistering suspend delay 496041987 (shill) on behalf of :1.8
[1017/123046:INFO:suspend_delay_controller.cc(75)] Unregistering dark suspend delay 496074754 (shill) on behalf of :1.8
[1017/123046:INFO:daemon.cc(1136)] Session state changed to stopped
[1017/123046:INFO:state_controller.cc(916)] Updated settings: dim=10s screen_off=15s lock=0s idle_warn=0s idle=20s (suspend) lid_closed=no-op use_audio=1 use_video=1 wake_locks=
[1017/123047:INFO:daemon.cc(1095)] 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=no-op 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)
[1017/123047:INFO:state_controller.cc(916)] Updated settings: dim=10s screen_off=15s lock=0s idle_warn=0s idle=20s (suspend) lid_closed=no-op use_audio=1 use_video=1 wake_locks=
[1017/123047:INFO:suspend_delay_controller.cc(121)] Unregistering suspend delay 496041986 (chrome) due to D-Bus client :1.9 going away
[1017/123047:INFO:suspend_delay_controller.cc(121)] Unregistering dark suspend delay 496074753 (chrome) due to D-Bus client :1.9 going away
EOF

Summarizing:

12:30:32 screen off
12:30:37 powerd starts suspending
12:30:43 power button down; suspend aborts
12:30:45 power button up; system shuts down

The reason we shut down was because the power button was held for two seconds. Did you release it more quickly than that, or does that sound right?

Also note that the system hadn't actually suspended when the power button was held, likely because some process (Chrome?) didn't report that it was ready.

Re: #2 - It was definitely a quick/short press <1 sec.  Able to reproduce it before the device went into suspend state (LED was still in blue color).  Latest logs updated in the above link.  

What's the repro rate on this? 1/10? 5/10? 10/10? Thanks.

Was able to repro 2/5 times.   

Mind attaching some more logs to make it possible to see if the symptoms are the same? A video would be helpful too. Thanks!

Oh, and one other question: do you still see this if you wait for the system to enter suspend (per the LED) before pressing the button? Or does it only happen if you press the button after the screen has turned off but before the LED indicates that it's suspended?

@pgangishetty, please attach logs and info per #8 when able. Thanks.

Re: #8 - Able to reproduce once this morning.  Attached are the latest logs from today. 

https://pantheon.corp.google.com/storage/browser/chromiumos-test-logs/bugfiles/cr/896424/10192018/

Re: #8 - I do not see the issue once the system enters suspend state (per the LED)

Thanks for the extra info. Sending to derat@

Thanks. From powerd.PREVIOUS in #10:

[1019/101512:INFO:suspender.cc(377)] Starting request 319422467
[1019/101512:INFO:daemon.cc(544)] Reading wakeup count from /sys/power/wakeup_count
[1019/101512:INFO:daemon.cc(548)] Read wakeup count 250
[1019/101512:INFO:suspend_delay_controller.cc(137)] Announcing suspend request 319422467 with 3 pending delay(s) and 0 outstanding delay(s) from previous request
[1019/101512:INFO:suspend_delay_controller.cc(86)] Got notification that delay 319422465 (btdispatch) is ready for suspend request 319422467 from :1.31
[1019/101512:INFO:suspend_delay_controller.cc(86)] Got notification that delay 319422466 (shill) is ready for suspend request 319422467 from :1.8
...
[1019/101517:INFO:daemon.cc(473)] Power button down
[1019/101517:INFO:main.cc(247)] Launching "sync"
[1019/101517:INFO:activity_logger.cc(20)] User activity reported
[1019/101517:INFO:suspender.cc(339)] Aborting request in response to user activity
[1019/101517:INFO:suspender.cc(416)] Finishing request 319422467 unsuccessfully after 4s
[1019/101517:INFO:state_controller.cc(107)] Undimming screen
[1019/101517:INFO:state_controller.cc(107)] Turning screen on
[1019/101517:INFO:display_power_setter.cc(81)] Asking DisplayService to turn all displays on
[1019/101520:INFO:internal_backlight_controller.cc(734)] Setting brightness to 14605 (50%) over 0 ms
...
[1019/101520:INFO:daemon.cc(1077)] Chrome is using presentation display mode
[1019/101520:INFO:daemon.cc(473)] Power button up
[1019/101520:INFO:daemon.cc(972)] Got RequestShutdown message from :1.9 with reason user-request (UI request from ash: power button)
[1019/101520:INFO:display_power_setter.cc(81)] Asking DisplayService to turn all displays off
[1019/101521:INFO:internal_backlight_controller.cc(734)] Setting brightness to 0 (0%) over 0 ms
[1019/101521:INFO:daemon.cc(1191)] Shutting down, reason: user-request

I think that the problem here is that Chrome is taking 3 seconds to respond to powerd's call to turn displays on at 10:15:17. powerd makes a synchronous call to Chrome, so it doesn't see the power button release event until 10:15:20. By the time that it reports that to Chrome, the button's been seen as having been down for long enough that Chrome just shuts down.

This is basically the same situation that's tracked in issue 685734 (Jan 2017). The workaround there was to increase the shutdown delay in Chrome to 2 seconds to work around the delayed power button events. I still think it's reasonable for powerd's D-Bus calls to set the display power to become asynchronous, but that's a high-risk change that makes the code substantially more complicated and race-prone. It's unlikely to happen for M70.

Stephane, can you recommend someone to investigate why kevin is apparently now taking 3 seconds to reconfigure displays?

pgangishetty@, can you also attach the Chrome user logs from /home/chronos/user/log (while logged in as the same user on the same device)? I'd like to know why Chrome is taking so long to report that it's ready to suspend. Is Chrome's display-configuration code also responsible for that being slow?

Chrome user logs attached in the link below as per #13 for the same user & device:

https://pantheon.corp.google.com/storage/browser/chromiumos-test-logs/bugfiles/cr/896424/chrome_logs/

Is this only on Kevin devices? Want to check on how widespread this issue might be. Thanks.

@13: Reconfiguring display is an operation that depends on environmental factors (cables, type of panel, what we do to the display etc.) and as such we can't guarantee that it will finish within any given time (of course; as you increase the limit, it gets easier to fit).

Re my question in #13 about why Chrome didn't report that it was ready to suspend:

[1588:1588:1019/101517.727604:WARNING:power_manager_client.cc(884)] Didn't report suspend readiness due to SuspendImminent@../../../../../../../home/chrome-bot/chrome_root/src/ash/system/power/power_event_observer.cc:257

Which is this:

251 void PowerEventObserver::SuspendImminent(
252     power_manager::SuspendImminent::Reason reason) {
253   suspend_in_progress_ = true;
254 
255   displays_suspended_callback_ = chromeos::DBusThreadManager::Get()
256                                      ->GetPowerManagerClient()
257                                      ->GetSuspendReadinessCallback(FROM_HERE);

So it looks like we still hadn't reconfigured displays after 5 seconds. :-(

Does either Chrome or the kernel give up on reconfiguration after some amount of time?

And is this actually a regression? Do pre-M70 builds not display this problem on kevin when you connect the same peripherals?

Will we be targeting a fix for this in M70? We are at Stable for M70.

No, any changes here would be way too risky to skip going through the usual canary/dev/beta/stable path.

But I also don't think that this should be RBS unless it's actually a regression (and if it's a regression, we should look into fixing whatever made it happen). I think it's likely that this happens inconsistently with slow monitors.