[Sync] - Implement isolated model association.

chrome/browser/sync/glue/model_association_manager.cc

Index: chrome/browser/sync/glue/model_association_manager.cc
diff --git a/chrome/browser/sync/glue/model_association_manager.cc b/chrome/browser/sync/glue/model_association_manager.cc
index bd74db75890f8b7f8f2d0aa2e7e87b52bf222462..4ad5bfe190b77c5bbc77861cde515ded59a9c819 100644
--- a/chrome/browser/sync/glue/model_association_manager.cc
+++ b/chrome/browser/sync/glue/model_association_manager.cc
@@ -2,6 +2,15 @@
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
+#include <algorithm>
+#include <functional>
+
+#include "base/debug/trace_event.h"
+
+#include "base/logging.h"
+#include "base/message_loop.h"
+#include "base/metrics/histogram.h"
+
 #include "chrome/browser/sync/glue/model_association_manager.h"
 
 #include "content/public/browser/browser_thread.h"
@@ -19,6 +28,11 @@ using content::BrowserThread;
 using syncable::ModelTypeSet;
 
 namespace browser_sync {
+// The amount of time we wait for a datatype to load. If the type has
+// not finished loading we move on to the next type. Once this type
+// finishes loading we will do a configure to associate this type. Note
+// that in most cases types finish loading before this timeout.
+const int64 kDataTypeLoadWaitTimeInSeconds = 120;
 namespace {
 
 static const syncable::ModelType kStartOrder[] = {
@@ -94,6 +108,24 @@ void ModelAssociationManager::Initialize(
   desired_types_ = desired_types;
   state_ = INITIAILIZED_TO_CONFIGURE;
 
+  DVLOG(1) << "ModelAssociationManager: Initializing";
+
+  // Stop the types that are still loading from the previous configuration.
+  // If they are enabled we will start them here once again.
+  for (std::vector<DataTypeController*>::const_iterator it =
+           pending_model_load_.begin();
+       it != pending_model_load_.end();
+       ++it) {
+    DVLOG(1) << "ModelAssociationManager: Stopping "
+             << (*it)->name()
+             << " before initialization";
+    (*it)->Stop();
+  }
+
+  pending_model_load_.clear();
+  waiting_to_associate_.clear();
+  currently_associating_ = NULL;
+
   // We need to calculate our |needs_start_| and |needs_stop_| list.
   GetControllersNeedingStart(&needs_start_);
   // Sort these according to kStartOrder.
@@ -112,7 +144,7 @@ void ModelAssociationManager::Initialize(
             dtc->state() == DataTypeController::RUNNING ||
             dtc->state() == DataTypeController::DISABLED)) {
       needs_stop_.push_back(dtc);
-      DVLOG(1) << "Will stop " << dtc->name();
+      DVLOG(1) << "ModelTypeToString: Will stop " << dtc->name();
     }
   }
   // Sort these according to kStartOrder.
@@ -124,12 +156,14 @@ void ModelAssociationManager::Initialize(
 void ModelAssociationManager::StartAssociationAsync() {
   DCHECK_EQ(state_, INITIAILIZED_TO_CONFIGURE);
   state_ = CONFIGURING;
+  DVLOG(1) << "ModelAssociationManager: Going to start model association";
   LoadModelForNextType();
 }
 
 void ModelAssociationManager::ResetForReconfiguration() {
   DCHECK_EQ(state_, INITIAILIZED_TO_CONFIGURE);
   state_ = IDLE;
+  DVLOG(1) << "ModelAssociationManager: Reseting for reconfiguration";
   needs_start_.clear();
   needs_stop_.clear();
   failed_datatypes_info_.clear();
@@ -137,9 +171,10 @@ void ModelAssociationManager::ResetForReconfiguration() {
 
 void ModelAssociationManager::StopDisabledTypes() {
   DCHECK_EQ(state_, INITIAILIZED_TO_CONFIGURE);
+  DVLOG(1) << "ModelAssociationManager: Stopping disabled types.";
   // Stop requested data types.
   for (size_t i = 0; i < needs_stop_.size(); ++i) {
-    DVLOG(1) << "Stopping " << needs_stop_[i]->name();
+    DVLOG(1) << "ModelAssociationManager: Stopping " << needs_stop_[i]->name();
     needs_stop_[i]->Stop();
   }
   needs_stop_.clear();
@@ -147,7 +182,10 @@ void ModelAssociationManager::StopDisabledTypes() {
 
 void ModelAssociationManager::Stop() {
   bool need_to_call_model_association_done = false;
+  DVLOG(1) << "ModelAssociationManager: Stopping MAM";
   if (state_ == CONFIGURING) {
+    DVLOG(1) << "ModelAssociationManager: In the middle of configuratio while"
+             << " stopping";
     state_ = ABORTED;
     DCHECK(currently_associating_ != NULL ||
            needs_start_.size() > 0 ||
@@ -155,6 +193,8 @@ void ModelAssociationManager::Stop() {
            waiting_to_associate_.size() > 0);
 
     if (currently_associating_) {
+      DVLOG(1) << "ModelAssociationManager: stopping "
+               << currently_associating_->name();
       currently_associating_->Stop();
     } else {
       // DTCs in other lists would be stopped below.
@@ -177,14 +217,16 @@ void ModelAssociationManager::Stop() {
     if (dtc->state() != DataTypeController::NOT_RUNNING &&
         dtc->state() != DataTypeController::STOPPING) {
       dtc->Stop();
-      DVLOG(1) << "Stopped " << dtc->name();
+      DVLOG(1) << "ModelAssociationManager: Stopped " << dtc->name();
     }
   }
 
   if (need_to_call_model_association_done) {
+    DVLOG(1) << "ModelAssociationManager: Calling OnModelAssociationDone";
     DataTypeManager::ConfigureResult result(DataTypeManager::ABORTED,
                                             desired_types_,
-                                            failed_datatypes_info_);
+                                            failed_datatypes_info_,
+                                            syncable::ModelTypeSet());
     result_processor_->OnModelAssociationDone(result);
   }
 
@@ -193,6 +235,7 @@ void ModelAssociationManager::Stop() {
 
 bool ModelAssociationManager::GetControllersNeedingStart(
     std::vector<DataTypeController*>* needs_start) {
+  DVLOG(1) << "ModelAssociationManager: GetControllersNeedingStart";
   // Add any data type controllers into the needs_start_ list that are
   // currently NOT_RUNNING or STOPPING.
   bool found_any = false;
@@ -207,7 +250,8 @@ bool ModelAssociationManager::GetControllersNeedingStart(
       if (needs_start)
         needs_start->push_back(dtc->second.get());
       if (dtc->second->state() == DataTypeController::DISABLED) {
-        DVLOG(1) << "Found " << syncable::ModelTypeToString(dtc->second->type())
+        DVLOG(1) << "ModelAssociationManager: Found "\
+                << syncable::ModelTypeToString(dtc->second->type())
                  << " in disabled state.";
       }
     }
@@ -215,14 +259,28 @@ bool ModelAssociationManager::GetControllersNeedingStart(
   return found_any;
 }
 
+void ModelAssociationManager::AppendToFailedDatatypesAndLogError(
+    DataTypeController::StartResult result,
+    const SyncError& error) {
+  failed_datatypes_info_.push_back(error);
+  LOG(ERROR) << "Failed to associate models for "
+             << syncable::ModelTypeToString(error.type());
+  UMA_HISTOGRAM_ENUMERATION("Sync.ConfigureFailed",
+                            error.type(),
+                            syncable::MODEL_TYPE_COUNT);
+}
+
 void ModelAssociationManager::TypeStartCallback(
     DataTypeController::StartResult result,
     const SyncError& error) {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
 
+  DVLOG(1) << "ModelAssociationManager: TypeStartCallback";
   if (state_ == ABORTED) {
     // Now that we have finished with the current type we can stop
     // if abort was called.
+    DVLOG(1) << "ModelAssociationManager: Doing an early return"
+             << " because of abort";
     state_ = IDLE;
     return;
   }
@@ -234,12 +292,8 @@ void ModelAssociationManager::TypeStartCallback(
   currently_associating_ = NULL;
 
   if (result == DataTypeController::ASSOCIATION_FAILED) {
-    failed_datatypes_info_.push_back(error);
-    LOG(ERROR) << "Failed to associate models for "
-               << syncable::ModelTypeToString(error.type());
-    UMA_HISTOGRAM_ENUMERATION("Sync.ConfigureFailed",
-                              error.type(),
-                              syncable::MODEL_TYPE_COUNT);
+    DVLOG(1) << "ModelAssociationManager: Encountered a failed type";
+    AppendToFailedDatatypesAndLogError(result, error);
   }
 
   // If the type started normally, continue to the next type.
@@ -250,6 +304,8 @@ void ModelAssociationManager::TypeStartCallback(
       result == DataTypeController::OK ||
       result == DataTypeController::OK_FIRST_RUN ||
       result == DataTypeController::ASSOCIATION_FAILED) {
+    DVLOG(1) << "ModelAssociationManager: type start callback returned "
+             << result << " so calling LoadModelForNextType";
     LoadModelForNextType();
     return;
   }
@@ -280,24 +336,34 @@ void ModelAssociationManager::TypeStartCallback(
 
   DataTypeManager::ConfigureResult configure_result(configure_status,
                                                     desired_types_,
-                                                    errors);
+                                                    errors,
+                                                    syncable::ModelTypeSet());
   result_processor_->OnModelAssociationDone(configure_result);
 }
 
 void ModelAssociationManager::LoadModelForNextType() {
+  DVLOG(1) << "ModelAssociationManager: LoadModelForNextType";
   if (!needs_start_.empty()) {
-    DVLOG(1) << "Starting " << needs_start_[0]->name();
+    DVLOG(1) << "ModelAssociationManager: Starting " << needs_start_[0]->name();
 
     DataTypeController* dtc = needs_start_[0];
     needs_start_.erase(needs_start_.begin());
     // Move from |needs_start_| to |pending_model_load_|.
-    pending_model_load_.push_back(dtc);
+    pending_model_load_.insert(pending_model_load_.begin(), dtc);
+    timer_.Start(FROM_HERE,
+                 base::TimeDelta::FromSeconds(kDataTypeLoadWaitTimeInSeconds),
+                 this,
+                 &ModelAssociationManager::LoadModelForNextType);
     dtc->LoadModels(base::Bind(
         &ModelAssociationManager::ModelLoadCallback,
         weak_ptr_factory_.GetWeakPtr()));
+
     return;
   }
 
+  DVLOG(1) << "ModelAssociationManager: All types have models loaded."
+          << "Moving on to StartAssociatingNextType.";
+
   // If all controllers have their |LoadModels| invoked then pass onto
   // |StartAssociatingNextType|.
   StartAssociatingNextType();
@@ -305,37 +371,68 @@ void ModelAssociationManager::LoadModelForNextType() {
 
 void ModelAssociationManager::ModelLoadCallback(
     syncable::ModelType type, SyncError error) {
-  DCHECK_EQ(state_, CONFIGURING);
-
-  for (std::vector<DataTypeController*>::iterator it =
-           pending_model_load_.begin();
-        it != pending_model_load_.end();
-        ++it) {
-    if ((*it)->type() == type) {
-      DataTypeController* dtc = *it;
-      pending_model_load_.erase(it);
-      if (!error.IsSet()) {
-        waiting_to_associate_.push_back(dtc);
-        StartAssociatingNextType();
-        } else {
-        // Treat it like a regular error.
-        DCHECK(currently_associating_ == NULL);
-        currently_associating_ = dtc;
-        TypeStartCallback(DataTypeController::ASSOCIATION_FAILED, error);
+  DVLOG(1) << "ModelAssociationManager: ModelLoadCallback for "
+          << syncable::ModelTypeToString(type);
+  if (state_ == CONFIGURING) {
+    DVLOG(1) << "ModelAssociationManager: ModelLoadCallback while configuring";
+    for (std::vector<DataTypeController*>::iterator it =
+             pending_model_load_.begin();
+          it != pending_model_load_.end();
+          ++it) {
+      if ((*it)->type() == type) {
+        // Each type is given |kDataTypeLoadWaitTimeInSeconds| time to load
+        // (as controlled by the timer.). If the type does not load in that
+        // time we move on to the next type. However if the type does
+        // finish loading in that time we want to stop the timer. We stop
+        // the timer, if the type that loaded is the same as the type that
+        // we started the timer for(as indicated by the type on the head
+        // of the list).
+        // Note: Regardless of this timer value the associations will always
+        // take place serially. The only thing this timer controls is how serial
+        // the model load is. If this timer has a value of zero seconds then
+        // the model loads will all be parallel.
+        if (it == pending_model_load_.begin()) {
+          DVLOG(1) << "ModelAssociationManager: Stopping timer";
+          timer_.Stop();
+        }
+        DataTypeController* dtc = *it;
+        pending_model_load_.erase(it);
+        if (!error.IsSet()) {
+          DVLOG(1) << "ModelAssociationManager:"
+                  << " Calling StartAssociatingNextType";
+          waiting_to_associate_.push_back(dtc);
+          StartAssociatingNextType();
+       } else {
+         DVLOG(1) << "ModelAssociationManager: Encountered error loading";
+         // Treat it like a regular error.
+         AppendToFailedDatatypesAndLogError(
+             DataTypeController::ASSOCIATION_FAILED,
+             error);
+       }
+       return;
       }
-     return;
     }
+    NOTREACHED();
+    return;
+  } else {
+    DVLOG(1) << "ModelAssociationManager: Models loaded after configure cycle"
+            << "Informing DTM";
+    // This datatype finished loading after the deadline imposed by the
+    // originating configuration cycle. Inform the DataTypeManager that the
+    // type has loaded, so that association may begin.
+    result_processor_->OnTypesLoaded();
   }
 
-  NOTREACHED();
 }
 
-
 void ModelAssociationManager::StartAssociatingNextType() {
   DCHECK_EQ(state_, CONFIGURING);
   DCHECK_EQ(currently_associating_, static_cast<DataTypeController*>(NULL));
+
+  DVLOG(1) << "ModelAssociationManager: StartAssociatingNextType";
   if (!waiting_to_associate_.empty()) {
-    DVLOG(1) << "Starting " << waiting_to_associate_[0]->name();
+    DVLOG(1) << "ModelAssociationManager: Starting "
+            << waiting_to_associate_[0]->name();
     TRACE_EVENT_BEGIN1("sync", "ModelAssociation",
                        "DataType",
                        ModelTypeToString(waiting_to_associate_[0]->type()));
@@ -354,28 +451,53 @@ void ModelAssociationManager::StartAssociatingNextType() {
   // things like encryption, which may still need to be sorted out before we
   // can announce we're "Done" configuration entirely.
   if (GetControllersNeedingStart(NULL)) {
-    DVLOG(1) << "GetControllersNeedingStart returned true."
-             << " Blocking DataTypeManager";
+    DVLOG(1) << "ModelAssociationManager: GetControllersNeedingStart"
+             << " returned true. Blocking DataTypeManager";
 
     DataTypeManager::ConfigureResult configure_result(
         DataTypeManager::CONFIGURE_BLOCKED,
         desired_types_,
-        failed_datatypes_info_);
+        failed_datatypes_info_,
+        syncable::ModelTypeSet());
     state_ = IDLE;
     result_processor_->OnModelAssociationDone(configure_result);
     return;
   }
 
   DataTypeManager::ConfigureStatus configure_status = DataTypeManager::OK;
-  if (!failed_datatypes_info_.empty())
+
+  if (!failed_datatypes_info_.empty() ||
+      !GetTypesWaitingToLoad().Empty()) {
+    // We have not configured all types that we have been asked to configure.
+    // Either we have failed types or types that have not completed loading
+    // yet.
+    DVLOG(1) << "ModelAssociationManager: setting partial success";
     configure_status = DataTypeManager::PARTIAL_SUCCESS;
+  }
 
   DataTypeManager::ConfigureResult result(configure_status,
                                           desired_types_,
-                                          failed_datatypes_info_);
+                                          failed_datatypes_info_,
+                                          GetTypesWaitingToLoad());
   result_processor_->OnModelAssociationDone(result);
   return;
 }
 
+syncable::ModelTypeSet ModelAssociationManager::GetTypesWaitingToLoad() {
+  syncable::ModelTypeSet result;
+  for (std::vector<DataTypeController*>::const_iterator it =
+           pending_model_load_.begin();
+       it != pending_model_load_.end();
+       ++it) {
+    result.Put((*it)->type());
+  }
+  return result;
+}
+
+base::OneShotTimer<ModelAssociationManager>*
+    ModelAssociationManager::GetTimerForTesting() {
+  return &timer_;
+}
+
 }  // namespace browser_sync