diff options
20 files changed, 264 insertions, 228 deletions
diff --git a/chrome/browser/automation/testing_automation_provider.cc b/chrome/browser/automation/testing_automation_provider.cc index cf4f677..0286750 100644 --- a/chrome/browser/automation/testing_automation_provider.cc +++ b/chrome/browser/automation/testing_automation_provider.cc @@ -4289,7 +4289,7 @@ void TestingAutomationProvider::SignInToSync(Browser* browser, } if (sync_waiter_.get() == NULL) { sync_waiter_.reset(new ProfileSyncServiceHarness( - browser->profile(), username, password, 0)); + browser->profile(), username, password)); } else { sync_waiter_->SetCredentials(username, password); } diff --git a/chrome/browser/profiles/profile.cc b/chrome/browser/profiles/profile.cc index ad93f46..03f0113 100644 --- a/chrome/browser/profiles/profile.cc +++ b/chrome/browser/profiles/profile.cc @@ -171,6 +171,14 @@ net::URLRequestContextGetter* Profile::GetDefaultRequestContext() { return default_request_context_; } +std::string Profile::GetDebugName() { + std::string name = GetPath().BaseName().MaybeAsASCII(); + if (name.empty()) { + name = "UnknownProfile"; + } + return name; +} + bool Profile::IsGuestSession() { #if defined(OS_CHROMEOS) static bool is_guest_session = diff --git a/chrome/browser/profiles/profile.h b/chrome/browser/profiles/profile.h index fcb78cf..9b31d1c 100644 --- a/chrome/browser/profiles/profile.h +++ b/chrome/browser/profiles/profile.h @@ -8,6 +8,8 @@ #define CHROME_BROWSER_PROFILES_PROFILE_H_ #pragma once +#include <string> + #include "base/basictypes.h" #include "base/logging.h" #include "chrome/common/extensions/extension.h" @@ -517,6 +519,8 @@ class Profile { // profile. virtual prerender::PrerenderManager* GetPrerenderManager() = 0; + std::string GetDebugName(); + // Returns whether it is a guest session. static bool IsGuestSession(); diff --git a/chrome/browser/sync/engine/syncapi.cc b/chrome/browser/sync/engine/syncapi.cc index 3546df4..8fe8b81 100644 --- a/chrome/browser/sync/engine/syncapi.cc +++ b/chrome/browser/sync/engine/syncapi.cc @@ -17,6 +17,7 @@ #include "base/bind.h" #include "base/callback.h" #include "base/command_line.h" +#include "base/compiler_specific.h" #include "base/json/json_writer.h" #include "base/logging.h" #include "base/memory/scoped_ptr.h" @@ -465,8 +466,16 @@ void WriteNode::EncryptIfNecessary(sync_pb::EntitySpecifics* unencrypted) { } sync_pb::EntitySpecifics encrypted; syncable::AddDefaultExtensionValue(type, &encrypted); - VLOG(2) << "Encrypted specifics of type " << syncable::ModelTypeToString(type) - << " with content: " << unencrypted->SerializeAsString() << "\n"; + if (VLOG_IS_ON(2)) { + std::string unencrypted_base64; + if (!base::Base64Encode(unencrypted->SerializeAsString(), + &unencrypted_base64)) { + NOTREACHED(); + } + VLOG(2) << "Encrypted specifics of type " + << syncable::ModelTypeToString(type) + << " with content: " << unencrypted_base64 << "\n"; + } if (!GetTransaction()->GetCryptographer()->Encrypt( *unencrypted, encrypted.mutable_encrypted())) { @@ -1118,8 +1127,9 @@ class SyncManager::SyncInternal static const int kDefaultNudgeDelayMilliseconds; static const int kPreferencesNudgeDelayMilliseconds; public: - explicit SyncInternal(SyncManager* sync_manager) - : core_message_loop_(NULL), + SyncInternal(const std::string& name, SyncManager* sync_manager) + : name_(name), + core_message_loop_(NULL), parent_router_(NULL), sync_manager_(sync_manager), registrar_(NULL), @@ -1520,6 +1530,8 @@ class SyncManager::SyncInternal browser_sync::JsArgList FindNodesContainingString( const browser_sync::JsArgList& args); + const std::string name_; + // We couple the DirectoryManager and username together in a UserShare member // so we can return a handle to share_ to clients of the API for use when // constructing any transaction type. @@ -1590,9 +1602,8 @@ const int SyncManager::SyncInternal::kPreferencesNudgeDelayMilliseconds = 2000; SyncManager::Observer::~Observer() {} -SyncManager::SyncManager() { - data_ = new SyncInternal(this); -} +SyncManager::SyncManager(const std::string& name) + : data_(new SyncInternal(name, ALLOW_THIS_IN_INITIALIZER_LIST(this))) {} bool SyncManager::Init(const FilePath& database_location, const char* sync_server_and_path, @@ -1760,7 +1771,8 @@ bool SyncManager::SyncInternal::Init( listeners); context->set_account_name(credentials.email); // The SyncerThread takes ownership of |context|. - syncer_thread_.reset(new SyncerThread(context, new Syncer())); + syncer_thread_.reset( + new SyncerThread(name_, context, new Syncer())); } bool signed_in = SignIn(credentials); diff --git a/chrome/browser/sync/engine/syncapi.h b/chrome/browser/sync/engine/syncapi.h index 5e0708a..2db4020 100644 --- a/chrome/browser/sync/engine/syncapi.h +++ b/chrome/browser/sync/engine/syncapi.h @@ -833,7 +833,7 @@ class SyncManager { typedef Callback0::Type ModeChangeCallback; // Create an uninitialized SyncManager. Callers must Init() before using. - SyncManager(); + explicit SyncManager(const std::string& name); virtual ~SyncManager(); // Initialize the sync manager. |database_location| specifies the path of diff --git a/chrome/browser/sync/engine/syncapi_unittest.cc b/chrome/browser/sync/engine/syncapi_unittest.cc index fdd1cd5..95a3ada 100644 --- a/chrome/browser/sync/engine/syncapi_unittest.cc +++ b/chrome/browser/sync/engine/syncapi_unittest.cc @@ -688,6 +688,7 @@ class SyncManagerTest : public testing::Test, protected: SyncManagerTest() : ui_thread_(BrowserThread::UI, &ui_loop_), + sync_manager_("Test sync manager"), sync_notifier_observer_(NULL), update_enabled_types_call_count_(0) {} diff --git a/chrome/browser/sync/engine/syncer.cc b/chrome/browser/sync/engine/syncer.cc index e23c40b..6352701 100644 --- a/chrome/browser/sync/engine/syncer.cc +++ b/chrome/browser/sync/engine/syncer.cc @@ -268,12 +268,20 @@ void Syncer::SyncShare(sessions::SyncSession* session, default: LOG(ERROR) << "Unknown command: " << current_step; } + VLOG(2) << "last step: " << last_step << ", current step: " + << current_step << ", next step: " + << next_step << ", snapshot: " + << session->TakeSnapshot().ToString(); if (last_step == current_step) break; current_step = next_step; } VLOG(1) << "Syncer End"; + VLOG(2) << "last step: " << last_step << ", current step: " + << current_step << ", next step: " + << next_step << ", snapshot: " + << session->TakeSnapshot().ToString(); SyncerEndCommand syncer_end_command; syncer_end_command.Execute(session); return; diff --git a/chrome/browser/sync/engine/syncer_thread.cc b/chrome/browser/sync/engine/syncer_thread.cc index fc1b3d8..44c528c 100644 --- a/chrome/browser/sync/engine/syncer_thread.cc +++ b/chrome/browser/sync/engine/syncer_thread.cc @@ -79,9 +79,15 @@ GetUpdatesCallerInfo::GetUpdatesSource GetSourceFromReason( SyncerThread::WaitInterval::WaitInterval(Mode mode, TimeDelta length) : mode(mode), had_nudge(false), length(length) { } -SyncerThread::SyncerThread(sessions::SyncSessionContext* context, +// Helper macro to log with the syncer thread name; useful when there +// are multiple syncer threads involved. +#define SVLOG(verbose_level) VLOG(verbose_level) << name_ << ": " + +SyncerThread::SyncerThread(const std::string& name, + sessions::SyncSessionContext* context, Syncer* syncer) - : thread_("SyncEngine_SyncerThread"), + : name_(name), + thread_("SyncEngine_SyncerThread"), syncer_short_poll_interval_seconds_( TimeDelta::FromSeconds(kDefaultShortPollIntervalSeconds)), syncer_long_poll_interval_seconds_( @@ -99,9 +105,8 @@ SyncerThread::~SyncerThread() { void SyncerThread::CheckServerConnectionManagerStatus( HttpResponse::ServerConnectionCode code) { + bool old_server_connection_ok = server_connection_ok_; - VLOG(1) << "SyncerThread(" << this << ")" << " Server connection changed." - << "Old mode: " << server_connection_ok_ << " Code: " << code; // Note, be careful when adding cases here because if the SyncerThread // thinks there is no valid connection as determined by this method, it // will drop out of *all* forward progress sync loops (it won't poll and it @@ -111,22 +116,24 @@ void SyncerThread::CheckServerConnectionManagerStatus( if (HttpResponse::CONNECTION_UNAVAILABLE == code || HttpResponse::SYNC_AUTH_ERROR == code) { server_connection_ok_ = false; - VLOG(1) << "SyncerThread(" << this << ")" << " Server connection changed." - << " new mode:" << server_connection_ok_; } else if (HttpResponse::SERVER_CONNECTION_OK == code) { server_connection_ok_ = true; - VLOG(1) << "SyncerThread(" << this << ")" << " Server connection changed." - << " new mode:" << server_connection_ok_; DoCanaryJob(); } + + if (old_server_connection_ok != server_connection_ok_) { + SVLOG(2) << "Server connection changed. Old mode: " + << old_server_connection_ok << ", new mode: " + << server_connection_ok_ << ", code: " << code; + } } void SyncerThread::Start(Mode mode, ModeChangeCallback* callback) { - VLOG(1) << "SyncerThread(" << this << ")" << " Start called from thread " - << MessageLoop::current()->thread_name(); + SVLOG(2) << "Start called from thread " + << MessageLoop::current()->thread_name() << " with mode " + << mode; if (!thread_.IsRunning()) { - VLOG(1) << "SyncerThread(" << this << ")" << " Starting thread with mode " - << mode; + SVLOG(2) << "Starting thread with mode " << mode; if (!thread_.Start()) { NOTREACHED() << "Unable to start SyncerThread."; return; @@ -136,9 +143,6 @@ void SyncerThread::Start(Mode mode, ModeChangeCallback* callback) { this, &SyncerThread::SendInitialSnapshot)); } - VLOG(1) << "SyncerThread(" << this << ")" << " Entering start with mode = " - << mode; - thread_.message_loop()->PostTask(FROM_HERE, NewRunnableMethod( this, &SyncerThread::StartImpl, mode, callback)); } @@ -161,8 +165,7 @@ void SyncerThread::WatchConnectionManager() { } void SyncerThread::StartImpl(Mode mode, ModeChangeCallback* callback) { - VLOG(1) << "SyncerThread(" << this << ")" << " Doing StartImpl with mode " - << mode; + SVLOG(2) << "Doing StartImpl with mode " << mode; // TODO(lipalani): This will leak if startimpl is never run. Fix it using a // ThreadSafeRefcounted object. @@ -186,10 +189,10 @@ SyncerThread::JobProcessDecision SyncerThread::DecideWhileInWaitInterval( DCHECK(wait_interval_.get()); DCHECK_NE(job.purpose, SyncSessionJob::CLEAR_USER_DATA); - VLOG(1) << "SyncerThread(" << this << ")" << " Wait interval mode : " - << wait_interval_->mode << "Wait interval had nudge : " - << wait_interval_->had_nudge << "is canary job : " - << job.is_canary_job; + SVLOG(2) << "Wait interval mode : " + << wait_interval_->mode << ", wait interval had nudge : " + << wait_interval_->had_nudge << ", is canary job : " + << job.is_canary_job; if (job.purpose == SyncSessionJob::POLL) return DROP; @@ -235,24 +238,21 @@ SyncerThread::JobProcessDecision SyncerThread::DecideOnJob( // Freshness condition if (job.scheduled_start < last_sync_session_end_time_) { - VLOG(1) << "SyncerThread(" << this << ")" - << " Dropping job because of freshness"; + SVLOG(2) << "Dropping job because of freshness"; return DROP; } if (server_connection_ok_) return CONTINUE; - VLOG(1) << "SyncerThread(" << this << ")" - << " Bad server connection. Using that to decide on job."; + SVLOG(2) << "Bad server connection. Using that to decide on job."; return job.purpose == SyncSessionJob::NUDGE ? SAVE : DROP; } void SyncerThread::InitOrCoalescePendingJob(const SyncSessionJob& job) { DCHECK(job.purpose != SyncSessionJob::CONFIGURATION); if (pending_nudge_.get() == NULL) { - VLOG(1) << "SyncerThread(" << this << ")" - << " Creating a pending nudge job"; + SVLOG(2) << "Creating a pending nudge job"; SyncSession* s = job.session.get(); scoped_ptr<SyncSession> session(new SyncSession(s->context(), s->delegate(), s->source(), s->routing_info(), s->workers())); @@ -264,7 +264,7 @@ void SyncerThread::InitOrCoalescePendingJob(const SyncSessionJob& job) { return; } - VLOG(1) << "SyncerThread(" << this << ")" << " Coalescing a pending nudge"; + SVLOG(2) << "Coalescing a pending nudge"; pending_nudge_->session->Coalesce(*(job.session.get())); pending_nudge_->scheduled_start = job.scheduled_start; @@ -274,8 +274,9 @@ void SyncerThread::InitOrCoalescePendingJob(const SyncSessionJob& job) { bool SyncerThread::ShouldRunJob(const SyncSessionJob& job) { JobProcessDecision decision = DecideOnJob(job); - VLOG(1) << "SyncerThread(" << this << ")" << " Should run job, decision: " - << decision << " Job purpose " << job.purpose << "mode " << mode_; + SVLOG(2) << "Should run job, decision: " + << decision << ", job purpose " << job.purpose + << ", mode " << mode_; if (decision != SAVE) return decision == CONTINUE; @@ -289,10 +290,10 @@ bool SyncerThread::ShouldRunJob(const SyncSessionJob& job) { void SyncerThread::SaveJob(const SyncSessionJob& job) { DCHECK(job.purpose != SyncSessionJob::CLEAR_USER_DATA); if (job.purpose == SyncSessionJob::NUDGE) { - VLOG(1) << "SyncerThread(" << this << ")" << " Saving a nudge job"; + SVLOG(2) << "Saving a nudge job"; InitOrCoalescePendingJob(job); } else if (job.purpose == SyncSessionJob::CONFIGURATION){ - VLOG(1) << "SyncerThread(" << this << ")" << " Saving a configuration job"; + SVLOG(2) << "Saving a configuration job"; DCHECK(wait_interval_.get()); DCHECK(mode_ == CONFIGURATION_MODE); @@ -327,12 +328,12 @@ void SyncerThread::ScheduleNudge(const TimeDelta& delay, NudgeSource source, const ModelTypeBitSet& types, const tracked_objects::Location& nudge_location) { if (!thread_.IsRunning()) { - VLOG(0) << "Dropping nudge because thread is not running."; + LOG(INFO) << "Dropping nudge because thread is not running."; NOTREACHED(); return; } - VLOG(1) << "SyncerThread(" << this << ")" << " Nudge scheduled"; + SVLOG(2) << "Nudge scheduled (source=" << source << ")"; ModelTypePayloadMap types_with_payloads = syncable::ModelTypePayloadMapFromBitSet(types, std::string()); @@ -350,7 +351,7 @@ void SyncerThread::ScheduleNudgeWithPayloads(const TimeDelta& delay, return; } - VLOG(1) << "SyncerThread(" << this << ")" << " Nudge scheduled with payloads"; + SVLOG(2) << "Nudge scheduled with payloads (source=" << source << ")"; thread_.message_loop()->PostTask(FROM_HERE, NewRunnableMethod( this, &SyncerThread::ScheduleNudgeImpl, delay, @@ -373,7 +374,7 @@ void SyncerThread::ScheduleNudgeImpl(const TimeDelta& delay, bool is_canary_job, const tracked_objects::Location& nudge_location) { DCHECK_EQ(MessageLoop::current(), thread_.message_loop()); - VLOG(1) << "SyncerThread(" << this << ")" << " Running Schedule nudge impl"; + SVLOG(2) << "Running Schedule nudge impl (source=" << source << ")"; // Note we currently nudge for all types regardless of the ones incurring // the nudge. Doing different would throw off some syncer commands like // CleanupDisabledTypes. We may want to change this in the future. @@ -390,21 +391,19 @@ void SyncerThread::ScheduleNudgeImpl(const TimeDelta& delay, if (pending_nudge_.get()) { if (IsBackingOff() && delay > TimeDelta::FromSeconds(1)) { - VLOG(1) << "SyncerThread(" << this << ")" << " Dropping the nudge because" - << "we are in backoff"; + SVLOG(2) << "Dropping the nudge because we are in backoff"; return; } - VLOG(1) << "SyncerThread(" << this << ")" << " Coalescing pending nudge"; + SVLOG(2) << "Coalescing pending nudge"; pending_nudge_->session->Coalesce(*(job.session.get())); if (!IsBackingOff()) { - VLOG(1) << "SyncerThread(" << this << ")" << " Dropping a nudge because" - << " we are not in backoff and the job was coalesced"; + SVLOG(2) << "Dropping a nudge because" + << " we are not in backoff and the job was coalesced"; return; } else { - VLOG(1) << "SyncerThread(" << this << ")" - << " Rescheduling pending nudge"; + SVLOG(2) << "Rescheduling pending nudge"; SyncSession* s = pending_nudge_->session.get(); job.session.reset(new SyncSession(s->context(), s->delegate(), s->source(), s->routing_info(), s->workers())); @@ -465,12 +464,12 @@ void GetModelSafeParamsForTypes(const ModelTypeBitSet& types, void SyncerThread::ScheduleConfig(const ModelTypeBitSet& types, sync_api::ConfigureReason reason) { if (!thread_.IsRunning()) { - VLOG(0) << "ScheduleConfig failed because thread is not running."; + LOG(INFO) << "ScheduleConfig failed because thread is not running."; NOTREACHED(); return; } - VLOG(1) << "SyncerThread(" << this << ")" << " Scheduling a config"; + SVLOG(2) << "Scheduling a config"; ModelSafeRoutingInfo routes; std::vector<ModelSafeWorker*> workers; GetModelSafeParamsForTypes(types, session_context_->registrar(), @@ -486,7 +485,7 @@ void SyncerThread::ScheduleConfigImpl(const ModelSafeRoutingInfo& routing_info, const sync_pb::GetUpdatesCallerInfo::GetUpdatesSource source) { DCHECK_EQ(MessageLoop::current(), thread_.message_loop()); - VLOG(1) << "SyncerThread(" << this << ")" << " ScheduleConfigImpl..."; + SVLOG(2) << "ScheduleConfigImpl..."; // TODO(tim): config-specific GetUpdatesCallerInfo value? SyncSession* session = new SyncSession(session_context_.get(), this, SyncSourceInfo(source, @@ -506,14 +505,12 @@ void SyncerThread::ScheduleSyncSessionJob(const base::TimeDelta& delay, SyncSessionJob job(purpose, TimeTicks::Now() + delay, make_linked_ptr(session), false, nudge_location); if (purpose == SyncSessionJob::NUDGE) { - VLOG(1) << "SyncerThread(" << this << ")" << " Resetting pending_nudge in" - << " ScheduleSyncSessionJob"; + SVLOG(2) << "Resetting pending_nudge in ScheduleSyncSessionJob"; DCHECK(!pending_nudge_.get() || pending_nudge_->session.get() == session); pending_nudge_.reset(new SyncSessionJob(job)); } - VLOG(1) << "SyncerThread(" << this << ")" - << " Posting job to execute in DoSyncSessionJob. Job purpose " - << job.purpose; + SVLOG(2) << "Posting job to execute in DoSyncSessionJob. Job purpose " + << job.purpose; MessageLoop::current()->PostDelayedTask(FROM_HERE, NewRunnableMethod(this, &SyncerThread::DoSyncSessionJob, job), delay.InMilliseconds()); @@ -552,8 +549,8 @@ void SyncerThread::DoSyncSessionJob(const SyncSessionJob& job) { if (job.purpose == SyncSessionJob::NUDGE) { if (pending_nudge_.get() == NULL || pending_nudge_->session != job.session) { - VLOG(1) << "SyncerThread(" << this << ")" << "Dropping a nudge in " - << "DoSyncSessionJob because another nudge was scheduled"; + SVLOG(2) << "Dropping a nudge in " + << "DoSyncSessionJob because another nudge was scheduled"; return; // Another nudge must have been scheduled in in the meantime. } pending_nudge_.reset(); @@ -564,8 +561,7 @@ void SyncerThread::DoSyncSessionJob(const SyncSessionJob& job) { job.session->RebaseRoutingInfoWithLatest(session.get()); } - VLOG(1) << "SyncerThread(" << this << ")" << " DoSyncSessionJob. job purpose " - << job.purpose; + SVLOG(2) << "DoSyncSessionJob. job purpose " << job.purpose; SyncerStep begin(SYNCER_BEGIN); SyncerStep end(SYNCER_END); @@ -573,16 +569,14 @@ void SyncerThread::DoSyncSessionJob(const SyncSessionJob& job) { bool has_more_to_sync = true; while (ShouldRunJob(job) && has_more_to_sync) { - VLOG(1) << "SyncerThread(" << this << ")" - << " SyncerThread: Calling SyncShare."; + SVLOG(2) << "Calling SyncShare."; // Synchronously perform the sync session from this thread. syncer_->SyncShare(job.session.get(), begin, end); has_more_to_sync = job.session->HasMoreToSync(); if (has_more_to_sync) job.session->ResetTransientState(); } - VLOG(1) << "SyncerThread(" << this << ")" - << " SyncerThread: Done SyncShare looping."; + SVLOG(2) << "Done SyncShare looping."; FinishSyncSessionJob(job); } @@ -621,14 +615,12 @@ void SyncerThread::FinishSyncSessionJob(const SyncSessionJob& job) { last_sync_session_end_time_ = now; UpdateCarryoverSessionState(job); if (IsSyncingCurrentlySilenced()) { - VLOG(1) << "SyncerThread(" << this << ")" - << " We are currently throttled. So not scheduling the next sync."; + SVLOG(2) << "We are currently throttled; not scheduling the next sync."; SaveJob(job); return; // Nothing to do. } - VLOG(1) << "SyncerThread(" << this << ")" - << " Updating the next polling time after SyncMain"; + SVLOG(2) << "Updating the next polling time after SyncMain"; ScheduleNextSync(job); } @@ -641,11 +633,15 @@ void SyncerThread::ScheduleNextSync(const SyncSessionJob& old_job) { // but HasMoreToSync is false, this implies that the Syncer determined no // forward progress was possible at this time (an error, such as an HTTP // 500, is likely to have occurred during commit). + int num_server_changes_remaining = + old_job.session->status_controller()->num_server_changes_remaining(); + size_t num_unsynced_handles = + old_job.session->status_controller()->unsynced_handles().size(); const bool work_to_do = - old_job.session->status_controller()->num_server_changes_remaining() > 0 - || old_job.session->status_controller()->unsynced_handles().size() > 0; - VLOG(1) << "SyncerThread(" << this << ")" << " syncer has work to do: " - << work_to_do; + num_server_changes_remaining > 0 || num_unsynced_handles > 0; + SVLOG(2) << "num server changes remaining: " << num_server_changes_remaining + << ", num unsynced handles: " << num_unsynced_handles + << ", syncer has work to do: " << work_to_do; AdjustPolling(&old_job); @@ -656,28 +652,24 @@ void SyncerThread::ScheduleNextSync(const SyncSessionJob& old_job) { // work_to_do before it ran this wont have changed, as jobs like this don't // run a full sync cycle. So we don't need special code here. wait_interval_.reset(); - VLOG(1) << "SyncerThread(" << this << ")" - << " Job suceeded so not scheduling more jobs"; + SVLOG(2) << "Job suceeded so not scheduling more jobs"; return; } if (old_job.session->source().updates_source == GetUpdatesCallerInfo::SYNC_CYCLE_CONTINUATION) { - VLOG(1) << "SyncerThread(" << this << ")" - << " Job failed with source continuation"; + SVLOG(2) << "Job failed with source continuation"; // We don't seem to have made forward progress. Start or extend backoff. HandleConsecutiveContinuationError(old_job); } else if (IsBackingOff()) { - VLOG(1) << "SyncerThread(" << this << ")" - << " A nudge during backoff failed"; + SVLOG(2) << "A nudge during backoff failed"; // We weren't continuing but we're in backoff; must have been a nudge. DCHECK_EQ(SyncSessionJob::NUDGE, old_job.purpose); DCHECK(!wait_interval_->had_nudge); wait_interval_->had_nudge = true; wait_interval_->timer.Reset(); } else { - VLOG(1) << "SyncerThread(" << this << ")" - << " Failed. Schedule a job with continuation as source"; + SVLOG(2) << "Failed. Schedule a job with continuation as source"; // We weren't continuing and we aren't in backoff. Schedule a normal // continuation. if (old_job.purpose == SyncSessionJob::CONFIGURATION) { @@ -725,10 +717,9 @@ void SyncerThread::HandleConsecutiveContinuationError( TimeDelta length = delay_provider_->GetDelay( IsBackingOff() ? wait_interval_->length : TimeDelta::FromSeconds(1)); - VLOG(1) << "SyncerThread(" << this << ")" - << " In handle continuation error. Old job purpose is " - << old_job.purpose << " . The time delta(ms) is " - << length.InMilliseconds(); + SVLOG(2) << "In handle continuation error. Old job purpose is " + << old_job.purpose << " . The time delta(ms) is " + << length.InMilliseconds(); // This will reset the had_nudge variable as well. wait_interval_.reset(new WaitInterval(WaitInterval::EXPONENTIAL_BACKOFF, @@ -776,14 +767,14 @@ TimeDelta SyncerThread::GetRecommendedDelay(const TimeDelta& last_delay) { } void SyncerThread::Stop() { - VLOG(1) << "SyncerThread(" << this << ")" << " stop called"; + SVLOG(2) << "stop called"; syncer_->RequestEarlyExit(); // Safe to call from any thread. session_context_->connection_manager()->RemoveListener(this); thread_.Stop(); } void SyncerThread::DoCanaryJob() { - VLOG(1) << "SyncerThread(" << this << ")" << " Do canary job"; + SVLOG(2) << "Do canary job"; DoPendingJobIfPossible(true); } @@ -791,10 +782,10 @@ void SyncerThread::DoPendingJobIfPossible(bool is_canary_job) { SyncSessionJob* job_to_execute = NULL; if (mode_ == CONFIGURATION_MODE && wait_interval_.get() && wait_interval_->pending_configure_job.get()) { - VLOG(1) << "SyncerThread(" << this << ")" << " Found pending configure job"; + SVLOG(2) << "Found pending configure job"; job_to_execute = wait_interval_->pending_configure_job.get(); } else if (mode_ == NORMAL_MODE && pending_nudge_.get()) { - VLOG(1) << "SyncerThread(" << this << ")" << " Found pending nudge job"; + SVLOG(2) << "Found pending nudge job"; // Pending jobs mostly have time from the past. Reset it so this job // will get executed. if (pending_nudge_->scheduled_start < TimeTicks::Now()) @@ -811,7 +802,7 @@ void SyncerThread::DoPendingJobIfPossible(bool is_canary_job) { } if (job_to_execute != NULL) { - VLOG(1) << "SyncerThread(" << this << ")" << " Executing pending job"; + SVLOG(2) << "Executing pending job"; SyncSessionJob copy = *job_to_execute; copy.is_canary_job = is_canary_job; DoSyncSessionJob(copy); @@ -844,7 +835,7 @@ void SyncerThread::PollTimerCallback() { void SyncerThread::Unthrottle() { DCHECK_EQ(WaitInterval::THROTTLED, wait_interval_->mode); - VLOG(1) << "SyncerThread(" << this << ")" << " Unthrottled.."; + SVLOG(2) << "Unthrottled."; DoCanaryJob(); wait_interval_.reset(); } @@ -884,8 +875,7 @@ void SyncerThread::OnReceivedLongPollIntervalUpdate( } void SyncerThread::OnShouldStopSyncingPermanently() { - VLOG(1) << "SyncerThread(" << this << ")" - << " OnShouldStopSyncingPermanently"; + SVLOG(2) << "OnShouldStopSyncingPermanently"; syncer_->RequestEarlyExit(); // Thread-safe. Notify(SyncEngineEvent::STOP_SYNCING_PERMANENTLY); } @@ -901,4 +891,6 @@ void SyncerThread::set_notifications_enabled(bool notifications_enabled) { session_context_->set_notifications_enabled(notifications_enabled); } +#undef SVLOG + } // browser_sync diff --git a/chrome/browser/sync/engine/syncer_thread.h b/chrome/browser/sync/engine/syncer_thread.h index 67b9376..be7d028 100644 --- a/chrome/browser/sync/engine/syncer_thread.h +++ b/chrome/browser/sync/engine/syncer_thread.h @@ -7,6 +7,8 @@ #define CHROME_BROWSER_SYNC_ENGINE_SYNCER_THREAD_H_ #pragma once +#include <string> + #include "base/callback.h" #include "base/memory/linked_ptr.h" #include "base/memory/scoped_ptr.h" @@ -43,8 +45,10 @@ class SyncerThread : public sessions::SyncSession::Delegate, NORMAL_MODE, }; - // Takes ownership of both |context| and |syncer|. - SyncerThread(sessions::SyncSessionContext* context, Syncer* syncer); + // |name| is a display string to identify the syncer thread. Takes + // |ownership of both |context| and |syncer|. + SyncerThread(const std::string& name, + sessions::SyncSessionContext* context, Syncer* syncer); virtual ~SyncerThread(); typedef Callback0::Type ModeChangeCallback; @@ -298,6 +302,8 @@ class SyncerThread : public sessions::SyncSession::Delegate, // the client starts up and does not need to perform an initial sync. void SendInitialSnapshot(); + const std::string name_; + base::Thread thread_; // Modifiable versions of kDefaultLongPollIntervalSeconds which can be diff --git a/chrome/browser/sync/engine/syncer_thread_unittest.cc b/chrome/browser/sync/engine/syncer_thread_unittest.cc index 3ff2d16..a2ce04e 100644 --- a/chrome/browser/sync/engine/syncer_thread_unittest.cc +++ b/chrome/browser/sync/engine/syncer_thread_unittest.cc @@ -70,7 +70,8 @@ class SyncerThreadTest : public testing::Test { registrar_.get(), std::vector<SyncEngineEventListener*>()); context_->set_notifications_enabled(true); context_->set_account_name("Test"); - syncer_thread_.reset(new SyncerThread(context_, syncer_)); + syncer_thread_.reset( + new SyncerThread("TestSyncerThread", context_, syncer_)); } SyncerThread* syncer_thread() { return syncer_thread_.get(); } diff --git a/chrome/browser/sync/engine/syncer_thread_whitebox_unittest.cc b/chrome/browser/sync/engine/syncer_thread_whitebox_unittest.cc index 796a148..681474a 100644 --- a/chrome/browser/sync/engine/syncer_thread_whitebox_unittest.cc +++ b/chrome/browser/sync/engine/syncer_thread_whitebox_unittest.cc @@ -29,7 +29,8 @@ class SyncerThreadWhiteboxTest : public testing::Test { registrar_.get(), std::vector<SyncEngineEventListener*>()); context_->set_notifications_enabled(true); context_->set_account_name("Test"); - syncer_thread_.reset(new SyncerThread(context_, syncer)); + syncer_thread_.reset( + new SyncerThread("TestSyncerThreadWhitebox", context_, syncer)); } virtual void TearDown() { diff --git a/chrome/browser/sync/glue/sync_backend_host.cc b/chrome/browser/sync/glue/sync_backend_host.cc index bb4af125e..931721b 100644 --- a/chrome/browser/sync/glue/sync_backend_host.cc +++ b/chrome/browser/sync/glue/sync_backend_host.cc @@ -59,7 +59,8 @@ using sessions::SyncSessionSnapshot; using sync_api::SyncCredentials; SyncBackendHost::SyncBackendHost(Profile* profile) - : core_(new Core(ALLOW_THIS_IN_INITIALIZER_LIST(this))), + : core_(new Core(profile->GetDebugName(), + ALLOW_THIS_IN_INITIALIZER_LIST(this))), core_thread_("Chrome_SyncCoreThread"), frontend_loop_(MessageLoop::current()), profile_(profile), @@ -699,9 +700,9 @@ void SyncBackendHost::LogUnsyncedItems(int level) const { return core_->syncapi()->LogUnsyncedItems(level); } -SyncBackendHost::Core::Core(SyncBackendHost* backend) +SyncBackendHost::Core::Core(const std::string& name, SyncBackendHost* backend) : host_(backend), - syncapi_(new sync_api::SyncManager()), + syncapi_(new sync_api::SyncManager(name)), sync_manager_observer_(ALLOW_THIS_IN_INITIALIZER_LIST(this)), parent_router_(NULL), processing_passphrase_(false), diff --git a/chrome/browser/sync/glue/sync_backend_host.h b/chrome/browser/sync/glue/sync_backend_host.h index 8dd2b51..84b0537 100644 --- a/chrome/browser/sync/glue/sync_backend_host.h +++ b/chrome/browser/sync/glue/sync_backend_host.h @@ -270,7 +270,7 @@ class SyncBackendHost : public browser_sync::ModelSafeWorkerRegistrar { public JsBackend, public JsEventRouter { public: - explicit Core(SyncBackendHost* backend); + Core(const std::string& name, SyncBackendHost* backend); // SyncManager::Observer implementation. The Core just acts like an air // traffic controller here, forwarding incoming messages to appropriate diff --git a/chrome/browser/sync/profile_sync_service_harness.cc b/chrome/browser/sync/profile_sync_service_harness.cc index cc628ca..79aed37 100644 --- a/chrome/browser/sync/profile_sync_service_harness.cc +++ b/chrome/browser/sync/profile_sync_service_harness.cc @@ -9,6 +9,7 @@ #include <iterator> #include <ostream> #include <set> +#include <sstream> #include <vector> #include "base/json/json_writer.h" @@ -90,8 +91,7 @@ bool StateChangeTimeoutEvent::Abort() { ProfileSyncServiceHarness::ProfileSyncServiceHarness( Profile* profile, const std::string& username, - const std::string& password, - int id) + const std::string& password) : waiting_for_encryption_type_(syncable::UNSPECIFIED), wait_state_(INITIAL_WAIT_STATE), profile_(profile), @@ -99,7 +99,7 @@ ProfileSyncServiceHarness::ProfileSyncServiceHarness( timestamp_match_partner_(NULL), username_(username), password_(password), - id_(id) { + profile_debug_name_(profile->GetDebugName()) { if (IsSyncAlreadySetup()) { service_ = profile_->GetProfileSyncService(); service_->AddObserver(this); @@ -114,7 +114,7 @@ ProfileSyncServiceHarness* ProfileSyncServiceHarness::CreateAndAttach( NOTREACHED() << "Profile has never signed into sync."; return NULL; } - return new ProfileSyncServiceHarness(profile, "", "", 0); + return new ProfileSyncServiceHarness(profile, "", ""); } void ProfileSyncServiceHarness::SetCredentials(const std::string& username, @@ -136,10 +136,10 @@ bool ProfileSyncServiceHarness::SetupSync() { bool result = SetupSync(synced_datatypes); if (result == false) { std::string status = GetServiceStatus(); - LOG(ERROR) << "Client " << id_ << ": SetupSync failed. Syncer status:\n" - << status; + LOG(ERROR) << profile_debug_name_ + << ": SetupSync failed. Syncer status:\n" << status; } else { - VLOG(1) << "Client " << id_ << ": SetupSync successful."; + VLOG(1) << profile_debug_name_ << ": SetupSync successful."; } return result; } @@ -210,7 +210,7 @@ bool ProfileSyncServiceHarness::RunStateChangeMachine() { WaitState original_wait_state = wait_state_; switch (wait_state_) { case WAITING_FOR_ON_BACKEND_INITIALIZED: { - LogClientInfo("WAITING_FOR_ON_BACKEND_INITIALIZED", 1); + VLOG(1) << "WAITING_FOR_ON_BACKEND_INITIALIZED: " << GetClientInfo(); if (service()->sync_initialized()) { // The sync backend is initialized. SignalStateCompleteWithNextState(WAITING_FOR_INITIAL_SYNC); @@ -218,7 +218,7 @@ bool ProfileSyncServiceHarness::RunStateChangeMachine() { break; } case WAITING_FOR_INITIAL_SYNC: { - LogClientInfo("WAITING_FOR_INITIAL_SYNC", 1); + VLOG(1) << "WAITING_FOR_INITIAL_SYNC: " << GetClientInfo(); if (IsSynced()) { // The first sync cycle is now complete. We can start running tests. SignalStateCompleteWithNextState(FULLY_SYNCED); @@ -234,7 +234,7 @@ bool ProfileSyncServiceHarness::RunStateChangeMachine() { break; } case WAITING_FOR_SYNC_TO_FINISH: { - LogClientInfo("WAITING_FOR_SYNC_TO_FINISH", 1); + VLOG(1) << "WAITING_FOR_SYNC_TO_FINISH: " << GetClientInfo(); if (IsSynced()) { // The sync cycle we were waiting for is complete. SignalStateCompleteWithNextState(FULLY_SYNCED); @@ -256,7 +256,7 @@ bool ProfileSyncServiceHarness::RunStateChangeMachine() { break; } case WAITING_FOR_UPDATES: { - LogClientInfo("WAITING_FOR_UPDATES", 1); + VLOG(1) << "WAITING_FOR_UPDATES: " << GetClientInfo(); DCHECK(timestamp_match_partner_); if (!MatchesOtherClient(timestamp_match_partner_)) { // The client is not yet fully synced; keep waiting until we converge. @@ -269,7 +269,7 @@ bool ProfileSyncServiceHarness::RunStateChangeMachine() { break; } case WAITING_FOR_PASSPHRASE_REQUIRED: { - LogClientInfo("WAITING_FOR_PASSPHRASE_REQUIRED", 1); + VLOG(1) << "WAITING_FOR_PASSPHRASE_REQUIRED: " << GetClientInfo(); if (service()->IsPassphraseRequired()) { // A passphrase is now required. Wait for it to be accepted. SignalStateCompleteWithNextState(WAITING_FOR_PASSPHRASE_ACCEPTED); @@ -277,7 +277,7 @@ bool ProfileSyncServiceHarness::RunStateChangeMachine() { break; } case WAITING_FOR_PASSPHRASE_ACCEPTED: { - LogClientInfo("WAITING_FOR_PASSPHRASE_ACCEPTED", 1); + VLOG(1) << "WAITING_FOR_PASSPHRASE_ACCEPTED: " << GetClientInfo(); if (service()->ShouldPushChanges() && !service()->IsPassphraseRequired() && service()->IsUsingSecondaryPassphrase()) { @@ -287,7 +287,7 @@ bool ProfileSyncServiceHarness::RunStateChangeMachine() { break; } case WAITING_FOR_ENCRYPTION: { - LogClientInfo("WAITING_FOR_ENCRYPTION", 1); + VLOG(1) << "WAITING_FOR_ENCRYPTION: " << GetClientInfo(); if (IsSynced() && IsTypeEncrypted(waiting_for_encryption_type_) && GetLastSessionSnapshot()->num_conflicting_updates == 0) { @@ -304,7 +304,7 @@ bool ProfileSyncServiceHarness::RunStateChangeMachine() { break; } case WAITING_FOR_SYNC_CONFIGURATION: { - LogClientInfo("WAITING_FOR_SYNC_CONFIGURATION", 1); + VLOG(1) << "WAITING_FOR_SYNC_CONFIGURATION: " << GetClientInfo(); if (service()->ShouldPushChanges()) { // The Datatype manager is configured and sync is fully initialized. SignalStateCompleteWithNextState(FULLY_SYNCED); @@ -312,7 +312,7 @@ bool ProfileSyncServiceHarness::RunStateChangeMachine() { break; } case SERVER_UNREACHABLE: { - LogClientInfo("SERVER_UNREACHABLE", 1); + VLOG(1) << "SERVER_UNREACHABLE: " << GetClientInfo(); if (GetStatus().server_reachable) { // The client was offline due to the network being disabled, but is now // back online. Wait for the pending sync cycle to complete. @@ -323,17 +323,17 @@ bool ProfileSyncServiceHarness::RunStateChangeMachine() { case SET_PASSPHRASE_FAILED: { // A passphrase is required for decryption. There is nothing the sync // client can do until SetPassphrase() is called. - LogClientInfo("SET_PASSPHRASE_FAILED", 1); + VLOG(1) << "SET_PASSPHRASE_FAILED: " << GetClientInfo(); break; } case FULLY_SYNCED: { // The client is online and fully synced. There is nothing to do. - LogClientInfo("FULLY_SYNCED", 1); + VLOG(1) << "FULLY_SYNCED: " << GetClientInfo(); break; } case SYNC_DISABLED: { // Syncing is disabled for the client. There is nothing to do. - LogClientInfo("SYNC_DISABLED", 1); + VLOG(1) << "SYNC_DISABLED: " << GetClientInfo(); break; } default: @@ -349,9 +349,9 @@ void ProfileSyncServiceHarness::OnStateChanged() { } bool ProfileSyncServiceHarness::AwaitPassphraseRequired() { - LogClientInfo("AwaitPassphraseRequired", 1); + VLOG(1) << "AwaitPassphraseRequired: " << GetClientInfo(); if (wait_state_ == SYNC_DISABLED) { - LOG(ERROR) << "Sync disabled for Client " << id_ << "."; + LOG(ERROR) << "Sync disabled for " << profile_debug_name_ << "."; return false; } @@ -366,9 +366,9 @@ bool ProfileSyncServiceHarness::AwaitPassphraseRequired() { } bool ProfileSyncServiceHarness::AwaitPassphraseAccepted() { - LogClientInfo("AwaitPassphraseAccepted", 1); + VLOG(1) << "AwaitPassphraseAccepted: " << GetClientInfo(); if (wait_state_ == SYNC_DISABLED) { - LOG(ERROR) << "Sync disabled for Client " << id_ << "."; + LOG(ERROR) << "Sync disabled for " << profile_debug_name_ << "."; return false; } @@ -385,7 +385,7 @@ bool ProfileSyncServiceHarness::AwaitPassphraseAccepted() { } bool ProfileSyncServiceHarness::AwaitBackendInitialized() { - LogClientInfo("AwaitBackendInitialized", 1); + VLOG(1) << "AwaitBackendInitialized: " << GetClientInfo(); if (service()->sync_initialized()) { // The sync backend host has already been initialized; don't wait. return true; @@ -397,7 +397,7 @@ bool ProfileSyncServiceHarness::AwaitBackendInitialized() { } bool ProfileSyncServiceHarness::AwaitSyncRestart() { - LogClientInfo("AwaitSyncRestart", 1); + VLOG(1) << "AwaitSyncRestart: " << GetClientInfo(); if (service()->ShouldPushChanges()) { // Sync has already been restarted; don't wait. return true; @@ -419,9 +419,9 @@ bool ProfileSyncServiceHarness::AwaitSyncRestart() { bool ProfileSyncServiceHarness::AwaitSyncCycleCompletion( const std::string& reason) { - LogClientInfo("AwaitSyncCycleCompletion", 1); + VLOG(1) << "AwaitSyncCycleCompletion: " << GetClientInfo(); if (wait_state_ == SYNC_DISABLED) { - LOG(ERROR) << "Sync disabled for Client " << id_ << "."; + LOG(ERROR) << "Sync disabled for " << profile_debug_name_ << "."; return false; } @@ -435,26 +435,27 @@ bool ProfileSyncServiceHarness::AwaitSyncCycleCompletion( AwaitStatusChangeWithTimeout(kLiveSyncOperationTimeoutMs, reason); DCHECK_EQ(wait_state_, WAITING_FOR_SYNC_TO_FINISH); return AwaitStatusChangeWithTimeout(kLiveSyncOperationTimeoutMs, reason); + } + + DCHECK(service()->sync_initialized()); + wait_state_ = WAITING_FOR_SYNC_TO_FINISH; + AwaitStatusChangeWithTimeout(kLiveSyncOperationTimeoutMs, reason); + if (wait_state_ == FULLY_SYNCED) { + // Client is online; sync was successful. + return true; + } else if (wait_state_ == SERVER_UNREACHABLE) { + // Client is offline; sync was unsuccessful. + LOG(ERROR) << "Client went offline after waiting for sync to finish"; + return false; } else { - DCHECK(service()->sync_initialized()); - wait_state_ = WAITING_FOR_SYNC_TO_FINISH; - AwaitStatusChangeWithTimeout(kLiveSyncOperationTimeoutMs, reason); - if (wait_state_ == FULLY_SYNCED) { - // Client is online; sync was successful. - return true; - } else if (wait_state_ == SERVER_UNREACHABLE) { - // Client is offline; sync was unsuccessful. - return false; - } else { - LOG(ERROR) << "Invalid wait state:" << wait_state_; - return false; - } + LOG(ERROR) << "Invalid wait state: " << wait_state_; + return false; } } bool ProfileSyncServiceHarness::AwaitMutualSyncCycleCompletion( ProfileSyncServiceHarness* partner) { - LogClientInfo("AwaitMutualSyncCycleCompletion", 1); + VLOG(1) << "AwaitMutualSyncCycleCompletion: " << GetClientInfo(); if (!AwaitSyncCycleCompletion("Sync cycle completion on active client.")) return false; return partner->WaitUntilTimestampMatches(this, @@ -463,7 +464,7 @@ bool ProfileSyncServiceHarness::AwaitMutualSyncCycleCompletion( bool ProfileSyncServiceHarness::AwaitGroupSyncCycleCompletion( std::vector<ProfileSyncServiceHarness*>& partners) { - LogClientInfo("AwaitGroupSyncCycleCompletion", 1); + VLOG(1) << "AwaitGroupSyncCycleCompletion: " << GetClientInfo(); if (!AwaitSyncCycleCompletion("Sync cycle completion on active client.")) return false; bool return_value = true; @@ -494,9 +495,9 @@ bool ProfileSyncServiceHarness::AwaitQuiescence( bool ProfileSyncServiceHarness::WaitUntilTimestampMatches( ProfileSyncServiceHarness* partner, const std::string& reason) { - LogClientInfo("WaitUntilTimestampMatches", 1); + VLOG(1) << "WaitUntilTimestampMatches: " << GetClientInfo(); if (wait_state_ == SYNC_DISABLED) { - LOG(ERROR) << "Sync disabled for Client " << id_ << "."; + LOG(ERROR) << "Sync disabled for " << profile_debug_name_ << "."; return false; } @@ -515,9 +516,9 @@ bool ProfileSyncServiceHarness::WaitUntilTimestampMatches( bool ProfileSyncServiceHarness::AwaitStatusChangeWithTimeout( int timeout_milliseconds, const std::string& reason) { - LogClientInfo("AwaitStatusChangeWithTimeout", 1); + VLOG(1) << "AwaitStatusChangeWithTimeout: " << GetClientInfo(); if (wait_state_ == SYNC_DISABLED) { - LOG(ERROR) << "Sync disabled for Client " << id_ << "."; + LOG(ERROR) << "Sync disabled for " << profile_debug_name_ << "."; return false; } scoped_refptr<StateChangeTimeoutEvent> timeout_signal( @@ -533,10 +534,10 @@ bool ProfileSyncServiceHarness::AwaitStatusChangeWithTimeout( loop->Run(); loop->SetNestableTasksAllowed(did_allow_nestable_tasks); if (timeout_signal->Abort()) { - LogClientInfo("AwaitStatusChangeWithTimeout succeeded", 1); + VLOG(1) << "AwaitStatusChangeWithTimeout succeeded: " << GetClientInfo(); return true; } else { - LogClientInfo("AwaitStatusChangeWithTimeout timed out", 0); + VLOG(0) << "AwaitStatusChangeWithTimeout timed out: " << GetClientInfo(); return false; } } @@ -547,22 +548,26 @@ ProfileSyncService::Status ProfileSyncServiceHarness::GetStatus() { } bool ProfileSyncServiceHarness::IsSynced() { - LogClientInfo("IsSynced", 1); - if (service() == NULL) + VLOG(1) << "IsSynced: " << GetClientInfo(); + if (service() == NULL) { + VLOG(1) << "NULL service; assuming not synced"; return false; + } const SyncSessionSnapshot* snap = GetLastSessionSnapshot(); // TODO(rsimha): Remove additional checks of snap->has_more_to_sync and // snap->unsynced_count once http://crbug.com/48989 is fixed. - return (snap && - snap->num_blocking_conflicting_updates == 0 && - ServiceIsPushingChanges() && - GetStatus().notifications_enabled && - !service()->HasUnsyncedItems() && - !snap->has_more_to_sync && - snap->unsynced_count == 0 && - !service()->HasPendingBackendMigration() && - service()->passphrase_required_reason() != - sync_api::REASON_SET_PASSPHRASE_FAILED); + bool is_synced = snap && + snap->num_blocking_conflicting_updates == 0 && + ServiceIsPushingChanges() && + GetStatus().notifications_enabled && + !service()->HasUnsyncedItems() && + !snap->has_more_to_sync && + snap->unsynced_count == 0 && + !service()->HasPendingBackendMigration() && + service()->passphrase_required_reason() != + sync_api::REASON_SET_PASSPHRASE_FAILED; + VLOG(1) << "IsSynced: " << is_synced; + return is_synced; } bool ProfileSyncServiceHarness::MatchesOtherClient( @@ -601,7 +606,7 @@ const SyncSessionSnapshot* bool ProfileSyncServiceHarness::EnableSyncForDatatype( syncable::ModelType datatype) { - LogClientInfo("EnableSyncForDatatype", 1); + VLOG(1) << "EnableSyncForDatatype: " << GetClientInfo(); syncable::ModelTypeSet synced_datatypes; if (wait_state_ == SYNC_DISABLED) { @@ -619,7 +624,7 @@ bool ProfileSyncServiceHarness::EnableSyncForDatatype( if (it != synced_datatypes.end()) { VLOG(1) << "EnableSyncForDatatype(): Sync already enabled for datatype " << syncable::ModelTypeToString(datatype) - << " on Client " << id_ << "."; + << " on " << profile_debug_name_ << "."; return true; } @@ -628,17 +633,17 @@ bool ProfileSyncServiceHarness::EnableSyncForDatatype( if (AwaitSyncCycleCompletion("Datatype configuration.")) { VLOG(1) << "EnableSyncForDatatype(): Enabled sync for datatype " << syncable::ModelTypeToString(datatype) - << " on Client " << id_ << "."; + << " on " << profile_debug_name_ << "."; return true; } - LogClientInfo("EnableSyncForDatatype failed", 0); + VLOG(0) << "EnableSyncForDatatype failed: " << GetClientInfo(); return false; } bool ProfileSyncServiceHarness::DisableSyncForDatatype( syncable::ModelType datatype) { - LogClientInfo("DisableSyncForDatatype", 1); + VLOG(1) << "DisableSyncForDatatype: " << GetClientInfo(); syncable::ModelTypeSet synced_datatypes; if (service() == NULL) { @@ -651,7 +656,7 @@ bool ProfileSyncServiceHarness::DisableSyncForDatatype( if (it == synced_datatypes.end()) { VLOG(1) << "DisableSyncForDatatype(): Sync already disabled for datatype " << syncable::ModelTypeToString(datatype) - << " on Client " << id_ << "."; + << " on " << profile_debug_name_ << "."; return true; } @@ -660,16 +665,16 @@ bool ProfileSyncServiceHarness::DisableSyncForDatatype( if (AwaitSyncCycleCompletion("Datatype reconfiguration.")) { VLOG(1) << "DisableSyncForDatatype(): Disabled sync for datatype " << syncable::ModelTypeToString(datatype) - << " on Client " << id_ << "."; + << " on " << profile_debug_name_ << "."; return true; } - LogClientInfo("DisableSyncForDatatype failed", 0); + VLOG(0) << "DisableSyncForDatatype failed: " << GetClientInfo(); return false; } bool ProfileSyncServiceHarness::EnableSyncForAllDatatypes() { - LogClientInfo("EnableSyncForAllDatatypes", 1); + VLOG(1) << "EnableSyncForAllDatatypes: " << GetClientInfo(); if (wait_state_ == SYNC_DISABLED) { return SetupSync(); @@ -689,16 +694,16 @@ bool ProfileSyncServiceHarness::EnableSyncForAllDatatypes() { service()->OnUserChoseDatatypes(true, synced_datatypes); if (AwaitSyncCycleCompletion("Datatype reconfiguration.")) { VLOG(1) << "EnableSyncForAllDatatypes(): Enabled sync for all datatypes on " - "Client " << id_ << "."; + << profile_debug_name_ << "."; return true; } - LogClientInfo("EnableSyncForAllDatatypes failed", 0); + VLOG(0) << "EnableSyncForAllDatatypes failed: " << GetClientInfo(); return false; } bool ProfileSyncServiceHarness::DisableSyncForAllDatatypes() { - LogClientInfo("DisableSyncForAllDatatypes", 1); + VLOG(1) << "DisableSyncForAllDatatypes: " << GetClientInfo(); if (service() == NULL) { LOG(ERROR) << "DisableSyncForAllDatatypes(): service() is null."; @@ -708,7 +713,7 @@ bool ProfileSyncServiceHarness::DisableSyncForAllDatatypes() { service()->DisableForUser(); wait_state_ = SYNC_DISABLED; VLOG(1) << "DisableSyncForAllDatatypes(): Disabled sync for all datatypes on " - "Client " << id_; + << profile_debug_name_; return true; } @@ -719,39 +724,36 @@ std::string ProfileSyncServiceHarness::GetUpdatedTimestamp( return snap->download_progress_markers[model_type]; } -void ProfileSyncServiceHarness::LogClientInfo(const std::string& message, - int log_level) { +std::string ProfileSyncServiceHarness::GetClientInfo() { + std::stringstream os; + os << profile_debug_name_ << ": "; if (service()) { const SyncSessionSnapshot* snap = GetLastSessionSnapshot(); + const ProfileSyncService::Status& status = GetStatus(); if (snap) { - VLOG(log_level) << "Client " << id_ << ": " << message - << ": num_updates_downloaded : " - << snap->syncer_status.num_updates_downloaded_total - << ", has_more_to_sync: " << snap->has_more_to_sync - << ", unsynced_count: " << snap->unsynced_count - << ", num_blocking_conflicting_updates: " - << snap->num_blocking_conflicting_updates - << ", num_conflicting_updates: " - << snap->num_conflicting_updates - << ", has_unsynced_items: " - << service()->HasUnsyncedItems() - << ", passphrase_required_reason: " - << sync_api::PassphraseRequiredReasonToString( - service()->passphrase_required_reason()) - << ", notifications_enabled: " - << GetStatus().notifications_enabled - << ", service_is_pushing_changes: " - << ServiceIsPushingChanges() - << ", has_pending_backend_migration: " - << service()->HasPendingBackendMigration(); + os << "snapshot: " << snap->ToString() + << ", has_unsynced_items: " + << service()->HasUnsyncedItems() + << ", passphrase_required_reason: " + << sync_api::PassphraseRequiredReasonToString( + service()->passphrase_required_reason()) + << ", notifications_enabled: " + << status.notifications_enabled + << ", local_overwrites_total: " + << status.num_local_overwrites_total + << ", server_overwrites_total: " + << status.num_server_overwrites_total + << ", service_is_pushing_changes: " + << ServiceIsPushingChanges() + << ", has_pending_backend_migration: " + << service()->HasPendingBackendMigration(); } else { - VLOG(log_level) << "Client " << id_ << ": " << message - << ": Sync session snapshot not available."; + os << "Sync session snapshot not available"; } } else { - VLOG(log_level) << "Client " << id_ << ": " << message - << ": Sync service not available."; + os << "Sync service not available"; } + return os.str(); } bool ProfileSyncServiceHarness::EnableEncryptionForType( diff --git a/chrome/browser/sync/profile_sync_service_harness.h b/chrome/browser/sync/profile_sync_service_harness.h index 3053e99..54ad1d2 100644 --- a/chrome/browser/sync/profile_sync_service_harness.h +++ b/chrome/browser/sync/profile_sync_service_harness.h @@ -31,8 +31,7 @@ class ProfileSyncServiceHarness : public ProfileSyncServiceObserver { public: ProfileSyncServiceHarness(Profile* profile, const std::string& username, - const std::string& password, - int id); + const std::string& password); virtual ~ProfileSyncServiceHarness() {} @@ -220,9 +219,9 @@ class ProfileSyncServiceHarness : public ProfileSyncServiceObserver { // other client has. bool MatchesOtherClient(ProfileSyncServiceHarness* partner); - // Logs message with relevant info about client's sync state (if available). - // |log_level| denotes the VLOG level. - void LogClientInfo(const std::string& message, int log_level); + // Returns a string with relevant info about client's sync state (if + // available). Useful for logging. + std::string GetClientInfo(); // Gets the current progress indicator of the current sync session // for a particular datatype. @@ -253,8 +252,8 @@ class ProfileSyncServiceHarness : public ProfileSyncServiceObserver { std::string username_; std::string password_; - // Client ID, used for logging purposes. - int id_; + // Used for logging. + const std::string profile_debug_name_; DISALLOW_COPY_AND_ASSIGN(ProfileSyncServiceHarness); }; diff --git a/chrome/browser/sync/sessions/session_state.cc b/chrome/browser/sync/sessions/session_state.cc index e426d00..cb089d9 100644 --- a/chrome/browser/sync/sessions/session_state.cc +++ b/chrome/browser/sync/sessions/session_state.cc @@ -11,6 +11,8 @@ #include <vector> #include "base/base64.h" +#include "base/json/json_writer.h" +#include "base/memory/scoped_ptr.h" #include "base/values.h" #include "chrome/browser/sync/protocol/proto_enum_conversions.h" @@ -172,6 +174,13 @@ DictionaryValue* SyncSessionSnapshot::ToValue() const { return value; } +std::string SyncSessionSnapshot::ToString() const { + scoped_ptr<DictionaryValue> value(ToValue()); + std::string json; + base::JSONWriter::Write(value.get(), true, &json); + return json; +} + ConflictProgress::ConflictProgress(bool* dirty_flag) : dirty_(dirty_flag) {} ConflictProgress::~ConflictProgress() { diff --git a/chrome/browser/sync/sessions/session_state.h b/chrome/browser/sync/sessions/session_state.h index 41ec77e..f618fe9 100644 --- a/chrome/browser/sync/sessions/session_state.h +++ b/chrome/browser/sync/sessions/session_state.h @@ -134,6 +134,8 @@ struct SyncSessionSnapshot { // Caller takes ownership of the returned dictionary. DictionaryValue* ToValue() const; + std::string ToString() const; + const SyncerStatus syncer_status; const ErrorCounters errors; const int64 num_server_changes_remaining; diff --git a/chrome/test/live_sync/live_sync_extension_helper.cc b/chrome/test/live_sync/live_sync_extension_helper.cc index a3e3fc7..dc260ad 100644 --- a/chrome/test/live_sync/live_sync_extension_helper.cc +++ b/chrome/test/live_sync/live_sync_extension_helper.cc @@ -16,16 +16,6 @@ #include "chrome/test/live_sync/live_sync_test.h" #include "testing/gtest/include/gtest/gtest.h" -namespace { - -std::string GetProfileName(Profile* profile) { - const std::string& name = profile->GetPath().BaseName().MaybeAsASCII(); - EXPECT_FALSE(name.empty()); - return name; -} - -} // namespace - LiveSyncExtensionHelper::LiveSyncExtensionHelper() {} LiveSyncExtensionHelper::~LiveSyncExtensionHelper() {} @@ -91,7 +81,7 @@ void LiveSyncExtensionHelper::InstallExtensionsPendingForSync( StringMap::const_iterator it2 = id_to_name_.find(id); if (it2 == id_to_name_.end()) { ADD_FAILURE() << "Could not get name for id " << id - << " (profile = " << GetProfileName(profile) << ")"; + << " (profile = " << profile->GetDebugName() << ")"; continue; } InstallExtension(profile, it2->second, type); @@ -101,7 +91,7 @@ void LiveSyncExtensionHelper::InstallExtensionsPendingForSync( LiveSyncExtensionHelper::ExtensionStateMap LiveSyncExtensionHelper::GetExtensionStates( Profile* profile) const { - const std::string& profile_name = GetProfileName(profile); + const std::string& profile_debug_name = profile->GetDebugName(); ExtensionStateMap extension_state_map; @@ -112,7 +102,7 @@ LiveSyncExtensionHelper::ExtensionStateMap it != extensions->end(); ++it) { extension_state_map[(*it)->id()] = ENABLED; VLOG(2) << "Extension " << (*it)->id() << " in profile " - << profile_name << " is enabled"; + << profile_debug_name << " is enabled"; } const ExtensionList* disabled_extensions = @@ -121,7 +111,7 @@ LiveSyncExtensionHelper::ExtensionStateMap it != disabled_extensions->end(); ++it) { extension_state_map[(*it)->id()] = DISABLED; VLOG(2) << "Extension " << (*it)->id() << " in profile " - << profile_name << " is disabled"; + << profile_debug_name << " is disabled"; } const PendingExtensionManager* pending_extension_manager = @@ -131,7 +121,7 @@ LiveSyncExtensionHelper::ExtensionStateMap it != pending_extension_manager->end(); ++it) { extension_state_map[it->first] = PENDING; VLOG(2) << "Extension " << it->first << " in profile " - << profile_name << " is pending"; + << profile_debug_name << " is pending"; } return extension_state_map; diff --git a/chrome/test/live_sync/live_sync_test.cc b/chrome/test/live_sync/live_sync_test.cc index b45d3ac..3eeb6a005 100644 --- a/chrome/test/live_sync/live_sync_test.cc +++ b/chrome/test/live_sync/live_sync_test.cc @@ -262,7 +262,7 @@ bool LiveSyncTest::SetupClients() { base::StringPrintf(FILE_PATH_LITERAL("Profile%d"), i))); EXPECT_FALSE(GetProfile(i) == NULL) << "GetProfile(" << i << ") failed."; clients_.push_back( - new ProfileSyncServiceHarness(GetProfile(i), username_, password_, i)); + new ProfileSyncServiceHarness(GetProfile(i), username_, password_)); EXPECT_FALSE(GetClient(i) == NULL) << "GetClient(" << i << ") failed."; } diff --git a/net/test/test_server.cc b/net/test/test_server.cc index aa704a8..b6d3286 100644 --- a/net/test/test_server.cc +++ b/net/test/test_server.cc @@ -349,7 +349,7 @@ bool TestServer::AddCommandLineArguments(CommandLine* command_line) const { command_line->AppendArgNative(FILE_PATH_LITERAL("--data-dir=") + document_root_.value()); - if (logging::GetMinLogLevel() == logging::LOG_VERBOSE) { + if (VLOG_IS_ON(1)) { command_line->AppendArg("--log-to-console"); } |