1// Copyright (c) 2012 The Chromium Authors. All rights reserved.
2// Use of this source code is governed by a BSD-style license that can be
3// found in the LICENSE file.
4
5#include "chrome/browser/sync/glue/model_association_manager.h"
6
7#include <algorithm>
8#include <functional>
9
10#include "base/debug/trace_event.h"
11#include "base/logging.h"
12#include "base/message_loop/message_loop.h"
13#include "base/metrics/histogram.h"
14#include "sync/internal_api/public/base/model_type.h"
15
16using content::BrowserThread;
17using syncer::ModelTypeSet;
18
19namespace browser_sync {
20// The amount of time we wait for a datatype to load. If the type has
21// not finished loading we move on to the next type. Once this type
22// finishes loading we will do a configure to associate this type. Note
23// that in most cases types finish loading before this timeout.
24const int64 kDataTypeLoadWaitTimeInSeconds = 120;
25namespace {
26
27static const syncer::ModelType kStartOrder[] = {
28  syncer::NIGORI,               //  Listed for completeness.
29  syncer::DEVICE_INFO,          //  Listed for completeness.
30  syncer::EXPERIMENTS,          //  Listed for completeness.
31  syncer::PROXY_TABS,           //  Listed for completeness.
32  syncer::BOOKMARKS,            //  UI thread datatypes.
33  syncer::MANAGED_USERS,        //  Syncing managed users on initial login might
34                                //  block creating a new managed user, so we
35                                //  want to do it early.
36  syncer::PREFERENCES,
37  syncer::PRIORITY_PREFERENCES,
38  syncer::EXTENSIONS,
39  syncer::APPS,
40  syncer::THEMES,
41  syncer::SEARCH_ENGINES,
42  syncer::SESSIONS,
43  syncer::APP_NOTIFICATIONS,
44  syncer::DICTIONARY,
45  syncer::FAVICON_IMAGES,
46  syncer::FAVICON_TRACKING,
47  syncer::MANAGED_USER_SETTINGS,
48  syncer::AUTOFILL,             // Non-UI thread datatypes.
49  syncer::AUTOFILL_PROFILE,
50  syncer::EXTENSION_SETTINGS,
51  syncer::APP_SETTINGS,
52  syncer::TYPED_URLS,
53  syncer::PASSWORDS,
54  syncer::HISTORY_DELETE_DIRECTIVES,
55  syncer::SYNCED_NOTIFICATIONS,
56};
57
58COMPILE_ASSERT(arraysize(kStartOrder) ==
59               syncer::MODEL_TYPE_COUNT - syncer::FIRST_REAL_MODEL_TYPE,
60               kStartOrder_IncorrectSize);
61
62// Comparator used when sorting data type controllers.
63class SortComparator : public std::binary_function<DataTypeController*,
64                                                   DataTypeController*,
65                                                   bool> {
66 public:
67  explicit SortComparator(std::map<syncer::ModelType, int>* order)
68      : order_(order) { }
69
70  // Returns true if lhs precedes rhs.
71  bool operator() (DataTypeController* lhs, DataTypeController* rhs) {
72    return (*order_)[lhs->type()] < (*order_)[rhs->type()];
73  }
74
75 private:
76  std::map<syncer::ModelType, int>* order_;
77};
78
79syncer::DataTypeAssociationStats BuildAssociationStatsFromMergeResults(
80    const syncer::SyncMergeResult& local_merge_result,
81    const syncer::SyncMergeResult& syncer_merge_result,
82    const base::TimeDelta& association_wait_time,
83    const base::TimeDelta& association_time) {
84  DCHECK_EQ(local_merge_result.model_type(), syncer_merge_result.model_type());
85  syncer::DataTypeAssociationStats stats;
86  stats.had_error = local_merge_result.error().IsSet() ||
87                    syncer_merge_result.error().IsSet();
88  stats.num_local_items_before_association =
89      local_merge_result.num_items_before_association();
90  stats.num_sync_items_before_association =
91      syncer_merge_result.num_items_before_association();
92  stats.num_local_items_after_association =
93      local_merge_result.num_items_after_association();
94  stats.num_sync_items_after_association =
95      syncer_merge_result.num_items_after_association();
96  stats.num_local_items_added =
97      local_merge_result.num_items_added();
98  stats.num_local_items_deleted =
99      local_merge_result.num_items_deleted();
100  stats.num_local_items_modified =
101      local_merge_result.num_items_modified();
102  stats.local_version_pre_association =
103      local_merge_result.pre_association_version();
104  stats.num_sync_items_added =
105      syncer_merge_result.num_items_added();
106  stats.num_sync_items_deleted =
107      syncer_merge_result.num_items_deleted();
108  stats.num_sync_items_modified =
109      syncer_merge_result.num_items_modified();
110  stats.sync_version_pre_association =
111      syncer_merge_result.pre_association_version();
112  stats.association_wait_time = association_wait_time;
113  stats.association_time = association_time;
114  return stats;
115}
116
117}  // namespace
118
119ModelAssociationManager::ModelAssociationManager(
120    const DataTypeController::TypeMap* controllers,
121    ModelAssociationResultProcessor* processor)
122    : state_(IDLE),
123      currently_associating_(NULL),
124      controllers_(controllers),
125      result_processor_(processor),
126      weak_ptr_factory_(this) {
127
128  // Ensure all data type controllers are stopped.
129  for (DataTypeController::TypeMap::const_iterator it = controllers_->begin();
130       it != controllers_->end(); ++it) {
131    DCHECK_EQ(DataTypeController::NOT_RUNNING, (*it).second->state());
132  }
133
134  // Build a ModelType -> order map for sorting.
135  for (int i = 0; i < static_cast<int>(arraysize(kStartOrder)); i++)
136    start_order_[kStartOrder[i]] = i;
137}
138
139ModelAssociationManager::~ModelAssociationManager() {
140}
141
142void ModelAssociationManager::Initialize(syncer::ModelTypeSet desired_types) {
143  // TODO(tim): Bug 134550.  CHECKing to ensure no reentrancy on dev channel.
144  // Remove this.
145  CHECK_EQ(state_, IDLE);
146  needs_start_.clear();
147  needs_stop_.clear();
148  failed_data_types_info_.clear();
149  associating_types_.Clear();
150  needs_crypto_types_.Clear();
151  state_ = INITIALIZED_TO_CONFIGURE;
152
153  DVLOG(1) << "ModelAssociationManager: Initializing for "
154           << syncer::ModelTypeSetToString(desired_types);
155
156  // Stop the types that are still loading from the previous configuration.
157  // If they are enabled we will start them here once again.
158  for (std::vector<DataTypeController*>::const_iterator it =
159           pending_model_load_.begin();
160       it != pending_model_load_.end();
161       ++it) {
162    DVLOG(1) << "ModelAssociationManager: Stopping "
163             << (*it)->name()
164             << " before initialization";
165    (*it)->Stop();
166  }
167
168  pending_model_load_.clear();
169  waiting_to_associate_.clear();
170  currently_associating_ = NULL;
171
172  // Add any data type controllers into that needs_stop_ list that are
173  // currently MODEL_STARTING, ASSOCIATING, RUNNING or DISABLED.
174  for (DataTypeController::TypeMap::const_iterator it = controllers_->begin();
175       it != controllers_->end(); ++it) {
176    DataTypeController* dtc = (*it).second.get();
177    if (!desired_types.Has(dtc->type()) &&
178        (dtc->state() == DataTypeController::MODEL_STARTING ||
179         dtc->state() == DataTypeController::ASSOCIATING ||
180         dtc->state() == DataTypeController::RUNNING ||
181         dtc->state() == DataTypeController::DISABLED)) {
182      needs_stop_.push_back(dtc);
183      DVLOG(1) << "ModelTypeToString: Will stop " << dtc->name();
184    }
185  }
186  // Sort these according to kStartOrder.
187  std::sort(needs_stop_.begin(),
188            needs_stop_.end(),
189            SortComparator(&start_order_));
190}
191
192void ModelAssociationManager::StartAssociationAsync(
193    const syncer::ModelTypeSet& types_to_associate) {
194  DCHECK(state_ == INITIALIZED_TO_CONFIGURE || state_ == IDLE);
195  state_ = CONFIGURING;
196
197  // Calculate |needs_start_| list.
198  associating_types_ = types_to_associate;
199  GetControllersNeedingStart(&needs_start_);
200  // Sort these according to kStartOrder.
201  std::sort(needs_start_.begin(),
202            needs_start_.end(),
203            SortComparator(&start_order_));
204
205  DVLOG(1) << "ModelAssociationManager: Going to start model association";
206  association_start_time_ = base::Time::Now();
207  LoadModelForNextType();
208}
209
210void ModelAssociationManager::ResetForReconfiguration() {
211  state_ = IDLE;
212  DVLOG(1) << "ModelAssociationManager: Reseting for reconfiguration";
213  needs_start_.clear();
214  needs_stop_.clear();
215  associating_types_.Clear();
216  failed_data_types_info_.clear();
217  needs_crypto_types_.Clear();
218}
219
220void ModelAssociationManager::StopDisabledTypes() {
221  DVLOG(1) << "ModelAssociationManager: Stopping disabled types.";
222  // Stop requested data types.
223  for (size_t i = 0; i < needs_stop_.size(); ++i) {
224    DVLOG(1) << "ModelAssociationManager: Stopping " << needs_stop_[i]->name();
225    needs_stop_[i]->Stop();
226  }
227  needs_stop_.clear();
228}
229
230void ModelAssociationManager::Stop() {
231  bool need_to_call_model_association_done = false;
232  DVLOG(1) << "ModelAssociationManager: Stopping MAM";
233  if (state_ == CONFIGURING) {
234    DVLOG(1) << "ModelAssociationManager: In the middle of configuration while"
235             << " stopping";
236    state_ = ABORTED;
237    DCHECK(currently_associating_ != NULL ||
238           needs_start_.size() > 0 ||
239           pending_model_load_.size() > 0 ||
240           waiting_to_associate_.size() > 0);
241
242    if (currently_associating_) {
243      TRACE_EVENT_END0("sync", "ModelAssociation");
244      DVLOG(1) << "ModelAssociationManager: stopping "
245               << currently_associating_->name();
246      currently_associating_->Stop();
247    } else {
248      // DTCs in other lists would be stopped below.
249      state_ = IDLE;
250    }
251
252    DCHECK_EQ(IDLE, state_);
253
254    // We are in the midle of model association. We need to inform the caller
255    // so the caller can send notificationst to PSS layer.
256    need_to_call_model_association_done = true;
257  }
258
259  // Now continue stopping any types that have already started.
260  DCHECK(state_ == IDLE ||
261         state_ == INITIALIZED_TO_CONFIGURE);
262  for (DataTypeController::TypeMap::const_iterator it = controllers_->begin();
263       it != controllers_->end(); ++it) {
264    DataTypeController* dtc = (*it).second.get();
265    if (dtc->state() != DataTypeController::NOT_RUNNING &&
266        dtc->state() != DataTypeController::STOPPING) {
267      dtc->Stop();
268      DVLOG(1) << "ModelAssociationManager: Stopped " << dtc->name();
269    }
270  }
271
272  DataTypeManager::ConfigureResult result(DataTypeManager::ABORTED,
273                                          associating_types_,
274                                          failed_data_types_info_,
275                                          syncer::ModelTypeSet(),
276                                          needs_crypto_types_);
277  failed_data_types_info_.clear();
278  needs_crypto_types_.Clear();
279  if (need_to_call_model_association_done) {
280    DVLOG(1) << "ModelAssociationManager: Calling OnModelAssociationDone";
281    result_processor_->OnModelAssociationDone(result);
282  }
283}
284
285bool ModelAssociationManager::GetControllersNeedingStart(
286    std::vector<DataTypeController*>* needs_start) {
287  DVLOG(1) << "ModelAssociationManager: GetControllersNeedingStart";
288  // Add any data type controllers into the needs_start_ list that are
289  // currently NOT_RUNNING or STOPPING.
290  bool found_any = false;
291  for (ModelTypeSet::Iterator it = associating_types_.First();
292       it.Good(); it.Inc()) {
293    DataTypeController::TypeMap::const_iterator dtc =
294        controllers_->find(it.Get());
295    if (dtc != controllers_->end() &&
296        (dtc->second->state() == DataTypeController::NOT_RUNNING ||
297         dtc->second->state() == DataTypeController::STOPPING)) {
298      found_any = true;
299      if (needs_start)
300        needs_start->push_back(dtc->second.get());
301      if (dtc->second->state() == DataTypeController::DISABLED) {
302        DVLOG(1) << "ModelAssociationManager: Found "\
303                << syncer::ModelTypeToString(dtc->second->type())
304                 << " in disabled state.";
305      }
306    }
307  }
308  return found_any;
309}
310
311void ModelAssociationManager::AppendToFailedDatatypesAndLogError(
312    DataTypeController::StartResult result,
313    const syncer::SyncError& error) {
314  failed_data_types_info_[error.model_type()] = error;
315  LOG(ERROR) << "Failed to associate models for "
316             << syncer::ModelTypeToString(error.model_type());
317  UMA_HISTOGRAM_ENUMERATION("Sync.ConfigureFailed",
318                            ModelTypeToHistogramInt(error.model_type()),
319                            syncer::MODEL_TYPE_COUNT);
320}
321
322void ModelAssociationManager::TypeStartCallback(
323    DataTypeController::StartResult start_result,
324    const syncer::SyncMergeResult& local_merge_result,
325    const syncer::SyncMergeResult& syncer_merge_result) {
326  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
327  TRACE_EVENT_END0("sync", "ModelAssociation");
328
329  DVLOG(1) << "ModelAssociationManager: TypeStartCallback";
330  if (state_ == ABORTED) {
331    // Now that we have finished with the current type we can stop
332    // if abort was called.
333    DVLOG(1) << "ModelAssociationManager: Doing an early return"
334             << " because of abort";
335    state_ = IDLE;
336    return;
337  }
338
339  DCHECK(state_ == CONFIGURING);
340
341  // We are done with this type. Clear it.
342  DataTypeController* started_dtc = currently_associating_;
343  currently_associating_ = NULL;
344
345  if (start_result == DataTypeController::ASSOCIATION_FAILED) {
346    DVLOG(1) << "ModelAssociationManager: Encountered a failed type";
347    AppendToFailedDatatypesAndLogError(start_result,
348                                       local_merge_result.error());
349  } else if (start_result == DataTypeController::NEEDS_CRYPTO) {
350    DVLOG(1) << "ModelAssociationManager: Encountered an undecryptable type";
351    needs_crypto_types_.Put(started_dtc->type());
352  }
353
354  // Track the merge results if we succeeded or an association failure
355  // occurred.
356  if ((DataTypeController::IsSuccessfulResult(start_result) ||
357       start_result == DataTypeController::ASSOCIATION_FAILED) &&
358      syncer::ProtocolTypes().Has(local_merge_result.model_type())) {
359    base::TimeDelta association_wait_time =
360        current_type_association_start_time_ - association_start_time_;
361    base::TimeDelta association_time =
362        base::Time::Now() - current_type_association_start_time_;
363    syncer::DataTypeAssociationStats stats =
364        BuildAssociationStatsFromMergeResults(local_merge_result,
365                                              syncer_merge_result,
366                                              association_wait_time,
367                                              association_time);
368    result_processor_->OnSingleDataTypeAssociationDone(
369        local_merge_result.model_type(), stats);
370  }
371
372  // If the type started normally, continue to the next type.
373  // If the type is waiting for the cryptographer, continue to the next type.
374  // Once the cryptographer is ready, we'll attempt to restart this type.
375  // If this type encountered a type specific error continue to the next type.
376  if (start_result == DataTypeController::NEEDS_CRYPTO ||
377      DataTypeController::IsSuccessfulResult(start_result) ||
378      start_result == DataTypeController::ASSOCIATION_FAILED) {
379
380    DVLOG(1) << "ModelAssociationManager: type start callback returned "
381             << start_result << " so calling LoadModelForNextType";
382    LoadModelForNextType();
383    return;
384  }
385
386  // Any other result requires reconfiguration. Pass it on through the callback.
387  LOG(ERROR) << "Failed to configure " << started_dtc->name();
388  DCHECK(local_merge_result.error().IsSet());
389  DCHECK_EQ(started_dtc->type(), local_merge_result.error().model_type());
390  DataTypeManager::ConfigureStatus configure_status =
391      DataTypeManager::ABORTED;
392  switch (start_result) {
393    case DataTypeController::ABORTED:
394      configure_status = DataTypeManager::ABORTED;
395      break;
396    case DataTypeController::UNRECOVERABLE_ERROR:
397      configure_status = DataTypeManager::UNRECOVERABLE_ERROR;
398      break;
399    default:
400      NOTREACHED();
401      break;
402  }
403
404  std::map<syncer::ModelType, syncer::SyncError> errors;
405  errors[local_merge_result.model_type()] = local_merge_result.error();
406
407  // Put our state to idle.
408  state_ = IDLE;
409
410  DataTypeManager::ConfigureResult configure_result(configure_status,
411                                                    associating_types_,
412                                                    errors,
413                                                    syncer::ModelTypeSet(),
414                                                    needs_crypto_types_);
415  result_processor_->OnModelAssociationDone(configure_result);
416}
417
418void ModelAssociationManager::LoadModelForNextType() {
419  DVLOG(1) << "ModelAssociationManager: LoadModelForNextType";
420  if (!needs_start_.empty()) {
421    DVLOG(1) << "ModelAssociationManager: Starting " << needs_start_[0]->name();
422
423    DataTypeController* dtc = needs_start_[0];
424    needs_start_.erase(needs_start_.begin());
425    // Move from |needs_start_| to |pending_model_load_|.
426    pending_model_load_.insert(pending_model_load_.begin(), dtc);
427    timer_.Start(FROM_HERE,
428                 base::TimeDelta::FromSeconds(kDataTypeLoadWaitTimeInSeconds),
429                 this,
430                 &ModelAssociationManager::LoadModelForNextType);
431    dtc->LoadModels(base::Bind(
432        &ModelAssociationManager::ModelLoadCallback,
433        weak_ptr_factory_.GetWeakPtr()));
434
435    return;
436  }
437
438  DVLOG(1) << "ModelAssociationManager: All types have models loaded. "
439          << "Moving on to StartAssociatingNextType.";
440
441  // If all controllers have their |LoadModels| invoked then pass onto
442  // |StartAssociatingNextType|.
443  StartAssociatingNextType();
444}
445
446void ModelAssociationManager::ModelLoadCallback(
447    syncer::ModelType type, syncer::SyncError error) {
448  DVLOG(1) << "ModelAssociationManager: ModelLoadCallback for "
449          << syncer::ModelTypeToString(type);
450  if (state_ == CONFIGURING) {
451    DVLOG(1) << "ModelAssociationManager: ModelLoadCallback while configuring";
452    for (std::vector<DataTypeController*>::iterator it =
453             pending_model_load_.begin();
454          it != pending_model_load_.end();
455          ++it) {
456      if ((*it)->type() == type) {
457        // Each type is given |kDataTypeLoadWaitTimeInSeconds| time to load
458        // (as controlled by the timer.). If the type does not load in that
459        // time we move on to the next type. However if the type does
460        // finish loading in that time we want to stop the timer. We stop
461        // the timer, if the type that loaded is the same as the type that
462        // we started the timer for(as indicated by the type on the head
463        // of the list).
464        // Note: Regardless of this timer value the associations will always
465        // take place serially. The only thing this timer controls is how serial
466        // the model load is. If this timer has a value of zero seconds then
467        // the model loads will all be parallel.
468        if (it == pending_model_load_.begin()) {
469          DVLOG(1) << "ModelAssociationManager: Stopping timer";
470          timer_.Stop();
471        }
472        DataTypeController* dtc = *it;
473        pending_model_load_.erase(it);
474        if (!error.IsSet()) {
475          DVLOG(1) << "ModelAssociationManager:"
476                  << " Calling StartAssociatingNextType";
477          waiting_to_associate_.push_back(dtc);
478          StartAssociatingNextType();
479        } else {
480          DVLOG(1) << "ModelAssociationManager: Encountered error loading";
481          syncer::SyncMergeResult local_merge_result(type);
482          local_merge_result.set_error(error);
483          TypeStartCallback(DataTypeController::ASSOCIATION_FAILED,
484                            local_merge_result,
485                            syncer::SyncMergeResult(type));
486       }
487       return;
488      }
489    }
490    NOTREACHED();
491    return;
492  } else if (state_ == IDLE) {
493    DVLOG(1) << "ModelAssociationManager: Models loaded after configure cycle. "
494            << "Informing DTM";
495    // This datatype finished loading after the deadline imposed by the
496    // originating configuration cycle. Inform the DataTypeManager that the
497    // type has loaded, so that association may begin.
498    result_processor_->OnTypesLoaded();
499  } else {
500    // If we're not IDLE or CONFIGURING, we're being invoked as part of an abort
501    // process (possibly a reconfiguration, or disabling of a broken data type).
502    DVLOG(1) << "ModelAssociationManager: ModelLoadCallback occurred while "
503             << "not IDLE or CONFIGURING. Doing nothing.";
504  }
505
506}
507
508void ModelAssociationManager::StartAssociatingNextType() {
509  DCHECK_EQ(state_, CONFIGURING);
510  DCHECK_EQ(currently_associating_, static_cast<DataTypeController*>(NULL));
511
512  DVLOG(1) << "ModelAssociationManager: StartAssociatingNextType";
513  if (!waiting_to_associate_.empty()) {
514    DVLOG(1) << "ModelAssociationManager: Starting "
515            << waiting_to_associate_[0]->name();
516    TRACE_EVENT_BEGIN1("sync", "ModelAssociation",
517                       "DataType",
518                       ModelTypeToString(waiting_to_associate_[0]->type()));
519    DataTypeController* dtc = waiting_to_associate_[0];
520    waiting_to_associate_.erase(waiting_to_associate_.begin());
521    currently_associating_ = dtc;
522    current_type_association_start_time_ = base::Time::Now();
523    dtc->StartAssociating(base::Bind(
524        &ModelAssociationManager::TypeStartCallback,
525        weak_ptr_factory_.GetWeakPtr()));
526    return;
527  }
528
529  // We are done with this cycle of association. Stop any failed types now.
530  needs_stop_.clear();
531  for (DataTypeController::TypeMap::const_iterator it = controllers_->begin();
532       it != controllers_->end(); ++it) {
533    DataTypeController* dtc = (*it).second.get();
534    if (failed_data_types_info_.count(dtc->type()) > 0 &&
535        dtc->state() != DataTypeController::NOT_RUNNING) {
536      needs_stop_.push_back(dtc);
537      DVLOG(1) << "ModelTypeToString: Will stop " << dtc->name();
538    }
539  }
540  StopDisabledTypes();
541
542  state_ = IDLE;
543
544  DataTypeManager::ConfigureStatus configure_status = DataTypeManager::OK;
545
546  if (!failed_data_types_info_.empty() ||
547      !GetTypesWaitingToLoad().Empty() ||
548      !needs_crypto_types_.Empty()) {
549    // We have not configured all types that we have been asked to configure.
550    // Either we have failed types or types that have not completed loading
551    // yet.
552    DVLOG(1) << "ModelAssociationManager: setting partial success";
553    configure_status = DataTypeManager::PARTIAL_SUCCESS;
554  }
555
556  DataTypeManager::ConfigureResult result(configure_status,
557                                          associating_types_,
558                                          failed_data_types_info_,
559                                          GetTypesWaitingToLoad(),
560                                          needs_crypto_types_);
561  result_processor_->OnModelAssociationDone(result);
562  return;
563}
564
565syncer::ModelTypeSet ModelAssociationManager::GetTypesWaitingToLoad() {
566  syncer::ModelTypeSet result;
567  for (std::vector<DataTypeController*>::const_iterator it =
568           pending_model_load_.begin();
569       it != pending_model_load_.end();
570       ++it) {
571    result.Put((*it)->type());
572  }
573  return result;
574}
575
576base::OneShotTimer<ModelAssociationManager>*
577    ModelAssociationManager::GetTimerForTesting() {
578  return &timer_;
579}
580
581}  // namespace browser_sync
582