[sync] Eliminate Await*SyncCompletion methods in integration tests

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

 // Copyright 2013 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 "chrome/browser/sync/test/integration/profile_sync_service_harness.h"
 
 #include <cstddef>
 #include <iterator>
 #include <ostream>
 #include <set>
@@ skipping 31 matching lines @@
 #include "sync/internal_api/public/util/sync_string_conversions.h"
 
 #if defined(ENABLE_MANAGED_USERS)
 #include "chrome/browser/managed_mode/managed_user_constants.h"
 #endif
 
 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 {
 
 // Checks if a desired change in the state of the sync engine has taken place by
 // running the callback passed to it.
 class CallbackStatusChecker : public StatusChangeChecker {
  public:
   CallbackStatusChecker(base::Callback<bool()> callback,
                         const std::string& source)
       : StatusChangeChecker(source),
@@ skipping 26 matching lines @@
   // Backend initialization is blocked by an auth error.
   if (harness->HasAuthError())
     return true;
   // Backend initialization is blocked by a failure to fetch Oauth2 tokens.
   if (harness->service()->IsRetryingAccessTokenFetchForTest())
     return true;
   // Still waiting on backend initialization.
   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) {
   DCHECK(harness);
   return harness->service()->IsPassphraseRequired();
 }
 
 // Helper function which returns true if the custom passphrase entered was
 // accepted.
 bool IsPassphraseAccepted(const ProfileSyncServiceHarness* harness) {
@@ skipping 135 matching lines @@
   if (!service()->IsUsingSecondaryPassphrase()) {
     service()->SetEncryptionPassphrase(password_, ProfileSyncService::IMPLICIT);
   } else {
     LOG(ERROR) << "A passphrase is required for decryption. Sync cannot proceed"
                   " until SetDecryptionPassphrase is called.";
     return false;
   }
 
   // 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.";
     return false;
   }
 
   // Make sure that initial sync wasn't blocked by a missing passphrase.
   if (service()->passphrase_required_reason() == syncer::REASON_DECRYPTION) {
     LOG(ERROR) << "A passphrase is required for decryption. Sync cannot proceed"
                   " until SetDecryptionPassphrase is called.";
@@ skipping 88 matching lines @@
   }
 
   CallbackStatusChecker backend_initialized_checker(
       base::Bind(&DoneWaitingForBackendInitialization,
                  base::Unretained(this)),
       "DoneWaitingForBackendInitialization");
   AwaitStatusChange(&backend_initialized_checker, "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() {
   DCHECK(service()->HasSyncSetupCompleted());
   DCHECK(!IsSyncDisabled());
   CallbackStatusChecker sync_disabled_checker(
       base::Bind(&ProfileSyncServiceHarness::IsSyncDisabled,
                  base::Unretained(this)),
       "IsSyncDisabled");
   return AwaitStatusChange(&sync_disabled_checker, "AwaitSyncDisabled");
 }
 
 bool ProfileSyncServiceHarness::AwaitMutualSyncCycleCompletion(
     ProfileSyncServiceHarness* partner) {
   DVLOG(1) << GetClientInfoString("AwaitMutualSyncCycleCompletion");
-  if (!AwaitFullSyncCompletion())
+  if (!AwaitCommitActivityCompletion())
     return false;
   return partner->WaitUntilProgressMarkersMatch(this);
 }
 
 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 =
       partners.begin(); it != partners.end(); ++it) {
     if ((this != *it) && (!(*it)->IsSyncDisabled())) {
       return_value = return_value &&
           (*it)->WaitUntilProgressMarkersMatch(this);
     }
   }
   return return_value;
