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 16 using content::BrowserThread; 17 using syncer::ModelTypeSet; 18 19 namespace 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. 24 const int64 kDataTypeLoadWaitTimeInSeconds = 120; 25 namespace { 26 27 static 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 58 COMPILE_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. 63 class 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 79 syncer::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 119 ModelAssociationManager::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 139 ModelAssociationManager::~ModelAssociationManager() { 140 } 141 142 void 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 192 void 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 210 void 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 220 void 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 230 void 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 285 bool 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 311 void 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 322 void 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 418 void 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 446 void 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 508 void 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 565 syncer::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 576 base::OneShotTimer<ModelAssociationManager>* 577 ModelAssociationManager::GetTimerForTesting() { 578 return &timer_; 579 } 580 581 } // namespace browser_sync 582