I have no real idea who should own this.  I can dig, but hopefully someone on the CC list knows?

Is this plain old screen locking (i.e. the "Show lock screen when waking from sleep" setting) or is it Smart Lock?

Plain old screen locking. I even confirmed that I had fast s2r right up
till the point I turned it on.

Hmm. I'll try to repro this on kevin tomorrow, but I haven't heard anything about it. Does it happen to you every time now?

Can you file a feedback report or collect debug logs after you see it? I want to see what's going on in /var/log/messages and /home/chronos/user/log/chrome with regard to screen-locking.

OK, here you go with a bunch of tests:

1. Started with password only screen lock on.  s2r is slow
2. Turn off screen lock.  s2r is slow (tried twice, slow both times)
3. Power off and on.  s2r is fast (three times in a row)
4. Turn on password only screen lock.  s2r is slow

Feedback report after step #4 is at: https://listnr.corp.google.com/report/84948626876

Presumably others will be able to reproduce this given that I reproduced it with a test account on two distinct machines (though both related devices).

I also repro'd this. Here's my log notice -- yep it's chrome:

[0118/210402:WARNING:suspend_delay_controller.cc(205)] Timed out while waiting for suspend request 104136709 readiness confirmation for 1 delay(s): 104136707 (:1.87: chrome)

Same as Doug's:

[0118/203553:WARNING:suspend_delay_controller.cc(205)] Timed out while waiting for suspend request 104595457 readiness confirmation for 1 delay(s): 104595458 (:1.11: chrome)

Chrome does other things unrelated to screen lock before suspending. From email:

---

The things in Chrome that defer suspend (based on grepping for GetSuspendReadinessCallback) are:

- screen lock (ash/system/power/power_event_observer.cc)
- display configuration (ash/system/power/power_event_observer.cc)
- reporting suspend events to extensions (chrome/browser/chromeos/power/extension_event_observer.cc)
- unmounting disks (chromeos/disks/suspend_unmount_manager.cc)
- notifying ARC (components/arc/power/arc_power_bridge.cc)
- closing ARC video capture device (media/capture/video/chromeos/video_capture_device_arc_chromeos.cc)

---

Is it easy for you to disable ARC to see if that makes the problem go away?

@8: I have definitely reproduced this without ARC++.  All I need is basic screen lock.  I don't even have any weird extensions.  I managed to reproduce this with a testing account that's pretty bare bones.

From the powerd log in #6:

[0118/204330:INFO:suspend_delay_controller.cc(137)] Announcing suspend request 101253124 with 2 pending delay(s) and 0 outstanding delay(s) from previous request
[0118/204330:INFO:suspend_delay_controller.cc(86)] Got notification that delay 101253121 (shill) is ready for suspend request 101253124 from :1.6
...
[0118/204349:WARNING:suspend_delay_controller.cc(205)] Timed out while waiting for suspend request 101253124 readiness confirmation for 1 delay(s): 101253122 (:1.11: chrome)
[0118/204349:INFO:suspend_delay_controller.cc(223)] Notifying observers that suspend is ready
[0118/204349:INFO:suspender.cc(458)] Starting suspend
...
[0118/204357:INFO:suspender.cc(414)] Finishing request 101253124 successfully

----

Here's the corresponding Chrome user log snippet:

[1744:1744:0118/204330.343921:INFO:tether_service.cc(342)] Tether state has changed. New state: [other or unknown], Old state: [no potential Tether hosts]
[1744:1744:0118/204330.351979:VERBOSE1:display_configurator.cc(950)] Display snapshots invalidated.
[1744:1744:0118/204330.353879:VERBOSE1:update_display_configuration_task.cc(69)] OnDisplaysUpdated: new_display_state=SINGLE new_power_state=ALL_OFF flags=0 force_configure=0 display_count=1
[1744:1744:0118/204330.354099:VERBOSE1:display_configurator.cc(212)] EnterState: display=SINGLE power=ALL_OFF
[1744:1744:0118/204330.367054:VERBOSE1:screen_locker.cc(489)] Received LockScreen request from session manager
[1744:1744:0118/204330.374417:VERBOSE1:screen_locker.cc(529)] Created ScreenLocker 0xe64b2d0
[1744:1744:0118/204330.581157:VERBOSE1:screen_locker.cc(610)] ScreenLocker 0xe64b2d0 is ready after 0.212154 second(s)
[1744:1744:0118/204330.581250:VERBOSE1:screen_locker.cc(615)] Emitting SCREEN_LOCK_STATE_CHANGED with state=1
[1744:1744:0118/204330.581540:VERBOSE1:screen_locker.cc(619)] Calling session manager's HandleLockScreenShown D-Bus method
[1744:1744:0118/204330.626154:VERBOSE1:lock_state_controller.cc(241)] OnLockStateChanged called with locked: 1, shutting_down_: 0, system_is_locked_: 0, lock_fail_timer_.IsRunning(): 0
[1744:1744:0118/204330.626220:VERBOSE1:lock_state_controller.cc(421)] StartPostLockAnimation
[1744:1744:0118/204330.626339:VERBOSE1:lock_state_controller.cc(523)] PostLockAnimationFinished
[1744:1744:0118/204330.632480:ERROR:views_screen_locker.cc(142)] Not implemented reached in virtual void chromeos<IPv6: 4>ViewsScreenLocker<IPv6: 4>OnAshLockAnimationFinished()
[1744:1744:0118/204330.934321:VERBOSE1:display_configurator.cc(1054)] OnConfigured: success=1 new_display_state=SINGLE new_power_state=ALL_OFF
[1744:1744:0118/204357.053933:ERROR:device_event_log_impl.cc(156)] [20:43:57.053] Network: network_state_handler.cc:1667 DefaultNetworkPropertyUpdated: Candynet-N.Error = "out-of-range"

----

The NOTIMPLEMENTED() in views_screen_locker.cc looks suspicious. Is there any chance that the (new, I think) Views-based code isn't running the callback that's fetched from chromeos::PowerManagerClient::GetSuspendReadinessCallback() in some/all cases?

Regardless of the cause of this, I'm going to add some logging within Chrome to narrow down the cause(s) of delayed suspend readiness acknowledgements, since we've had similar problems in the past.

Not sure if the NOTIMPLEMENTED() is the cause. Jacob is more familiar with the views-based lock. 

I was able to repro this on a ToT kevin build, and yeah, it's screen lock:

[4761:4761:0119/153753.737269:VERBOSE1:screen_locker.cc(493)] Received LockScreen request from session manager
[4761:4761:0119/153753.738321:VERBOSE1:update_display_configuration_task.cc(69)] OnDisplaysUpdated: new_display_state=SINGLE new_power_state=ALL_OFF flags=0 force_configure=0 display_count=1
[4761:4761:0119/153753.738412:VERBOSE1:display_configurator.cc(212)] EnterState: display=SINGLE power=ALL_OFF
[4761:4761:0119/153753.744905:VERBOSE1:screen_locker.cc(533)] Created ScreenLocker 0x1451bd80
[4761:4761:0119/153753.808454:VERBOSE1:screen_locker.cc(626)] ScreenLocker 0x1451bd80 is ready after 0.063823 second(s)
[4761:4761:0119/153753.808666:VERBOSE1:screen_locker.cc(631)] Emitting SCREEN_LOCK_STATE_CHANGED with state=1
[4761:4761:0119/153753.809243:VERBOSE1:screen_locker.cc(635)] Calling session manager's HandleLockScreenShown D-Bus method
[4761:4761:0119/153753.814089:VERBOSE1:connection_holder.h(384)] Instance arc::mojom::LockScreenInstance not available.
[4761:4761:0119/153753.825100:VERBOSE1:lock_state_controller.cc(241)] OnLockStateChanged called with locked: 1, shutting_down_: 0, system_is_locked_: 0, lock_fail_timer_.IsRunning(): 0
[4761:4761:0119/153753.825150:VERBOSE1:lock_state_controller.cc(425)] StartPostLockAnimation
[4761:4761:0119/153753.825213:VERBOSE1:lock_state_controller.cc(527)] PostLockAnimationFinished
[4761:4761:0119/153753.830138:ERROR:views_screen_locker.cc(143)] Not implemented reached in virtual void chromeos::ViewsScreenLocker::OnAshLockAnimationFinished()
[4761:4761:0119/153754.327151:VERBOSE1:display_configurator.cc(1062)] OnConfigured: success=1 new_display_state=SINGLE new_power_state=ALL_OFF
[4761:4761:0119/153844.045692:ERROR:device_event_log_impl.cc(156)] [15:38:44.045] Network: network_state_handler.cc:1604 Default network in unexpected state: Ethernet (/service/29)State: idle
[4761:4761:0119/153844.068887:VERBOSE1:connection_holder.h(384)] Instance arc::mojom::UsbHostInstance not available.
[4761:4761:0119/153844.101996:WARNING:power_manager_client.cc(830)] Didn't report suspend readiness due to SuspendImminent@../../ash/system/power/power_event_observer.cc:93

