[Sync] - Implement isolated model association.

chrome/browser/sync/glue/model_association_manager.cc

 // Copyright (c) 2012 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 <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"
 #include <algorithm>
 #include <functional>
 
 #include "base/debug/trace_event.h"
 
 #include "base/logging.h"
 #include "base/message_loop.h"
 #include "base/metrics/histogram.h"
 
 
 using content::BrowserThread;
 using syncable::ModelTypeSet;
 
 namespace browser_sync {
+const int64 kDataTypeLoadWaitTimeInSeconds = 120;

[tim (not reviewing), 2012/05/22 16:50:05]

Comment. 

[lipalani1, 2012/05/22 20:20:46]

Done.

 namespace {
 
 static const syncable::ModelType kStartOrder[] = {
   syncable::NIGORI,  //  Listed for completeness.
   syncable::BOOKMARKS,
   syncable::PREFERENCES,
   syncable::AUTOFILL,
   syncable::AUTOFILL_PROFILE,
   syncable::EXTENSION_SETTINGS,
   syncable::EXTENSIONS,
@@ skipping 55 matching lines @@
 
 void ModelAssociationManager::Initialize(
     syncable::ModelTypeSet desired_types) {
   DCHECK_EQ(state_, IDLE);
   needs_start_.clear();
   needs_stop_.clear();
   failed_datatypes_info_.clear();
   desired_types_ = desired_types;
   state_ = INITIAILIZED_TO_CONFIGURE;
 
+  VLOG(0) << "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) {
+    VLOG(0) << "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.
   std::sort(needs_start_.begin(),
             needs_start_.end(),
             SortComparator(&start_order_));
 
   // Add any data type controllers into that needs_stop_ list that are
   // currently MODEL_STARTING, ASSOCIATING, RUNNING or DISABLED.
   for (DataTypeController::TypeMap::const_iterator it = controllers_->begin();
        it != controllers_->end(); ++it) {
     DataTypeController* dtc = (*it).second;
     if (!desired_types.Has(dtc->type()) && (
             dtc->state() == DataTypeController::MODEL_STARTING ||
             dtc->state() == DataTypeController::ASSOCIATING ||
             dtc->state() == DataTypeController::RUNNING ||
             dtc->state() == DataTypeController::DISABLED)) {
       needs_stop_.push_back(dtc);
-      DVLOG(1) << "Will stop " << dtc->name();
+      VLOG(0) << "ModelTypeToString: Will stop " << dtc->name();
     }
   }
   // Sort these according to kStartOrder.
   std::sort(needs_stop_.begin(),
             needs_stop_.end(),
             SortComparator(&start_order_));
 }
 
 void ModelAssociationManager::StartAssociationAsync() {
   DCHECK_EQ(state_, INITIAILIZED_TO_CONFIGURE);
   state_ = CONFIGURING;
+  VLOG(0) << "ModelAssociationManager: Going to start model association";
   LoadModelForNextType();
 }
 
 void ModelAssociationManager::ResetForReconfiguration() {
   DCHECK_EQ(state_, INITIAILIZED_TO_CONFIGURE);
   state_ = IDLE;
+  VLOG(0) << "ModelAssociationManager: Reseting for reconfiguration";
   needs_start_.clear();
   needs_stop_.clear();
   failed_datatypes_info_.clear();
 }
 
 void ModelAssociationManager::StopDisabledTypes() {
   DCHECK_EQ(state_, INITIAILIZED_TO_CONFIGURE);
+  VLOG(0) << "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();
+    VLOG(0) << "ModelAssociationManager: Stopping " << needs_stop_[i]->name();
     needs_stop_[i]->Stop();
   }
   needs_stop_.clear();
 }
 
 void ModelAssociationManager::Stop() {
   bool need_to_call_model_association_done = false;
+  VLOG(0) << "ModelAssociationManager: Stopping MAM";
   if (state_ == CONFIGURING) {
+    VLOG(0) << "ModelAssociationManager: In the middle of configuratio while"
+            << " stopping";
     state_ = ABORTED;
     DCHECK(currently_associating_ != NULL ||
            needs_start_.size() > 0 ||
            pending_model_load_.size() > 0 ||
            waiting_to_associate_.size() > 0);
 
     if (currently_associating_) {
+      VLOG(0) << "ModelAssociationManager: stopping "
+              << currently_associating_->name();
       currently_associating_->Stop();
     } else {
       // DTCs in other lists would be stopped below.
       state_ = IDLE;
     }
 
     DCHECK_EQ(IDLE, state_);
 
     // We are in the midle of model association. We need to inform the caller
     // so the caller can send notificationst to PSS layer.
     need_to_call_model_association_done = true;
   }
 
   // Now continue stopping any types that have already started.
   DCHECK(state_ == IDLE ||
          state_ == INITIAILIZED_TO_CONFIGURE);
   for (DataTypeController::TypeMap::const_iterator it = controllers_->begin();
        it != controllers_->end(); ++it) {
     DataTypeController* dtc = (*it).second;
     if (dtc->state() != DataTypeController::NOT_RUNNING &&
         dtc->state() != DataTypeController::STOPPING) {
       dtc->Stop();
-      DVLOG(1) << "Stopped " << dtc->name();
+      VLOG(0) << "ModelAssociationManager: Stopped " << dtc->name();
     }
   }
 
   if (need_to_call_model_association_done) {
+    VLOG(0) << "ModelAssociationManager: Calling OnModelAssociationDone";
     DataTypeManager::ConfigureResult result(DataTypeManager::ABORTED,
                                             desired_types_,
-                                            failed_datatypes_info_);
+                                            failed_datatypes_info_,
+                                            syncable::ModelTypeSet());
     result_processor_->OnModelAssociationDone(result);
   }
 
   failed_datatypes_info_.clear();
 }
 
 bool ModelAssociationManager::GetControllersNeedingStart(
     std::vector<DataTypeController*>* needs_start) {
+  VLOG(0) << "ModelAssociationManager: GetControllersNeedingStart";
   // Add any data type controllers into the needs_start_ list that are
   // currently NOT_RUNNING or STOPPING.
   bool found_any = false;
   for (ModelTypeSet::Iterator it = desired_types_.First();
        it.Good(); it.Inc()) {
     DataTypeController::TypeMap::const_iterator dtc =
         controllers_->find(it.Get());
     if (dtc != controllers_->end() &&
         (dtc->second->state() == DataTypeController::NOT_RUNNING ||
          dtc->second->state() == DataTypeController::STOPPING)) {
       found_any = true;
       if (needs_start)
         needs_start->push_back(dtc->second.get());
       if (dtc->second->state() == DataTypeController::DISABLED) {
-        DVLOG(1) << "Found " << syncable::ModelTypeToString(dtc->second->type())
+        VLOG(0) << "ModelAssociationManager: Found "\
+                << syncable::ModelTypeToString(dtc->second->type())
                  << " in disabled state.";
       }
     }
   }
   return found_any;
 }
 
+void ModelAssociationManager::HandleFailedTypes(

[tim (not reviewing), 2012/05/22 16:50:05]

Is this called for failures other than associations?  If not
HandleFailedAssociations(...) would be a better name, since it's unclear what
steps "failed types" refers to.

[lipalani1, 2012/05/22 20:20:46]

It is refactored so it could be called to handle load failure and association
failure. I dont see any reason for differentiating them. The SyncError struct
would have the detailed information which gets displayed in about:sync(that code
is already there).
On 2012/05/22 16:50:05, timsteele wrote:

+    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));
 