@@ skipping 37 matching lines @@
                    base::Unretained(this)),
         "MatchesPartnerClient");
     return_value = AwaitStatusChange(&matches_other_client_checker,
                                      "WaitUntilProgressMarkersMatch");
     partner->service()->RemoveObserver(this);
   }
   progress_marker_partner_ = NULL;
   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");
 
   if (IsSyncDisabled()) {
     LOG(ERROR) << "Sync disabled for " << profile_debug_name_ << ".";
     return false;
   }
 
   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 {
     DVLOG(0) << GetClientInfoString(base::StringPrintf(
         "AwaitStatusChange called from %s timed out", source.c_str()));
     return false;
   }
 }
 
 std::string ProfileSyncServiceHarness::GenerateFakeOAuth2RefreshTokenString() {
@@ skipping 15 matching lines @@
 
 bool ProfileSyncServiceHarness::HasAuthError() const {
   return service()->GetAuthError().state() ==
              GoogleServiceAuthError::INVALID_GAIA_CREDENTIALS ||
          service()->GetAuthError().state() ==
              GoogleServiceAuthError::SERVICE_ERROR ||
          service()->GetAuthError().state() ==
              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();
+// 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();
+  return snap.model_neutral_state().num_successful_commits == 0 &&
+         !service()->HasUnsyncedItems();
 }
 
-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.
-  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();
-
-  DVLOG(1) << GetClientInfoString(
-      is_fully_synced ? "IsFullySynced: true" : "IsFullySynced: false");
-  return is_fully_synced;
+bool ProfileSyncServiceHarness::IsSyncSetupComplete() const {
+  return ServiceIsPushingChanges() && IsCommitActivityComplete();
 }
 
 void ProfileSyncServiceHarness::FinishSyncSetup() {
   service()->SetSetupInProgress(false);
   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.
   const syncer::ModelTypeSet common_types =
       Intersection(service()->GetActiveDataTypes(),
                    progress_marker_partner_->service()->GetActiveDataTypes());
 
   DVLOG(2) << profile_debug_name_ << ", "
            << progress_marker_partner_->profile_debug_name_
            << ": 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());
     const std::string partner_marker =
         progress_marker_partner_->GetSerializedProgressMarker(i.Get());
     if (marker != partner_marker) {
       if (VLOG_IS_ON(2)) {
         std::string marker_base64, partner_marker_base64;
         base::Base64Encode(marker, &marker_base64);
         base::Base64Encode(partner_marker, &partner_marker_base64);
@@ skipping 35 matching lines @@
   syncer::ModelTypeSet synced_datatypes = service()->GetPreferredDataTypes();
   if (synced_datatypes.Has(datatype)) {
     DVLOG(1) << "EnableSyncForDatatype(): Sync already enabled for datatype "
              << syncer::ModelTypeToString(datatype)
              << " on " << profile_debug_name_ << ".";
     return true;
   }
 
   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_ << ".";
     return true;
   }
 
   DVLOG(0) << GetClientInfoString("EnableSyncForDatatype failed");
   return false;
 }
 
@@ skipping 12 matching lines @@
   if (!synced_datatypes.Has(datatype)) {
     DVLOG(1) << "DisableSyncForDatatype(): Sync already disabled for datatype "
              << syncer::ModelTypeToString(datatype)
              << " on " << profile_debug_name_ << ".";
     return true;
   }
 
   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_ << ".";
     return true;
   }
 
   DVLOG(0) << GetClientInfoString("DisableSyncForDatatype failed");
   return false;
 }
 
 bool ProfileSyncServiceHarness::EnableSyncForAllDatatypes() {
   DVLOG(1) << GetClientInfoString("EnableSyncForAllDatatypes");
 
   if (IsSyncDisabled())
     return SetupSync();
 
   if (service() == NULL) {
     LOG(ERROR) << "EnableSyncForAllDatatypes(): service() is null.";
     return false;
   }
 
   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;
   }
 
   DVLOG(0) << GetClientInfoString("EnableSyncForAllDatatypes failed");
   return false;
 }
 
 bool ProfileSyncServiceHarness::DisableSyncForAllDatatypes() {
@@ skipping 15 matching lines @@
     syncer::ModelType model_type) const {
   const SyncSessionSnapshot& snap = GetLastSessionSnapshot();
   const syncer::ProgressMarkerMap& markers_map =
       snap.download_progress_markers();
 
   syncer::ProgressMarkerMap::const_iterator it =
       markers_map.find(model_type);
   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;
   os << profile_debug_name_ << ": " << message << ": ";
   if (service()) {
     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: "
        << (snap.model_neutral_state().num_successful_commits == 0 &&
            snap.model_neutral_state().commit_result == syncer::SYNCER_OK)
        << ", encryption conflicts: "
        << snap.num_encryption_conflicts()
        << ", hierarchy conflicts: "
        << snap.num_hierarchy_conflicts()
        << ", server conflicts: "
        << snap.num_server_conflicts()
        << ", num_updates_downloaded : "
        << snap.model_neutral_state().num_updates_downloaded_total
        << ", passphrase_required_reason: "
        << syncer::PassphraseRequiredReasonToString(
            service()->passphrase_required_reason())
        << ", notifications_enabled: "
        << status.notifications_enabled
        << ", service_is_pushing_changes: "
-       << ServiceIsPushingChanges()
-       << ", has_pending_backend_migration: "
-       << HasPendingBackendMigration();
+       << ServiceIsPushingChanges();
   } else {
     os << "Sync service not available";
   }
   return os.str();
 }
 
 bool ProfileSyncServiceHarness::EnableEncryption() {
   if (IsEncryptionComplete())
     return true;
   service()->EnableEncryptEverything();
@@ skipping 56 matching lines @@
 
 std::string ProfileSyncServiceHarness::GetServiceStatus() {
   scoped_ptr<base::DictionaryValue> value(
       sync_ui_util::ConstructAboutInformation(service()));
   std::string service_status;
   base::JSONWriter::WriteWithOptions(value.get(),
                                      base::JSONWriter::OPTIONS_PRETTY_PRINT,
                                      &service_status);
   return service_status;
 }