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