Fix the false-positive detection of commit errors

chrome/browser/sync/profile_sync_service_harness.cc

Index: chrome/browser/sync/profile_sync_service_harness.cc
diff --git a/chrome/browser/sync/profile_sync_service_harness.cc b/chrome/browser/sync/profile_sync_service_harness.cc
index c25ec5424830f0c3454cb91ff42260064c137976..b1b0dd6b4134d2eb39e2957d184dc31eab5b7248 100644
--- a/chrome/browser/sync/profile_sync_service_harness.cc
+++ b/chrome/browser/sync/profile_sync_service_harness.cc
@@ -256,7 +256,7 @@ bool ProfileSyncServiceHarness::RunStateChangeMachine() {
     }
     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;
@@ -270,9 +270,9 @@ bool ProfileSyncServiceHarness::RunStateChangeMachine() {
       }
       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;
@@ -292,6 +292,13 @@ bool ProfileSyncServiceHarness::RunStateChangeMachine() {
       }
       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_);
@@ -329,7 +336,7 @@ bool ProfileSyncServiceHarness::RunStateChangeMachine() {
       // 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);
@@ -403,7 +410,7 @@ bool ProfileSyncServiceHarness::RunStateChangeMachine() {
       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;
     }
@@ -544,15 +551,38 @@ bool ProfileSyncServiceHarness::AwaitSyncRestart() {
                                       "Waiting for sync configuration.");
 }
 
-bool ProfileSyncServiceHarness::AwaitSyncCycleCompletion(
+bool ProfileSyncServiceHarness::AwaitDataSyncCompletion(
+    const std::string& reason) {
+  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("AwaitSyncCycleCompletion");
+  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;
   }
@@ -560,12 +590,12 @@ bool ProfileSyncServiceHarness::AwaitSyncCycleCompletion(
   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.
@@ -650,7 +680,14 @@ bool ProfileSyncServiceHarness::AwaitMigration(
               << " 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;
     }
@@ -660,7 +697,7 @@ bool ProfileSyncServiceHarness::AwaitMigration(
 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.");
@@ -669,7 +706,7 @@ bool ProfileSyncServiceHarness::AwaitMutualSyncCycleCompletion(
 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 =
@@ -751,27 +788,49 @@ ProfileSyncService::Status ProfileSyncServiceHarness::GetStatus() {
   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_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_synced ? "IsSynced: true" : "IsSynced: false");
-  return is_synced;
+      is_fully_synced ? "IsFullySynced: true" : "IsFullySynced: false");
+  return is_fully_synced;
 }
 
 bool ProfileSyncServiceHarness::HasPendingBackendMigration() {
@@ -784,7 +843,7 @@ 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;
   }
@@ -803,7 +862,7 @@ bool ProfileSyncServiceHarness::MatchesOtherClient(
           << ": 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;
@@ -872,7 +931,7 @@ bool ProfileSyncServiceHarness::EnableSyncForDatatype(
 
   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_ << ".";
@@ -905,7 +964,7 @@ bool ProfileSyncServiceHarness::DisableSyncForDatatype(
 
   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_ << ".";
@@ -935,7 +994,7 @@ bool ProfileSyncServiceHarness::EnableSyncForAllDatatypes() {
     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;
@@ -1035,7 +1094,7 @@ bool ProfileSyncServiceHarness::WaitForTypeEncryption(
   // 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;