[Sync] Make BackendMigrator not wait for full sync cycles

chrome/browser/sync/glue/sync_backend_host.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 "build/build_config.h"
 
 #include "chrome/browser/sync/glue/sync_backend_host.h"
 
 #include <algorithm>
 #include <map>
 
 #include "base/bind.h"
 #include "base/command_line.h"
 #include "base/compiler_specific.h"
 #include "base/file_util.h"
 #include "base/task.h"
 #include "base/threading/thread_restrictions.h"
 #include "base/tracked.h"
 #include "base/utf_string_conversions.h"
 #include "chrome/browser/net/gaia/token_service.h"
 #include "chrome/browser/prefs/pref_service.h"
 #include "chrome/browser/profiles/profile.h"
 #include "chrome/browser/sync/glue/change_processor.h"
 #include "chrome/browser/sync/glue/http_bridge.h"
 #include "chrome/browser/sync/internal_api/base_transaction.h"
+#include "chrome/browser/sync/internal_api/read_transaction.h"
 #include "chrome/browser/sync/internal_api/sync_manager.h"
 #include "chrome/browser/sync/glue/sync_backend_registrar.h"
 #include "chrome/browser/sync/notifier/sync_notifier.h"
+#include "chrome/browser/sync/protocol/sync.pb.h"
 #include "chrome/browser/sync/sessions/session_state.h"
 // TODO(tim): Remove this! We should have a syncapi pass-thru instead.
 #include "chrome/browser/sync/syncable/directory_manager.h"  // Cryptographer.
 #include "chrome/common/chrome_notification_types.h"
 #include "chrome/common/chrome_version_info.h"
 #include "chrome/common/net/gaia/gaia_constants.h"
 #include "chrome/common/pref_names.h"
 #include "content/browser/browser_thread.h"
 #include "content/common/notification_service.h"
 #include "webkit/glue/webkit_glue.h"
 
 static const int kSaveChangesIntervalSeconds = 10;
 static const FilePath::CharType kSyncDataFolderName[] =
     FILE_PATH_LITERAL("Sync Data");
 
 typedef TokenService::TokenAvailableDetails TokenAvailableDetails;
 
 typedef GoogleServiceAuthError AuthError;
 
 namespace browser_sync {
 
 using sessions::SyncSessionSnapshot;
 using sync_api::SyncCredentials;
 
-SyncBackendHost::SyncBackendHost(Profile* profile)
-    : core_(new Core(profile,
-                     ALLOW_THIS_IN_INITIALIZER_LIST(this))),
+// Helper macros to log with the syncer thread name; useful when there
+// are multiple syncers involved.
+
+#define SLOG(severity) LOG(severity) << name_ << ": "
+
+#define SVLOG(verbose_level) VLOG(verbose_level) << name_ << ": "
+
+SyncBackendHost::SyncBackendHost(const std::string& name, Profile* profile)
+    : core_(new Core(name, ALLOW_THIS_IN_INITIALIZER_LIST(this))),
       initialization_state_(NOT_INITIALIZED),
       sync_thread_("Chrome_SyncThread"),
       frontend_loop_(MessageLoop::current()),
       profile_(profile),
+      name_(name),
       sync_notifier_factory_(webkit_glue::GetUserAgent(GURL()),
                              profile_->GetRequestContext(),
                              *CommandLine::ForCurrentProcess()),
       frontend_(NULL),
       sync_data_folder_path_(
           profile_->GetPath().Append(kSyncDataFolderName)),
       last_auth_error_(AuthError::None()) {
 }
 
 SyncBackendHost::SyncBackendHost()
     : initialization_state_(NOT_INITIALIZED),
       sync_thread_("Chrome_SyncThread"),
       frontend_loop_(MessageLoop::current()),
       profile_(NULL),
+      name_("Unknown"),
       sync_notifier_factory_(webkit_glue::GetUserAgent(GURL()),
                              NULL,
                              *CommandLine::ForCurrentProcess()),
       frontend_(NULL),
       last_auth_error_(AuthError::None()) {
 }
 
 SyncBackendHost::~SyncBackendHost() {
   DCHECK(!core_ && !frontend_) << "Must call Shutdown before destructor.";
   DCHECK(!registrar_.get());
@@ skipping 10 matching lines @@
     return;
 
   frontend_ = frontend;
   DCHECK(frontend);
 
   syncable::ModelTypeSet initial_types_with_nigori(initial_types);
   if (profile_->GetPrefs()->GetBoolean(prefs::kSyncHasSetupCompleted))
     initial_types_with_nigori.insert(syncable::NIGORI);
 
   registrar_.reset(new SyncBackendRegistrar(initial_types_with_nigori,
+                                            name_,
                                             profile_,
                                             sync_thread_.message_loop()));
 
   InitCore(Core::DoInitializeOptions(
       registrar_.get(),
       event_handler,
       sync_service_url,
       profile_->GetRequestContext(),
       credentials,
       delete_sync_data_folder,
@@ skipping 52 matching lines @@
 }
 
 void SyncBackendHost::UpdateCredentials(const SyncCredentials& credentials) {
   sync_thread_.message_loop()->PostTask(FROM_HERE,
       NewRunnableMethod(core_.get(),
                         &SyncBackendHost::Core::DoUpdateCredentials,
                         credentials));
 }
 
 void SyncBackendHost::StartSyncingWithServer() {
-  VLOG(1) << "SyncBackendHost::StartSyncingWithServer called.";
+  SVLOG(1) << "SyncBackendHost::StartSyncingWithServer called.";
   sync_thread_.message_loop()->PostTask(FROM_HERE,
       NewRunnableMethod(core_.get(), &SyncBackendHost::Core::DoStartSyncing));
 }
 
 void SyncBackendHost::SetPassphrase(const std::string& passphrase,
                                     bool is_explicit) {
   if (!IsNigoriEnabled()) {
-    LOG(WARNING) << "Silently dropping SetPassphrase request.";
+    SLOG(WARNING) << "Silently dropping SetPassphrase request.";
     return;
   }
 
   // This should only be called by the frontend.
   DCHECK_EQ(MessageLoop::current(), frontend_loop_);
   if (core_->processing_passphrase()) {
-    VLOG(1) << "Attempted to call SetPassphrase while already waiting for "
-            << " result from previous SetPassphrase call. Silently dropping.";
+    SVLOG(1) << "Attempted to call SetPassphrase while already waiting for "
+             << " result from previous SetPassphrase call. Silently dropping.";
     return;
   }
   core_->set_processing_passphrase();
 
   // If encryption is enabled and we've got a SetPassphrase
   sync_thread_.message_loop()->PostTask(FROM_HERE,
       NewRunnableMethod(core_.get(), &SyncBackendHost::Core::DoSetPassphrase,
                         passphrase, is_explicit));
 }
 
@@ skipping 72 matching lines @@
   pending_config_mode_state_->ready_task = ready_task;
   pending_config_mode_state_->types_to_add = types_to_add_with_nigori;
   pending_config_mode_state_->added_types =
       registrar_->ConfigureDataTypes(types_to_add_with_nigori,
                                      types_to_remove_with_nigori);
   pending_config_mode_state_->reason = reason;
 
   // Cleanup disabled types before starting configuration so that
   // callers can assume that the data types are cleaned up once
   // configuration is done.
-  if (!types_to_remove.empty()) {
+  if (!types_to_remove_with_nigori.empty()) {
     sync_thread_.message_loop()->PostTask(
         FROM_HERE,
         NewRunnableMethod(
             core_.get(),
             &SyncBackendHost::Core::DoRequestCleanupDisabledTypes));
   }
 
   StartConfiguration(NewCallback(core_.get(),
       &SyncBackendHost::Core::FinishConfigureDataTypes));
 }
@@ skipping 12 matching lines @@
   //
   // Deletions need a nudge in order to ensure the deletion occurs in a timely
   // manner (see issue 56416).
   //
   // In the case of additions, on the next sync cycle, the syncer should
   // notice that the routing info has changed and start the process of
   // downloading updates for newly added data types.  Once this is
   // complete, the configure_state_.ready_task_ is run via an
   // OnInitializationComplete notification.
 
-  VLOG(1) << "Syncer in config mode. SBH executing"
-          << "FinishConfigureDataTypesOnFrontendLoop";
+  SVLOG(1) << "Syncer in config mode. SBH executing "
+           << "FinishConfigureDataTypesOnFrontendLoop";
 
   if (pending_config_mode_state_->added_types.empty() &&
       !core_->sync_manager()->InitialSyncEndedForAllEnabledTypes()) {
-    LOG(WARNING) << "No new types, but initial sync not finished."
-                 << "Possible sync db corruption / removal.";
+    SLOG(WARNING) << "No new types, but initial sync not finished."
+                  << "Possible sync db corruption / removal.";
     // TODO(tim): Log / UMA / count this somehow?
     // TODO(tim): If no added types, we could (should?) config only for
     // types that are needed... but this is a rare corruption edge case or
     // implies the user mucked around with their syncdb, so for now do all.
     pending_config_mode_state_->added_types =
         pending_config_mode_state_->types_to_add;
   }
 
   // If we've added types, we always want to request a nudge/config (even if
   // the initial sync is ended), in case we could not decrypt the data.
   if (pending_config_mode_state_->added_types.empty()) {
-    VLOG(1) << "SyncBackendHost(" << this << "): No new types added. "
-            << "Calling ready_task directly";
+    SVLOG(1) << "No new types added; calling ready_task directly";
     // No new types - just notify the caller that the types are available.
     pending_config_mode_state_->ready_task.Run(true);
   } else {
     pending_download_state_.reset(pending_config_mode_state_.release());
 
     // Always configure nigori if it's enabled.
     syncable::ModelTypeSet types_to_config =
         pending_download_state_->added_types;
     if (IsNigoriEnabled()) {
       types_to_config.insert(syncable::NIGORI);
     }
-    VLOG(1) <<  "SyncBackendHost(" << this << "):New Types added. "
-            << "Calling DoRequestConfig";
+    SVLOG(1) << "Types " << ModelTypeSetToString(types_to_config)
+            << " added; calling DoRequestConfig";
     sync_thread_.message_loop()->PostTask(FROM_HERE,
          NewRunnableMethod(core_.get(),
                            &SyncBackendHost::Core::DoRequestConfig,
                            syncable::ModelTypeBitSetFromSet(types_to_config),
                            pending_download_state_->reason));
   }
 
   pending_config_mode_state_.reset();
 
   // Notify the SyncManager about the new types.
@@ skipping 41 matching lines @@
   if (!host_ || !host_->frontend_)
     return;
 
   DCHECK_EQ(MessageLoop::current(), host_->frontend_loop_);
 
   // When setting a passphrase fails, unset our waiting flag.
   if (reason == sync_api::REASON_SET_PASSPHRASE_FAILED)
     processing_passphrase_ = false;
 
   if (processing_passphrase_) {
-    VLOG(1) << "Core received OnPassphraseRequired while processing a "
-            << "passphrase. Silently dropping.";
+    SVLOG(1) << "Core received OnPassphraseRequired while processing a "
+             << "passphrase. Silently dropping.";
     return;
   }
 
   host_->frontend_->OnPassphraseRequired(reason);
 }
 
 void SyncBackendHost::Core::NotifyPassphraseAccepted(
     const std::string& bootstrap_token) {
   if (!host_ || !host_->frontend_)
     return;
 
   DCHECK_EQ(MessageLoop::current(), host_->frontend_loop_);
 
   processing_passphrase_ = false;
   host_->PersistEncryptionBootstrapToken(bootstrap_token);
   host_->frontend_->OnPassphraseAccepted();
 }
 
 void SyncBackendHost::Core::NotifyUpdatedToken(const std::string& token) {
   if (!host_)
     return;
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
   TokenAvailableDetails details(GaiaConstants::kSyncService, token);
   NotificationService::current()->Notify(
       chrome::NOTIFICATION_TOKEN_UPDATED,
-      Source<Profile>(profile_),
+      Source<Profile>(host_->profile_),
       Details<const TokenAvailableDetails>(&details));
 }
 
 void SyncBackendHost::Core::NotifyEncryptionComplete(
     const syncable::ModelTypeSet& encrypted_types) {
   if (!host_)
     return;
   DCHECK_EQ(MessageLoop::current(), host_->frontend_loop_);
   host_->frontend_->OnEncryptionComplete(encrypted_types);
 }
@@ skipping 61 matching lines @@
 bool SyncBackendHost::HasUnsyncedItems() const {
   DCHECK(initialized());
   return core_->sync_manager()->HasUnsyncedItems();
 }
 
 void SyncBackendHost::LogUnsyncedItems(int level) const {
   DCHECK(initialized());
   return core_->sync_manager()->LogUnsyncedItems(level);
 }
 
-SyncBackendHost::Core::Core(Profile* profile, SyncBackendHost* backend)
-    : profile_(profile),
+SyncBackendHost::Core::Core(const std::string& name,
+                            SyncBackendHost* backend)
+    : name_(name),
       host_(backend),
       registrar_(NULL),
       processing_passphrase_(false) {
   DCHECK(host_);
 }
 
 // Helper to construct a user agent string (ASCII) suitable for use by
 // the syncapi for any HTTP communication. This string is used by the sync
 // backend for classifying client types when calculating statistics.
 std::string MakeUserAgentForSyncApi() {
@@ skipping 35 matching lines @@
 
   // Make sure that the directory exists before initializing the backend.
   // If it already exists, this will do no harm.
   bool success = file_util::CreateDirectory(host_->sync_data_folder_path());
   DCHECK(success);
 
   DCHECK(!registrar_);
   registrar_ = options.registrar;
   DCHECK(registrar_);
 
-  sync_manager_.reset(new sync_api::SyncManager(profile_->GetDebugName())),
+  sync_manager_.reset(new sync_api::SyncManager(name_));
   sync_manager_->AddObserver(this);
   const FilePath& path_str = host_->sync_data_folder_path();
   success = sync_manager_->Init(
       path_str,
       options.event_handler,
       options.service_url.host() + options.service_url.path(),
       options.service_url.EffectiveIntPort(),
       options.service_url.SchemeIsSecure(),
       host_->MakeHttpBridgeFactory(options.request_context_getter),
       options.registrar,
@@ skipping 109 matching lines @@
 }
 
 void SyncBackendHost::Core::HandleSyncCycleCompletedOnFrontendLoop(
     SyncSessionSnapshot* snapshot) {
   if (!host_ || !host_->frontend_)
     return;
   DCHECK_EQ(MessageLoop::current(), host_->frontend_loop_);
 
   host_->last_snapshot_.reset(snapshot);
 
+  SVLOG(1) << "Got snapshot " << snapshot->ToString();
+
   const syncable::ModelTypeSet& to_migrate =
       snapshot->syncer_status.types_needing_local_migration;
   if (!to_migrate.empty())
     host_->frontend_->OnMigrationNeededForTypes(to_migrate);
 
   // Process any changes to the datatypes we're syncing.
   // TODO(sync): add support for removing types.
   syncable::ModelTypeSet to_add;
   if (host_->initialized() &&
       sync_manager()->ReceivedExperimentalTypes(&to_add)) {
     host_->frontend_->OnDataTypesChanged(to_add);
   }
 
   // If we are waiting for a configuration change, check here to see
   // if this sync cycle has initialized all of the types we've been
   // waiting for.
   if (host_->pending_download_state_.get()) {
     scoped_ptr<PendingConfigureDataTypesState> state(
         host_->pending_download_state_.release());
     DCHECK(
         std::includes(state->types_to_add.begin(), state->types_to_add.end(),
                       state->added_types.begin(), state->added_types.end()));
+    SVLOG(1)
+        << "Added types: "
+        << syncable::ModelTypeSetToString(state->added_types)
+        << ", configured types: "
+        << syncable::ModelTypeBitSetToString(snapshot->initial_sync_ended);
     syncable::ModelTypeBitSet added_types =
         syncable::ModelTypeBitSetFromSet(state->added_types);
     bool found_all_added =
         (added_types & snapshot->initial_sync_ended) == added_types;
     state->ready_task.Run(found_all_added);
     if (!found_all_added)
       return;
   }
 
   if (host_->initialized())
@@ skipping 151 matching lines @@
   sync_manager_->RequestCleanupDisabledTypes();
 }
 
 void SyncBackendHost::Core::SaveChanges() {
   sync_manager_->SaveChanges();
 }
 
 void SyncBackendHost::Core::DeleteSyncDataFolder() {
   if (file_util::DirectoryExists(host_->sync_data_folder_path())) {
     if (!file_util::Delete(host_->sync_data_folder_path(), true))
-      LOG(DFATAL) << "Could not delete the Sync Data folder.";
+      SLOG(DFATAL) << "Could not delete the Sync Data folder.";
   }
 }
 
+#undef SVLOG
+
+#undef SLOG
+
 }  // namespace browser_sync