[SyncFS] Add verbose logging to RemoteToLocalSyncer

BUG=240165
NOTRY=true
R=kinuko@chromium.org, nhiroki@chromium.org

Review URL: https://codereview.chromium.org/108693003

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

3 files changed, 62 insertions, 0 deletions

diff --git a/chrome/browser/sync_file_system/drive_backend/remote_to_local_syncer.cc b/chrome/browser/sync_file_system/drive_backend/remote_to_local_syncer.cc
index a09e6f2..f5e14dd 100644
--- a/chrome/browser/sync_file_system/drive_backend/remote_to_local_syncer.cc
+++ b/chrome/browser/sync_file_system/drive_backend/remote_to_local_syncer.cc
@@ -6,6 +6,7 @@
 
 #include "base/bind.h"
 #include "base/callback.h"
+#include "base/format_macros.h"
 #include "base/location.h"
 #include "base/logging.h"
 #include "base/message_loop/message_loop_proxy.h"
@@ -16,6 +17,7 @@
 #include "chrome/browser/sync_file_system/drive_backend/metadata_database.h"
 #include "chrome/browser/sync_file_system/drive_backend/sync_engine_context.h"
 #include "chrome/browser/sync_file_system/drive_backend_v1/drive_file_sync_util.h"
+#include "chrome/browser/sync_file_system/logger.h"
 #include "chrome/browser/sync_file_system/syncable_file_system_util.h"
 #include "extensions/common/extension.h"
 #include "google_apis/drive/drive_api_parser.h"
