Add additional logging when the screen is locked.

BUG=452599

Review URL: https://codereview.chromium.org/1745653002

Cr-Commit-Position: refs/heads/master@{#378475}

ash/wm/lock_state_controller.cc

@@ -89,11 +89,16 @@ LockStateController::LockStateController()
       shutdown_after_lock_(false),
       animating_lock_(false),
       can_cancel_lock_animation_(false),
+      lock_fail_timer_is_stopped_(true),
       weak_ptr_factory_(this) {
+  // TODO(jdufault): Remove after resolving crbug.com/452599.
+  VLOG(0) << "Constructing LockStateController instance " << this;
   Shell::GetPrimaryRootWindow()->GetHost()->AddObserver(this);
 }
 
 LockStateController::~LockStateController() {
+  // TODO(jdufault): Remove after resolving crbug.com/452599.
+  VLOG(0) << "Destroying LockStateController instance " << this;
   Shell::GetPrimaryRootWindow()->GetHost()->RemoveObserver(this);
 }
 
@@ -137,6 +142,9 @@ void LockStateController::StartLockAnimationAndLockImmediately(
 }
 
 bool LockStateController::LockRequested() {
+  // TODO(jdufault): Remove DCHECK after resolving crbug.com/452599; this is not
+  // expected to trigger. The DCHECK is only present to assert all assumptions.
+  DCHECK(lock_fail_timer_is_stopped_ != lock_fail_timer_.IsRunning());
   return lock_fail_timer_.IsRunning();
 }
 
@@ -223,6 +231,9 @@ void LockStateController::OnHostCloseRequested(
 
 void LockStateController::OnLoginStateChanged(
     user::LoginStatus status) {
+  // TODO(jdufault): Remove after resolving crbug.com/452599.
+  VLOG(0) << "LockStateController::OnLoginStateChanged login_status_: "
+          << login_status_ << ", status: " << status;
   if (status != user::LOGGED_IN_LOCKED)
     login_status_ = status;
   system_is_locked_ = (status == user::LOGGED_IN_LOCKED);
@@ -246,15 +257,25 @@ void LockStateController::OnAppTerminating() {
 void LockStateController::OnLockStateChanged(bool locked) {
   DCHECK((lock_fail_timer_.IsRunning() && lock_duration_timer_ != nullptr) ||
          (!lock_fail_timer_.IsRunning() && lock_duration_timer_ == nullptr));
-  VLOG(1) << "OnLockStateChanged " << locked;
+  VLOG(1) << "OnLockStateChanged called with locked: " << locked
+          << ", shutting_down_: " << shutting_down_
+          << ", system_is_locked_: " << system_is_locked_
+          << ", lock_fail_timer_.IsRunning(): " << lock_fail_timer_.IsRunning()
+          << ", lock_fail_timer_is_stopped_: " << lock_fail_timer_is_stopped_;
+
   if (shutting_down_ || (system_is_locked_ == locked))
     return;
 
   system_is_locked_ = locked;
 
   if (locked) {
     StartPostLockAnimation();
+
+    // TODO(jdufault): Remove after resolving crbug.com/452599.
+    VLOG(0) << "Stopping lock_fail_timer_";
     lock_fail_timer_.Stop();
+    lock_fail_timer_is_stopped_ = true;
+
     if (lock_duration_timer_) {
       UMA_HISTOGRAM_LOCK_TIMES("Ash.WindowManager.Lock.Success",
                                lock_duration_timer_->Elapsed());
@@ -276,7 +297,10 @@ void LockStateController::OnLockFailTimeout() {
     loading_webpage = delegate_->IsLoading() ? "true" : "false";
 
   LOG(FATAL) << "Screen lock took too long; crashing intentionally "
-             << "(loading webpage? " << loading_webpage << ")";
+             << "(loading webpage: " << loading_webpage
+             << ", lock_fail_timer.IsRunning: " << lock_fail_timer_.IsRunning()
+             << ", lock_fail_timer_is_stopped_: " << lock_fail_timer_is_stopped_
+             << ")";
 }
 
 void LockStateController::StartLockToShutdownTimer() {
@@ -537,8 +561,12 @@ void LockStateController::PreLockAnimationFinished(bool request_lock) {
     timeout *= 2;
   }
 #endif
+  // TODO(jdufault): Remove after resolving crbug.com/452599.
+  VLOG(0) << "Starting LockFailTimer with a timeout of " << timeout << "s";
   lock_fail_timer_.Start(
       FROM_HERE, timeout, this, &LockStateController::OnLockFailTimeout);
+  lock_fail_timer_is_stopped_ = false;
+
   lock_duration_timer_.reset(new base::ElapsedTimer());
 }
 

ash/wm/lock_state_controller.h

@@ -319,6 +319,8 @@ class ASH_EXPORT LockStateController : public aura::WindowTreeHostObserver,
   // Started when we request that the screen be locked.  When it fires, we
   // assume that our request got dropped.
   base::OneShotTimer lock_fail_timer_;
+  // TODO(jdufault): Remove after resolving crbug.com/452599.
+  bool lock_fail_timer_is_stopped_;
 
   // Started when the screen is locked while the power button is held.  Adds a
   // delay between the appearance of the lock screen and the beginning of the

chrome/browser/chromeos/login/ui/webui_login_view.cc

@@ -459,31 +459,31 @@ bool WebUILoginView::PreHandleGestureEvent(
 void WebUILoginView::LoadProgressChanged(content::WebContents* source,
                                          double progress) {
   // TODO(jdufault): Remove once crbug.com/452599 is resolved.
-  LOG(ERROR) << "WebUILoginView loading progress updated to " << progress;
+  VLOG(1) << "WebUILoginView loading progress updated to " << progress;
 }
 
 void WebUILoginView::SwappedOut(content::WebContents* source) {
-  LOG(ERROR) << "WebUILoginView got swapped out";
+  VLOG(1) << "WebUILoginView got swapped out";
 }
 
 void WebUILoginView::BeforeUnloadFired(content::WebContents* tab,
                                        bool proceed,
                                        bool* proceed_to_fire_unload) {
-  LOG(ERROR) << "WebUILoginView is unloading";
+  VLOG(1) << "WebUILoginView is unloading";
   *proceed_to_fire_unload = true;
 }
 
 void WebUILoginView::RendererUnresponsive(content::WebContents* source) {
-  LOG(ERROR) << "WebUILoginView renderer became unresponsive";
+  VLOG(1) << "WebUILoginView renderer became unresponsive";
 }
 
 void WebUILoginView::RendererResponsive(content::WebContents* source) {
-  LOG(ERROR) << "WebUILoginView renderer became responsive";
+  VLOG(1) << "WebUILoginView renderer became responsive";
 }
 
 void WebUILoginView::DidNavigateMainFramePostCommit(
     content::WebContents* source) {
-  LOG(ERROR) << "WebUILoginView navigated";
+  VLOG(1) << "WebUILoginView navigated";
 }
 
 void WebUILoginView::OnLoginPromptVisible() {

chrome/browser/chromeos/power/power_button_observer.cc

@@ -33,6 +33,9 @@ ash::user::LoginStatus GetCurrentLoginStatus() {
 }  // namespace
 
 PowerButtonObserver::PowerButtonObserver() {
+  // TODO: Remove after resolving crbug.com/452599.
+  VLOG(0) << "Creating PowerButtonObserver " << this;
+
   ash::Shell::GetInstance()->lock_state_controller()->
       SetDelegate(scoped_ptr<ash::LockStateControllerDelegate>(
           new SessionStateControllerDelegateChromeos));
@@ -62,6 +65,9 @@ PowerButtonObserver::PowerButtonObserver() {
 }
 
 PowerButtonObserver::~PowerButtonObserver() {
+  // TODO: Remove after resolving crbug.com/452599.
+  VLOG(0) << "Destroying PowerButtonObserver " << this;
+
   DBusThreadManager::Get()->GetSessionManagerClient()->RemoveObserver(this);
   DBusThreadManager::Get()->GetPowerManagerClient()->RemoveObserver(this);
 }
@@ -78,6 +84,9 @@ void PowerButtonObserver::Observe(int type,
       ash::Shell::GetInstance()->OnAppTerminating();
       break;
     case chrome::NOTIFICATION_SCREEN_LOCK_STATE_CHANGED: {
+      // TODO(jdufault): Remove after resolving crbug.com/452599.
+      VLOG(0) << "PowerButtonObserver " << this
+              << "calling ash::Shell OnLockStateChanged";
       bool locked = *content::Details<bool>(details).ptr();
       ash::Shell::GetInstance()->OnLockStateChanged(locked);
       break;