[Sync] Make BackendMigrator not wait for full sync cycles

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>
 #include <set>
 #include <sstream>
 #include <vector>
 
+#include "base/base64.h"
 #include "base/json/json_writer.h"
 #include "base/logging.h"
 #include "base/memory/ref_counted.h"
 #include "base/message_loop.h"
 #include "base/task.h"
 #include "base/tracked.h"
 #include "chrome/browser/profiles/profile.h"
 #include "chrome/browser/sync/sessions/session_state.h"
 #include "chrome/browser/sync/signin_manager.h"
 #include "chrome/browser/sync/sync_ui_util.h"
@@ skipping 188 matching lines @@
 void ProfileSyncServiceHarness::SignalStateCompleteWithNextState(
     WaitState next_state) {
   wait_state_ = next_state;
   SignalStateComplete();
 }
 
 void ProfileSyncServiceHarness::SignalStateComplete() {
   MessageLoop::current()->Quit();
 }
 
+void ProfileSyncServiceHarness::UpdateMigrationState() {
+  if (service()->HasPendingBackendMigration()) {
+    // Merge current pending migration types into
+    // |pending_migration_types_|.

[Raghu Simha, 2011/09/01 03:53:06]

Should we not simply replace pending_migration_types_ with
new_pending_migration_types?

For instance: What if pending_migration_types_ was originally {BOOKMARKS,
PREFERENCES}, and then, AUTOFILL was added to the list via
GetPendingMigrationTypesForTest(), but in the meantime, BOOKMARKS was already
migrated?

Will we not end up with {BOOKMARKS, PREFERENCES, AUTOFILL} when we should in
fact end up with {PREFERENCES, AUTOFILL}?

Or is something like the above not possible?

[akalin, 2011/09/01 04:03:24]

The idea is to accumulate all migrated types instead of just the one in the
current migration "session".  But in practice, all the pending types get
migrated at the same time (since the migrator waits until the configuration is
complete for all of them).

So in a nutshell, simply assigning would work, but I'm merging to be defensive,
since the intended end result is an accumulation.

[Raghu Simha, 2011/09/01 04:23:58]

SGTM.

+    syncable::ModelTypeSet new_pending_migration_types =
+        service()->GetPendingMigrationTypesForTest();
+    syncable::ModelTypeSet temp;
+    std::set_union(pending_migration_types_.begin(),
+                   pending_migration_types_.end(),
+                   new_pending_migration_types.begin(),
+                   new_pending_migration_types.end(),
+                   std::inserter(temp, temp.end()));
+    std::swap(pending_migration_types_, temp);
+    VLOG(1) << profile_debug_name_ << ": new pending migration types "
+            << syncable::ModelTypeSetToString(pending_migration_types_);
+  } else {
+    // Merge just-finished pending migration types into
+    // |migration_types_|.
+    syncable::ModelTypeSet temp;
+    std::set_union(pending_migration_types_.begin(),
+                   pending_migration_types_.end(),
+                   migrated_types_.begin(),
+                   migrated_types_.end(),
+                   std::inserter(temp, temp.end()));
+    std::swap(migrated_types_, temp);
+    pending_migration_types_.clear();
+    VLOG(1) << profile_debug_name_ << ": new migrated types "
+            << syncable::ModelTypeSetToString(migrated_types_);
+  }
+}
+
 bool ProfileSyncServiceHarness::RunStateChangeMachine() {
   WaitState original_wait_state = wait_state_;
   switch (wait_state_) {
     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;
@@ skipping 104 matching lines @@
       VLOG(1) << GetClientInfoString(
                      "WAITING_FOR_EXPONENTIAL_BACKOFF_VERIFICATION");
       const browser_sync::sessions::SyncSessionSnapshot *snap =
           GetLastSessionSnapshot();
       CHECK(snap);
       retry_verifier_.VerifyRetryInterval(*snap);
       if (retry_verifier_.done())
         SignalStateCompleteWithNextState(WAITING_FOR_NOTHING);
       break;
     }
+    case WAITING_FOR_MIGRATION_TO_START: {
+      VLOG(1) << GetClientInfoString("WAITING_FOR_MIGRATION_TO_START");
+      if (service()->HasPendingBackendMigration()) {
+        SignalStateCompleteWithNextState(WAITING_FOR_MIGRATION_TO_FINISH);
+      }
+      break;
+    }
+    case WAITING_FOR_MIGRATION_TO_FINISH: {
+      VLOG(1) << GetClientInfoString("WAITING_FOR_MIGRATION_TO_FINISH");
+      if (!service()->HasPendingBackendMigration()) {
+        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);
       }
       break;
     }
     case SET_PASSPHRASE_FAILED: {
@@ skipping 20 matching lines @@
     }
     default:
       // Invalid state during observer callback which may be triggered by other
       // classes using the the UI message loop.  Defer to their handling.
       break;
   }
   return original_wait_state != wait_state_;
 }
 
 void ProfileSyncServiceHarness::OnStateChanged() {
+  UpdateMigrationState();

[Raghu Simha, 2011/09/01 03:53:06]

Any particular reason for calling UpdateMigrationState() here, where it will be
run after every single state change? Would it not be sufficient to call it in
RunStateChangeMachine() only when we are in either
WAITING_FOR_MIGRATION_TO_START or WAITING_FOR_MIGRATION_TO_FINISH? (where it
will be run a much smaller percentage of the time)

[akalin, 2011/09/01 04:03:24]

Addressed in latest patch.

   RunStateChangeMachine();
 }
 
 bool ProfileSyncServiceHarness::AwaitPassphraseRequired() {
   VLOG(1) << GetClientInfoString("AwaitPassphraseRequired");
   if (wait_state_ == SYNC_DISABLED) {
     LOG(ERROR) << "Sync disabled for " << profile_debug_name_ << ".";
     return false;
   }
 
@@ skipping 65 matching lines @@
   if (wait_state_ == SYNC_DISABLED) {
     LOG(ERROR) << "Sync disabled for " << profile_debug_name_ << ".";
     return false;
   }
 
   if (IsSynced()) {
     // Client is already synced; don't wait.
     return true;
   }
 
-  return AwaitSyncCycleCompletionHelper(reason);
-}
-
-bool ProfileSyncServiceHarness::AwaitNextSyncCycleCompletion(
-    const std::string& reason) {
-  VLOG(1) << GetClientInfoString("AwaitNextSyncCycleCompletion");
-  return AwaitSyncCycleCompletionHelper(reason);
-}
-
-bool ProfileSyncServiceHarness::AwaitSyncCycleCompletionHelper(
-    const std::string& reason) {
   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);
     return AwaitStatusChangeWithTimeout(kLiveSyncOperationTimeoutMs, reason);
   }
 
   DCHECK(service()->sync_initialized());
   wait_state_ = WAITING_FOR_SYNC_TO_FINISH;
   AwaitStatusChangeWithTimeout(kLiveSyncOperationTimeoutMs, reason);
