Adding debugging info for sync integration tests.

chrome/test/live_sync/profile_sync_service_test_harness.cc

 // Copyright (c) 2010 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "base/message_loop.h"
 #include "chrome/browser/browser.h"
 #include "chrome/browser/defaults.h"
 #include "chrome/browser/pref_service.h"
 #include "chrome/browser/profile.h"
 #include "chrome/browser/sync/glue/sync_backend_host.h"
@@ skipping 64 matching lines @@
     }
   }
 }
 
 bool StateChangeTimeoutEvent::Abort() {
   aborted_ = true;
   caller_ = NULL;
   return !did_timeout_;
 }
 
-ProfileSyncServiceTestHarness::ProfileSyncServiceTestHarness(
-    Profile* p, const std::string& username, const std::string& password)
+ProfileSyncServiceTestHarness::ProfileSyncServiceTestHarness(Profile* p,
+    const std::string& username, const std::string& password, int id)
     : wait_state_(WAITING_FOR_ON_AUTH_ERROR), profile_(p), service_(NULL),
       last_status_(kInvalidStatus),
       last_timestamp_(0),
       min_timestamp_needed_(kMinTimestampNeededNone),
-      username_(username), password_(password) {
+      username_(username), password_(password), id_(id) {
   // Ensure the profile has enough prefs registered for use by sync.
   if (!p->GetPrefs()->FindPreference(prefs::kAcceptLanguages))
     TabContents::RegisterUserPrefs(p->GetPrefs());
 }
 
 bool ProfileSyncServiceTestHarness::SetupSync() {
   service_ = profile_->GetProfileSyncService();
   service_->StartUp();
   service_->AddObserver(this);
   return WaitForServiceInit(false);
@@ skipping 13 matching lines @@
 
 void ProfileSyncServiceTestHarness::SignalStateComplete() {
   MessageLoopForUI::current()->Quit();
 }
 
 bool ProfileSyncServiceTestHarness::RunStateChangeMachine() {
   WaitState state = wait_state_;
   ProfileSyncService::Status status(service_->QueryDetailedSyncStatus());
   switch (wait_state_) {
     case WAITING_FOR_ON_AUTH_ERROR: {
+      LogClientInfo("WAITING_FOR_ON_AUTH_ERROR");
       SignalStateCompleteWithNextState(WAITING_FOR_ON_BACKEND_INITIALIZED);
       break;
     }
     case WAITING_FOR_ON_BACKEND_INITIALIZED: {
+      LogClientInfo("WAITING_FOR_ON_BACKEND_INITIALIZED");
       if (service_->GetAuthError().state() != GoogleServiceAuthError::NONE) {
         SignalStateCompleteWithNextState(AUTH_ERROR);
       }
       if (service_->sync_initialized()) {
         SignalStateCompleteWithNextState(WAITING_FOR_NOTIFICATIONS_ENABLED);
       }
       break;
     }
     case WAITING_FOR_NOTIFICATIONS_ENABLED: {
+      LogClientInfo("WAITING_FOR_NOTIFICATIONS_ENABLED");
       if (status.notifications_enabled) {
         SignalStateCompleteWithNextState(FULLY_SYNCED);
       }
       break;
     }
     case WAITING_FOR_SYNC_TO_FINISH: {
+      LogClientInfo("WAITING_FOR_SYNC_TO_FINISH");
       const SyncSessionSnapshot* snap = GetLastSessionSnapshot();
       DCHECK(snap) << "Should have been at least one sync session by now";
       // TODO(rsimha): In an ideal world, snap->has_more_to_sync == false should
       // be a sufficient condition for sync to have completed. However, the
       // additional check of snap->unsynced_count is required due to
       // http://crbug.com/48989.
       if (snap->has_more_to_sync || snap->unsynced_count != 0) {
         break;
       }
       EXPECT_LE(last_timestamp_, snap->max_local_timestamp);
       last_timestamp_ = snap->max_local_timestamp;
       SignalStateCompleteWithNextState(FULLY_SYNCED);
       break;
     }
     case WAITING_FOR_UPDATES: {
+      LogClientInfo("WAITING_FOR_UPDATES");
       const SyncSessionSnapshot* snap = GetLastSessionSnapshot();
       DCHECK(snap) << "Should have been at least one sync session by now";
       if (snap->max_local_timestamp < min_timestamp_needed_) {
         break;
       }
       EXPECT_LE(last_timestamp_, snap->max_local_timestamp);
       last_timestamp_ = snap->max_local_timestamp;
       SignalStateCompleteWithNextState(FULLY_SYNCED);
       break;
     }
-    case FULLY_SYNCED:
+    case FULLY_SYNCED: {
+      LogClientInfo("FULLY_SYNCED");
+      break;
+    }
+    case AUTH_ERROR: {
+      LogClientInfo("AUTH_ERROR");
+      break;
+    }
     default:
       // Invalid state during observer callback which may be triggered by other
       // classes using the the UI message loop.  Defer to their handling.
       break;
   }
   last_status_ = status;
   return state != wait_state_;
 }
 
 void ProfileSyncServiceTestHarness::OnStateChanged() {
   RunStateChangeMachine();
 }
 
 bool ProfileSyncServiceTestHarness::AwaitSyncCycleCompletion(
     const std::string& reason) {
+  LogClientInfo("AwaitSyncCycleCompletion");
   const SyncSessionSnapshot* snap = GetLastSessionSnapshot();
   DCHECK(snap) << "Should have been at least one sync session by now";
   // TODO(rsimha): Remove additional checks of snap->has_more_to_sync and
   // snap->unsynced_count once http://crbug.com/48989 is fixed.
   if (service()->backend()->HasUnsyncedItems() ||
       snap->has_more_to_sync ||
       snap->unsynced_count != 0) {
     wait_state_ = WAITING_FOR_SYNC_TO_FINISH;
     return AwaitStatusChangeWithTimeout(60, reason);
   } else {
     EXPECT_LE(last_timestamp_, snap->max_local_timestamp);
     last_timestamp_ = snap->max_local_timestamp;
     return true;
   }
 }
 
 bool ProfileSyncServiceTestHarness::AwaitMutualSyncCycleCompletion(
     ProfileSyncServiceTestHarness* partner) {
+  LogClientInfo("AwaitMutualSyncCycleCompletion");
   bool success = AwaitSyncCycleCompletion(
       "Sync cycle completion on active client.");
   if (!success)
     return false;
   return partner->WaitUntilTimestampIsAtLeast(last_timestamp_,
       "Sync cycle completion on passive client.");
 }
 
 bool ProfileSyncServiceTestHarness::AwaitGroupSyncCycleCompletion(
     std::vector<ProfileSyncServiceTestHarness*>& partners) {
+  LogClientInfo("AwaitGroupSyncCycleCompletion");
   bool success = AwaitSyncCycleCompletion(
       "Sync cycle completion on active client.");
   if (!success)
     return false;
   bool return_value = true;
   for (std::vector<ProfileSyncServiceTestHarness*>::iterator it =
       partners.begin(); it != partners.end(); ++it) {
     if (this != *it) {
       return_value = return_value &&
           (*it)->WaitUntilTimestampIsAtLeast(last_timestamp_,
           "Sync cycle completion on partner client.");
     }
   }
   return return_value;
 }
 
 // static
 bool ProfileSyncServiceTestHarness::AwaitQuiescence(
     std::vector<ProfileSyncServiceTestHarness*>& clients) {
+  LOG(INFO) << "AwaitQuiescence.";
   bool return_value = true;
   for (std::vector<ProfileSyncServiceTestHarness*>::iterator it =
       clients.begin(); it != clients.end(); ++it) {
     return_value = return_value &&
         (*it)->AwaitGroupSyncCycleCompletion(clients);
   }
   return return_value;
 }
 
 bool ProfileSyncServiceTestHarness::WaitUntilTimestampIsAtLeast(
     int64 timestamp, const std::string& reason) {
+  LogClientInfo("WaitUntilTimestampIsAtLeast");
   min_timestamp_needed_ = timestamp;
   const SyncSessionSnapshot* snap = GetLastSessionSnapshot();
   DCHECK(snap) << "Should have been at least one sync session by now";
   if (snap->max_local_timestamp < min_timestamp_needed_) {
     wait_state_ = WAITING_FOR_UPDATES;
     return AwaitStatusChangeWithTimeout(60, reason);
   } else {
     return true;
   }
 }
 
 bool ProfileSyncServiceTestHarness::AwaitStatusChangeWithTimeout(
     int timeout_seconds,
     const std::string& reason) {
+  LogClientInfo("AwaitStatusChangeWithTimeout");
   scoped_refptr<StateChangeTimeoutEvent> timeout_signal(
       new StateChangeTimeoutEvent(this, reason));
   MessageLoopForUI* loop = MessageLoopForUI::current();
   loop->PostDelayedTask(
       FROM_HERE,
       NewRunnableMethod(timeout_signal.get(),
                         &StateChangeTimeoutEvent::Callback),
       1000 * timeout_seconds);
+  LogClientInfo("Before RunMessageLoop");
   ui_test_utils::RunMessageLoop();
+  LogClientInfo("After RunMessageLoop");
   return timeout_signal->Abort();
 }
 
 bool ProfileSyncServiceTestHarness::WaitForServiceInit(bool is_auth_retry) {
+  LogClientInfo("WaitForServiceInit");
   if (!is_auth_retry) {
     // Wait for the OnAuthError() callback.
     EXPECT_EQ(wait_state_, WAITING_FOR_ON_AUTH_ERROR);
     EXPECT_TRUE(AwaitStatusChangeWithTimeout(30,
         "Waiting for the OnAuthError() callback.")) <<
         "OnAuthError() not seen after 30 seconds.";
   }
 
   // Enter GAIA credentials and wait for the OnBackendInitialized() callback.
   service_->backend()->Authenticate(username_, password_, std::string());
@@ skipping 23 matching lines @@
       "notifications_enabled not set to true after 30 seconds.";
 
   return true;
 }
 
 const SyncSessionSnapshot*
     ProfileSyncServiceTestHarness::GetLastSessionSnapshot() const {
   EXPECT_FALSE(service_ == NULL) << "Sync service has not yet been set up.";
   return service_->backend()->GetLastSessionSnapshot();
 }
+
+void ProfileSyncServiceTestHarness::LogClientInfo(std::string message) {
+  const SyncSessionSnapshot* snap = GetLastSessionSnapshot();
+  if (snap) {
+    LOG(INFO) << "Client " << id_ << ": " << message << ": "
+        << "has_more_to_sync: " << snap->has_more_to_sync
+        << ", max_local_timestamp: " << snap->max_local_timestamp
+        << ", unsynced_count: " << snap->unsynced_count
+        << ", has_unsynced_items: " << service()->backend()->HasUnsyncedItems()
+        << ".";
+  } else {
+    LOG(INFO) << "Client " << id_ << ": " << message << ": "
+        << "Snap not available.";
+  }
+}