[Sync] Clean up sync logging

Add GetDebugName() method to Profile.  Use it in ProfileSyncServiceHarness,
SyncerThread, and LiveSyncExtensionHelper.

Change VLOG(1)s in SyncerThread to VLOG(2)s.

Turn on logging for the test server if VLOG is enabled for that file, and not just in general.

BUG=
TEST=

Review URL: http://codereview.chromium.org/7024058

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@88355 0039d316-1c4b-4281-b951-d872f2087c98

19 files changed, 263 insertions, 227 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.";
   }