@@ skipping 22 matching lines @@
   const browser_sync::sessions::SyncSessionSnapshot *snap =
       GetLastSessionSnapshot();
   CHECK(snap);
   retry_verifier_.Initialize(*snap);
   wait_state_ = WAITING_FOR_EXPONENTIAL_BACKOFF_VERIFICATION;
   AwaitStatusChangeWithTimeout(kExponentialBackoffVerificationTimeoutMs,
       "Verify Exponential backoff");
   return (retry_verifier_.Succeeded());
 }
 
+bool ProfileSyncServiceHarness::AwaitMigration(
+    const syncable::ModelTypeSet& expected_migrated_types) {
+  VLOG(1) << GetClientInfoString("AwaitMigration");
+  VLOG(1) << profile_debug_name_ << ": waiting until migration is done for "
+          << syncable::ModelTypeSetToString(expected_migrated_types);
+  while (true) {
+    bool migration_finished =
+        std::includes(migrated_types_.begin(), migrated_types_.end(),
+                      expected_migrated_types.begin(),
+                      expected_migrated_types.end());
+    VLOG(1) << "Migrated types "
+            << syncable::ModelTypeSetToString(migrated_types_)
+            << (migration_finished ? " contains " : " does not contain ")
+            << syncable::ModelTypeSetToString(expected_migrated_types);
+    if (migration_finished) {
+      return true;
+    }
+
+    if (service()->HasPendingBackendMigration()) {
+      wait_state_ = WAITING_FOR_MIGRATION_TO_FINISH;
+    } else {
+      wait_state_ = WAITING_FOR_MIGRATION_TO_START;
+      AwaitStatusChangeWithTimeout(kLiveSyncOperationTimeoutMs,
+                                   "Wait for migration to start");
+      if (wait_state_ != WAITING_FOR_MIGRATION_TO_FINISH) {
+        VLOG(1) << profile_debug_name_
+                << ": wait state = " << wait_state_
+                << " after migration start is not "
+                << "WAITING_FOR_MIGRATION_TO_FINISH";
+        return false;
+      }
+    }
+    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(
+            "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."))
     return false;
   return partner->WaitUntilTimestampMatches(this,
       "Sync cycle completion on passive client.");
 }
 
 bool ProfileSyncServiceHarness::AwaitGroupSyncCycleCompletion(
@@ skipping 99 matching lines @@
       !service()->HasPendingBackendMigration() &&
       service()->passphrase_required_reason() !=
       sync_api::REASON_SET_PASSPHRASE_FAILED;
   VLOG(1) << GetClientInfoString(
       is_synced ? "IsSynced: true" : "IsSynced: false");
   return is_synced;
 }
 
 bool ProfileSyncServiceHarness::MatchesOtherClient(
     ProfileSyncServiceHarness* partner) {
-  if (!IsSynced())
+  // TODO(akalin): Shouldn't this with the intersection check?

[Raghu Simha, 2011/09/01 03:53:06]

Is this comment Yoda-speak? :)