That last line is the new logging I added. Here's the relevant code:

 72 void PowerEventObserver::SuspendImminent(
 73     power_manager::SuspendImminent::Reason reason) {
 74   SessionController* controller = Shell::Get()->session_controller();
 75 
 76   // This class is responsible for disabling all rendering requests at suspend
 77   // time and then enabling them at resume time.  When the
 78   // auto-screen-lock pref is not set this is easy to do since
 79   // StopRenderingRequests() is just called directly from this function.  If the
 80   // auto-screen-lock pref _is_ set, then the suspend needs to be delayed
 81   // until the lock screen is fully visible.  While it is sufficient from a
 82   // security perspective to block only until the lock screen is ready, which
 83   // guarantees that the contents of the user's screen are no longer visible,
 84   // this leads to poor UX on the first resume since neither the user pod nor
 85   // the header bar will be visible for a few hundred milliseconds until the GPU
 86   // process starts rendering again.  To deal with this, the suspend is delayed
 87   // until all the lock screen animations have completed and the suspend request
 88   // is unblocked from OnLockAnimationsComplete().
 89   if (!screen_locked_ && controller->ShouldLockScreenAutomatically() &&
 90       controller->CanLockScreen()) {
 91     screen_lock_callback_ = chromeos::DBusThreadManager::Get()
 92                                 ->GetPowerManagerClient()
 93                                 ->GetSuspendReadinessCallback(FROM_HERE);
 94     VLOG(1) << "Requesting screen lock from PowerEventObserver";
 95     // TODO(warx): once  crbug.com/748732  is fixed, we probably can treat
 96     // auto-screen-lock pref set and not set cases as the same. Also remove
 97     // |waiting_for_lock_screen_animations_|.
 98     Shell::Get()->lock_state_controller()->LockWithoutAnimation();

The callback is supposed to be called from here:

 60 void PowerEventObserver::OnLockAnimationsComplete() {
 61   VLOG(1) << "Screen locker animations have completed.";
 62   waiting_for_lock_screen_animations_ = false;
 63 
 64   if (!screen_lock_callback_.is_null()) {
 65     StopRenderingRequests();
 66 
 67     screen_lock_callback_.Run();
 68     screen_lock_callback_.Reset();
 69   }
 70 }

OnLockAnimationsComplete looks like it's supposed to be called from SessionController::NotifyChromeLockAnimationsComplete, which is called from WebUIScreenLocker::OnHeaderBarVisible... but not from anywhere ViewsScreenLocker, as far as I can tell:

130 void ViewsScreenLocker::OnLockWebUIReady() {
131   NOTIMPLEMENTED();
132 }
133      
134 void ViewsScreenLocker::OnLockBackgroundDisplayed() {
135   NOTIMPLEMENTED();
136 }
137 
138 void ViewsScreenLocker::OnHeaderBarVisible() {
139   NOTIMPLEMENTED();    
140 }
141 
142 void ViewsScreenLocker::OnAshLockAnimationFinished() {
143   NOTIMPLEMENTED();
144 }

If this affects all M64 boards, which seems likely, I'm pretty bummed that it was seemingly only caught because a team member noticed that the LED on their device is the wrong color. When did the Views-based lock screen get turned on?

yep, it sounds like views-based lock screen should report readiness

Thanks for the debugging, I can upload a CL shortly to fix.

> If this affects all M64 boards, which seems likely, I'm pretty bummed that it was seemingly only caught because a team member noticed that the LED on their device is the wrong color. When did the Views-based lock screen get turned on?

Views-based lock is launching in 64.

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/19235fd364e16e4eeae0459f962460e4c851920d

commit 19235fd364e16e4eeae0459f962460e4c851920d
Author: Daniel Erat <derat@chromium.org>
Date: Mon Jan 22 20:14:47 2018

chromeos: Make GetSuspendReadinessCallback take location.

Make PowerManagerClient::GetSuspendReadinessCallback take a
base::Location argument, and log callers' locations when
powerd gives up on waiting for Chrome to report suspend
readiness.

Bug:  803727 
Change-Id: Ie07bf8b6e691ce114486d44da9fe1157b0067d88
Reviewed-on: https://chromium-review.googlesource.com/877321
Reviewed-by: Wu-Cheng Li <wuchengli@chromium.org>
Reviewed-by: Luis Hector Chavez <lhchavez@chromium.org>
Commit-Queue: Dan Erat <derat@chromium.org>
Cr-Commit-Position: refs/heads/master@{#530968}
[modify] https://crrev.com/19235fd364e16e4eeae0459f962460e4c851920d/ash/system/power/power_event_observer.cc
[modify] https://crrev.com/19235fd364e16e4eeae0459f962460e4c851920d/chrome/browser/chromeos/power/extension_event_observer.cc
[modify] https://crrev.com/19235fd364e16e4eeae0459f962460e4c851920d/chromeos/dbus/fake_power_manager_client.cc
[modify] https://crrev.com/19235fd364e16e4eeae0459f962460e4c851920d/chromeos/dbus/fake_power_manager_client.h
[modify] https://crrev.com/19235fd364e16e4eeae0459f962460e4c851920d/chromeos/dbus/power_manager_client.cc
[modify] https://crrev.com/19235fd364e16e4eeae0459f962460e4c851920d/chromeos/dbus/power_manager_client.h
[modify] https://crrev.com/19235fd364e16e4eeae0459f962460e4c851920d/chromeos/dbus/power_manager_client_unittest.cc
[modify] https://crrev.com/19235fd364e16e4eeae0459f962460e4c851920d/chromeos/disks/suspend_unmount_manager.cc
[modify] https://crrev.com/19235fd364e16e4eeae0459f962460e4c851920d/components/arc/power/arc_power_bridge.cc
[modify] https://crrev.com/19235fd364e16e4eeae0459f962460e4c851920d/media/capture/video/chromeos/video_capture_device_arc_chromeos.cc

I filed issue 804495 to think about writing integration tests for this.

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/8aa06a97852df56583204001684a1218ea97372d

commit 8aa06a97852df56583204001684a1218ea97372d
Author: Jacob Dufault <jdufault@google.com>
Date: Mon Jan 22 22:49:24 2018

cros: Notify powerd that views-based lock is finished.

Bug:  803727 
Change-Id: I2fc28069cd33106b3c9019b402e9f549d956e54c
Reviewed-on: https://chromium-review.googlesource.com/879466
Reviewed-by: Dan Erat <derat@chromium.org>
Commit-Queue: Jacob Dufault <jdufault@chromium.org>
Cr-Commit-Position: refs/heads/master@{#531031}
[modify] https://crrev.com/8aa06a97852df56583204001684a1218ea97372d/chrome/browser/chromeos/login/lock/views_screen_locker.cc

This bug requires manual review: We are only 0 days from stable.
Please contact the milestone owner if you have questions.
Owners: cmasso@(Android), cmasso@(iOS), kbleicher@(ChromeOS), abdulsyed@(Desktop)

For more details visit https://www.chromium.org/issue-tracking/autotriage - Your friendly Sheriffbot

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/bcb0a479715aa1c704ee71b93ead6ace9bafeae8

commit bcb0a479715aa1c704ee71b93ead6ace9bafeae8
Author: Jacob Dufault <jdufault@google.com>
Date: Wed Jan 24 00:26:07 2018

cros: Notify powerd that views-based lock is finished.

TBR=jdufault@google.com

(cherry picked from commit 8aa06a97852df56583204001684a1218ea97372d)

Bug:  803727 
Change-Id: I2fc28069cd33106b3c9019b402e9f549d956e54c
Reviewed-on: https://chromium-review.googlesource.com/879466
Reviewed-by: Dan Erat <derat@chromium.org>
Commit-Queue: Jacob Dufault <jdufault@chromium.org>
Cr-Original-Commit-Position: refs/heads/master@{#531031}
Reviewed-on: https://chromium-review.googlesource.com/882448
Reviewed-by: Jacob Dufault <jdufault@chromium.org>
Cr-Commit-Position: refs/branch-heads/3325@{#49}
Cr-Branched-From: bc084a8b5afa3744a74927344e304c02ae54189f-refs/heads/master@{#530369}
[modify] https://crrev.com/bcb0a479715aa1c704ee71b93ead6ace9bafeae8/chrome/browser/chromeos/login/lock/views_screen_locker.cc

This CL is larger to what we would like to merge this late in M64 

IS this a regression in M64?
Is this something that we can comprehensively validate with a set of test cases when(if) merged? Can we add use case validation needed? 

#24: Sorry for the lack of clarity on this, but the merge request is just for the one-line change at https://crrev.com/c/879466.

My https://crrev.com/c/877321 added some logging to help make bugs like this easier to track down next time. It doesn't need to be merged anywhere.

Per #24, confirmed M64 regression?  Do we know where this started to occur, along with impact if we wait for M65?

Yes, it regressed in M64 due to an intentional switch to the Views-based lock screen. This call was accidentally left out of the Views-based implementation. The bug makes devices stay awake for 20 seconds when the lid is closed. There will probably be weird side effects as a result (video and audio continues to play instead of stopping, open pages stay active, etc.).

Thanks for the background, Dan.

Let's get this merged since it's a minor change and reviewed.  From there we can remove the stable blocker asap.

Reminder to merge today so we can capture in the next RC for testing.  Thx

Thanks, I've merged it at https://crrev.com/c/893698.

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/7a2412243bb2c534de0f17cd83e2d242901142ca

commit 7a2412243bb2c534de0f17cd83e2d242901142ca
Author: Jacob Dufault <jdufault@google.com>
Date: Tue Jan 30 17:26:39 2018

cros: Notify powerd that views-based lock is finished.

Bug:  803727 
Change-Id: I2fc28069cd33106b3c9019b402e9f549d956e54c
Reviewed-on: https://chromium-review.googlesource.com/879466
Reviewed-by: Dan Erat <derat@chromium.org>
Commit-Queue: Jacob Dufault <jdufault@chromium.org>
Cr-Original-Commit-Position: refs/heads/master@{#531031}(cherry picked from commit 8aa06a97852df56583204001684a1218ea97372d)
Reviewed-on: https://chromium-review.googlesource.com/893698
Cr-Commit-Position: refs/branch-heads/3282@{#617}
Cr-Branched-From: 5fdc0fab22ce7efd32532ee989b223fa12f8171e-refs/heads/master@{#520840}
[modify] https://crrev.com/7a2412243bb2c534de0f17cd83e2d242901142ca/chrome/browser/chromeos/login/lock/views_screen_locker.cc