+  VLOG(0) << "ModelAssociationManager: TypeStartCallback";
   if (state_ == ABORTED) {
     // Now that we have finished with the current type we can stop
     // if abort was called.
+    VLOG(0) << "ModelAssociationManager: Doing an early return"
+            << " because of abort";
     state_ = IDLE;
     return;
   }
 
   DCHECK(state_ == CONFIGURING);
 
   // We are done with this type. Clear it.
   DataTypeController* started_dtc = currently_associating_;
   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);
+    VLOG(0) << "ModelAssociationManager: Encountered a failed type";
+    HandleFailedTypes(result, error);
   }
 
   // If the type started normally, continue to the next type.
   // If the type is waiting for the cryptographer, continue to the next type.
   // Once the cryptographer is ready, we'll attempt to restart this type.
   // If this type encountered a type specific error continue to the next type.
   if (result == DataTypeController::NEEDS_CRYPTO ||
       result == DataTypeController::OK ||
       result == DataTypeController::OK_FIRST_RUN ||
       result == DataTypeController::ASSOCIATION_FAILED) {
+    VLOG(0) << "ModelAssociationManager: type start callback returned "
+            << result << " so calling LoadModelForNextType";
     LoadModelForNextType();
     return;
   }
 
   // Any other result requires reconfiguration. Pass it on through the callback.
   LOG(ERROR) << "Failed to configure " << started_dtc->name();
   DCHECK(error.IsSet());
   DCHECK_EQ(started_dtc->type(), error.type());
   DataTypeManager::ConfigureStatus configure_status =
       DataTypeManager::ABORTED;