[akalin, 2011/09/01 04:03:24]

Fixed!

+  // Otherwise, this function isn't symmetric.
+  if (!IsSynced()) {
+    VLOG(1) << profile_debug_name_ << ": not synced, assuming doesn't match";

[Raghu Simha, 2011/09/01 03:53:06]

This should probably be a VLOG(2), since it's a genuine possibility that the
client is not yet fully synced, and we don't want to pollute the logs with
several reps of this statement. (Ignore this comment if you've run the
integration tests with --v=1 and feel that this is really useful while
debugging)

[akalin, 2011/09/01 04:03:24]

Done.

     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(1) << profile_debug_name_ << ", " << partner->profile_debug_name_
+          << ": common types are "
+          << syncable::ModelTypeSetToString(intersection_types);
+
+  if (!intersection_types.empty() && !partner->IsSynced()) {
+    VLOG(1) << "non-empty common types and "

[Raghu Simha, 2011/09/01 03:53:06]

Same as above. This too should probably be a VLOG(2).

[akalin, 2011/09/01 04:03:24]

Done.

+            << partner->profile_debug_name_ << " isn't synced";
+    return false;
+  }
+
   for (syncable::ModelTypeSet::iterator i = intersection_types.begin();
-       i != intersection_types.end();
-       ++i) {
-    if (!partner->IsSynced() ||
-        partner->GetUpdatedTimestamp(*i) != GetUpdatedTimestamp(*i)) {
+       i != intersection_types.end(); ++i) {
+    const std::string timestamp = GetUpdatedTimestamp(*i);
+    const std::string partner_timestamp = partner->GetUpdatedTimestamp(*i);
+    if (timestamp != partner_timestamp) {
+      if (VLOG_IS_ON(1)) {
+        std::string timestamp_base64, partner_timestamp_base64;
+        if (!base::Base64Encode(timestamp, &timestamp_base64)) {
+          NOTREACHED();
+        }
+        if (!base::Base64Encode(
+                partner_timestamp, &partner_timestamp_base64)) {
+          NOTREACHED();
+        }
+        VLOG(1) << syncable::ModelTypeToString(*i) << ": "
+                << profile_debug_name_ << " timestamp = "
+                << timestamp_base64 << ", "
+                << partner->profile_debug_name_
+                << " partner timestamp = "
+                << partner_timestamp_base64;
+      }
       return false;
     }
   }
   return true;
 }
 
 const SyncSessionSnapshot*
     ProfileSyncServiceHarness::GetLastSessionSnapshot() const {
   DCHECK(service_ != NULL) << "Sync service has not yet been set up.";
   if (service_->sync_initialized()) {
@@ skipping 224 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;
 }