[sync] Eliminate Await*SyncCompletion methods in integration tests

chrome/browser/sync/test/integration/profile_sync_service_harness.cc

Index: chrome/browser/sync/test/integration/profile_sync_service_harness.cc
diff --git a/chrome/browser/sync/test/integration/profile_sync_service_harness.cc b/chrome/browser/sync/test/integration/profile_sync_service_harness.cc
index 80478dbeace80dd5ee496c30d5218c58382fb185..1968ecb9ddbe1d3af55cb16c86a156a036349334 100644
--- a/chrome/browser/sync/test/integration/profile_sync_service_harness.cc
+++ b/chrome/browser/sync/test/integration/profile_sync_service_harness.cc
@@ -49,7 +49,10 @@ using syncer::sessions::SyncSessionSnapshot;
 using invalidation::P2PInvalidationService;
 
 // The amount of time for which we wait for a sync operation to complete.
-static const int kSyncOperationTimeoutMs = 45000;
+// Note: This must be less than the default 45 second timeout for integration
+// tests so that in case a sync operation times out, it is able to log a useful
+// failure message before the test is killed.
+static const int kSyncOperationTimeoutMs = 30000;

[rlarocque, 2014/01/28 02:50:48]

Are you sure about this?  I think I've seen sync tests in the 40s range on the
build bots before.

[Raghu Simha, 2014/01/28 21:13:12]

