[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.
+// TODO(sync): This timeout must eventually be made 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 = 45000;
 
 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)
@@ skipping 27 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")) {
+  if (!AwaitSyncSetupCompletion()) {

[rlarocque, 2014/01/28 23:08:29]

As I understand it, this will loop until ShouldPushChanges() returns true.  At
this point in init, that's likely to be blocked on the condition

  data_type_manager_->state() == DataTypeManager::CONFIGURED;

That's OK, I guess.  It means we'll keep looping util we're ready to commit
changes.

However, if the server were to reject our credentials or we fail to decrypt the
data we receive, I don't think we'll ever reach the ShouldPushChanges() state. 
This makes me wonder what the if statements on lines 264 and 271 are for.  

Also, we won't exit if we hit an unrecoverable error, either.  I'm not sure if
that's a problem.

[Raghu Simha, 2014/01/29 00:28:43]

Fair point. I've covered these error conditions in DoneWaitingForSyncSetup,
which causes AwaitSyncSetupCompletion to exit early and return false if any
errors were hit.

     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");
+bool ProfileSyncServiceHarness::AwaitCommitActivityCompletion() {

[rlarocque, 2014/01/28 23:08:29]

You should change the name of this function, too.

[Raghu Simha, 2014/01/29 00:28:43]

Actually, here's why I'd like to keep this name instead of renaming it to
something like AwaitLatestProgressMarkers. Numerous tests call this method when
a client changes data, in order to wait for its commit activity to end. I don't
think tests should have to know about or worry about progress markers. In
future, once the C++ server is implemented, we should re-implement this function
using knowledge of global state and remove references to progress markers.

I've made a note of this in a TODO.

+  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.
+  if (HasLatestProgressMarkers()) {
+    // Client has nothing to commit and 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 latest_progress_markers_checker(
+      base::Bind(&ProfileSyncServiceHarness::HasLatestProgressMarkers,
+                 base::Unretained(this)),
+      "HasLatestProgressMarkers");
+  AwaitStatusChange(&latest_progress_markers_checker,
+                    "AwaitCommitActivityCompletion");
+  return HasLatestProgressMarkers();
 }
 
 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::AwaitSyncSetupCompletion() {
+  if (ServiceIsPushingChanges()) {

[rlarocque, 2014/01/28 23:08:29]

If this is likely to become a pattern (ie. many StatusChangeCheckers will have
special conditions to check before they start looping), you should add support
for it in the StatusChangeChecker class.

[Raghu Simha, 2014/01/29 00:28:43]

The following checks are now in AwaitStatusChange. They needn't be repeated in
other Await* methods, so I've removed them.
- If sync is disabled, return false
- If the exit criterion is already satisfied, return true

+    // Sync is already set up for the client, and it is pushing changes to the
+    // server; don't wait.
+    return true;
+  }
+
+  CallbackStatusChecker sync_setup_complete_checker(
+      base::Bind(&ProfileSyncServiceHarness::ServiceIsPushingChanges,
+                 base::Unretained(this)),
+      "ServiceIsPushingChanges");
+  return AwaitStatusChange(&sync_setup_complete_checker,
+                           "AwaitSyncSetupCompletion");
+}
+
 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 98 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();
-}
-
-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::HasLatestProgressMarkers() const {
   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;
+  return snap.model_neutral_state().num_successful_commits == 0 &&
+         !service()->HasUnsyncedItems();
 }
 
 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()) {
+  if (AwaitSyncSetupCompletion()) {
     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 (AwaitSyncSetupCompletion()) {
     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()) {
+  if (AwaitSyncSetupCompletion()) {
     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;
 }