arc: Add loging to arc provisioning events

In order to better understand the feedback reports, adding logging in key events of arc provisioning process.

BUG=b:162221783
TEST=deploy to dut, disable playstore, re-enable playstore, successfully
finish the authorization flow

Change-Id: Ie6cd8a4dd9b89353a0a3fa1dcc656496f62bfb07
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2365997Reviewed-by: Yusuke Sato <yusukes@chromium.org>
Commit-Queue: Muhammad Hasan Khan <mhasank@chromium.org>
Cr-Commit-Position: refs/heads/master@{#800319}

chrome/browser/chromeos/arc/session/arc_session_manager.cc

@@ -712,6 +712,7 @@ void ArcSessionManager::OnProvisioningFinished(
       result == ProvisioningResult::CHROME_SERVER_COMMUNICATION_ERROR) {
     if (profile_->GetPrefs()->HasPrefPath(prefs::kArcSignedIn))
       profile_->GetPrefs()->SetBoolean(prefs::kArcSignedIn, false);
+    VLOG(1) << "Stopping ARC due to provisioning failure";
     ShutdownSession();
     ShowArcSupportHostError(error, 0 /* error_code */, true);
     return;
@@ -824,6 +825,7 @@ void ArcSessionManager::Initialize() {
 }
 
 void ArcSessionManager::Shutdown() {
+  VLOG(1) << "Shutting down session manager";
   enable_requested_ = false;
   ResetArcState();
   arc_session_runner_->OnShutdown();
@@ -851,9 +853,14 @@ void ArcSessionManager::ShutdownSession() {
       // Ignore in NOT_INITIALIZED case. This is called in initial SetProfile
       // invocation.
       // TODO(hidehiko): Remove this along with the clean up.
-      break;
     case State::STOPPED:
       // Currently, ARC is stopped. Do nothing.
+    case State::REMOVING_DATA_DIR:
+      // When data removing is done, |state_| will be set to STOPPED.
+      // Do nothing here.
+    case State::STOPPING:
+      // Now ARC is stopping. Do nothing here.
+      VLOG(1) << "Skipping session shutdown because state is: " << state_;
       break;
     case State::NEGOTIATING_TERMS_OF_SERVICE:
     case State::CHECKING_ANDROID_MANAGEMENT:
@@ -864,9 +871,7 @@ void ArcSessionManager::ShutdownSession() {
       // immediately.
       state_ = State::STOPPED;
       break;
-    case State::REMOVING_DATA_DIR:
-      // When data removing is done, |state_| will be set to STOPPED.
-      // Do nothing here.
+
       break;
     case State::ACTIVE:
       // Request to stop the ARC. |state_| will be set to STOPPED eventually.
@@ -876,9 +881,6 @@ void ArcSessionManager::ShutdownSession() {
       state_ = State::STOPPING;
       arc_session_runner_->RequestStop();
       break;
-    case State::STOPPING:
-      // Now ARC is stopping. Do nothing here.
-      break;
   }
 }
 
@@ -942,6 +944,7 @@ void ArcSessionManager::CancelAuthCode() {
   }
 
   MaybeUpdateOptInCancelUMA(support_host_.get());
+  VLOG(1) << "Auth cancelled. Stopping ARC. state: " << state_;
   StopArc();
   SetArcPlayStoreEnabledForProfile(profile_, false);
 }
@@ -1509,6 +1512,8 @@ void ArcSessionManager::OnRetryClicked() {
 
   UpdateOptInActionUMA(OptInActionType::RETRY);
 
+  VLOG(1) << "Retry button clicked";
+
   if (state_ == State::ACTIVE) {
     // ERROR_WITH_FEEDBACK is set in OnSignInFailed(). In the case, stopping
     // ARC was postponed to contain its internal state into the report.

components/arc/session/arc_session_impl.cc

@@ -614,6 +614,7 @@ void ArcSessionImpl::Stop() {
     case State::WAITING_FOR_LCD_DENSITY:
       // If |Stop()| is called while waiting for LCD density or CPU cores
       // information, it can directly move to stopped state.
+      VLOG(1) << "ARC session is not started. state: " << state_;
       OnStopped(ArcStopReason::SHUTDOWN);
       return;
     case State::STARTING_MINI_INSTANCE:
@@ -642,6 +643,7 @@ void ArcSessionImpl::Stop() {
       return;
 
     case State::STOPPED:
+      VLOG(1) << "ARC session is already stopped.";
       // The instance is already stopped. Do nothing.
       return;
   }
@@ -657,7 +659,9 @@ void ArcSessionImpl::StopArcInstance(bool on_shutdown, bool should_backup_log) {
          state_ == State::CONNECTING_MOJO ||
          state_ == State::RUNNING_FULL_INSTANCE);
 
-  VLOG(2) << "Requesting session_manager to stop ARC instance";
+  VLOG(1) << "Requesting session_manager to stop ARC instance"
+          << " on_shutdown: " << on_shutdown
+          << " should_backup_log: " << should_backup_log;
 
   // When the instance is full instance, change the |state_| in
   // ArcInstanceStopped().
@@ -702,7 +706,9 @@ void ArcSessionImpl::OnStopped(ArcStopReason reason) {
   DCHECK_CALLED_ON_VALID_THREAD(thread_checker_);
   // OnStopped() should be called once per instance.
   DCHECK_NE(state_, State::STOPPED);
-  VLOG(2) << "ARC session is stopped.";
+  VLOG(1) << "ARC session is stopped."
+          << " reason: " << reason << " state: " << state_;
+
   const bool was_running = (state_ == State::RUNNING_FULL_INSTANCE);
   arc_bridge_host_.reset();
   state_ = State::STOPPED;