In that case, I'll undo this change and leave it for its own CL. Having said
that, the point I make is still valid: For the most part, we'd like tests that
timeout to have a few seconds to log their failure cause before the test runner
kills the test.

 
 namespace {
 
@@ -96,42 +99,6 @@ bool DoneWaitingForBackendInitialization(
   return false;
 }
 
-// Helper function which returns true if initial sync is complete, or if the
-// initial sync is blocked for some reason.
-bool DoneWaitingForInitialSync(const ProfileSyncServiceHarness* harness) {
-  DCHECK(harness);
-  // Initial sync is complete.
-  if (harness->IsFullySynced())
-    return true;
-  // Initial sync is blocked because custom passphrase is required.
-  if (harness->service()->passphrase_required_reason() ==
-      syncer::REASON_DECRYPTION) {
-    return true;
-  }
-  // Initial sync is blocked by an auth error.
-  if (harness->HasAuthError())
-    return true;
-  // Still waiting on initial sync.
-  return false;
-}
-
-// Helper function which returns true if the sync client is fully synced, or if
-// sync is blocked for some reason.
-bool DoneWaitingForFullSync(const ProfileSyncServiceHarness* harness) {
-  DCHECK(harness);
-  // Sync is complete.
-  if (harness->IsFullySynced())
-    return true;
-  // Sync is blocked by an auth error.
-  if (harness->HasAuthError())
-    return true;
-  // Sync is blocked by a failure to fetch Oauth2 tokens.
-  if (harness->service()->IsRetryingAccessTokenFetchForTest())
-    return true;
-  // Still waiting on sync.
-  return false;
-}
-
 // Helper function which returns true if the sync client requires a custom
 // passphrase to be entered for decryption.
 bool IsPassphraseRequired(const ProfileSyncServiceHarness* harness) {
@@ -287,10 +254,11 @@ bool ProfileSyncServiceHarness::SetupSync(
 
   // Wait for initial sync cycle to be completed.
   DCHECK(service()->sync_initialized());
-  CallbackStatusChecker initial_sync_checker(
-      base::Bind(&DoneWaitingForInitialSync, base::Unretained(this)),
-      "DoneWaitingForInitialSync");
-  if (!AwaitStatusChange(&initial_sync_checker, "SetupSync")) {
+  CallbackStatusChecker sync_setup_complete_checker(
+      base::Bind(&ProfileSyncServiceHarness::IsSyncSetupComplete,
+                 base::Unretained(this)),
+      "IsSyncSetupComplete");
+  if (!AwaitStatusChange(&sync_setup_complete_checker, "SetupSync")) {
     LOG(ERROR) << "Initial sync cycle did not complete after "
                << kSyncOperationTimeoutMs / 1000
                << " seconds.";
@@ -399,42 +367,28 @@ bool ProfileSyncServiceHarness::AwaitBackendInitialized() {
   return service()->sync_initialized();
 }
 
-bool ProfileSyncServiceHarness::AwaitDataSyncCompletion() {
-  DVLOG(1) << GetClientInfoString("AwaitDataSyncCompletion");
-
-  DCHECK(service()->sync_initialized());
-  DCHECK(!IsSyncDisabled());
-
-  if (IsDataSynced()) {
-    // Client is already synced; don't wait.
-    return true;
-  }
-
-  CallbackStatusChecker data_synced_checker(
-      base::Bind(&ProfileSyncServiceHarness::IsDataSynced,
-                 base::Unretained(this)),
-      "IsDataSynced");
-  return AwaitStatusChange(&data_synced_checker, "AwaitDataSyncCompletion");
-}
-
-bool ProfileSyncServiceHarness::AwaitFullSyncCompletion() {
-  DVLOG(1) << GetClientInfoString("AwaitFullSyncCompletion");
+// TODO(sync): Remove this method and replace calls with AwaitSteadyState once
+// we stop comparing progress markers.
+bool ProfileSyncServiceHarness::AwaitCommitActivityCompletion() {
+  DVLOG(1) << GetClientInfoString("AwaitCommitActivityCompletion");
   if (IsSyncDisabled()) {
     LOG(ERROR) << "Sync disabled for " << profile_debug_name_ << ".";
     return false;
   }
 
-  if (IsFullySynced()) {
-    // Client is already synced; don't wait.
+  AwaitSteadyState();
+  if (IsCommitActivityComplete()) {
+    // Client already has latest progress markers; don't wait.
     return true;
   }
 
-  DCHECK(service()->sync_initialized());
-  CallbackStatusChecker fully_synced_checker(
-      base::Bind(&DoneWaitingForFullSync, base::Unretained(this)),
-      "DoneWaitingForFullSync");
-  AwaitStatusChange(&fully_synced_checker, "AwaitFullSyncCompletion");
-  return IsFullySynced();
+  CallbackStatusChecker commit_activity_complete_checker(
+      base::Bind(&ProfileSyncServiceHarness::IsCommitActivityComplete,
+                 base::Unretained(this)),
+      "IsCommitActivityComplete");
+  AwaitStatusChange(&commit_activity_complete_checker,
+                    "AwaitCommitActivityCompletion");
+  return IsCommitActivityComplete();
 }
 
 bool ProfileSyncServiceHarness::AwaitSyncDisabled() {
@@ -450,7 +404,7 @@ bool ProfileSyncServiceHarness::AwaitSyncDisabled() {
 bool ProfileSyncServiceHarness::AwaitMutualSyncCycleCompletion(
     ProfileSyncServiceHarness* partner) {
   DVLOG(1) << GetClientInfoString("AwaitMutualSyncCycleCompletion");
-  if (!AwaitFullSyncCompletion())
+  if (!AwaitCommitActivityCompletion())
     return false;
   return partner->WaitUntilProgressMarkersMatch(this);
 }
@@ -458,7 +412,7 @@ bool ProfileSyncServiceHarness::AwaitMutualSyncCycleCompletion(
 bool ProfileSyncServiceHarness::AwaitGroupSyncCycleCompletion(
     std::vector<ProfileSyncServiceHarness*>& partners) {
   DVLOG(1) << GetClientInfoString("AwaitGroupSyncCycleCompletion");
-  if (!AwaitFullSyncCompletion())
+  if (!AwaitCommitActivityCompletion())
     return false;
   bool return_value = true;
   for (std::vector<ProfileSyncServiceHarness*>::iterator it =
@@ -516,6 +470,35 @@ bool ProfileSyncServiceHarness::WaitUntilProgressMarkersMatch(
   return return_value;
 }
 
+bool ProfileSyncServiceHarness::RunMessageLoop(bool quit_when_idle) {
+  base::OneShotTimer<ProfileSyncServiceHarness> timer;
+  timer.Start(FROM_HERE,
+              base::TimeDelta::FromMilliseconds(kSyncOperationTimeoutMs),
+              base::Bind(&ProfileSyncServiceHarness::QuitMessageLoop,
+                         base::Unretained(this)));
+  {
+    base::MessageLoop* loop = base::MessageLoop::current();
+    base::MessageLoop::ScopedNestableTaskAllower allow(loop);
+    if (quit_when_idle)
+      loop->RunUntilIdle();
+    else
+      loop->Run();
+  }
+
+  return timer.IsRunning();
+}
+
+bool ProfileSyncServiceHarness::AwaitSteadyState() {

[rlarocque, 2014/01/28 02:50:48]

It's not clear to me what we can infer about the state of the system when we run
out of callbacks.  This condition is likely to be very racy.  Why should we use
it instead of AwaitStatusChange?

[Raghu Simha, 2014/01/28 21:13:12]

AwaitStatusChange will run the message loop forever until an exit criterion is
satisfied. This relies on the fact that ProfileSyncService will nudge the
harness, and can (and does) cause tests to timeout. I added AwaitSteadyState as
a means to pump the message loop for a particular client before moving on to
other clients.

I accept your point about it potentially being racy. Stay tuned for an updated
CL that reuses AwaitStatusChange in these cases.

+  bool success = RunMessageLoop(true  /* quit_when_idle */);
+  if (success) {
+    DVLOG(1) << GetClientInfoString("AwaitSteadyState succeeded");
+    return true;
+  } else {
+    DVLOG(0) << GetClientInfoString("AwaitSteadyState timed out");
+    return false;
+  }
+}
+
 bool ProfileSyncServiceHarness::AwaitStatusChange(
     StatusChangeChecker* checker, const std::string& source) {
   DVLOG(1) << GetClientInfoString("AwaitStatusChange");
@@ -527,21 +510,10 @@ bool ProfileSyncServiceHarness::AwaitStatusChange(
 
   DCHECK(status_change_checker_ == NULL);
   status_change_checker_ = checker;
-
-  base::OneShotTimer<ProfileSyncServiceHarness> timer;
-  timer.Start(FROM_HERE,
-              base::TimeDelta::FromMilliseconds(kSyncOperationTimeoutMs),
-              base::Bind(&ProfileSyncServiceHarness::QuitMessageLoop,
-                         base::Unretained(this)));
-  {
-    base::MessageLoop* loop = base::MessageLoop::current();
-    base::MessageLoop::ScopedNestableTaskAllower allow(loop);
-    loop->Run();
-  }
-
+  bool success = RunMessageLoop(false  /* quit_when_idle */);
   status_change_checker_ = NULL;
 
-  if (timer.IsRunning()) {
+  if (success) {
     DVLOG(1) << GetClientInfoString("AwaitStatusChange succeeded");
     return true;
   } else {
@@ -577,43 +549,16 @@ bool ProfileSyncServiceHarness::HasAuthError() const {
              GoogleServiceAuthError::REQUEST_CANCELED;
 }
 
-// We use this function to share code between IsFullySynced and IsDataSynced.
-bool ProfileSyncServiceHarness::IsDataSyncedImpl() const {
-  return ServiceIsPushingChanges() &&
-         GetStatus().notifications_enabled &&
-         !service()->HasUnsyncedItems() &&
-         !HasPendingBackendMigration();
-}
-
-bool ProfileSyncServiceHarness::IsDataSynced() const {
-  if (service() == NULL) {
-    DVLOG(1) << GetClientInfoString("IsDataSynced(): false");
-    return false;
-  }
-
-  bool is_data_synced = IsDataSyncedImpl();
-
-  DVLOG(1) << GetClientInfoString(
-      is_data_synced ? "IsDataSynced: true" : "IsDataSynced: false");
-  return is_data_synced;
-}
-
-bool ProfileSyncServiceHarness::IsFullySynced() const {
-  if (service() == NULL) {
-    DVLOG(1) << GetClientInfoString("IsFullySynced: false");
-    return false;
-  }
-  // If we didn't try to commit anything in the previous cycle, there's a
-  // good chance that we're now fully up to date.
+// TODO(sync): Remove this method once we stop relying on self notifications and
+// comparing progress markers.
+bool ProfileSyncServiceHarness::IsCommitActivityComplete() const {

[rlarocque, 2014/01/28 02:50:48]

I think HasFullySyncedProgressMarkers() might be a better name for this.

I was a bit confused about what IsCommitActivityComplete() meant.  The way I see
it, the client is done committing when the last sync cycle that included commits
is done.  That occurs long before the follow-up, self-notify-induced sync cycle
that this function tests for.  

[Raghu Simha, 2014/01/28 21:13:12]

I've renamed it to HasLatestProgressMarkers.

   const SyncSessionSnapshot& snap = GetLastSessionSnapshot();
-  bool is_fully_synced =
-      snap.model_neutral_state().num_successful_commits == 0
-      && snap.model_neutral_state().commit_result == syncer::SYNCER_OK
-      && IsDataSyncedImpl();
+  return snap.model_neutral_state().num_successful_commits == 0 &&
+         !service()->HasUnsyncedItems();
+}
 
-  DVLOG(1) << GetClientInfoString(
-      is_fully_synced ? "IsFullySynced: true" : "IsFullySynced: false");
-  return is_fully_synced;
+bool ProfileSyncServiceHarness::IsSyncSetupComplete() const {
+  return ServiceIsPushingChanges() && IsCommitActivityComplete();
 }
 
 void ProfileSyncServiceHarness::FinishSyncSetup() {
@@ -621,24 +566,12 @@ void ProfileSyncServiceHarness::FinishSyncSetup() {
   service()->SetSyncSetupCompleted();
 }
 
-bool ProfileSyncServiceHarness::HasPendingBackendMigration() const {
-  browser_sync::BackendMigrator* migrator =
-      service()->GetBackendMigratorForTest();
-  return migrator && migrator->state() != browser_sync::BackendMigrator::IDLE;
-}
-
 bool ProfileSyncServiceHarness::AutoStartEnabled() {
   return service()->auto_start_enabled();
 }
 
 bool ProfileSyncServiceHarness::MatchesPartnerClient() const {
-  // TODO(akalin): Shouldn't this belong with the intersection check?
-  // Otherwise, this function isn't symmetric.
   DCHECK(progress_marker_partner_);
-  if (!IsFullySynced()) {
-    DVLOG(2) << profile_debug_name_ << ": not synced, assuming doesn't match";
-    return false;
-  }
 
   // Only look for a match if we have at least one enabled datatype in
   // common with the partner client.
@@ -651,13 +584,6 @@ bool ProfileSyncServiceHarness::MatchesPartnerClient() const {
            << ": common types are "
            << syncer::ModelTypeSetToString(common_types);
 
-  if (!common_types.Empty() && !progress_marker_partner_->IsFullySynced()) {
-    DVLOG(2) << "non-empty common types and "
-             << progress_marker_partner_->profile_debug_name_
-             << " isn't synced";
-    return false;
-  }
-
   for (syncer::ModelTypeSet::Iterator i = common_types.First();
        i.Good(); i.Inc()) {
     const std::string marker = GetSerializedProgressMarker(i.Get());
@@ -713,7 +639,12 @@ bool ProfileSyncServiceHarness::EnableSyncForDatatype(
 
   synced_datatypes.Put(syncer::ModelTypeFromInt(datatype));
   service()->OnUserChoseDatatypes(false, synced_datatypes);
-  if (AwaitDataSyncCompletion()) {
+  CallbackStatusChecker sync_setup_complete_checker(
+      base::Bind(&ProfileSyncServiceHarness::IsSyncSetupComplete,
+                 base::Unretained(this)),
+      "IsSyncSetupComplete");
+  if (AwaitStatusChange(&sync_setup_complete_checker,
+                        "EnableSyncForDatatype")) {
     DVLOG(1) << "EnableSyncForDatatype(): Enabled sync for datatype "
              << syncer::ModelTypeToString(datatype)
              << " on " << profile_debug_name_ << ".";
@@ -746,7 +677,7 @@ bool ProfileSyncServiceHarness::DisableSyncForDatatype(
   synced_datatypes.RetainAll(syncer::UserSelectableTypes());
   synced_datatypes.Remove(datatype);
   service()->OnUserChoseDatatypes(false, synced_datatypes);
-  if (AwaitFullSyncCompletion()) {
+  if (AwaitCommitActivityCompletion()) {
     DVLOG(1) << "DisableSyncForDatatype(): Disabled sync for datatype "
              << syncer::ModelTypeToString(datatype)
              << " on " << profile_debug_name_ << ".";
@@ -769,7 +700,12 @@ bool ProfileSyncServiceHarness::EnableSyncForAllDatatypes() {
   }
 
   service()->OnUserChoseDatatypes(true, syncer::ModelTypeSet::All());
-  if (AwaitFullSyncCompletion()) {
+  CallbackStatusChecker sync_setup_complete_checker(
+      base::Bind(&ProfileSyncServiceHarness::IsSyncSetupComplete,
+                 base::Unretained(this)),
+      "IsSyncSetupComplete");
+  if (AwaitStatusChange(&sync_setup_complete_checker,
+                        "EnableSyncForAllDatatypes")) {
     DVLOG(1) << "EnableSyncForAllDatatypes(): Enabled sync for all datatypes "
              << "on " << profile_debug_name_ << ".";
     return true;
@@ -805,6 +741,8 @@ std::string ProfileSyncServiceHarness::GetSerializedProgressMarker(
   return (it != markers_map.end()) ? it->second : std::string();
 }
 
+// TODO(sync): Clean up this method in a separate CL. Remove all snapshot fields
+// and log shorter, more meaningful messages.
 std::string ProfileSyncServiceHarness::GetClientInfoString(
     const std::string& message) const {
   std::stringstream os;
@@ -813,8 +751,6 @@ std::string ProfileSyncServiceHarness::GetClientInfoString(
     const SyncSessionSnapshot& snap = GetLastSessionSnapshot();
     const ProfileSyncService::Status& status = GetStatus();
     // Capture select info from the sync session snapshot and syncer status.
-    // TODO(rsimha): Audit the list of fields below, and eventually eliminate
-    // the use of the sync session snapshot. See crbug.com/323380.
     os << ", has_unsynced_items: "
        << (service()->sync_initialized() ? service()->HasUnsyncedItems() : 0)
        << ", did_commit: "
@@ -834,9 +770,7 @@ std::string ProfileSyncServiceHarness::GetClientInfoString(
        << ", notifications_enabled: "
        << status.notifications_enabled
        << ", service_is_pushing_changes: "
-       << ServiceIsPushingChanges()
-       << ", has_pending_backend_migration: "
-       << HasPendingBackendMigration();
+       << ServiceIsPushingChanges();
   } else {
     os << "Sync service not available";
   }