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.
5 #include "chrome/browser/sync/profile_sync_service_harness.h"
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.h"
23 #include "chrome/browser/profiles/profile.h"
24 #include "chrome/browser/signin/signin_manager.h"
25 #include "chrome/browser/sync/about_sync_util.h"
26 #include "chrome/browser/sync/glue/data_type_controller.h"
27 #include "chrome/browser/sync/profile_sync_service_factory.h"
28 #include "chrome/common/chrome_switches.h"
29 #include "sync/internal_api/public/base/progress_marker_map.h"
30 #include "sync/internal_api/public/sessions/sync_session_snapshot.h"
31 #include "sync/internal_api/public/util/sync_string_conversions.h"
33 using syncer::sessions::SyncSessionSnapshot
;
35 // TODO(rsimha): Remove the following lines once crbug.com/91863 is fixed.
36 // The amount of time for which we wait for a live sync operation to complete.
37 static const int kLiveSyncOperationTimeoutMs
= 45000;
39 // The amount of time we wait for test cases that verify exponential backoff.
40 static const int kExponentialBackoffVerificationTimeoutMs
= 60000;
42 // Simple class to implement a timeout using PostDelayedTask. If it is not
43 // aborted before picked up by a message queue, then it asserts with the message
44 // provided. This class is not thread safe.
45 class StateChangeTimeoutEvent
46 : public base::RefCountedThreadSafe
<StateChangeTimeoutEvent
> {
48 StateChangeTimeoutEvent(ProfileSyncServiceHarness
* caller
,
49 const std::string
& message
);
51 // The entry point to the class from PostDelayedTask.
54 // Cancels the actions of the callback. Returns true if success, false
55 // if the callback has already timed out.
59 friend class base::RefCountedThreadSafe
<StateChangeTimeoutEvent
>;
61 ~StateChangeTimeoutEvent();
66 // Due to synchronization of the IO loop, the caller will always be alive
67 // if the class is not aborted.
68 ProfileSyncServiceHarness
* caller_
;
70 // Informative message to assert in the case of a timeout.
73 DISALLOW_COPY_AND_ASSIGN(StateChangeTimeoutEvent
);
76 StateChangeTimeoutEvent::StateChangeTimeoutEvent(
77 ProfileSyncServiceHarness
* caller
,
78 const std::string
& message
)
79 : aborted_(false), did_timeout_(false), caller_(caller
), message_(message
) {
82 StateChangeTimeoutEvent::~StateChangeTimeoutEvent() {
85 void StateChangeTimeoutEvent::Callback() {
87 if (!caller_
->RunStateChangeMachine()) {
88 // Report the message.
90 DCHECK(!aborted_
) << message_
;
91 caller_
->SignalStateComplete();
96 bool StateChangeTimeoutEvent::Abort() {
102 ProfileSyncServiceHarness::ProfileSyncServiceHarness(
104 const std::string
& username
,
105 const std::string
& password
)
106 : waiting_for_encryption_type_(syncer::UNSPECIFIED
),
107 wait_state_(INITIAL_WAIT_STATE
),
110 progress_marker_partner_(NULL
),
113 profile_debug_name_(profile
->GetDebugName()),
114 waiting_for_status_change_(false) {
115 if (IsSyncAlreadySetup()) {
116 service_
= ProfileSyncServiceFactory::GetInstance()->GetForProfile(
118 service_
->AddObserver(this);
119 ignore_result(TryListeningToMigrationEvents());
120 wait_state_
= FULLY_SYNCED
;
124 ProfileSyncServiceHarness::~ProfileSyncServiceHarness() {
125 if (service_
->HasObserver(this))
126 service_
->RemoveObserver(this);
130 ProfileSyncServiceHarness
* ProfileSyncServiceHarness::CreateAndAttach(
132 ProfileSyncServiceFactory
* f
= ProfileSyncServiceFactory::GetInstance();
133 if (!f
->HasProfileSyncService(profile
)) {
134 NOTREACHED() << "Profile has never signed into sync.";
137 return new ProfileSyncServiceHarness(profile
, std::string(), std::string());
140 void ProfileSyncServiceHarness::SetCredentials(const std::string
& username
,
141 const std::string
& password
) {
142 username_
= username
;
143 password_
= password
;
146 bool ProfileSyncServiceHarness::IsSyncAlreadySetup() {
147 return ProfileSyncServiceFactory::GetInstance()->HasProfileSyncService(
151 bool ProfileSyncServiceHarness::SetupSync() {
152 bool result
= SetupSync(syncer::ModelTypeSet::All());
153 if (result
== false) {
154 std::string status
= GetServiceStatus();
155 LOG(ERROR
) << profile_debug_name_
156 << ": SetupSync failed. Syncer status:\n" << status
;
158 DVLOG(1) << profile_debug_name_
<< ": SetupSync successful.";
163 bool ProfileSyncServiceHarness::SetupSync(
164 syncer::ModelTypeSet synced_datatypes
) {
165 // Initialize the sync client's profile sync service object.
167 ProfileSyncServiceFactory::GetInstance()->GetForProfile(profile_
);
168 if (service_
== NULL
) {
169 LOG(ERROR
) << "SetupSync(): service_ is null.";
173 // Subscribe sync client to notifications from the profile sync service.
174 if (!service_
->HasObserver(this))
175 service_
->AddObserver(this);
177 // Tell the sync service that setup is in progress so we don't start syncing
178 // until we've finished configuration.
179 service_
->SetSetupInProgress(true);
181 // Authenticate sync client using GAIA credentials.
183 ->StartSignIn(username_
, password_
, std::string(), std::string());
185 // Wait for the OnBackendInitialized() callback.
186 if (!AwaitBackendInitialized()) {
187 LOG(ERROR
) << "OnBackendInitialized() not seen after "
188 << kLiveSyncOperationTimeoutMs
/ 1000
193 // Make sure that initial sync wasn't blocked by a missing passphrase.
194 if (wait_state_
== SET_PASSPHRASE_FAILED
) {
195 LOG(ERROR
) << "A passphrase is required for decryption. Sync cannot proceed"
196 " until SetDecryptionPassphrase is called.";
200 // Make sure that initial sync wasn't blocked by rejected credentials.
201 if (wait_state_
== CREDENTIALS_REJECTED
) {
202 LOG(ERROR
) << "Credentials were rejected. Sync cannot proceed.";
206 // Choose the datatypes to be synced. If all datatypes are to be synced,
207 // set sync_everything to true; otherwise, set it to false.
208 bool sync_everything
=
209 synced_datatypes
.Equals(syncer::ModelTypeSet::All());
210 service()->OnUserChoseDatatypes(sync_everything
, synced_datatypes
);
212 // Notify ProfileSyncService that we are done with configuration.
213 service_
->SetSetupInProgress(false);
215 // Subscribe sync client to notifications from the backend migrator
216 // (possible only after choosing data types).
217 if (!TryListeningToMigrationEvents()) {
222 // Set an implicit passphrase for encryption if an explicit one hasn't already
223 // been set. If an explicit passphrase has been set, immediately return false,
224 // since a decryption passphrase is required.
225 if (!service_
->IsUsingSecondaryPassphrase()) {
226 service_
->SetEncryptionPassphrase(password_
, ProfileSyncService::IMPLICIT
);
228 LOG(ERROR
) << "A passphrase is required for decryption. Sync cannot proceed"
229 " until SetDecryptionPassphrase is called.";
233 // Wait for initial sync cycle to be completed.
234 DCHECK_EQ(wait_state_
, WAITING_FOR_INITIAL_SYNC
);
235 if (!AwaitStatusChangeWithTimeout(kLiveSyncOperationTimeoutMs
,
236 "Waiting for initial sync cycle to complete.")) {
237 LOG(ERROR
) << "Initial sync cycle did not complete after "
238 << kLiveSyncOperationTimeoutMs
/ 1000
243 // Make sure that initial sync wasn't blocked by a missing passphrase.
244 if (wait_state_
== SET_PASSPHRASE_FAILED
) {
245 LOG(ERROR
) << "A passphrase is required for decryption. Sync cannot proceed"
246 " until SetDecryptionPassphrase is called.";
250 // Make sure that initial sync wasn't blocked by rejected credentials.
251 if (wait_state_
== CREDENTIALS_REJECTED
) {
252 LOG(ERROR
) << "Credentials were rejected. Sync cannot proceed.";
256 // Indicate to the browser that sync setup is complete.
257 service()->SetSyncSetupCompleted();
262 bool ProfileSyncServiceHarness::TryListeningToMigrationEvents() {
263 browser_sync::BackendMigrator
* migrator
=
264 service_
->GetBackendMigratorForTest();
265 if (migrator
&& !migrator
->HasMigrationObserver(this)) {
266 migrator
->AddMigrationObserver(this);
272 void ProfileSyncServiceHarness::SignalStateCompleteWithNextState(
273 WaitState next_state
) {
274 wait_state_
= next_state
;
275 SignalStateComplete();
278 void ProfileSyncServiceHarness::SignalStateComplete() {
279 if (waiting_for_status_change_
)
280 MessageLoop::current()->QuitWhenIdle();
283 bool ProfileSyncServiceHarness::RunStateChangeMachine() {
284 WaitState original_wait_state
= wait_state_
;
285 switch (wait_state_
) {
286 case WAITING_FOR_ON_BACKEND_INITIALIZED
: {
287 DVLOG(1) << GetClientInfoString("WAITING_FOR_ON_BACKEND_INITIALIZED");
288 if (service()->GetAuthError().state() ==
289 GoogleServiceAuthError::INVALID_GAIA_CREDENTIALS
) {
290 // Our credentials were rejected. Do not wait any more.
291 SignalStateCompleteWithNextState(CREDENTIALS_REJECTED
);
294 if (service()->sync_initialized()) {
295 // The sync backend is initialized.
296 SignalStateCompleteWithNextState(WAITING_FOR_INITIAL_SYNC
);
300 case WAITING_FOR_INITIAL_SYNC
: {
301 DVLOG(1) << GetClientInfoString("WAITING_FOR_INITIAL_SYNC");
302 if (IsFullySynced()) {
303 // The first sync cycle is now complete. We can start running tests.
304 SignalStateCompleteWithNextState(FULLY_SYNCED
);
307 if (service()->passphrase_required_reason() ==
308 syncer::REASON_DECRYPTION
) {
309 // A passphrase is required for decryption and we don't have it. Do not
311 SignalStateCompleteWithNextState(SET_PASSPHRASE_FAILED
);
314 if (service()->GetAuthError().state() ==
315 GoogleServiceAuthError::INVALID_GAIA_CREDENTIALS
) {
316 // Our credentials were rejected. Do not wait any more.
317 SignalStateCompleteWithNextState(CREDENTIALS_REJECTED
);
322 case WAITING_FOR_FULL_SYNC
: {
323 DVLOG(1) << GetClientInfoString("WAITING_FOR_FULL_SYNC");
324 if (IsFullySynced()) {
325 // The sync cycle we were waiting for is complete.
326 SignalStateCompleteWithNextState(FULLY_SYNCED
);
331 case WAITING_FOR_DATA_SYNC
: {
332 if (IsDataSynced()) {
333 SignalStateCompleteWithNextState(FULLY_SYNCED
);
338 case WAITING_FOR_UPDATES
: {
339 DVLOG(1) << GetClientInfoString("WAITING_FOR_UPDATES");
340 DCHECK(progress_marker_partner_
);
341 if (!MatchesOtherClient(progress_marker_partner_
)) {
342 // The client is not yet fully synced; keep waiting until we converge.
346 SignalStateCompleteWithNextState(FULLY_SYNCED
);
349 case WAITING_FOR_PASSPHRASE_REQUIRED
: {
350 DVLOG(1) << GetClientInfoString("WAITING_FOR_PASSPHRASE_REQUIRED");
351 if (service()->IsPassphraseRequired()) {
352 // A passphrase is now required. Wait for it to be accepted.
353 SignalStateCompleteWithNextState(WAITING_FOR_PASSPHRASE_ACCEPTED
);
357 case WAITING_FOR_PASSPHRASE_ACCEPTED
: {
358 DVLOG(1) << GetClientInfoString("WAITING_FOR_PASSPHRASE_ACCEPTED");
359 if (service()->ShouldPushChanges() &&
360 !service()->IsPassphraseRequired() &&
361 service()->IsUsingSecondaryPassphrase()) {
362 // The passphrase has been accepted, and sync has been restarted.
363 SignalStateCompleteWithNextState(FULLY_SYNCED
);
367 case WAITING_FOR_ENCRYPTION
: {
368 DVLOG(1) << GetClientInfoString("WAITING_FOR_ENCRYPTION");
369 // The correctness of this if condition may depend on the ordering of its
370 // sub-expressions. See crbug.com/98607, crbug.com/95619.
371 // TODO(rlarocque): Figure out a less brittle way of detecting this.
372 if (IsTypeEncrypted(waiting_for_encryption_type_
) &&
374 GetLastSessionSnapshot().num_encryption_conflicts() == 0) {
375 // Encryption is now complete for the the type in which we were waiting.
376 SignalStateCompleteWithNextState(FULLY_SYNCED
);
381 case WAITING_FOR_SYNC_CONFIGURATION
: {
382 DVLOG(1) << GetClientInfoString("WAITING_FOR_SYNC_CONFIGURATION");
383 if (service()->ShouldPushChanges()) {
384 // The Datatype manager is configured and sync is fully initialized.
385 SignalStateCompleteWithNextState(FULLY_SYNCED
);
389 case WAITING_FOR_SYNC_DISABLED
: {
390 DVLOG(1) << GetClientInfoString("WAITING_FOR_SYNC_DISABLED");
391 if (service()->HasSyncSetupCompleted() == false) {
392 // Sync has been disabled.
393 SignalStateCompleteWithNextState(SYNC_DISABLED
);
397 case WAITING_FOR_EXPONENTIAL_BACKOFF_VERIFICATION
: {
398 DVLOG(1) << GetClientInfoString(
399 "WAITING_FOR_EXPONENTIAL_BACKOFF_VERIFICATION");
400 const SyncSessionSnapshot
& snap
= GetLastSessionSnapshot();
401 retry_verifier_
.VerifyRetryInterval(snap
);
402 if (retry_verifier_
.done()) {
403 // Retry verifier is done verifying exponential backoff.
404 SignalStateCompleteWithNextState(WAITING_FOR_NOTHING
);
408 case WAITING_FOR_MIGRATION_TO_START
: {
409 DVLOG(1) << GetClientInfoString("WAITING_FOR_MIGRATION_TO_START");
410 if (HasPendingBackendMigration()) {
411 // There are pending migrations. Wait for them.
412 SignalStateCompleteWithNextState(WAITING_FOR_MIGRATION_TO_FINISH
);
416 case WAITING_FOR_MIGRATION_TO_FINISH
: {
417 DVLOG(1) << GetClientInfoString("WAITING_FOR_MIGRATION_TO_FINISH");
418 if (!HasPendingBackendMigration()) {
420 SignalStateCompleteWithNextState(WAITING_FOR_NOTHING
);
424 case WAITING_FOR_ACTIONABLE_ERROR
: {
425 DVLOG(1) << GetClientInfoString("WAITING_FOR_ACTIONABLE_ERROR");
426 ProfileSyncService::Status status
= GetStatus();
427 if (status
.sync_protocol_error
.action
!= syncer::UNKNOWN_ACTION
&&
428 service_
->HasUnrecoverableError() == true) {
429 // An actionable error has been detected.
430 SignalStateCompleteWithNextState(WAITING_FOR_NOTHING
);
434 case SET_PASSPHRASE_FAILED
: {
435 // A passphrase is required for decryption. There is nothing the sync
436 // client can do until SetDecryptionPassphrase() is called.
437 DVLOG(1) << GetClientInfoString("SET_PASSPHRASE_FAILED");
441 // The client is online and fully synced. There is nothing to do.
442 DVLOG(1) << GetClientInfoString("FULLY_SYNCED");
445 case SYNC_DISABLED
: {
446 // Syncing is disabled for the client. There is nothing to do.
447 DVLOG(1) << GetClientInfoString("SYNC_DISABLED");
450 case WAITING_FOR_NOTHING
: {
451 // We don't care about the state of the syncer for the rest of the test
453 DVLOG(1) << GetClientInfoString("WAITING_FOR_NOTHING");
457 // Invalid state during observer callback which may be triggered by other
458 // classes using the the UI message loop. Defer to their handling.
461 return original_wait_state
!= wait_state_
;
464 void ProfileSyncServiceHarness::OnStateChanged() {
465 RunStateChangeMachine();
468 void ProfileSyncServiceHarness::OnMigrationStateChange() {
469 // Update migration state.
470 if (HasPendingBackendMigration()) {
471 // Merge current pending migration types into
472 // |pending_migration_types_|.
473 pending_migration_types_
.PutAll(
474 service()->GetBackendMigratorForTest()->
475 GetPendingMigrationTypesForTest());
476 DVLOG(1) << profile_debug_name_
<< ": new pending migration types "
477 << syncer::ModelTypeSetToString(pending_migration_types_
);
479 // Merge just-finished pending migration types into
480 // |migration_types_|.
481 migrated_types_
.PutAll(pending_migration_types_
);
482 pending_migration_types_
.Clear();
483 DVLOG(1) << profile_debug_name_
<< ": new migrated types "
484 << syncer::ModelTypeSetToString(migrated_types_
);
486 RunStateChangeMachine();
489 bool ProfileSyncServiceHarness::AwaitPassphraseRequired() {
490 DVLOG(1) << GetClientInfoString("AwaitPassphraseRequired");
491 if (wait_state_
== SYNC_DISABLED
) {
492 LOG(ERROR
) << "Sync disabled for " << profile_debug_name_
<< ".";
496 if (service()->IsPassphraseRequired()) {
497 // It's already true that a passphrase is required; don't wait.
501 wait_state_
= WAITING_FOR_PASSPHRASE_REQUIRED
;
502 return AwaitStatusChangeWithTimeout(kLiveSyncOperationTimeoutMs
,
503 "Waiting for passphrase to be required.");
506 bool ProfileSyncServiceHarness::AwaitPassphraseAccepted() {
507 DVLOG(1) << GetClientInfoString("AwaitPassphraseAccepted");
508 if (wait_state_
== SYNC_DISABLED
) {
509 LOG(ERROR
) << "Sync disabled for " << profile_debug_name_
<< ".";
513 if (service()->ShouldPushChanges() &&
514 !service()->IsPassphraseRequired() &&
515 service()->IsUsingSecondaryPassphrase()) {
516 // Passphrase is already accepted; don't wait.
520 wait_state_
= WAITING_FOR_PASSPHRASE_ACCEPTED
;
521 return AwaitStatusChangeWithTimeout(kLiveSyncOperationTimeoutMs
,
522 "Waiting for passphrase to be accepted.");
525 bool ProfileSyncServiceHarness::AwaitBackendInitialized() {
526 DVLOG(1) << GetClientInfoString("AwaitBackendInitialized");
527 if (service()->sync_initialized()) {
528 // The sync backend host has already been initialized; don't wait.
532 wait_state_
= WAITING_FOR_ON_BACKEND_INITIALIZED
;
533 return AwaitStatusChangeWithTimeout(kLiveSyncOperationTimeoutMs
,
534 "Waiting for OnBackendInitialized().");
537 bool ProfileSyncServiceHarness::AwaitSyncRestart() {
538 DVLOG(1) << GetClientInfoString("AwaitSyncRestart");
539 if (service()->ShouldPushChanges()) {
540 // Sync has already been restarted; don't wait.
544 // Wait for the sync backend to be initialized.
545 if (!AwaitBackendInitialized()) {
546 LOG(ERROR
) << "OnBackendInitialized() not seen after "
547 << kLiveSyncOperationTimeoutMs
/ 1000
552 // Wait for sync configuration to complete.
553 wait_state_
= WAITING_FOR_SYNC_CONFIGURATION
;
554 return AwaitStatusChangeWithTimeout(kLiveSyncOperationTimeoutMs
,
555 "Waiting for sync configuration.");
558 bool ProfileSyncServiceHarness::AwaitDataSyncCompletion(
559 const std::string
& reason
) {
560 DVLOG(1) << GetClientInfoString("AwaitDataSyncCompletion");
562 CHECK(service()->sync_initialized());
563 CHECK_NE(wait_state_
, SYNC_DISABLED
);
565 if (IsDataSynced()) {
566 // Client is already synced; don't wait.
570 wait_state_
= WAITING_FOR_DATA_SYNC
;
571 AwaitStatusChangeWithTimeout(kLiveSyncOperationTimeoutMs
, reason
);
572 if (wait_state_
== FULLY_SYNCED
) {
575 LOG(ERROR
) << "AwaitDataSyncCompletion failed, state is now: "
581 bool ProfileSyncServiceHarness::AwaitFullSyncCompletion(
582 const std::string
& reason
) {
583 DVLOG(1) << GetClientInfoString("AwaitFullSyncCompletion");
584 if (wait_state_
== SYNC_DISABLED
) {
585 LOG(ERROR
) << "Sync disabled for " << profile_debug_name_
<< ".";
589 if (IsFullySynced()) {
590 // Client is already synced; don't wait.
594 DCHECK(service()->sync_initialized());
595 wait_state_
= WAITING_FOR_FULL_SYNC
;
596 AwaitStatusChangeWithTimeout(kLiveSyncOperationTimeoutMs
, reason
);
597 if (wait_state_
== FULLY_SYNCED
) {
598 // Client is online; sync was successful.
601 LOG(ERROR
) << "Invalid wait state: " << wait_state_
;
606 bool ProfileSyncServiceHarness::AwaitSyncDisabled(const std::string
& reason
) {
607 DCHECK(service()->HasSyncSetupCompleted());
608 DCHECK_NE(wait_state_
, SYNC_DISABLED
);
609 wait_state_
= WAITING_FOR_SYNC_DISABLED
;
610 AwaitStatusChangeWithTimeout(kLiveSyncOperationTimeoutMs
, reason
);
611 return wait_state_
== SYNC_DISABLED
;
614 bool ProfileSyncServiceHarness::AwaitExponentialBackoffVerification() {
615 const SyncSessionSnapshot
& snap
= GetLastSessionSnapshot();
616 retry_verifier_
.Initialize(snap
);
617 wait_state_
= WAITING_FOR_EXPONENTIAL_BACKOFF_VERIFICATION
;
618 AwaitStatusChangeWithTimeout(kExponentialBackoffVerificationTimeoutMs
,
619 "Verify Exponential backoff");
620 return (retry_verifier_
.Succeeded());
623 bool ProfileSyncServiceHarness::AwaitActionableError() {
624 ProfileSyncService::Status status
= GetStatus();
625 CHECK(status
.sync_protocol_error
.action
== syncer::UNKNOWN_ACTION
);
626 wait_state_
= WAITING_FOR_ACTIONABLE_ERROR
;
627 AwaitStatusChangeWithTimeout(kLiveSyncOperationTimeoutMs
,
628 "Waiting for actionable error");
629 status
= GetStatus();
630 return (status
.sync_protocol_error
.action
!= syncer::UNKNOWN_ACTION
&&
631 service_
->HasUnrecoverableError());
634 bool ProfileSyncServiceHarness::AwaitMigration(
635 syncer::ModelTypeSet expected_migrated_types
) {
636 DVLOG(1) << GetClientInfoString("AwaitMigration");
637 DVLOG(1) << profile_debug_name_
<< ": waiting until migration is done for "
638 << syncer::ModelTypeSetToString(expected_migrated_types
);
640 bool migration_finished
= migrated_types_
.HasAll(expected_migrated_types
);
641 DVLOG(1) << "Migrated types "
642 << syncer::ModelTypeSetToString(migrated_types_
)
643 << (migration_finished
? " contains " : " does not contain ")
644 << syncer::ModelTypeSetToString(expected_migrated_types
);
645 if (migration_finished
) {
649 if (HasPendingBackendMigration()) {
650 wait_state_
= WAITING_FOR_MIGRATION_TO_FINISH
;
652 wait_state_
= WAITING_FOR_MIGRATION_TO_START
;
653 AwaitStatusChangeWithTimeout(kLiveSyncOperationTimeoutMs
,
654 "Wait for migration to start");
655 if (wait_state_
!= WAITING_FOR_MIGRATION_TO_FINISH
) {
656 DVLOG(1) << profile_debug_name_
657 << ": wait state = " << wait_state_
658 << " after migration start is not "
659 << "WAITING_FOR_MIGRATION_TO_FINISH";
663 AwaitStatusChangeWithTimeout(kLiveSyncOperationTimeoutMs
,
664 "Wait for migration to finish");
665 if (wait_state_
!= WAITING_FOR_NOTHING
) {
666 DVLOG(1) << profile_debug_name_
667 << ": wait state = " << wait_state_
668 << " after migration finish is not WAITING_FOR_NOTHING";
671 // We must use AwaitDataSyncCompletion rather than the more common
672 // AwaitFullSyncCompletion. As long as crbug.com/97780 is open, we will
673 // rely on self-notifications to ensure that progress markers are updated,
674 // which allows AwaitFullSyncCompletion to return. However, in some
675 // migration tests these notifications are completely disabled, so the
676 // progress markers do not get updated. This is why we must use the less
677 // strict condition, AwaitDataSyncCompletion.
678 if (!AwaitDataSyncCompletion(
679 "Config sync cycle after migration cycle")) {
685 bool ProfileSyncServiceHarness::AwaitMutualSyncCycleCompletion(
686 ProfileSyncServiceHarness
* partner
) {
687 DVLOG(1) << GetClientInfoString("AwaitMutualSyncCycleCompletion");
688 if (!AwaitFullSyncCompletion("Sync cycle completion on active client."))
690 return partner
->WaitUntilProgressMarkersMatch(this,
691 "Sync cycle completion on passive client.");
694 bool ProfileSyncServiceHarness::AwaitGroupSyncCycleCompletion(
695 std::vector
<ProfileSyncServiceHarness
*>& partners
) {
696 DVLOG(1) << GetClientInfoString("AwaitGroupSyncCycleCompletion");
697 if (!AwaitFullSyncCompletion("Sync cycle completion on active client."))
699 bool return_value
= true;
700 for (std::vector
<ProfileSyncServiceHarness
*>::iterator it
=
701 partners
.begin(); it
!= partners
.end(); ++it
) {
702 if ((this != *it
) && ((*it
)->wait_state_
!= SYNC_DISABLED
)) {
703 return_value
= return_value
&&
704 (*it
)->WaitUntilProgressMarkersMatch(this,
705 "Sync cycle completion on partner client.");
712 bool ProfileSyncServiceHarness::AwaitQuiescence(
713 std::vector
<ProfileSyncServiceHarness
*>& clients
) {
714 DVLOG(1) << "AwaitQuiescence.";
715 bool return_value
= true;
716 for (std::vector
<ProfileSyncServiceHarness
*>::iterator it
=
717 clients
.begin(); it
!= clients
.end(); ++it
) {
718 if ((*it
)->wait_state_
!= SYNC_DISABLED
)
719 return_value
= return_value
&&
720 (*it
)->AwaitGroupSyncCycleCompletion(clients
);
725 bool ProfileSyncServiceHarness::WaitUntilProgressMarkersMatch(
726 ProfileSyncServiceHarness
* partner
, const std::string
& reason
) {
727 DVLOG(1) << GetClientInfoString("WaitUntilProgressMarkersMatch");
728 if (wait_state_
== SYNC_DISABLED
) {
729 LOG(ERROR
) << "Sync disabled for " << profile_debug_name_
<< ".";
733 if (MatchesOtherClient(partner
)) {
734 // Progress markers already match; don't wait.
738 DCHECK(!progress_marker_partner_
);
739 progress_marker_partner_
= partner
;
740 partner
->service()->AddObserver(this);
741 wait_state_
= WAITING_FOR_UPDATES
;
743 AwaitStatusChangeWithTimeout(kLiveSyncOperationTimeoutMs
, reason
);
744 partner
->service()->RemoveObserver(this);
745 progress_marker_partner_
= NULL
;
749 bool ProfileSyncServiceHarness::AwaitStatusChangeWithTimeout(
750 int timeout_milliseconds
,
751 const std::string
& reason
) {
752 DVLOG(1) << GetClientInfoString("AwaitStatusChangeWithTimeout");
753 if (wait_state_
== SYNC_DISABLED
) {
754 LOG(ERROR
) << "Sync disabled for " << profile_debug_name_
<< ".";
757 scoped_refptr
<StateChangeTimeoutEvent
> timeout_signal(
758 new StateChangeTimeoutEvent(this, reason
));
760 // Set the flag to tell SignalStateComplete() that it's OK to quit out of
761 // the MessageLoop if we hit a state transition.
762 waiting_for_status_change_
= true;
763 MessageLoop
* loop
= MessageLoop::current();
764 MessageLoop::ScopedNestableTaskAllower
allow(loop
);
765 loop
->PostDelayedTask(
767 base::Bind(&StateChangeTimeoutEvent::Callback
,
768 timeout_signal
.get()),
769 base::TimeDelta::FromMilliseconds(timeout_milliseconds
));
771 waiting_for_status_change_
= false;
774 if (timeout_signal
->Abort()) {
775 DVLOG(1) << GetClientInfoString("AwaitStatusChangeWithTimeout succeeded");
778 DVLOG(0) << GetClientInfoString("AwaitStatusChangeWithTimeout timed out");
783 ProfileSyncService::Status
ProfileSyncServiceHarness::GetStatus() {
784 DCHECK(service() != NULL
) << "GetStatus(): service() is NULL.";
785 ProfileSyncService::Status result
;
786 service()->QueryDetailedSyncStatus(&result
);
790 // We use this function to share code between IsFullySynced and IsDataSynced
791 // while ensuring that all conditions are evaluated using on the same snapshot.
792 bool ProfileSyncServiceHarness::IsDataSyncedImpl(
793 const SyncSessionSnapshot
& snap
) {
794 return ServiceIsPushingChanges() &&
795 GetStatus().notifications_enabled
&&
796 !service()->HasUnsyncedItems() &&
797 !HasPendingBackendMigration();
800 bool ProfileSyncServiceHarness::IsDataSynced() {
801 if (service() == NULL
) {
802 DVLOG(1) << GetClientInfoString("IsDataSynced(): false");
806 const SyncSessionSnapshot
& snap
= GetLastSessionSnapshot();
807 bool is_data_synced
= IsDataSyncedImpl(snap
);
809 DVLOG(1) << GetClientInfoString(
810 is_data_synced
? "IsDataSynced: true" : "IsDataSynced: false");
811 return is_data_synced
;
814 bool ProfileSyncServiceHarness::IsFullySynced() {
815 if (service() == NULL
) {
816 DVLOG(1) << GetClientInfoString("IsFullySynced: false");
819 const SyncSessionSnapshot
& snap
= GetLastSessionSnapshot();
820 // If we didn't try to commit anything in the previous cycle, there's a
821 // good chance that we're now fully up to date.
822 bool is_fully_synced
=
823 snap
.model_neutral_state().num_successful_commits
== 0
824 && snap
.model_neutral_state().commit_result
== syncer::SYNCER_OK
825 && IsDataSyncedImpl(snap
);
827 DVLOG(1) << GetClientInfoString(
828 is_fully_synced
? "IsFullySynced: true" : "IsFullySynced: false");
829 return is_fully_synced
;
832 bool ProfileSyncServiceHarness::HasPendingBackendMigration() {
833 browser_sync::BackendMigrator
* migrator
=
834 service()->GetBackendMigratorForTest();
835 return migrator
&& migrator
->state() != browser_sync::BackendMigrator::IDLE
;
838 bool ProfileSyncServiceHarness::AutoStartEnabled() {
839 return service_
->auto_start_enabled();
842 bool ProfileSyncServiceHarness::MatchesOtherClient(
843 ProfileSyncServiceHarness
* partner
) {
844 // TODO(akalin): Shouldn't this belong with the intersection check?
845 // Otherwise, this function isn't symmetric.
846 if (!IsFullySynced()) {
847 DVLOG(2) << profile_debug_name_
<< ": not synced, assuming doesn't match";
851 // Only look for a match if we have at least one enabled datatype in
852 // common with the partner client.
853 const syncer::ModelTypeSet common_types
=
854 Intersection(service()->GetPreferredDataTypes(),
855 partner
->service()->GetPreferredDataTypes());
857 DVLOG(2) << profile_debug_name_
<< ", " << partner
->profile_debug_name_
858 << ": common types are "
859 << syncer::ModelTypeSetToString(common_types
);
861 if (!common_types
.Empty() && !partner
->IsFullySynced()) {
862 DVLOG(2) << "non-empty common types and "
863 << partner
->profile_debug_name_
<< " isn't synced";
867 for (syncer::ModelTypeSet::Iterator i
= common_types
.First();
869 const std::string marker
= GetSerializedProgressMarker(i
.Get());
870 const std::string partner_marker
=
871 partner
->GetSerializedProgressMarker(i
.Get());
872 if (marker
!= partner_marker
) {
874 std::string marker_base64
, partner_marker_base64
;
875 if (!base::Base64Encode(marker
, &marker_base64
)) {
878 if (!base::Base64Encode(
879 partner_marker
, &partner_marker_base64
)) {
882 DVLOG(2) << syncer::ModelTypeToString(i
.Get()) << ": "
883 << profile_debug_name_
<< " progress marker = "
884 << marker_base64
<< ", "
885 << partner
->profile_debug_name_
886 << " partner progress marker = "
887 << partner_marker_base64
;
895 SyncSessionSnapshot
ProfileSyncServiceHarness::GetLastSessionSnapshot() const {
896 DCHECK(service_
!= NULL
) << "Sync service has not yet been set up.";
897 if (service_
->sync_initialized()) {
898 return service_
->GetLastSessionSnapshot();
900 return SyncSessionSnapshot();
903 bool ProfileSyncServiceHarness::EnableSyncForDatatype(
904 syncer::ModelType datatype
) {
905 DVLOG(1) << GetClientInfoString(
906 "EnableSyncForDatatype("
907 + std::string(syncer::ModelTypeToString(datatype
)) + ")");
909 if (wait_state_
== SYNC_DISABLED
) {
910 return SetupSync(syncer::ModelTypeSet(datatype
));
913 if (service() == NULL
) {
914 LOG(ERROR
) << "EnableSyncForDatatype(): service() is null.";
918 syncer::ModelTypeSet synced_datatypes
= service()->GetPreferredDataTypes();
919 if (synced_datatypes
.Has(datatype
)) {
920 DVLOG(1) << "EnableSyncForDatatype(): Sync already enabled for datatype "
921 << syncer::ModelTypeToString(datatype
)
922 << " on " << profile_debug_name_
<< ".";
926 synced_datatypes
.Put(syncer::ModelTypeFromInt(datatype
));
927 service()->OnUserChoseDatatypes(false, synced_datatypes
);
928 if (AwaitDataSyncCompletion("Datatype configuration.")) {
929 DVLOG(1) << "EnableSyncForDatatype(): Enabled sync for datatype "
930 << syncer::ModelTypeToString(datatype
)
931 << " on " << profile_debug_name_
<< ".";
935 DVLOG(0) << GetClientInfoString("EnableSyncForDatatype failed");
939 bool ProfileSyncServiceHarness::DisableSyncForDatatype(
940 syncer::ModelType datatype
) {
941 DVLOG(1) << GetClientInfoString(
942 "DisableSyncForDatatype("
943 + std::string(syncer::ModelTypeToString(datatype
)) + ")");
945 if (service() == NULL
) {
946 LOG(ERROR
) << "DisableSyncForDatatype(): service() is null.";
950 syncer::ModelTypeSet synced_datatypes
= service()->GetPreferredDataTypes();
951 if (!synced_datatypes
.Has(datatype
)) {
952 DVLOG(1) << "DisableSyncForDatatype(): Sync already disabled for datatype "
953 << syncer::ModelTypeToString(datatype
)
954 << " on " << profile_debug_name_
<< ".";
958 synced_datatypes
.RetainAll(syncer::UserSelectableTypes());
959 synced_datatypes
.Remove(datatype
);
960 service()->OnUserChoseDatatypes(false, synced_datatypes
);
961 if (AwaitFullSyncCompletion("Datatype reconfiguration.")) {
962 DVLOG(1) << "DisableSyncForDatatype(): Disabled sync for datatype "
963 << syncer::ModelTypeToString(datatype
)
964 << " on " << profile_debug_name_
<< ".";
968 DVLOG(0) << GetClientInfoString("DisableSyncForDatatype failed");
972 bool ProfileSyncServiceHarness::EnableSyncForAllDatatypes() {
973 DVLOG(1) << GetClientInfoString("EnableSyncForAllDatatypes");
975 if (wait_state_
== SYNC_DISABLED
) {
979 if (service() == NULL
) {
980 LOG(ERROR
) << "EnableSyncForAllDatatypes(): service() is null.";
984 service()->OnUserChoseDatatypes(true, syncer::ModelTypeSet::All());
985 if (AwaitFullSyncCompletion("Datatype reconfiguration.")) {
986 DVLOG(1) << "EnableSyncForAllDatatypes(): Enabled sync for all datatypes "
987 << "on " << profile_debug_name_
<< ".";
991 DVLOG(0) << GetClientInfoString("EnableSyncForAllDatatypes failed");
995 bool ProfileSyncServiceHarness::DisableSyncForAllDatatypes() {
996 DVLOG(1) << GetClientInfoString("DisableSyncForAllDatatypes");
998 if (service() == NULL
) {
999 LOG(ERROR
) << "DisableSyncForAllDatatypes(): service() is null.";
1003 service()->DisableForUser();
1004 wait_state_
= SYNC_DISABLED
;
1005 DVLOG(1) << "DisableSyncForAllDatatypes(): Disabled sync for all "
1006 << "datatypes on " << profile_debug_name_
;
1010 std::string
ProfileSyncServiceHarness::GetSerializedProgressMarker(
1011 syncer::ModelType model_type
) const {
1012 const SyncSessionSnapshot
& snap
= GetLastSessionSnapshot();
1013 const syncer::ProgressMarkerMap
& markers_map
=
1014 snap
.download_progress_markers();
1016 syncer::ProgressMarkerMap::const_iterator it
=
1017 markers_map
.find(model_type
);
1018 return (it
!= markers_map
.end()) ? it
->second
: std::string();
1021 std::string
ProfileSyncServiceHarness::GetClientInfoString(
1022 const std::string
& message
) {
1023 std::stringstream os
;
1024 os
<< profile_debug_name_
<< ": " << message
<< ": ";
1026 const SyncSessionSnapshot
& snap
= GetLastSessionSnapshot();
1027 const ProfileSyncService::Status
& status
= GetStatus();
1028 // Capture select info from the sync session snapshot and syncer status.
1029 os
<< ", has_unsynced_items: "
1030 << (service()->sync_initialized() ? service()->HasUnsyncedItems() : 0)
1032 << (snap
.model_neutral_state().num_successful_commits
== 0 &&
1033 snap
.model_neutral_state().commit_result
== syncer::SYNCER_OK
)
1034 << ", encryption conflicts: "
1035 << snap
.num_encryption_conflicts()
1036 << ", hierarchy conflicts: "
1037 << snap
.num_hierarchy_conflicts()
1038 << ", server conflicts: "
1039 << snap
.num_server_conflicts()
1040 << ", num_updates_downloaded : "
1041 << snap
.model_neutral_state().num_updates_downloaded_total
1042 << ", passphrase_required_reason: "
1043 << syncer::PassphraseRequiredReasonToString(
1044 service()->passphrase_required_reason())
1045 << ", notifications_enabled: "
1046 << status
.notifications_enabled
1047 << ", service_is_pushing_changes: "
1048 << ServiceIsPushingChanges()
1049 << ", has_pending_backend_migration: "
1050 << HasPendingBackendMigration();
1052 os
<< "Sync service not available";
1057 // TODO(zea): Rename this EnableEncryption, since we no longer turn on
1058 // encryption for individual types but for all.
1059 bool ProfileSyncServiceHarness::EnableEncryptionForType(
1060 syncer::ModelType type
) {
1061 const syncer::ModelTypeSet encrypted_types
=
1062 service_
->GetEncryptedDataTypes();
1063 if (encrypted_types
.Has(type
))
1065 service_
->EnableEncryptEverything();
1067 // In order to kick off the encryption we have to reconfigure. Just grab the
1068 // currently synced types and use them.
1069 const syncer::ModelTypeSet synced_datatypes
=
1070 service_
->GetPreferredDataTypes();
1071 bool sync_everything
=
1072 synced_datatypes
.Equals(syncer::ModelTypeSet::All());
1073 service_
->OnUserChoseDatatypes(sync_everything
, synced_datatypes
);
1075 // Wait some time to let the enryption finish.
1076 return WaitForTypeEncryption(type
);
1079 bool ProfileSyncServiceHarness::WaitForTypeEncryption(syncer::ModelType type
) {
1080 // The correctness of this if condition depends on the ordering of its
1081 // sub-expressions. See crbug.com/95619.
1082 // TODO(rlarocque): Figure out a less brittle way of detecting this.
1083 if (IsTypeEncrypted(type
) &&
1085 GetLastSessionSnapshot().num_encryption_conflicts() == 0) {
1086 // Encryption is already complete for |type|; do not wait.
1090 std::string reason
= "Waiting for encryption.";
1091 wait_state_
= WAITING_FOR_ENCRYPTION
;
1092 waiting_for_encryption_type_
= type
;
1093 if (!AwaitStatusChangeWithTimeout(kLiveSyncOperationTimeoutMs
, reason
)) {
1094 LOG(ERROR
) << "Did not receive EncryptionComplete notification after"
1095 << kLiveSyncOperationTimeoutMs
/ 1000
1099 return IsTypeEncrypted(type
);
1102 bool ProfileSyncServiceHarness::IsTypeEncrypted(syncer::ModelType type
) {
1103 const syncer::ModelTypeSet encrypted_types
=
1104 service_
->GetEncryptedDataTypes();
1105 bool is_type_encrypted
= service_
->GetEncryptedDataTypes().Has(type
);
1106 DVLOG(2) << syncer::ModelTypeToString(type
) << " is "
1107 << (is_type_encrypted
? "" : "not ") << "encrypted; "
1108 << "encrypted types = "
1109 << syncer::ModelTypeSetToString(encrypted_types
);
1110 return is_type_encrypted
;
1113 bool ProfileSyncServiceHarness::IsTypeRunning(syncer::ModelType type
) {
1114 browser_sync::DataTypeController::StateMap state_map
;
1115 service_
->GetDataTypeControllerStates(&state_map
);
1116 return (state_map
.count(type
) != 0 &&
1117 state_map
[type
] == browser_sync::DataTypeController::RUNNING
);
1120 bool ProfileSyncServiceHarness::IsTypePreferred(syncer::ModelType type
) {
1121 return service_
->GetPreferredDataTypes().Has(type
);
1124 size_t ProfileSyncServiceHarness::GetNumEntries() const {
1125 return GetLastSessionSnapshot().num_entries();
1128 size_t ProfileSyncServiceHarness::GetNumDatatypes() const {
1129 browser_sync::DataTypeController::StateMap state_map
;
1130 service_
->GetDataTypeControllerStates(&state_map
);
1131 return state_map
.size();
1134 std::string
ProfileSyncServiceHarness::GetServiceStatus() {
1135 scoped_ptr
<DictionaryValue
> value(
1136 sync_ui_util::ConstructAboutInformation(service_
));
1137 std::string service_status
;
1138 base::JSONWriter::WriteWithOptions(value
.get(),
1139 base::JSONWriter::OPTIONS_PRETTY_PRINT
,
1141 return service_status
;