@@ skipping 10 matching lines @@
   }
 
   std::list<SyncError> errors;
   errors.push_back(error);
 
   // Put our state to idle.
   state_ = IDLE;
 
   DataTypeManager::ConfigureResult configure_result(configure_status,
                                                     desired_types_,
-                                                    errors);
+                                                    errors,
+                                                    syncable::ModelTypeSet());
   result_processor_->OnModelAssociationDone(configure_result);
 }
 
 void ModelAssociationManager::LoadModelForNextType() {
+  VLOG(0) << "ModelAssociationManager: LoadModelForNextType";
   if (!needs_start_.empty()) {
-    DVLOG(1) << "Starting " << needs_start_[0]->name();
+    VLOG(0) << "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::ModelLoadTimedOut);
     dtc->LoadModels(base::Bind(
         &ModelAssociationManager::ModelLoadCallback,
         weak_ptr_factory_.GetWeakPtr()));
+
     return;
   }
 
+  VLOG(0) << "ModelAssociationManager: All types have models loaded."
+          << "Moving on to StartAssociatingNextType.";
+
   // If all controllers have their |LoadModels| invoked then pass onto
   // |StartAssociatingNextType|.
   StartAssociatingNextType();
 }
 
 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);
+  VLOG(0) << "ModelAssociationManager: ModelLoadCallback for "
+          << syncable::ModelTypeToString(type);
+  if (state_ == CONFIGURING) {
+    VLOG(0) << "ModelAssociationManager: ModelLoadCallback while configuring";
+    for (std::vector<DataTypeController*>::iterator it =
+             pending_model_load_.begin();
+          it != pending_model_load_.end();
+          ++it) {
+      if ((*it)->type() == type) {
+        // If the type that just finsihed loading was the last type to start,
+        // we can safely stop the timer. This is because the types are loaded
+        // serially.(Except when the type loading takes more than the alloted

[tim (not reviewing), 2012/05/22 16:50:05]

nit- Space after period, and 'alloted' -> 'allotted'. 

Actually your edit was a case I hadn't thought of. I think this might be clearer
worded as:

"... because the types are loaded serially while the timer is running.  If the
timer expires (because at least one type took longer than
kDataTypeLoadWaitTimeSeconds to load), we can have multiple types loading in
parallel, but they are no longer timed."

[lipalani1, 2012/05/22 20:20:46]

I think I have reworded this now. Please take a look. I want to make sure you
are not confused by this. As this timer is relatively insignificant.
On 2012/05/22 16:50:05, timsteele wrote:

+        // amount of time in which case we can have 2 or more types loading
+        // in parallel.)
+        if (it == pending_model_load_.begin()) {
+          VLOG(0) << "ModelAssociationManager: Stopping timer";
+          timer_.Stop();
+        }
+        DataTypeController* dtc = *it;
+        pending_model_load_.erase(it);
+        if (!error.IsSet()) {
+          VLOG(0) << "ModelAssociationManager:"
+                  << " Calling StartAssociatingNextType";
+          waiting_to_associate_.push_back(dtc);
+          StartAssociatingNextType();
+       } else {
+         VLOG(0) << "ModelAssociationManager: Encountered error loading";
+         // Treat it like a regular error.
+         HandleFailedTypes(DataTypeController::ASSOCIATION_FAILED, error);
+       }
+       return;
       }
-     return;
     }
+    NOTREACHED();
+    return;
+  } else {
+    VLOG(0) << "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));
+
+  VLOG(0) << "ModelAssociationManager: StartAssociatingNextType";
   if (!waiting_to_associate_.empty()) {
-    DVLOG(1) << "Starting " << waiting_to_associate_[0]->name();
+    VLOG(0) << "ModelAssociationManager: Starting "
+            << waiting_to_associate_[0]->name();
     TRACE_EVENT_BEGIN1("sync", "ModelAssociation",
                        "DataType",
                        ModelTypeToString(waiting_to_associate_[0]->type()));
     DataTypeController* dtc = waiting_to_associate_[0];
     waiting_to_associate_.erase(waiting_to_associate_.begin());
     currently_associating_ = dtc;
     dtc->StartAssociating(base::Bind(
         &ModelAssociationManager::TypeStartCallback,
         weak_ptr_factory_.GetWeakPtr()));
     return;
   }
 
   // We are done with this cycle of association.
   state_ = IDLE;
   // Do a fresh calculation to see if controllers need starting to account for
   // 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";
+    VLOG(0) << "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()) {
+    VLOG(0) << "ModelAssociationManager: setting partial success";
     configure_status = DataTypeManager::PARTIAL_SUCCESS;

[tim (not reviewing), 2012/05/22 16:50:05]

Explain why this is only a partial success.

[lipalani1, 2012/05/22 20:20:46]

Done.

+  }
 
   DataTypeManager::ConfigureResult result(configure_status,
                                           desired_types_,
-                                          failed_datatypes_info_);
+                                          failed_datatypes_info_,
+                                          GetTypesWaitingToLoad());
   result_processor_->OnModelAssociationDone(result);
   return;
 }
 
+void ModelAssociationManager::ModelLoadTimedOut() {
+  VLOG(0) << "ModelAssociationManager: Model Loading timed out";
+  LoadModelForNextType();
+}
+
+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