Add more debug logging to trace a race condition.

BUG=
TEST=

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

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

10 files changed, 122 insertions, 53 deletions

diff --git a/chrome/browser/sync/engine/syncapi.cc b/chrome/browser/sync/engine/syncapi.cc
index 43748a1..ef3eb68 100644
--- a/chrome/browser/sync/engine/syncapi.cc
+++ b/chrome/browser/sync/engine/syncapi.cc
@@ -14,6 +14,7 @@
 
 #include "base/base64.h"
 #include "base/command_line.h"
+#include "base/json/json_writer.h"
 #include "base/logging.h"
 #include "base/memory/scoped_ptr.h"
 #include "base/message_loop.h"
@@ -1781,6 +1782,7 @@ void SyncManager::SyncInternal::BootstrapEncryption(
     const std::string& restored_key_for_bootstrapping) {
   syncable::ScopedDirLookup lookup(dir_manager(), username_for_share());
   if (!lookup.good()) {
+    VLOG(0) << "BootstrapEncryption: lookup not good so bailing out";
     NOTREACHED();
     return;
   }
@@ -2471,8 +2473,10 @@ void SyncManager::SyncInternal::RequestNudgeWithDataTypes(
 
 void SyncManager::SyncInternal::OnSyncEngineEvent(
     const SyncEngineEvent& event) {
-  if (observers_.size() <= 0)
+  if (observers_.size() <= 0) {
+    VLOG(0) << "OnSyncEngineEvent returning because observers_.size() is zero";
     return;
+  }
 
   // Only send an event if this is due to a cycle ending and this cycle
   // concludes a canonical "sync" process; that is, based on what is known
@@ -2511,9 +2515,12 @@ void SyncManager::SyncInternal::OnSyncEngineEvent(
         // If we've completed a sync cycle and the cryptographer isn't ready
         // yet, prompt the user for a passphrase.
         if (cryptographer->has_pending_keys()) {
+          VLOG(0) << "OnPassPhraseRequired Sent";
           FOR_EACH_OBSERVER(SyncManager::Observer, observers_,
                             OnPassphraseRequired(sync_api::REASON_DECRYPTION));
         } else if (!cryptographer->is_ready()) {
+          VLOG(0) << "OnPassphraseRequired sent because cryptographer is not "
+                  << "ready";
           FOR_EACH_OBSERVER(SyncManager::Observer, observers_,
                             OnPassphraseRequired(sync_api::REASON_ENCRYPTION));
         } else {
@@ -2523,10 +2530,14 @@ void SyncManager::SyncInternal::OnSyncEngineEvent(
       }
     }
 
-    if (!initialized())
+    if (!initialized()) {
+      VLOG(0) << "OnSyncCycleCompleted not sent because sync api is not "
+              << "initialized";
       return;
+    }
 
     if (!event.snapshot->has_more_to_sync) {
+      VLOG(1) << "OnSyncCycleCompleted sent";
       FOR_EACH_OBSERVER(SyncManager::Observer, observers_,
                         OnSyncCycleCompleted(event.snapshot));
     }
@@ -2831,6 +2842,24 @@ bool SyncManager::HasUnsyncedItems() const {
   return (trans.GetWrappedTrans()->directory()->unsynced_entity_count() != 0);
 }
 
+void SyncManager::LogUnsyncedItems(int level) const {
+  std::vector<int64> unsynced_handles;
+  sync_api::ReadTransaction trans(GetUserShare());
+  trans.GetWrappedTrans()->directory()->GetUnsyncedMetaHandles(
+      trans.GetWrappedTrans(), &unsynced_handles);
+
+  for (std::vector<int64>::const_iterator it = unsynced_handles.begin();
+       it != unsynced_handles.end(); ++it) {
+    ReadNode node(&trans);
+    if (node.InitByIdLookup(*it)) {
+      scoped_ptr<DictionaryValue> value(node.ToValue());
+      std::string info;
+      base::JSONWriter::Write(value.get(), true, &info);
+      VLOG(level) << info;
+    }
+  }
+}
+
 void SyncManager::TriggerOnNotificationStateChangeForTest(
     bool notifications_enabled) {
   data_->OnNotificationStateChange(notifications_enabled);
diff --git a/chrome/browser/sync/engine/syncapi.h b/chrome/browser/sync/engine/syncapi.h
index 75c4c2a..9128889 100644
--- a/chrome/browser/sync/engine/syncapi.h
+++ b/chrome/browser/sync/engine/syncapi.h
@@ -1011,6 +1011,9 @@ class SyncManager {
   // any remaining unsynced items.
   bool HasUnsyncedItems() const;
 
+  // Logs the list of unsynced meta handles.
+  void LogUnsyncedItems(int level) const;
+
   // Functions used for testing.
 
   void TriggerOnNotificationStateChangeForTest(
diff --git a/chrome/browser/sync/engine/syncer_thread.cc b/chrome/browser/sync/engine/syncer_thread.cc
index dda78a1..a567111 100644
--- a/chrome/browser/sync/engine/syncer_thread.cc
+++ b/chrome/browser/sync/engine/syncer_thread.cc
@@ -310,6 +310,7 @@ 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.";
     NOTREACHED();
     return;
   }
@@ -446,6 +447,7 @@ void GetModelSafeParamsForTypes(const ModelTypeBitSet& types,
 
 void SyncerThread::ScheduleConfig(const ModelTypeBitSet& types) {
   if (!thread_.IsRunning()) {
+    VLOG(0) << "ScheduleConfig failed because thread is not running.";
     NOTREACHED();
     return;
   }
diff --git a/chrome/browser/sync/glue/data_type_manager_impl.cc b/chrome/browser/sync/glue/data_type_manager_impl.cc
index ef7936b..000bbe3 100644
--- a/chrome/browser/sync/glue/data_type_manager_impl.cc
+++ b/chrome/browser/sync/glue/data_type_manager_impl.cc
@@ -109,7 +109,7 @@ void DataTypeManagerImpl::Configure(const TypeSet& desired_types) {
   last_requested_types_ = desired_types;
   // Only proceed if we're in a steady state or blocked.
   if (state_ != STOPPED && state_ != CONFIGURED && state_ != BLOCKED) {
-    VLOG(1) << "Received configure request while configuration in flight. "
+    VLOG(0) << "Received configure request while configuration in flight. "
             << "Postponing until current configuration complete.";
     needs_reconfigure_ = true;
     return;
@@ -203,7 +203,7 @@ void DataTypeManagerImpl::StartNextType() {
     // because we may need to stop datatypes.
     SetBlockedAndNotify();
     needs_reconfigure_ = false;
-    VLOG(1) << "Reconfiguring due to previous configure attempt occuring while"
+    VLOG(0) << "Reconfiguring due to previous configure attempt occuring while"
             << " busy.";
 
     // Unwind the stack before executing configure. The method configure and its
@@ -218,6 +218,7 @@ void DataTypeManagerImpl::StartNextType() {
   // things like encryption, which may still need to be sorted out before we
   // can announce we're "Done" configuration entirely.
   if (GetControllersNeedingStart(NULL)) {
+    VLOG(0) << "GetControllersNeedingStart returned true. DTM blocked";
     SetBlockedAndNotify();
     return;
   }
@@ -270,7 +271,7 @@ void DataTypeManagerImpl::TypeStartCallback(
   // Any other result is a fatal error.  Shut down any types we've
   // managed to start up to this point and pass the result to the
   // callback.
-  VLOG(1) << "Failed " << started_dtc->name();
+  VLOG(0) << "Failed " << started_dtc->name();
   ConfigureResult configure_result = DataTypeManager::ABORTED;
   switch (result) {
     case DataTypeController::ABORTED:
@@ -356,6 +357,7 @@ void DataTypeManagerImpl::NotifyDone(ConfigureResult result,
     const tracked_objects::Location& location) {
   ConfigureResultWithErrorLocation result_with_location(result, location,
                                                         last_requested_types_);
+  VLOG(0) << "NotifyDone called with result: " << result;
   NotificationService::current()->Notify(
       NotificationType::SYNC_CONFIGURE_DONE,
       Source<DataTypeManager>(this),
diff --git a/chrome/browser/sync/glue/sync_backend_host.cc b/chrome/browser/sync/glue/sync_backend_host.cc
index 688a4fa..e5e2259 100644
--- a/chrome/browser/sync/glue/sync_backend_host.cc
+++ b/chrome/browser/sync/glue/sync_backend_host.cc
@@ -212,6 +212,7 @@ void SyncBackendHost::UpdateCredentials(const SyncCredentials& credentials) {
 }
 
 void SyncBackendHost::StartSyncingWithServer() {
+  VLOG(0) << "SyncBackendHost::StartSyncingWithServer called.";
   core_thread_.message_loop()->PostTask(FROM_HERE,
       NewRunnableMethod(core_.get(), &SyncBackendHost::Core::DoStartSyncing));
 }
@@ -663,6 +664,11 @@ bool SyncBackendHost::HasUnsyncedItems() const {
   return core_->syncapi()->HasUnsyncedItems();
 }
 
+void SyncBackendHost::LogUnsyncedItems(int level) const {
+  DCHECK(syncapi_initialized_);
+  return core_->syncapi()->LogUnsyncedItems(level);
+}
+
 SyncBackendHost::Core::Core(SyncBackendHost* backend)
     : host_(backend),
       syncapi_(new sync_api::SyncManager()),
diff --git a/chrome/browser/sync/glue/sync_backend_host.h b/chrome/browser/sync/glue/sync_backend_host.h
index 007e106..063d05a 100644
--- a/chrome/browser/sync/glue/sync_backend_host.h
+++ b/chrome/browser/sync/glue/sync_backend_host.h
@@ -234,6 +234,9 @@ class SyncBackendHost : public browser_sync::ModelSafeWorkerRegistrar {
   // ONLY CALL THIS IF OnInitializationComplete was called!
   bool HasUnsyncedItems() const;
 
+  // Logs the unsynced items.
+  void LogUnsyncedItems(int level) const;
+
   // Whether or not we are syncing encryption keys.
   bool IsNigoriEnabled() const;
 
diff --git a/chrome/browser/sync/profile_sync_service.cc b/chrome/browser/sync/profile_sync_service.cc
index a8606cb..2c50830 100644
--- a/chrome/browser/sync/profile_sync_service.cc
+++ b/chrome/browser/sync/profile_sync_service.cc
@@ -867,6 +867,7 @@ void ProfileSyncService::OnUserCancelledDialog() {
 void ProfileSyncService::ChangePreferredDataTypes(
     const syncable::ModelTypeSet& preferred_types) {
 
+  VLOG(0) << "ChangePreferredDataTypes invoked";
   // Filter out any datatypes which aren't registered, or for which
   // the preference can't be set.
   syncable::ModelTypeSet registered_types;
@@ -888,8 +889,12 @@ void ProfileSyncService::ChangePreferredDataTypes(
 
   // If we haven't initialized yet, don't configure the DTM as it could cause
   // association to start before a Directory has even been created.
-  if (backend_initialized_)
+  if (backend_initialized_) {
     ConfigureDataTypeManager();
+  } else {
+    VLOG(0) << "ConfigureDataTypeManager not invoked because backend is not "
+            << "initialized";
+  }
 }
 
 void ProfileSyncService::GetPreferredDataTypes(
@@ -1025,6 +1030,14 @@ bool ProfileSyncService::HasUnsyncedItems() const {
   return false;
 }
 
+void ProfileSyncService::LogUnsyncedItems(int level) const {
+  if (backend_.get() && backend_initialized_) {
+    return backend_->LogUnsyncedItems(level);
+  }
+  VLOG(level) << "Unsynced items not printed because backend is not "
+              << "initialized";
+}
+
 bool ProfileSyncService::HasPendingBackendMigration() const {
   return migrator_.get() &&
       migrator_->state() != browser_sync::BackendMigrator::IDLE;
@@ -1134,6 +1147,7 @@ void ProfileSyncService::Observe(NotificationType type,
               details).ptr();
 
       DataTypeManager::ConfigureResult result = result_with_location->result;
+      VLOG(0) << "PSS SYNC_CONFIGURE_DONE called with result: " << result;
       if (result == DataTypeManager::ABORTED &&
           expect_sync_configuration_aborted_) {
         expect_sync_configuration_aborted_ = false;
diff --git a/chrome/browser/sync/profile_sync_service.h b/chrome/browser/sync/profile_sync_service.h
index e343b12..7a284cd 100644
--- a/chrome/browser/sync/profile_sync_service.h
+++ b/chrome/browser/sync/profile_sync_service.h
@@ -364,6 +364,9 @@ class ProfileSyncService : public browser_sync::SyncFrontend,
   // server.
   bool HasUnsyncedItems() const;
 
+  // Logs the current unsynced items in the sync database. Useful for debugging.
+  void LogUnsyncedItems(int level) const;
+
   // Returns whether or not the sync service is reconfiguring due
   // to server-initiated resynchronization.
   bool HasPendingBackendMigration() const;
diff --git a/chrome/browser/sync/profile_sync_service_harness.cc b/chrome/browser/sync/profile_sync_service_harness.cc
index 1988768..fdbbe01 100644
--- a/chrome/browser/sync/profile_sync_service_harness.cc
+++ b/chrome/browser/sync/profile_sync_service_harness.cc
@@ -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");
+      LogClientInfo("WAITING_FOR_ON_BACKEND_INITIALIZED", 1);
       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");
+      LogClientInfo("WAITING_FOR_INITIAL_SYNC", 1);
       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");
+      LogClientInfo("WAITING_FOR_SYNC_TO_FINISH", 1);
       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");
+      LogClientInfo("WAITING_FOR_UPDATES", 1);
       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_ACCEPTED: {
-      LogClientInfo("WAITING_FOR_PASSPHRASE_ACCEPTED");
+      LogClientInfo("WAITING_FOR_PASSPHRASE_ACCEPTED", 1);
       if (service()->ShouldPushChanges() &&
           !service()->IsPassphraseRequired()) {
         // The passphrase has been accepted, and sync has been restarted.
@@ -278,7 +278,7 @@ bool ProfileSyncServiceHarness::RunStateChangeMachine() {
       break;
     }
     case WAITING_FOR_ENCRYPTION: {
-      LogClientInfo("WAITING_FOR_ENCRYPTION");
+      LogClientInfo("WAITING_FOR_ENCRYPTION", 1);
       if (IsTypeEncrypted(waiting_for_encryption_type_)) {
         // Encryption is complete for the type we are waiting on.
         SignalStateCompleteWithNextState(FULLY_SYNCED);
@@ -286,7 +286,7 @@ bool ProfileSyncServiceHarness::RunStateChangeMachine() {
       break;
     }
     case WAITING_FOR_SYNC_CONFIGURATION: {
-      LogClientInfo("WAITING_FOR_SYNC_CONFIGURATION");
+      LogClientInfo("WAITING_FOR_SYNC_CONFIGURATION", 1);
       if (service()->ShouldPushChanges()) {
         // The Datatype manager is configured and sync is fully initialized.
         SignalStateCompleteWithNextState(FULLY_SYNCED);
@@ -294,7 +294,7 @@ bool ProfileSyncServiceHarness::RunStateChangeMachine() {
       break;
     }
     case SERVER_UNREACHABLE: {
-      LogClientInfo("SERVER_UNREACHABLE");
+      LogClientInfo("SERVER_UNREACHABLE", 1);
       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.
@@ -305,17 +305,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");
+      LogClientInfo("SET_PASSPHRASE_FAILED", 1);
       break;
     }
     case FULLY_SYNCED: {
       // The client is online and fully synced. There is nothing to do.
-      LogClientInfo("FULLY_SYNCED");
+      LogClientInfo("FULLY_SYNCED", 1);
       break;
     }
     case SYNC_DISABLED: {
       // Syncing is disabled for the client. There is nothing to do.
-      LogClientInfo("SYNC_DISABLED");
+      LogClientInfo("SYNC_DISABLED", 1);
       break;
     }
     default:
@@ -331,7 +331,7 @@ void ProfileSyncServiceHarness::OnStateChanged() {
 }
 
 bool ProfileSyncServiceHarness::AwaitPassphraseAccepted() {
-  LogClientInfo("AwaitPassphraseAccepted");
+  LogClientInfo("AwaitPassphraseAccepted", 1);
   if (wait_state_ == SYNC_DISABLED) {
     LOG(ERROR) << "Sync disabled for Client " << id_ << ".";
     return false;
@@ -349,7 +349,7 @@ bool ProfileSyncServiceHarness::AwaitPassphraseAccepted() {
 }
 
 bool ProfileSyncServiceHarness::AwaitBackendInitialized() {
-  LogClientInfo("AwaitBackendInitialized");
+  LogClientInfo("AwaitBackendInitialized", 1);
   if (service()->sync_initialized()) {
     // The sync backend host has already been initialized; don't wait.
     return true;
@@ -361,7 +361,7 @@ bool ProfileSyncServiceHarness::AwaitBackendInitialized() {
 }
 
 bool ProfileSyncServiceHarness::AwaitSyncRestart() {
-  LogClientInfo("AwaitSyncRestart");
+  LogClientInfo("AwaitSyncRestart", 1);
   if (service()->ShouldPushChanges()) {
     // Sync has already been restarted; don't wait.
     return true;
@@ -383,7 +383,7 @@ bool ProfileSyncServiceHarness::AwaitSyncRestart() {
 
 bool ProfileSyncServiceHarness::AwaitSyncCycleCompletion(
     const std::string& reason) {
-  LogClientInfo("AwaitSyncCycleCompletion");
+  LogClientInfo("AwaitSyncCycleCompletion", 1);
   if (wait_state_ == SYNC_DISABLED) {
     LOG(ERROR) << "Sync disabled for Client " << id_ << ".";
     return false;
@@ -418,7 +418,7 @@ bool ProfileSyncServiceHarness::AwaitSyncCycleCompletion(
 
 bool ProfileSyncServiceHarness::AwaitMutualSyncCycleCompletion(
     ProfileSyncServiceHarness* partner) {
-  LogClientInfo("AwaitMutualSyncCycleCompletion");
+  LogClientInfo("AwaitMutualSyncCycleCompletion", 1);
   if (!AwaitSyncCycleCompletion("Sync cycle completion on active client."))
     return false;
   return partner->WaitUntilTimestampMatches(this,
@@ -427,7 +427,7 @@ bool ProfileSyncServiceHarness::AwaitMutualSyncCycleCompletion(
 
 bool ProfileSyncServiceHarness::AwaitGroupSyncCycleCompletion(
     std::vector<ProfileSyncServiceHarness*>& partners) {
-  LogClientInfo("AwaitGroupSyncCycleCompletion");
+  LogClientInfo("AwaitGroupSyncCycleCompletion", 1);
   if (!AwaitSyncCycleCompletion("Sync cycle completion on active client."))
     return false;
   bool return_value = true;
@@ -458,7 +458,7 @@ bool ProfileSyncServiceHarness::AwaitQuiescence(
 
 bool ProfileSyncServiceHarness::WaitUntilTimestampMatches(
     ProfileSyncServiceHarness* partner, const std::string& reason) {
-  LogClientInfo("WaitUntilTimestampMatches");
+  LogClientInfo("WaitUntilTimestampMatches", 1);
   if (wait_state_ == SYNC_DISABLED) {
     LOG(ERROR) << "Sync disabled for Client " << id_ << ".";
     return false;
@@ -479,7 +479,7 @@ bool ProfileSyncServiceHarness::WaitUntilTimestampMatches(
 bool ProfileSyncServiceHarness::AwaitStatusChangeWithTimeout(
     int timeout_milliseconds,
     const std::string& reason) {
-  LogClientInfo("AwaitStatusChangeWithTimeout");
+  LogClientInfo("AwaitStatusChangeWithTimeout", 1);
   if (wait_state_ == SYNC_DISABLED) {
     LOG(ERROR) << "Sync disabled for Client " << id_ << ".";
     return false;
@@ -497,10 +497,10 @@ bool ProfileSyncServiceHarness::AwaitStatusChangeWithTimeout(
   loop->Run();
   loop->SetNestableTasksAllowed(did_allow_nestable_tasks);
   if (timeout_signal->Abort()) {
-    LogClientInfo("AwaitStatusChangeWithTimeout succeeded");
+    LogClientInfo("AwaitStatusChangeWithTimeout succeeded", 1);
     return true;
   } else {
-    LogClientInfo("AwaitStatusChangeWithTimeout timed out");
+    LogClientInfo("AwaitStatusChangeWithTimeout timed out", 0);
     return false;
   }
 }
@@ -511,7 +511,7 @@ ProfileSyncService::Status ProfileSyncServiceHarness::GetStatus() {
 }
 
 bool ProfileSyncServiceHarness::IsSynced() {
-  LogClientInfo("IsSynced");
+  LogClientInfo("IsSynced", 1);
   if (service() == NULL)
     return false;
   const SyncSessionSnapshot* snap = GetLastSessionSnapshot();
@@ -565,7 +565,7 @@ const SyncSessionSnapshot*
 
 void ProfileSyncServiceHarness::EnableSyncForDatatype(
     syncable::ModelType datatype) {
-  LogClientInfo("EnableSyncForDatatype");
+  LogClientInfo("EnableSyncForDatatype", 1);
   syncable::ModelTypeSet synced_datatypes;
   if (wait_state_ == SYNC_DISABLED) {
     wait_state_ = WAITING_FOR_ON_BACKEND_INITIALIZED;
@@ -593,7 +593,7 @@ void ProfileSyncServiceHarness::EnableSyncForDatatype(
 
 void ProfileSyncServiceHarness::DisableSyncForDatatype(
     syncable::ModelType datatype) {
-  LogClientInfo("DisableSyncForDatatype");
+  LogClientInfo("DisableSyncForDatatype", 1);
   syncable::ModelTypeSet synced_datatypes;
   DCHECK(service() != NULL) << "DisableSyncForDatatype(): service() is null.";
   service()->GetPreferredDataTypes(&synced_datatypes);
@@ -611,7 +611,7 @@ void ProfileSyncServiceHarness::DisableSyncForDatatype(
 }
 
 void ProfileSyncServiceHarness::EnableSyncForAllDatatypes() {
-  LogClientInfo("EnableSyncForAllDatatypes");
+  LogClientInfo("EnableSyncForAllDatatypes", 1);
   if (wait_state_ == SYNC_DISABLED) {
     wait_state_ = WAITING_FOR_ON_BACKEND_INITIALIZED;
     DCHECK(SetupSync()) << "Reinitialization of Client " << id_ << " failed.";
@@ -632,7 +632,7 @@ void ProfileSyncServiceHarness::EnableSyncForAllDatatypes() {
 }
 
 void ProfileSyncServiceHarness::DisableSyncForAllDatatypes() {
-  LogClientInfo("DisableSyncForAllDatatypes");
+  LogClientInfo("DisableSyncForAllDatatypes", 1);
   DCHECK(service() != NULL) << "EnableSyncForAllDatatypes(): service() is "
                                "null.";
   service()->DisableForUser();
@@ -648,33 +648,39 @@ std::string ProfileSyncServiceHarness::GetUpdatedTimestamp(
   return snap->download_progress_markers[model_type];
 }
 
-void ProfileSyncServiceHarness::LogClientInfo(const std::string& message) {
-  // TODO(lipalani): Change VLOG(0) to VLOG(1) -- See http://crbug.com/80706.
+void ProfileSyncServiceHarness::LogClientInfo(const std::string& message,
+                                              int log_level) {
   if (service()) {
     const SyncSessionSnapshot* snap = GetLastSessionSnapshot();
     if (snap) {
-      VLOG(0) << "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_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();
+      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_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();
+
+    if (service()->HasUnsyncedItems()) {
+         service()->LogUnsyncedItems(log_level);
+      }
     } else {
-      VLOG(0) << "Client " << id_ << ": " << message
+      VLOG(log_level) << "Client " << id_ << ": " << message
               << ": Sync session snapshot not available.";
     }
   } else {
-    VLOG(0) << "Client " << id_ << ": " << message
+    VLOG(log_level) << "Client " << id_ << ": " << message
             << ": Sync service not available.";
   }
 }
diff --git a/chrome/browser/sync/profile_sync_service_harness.h b/chrome/browser/sync/profile_sync_service_harness.h
index af1d83c..1ed972f 100644
--- a/chrome/browser/sync/profile_sync_service_harness.h
+++ b/chrome/browser/sync/profile_sync_service_harness.h
@@ -209,7 +209,8 @@ class ProfileSyncServiceHarness : public ProfileSyncServiceObserver {
   bool MatchesOtherClient(ProfileSyncServiceHarness* partner);
 
   // Logs message with relevant info about client's sync state (if available).
-  void LogClientInfo(const std::string& message);
+  // |log_level| denotes the VLOG level.
+  void LogClientInfo(const std::string& message, int log_level);
 
   // Gets the current progress indicator of the current sync session
   // for a particular datatype.