@@ -87,6 +89,8 @@ RemoteToLocalSyncer::~RemoteToLocalSyncer() {
 
 void RemoteToLocalSyncer::Run(const SyncStatusCallback& callback) {
   if (!drive_service() || !metadata_database() || !remote_change_processor()) {
+    util::Log(logging::LOG_VERBOSE, FROM_HERE,
+              "[Remote -> Local] Context not ready.");
     NOTREACHED();
     callback.Run(SYNC_STATUS_FAILED);
     return;
@@ -101,10 +105,15 @@ void RemoteToLocalSyncer::Run(const SyncStatusCallback& callback) {
   dirty_tracker_ = make_scoped_ptr(new FileTracker);
   if (metadata_database()->GetNormalPriorityDirtyTracker(
           dirty_tracker_.get())) {
+    util::Log(logging::LOG_VERBOSE, FROM_HERE,
+              "[Remote -> Local] Start: tracker_id=%" PRId64,
+              dirty_tracker_->tracker_id());
     ResolveRemoteChange(wrapped_callback);
     return;
   }
 
+  util::Log(logging::LOG_VERBOSE, FROM_HERE,
+            "[Remote -> Local] Nothing to do.");
   base::MessageLoopProxy::current()->PostTask(
       FROM_HERE,
       base::Bind(callback, SYNC_STATUS_NO_CHANGE_TO_SYNC));
@@ -122,6 +131,8 @@ void RemoteToLocalSyncer::ResolveRemoteChange(
                  << remote_metadata_->file_id();
       NOTREACHED();
     }
+    util::Log(logging::LOG_VERBOSE, FROM_HERE,
+              "[Remote -> Local]: Missing remote file case.");
     HandleMissingRemoteMetadata(callback);
     return;
   }
@@ -133,6 +144,8 @@ void RemoteToLocalSyncer::ResolveRemoteChange(
   if (!dirty_tracker_->active() ||
       HasDisabledAppRoot(metadata_database(), *dirty_tracker_)) {
     // Handle inactive tracker in SyncCompleted.
+    util::Log(logging::LOG_VERBOSE, FROM_HERE,
+              "[Remote -> Local]: Inactive tracker case.");
     callback.Run(SYNC_STATUS_OK);
     return;
   }
@@ -156,9 +169,13 @@ void RemoteToLocalSyncer::ResolveRemoteChange(
     if (remote_details.missing() ||
         synced_details.title() != remote_details.title() ||
         remote_details.parent_folder_ids_size()) {
+      util::Log(logging::LOG_VERBOSE, FROM_HERE,
+                "[Remote -> Local]: Sync-root deletion.");
       HandleSyncRootDeletion(callback);
       return;
     }
+    util::Log(logging::LOG_VERBOSE, FROM_HERE,
+              "[Remote -> Local]: Trivial sync-root change.");
     callback.Run(SYNC_STATUS_OK);
     return;
   }
@@ -168,6 +185,8 @@ void RemoteToLocalSyncer::ResolveRemoteChange(
 
   if (remote_details.missing()) {
     if (!synced_details.missing()) {
+      util::Log(logging::LOG_VERBOSE, FROM_HERE,
+                "[Remote -> Local]: Remote file deletion.");
       HandleDeletion(callback);
       return;
     }
@@ -206,6 +225,8 @@ void RemoteToLocalSyncer::ResolveRemoteChange(
 
   if (synced_details.title() != remote_details.title()) {
     // Handle rename as deletion + addition.
+    util::Log(logging::LOG_VERBOSE, FROM_HERE,
+              "[Remote -> Local]: Detected file rename.");
     Prepare(base::Bind(&RemoteToLocalSyncer::DidPrepareForDeletion,
                        weak_ptr_factory_.GetWeakPtr(), callback));
     return;
@@ -224,6 +245,8 @@ void RemoteToLocalSyncer::ResolveRemoteChange(
 
   if (!HasFolderAsParent(remote_details, parent_tracker.file_id())) {
     // Handle reorganize as deletion + addition.
+    util::Log(logging::LOG_VERBOSE, FROM_HERE,
+              "[Remote -> Local]: Detected file reorganize.");
     Prepare(base::Bind(&RemoteToLocalSyncer::DidPrepareForDeletion,
                        weak_ptr_factory_.GetWeakPtr(), callback));
     return;
@@ -231,15 +254,21 @@ void RemoteToLocalSyncer::ResolveRemoteChange(
 
   if (synced_details.file_kind() == FILE_KIND_FILE) {
     if (synced_details.md5() != remote_details.md5()) {
+      util::Log(logging::LOG_VERBOSE, FROM_HERE,
+                "[Remote -> Local]: Detected file content update.");
       HandleContentUpdate(callback);
       return;
     }
   } else {
     DCHECK_EQ(FILE_KIND_FOLDER, synced_details.file_kind());
+    util::Log(logging::LOG_VERBOSE, FROM_HERE,
+              "[Remote -> Local]: Detected folder update.");
     HandleFolderUpdate(callback);
     return;
   }
 
+  util::Log(logging::LOG_VERBOSE, FROM_HERE,
+            "[Remote -> Local]: Trivial file change.");
   callback.Run(SYNC_STATUS_OK);
 }
 
@@ -518,6 +547,10 @@ void RemoteToLocalSyncer::DidListFolderContent(
 
 void RemoteToLocalSyncer::SyncCompleted(const SyncStatusCallback& callback,
                                         SyncStatusCode status) {
+  util::Log(logging::LOG_VERBOSE, FROM_HERE,
+            "[Remote -> Local]: Finished: action=%s, tracker=%" PRId64,
+            SyncActionToString(sync_action_), dirty_tracker_->tracker_id());
+
   if (sync_root_deletion_) {
     callback.Run(SYNC_STATUS_OK);
     return;
diff --git a/chrome/browser/sync_file_system/sync_action.cc b/chrome/browser/sync_file_system/sync_action.cc
new file mode 100644
index 0000000..0b255f01
--- /dev/null
+++ b/chrome/browser/sync_file_system/sync_action.cc
@@ -0,0 +1,27 @@
+// Copyright 2013 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+#include "chrome/browser/sync_file_system/sync_action.h"
+
+#include "base/logging.h"
+
+namespace sync_file_system {
+
+const char* SyncActionToString(SyncAction action) {
+  switch (action) {
+    case SYNC_ACTION_NONE:
+      return "None";
+    case SYNC_ACTION_ADDED:
+      return "Added";
+    case SYNC_ACTION_UPDATED:
+      return "Updated";
+    case SYNC_ACTION_DELETED:
+      return "Deleted";
+  }
+
+  NOTREACHED();
+  return "Unknown SyncAction";
+}
+
+}  // namespace sync_file_system
diff --git a/chrome/browser/sync_file_system/sync_action.h b/chrome/browser/sync_file_system/sync_action.h
index 1941288..639de56 100644
--- a/chrome/browser/sync_file_system/sync_action.h
+++ b/chrome/browser/sync_file_system/sync_action.h
@@ -21,6 +21,8 @@ enum SyncAction {
   SYNC_ACTION_DELETED,
 };
 
+const char* SyncActionToString(SyncAction action);
+
 }  // namespace sync_file_system
 
 #endif  // CHROME_BROWSER_SYNC_FILE_SYSTEM_SYNC_ACTION_H_