Track merged nudge sources

There's a lot of valuable information in coalesced nudges.  Currently, one
nudge source can overwrite another, which leaves us in the dark as to why the
client behaved a certain way.  In fact, today we can't even determine whether
or not any coalescing was done.  

By logging all the coalesced sources and their payloads, we can learn a lot
more about client behaviour.  I'm hoping to use this to improve our
notification effectiveness metrics.

BUG=138613

Review URL: https://chromiumcodereview.appspot.com/11416126

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

8 files changed, 92 insertions, 16 deletions

diff --git a/sync/internal_api/debug_info_event_listener.cc b/sync/internal_api/debug_info_event_listener.cc
index a356f84..1bd83e4 100644
--- a/sync/internal_api/debug_info_event_listener.cc
+++ b/sync/internal_api/debug_info_event_listener.cc
@@ -43,6 +43,26 @@ void DebugInfoEventListener::OnSyncCycleCompleted(
   sync_completed_event_info->mutable_caller_info()->set_notifications_enabled(
       snapshot.notifications_enabled());
 
+  // Log the sources and per-type payloads coalesced into this session.
+  const std::vector<sessions::SyncSourceInfo>& snap_sources =
+      snapshot.debug_info_sources_list();
+  for (std::vector<sessions::SyncSourceInfo>::const_iterator source_iter =
+       snap_sources.begin(); source_iter != snap_sources.end(); ++source_iter) {
+    sync_pb::SourceInfo* pb_source_info =
+        sync_completed_event_info->add_source_info();
+
+    pb_source_info->set_source(source_iter->updates_source);
+
+    for (ModelTypeInvalidationMap::const_iterator type_iter =
+         source_iter->types.begin();
+         type_iter != source_iter->types.end(); ++type_iter) {
+      sync_pb::TypeHint* pb_type_hint = pb_source_info->add_type_hint();
+      pb_type_hint->set_data_type_id(
+          GetSpecificsFieldNumberFromModelType(type_iter->first));
+      pb_type_hint->set_has_valid_hint(!type_iter->second.payload.empty());
+    }
+  }
+
   AddEventToQueue(event_info);
 }
 
