Fix the false-positive detection of commit errors

chrome/browser/sync/profile_sync_service_harness.cc

 // Copyright (c) 2011 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/profile_sync_service_harness.h"
 
 #include <stddef.h>
 #include <algorithm>
 #include <iterator>
 #include <ostream>
@@ skipping 238 matching lines @@
     case WAITING_FOR_ON_BACKEND_INITIALIZED: {
       VLOG(1) << GetClientInfoString("WAITING_FOR_ON_BACKEND_INITIALIZED");
       if (service()->sync_initialized()) {
         // The sync backend is initialized.
         SignalStateCompleteWithNextState(WAITING_FOR_INITIAL_SYNC);
       }
       break;
     }
     case WAITING_FOR_INITIAL_SYNC: {
       VLOG(1) << GetClientInfoString("WAITING_FOR_INITIAL_SYNC");
-      if (IsSynced()) {
+      if (IsFullySynced()) {
         // The first sync cycle is now complete. We can start running tests.
         SignalStateCompleteWithNextState(FULLY_SYNCED);
         break;
       }
       if (service()->passphrase_required_reason() ==
               sync_api::REASON_SET_PASSPHRASE_FAILED) {
         // A passphrase is required for decryption and we don't have it. Do not
         // wait any more.
         SignalStateCompleteWithNextState(SET_PASSPHRASE_FAILED);
         break;
       }
       break;
     }
-    case WAITING_FOR_SYNC_TO_FINISH: {
-      VLOG(1) << GetClientInfoString("WAITING_FOR_SYNC_TO_FINISH");
-      if (IsSynced()) {
+    case WAITING_FOR_FULL_SYNC: {
+      VLOG(1) << GetClientInfoString("WAITING_FOR_FULL_SYNC");
+      if (IsFullySynced()) {
         // The sync cycle we were waiting for is complete.
         SignalStateCompleteWithNextState(FULLY_SYNCED);
         break;
       }
       if (service()->passphrase_required_reason() ==
               sync_api::REASON_SET_PASSPHRASE_FAILED) {
         // A passphrase is required for decryption and we don't have it. Do not
         // wait any more.
         SignalStateCompleteWithNextState(SET_PASSPHRASE_FAILED);
         break;
       }
       if (!GetStatus().server_reachable) {
         // The client cannot reach the sync server because the network is
         // disabled. There is no need to wait anymore.
         SignalStateCompleteWithNextState(SERVER_UNREACHABLE);
         break;
       }
       break;
     }
+    case WAITING_FOR_DATA_SYNC: {
+      if (IsDataSynced()) {
+        SignalStateCompleteWithNextState(FULLY_SYNCED);
+        break;
+      }
+      break;
+    }
     case WAITING_FOR_UPDATES: {
       VLOG(1) << GetClientInfoString("WAITING_FOR_UPDATES");
       DCHECK(timestamp_match_partner_);
       if (!MatchesOtherClient(timestamp_match_partner_)) {
         // The client is not yet fully synced; keep waiting until we converge.
         break;
       }
       timestamp_match_partner_->service()->RemoveObserver(this);
       timestamp_match_partner_ = NULL;
 
@@ skipping 17 matching lines @@
         SignalStateCompleteWithNextState(FULLY_SYNCED);
       }
       break;
     }
     case WAITING_FOR_ENCRYPTION: {
       VLOG(1) << GetClientInfoString("WAITING_FOR_ENCRYPTION");
       // The correctness of this if condition may depend on the ordering of its
       // sub-expressions.  See crbug.com/98607, crbug.com/95619.
       // TODO(rlarocque): Figure out a less brittle way of detecting this.
       if (IsTypeEncrypted(waiting_for_encryption_type_) &&
-          IsSynced() &&
+          IsFullySynced() &&
           GetLastSessionSnapshot()->num_conflicting_updates == 0) {
         // Encryption is now complete for the the type in which we were waiting.
         SignalStateCompleteWithNextState(FULLY_SYNCED);
         break;
       }
       if (!GetStatus().server_reachable) {
         // The client cannot reach the sync server because the network is
         // disabled. There is no need to wait anymore.
         SignalStateCompleteWithNextState(SERVER_UNREACHABLE);
         break;
@@ skipping 53 matching lines @@
         // An actionable error has been detected.
         SignalStateCompleteWithNextState(WAITING_FOR_NOTHING);
       }
       break;
     }
     case SERVER_UNREACHABLE: {
       VLOG(1) << GetClientInfoString("SERVER_UNREACHABLE");
       if (GetStatus().server_reachable) {
         // The client was offline due to the network being disabled, but is now
         // back online. Wait for the pending sync cycle to complete.
-        SignalStateCompleteWithNextState(WAITING_FOR_SYNC_TO_FINISH);
+        SignalStateCompleteWithNextState(WAITING_FOR_FULL_SYNC);
       }
       break;
     }
     case SET_PASSPHRASE_FAILED: {
       // A passphrase is required for decryption. There is nothing the sync
       // client can do until SetPassphrase() is called.
       VLOG(1) << GetClientInfoString("SET_PASSPHRASE_FAILED");
       break;
     }
     case FULLY_SYNCED: {
@@ skipping 120 matching lines @@
                << " seconds.";
     return false;
   }
 
   // Wait for sync configuration to complete.
   wait_state_ = WAITING_FOR_SYNC_CONFIGURATION;
   return AwaitStatusChangeWithTimeout(kLiveSyncOperationTimeoutMs,
                                       "Waiting for sync configuration.");
 }
 
-bool ProfileSyncServiceHarness::AwaitSyncCycleCompletion(
+bool ProfileSyncServiceHarness::AwaitDataSyncCompletion(
     const std::string& reason) {
-  VLOG(1) << GetClientInfoString("AwaitSyncCycleCompletion");
+  VLOG(1) << GetClientInfoString("AwaitDataSyncCompletion");
+
+  DCHECK(service()->sync_initialized());
+  DCHECK_NE(wait_state_, SYNC_DISABLED);
+  DCHECK_NE(wait_state_, SERVER_UNREACHABLE);
+
+  if (IsDataSynced()) {
+    // Client is already synced; don't wait.
+    return true;
+  }
+
+  wait_state_ = WAITING_FOR_DATA_SYNC;
+  AwaitStatusChangeWithTimeout(kLiveSyncOperationTimeoutMs, reason);
+  if (wait_state_ == FULLY_SYNCED) {
+    return true;
+  } else {
+    LOG(ERROR) << "AwaitDataSyncCompletion failed, state is now: " << wait_state_;
+    return false;
+  }
+}
+
+bool ProfileSyncServiceHarness::AwaitFullSyncCompletion(
+    const std::string& reason) {
+  VLOG(1) << GetClientInfoString("AwaitFullSyncCompletion");
   if (wait_state_ == SYNC_DISABLED) {
     LOG(ERROR) << "Sync disabled for " << profile_debug_name_ << ".";
     return false;
   }
 
-  if (IsSynced()) {
+  if (IsFullySynced()) {
     // Client is already synced; don't wait.
     return true;
   }
 
   if (wait_state_ == SERVER_UNREACHABLE) {
     // Client was offline; wait for it to go online, and then wait for sync.
     AwaitStatusChangeWithTimeout(kLiveSyncOperationTimeoutMs, reason);
-    DCHECK_EQ(wait_state_, WAITING_FOR_SYNC_TO_FINISH);
+    DCHECK_EQ(wait_state_, WAITING_FOR_FULL_SYNC);
     return AwaitStatusChangeWithTimeout(kLiveSyncOperationTimeoutMs, reason);
   }
 
   DCHECK(service()->sync_initialized());
-  wait_state_ = WAITING_FOR_SYNC_TO_FINISH;
+  wait_state_ = WAITING_FOR_FULL_SYNC;
   AwaitStatusChangeWithTimeout(kLiveSyncOperationTimeoutMs, reason);
   if (wait_state_ == FULLY_SYNCED) {
     // Client is online; sync was successful.
     return true;
   } else if (wait_state_ == SERVER_UNREACHABLE) {
     // Client is offline; sync was unsuccessful.
     LOG(ERROR) << "Client went offline after waiting for sync to finish";
     return false;
   } else {
     LOG(ERROR) << "Invalid wait state: " << wait_state_;
@@ skipping 64 matching lines @@
       }
     }
     AwaitStatusChangeWithTimeout(kLiveSyncOperationTimeoutMs,
                                  "Wait for migration to finish");
     if (wait_state_ != WAITING_FOR_NOTHING) {
       VLOG(1) << profile_debug_name_
               << ": wait state = " << wait_state_
               << " after migration finish is not WAITING_FOR_NOTHING";
       return false;
     }
-    if (!AwaitSyncCycleCompletion(
+    // We must use AwaitDataSyncCompletion rather than the more common
+    // AwaitFullSyncCompletion.  As long as crbug.com/97780 is open, we will
+    // rely on self-notifiations to ensure that timestamps are udpated, which
+    // allows AwaitFullSyncCompletion to return.  However, in some migration
+    // tests these notifications are completely disabled, so the timestamps do
+    // not get updated.  This is why we must use the less strict condition,
+    // AwaitDataSyncCompletion.
+    if (!AwaitDataSyncCompletion(
             "Config sync cycle after migration cycle")) {
       return false;
     }
   }
 }
 
 bool ProfileSyncServiceHarness::AwaitMutualSyncCycleCompletion(
     ProfileSyncServiceHarness* partner) {
   VLOG(1) << GetClientInfoString("AwaitMutualSyncCycleCompletion");
-  if (!AwaitSyncCycleCompletion("Sync cycle completion on active client."))
+  if (!AwaitFullSyncCompletion("Sync cycle completion on active client."))
     return false;
   return partner->WaitUntilTimestampMatches(this,
       "Sync cycle completion on passive client.");
 }
 
 bool ProfileSyncServiceHarness::AwaitGroupSyncCycleCompletion(
     std::vector<ProfileSyncServiceHarness*>& partners) {
   VLOG(1) << GetClientInfoString("AwaitGroupSyncCycleCompletion");
-  if (!AwaitSyncCycleCompletion("Sync cycle completion on active client."))
+  if (!AwaitFullSyncCompletion("Sync cycle completion on active client."))
     return false;
   bool return_value = true;
   for (std::vector<ProfileSyncServiceHarness*>::iterator it =
       partners.begin(); it != partners.end(); ++it) {
     if ((this != *it) && ((*it)->wait_state_ != SYNC_DISABLED)) {
       return_value = return_value &&
           (*it)->WaitUntilTimestampMatches(this,
           "Sync cycle completion on partner client.");
     }
   }
@@ skipping 61 matching lines @@
     VLOG(0) << GetClientInfoString("AwaitStatusChangeWithTimeout timed out");
     return false;
   }
 }
 
 ProfileSyncService::Status ProfileSyncServiceHarness::GetStatus() {
   DCHECK(service() != NULL) << "GetStatus(): service() is NULL.";
   return service()->QueryDetailedSyncStatus();
 }
 
-bool ProfileSyncServiceHarness::IsSynced() {
-  if (service() == NULL) {
-    VLOG(1) << GetClientInfoString("IsSynced: false");
-    return false;
-  }
-  const SyncSessionSnapshot* snap = GetLastSessionSnapshot();
-  // TODO(rsimha): Remove additional checks of snap->has_more_to_sync and
-  // snap->unsynced_count once http://crbug.com/48989 is fixed.
-  bool is_synced = snap &&
+// We use this function to share code between IsFullySynced and IsDataSynced
+// while ensuring that all conditions are evaluated using on the same snapshot.
+bool ProfileSyncServiceHarness::IsDataSyncedImpl(
+    const browser_sync::sessions::SyncSessionSnapshot *snap) {
+  return snap &&
       snap->num_blocking_conflicting_updates == 0 &&
       ServiceIsPushingChanges() &&
       GetStatus().notifications_enabled &&
       !service()->HasUnsyncedItems() &&
       !snap->has_more_to_sync &&
-      snap->unsynced_count == 0 &&
       !HasPendingBackendMigration() &&
       service()->passphrase_required_reason() !=
-      sync_api::REASON_SET_PASSPHRASE_FAILED;
+        sync_api::REASON_SET_PASSPHRASE_FAILED;
+}
+
+bool ProfileSyncServiceHarness::IsDataSynced() {
+  if (service() == NULL) {
+    VLOG(1) << GetClientInfoString("IsDataSynced(): false");
+    return false;
+  }
+
+  const SyncSessionSnapshot* snap = GetLastSessionSnapshot();
+  bool is_data_synced = IsDataSyncedImpl(snap);
+
   VLOG(1) << GetClientInfoString(
-      is_synced ? "IsSynced: true" : "IsSynced: false");
-  return is_synced;
+      is_data_synced ? "IsDataSynced: true" : "IsDataSynced: false");
+  return is_data_synced;
+}
+
+bool ProfileSyncServiceHarness::IsFullySynced() {
+  if (service() == NULL) {
+    VLOG(1) << GetClientInfoString("IsFullySynced: false");
+    return false;
+  }
+  const SyncSessionSnapshot* snap = GetLastSessionSnapshot();
+  // snap->unsynced_count == 0 is a fairly reliable indicator of whether or not
+  // our timestamp is in sync with the server.
+  bool is_fully_synced = IsDataSyncedImpl(snap) &&
+      snap->unsynced_count == 0;
+
+  VLOG(1) << GetClientInfoString(
+      is_fully_synced ? "IsFullySynced: true" : "IsFullySynced: false");
+  return is_fully_synced;
 }
 
 bool ProfileSyncServiceHarness::HasPendingBackendMigration() {
   browser_sync::BackendMigrator* migrator =
       service()->GetBackendMigratorForTest();
   return migrator && migrator->state() != browser_sync::BackendMigrator::IDLE;
 }
 
 bool ProfileSyncServiceHarness::MatchesOtherClient(
     ProfileSyncServiceHarness* partner) {
   // TODO(akalin): Shouldn't this belong with the intersection check?
   // Otherwise, this function isn't symmetric.
-  if (!IsSynced()) {
+  if (!IsFullySynced()) {
     VLOG(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.
   syncable::ModelTypeSet types, other_types, intersection_types;
   service()->GetPreferredDataTypes(&types);
   partner->service()->GetPreferredDataTypes(&other_types);
   std::set_intersection(types.begin(), types.end(), other_types.begin(),
                         other_types.end(),
                         inserter(intersection_types,
                                  intersection_types.begin()));
 
   VLOG(2) << profile_debug_name_ << ", " << partner->profile_debug_name_
           << ": common types are "
           << syncable::ModelTypeSetToString(intersection_types);
 
-  if (!intersection_types.empty() && !partner->IsSynced()) {
+  if (!intersection_types.empty() && !partner->IsFullySynced()) {
     VLOG(2) << "non-empty common types and "
             << partner->profile_debug_name_ << " isn't synced";
     return false;
   }
 
   for (syncable::ModelTypeSet::iterator i = intersection_types.begin();
        i != intersection_types.end(); ++i) {
     const std::string timestamp = GetUpdatedTimestamp(*i);
     const std::string partner_timestamp = partner->GetUpdatedTimestamp(*i);
     if (timestamp != partner_timestamp) {
@@ skipping 48 matching lines @@
   syncable::ModelTypeSet::iterator it = synced_datatypes.find(datatype);
   if (it != synced_datatypes.end()) {
     VLOG(1) << "EnableSyncForDatatype(): Sync already enabled for datatype "
             << syncable::ModelTypeToString(datatype)
             << " on " << profile_debug_name_ << ".";
     return true;
   }
 
   synced_datatypes.insert(syncable::ModelTypeFromInt(datatype));
   service()->OnUserChoseDatatypes(false, synced_datatypes);
-  if (AwaitSyncCycleCompletion("Datatype configuration.")) {
+  if (AwaitFullSyncCompletion("Datatype configuration.")) {
     VLOG(1) << "EnableSyncForDatatype(): Enabled sync for datatype "
             << syncable::ModelTypeToString(datatype)
             << " on " << profile_debug_name_ << ".";
     return true;
   }
 
   VLOG(0) << GetClientInfoString("EnableSyncForDatatype failed");
   return false;
 }
 
@@ skipping 12 matching lines @@
   syncable::ModelTypeSet::iterator it = synced_datatypes.find(datatype);
   if (it == synced_datatypes.end()) {
     VLOG(1) << "DisableSyncForDatatype(): Sync already disabled for datatype "
             << syncable::ModelTypeToString(datatype)
             << " on " << profile_debug_name_ << ".";
     return true;
   }
 
   synced_datatypes.erase(it);
   service()->OnUserChoseDatatypes(false, synced_datatypes);
-  if (AwaitSyncCycleCompletion("Datatype reconfiguration.")) {
+  if (AwaitFullSyncCompletion("Datatype reconfiguration.")) {
     VLOG(1) << "DisableSyncForDatatype(): Disabled sync for datatype "
             << syncable::ModelTypeToString(datatype)
             << " on " << profile_debug_name_ << ".";
     return true;
   }
 
   VLOG(0) << GetClientInfoString("DisableSyncForDatatype failed");
   return false;
 }
 
 bool ProfileSyncServiceHarness::EnableSyncForAllDatatypes() {
   VLOG(1) << GetClientInfoString("EnableSyncForAllDatatypes");
 
   if (wait_state_ == SYNC_DISABLED) {
     return SetupSync();
   }
 
   if (service() == NULL) {
     LOG(ERROR) << "EnableSyncForAllDatatypes(): service() is null.";
     return false;
   }
 
   syncable::ModelTypeSet synced_datatypes;
   for (int i = syncable::FIRST_REAL_MODEL_TYPE;
        i < syncable::MODEL_TYPE_COUNT;
        ++i) {
     synced_datatypes.insert(syncable::ModelTypeFromInt(i));
   }
   service()->OnUserChoseDatatypes(true, synced_datatypes);
-  if (AwaitSyncCycleCompletion("Datatype reconfiguration.")) {
+  if (AwaitFullSyncCompletion("Datatype reconfiguration.")) {
     VLOG(1) << "EnableSyncForAllDatatypes(): Enabled sync for all datatypes on "
             << profile_debug_name_ << ".";
     return true;
   }
 
   VLOG(0) << GetClientInfoString("EnableSyncForAllDatatypes failed");
   return false;
 }
 
 bool ProfileSyncServiceHarness::DisableSyncForAllDatatypes() {
@@ skipping 79 matching lines @@
   // Wait some time to let the enryption finish.
   return WaitForTypeEncryption(type);
 }
 
 bool ProfileSyncServiceHarness::WaitForTypeEncryption(
     syncable::ModelType type) {
   // The correctness of this if condition depends on the ordering of its
   // sub-expressions.  See crbug.com/95619.
   // TODO(rlarocque): Figure out a less brittle way of detecting this.
   if (IsTypeEncrypted(type) &&
-      IsSynced() &&
+      IsFullySynced() &&
       GetLastSessionSnapshot()->num_conflicting_updates == 0) {
     // Encryption is already complete for |type|; do not wait.
     return true;
   }
 
   std::string reason = "Waiting for encryption.";
   wait_state_ = WAITING_FOR_ENCRYPTION;
   waiting_for_encryption_type_ = type;
   if (!AwaitStatusChangeWithTimeout(kLiveSyncOperationTimeoutMs, reason)) {
     LOG(ERROR) << "Did not receive EncryptionComplete notification after"
@@ skipping 22 matching lines @@
   return (synced_types.count(type) != 0);
 }
 
 std::string ProfileSyncServiceHarness::GetServiceStatus() {
   DictionaryValue value;
   sync_ui_util::ConstructAboutInformation(service_, &value);
   std::string service_status;
   base::JSONWriter::Write(&value, true, &service_status);
   return service_status;
 }