Home | History | Annotate | Download | only in integration 
      1 // Copyright 2013 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/test/integration/profile_sync_service_harness.h"
      6 
      7 #include <cstddef>
      8 #include <iterator>
      9 #include <ostream>
     10 #include <set>
     11 #include <sstream>
     12 #include <vector>
     13 
     14 #include "base/base64.h"
     15 #include "base/bind.h"
     16 #include "base/command_line.h"
     17 #include "base/compiler_specific.h"
     18 #include "base/json/json_writer.h"
     19 #include "base/location.h"
     20 #include "base/logging.h"
     21 #include "base/memory/ref_counted.h"
     22 #include "base/message_loop/message_loop.h"
     23 #include "base/prefs/pref_service.h"
     24 #include "base/strings/stringprintf.h"
     25 #include "chrome/browser/chrome_notification_types.h"
     26 #include "chrome/browser/invalidation/p2p_invalidation_service.h"
     27 #include "chrome/browser/profiles/profile.h"
     28 #include "chrome/browser/signin/profile_oauth2_token_service.h"
     29 #include "chrome/browser/signin/profile_oauth2_token_service_factory.h"
     30 #include "chrome/browser/signin/signin_manager_base.h"
     31 #include "chrome/browser/sync/about_sync_util.h"
     32 #include "chrome/browser/sync/glue/data_type_controller.h"
     33 #include "chrome/browser/sync/profile_sync_service_factory.h"
     34 #include "chrome/browser/sync/test/integration/status_change_checker.h"
     35 #include "chrome/common/chrome_switches.h"
     36 #include "chrome/common/pref_names.h"
     37 #include "content/public/browser/notification_service.h"
     38 #include "google_apis/gaia/gaia_constants.h"
     39 #include "sync/internal_api/public/base/progress_marker_map.h"
     40 #include "sync/internal_api/public/sessions/sync_session_snapshot.h"
     41 #include "sync/internal_api/public/util/sync_string_conversions.h"
     42 
     43 #if defined(ENABLE_MANAGED_USERS)
     44 #include "chrome/browser/managed_mode/managed_user_constants.h"
     45 #endif
     46 
     47 using syncer::sessions::SyncSessionSnapshot;
     48 using invalidation::P2PInvalidationService;
     49 
     50 // The amount of time for which we wait for a sync operation to complete.
     51 static const int kSyncOperationTimeoutMs = 45000;
     52 
     53 // Simple class to implement a timeout using PostDelayedTask.  If it is not
     54 // aborted before picked up by a message queue, then it asserts.  This class is
     55 // not thread safe.
     56 class StateChangeTimeoutEvent
     57     : public base::RefCountedThreadSafe<StateChangeTimeoutEvent> {
     58  public:
     59   explicit StateChangeTimeoutEvent(ProfileSyncServiceHarness* caller);
     60 
     61   // The entry point to the class from PostDelayedTask.
     62   void Callback();
     63 
     64   // Cancels the actions of the callback.  Returns true if success, false
     65   // if the callback has already timed out.
     66   bool Abort();
     67 
     68  private:
     69   friend class base::RefCountedThreadSafe<StateChangeTimeoutEvent>;
     70 
     71   ~StateChangeTimeoutEvent();
     72 
     73   bool aborted_;
     74   bool did_timeout_;
     75 
     76   // Due to synchronization of the IO loop, the caller will always be alive
     77   // if the class is not aborted.
     78   ProfileSyncServiceHarness* caller_;
     79 
     80   DISALLOW_COPY_AND_ASSIGN(StateChangeTimeoutEvent);
     81 };
     82 
     83 StateChangeTimeoutEvent::StateChangeTimeoutEvent(
     84     ProfileSyncServiceHarness* caller)
     85     : aborted_(false), did_timeout_(false), caller_(caller) {
     86 }
     87 
     88 StateChangeTimeoutEvent::~StateChangeTimeoutEvent() {
     89 }
     90 
     91 void StateChangeTimeoutEvent::Callback() {
     92   if (!aborted_) {
     93     DCHECK(caller_->status_change_checker_);
     94     // TODO(rsimha): Simply return false on timeout instead of repeating the
     95     // exit condition check.
     96     if (!caller_->status_change_checker_->IsExitConditionSatisfied()) {
     97       did_timeout_ = true;
     98       DCHECK(!aborted_);
     99       caller_->SignalStateComplete();
    100     }
    101   }
    102 }
    103 
    104 bool StateChangeTimeoutEvent::Abort() {
    105   aborted_ = true;
    106   caller_ = NULL;
    107   return !did_timeout_;
    108 }
    109 
    110 namespace {
    111 
    112 // Helper function which returns true if the sync backend has been initialized,
    113 // or if backend initialization was blocked for some reason.
    114 bool DoneWaitingForBackendInitialization(
    115     const ProfileSyncServiceHarness* harness) {
    116   DCHECK(harness);
    117   // Backend is initialized.
    118   if (harness->service()->sync_initialized())
    119     return true;
    120   // Backend initialization is blocked by an auth error.
    121   if (harness->HasAuthError())
    122     return true;
    123   // Backend initialization is blocked by a failure to fetch Oauth2 tokens.
    124   if (harness->service()->IsRetryingAccessTokenFetchForTest())
    125     return true;
    126   // Still waiting on backend initialization.
    127   return false;
    128 }
    129 
    130 // Helper function which returns true if initial sync is complete, or if the
    131 // initial sync is blocked for some reason.
    132 bool DoneWaitingForInitialSync(const ProfileSyncServiceHarness* harness) {
    133   DCHECK(harness);
    134   // Initial sync is complete.
    135   if (harness->IsFullySynced())
    136     return true;
    137   // Initial sync is blocked because custom passphrase is required.
    138   if (harness->service()->passphrase_required_reason() ==
    139       syncer::REASON_DECRYPTION) {
    140     return true;
    141   }
    142   // Initial sync is blocked by an auth error.
    143   if (harness->HasAuthError())
    144     return true;
    145   // Still waiting on initial sync.
    146   return false;
    147 }
    148 
    149 // Helper function which returns true if the sync client is fully synced, or if
    150 // sync is blocked for some reason.
    151 bool DoneWaitingForFullSync(const ProfileSyncServiceHarness* harness) {
    152   DCHECK(harness);
    153   // Sync is complete.
    154   if (harness->IsFullySynced())
    155     return true;
    156   // Sync is blocked by an auth error.
    157   if (harness->HasAuthError())
    158     return true;
    159   // Sync is blocked by a failure to fetch Oauth2 tokens.
    160   if (harness->service()->IsRetryingAccessTokenFetchForTest())
    161     return true;
    162   // Still waiting on sync.
    163   return false;
    164 }
    165 
    166 // Helper function which returns true if the sync client requires a custom
    167 // passphrase to be entered for decryption.
    168 bool IsPassphraseRequired(const ProfileSyncServiceHarness* harness) {
    169   DCHECK(harness);
    170   return harness->service()->IsPassphraseRequired();
    171 }
    172 
    173 // Helper function which returns true if the custom passphrase entered was
    174 // accepted.
    175 bool IsPassphraseAccepted(const ProfileSyncServiceHarness* harness) {
    176   DCHECK(harness);
    177   return (!harness->service()->IsPassphraseRequired() &&
    178           harness->service()->IsUsingSecondaryPassphrase());
    179 }
    180 
    181 // Helper function which returns true if the sync client no longer has a pending
    182 // backend migration.
    183 bool NoPendingBackendMigration(const ProfileSyncServiceHarness* harness) {
    184   DCHECK(harness);
    185   return !harness->HasPendingBackendMigration();
    186 }
    187 
    188 // Helper function which returns true if the client has detected an actionable
    189 // error.
    190 bool HasActionableError(const ProfileSyncServiceHarness* harness) {
    191   DCHECK(harness);
    192   ProfileSyncService::Status status = harness->GetStatus();
    193   return (status.sync_protocol_error.action != syncer::UNKNOWN_ACTION &&
    194           harness->service()->HasUnrecoverableError() == true);
    195 }
    196 
    197 }  // namespace
    198 
    199 // static
    200 ProfileSyncServiceHarness* ProfileSyncServiceHarness::Create(
    201     Profile* profile,
    202     const std::string& username,
    203     const std::string& password) {
    204   return new ProfileSyncServiceHarness(profile, username, password, NULL);
    205 }
    206 
    207 // static
    208 ProfileSyncServiceHarness* ProfileSyncServiceHarness::CreateForIntegrationTest(
    209     Profile* profile,
    210     const std::string& username,
    211     const std::string& password,
    212     P2PInvalidationService* p2p_invalidation_service) {
    213   return new ProfileSyncServiceHarness(profile,
    214                                        username,
    215                                        password,
    216                                        p2p_invalidation_service);
    217 }
    218 
    219 ProfileSyncServiceHarness::ProfileSyncServiceHarness(
    220     Profile* profile,
    221     const std::string& username,
    222     const std::string& password,
    223     P2PInvalidationService* p2p_invalidation_service)
    224     : profile_(profile),
    225       service_(ProfileSyncServiceFactory::GetForProfile(profile)),
    226       p2p_invalidation_service_(p2p_invalidation_service),
    227       progress_marker_partner_(NULL),
    228       username_(username),
    229       password_(password),
    230       oauth2_refesh_token_number_(0),
    231       profile_debug_name_(profile->GetDebugName()),
    232       status_change_checker_(NULL) {
    233 }
    234 
    235 ProfileSyncServiceHarness::~ProfileSyncServiceHarness() {
    236   if (service()->HasObserver(this))
    237     service()->RemoveObserver(this);
    238 }
    239 
    240 void ProfileSyncServiceHarness::SetCredentials(const std::string& username,
    241                                                const std::string& password) {
    242   username_ = username;
    243   password_ = password;
    244 }
    245 
    246 bool ProfileSyncServiceHarness::SetupSync() {
    247   bool result = SetupSync(syncer::ModelTypeSet::All());
    248   if (result == false) {
    249     std::string status = GetServiceStatus();
    250     LOG(ERROR) << profile_debug_name_
    251                << ": SetupSync failed. Syncer status:\n" << status;
    252   } else {
    253     DVLOG(1) << profile_debug_name_ << ": SetupSync successful.";
    254   }
    255   return result;
    256 }
    257 
    258 bool ProfileSyncServiceHarness::SetupSync(
    259     syncer::ModelTypeSet synced_datatypes) {
    260   // Initialize the sync client's profile sync service object.
    261   if (service() == NULL) {
    262     LOG(ERROR) << "SetupSync(): service() is null.";
    263     return false;
    264   }
    265 
    266   // Subscribe sync client to notifications from the profile sync service.
    267   if (!service()->HasObserver(this))
    268     service()->AddObserver(this);
    269 
    270   // Tell the sync service that setup is in progress so we don't start syncing
    271   // until we've finished configuration.
    272   service()->SetSetupInProgress(true);
    273 
    274   // Authenticate sync client using GAIA credentials.
    275   service()->signin()->SetAuthenticatedUsername(username_);
    276   profile_->GetPrefs()->SetString(prefs::kGoogleServicesUsername,
    277                                   username_);
    278   GoogleServiceSigninSuccessDetails details(username_, password_);
    279   content::NotificationService::current()->Notify(
    280       chrome::NOTIFICATION_GOOGLE_SIGNIN_SUCCESSFUL,
    281       content::Source<Profile>(profile_),
    282       content::Details<const GoogleServiceSigninSuccessDetails>(&details));
    283 
    284 #if defined(ENABLE_MANAGED_USERS)
    285   std::string account_id = profile_->IsManaged() ?
    286       managed_users::kManagedUserPseudoEmail : username_;
    287 #else
    288   std::string account_id = username_;
    289 #endif
    290   DCHECK(!account_id.empty());
    291   ProfileOAuth2TokenServiceFactory::GetForProfile(profile_)->
    292       UpdateCredentials(account_id, GenerateFakeOAuth2RefreshTokenString());
    293 
    294   // Wait for the OnBackendInitialized() callback.
    295   if (!AwaitBackendInitialized()) {
    296     LOG(ERROR) << "OnBackendInitialized() not seen after "
    297                << kSyncOperationTimeoutMs / 1000
    298                << " seconds.";
    299     return false;
    300   }
    301 
    302   // Make sure that initial sync wasn't blocked by a missing passphrase.
    303   if (service()->passphrase_required_reason() == syncer::REASON_DECRYPTION) {
    304     LOG(ERROR) << "A passphrase is required for decryption. Sync cannot proceed"
    305                   " until SetDecryptionPassphrase is called.";
    306     return false;
    307   }
    308 
    309   // Make sure that initial sync wasn't blocked by rejected credentials.
    310   if (HasAuthError()) {
    311     LOG(ERROR) << "Credentials were rejected. Sync cannot proceed.";
    312     return false;
    313   }
    314 
    315   // Choose the datatypes to be synced. If all datatypes are to be synced,
    316   // set sync_everything to true; otherwise, set it to false.
    317   bool sync_everything =
    318       synced_datatypes.Equals(syncer::ModelTypeSet::All());
    319   service()->OnUserChoseDatatypes(sync_everything, synced_datatypes);
    320 
    321   // Notify ProfileSyncService that we are done with configuration.
    322   FinishSyncSetup();
    323 
    324   // Subscribe sync client to notifications from the backend migrator
    325   // (possible only after choosing data types).
    326   if (!TryListeningToMigrationEvents()) {
    327     NOTREACHED();
    328     return false;
    329   }
    330 
    331   // Set an implicit passphrase for encryption if an explicit one hasn't already
    332   // been set. If an explicit passphrase has been set, immediately return false,
    333   // since a decryption passphrase is required.
    334   if (!service()->IsUsingSecondaryPassphrase()) {
    335     service()->SetEncryptionPassphrase(password_, ProfileSyncService::IMPLICIT);
    336   } else {
    337     LOG(ERROR) << "A passphrase is required for decryption. Sync cannot proceed"
    338                   " until SetDecryptionPassphrase is called.";
    339     return false;
    340   }
    341 
    342   // Wait for initial sync cycle to be completed.
    343   DCHECK(service()->sync_initialized());
    344   StatusChangeChecker initial_sync_checker(
    345       base::Bind(&DoneWaitingForInitialSync, base::Unretained(this)),
    346       "DoneWaitingForInitialSync");
    347   if (!AwaitStatusChange(&initial_sync_checker, "SetupSync")) {
    348     LOG(ERROR) << "Initial sync cycle did not complete after "
    349                << kSyncOperationTimeoutMs / 1000
    350                << " seconds.";
    351     return false;
    352   }
    353 
    354   // Make sure that initial sync wasn't blocked by a missing passphrase.
    355   if (service()->passphrase_required_reason() == syncer::REASON_DECRYPTION) {
    356     LOG(ERROR) << "A passphrase is required for decryption. Sync cannot proceed"
    357                   " until SetDecryptionPassphrase is called.";
    358     return false;
    359   }
    360 
    361   // Make sure that initial sync wasn't blocked by rejected credentials.
    362   if (service()->GetAuthError().state() ==
    363       GoogleServiceAuthError::INVALID_GAIA_CREDENTIALS) {
    364     LOG(ERROR) << "Credentials were rejected. Sync cannot proceed.";
    365     return false;
    366   }
    367 
    368   return true;
    369 }
    370 
    371 bool ProfileSyncServiceHarness::TryListeningToMigrationEvents() {
    372   browser_sync::BackendMigrator* migrator =
    373       service()->GetBackendMigratorForTest();
    374   if (migrator && !migrator->HasMigrationObserver(this)) {
    375     migrator->AddMigrationObserver(this);
    376     return true;
    377   }
    378   return false;
    379 }
    380 
    381 void ProfileSyncServiceHarness::SignalStateComplete() {
    382   base::MessageLoop::current()->QuitWhenIdle();
    383 }
    384 
    385 void ProfileSyncServiceHarness::OnStateChanged() {
    386   if (!status_change_checker_)
    387     return;
    388 
    389   DVLOG(1) << GetClientInfoString(status_change_checker_->callback_name());
    390   if (status_change_checker_->IsExitConditionSatisfied())
    391     base::MessageLoop::current()->QuitWhenIdle();
    392 }
    393 
    394 void ProfileSyncServiceHarness::OnSyncCycleCompleted() {
    395   // Integration tests still use p2p notifications.
    396   const SyncSessionSnapshot& snap = GetLastSessionSnapshot();
    397   bool is_notifiable_commit =
    398       (snap.model_neutral_state().num_successful_commits > 0);
    399   if (is_notifiable_commit && p2p_invalidation_service_) {
    400     syncer::ModelTypeSet model_types =
    401         snap.model_neutral_state().commit_request_types;
    402     syncer::ObjectIdSet ids = ModelTypeSetToObjectIdSet(model_types);
    403     p2p_invalidation_service_->SendInvalidation(ids);
    404   }
    405   OnStateChanged();
    406 }
    407 
    408 void ProfileSyncServiceHarness::OnMigrationStateChange() {
    409   // Update migration state.
    410   if (HasPendingBackendMigration()) {
    411     // Merge current pending migration types into
    412     // |pending_migration_types_|.
    413     pending_migration_types_.PutAll(
    414         service()->GetBackendMigratorForTest()->
    415             GetPendingMigrationTypesForTest());
    416     DVLOG(1) << profile_debug_name_ << ": new pending migration types "
    417              << syncer::ModelTypeSetToString(pending_migration_types_);
    418   } else {
    419     // Merge just-finished pending migration types into
    420     // |migration_types_|.
    421     migrated_types_.PutAll(pending_migration_types_);
    422     pending_migration_types_.Clear();
    423     DVLOG(1) << profile_debug_name_ << ": new migrated types "
    424              << syncer::ModelTypeSetToString(migrated_types_);
    425   }
    426   OnStateChanged();
    427 }
    428 
    429 bool ProfileSyncServiceHarness::AwaitPassphraseRequired() {
    430   DVLOG(1) << GetClientInfoString("AwaitPassphraseRequired");
    431   if (IsSyncDisabled()) {
    432     LOG(ERROR) << "Sync disabled for " << profile_debug_name_ << ".";
    433     return false;
    434   }
    435 
    436   if (service()->IsPassphraseRequired()) {
    437     // It's already true that a passphrase is required; don't wait.
    438     return true;
    439   }
    440 
    441   StatusChangeChecker passphrase_required_checker(
    442       base::Bind(&::IsPassphraseRequired, base::Unretained(this)),
    443       "IsPassphraseRequired");
    444   return AwaitStatusChange(&passphrase_required_checker,
    445                            "AwaitPassphraseRequired");
    446 }
    447 
    448 bool ProfileSyncServiceHarness::AwaitPassphraseAccepted() {
    449   DVLOG(1) << GetClientInfoString("AwaitPassphraseAccepted");
    450   if (IsSyncDisabled()) {
    451     LOG(ERROR) << "Sync disabled for " << profile_debug_name_ << ".";
    452     return false;
    453   }
    454 
    455   if (!service()->IsPassphraseRequired() &&
    456       service()->IsUsingSecondaryPassphrase()) {
    457     // Passphrase is already accepted; don't wait.
    458     FinishSyncSetup();
    459     return true;
    460   }
    461 
    462   StatusChangeChecker passphrase_accepted_checker(
    463       base::Bind(&::IsPassphraseAccepted, base::Unretained(this)),
    464       "IsPassphraseAccepted");
    465   bool return_value = AwaitStatusChange(&passphrase_accepted_checker,
    466                                         "AwaitPassphraseAccepted");
    467   if (return_value)
    468     FinishSyncSetup();
    469   return return_value;
    470 }
    471 
    472 bool ProfileSyncServiceHarness::AwaitBackendInitialized() {
    473   DVLOG(1) << GetClientInfoString("AwaitBackendInitialized");
    474   if (service()->sync_initialized()) {
    475     // The sync backend host has already been initialized; don't wait.
    476     return true;
    477   }
    478 
    479   StatusChangeChecker backend_initialized_checker(
    480       base::Bind(&DoneWaitingForBackendInitialization,
    481                  base::Unretained(this)),
    482       "DoneWaitingForBackendInitialization");
    483   AwaitStatusChange(&backend_initialized_checker, "AwaitBackendInitialized");
    484   return service()->sync_initialized();
    485 }
    486 
    487 bool ProfileSyncServiceHarness::AwaitDataSyncCompletion() {
    488   DVLOG(1) << GetClientInfoString("AwaitDataSyncCompletion");
    489 
    490   DCHECK(service()->sync_initialized());
    491   DCHECK(!IsSyncDisabled());
    492 
    493   if (IsDataSynced()) {
    494     // Client is already synced; don't wait.
    495     return true;
    496   }
    497 
    498   StatusChangeChecker data_synced_checker(
    499       base::Bind(&ProfileSyncServiceHarness::IsDataSynced,
    500                  base::Unretained(this)),
    501       "IsDataSynced");
    502   return AwaitStatusChange(&data_synced_checker, "AwaitDataSyncCompletion");
    503 }
    504 
    505 bool ProfileSyncServiceHarness::AwaitFullSyncCompletion() {
    506   DVLOG(1) << GetClientInfoString("AwaitFullSyncCompletion");
    507   if (IsSyncDisabled()) {
    508     LOG(ERROR) << "Sync disabled for " << profile_debug_name_ << ".";
    509     return false;
    510   }
    511 
    512   if (IsFullySynced()) {
    513     // Client is already synced; don't wait.
    514     return true;
    515   }
    516 
    517   DCHECK(service()->sync_initialized());
    518   StatusChangeChecker fully_synced_checker(
    519       base::Bind(&DoneWaitingForFullSync, base::Unretained(this)),
    520       "DoneWaitingForFullSync");
    521   AwaitStatusChange(&fully_synced_checker, "AwaitFullSyncCompletion");
    522   return IsFullySynced();
    523 }
    524 
    525 bool ProfileSyncServiceHarness::AwaitSyncDisabled() {
    526   DCHECK(service()->HasSyncSetupCompleted());
    527   DCHECK(!IsSyncDisabled());
    528   StatusChangeChecker sync_disabled_checker(
    529       base::Bind(&ProfileSyncServiceHarness::IsSyncDisabled,
    530                  base::Unretained(this)),
    531       "IsSyncDisabled");
    532   return AwaitStatusChange(&sync_disabled_checker, "AwaitSyncDisabled");
    533 }
    534 
    535 // TODO(rsimha): Move this method from PSSHarness to the class that uses it.
    536 bool ProfileSyncServiceHarness::AwaitExponentialBackoffVerification() {
    537   const SyncSessionSnapshot& snap = GetLastSessionSnapshot();
    538   retry_verifier_.reset(new RetryVerifier());
    539   retry_verifier_->Initialize(snap);
    540   StatusChangeChecker exponential_backoff_checker(
    541       base::Bind(&ProfileSyncServiceHarness::IsExponentialBackoffDone,
    542                  base::Unretained(this)),
    543       "IsExponentialBackoffDone");
    544   AwaitStatusChange(&exponential_backoff_checker,
    545                     "AwaitExponentialBackoffVerification");
    546   return retry_verifier_->Succeeded();
    547 }
    548 
    549 bool ProfileSyncServiceHarness::AwaitActionableError() {
    550   ProfileSyncService::Status status = GetStatus();
    551   CHECK(status.sync_protocol_error.action == syncer::UNKNOWN_ACTION);
    552   StatusChangeChecker actionable_error_checker(
    553       base::Bind(&HasActionableError, base::Unretained(this)),
    554       "HasActionableError");
    555   return AwaitStatusChange(&actionable_error_checker, "AwaitActionableError");
    556 }
    557 
    558 bool ProfileSyncServiceHarness::AwaitMigration(
    559     syncer::ModelTypeSet expected_migrated_types) {
    560   DVLOG(1) << GetClientInfoString("AwaitMigration");
    561   DVLOG(1) << profile_debug_name_ << ": waiting until migration is done for "
    562           << syncer::ModelTypeSetToString(expected_migrated_types);
    563   while (true) {
    564     bool migration_finished = migrated_types_.HasAll(expected_migrated_types);
    565     DVLOG(1) << "Migrated types "
    566              << syncer::ModelTypeSetToString(migrated_types_)
    567              << (migration_finished ? " contains " : " does not contain ")
    568              << syncer::ModelTypeSetToString(expected_migrated_types);
    569     if (migration_finished) {
    570       return true;
    571     }
    572 
    573     if (!HasPendingBackendMigration()) {
    574       StatusChangeChecker pending_migration_checker(
    575           base::Bind(&ProfileSyncServiceHarness::HasPendingBackendMigration,
    576                      base::Unretained(this)),
    577           "HasPendingBackendMigration");
    578       if (!AwaitStatusChange(&pending_migration_checker,
    579                              "AwaitMigration Start")) {
    580         DVLOG(1) << profile_debug_name_ << ": Migration did not start";
    581         return false;
    582       }
    583     }
    584 
    585     StatusChangeChecker migration_finished_checker(
    586         base::Bind(&::NoPendingBackendMigration, base::Unretained(this)),
    587         "NoPendingBackendMigration");
    588     if (!AwaitStatusChange(&migration_finished_checker,
    589                            "AwaitMigration Finish")) {
    590       DVLOG(1) << profile_debug_name_ << ": Migration did not finish";
    591       return false;
    592     }
    593 
    594     // We must use AwaitDataSyncCompletion rather than the more common
    595     // AwaitFullSyncCompletion.  As long as crbug.com/97780 is open, we will
    596     // rely on self-notifications to ensure that progress markers are updated,
    597     // which allows AwaitFullSyncCompletion to return.  However, in some
    598     // migration tests these notifications are completely disabled, so the
    599     // progress markers do not get updated.  This is why we must use the less
    600     // strict condition, AwaitDataSyncCompletion.
    601     if (!AwaitDataSyncCompletion())
    602       return false;
    603   }
    604 }
    605 
    606 bool ProfileSyncServiceHarness::AwaitMutualSyncCycleCompletion(
    607     ProfileSyncServiceHarness* partner) {
    608   DVLOG(1) << GetClientInfoString("AwaitMutualSyncCycleCompletion");
    609   if (!AwaitFullSyncCompletion())
    610     return false;
    611   return partner->WaitUntilProgressMarkersMatch(this);
    612 }
    613 
    614 bool ProfileSyncServiceHarness::AwaitGroupSyncCycleCompletion(
    615     std::vector<ProfileSyncServiceHarness*>& partners) {
    616   DVLOG(1) << GetClientInfoString("AwaitGroupSyncCycleCompletion");
    617   if (!AwaitFullSyncCompletion())
    618     return false;
    619   bool return_value = true;
    620   for (std::vector<ProfileSyncServiceHarness*>::iterator it =
    621       partners.begin(); it != partners.end(); ++it) {
    622     if ((this != *it) && (!(*it)->IsSyncDisabled())) {
    623       return_value = return_value &&
    624           (*it)->WaitUntilProgressMarkersMatch(this);
    625     }
    626   }
    627   return return_value;
    628 }
    629 
    630 // static
    631 bool ProfileSyncServiceHarness::AwaitQuiescence(
    632     std::vector<ProfileSyncServiceHarness*>& clients) {
    633   DVLOG(1) << "AwaitQuiescence.";
    634   bool return_value = true;
    635   for (std::vector<ProfileSyncServiceHarness*>::iterator it =
    636       clients.begin(); it != clients.end(); ++it) {
    637     if (!(*it)->IsSyncDisabled()) {
    638       return_value = return_value &&
    639           (*it)->AwaitGroupSyncCycleCompletion(clients);
    640     }
    641   }
    642   return return_value;
    643 }
    644 
    645 bool ProfileSyncServiceHarness::WaitUntilProgressMarkersMatch(
    646     ProfileSyncServiceHarness* partner) {
    647   DVLOG(1) << GetClientInfoString("WaitUntilProgressMarkersMatch");
    648   if (IsSyncDisabled()) {
    649     LOG(ERROR) << "Sync disabled for " << profile_debug_name_ << ".";
    650     return false;
    651   }
    652 
    653   // TODO(rsimha): Replace the mechanism of matching up progress markers with
    654   // one that doesn't require every client to have the same progress markers.
    655   DCHECK(!progress_marker_partner_);
    656   progress_marker_partner_ = partner;
    657   bool return_value = false;
    658   if (MatchesPartnerClient()) {
    659     // Progress markers already match; don't wait.
    660     return_value = true;
    661   } else {
    662     partner->service()->AddObserver(this);
    663     StatusChangeChecker matches_other_client_checker(
    664         base::Bind(&ProfileSyncServiceHarness::MatchesPartnerClient,
    665                    base::Unretained(this)),
    666         "MatchesPartnerClient");
    667     return_value = AwaitStatusChange(&matches_other_client_checker,
    668                                      "WaitUntilProgressMarkersMatch");
    669     partner->service()->RemoveObserver(this);
    670   }
    671   progress_marker_partner_ = NULL;
    672   return return_value;
    673 }
    674 
    675 bool ProfileSyncServiceHarness::AwaitStatusChange(
    676     StatusChangeChecker* checker, const std::string& source) {
    677   DVLOG(1) << GetClientInfoString("AwaitStatusChange");
    678 
    679   if (IsSyncDisabled()) {
    680     LOG(ERROR) << "Sync disabled for " << profile_debug_name_ << ".";
    681     return false;
    682   }
    683 
    684   DCHECK(status_change_checker_ == NULL);
    685   status_change_checker_ = checker;
    686 
    687   scoped_refptr<StateChangeTimeoutEvent> timeout_signal(
    688       new StateChangeTimeoutEvent(this));
    689   {
    690     base::MessageLoop* loop = base::MessageLoop::current();
    691     base::MessageLoop::ScopedNestableTaskAllower allow(loop);
    692     loop->PostDelayedTask(
    693         FROM_HERE,
    694         base::Bind(&StateChangeTimeoutEvent::Callback,
    695                    timeout_signal.get()),
    696         base::TimeDelta::FromMilliseconds(kSyncOperationTimeoutMs));
    697     loop->Run();
    698   }
    699 
    700   status_change_checker_ = NULL;
    701 
    702   if (timeout_signal->Abort()) {
    703     DVLOG(1) << GetClientInfoString("AwaitStatusChange succeeded");
    704     return true;
    705   } else {
    706     DVLOG(0) << GetClientInfoString(base::StringPrintf(
    707         "AwaitStatusChange called from %s timed out", source.c_str()));
    708     return false;
    709   }
    710 }
    711 
    712 std::string ProfileSyncServiceHarness::GenerateFakeOAuth2RefreshTokenString() {
    713   return base::StringPrintf("oauth2_refresh_token_%d",
    714                             ++oauth2_refesh_token_number_);
    715 }
    716 
    717 ProfileSyncService::Status ProfileSyncServiceHarness::GetStatus() const {
    718   DCHECK(service() != NULL) << "GetStatus(): service() is NULL.";
    719   ProfileSyncService::Status result;
    720   service()->QueryDetailedSyncStatus(&result);
    721   return result;
    722 }
    723 
    724 bool ProfileSyncServiceHarness::IsExponentialBackoffDone() const {
    725   const SyncSessionSnapshot& snap = GetLastSessionSnapshot();
    726   retry_verifier_->VerifyRetryInterval(snap);
    727   return (retry_verifier_->done());
    728 }
    729 
    730 bool ProfileSyncServiceHarness::IsSyncDisabled() const {
    731   return !service()->setup_in_progress() &&
    732          !service()->HasSyncSetupCompleted();
    733 }
    734 
    735 bool ProfileSyncServiceHarness::HasAuthError() const {
    736   return service()->GetAuthError().state() ==
    737              GoogleServiceAuthError::INVALID_GAIA_CREDENTIALS ||
    738          service()->GetAuthError().state() ==
    739              GoogleServiceAuthError::SERVICE_ERROR ||
    740          service()->GetAuthError().state() ==
    741              GoogleServiceAuthError::REQUEST_CANCELED;
    742 }
    743 
    744 // We use this function to share code between IsFullySynced and IsDataSynced.
    745 bool ProfileSyncServiceHarness::IsDataSyncedImpl() const {
    746   return ServiceIsPushingChanges() &&
    747          GetStatus().notifications_enabled &&
    748          !service()->HasUnsyncedItems() &&
    749          !HasPendingBackendMigration();
    750 }
    751 
    752 bool ProfileSyncServiceHarness::IsDataSynced() const {
    753   if (service() == NULL) {
    754     DVLOG(1) << GetClientInfoString("IsDataSynced(): false");
    755     return false;
    756   }
    757 
    758   bool is_data_synced = IsDataSyncedImpl();
    759 
    760   DVLOG(1) << GetClientInfoString(
    761       is_data_synced ? "IsDataSynced: true" : "IsDataSynced: false");
    762   return is_data_synced;
    763 }
    764 
    765 bool ProfileSyncServiceHarness::IsFullySynced() const {
    766   if (service() == NULL) {
    767     DVLOG(1) << GetClientInfoString("IsFullySynced: false");
    768     return false;
    769   }
    770   // If we didn't try to commit anything in the previous cycle, there's a
    771   // good chance that we're now fully up to date.
    772   const SyncSessionSnapshot& snap = GetLastSessionSnapshot();
    773   bool is_fully_synced =
    774       snap.model_neutral_state().num_successful_commits == 0
    775       && snap.model_neutral_state().commit_result == syncer::SYNCER_OK
    776       && IsDataSyncedImpl();
    777 
    778   DVLOG(1) << GetClientInfoString(
    779       is_fully_synced ? "IsFullySynced: true" : "IsFullySynced: false");
    780   return is_fully_synced;
    781 }
    782 
    783 void ProfileSyncServiceHarness::FinishSyncSetup() {
    784   service()->SetSetupInProgress(false);
    785   service()->SetSyncSetupCompleted();
    786 }
    787 
    788 bool ProfileSyncServiceHarness::HasPendingBackendMigration() const {
    789   browser_sync::BackendMigrator* migrator =
    790       service()->GetBackendMigratorForTest();
    791   return migrator && migrator->state() != browser_sync::BackendMigrator::IDLE;
    792 }
    793 
    794 bool ProfileSyncServiceHarness::AutoStartEnabled() {
    795   return service()->auto_start_enabled();
    796 }
    797 
    798 bool ProfileSyncServiceHarness::MatchesPartnerClient() const {
    799   // TODO(akalin): Shouldn't this belong with the intersection check?
    800   // Otherwise, this function isn't symmetric.
    801   DCHECK(progress_marker_partner_);
    802   if (!IsFullySynced()) {
    803     DVLOG(2) << profile_debug_name_ << ": not synced, assuming doesn't match";
    804     return false;
    805   }
    806 
    807   // Only look for a match if we have at least one enabled datatype in
    808   // common with the partner client.
    809   const syncer::ModelTypeSet common_types =
    810       Intersection(service()->GetActiveDataTypes(),
    811                    progress_marker_partner_->service()->GetActiveDataTypes());
    812 
    813   DVLOG(2) << profile_debug_name_ << ", "
    814            << progress_marker_partner_->profile_debug_name_
    815            << ": common types are "
    816            << syncer::ModelTypeSetToString(common_types);
    817 
    818   if (!common_types.Empty() && !progress_marker_partner_->IsFullySynced()) {
    819     DVLOG(2) << "non-empty common types and "
    820              << progress_marker_partner_->profile_debug_name_
    821              << " isn't synced";
    822     return false;
    823   }
    824 
    825   for (syncer::ModelTypeSet::Iterator i = common_types.First();
    826        i.Good(); i.Inc()) {
    827     const std::string marker = GetSerializedProgressMarker(i.Get());
    828     const std::string partner_marker =
    829         progress_marker_partner_->GetSerializedProgressMarker(i.Get());
    830     if (marker != partner_marker) {
    831       if (VLOG_IS_ON(2)) {
    832         std::string marker_base64, partner_marker_base64;
    833         base::Base64Encode(marker, &marker_base64);
    834         base::Base64Encode(partner_marker, &partner_marker_base64);
    835         DVLOG(2) << syncer::ModelTypeToString(i.Get()) << ": "
    836                  << profile_debug_name_ << " progress marker = "
    837                  << marker_base64 << ", "
    838                  << progress_marker_partner_->profile_debug_name_
    839                  << " partner progress marker = "
    840                  << partner_marker_base64;
    841       }
    842       return false;
    843     }
    844   }
    845   return true;
    846 }
    847 
    848 SyncSessionSnapshot ProfileSyncServiceHarness::GetLastSessionSnapshot() const {
    849   DCHECK(service() != NULL) << "Sync service has not yet been set up.";
    850   if (service()->sync_initialized()) {
    851     return service()->GetLastSessionSnapshot();
    852   }
    853   return SyncSessionSnapshot();
    854 }
    855 
    856 bool ProfileSyncServiceHarness::EnableSyncForDatatype(
    857     syncer::ModelType datatype) {
    858   DVLOG(1) << GetClientInfoString(
    859       "EnableSyncForDatatype("
    860       + std::string(syncer::ModelTypeToString(datatype)) + ")");
    861 
    862   if (IsSyncDisabled())
    863     return SetupSync(syncer::ModelTypeSet(datatype));
    864 
    865   if (service() == NULL) {
    866     LOG(ERROR) << "EnableSyncForDatatype(): service() is null.";
    867     return false;
    868   }
    869 
    870   syncer::ModelTypeSet synced_datatypes = service()->GetPreferredDataTypes();
    871   if (synced_datatypes.Has(datatype)) {
    872     DVLOG(1) << "EnableSyncForDatatype(): Sync already enabled for datatype "
    873              << syncer::ModelTypeToString(datatype)
    874              << " on " << profile_debug_name_ << ".";
    875     return true;
    876   }
    877 
    878   synced_datatypes.Put(syncer::ModelTypeFromInt(datatype));
    879   service()->OnUserChoseDatatypes(false, synced_datatypes);
    880   if (AwaitDataSyncCompletion()) {
    881     DVLOG(1) << "EnableSyncForDatatype(): Enabled sync for datatype "
    882              << syncer::ModelTypeToString(datatype)
    883              << " on " << profile_debug_name_ << ".";
    884     return true;
    885   }
    886 
    887   DVLOG(0) << GetClientInfoString("EnableSyncForDatatype failed");
    888   return false;
    889 }
    890 
    891 bool ProfileSyncServiceHarness::DisableSyncForDatatype(
    892     syncer::ModelType datatype) {
    893   DVLOG(1) << GetClientInfoString(
    894       "DisableSyncForDatatype("
    895       + std::string(syncer::ModelTypeToString(datatype)) + ")");
    896 
    897   if (service() == NULL) {
    898     LOG(ERROR) << "DisableSyncForDatatype(): service() is null.";
    899     return false;
    900   }
    901 
    902   syncer::ModelTypeSet synced_datatypes = service()->GetPreferredDataTypes();
    903   if (!synced_datatypes.Has(datatype)) {
    904     DVLOG(1) << "DisableSyncForDatatype(): Sync already disabled for datatype "
    905              << syncer::ModelTypeToString(datatype)
    906              << " on " << profile_debug_name_ << ".";
    907     return true;
    908   }
    909 
    910   synced_datatypes.RetainAll(syncer::UserSelectableTypes());
    911   synced_datatypes.Remove(datatype);
    912   service()->OnUserChoseDatatypes(false, synced_datatypes);
    913   if (AwaitFullSyncCompletion()) {
    914     DVLOG(1) << "DisableSyncForDatatype(): Disabled sync for datatype "
    915              << syncer::ModelTypeToString(datatype)
    916              << " on " << profile_debug_name_ << ".";
    917     return true;
    918   }
    919 
    920   DVLOG(0) << GetClientInfoString("DisableSyncForDatatype failed");
    921   return false;
    922 }
    923 
    924 bool ProfileSyncServiceHarness::EnableSyncForAllDatatypes() {
    925   DVLOG(1) << GetClientInfoString("EnableSyncForAllDatatypes");
    926 
    927   if (IsSyncDisabled())
    928     return SetupSync();
    929 
    930   if (service() == NULL) {
    931     LOG(ERROR) << "EnableSyncForAllDatatypes(): service() is null.";
    932     return false;
    933   }
    934 
    935   service()->OnUserChoseDatatypes(true, syncer::ModelTypeSet::All());
    936   if (AwaitFullSyncCompletion()) {
    937     DVLOG(1) << "EnableSyncForAllDatatypes(): Enabled sync for all datatypes "
    938              << "on " << profile_debug_name_ << ".";
    939     return true;
    940   }
    941 
    942   DVLOG(0) << GetClientInfoString("EnableSyncForAllDatatypes failed");
    943   return false;
    944 }
    945 
    946 bool ProfileSyncServiceHarness::DisableSyncForAllDatatypes() {
    947   DVLOG(1) << GetClientInfoString("DisableSyncForAllDatatypes");
    948 
    949   if (service() == NULL) {
    950     LOG(ERROR) << "DisableSyncForAllDatatypes(): service() is null.";
    951     return false;
    952   }
    953 
    954   service()->DisableForUser();
    955 
    956   DVLOG(1) << "DisableSyncForAllDatatypes(): Disabled sync for all "
    957            << "datatypes on " << profile_debug_name_;
    958   return true;
    959 }
    960 
    961 std::string ProfileSyncServiceHarness::GetSerializedProgressMarker(
    962     syncer::ModelType model_type) const {
    963   const SyncSessionSnapshot& snap = GetLastSessionSnapshot();
    964   const syncer::ProgressMarkerMap& markers_map =
    965       snap.download_progress_markers();
    966 
    967   syncer::ProgressMarkerMap::const_iterator it =
    968       markers_map.find(model_type);
    969   return (it != markers_map.end()) ? it->second : std::string();
    970 }
    971 
    972 std::string ProfileSyncServiceHarness::GetClientInfoString(
    973     const std::string& message) const {
    974   std::stringstream os;
    975   os << profile_debug_name_ << ": " << message << ": ";
    976   if (service()) {
    977     const SyncSessionSnapshot& snap = GetLastSessionSnapshot();
    978     const ProfileSyncService::Status& status = GetStatus();
    979     // Capture select info from the sync session snapshot and syncer status.
    980     // TODO(rsimha): Audit the list of fields below, and eventually eliminate
    981     // the use of the sync session snapshot. See crbug.com/323380.
    982     os << ", has_unsynced_items: "
    983        << (service()->sync_initialized() ? service()->HasUnsyncedItems() : 0)
    984        << ", did_commit: "
    985        << (snap.model_neutral_state().num_successful_commits == 0 &&
    986            snap.model_neutral_state().commit_result == syncer::SYNCER_OK)
    987        << ", encryption conflicts: "
    988        << snap.num_encryption_conflicts()
    989        << ", hierarchy conflicts: "
    990        << snap.num_hierarchy_conflicts()
    991        << ", server conflicts: "
    992        << snap.num_server_conflicts()
    993        << ", num_updates_downloaded : "
    994        << snap.model_neutral_state().num_updates_downloaded_total
    995        << ", passphrase_required_reason: "
    996        << syncer::PassphraseRequiredReasonToString(
    997            service()->passphrase_required_reason())
    998        << ", notifications_enabled: "
    999        << status.notifications_enabled
   1000        << ", service_is_pushing_changes: "
   1001        << ServiceIsPushingChanges()
   1002        << ", has_pending_backend_migration: "
   1003        << HasPendingBackendMigration();
   1004   } else {
   1005     os << "Sync service not available";
   1006   }
   1007   return os.str();
   1008 }
   1009 
   1010 bool ProfileSyncServiceHarness::EnableEncryption() {
   1011   if (IsEncryptionComplete())
   1012     return true;
   1013   service()->EnableEncryptEverything();
   1014 
   1015   // In order to kick off the encryption we have to reconfigure. Just grab the
   1016   // currently synced types and use them.
   1017   const syncer::ModelTypeSet synced_datatypes =
   1018       service()->GetPreferredDataTypes();
   1019   bool sync_everything =
   1020       synced_datatypes.Equals(syncer::ModelTypeSet::All());
   1021   service()->OnUserChoseDatatypes(sync_everything, synced_datatypes);
   1022 
   1023   // Wait some time to let the enryption finish.
   1024   return WaitForEncryption();
   1025 }
   1026 
   1027 bool ProfileSyncServiceHarness::WaitForEncryption() {
   1028   if (IsEncryptionComplete()) {
   1029     // Encryption is already complete; do not wait.
   1030     return true;
   1031   }
   1032 
   1033   StatusChangeChecker encryption_complete_checker(
   1034       base::Bind(&ProfileSyncServiceHarness::IsEncryptionComplete,
   1035                  base::Unretained(this)),
   1036       "IsEncryptionComplete");
   1037   return AwaitStatusChange(&encryption_complete_checker, "WaitForEncryption");
   1038 }
   1039 
   1040 bool ProfileSyncServiceHarness::IsEncryptionComplete() const {
   1041   bool is_encryption_complete = service()->EncryptEverythingEnabled() &&
   1042                                 !service()->encryption_pending();
   1043   DVLOG(2) << "Encryption is "
   1044            << (is_encryption_complete ? "" : "not ")
   1045            << "complete; Encrypted types = "
   1046            << syncer::ModelTypeSetToString(service()->GetEncryptedDataTypes());
   1047   return is_encryption_complete;
   1048 }
   1049 
   1050 bool ProfileSyncServiceHarness::IsTypeRunning(syncer::ModelType type) {
   1051   browser_sync::DataTypeController::StateMap state_map;
   1052   service()->GetDataTypeControllerStates(&state_map);
   1053   return (state_map.count(type) != 0 &&
   1054           state_map[type] == browser_sync::DataTypeController::RUNNING);
   1055 }
   1056 
   1057 bool ProfileSyncServiceHarness::IsTypePreferred(syncer::ModelType type) {
   1058   return service()->GetPreferredDataTypes().Has(type);
   1059 }
   1060 
   1061 size_t ProfileSyncServiceHarness::GetNumEntries() const {
   1062   return GetLastSessionSnapshot().num_entries();
   1063 }
   1064 
   1065 size_t ProfileSyncServiceHarness::GetNumDatatypes() const {
   1066   browser_sync::DataTypeController::StateMap state_map;
   1067   service()->GetDataTypeControllerStates(&state_map);
   1068   return state_map.size();
   1069 }
   1070 
   1071 std::string ProfileSyncServiceHarness::GetServiceStatus() {
   1072   scoped_ptr<DictionaryValue> value(
   1073       sync_ui_util::ConstructAboutInformation(service()));
   1074   std::string service_status;
   1075   base::JSONWriter::WriteWithOptions(value.get(),
   1076                                      base::JSONWriter::OPTIONS_PRETTY_PRINT,
   1077                                      &service_status);
   1078   return service_status;
   1079 }
   1080