diff --git a/sync/internal_api/js_sync_manager_observer_unittest.cc b/sync/internal_api/js_sync_manager_observer_unittest.cc
index ee93336..3668400 100644
--- a/sync/internal_api/js_sync_manager_observer_unittest.cc
+++ b/sync/internal_api/js_sync_manager_observer_unittest.cc
@@ -75,20 +75,22 @@ TEST_F(JsSyncManagerObserverTest, OnInitializationComplete) {
 }
 
 TEST_F(JsSyncManagerObserverTest, OnSyncCycleCompleted) {
-  sessions::SyncSessionSnapshot snapshot(sessions::ModelNeutralState(),
-                                         false,
-                                         ModelTypeSet(),
-                                         ProgressMarkerMap(),
-                                         false,
-                                         5,
-                                         2,
-                                         7,
-                                         sessions::SyncSourceInfo(),
-                                         false,
-                                         0,
-                                         base::Time::Now(),
-                                         std::vector<int>(MODEL_TYPE_COUNT, 0),
-                                         std::vector<int>(MODEL_TYPE_COUNT, 0));
+  sessions::SyncSessionSnapshot snapshot(
+      sessions::ModelNeutralState(),
+      false,
+      ModelTypeSet(),
+      ProgressMarkerMap(),
+      false,
+      5,
+      2,
+      7,
+      sessions::SyncSourceInfo(),
+      std::vector<sessions::SyncSourceInfo>(),
+      false,
+      0,
+      base::Time::Now(),
+      std::vector<int>(MODEL_TYPE_COUNT, 0),
+      std::vector<int>(MODEL_TYPE_COUNT, 0));
   DictionaryValue expected_details;
   expected_details.Set("snapshot", snapshot.ToValue());
 
diff --git a/sync/internal_api/public/sessions/sync_session_snapshot.cc b/sync/internal_api/public/sessions/sync_session_snapshot.cc
index 5e25da3..d74ffa7 100644
--- a/sync/internal_api/public/sessions/sync_session_snapshot.cc
+++ b/sync/internal_api/public/sessions/sync_session_snapshot.cc
@@ -34,6 +34,7 @@ SyncSessionSnapshot::SyncSessionSnapshot(
     int num_hierarchy_conflicts,
     int num_server_conflicts,
     const SyncSourceInfo& source,
+    const std::vector<SyncSourceInfo>& debug_info_sources_list,
     bool notifications_enabled,
     size_t num_entries,
     base::Time sync_start_time,
@@ -48,6 +49,7 @@ SyncSessionSnapshot::SyncSessionSnapshot(
       num_hierarchy_conflicts_(num_hierarchy_conflicts),
       num_server_conflicts_(num_server_conflicts),
       source_(source),
+      debug_info_sources_list_(debug_info_sources_list),
       notifications_enabled_(notifications_enabled),
       num_entries_(num_entries),
       sync_start_time_(sync_start_time),
@@ -92,9 +94,15 @@ DictionaryValue* SyncSessionSnapshot::ToValue() const {
                     num_server_conflicts_);
   value->SetInteger("numEntries", num_entries_);
   value->Set("source", source_.ToValue());
+  scoped_ptr<ListValue> sources_list(new ListValue());
+  for (std::vector<SyncSourceInfo>::const_iterator i =
+       debug_info_sources_list_.begin();
+       i != debug_info_sources_list_.end(); ++i) {
+    sources_list->Append(i->ToValue());
+  }
+  value->Set("sourcesList", sources_list.release());
   value->SetBoolean("notificationsEnabled", notifications_enabled_);
 
-
   scoped_ptr<DictionaryValue> counter_entries(new DictionaryValue());
   for (int i = FIRST_REAL_MODEL_TYPE; i < MODEL_TYPE_COUNT; i++) {
     scoped_ptr<DictionaryValue> type_entries(new DictionaryValue());
@@ -155,6 +163,11 @@ SyncSourceInfo SyncSessionSnapshot::source() const {
   return source_;
 }
 
+const std::vector<SyncSourceInfo>&
+SyncSessionSnapshot::debug_info_sources_list() const {
+  return debug_info_sources_list_;
+}
+
 bool SyncSessionSnapshot::notifications_enabled() const {
   return notifications_enabled_;
 }
diff --git a/sync/internal_api/public/sessions/sync_session_snapshot.h b/sync/internal_api/public/sessions/sync_session_snapshot.h
index c6b3c78..8252419 100644
--- a/sync/internal_api/public/sessions/sync_session_snapshot.h
+++ b/sync/internal_api/public/sessions/sync_session_snapshot.h
@@ -39,6 +39,7 @@ class SyncSessionSnapshot {
       int num_hierarchy_conflicts,
       int num_server_conflicts,
       const SyncSourceInfo& source,
+      const std::vector<SyncSourceInfo>& debug_info_sources_list,
       bool notifications_enabled,
       size_t num_entries,
       base::Time sync_start_time,
@@ -63,6 +64,7 @@ class SyncSessionSnapshot {
   int num_hierarchy_conflicts() const;
   int num_server_conflicts() const;
   SyncSourceInfo source() const;
+  const std::vector<SyncSourceInfo>& debug_info_sources_list() const;
   bool notifications_enabled() const;
   size_t num_entries() const;
   base::Time sync_start_time() const;
@@ -82,6 +84,7 @@ class SyncSessionSnapshot {
   int num_hierarchy_conflicts_;
   int num_server_conflicts_;
   SyncSourceInfo source_;
+  std::vector<SyncSourceInfo> debug_info_sources_list_;
   bool notifications_enabled_;
   size_t num_entries_;
   base::Time sync_start_time_;
diff --git a/sync/internal_api/public/sessions/sync_session_snapshot_unittest.cc b/sync/internal_api/public/sessions/sync_session_snapshot_unittest.cc
index df33a41..5a97a16 100644
--- a/sync/internal_api/public/sessions/sync_session_snapshot_unittest.cc
+++ b/sync/internal_api/public/sessions/sync_session_snapshot_unittest.cc
@@ -53,6 +53,11 @@ TEST_F(SyncSessionSnapshotTest, SyncSessionSnapshotToValue) {
   SyncSourceInfo source;
   scoped_ptr<DictionaryValue> expected_source_value(source.ToValue());
 
+  std::vector<SyncSourceInfo> debug_info_sources_list;
+  debug_info_sources_list.push_back(source);
+  scoped_ptr<ListValue> expected_sources_list_value(new ListValue());
+  expected_sources_list_value->Append(source.ToValue());
+
   SyncSessionSnapshot snapshot(model_neutral,
                                kIsShareUsable,
                                initial_sync_ended,
@@ -62,13 +67,14 @@ TEST_F(SyncSessionSnapshotTest, SyncSessionSnapshotToValue) {
                                kNumHierarchyConflicts,
                                kNumServerConflicts,
                                source,
+                               debug_info_sources_list,
                                false,
                                0,
                                base::Time::Now(),
                                std::vector<int>(MODEL_TYPE_COUNT,0),
                                std::vector<int>(MODEL_TYPE_COUNT, 0));
   scoped_ptr<DictionaryValue> value(snapshot.ToValue());
-  EXPECT_EQ(19u, value->size());
+  EXPECT_EQ(20u, value->size());
   ExpectDictIntegerValue(model_neutral.num_successful_commits,
                          *value, "numSuccessfulCommits");
   ExpectDictIntegerValue(model_neutral.num_successful_bookmark_commits,
@@ -98,6 +104,7 @@ TEST_F(SyncSessionSnapshotTest, SyncSessionSnapshotToValue) {
   ExpectDictIntegerValue(kNumServerConflicts, *value,
                          "numServerConflicts");
   ExpectDictDictionaryValue(*expected_source_value, *value, "source");
+  ExpectDictListValue(*expected_sources_list_value, *value, "sourcesList");
   ExpectDictBooleanValue(false, *value, "notificationsEnabled");
 }
 
diff --git a/sync/protocol/client_debug_info.proto b/sync/protocol/client_debug_info.proto
index 7e4e1a5..ab7de4f 100644
--- a/sync/protocol/client_debug_info.proto
+++ b/sync/protocol/client_debug_info.proto
@@ -13,6 +13,24 @@ package sync_pb;
 
 import "get_updates_caller_info.proto";
 
+// Per-type hint information.
+message TypeHint {
+  // The data type this hint applied to.
+  optional int32 data_type_id = 1;
+
+  // Whether or not a valid hint is provided.
+  optional bool has_valid_hint = 2;
+}
+
+// Information about the source that triggered a sync.
+message SourceInfo {
+  // An enum indicating the reason for the nudge.
+  optional GetUpdatesCallerInfo.GetUpdatesSource source = 1;
+
+  // The per-type hint information associated with the nudge.
+  repeated TypeHint type_hint = 2;
+}
+
 // The additional info here is from the StatusController. They get sent when
 // the event SYNC_CYCLE_COMPLETED  is sent.
 message SyncCycleCompletedEventInfo {
@@ -38,6 +56,12 @@ message SyncCycleCompletedEventInfo {
   optional int32 num_updates_downloaded = 8;
   optional int32 num_reflected_updates_downloaded = 9;
   optional GetUpdatesCallerInfo caller_info = 10;
+
+  // A list of all the sources that were merged into this session.
+  //
+  // Some scenarios, notably mode switches and canary jobs, can spuriously add
+  // back-to-back duplicate sources to this list.
+  repeated SourceInfo source_info = 11;
 }
 
 // Datatype specifics statistics gathered at association time.
diff --git a/sync/sessions/sync_session.cc b/sync/sessions/sync_session.cc
index b57a8ea..0732329 100644
--- a/sync/sessions/sync_session.cc
+++ b/sync/sessions/sync_session.cc
@@ -80,6 +80,7 @@ SyncSession::SyncSession(SyncSessionContext* context, Delegate* delegate,
       enabled_groups_(ComputeEnabledGroups(routing_info_, workers_)) {
   status_controller_.reset(new StatusController(routing_info_));
   std::sort(workers_.begin(), workers_.end());
+  debug_info_sources_list_.push_back(source_);
 }
 
 SyncSession::~SyncSession() {}
@@ -92,6 +93,7 @@ void SyncSession::Coalesce(const SyncSession& session) {
 
   // When we coalesce sessions, the sync update source gets overwritten with the
   // most recent, while the type/state map gets merged.
+  debug_info_sources_list_.push_back(session.source_);
   CoalesceStates(&source_.types, session.source_.types);
   source_.updates_source = session.source_.updates_source;
 
@@ -177,6 +179,7 @@ SyncSessionSnapshot SyncSession::TakeSnapshot() const {
       status_controller_->num_hierarchy_conflicts(),
       status_controller_->num_server_conflicts(),
       source_,
+      debug_info_sources_list_,
       context_->notifications_enabled(),
       dir->GetEntriesCount(),
       status_controller_->sync_start_time(),
diff --git a/sync/sessions/sync_session.h b/sync/sessions/sync_session.h
index 19cba8c..58065b7 100644
--- a/sync/sessions/sync_session.h
+++ b/sync/sessions/sync_session.h
@@ -165,6 +165,10 @@ class SyncSession {
   // The source for initiating this sync session.
   SyncSourceInfo source_;
 
+  // A list of sources for sessions that have been merged with this one.
+  // Currently used only for logging.
+  std::vector<SyncSourceInfo> debug_info_sources_list_;
+
   // Information about extensions activity since the last successful commit.
   ExtensionsActivityMonitor::Records extensions_activity_;