[invalidations] Added internal debugging information for push and GCM

This patch builds up from SVN r257555.

This patch adds debugging information from the GCMNetworkChannel
and for the PushClientChannel. It changes a bit how the
RequestDetailedStatus work. Now the prefered way to do debugging is,
for each object, assemblying a DictionaryValue with all the debugging
information, running the callback with that dictionary and passing
the callback to other objects that might want to log something.
The pro of doing it this way is that is very easy to propagate this
debugging mechanism to any interesting object. All the dictionaries
are merged in the JS, making it easy to keep adding more information
if needed.

Among others, about:invalidations detailed status can now display:
-Underlying Network Channel in use
-Sent messages / Received messages count
-Chrome flags used to set the jingle servers
-GCM: Last response status, if it was an empty echo packet,
	timestamp of the last received message, registration result,
	hash of the registration_id.

BUG=263863

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

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

9 files changed, 145 insertions, 6 deletions

diff --git a/sync/notifier/gcm_network_channel.cc b/sync/notifier/gcm_network_channel.cc
index cab9510..e194d9a 100644
--- a/sync/notifier/gcm_network_channel.cc
+++ b/sync/notifier/gcm_network_channel.cc
@@ -3,6 +3,8 @@
 // found in the LICENSE file.
 
 #include "base/base64.h"
+#include "base/i18n/time_formatting.h"
+#include "base/sha1.h"
 #include "base/strings/string_util.h"
 #if !defined(ANDROID)
 // channel_common.proto defines ANDROID constant that conflicts with Android
@@ -55,12 +57,59 @@ const net::BackoffEntry::Policy kRegisterBackoffPolicy = {
 
 }  // namespace
 
+GCMNetworkChannelDiagnostic::GCMNetworkChannelDiagnostic(
+    GCMNetworkChannel* parent)
+    : parent_(parent),
+      last_message_empty_echo_token_(false),
+      last_post_response_code_(0),
+      registration_result_(gcm::GCMClient::UNKNOWN_ERROR),
+      sent_messages_count_(0) {}
+
+scoped_ptr<base::DictionaryValue>
+GCMNetworkChannelDiagnostic::CollectDebugData() const {
+  scoped_ptr<base::DictionaryValue> status(new base::DictionaryValue);
+  status->SetString("GCMNetworkChannel.Channel", "GCM");
+  status->SetString("GCMNetworkChannel.HashedRegistrationID",
+                    base::SHA1HashString(registration_id_));
+  status->SetString("GCMNetworkChannel.RegistrationResult",
+                    GCMClientResultToString(registration_result_));
+  status->SetBoolean("GCMNetworkChannel.HadLastMessageEmptyEchoToken",
+                     last_message_empty_echo_token_);
+  status->SetString(
+      "GCMNetworkChannel.LastMessageReceivedTime",
+      base::TimeFormatShortDateAndTime(last_message_received_time_));
+  status->SetInteger("GCMNetworkChannel.LastPostResponseCode",
+                     last_post_response_code_);
+  status->SetInteger("GCMNetworkChannel.SentMessages", sent_messages_count_);
+  status->SetInteger("GCMNetworkChannel.ReceivedMessages",
+                     parent_->GetReceivedMessagesCount());
+  return status.Pass();
+}
+
+std::string GCMNetworkChannelDiagnostic::GCMClientResultToString(
+    const gcm::GCMClient::Result result) const {
+#define ENUM_CASE(x) case x: return #x; break;
+  switch (result) {
+    ENUM_CASE(gcm::GCMClient::SUCCESS);
+    ENUM_CASE(gcm::GCMClient::NETWORK_ERROR);
+    ENUM_CASE(gcm::GCMClient::SERVER_ERROR);
+    ENUM_CASE(gcm::GCMClient::TTL_EXCEEDED);
+    ENUM_CASE(gcm::GCMClient::UNKNOWN_ERROR);
+    ENUM_CASE(gcm::GCMClient::NOT_SIGNED_IN);
+    ENUM_CASE(gcm::GCMClient::INVALID_PARAMETER);
+    ENUM_CASE(gcm::GCMClient::ASYNC_OPERATION_PENDING);
+  }
+  NOTREACHED();
+  return "";
+}
+
 GCMNetworkChannel::GCMNetworkChannel(
     scoped_refptr<net::URLRequestContextGetter> request_context_getter,
     scoped_ptr<GCMNetworkChannelDelegate> delegate)
     : request_context_getter_(request_context_getter),
       delegate_(delegate.Pass()),
       register_backoff_entry_(new net::BackoffEntry(&kRegisterBackoffPolicy)),
+      diagnostic_info_(this),
       weak_factory_(this) {
   delegate_->Initialize();
   Register();
@@ -75,6 +124,11 @@ void GCMNetworkChannel::UpdateCredentials(
   // Do nothing. We get access token by requesting it for every message.
 }
 
+void GCMNetworkChannel::RequestDetailedStatus(
+    base::Callback<void(const base::DictionaryValue&)> callback) {
+  callback.Run(*diagnostic_info_.CollectDebugData());
+}
+
 void GCMNetworkChannel::ResetRegisterBackoffEntryForTest(
     const net::BackoffEntry::Policy* policy) {
   register_backoff_entry_.reset(new net::BackoffEntry(policy));
@@ -116,12 +170,15 @@ void GCMNetworkChannel::OnRegisterComplete(
         break;
     }
   }
+  diagnostic_info_.registration_id_ = registration_id_;
+  diagnostic_info_.registration_result_ = result;
 }
 
 void GCMNetworkChannel::SendMessage(const std::string& message) {
   DCHECK(CalledOnValidThread());
   DCHECK(!message.empty());
   DVLOG(2) << "SendMessage";
+  diagnostic_info_.sent_messages_count_++;
   cached_message_ = message;
 
   if (!registration_id_.empty()) {
@@ -184,6 +241,7 @@ void GCMNetworkChannel::OnIncomingMessage(const std::string& message,
   DCHECK(!message.empty());
   if (!echo_token.empty())
     echo_token_ = echo_token;
+  diagnostic_info_.last_message_empty_echo_token_ = echo_token.empty();
   std::string data;
   if (!Base64DecodeURLSafe(message, &data))
     return;
@@ -192,6 +250,7 @@ void GCMNetworkChannel::OnIncomingMessage(const std::string& message,
     return;
   if (!android_message.has_message())
     return;
+  diagnostic_info_.last_message_received_time_ = base::Time::Now();
   DVLOG(2) << "Deliver incoming message";
   DeliverIncomingMessage(android_message.message());
 #else
@@ -207,6 +266,8 @@ void GCMNetworkChannel::OnURLFetchComplete(const net::URLFetcher* source) {
   scoped_ptr<net::URLFetcher> fetcher = fetcher_.Pass();
 
   net::URLRequestStatus status = fetcher->GetStatus();
+  diagnostic_info_.last_post_response_code_ =
+      status.is_success() ? source->GetResponseCode() : status.error();
   if (!status.is_success()) {
     DVLOG(1) << "URLFetcher failure";
     return;
diff --git a/sync/notifier/gcm_network_channel.h b/sync/notifier/gcm_network_channel.h
index 2ab8419..9fc6364 100644
--- a/sync/notifier/gcm_network_channel.h
+++ b/sync/notifier/gcm_network_channel.h
@@ -21,6 +21,27 @@
 class GoogleServiceAuthError;
 
 namespace syncer {
+class GCMNetworkChannel;
+
+// POD with copy of some statuses for debugging purposes.
+struct GCMNetworkChannelDiagnostic {
+  explicit GCMNetworkChannelDiagnostic(GCMNetworkChannel* parent);
+
+  // Collect all the internal variables in a single readable dictionary.
+  scoped_ptr<base::DictionaryValue> CollectDebugData() const;
+
+  // TODO(pavely): Move this toString to a more appropiate place in GCMClient.
+  std::string GCMClientResultToString(
+      const gcm::GCMClient::Result result) const;
+
+  GCMNetworkChannel* parent_;
+  bool last_message_empty_echo_token_;
+  base::Time last_message_received_time_;
+  int last_post_response_code_;
+  std::string registration_id_;
+  gcm::GCMClient::Result registration_result_;
+  int sent_messages_count_;
+};
 
 // GCMNetworkChannel is an implementation of SyncNetworkChannel that routes
 // messages through GCMProfileService.
@@ -43,6 +64,8 @@ class SYNC_EXPORT_PRIVATE GCMNetworkChannel
   // SyncNetworkChannel implementation.
   virtual void UpdateCredentials(const std::string& email,
                                  const std::string& token) OVERRIDE;
+  virtual void RequestDetailedStatus(
+      base::Callback<void(const base::DictionaryValue&)> callback) OVERRIDE;
 
   // URLFetcherDelegate implementation.
   virtual void OnURLFetchComplete(const net::URLFetcher* source) OVERRIDE;
@@ -93,6 +116,8 @@ class SYNC_EXPORT_PRIVATE GCMNetworkChannel
   // GCM and shuld include it in headers with outgoing message over http.
   std::string echo_token_;
 
+  GCMNetworkChannelDiagnostic diagnostic_info_;
+
   base::WeakPtrFactory<GCMNetworkChannel> weak_factory_;
 
   DISALLOW_COPY_AND_ASSIGN(GCMNetworkChannel);
diff --git a/sync/notifier/push_client_channel.cc b/sync/notifier/push_client_channel.cc
index 66878b1..3426d2c 100644
--- a/sync/notifier/push_client_channel.cc
+++ b/sync/notifier/push_client_channel.cc
@@ -19,7 +19,9 @@ const char kChannelName[] = "tango_raw";
 
 PushClientChannel::PushClientChannel(
     scoped_ptr<notifier::PushClient> push_client)
-    : push_client_(push_client.Pass()), scheduling_hash_(0) {
+    : push_client_(push_client.Pass()),
+      scheduling_hash_(0),
+      sent_messages_count_(0) {
   push_client_->AddObserver(this);
   notifier::Subscription subscription;
   subscription.channel = kChannelName;
@@ -38,6 +40,11 @@ void PushClientChannel::UpdateCredentials(
   push_client_->UpdateCredentials(email, token);
 }
 
+void PushClientChannel::RequestDetailedStatus(
+    base::Callback<void(const base::DictionaryValue&)> callback) {
+  callback.Run(*CollectDebugData());
+}
+
 void PushClientChannel::SendMessage(const std::string& message) {
   std::string encoded_message;
   EncodeMessage(&encoded_message, message, service_context_, scheduling_hash_);
@@ -49,6 +56,7 @@ void PushClientChannel::SendMessage(const std::string& message) {
   notification.recipients.push_back(recipient);
   notification.data = encoded_message;
   push_client_->SendNotification(notification);
+  sent_messages_count_++;
 }
 
 void PushClientChannel::OnNotificationsEnabled() {
@@ -132,4 +140,13 @@ bool PushClientChannel::DecodeMessage(const std::string& data,
   return true;
 }
 
+scoped_ptr<base::DictionaryValue> PushClientChannel::CollectDebugData() const {
+  scoped_ptr<base::DictionaryValue> status(new base::DictionaryValue);
+  status->SetString("PushClientChannel.NetworkChannel", "Push Client");
+  status->SetInteger("PushClientChannel.SentMessages", sent_messages_count_);
+  status->SetInteger("PushClientChannel.ReceivedMessages",
+                     SyncNetworkChannel::GetReceivedMessagesCount());
+  return status.Pass();
+}
+
 }  // namespace syncer
diff --git a/sync/notifier/push_client_channel.h b/sync/notifier/push_client_channel.h
index 5231bbb..7e33e5e 100644
--- a/sync/notifier/push_client_channel.h
+++ b/sync/notifier/push_client_channel.h
@@ -34,6 +34,8 @@ class SYNC_EXPORT_PRIVATE PushClientChannel
 
   // invalidation::NetworkChannel implementation.
   virtual void SendMessage(const std::string& message) OVERRIDE;
+  virtual void RequestDetailedStatus(
+      base::Callback<void(const base::DictionaryValue&)> callback) OVERRIDE;
 
   // SyncNetworkChannel implementation.
   // If not connected, connects with the given credentials.  If
@@ -71,11 +73,15 @@ class SYNC_EXPORT_PRIVATE PushClientChannel
                             std::string* message,
                             std::string* service_context,
                             int64* scheduling_hash);
+  scoped_ptr<base::DictionaryValue> CollectDebugData() const;
 
   scoped_ptr<notifier::PushClient> push_client_;
   std::string service_context_;
   int64 scheduling_hash_;
 
+  // This count is saved for displaying statatistics.
+  int sent_messages_count_;
+
   DISALLOW_COPY_AND_ASSIGN(PushClientChannel);
 };
 
diff --git a/sync/notifier/sync_invalidation_listener.cc b/sync/notifier/sync_invalidation_listener.cc
index 61c7a5d..c5dc8e3 100644
--- a/sync/notifier/sync_invalidation_listener.cc
+++ b/sync/notifier/sync_invalidation_listener.cc
@@ -363,19 +363,27 @@ void SyncInvalidationListener::DoRegistrationUpdate() {
 void SyncInvalidationListener::RequestDetailedStatus(
     base::Callback<void(const base::DictionaryValue&)> callback) {
   DCHECK(CalledOnValidThread());
+  sync_network_channel_->RequestDetailedStatus(callback);
   callback.Run(*CollectDebugData());
 }
 
-scoped_ptr<base::DictionaryValue> SyncInvalidationListener::CollectDebugData() {
+scoped_ptr<base::DictionaryValue>
+SyncInvalidationListener::CollectDebugData() const {
   scoped_ptr<base::DictionaryValue> return_value(new base::DictionaryValue());
+  return_value->SetString(
+      "SyncInvalidationListener.PushClientState",
+      std::string(InvalidatorStateToString(push_client_state_)));
+  return_value->SetString("SyncInvalidationListener.TiclState",
+                          std::string(InvalidatorStateToString(ticl_state_)));
   scoped_ptr<base::DictionaryValue> unacked_map(new base::DictionaryValue());
-  for (UnackedInvalidationsMap::iterator it =
+  for (UnackedInvalidationsMap::const_iterator it =
            unacked_invalidations_map_.begin();
        it != unacked_invalidations_map_.end();
        ++it) {
     unacked_map->Set((it->first).name(), (it->second).ToValue().release());
   }
-  return_value->Set("UnackedInvalidationsMap", unacked_map.release());
+  return_value->Set("SyncInvalidationListener.UnackedInvalidationsMap",
+                    unacked_map.release());
   return return_value.Pass();
 }
 
diff --git a/sync/notifier/sync_invalidation_listener.h b/sync/notifier/sync_invalidation_listener.h
index 3f2f158..fddc208 100644
--- a/sync/notifier/sync_invalidation_listener.h
+++ b/sync/notifier/sync_invalidation_listener.h
@@ -168,7 +168,7 @@ class SYNC_EXPORT_PRIVATE SyncInvalidationListener
   void EmitSavedInvalidations(const ObjectIdInvalidationMap& to_emit);
 
   // Generate a Dictionary with all the debugging information.
-  scoped_ptr<base::DictionaryValue> CollectDebugData();
+  scoped_ptr<base::DictionaryValue> CollectDebugData() const;
 
   WeakHandle<AckHandler> GetThisAsAckHandler();
 
diff --git a/sync/notifier/sync_system_resources.cc b/sync/notifier/sync_system_resources.cc
index 4d4e56b1..f688609 100644
--- a/sync/notifier/sync_system_resources.cc
+++ b/sync/notifier/sync_system_resources.cc
@@ -132,7 +132,8 @@ void SyncInvalidationScheduler::RunPostedTask(invalidation::Closure* task) {
 }
 
 SyncNetworkChannel::SyncNetworkChannel()
-    : invalidator_state_(DEFAULT_INVALIDATION_ERROR) {}
+    : invalidator_state_(DEFAULT_INVALIDATION_ERROR),
+      received_messages_count_(0) {}
 
 SyncNetworkChannel::~SyncNetworkChannel() {
   STLDeleteElements(&network_status_receivers_);
@@ -196,10 +197,14 @@ bool SyncNetworkChannel::DeliverIncomingMessage(const std::string& message) {
     DLOG(ERROR) << "No receiver for incoming notification";
     return false;
   }
+  received_messages_count_++;
   incoming_receiver_->Run(message);
   return true;
 }
 
+int SyncNetworkChannel::GetReceivedMessagesCount() const {
+  return received_messages_count_;
+}
 
 SyncStorage::SyncStorage(StateWriter* state_writer,
                          invalidation::Scheduler* scheduler)
diff --git a/sync/notifier/sync_system_resources.h b/sync/notifier/sync_system_resources.h
index 9f9dbff..a616ee46 100644
--- a/sync/notifier/sync_system_resources.h
+++ b/sync/notifier/sync_system_resources.h
@@ -18,6 +18,7 @@
 #include "base/memory/weak_ptr.h"
 #include "base/message_loop/message_loop.h"
 #include "base/threading/non_thread_safe.h"
+#include "base/values.h"
 #include "google/cacheinvalidation/include/system-resources.h"
 #include "jingle/notifier/base/notifier_options.h"
 #include "sync/base/sync_export.h"
@@ -115,6 +116,11 @@ class SYNC_EXPORT_PRIVATE SyncNetworkChannel
   virtual void UpdateCredentials(const std::string& email,
       const std::string& token) = 0;
 
+  // Subclass should implement RequestDetailedStatus to provide debugging
+  // information.
+  virtual void RequestDetailedStatus(
+      base::Callback<void(const base::DictionaryValue&)> callback) = 0;
+
   // Classes interested in network channel state changes should implement
   // SyncNetworkChannel::Observer and register here.
   void AddObserver(Observer* observer);
@@ -128,6 +134,9 @@ class SYNC_EXPORT_PRIVATE SyncNetworkChannel
       scoped_refptr<net::URLRequestContextGetter> request_context_getter,
       scoped_ptr<GCMNetworkChannelDelegate> delegate);
 
+  // Get the count of how many valid received messages were received.
+  int GetReceivedMessagesCount() const;
+
  protected:
   // Subclass should notify about connection state through NotifyStateChange.
   void NotifyStateChange(InvalidatorState invalidator_state);
@@ -146,6 +155,8 @@ class SYNC_EXPORT_PRIVATE SyncNetworkChannel
   // Last channel state for new network status receivers.
   InvalidatorState invalidator_state_;
 
+  int received_messages_count_;
+
   ObserverList<Observer> observers_;
 };
 
diff --git a/sync/notifier/sync_system_resources_unittest.cc b/sync/notifier/sync_system_resources_unittest.cc
index 901e0f9..f8dd459 100644
--- a/sync/notifier/sync_system_resources_unittest.cc
+++ b/sync/notifier/sync_system_resources_unittest.cc
@@ -190,6 +190,12 @@ class TestSyncNetworkChannel : public SyncNetworkChannel {
   virtual void UpdateCredentials(const std::string& email,
       const std::string& token) OVERRIDE {
   }
+
+  virtual void RequestDetailedStatus(
+      base::Callback<void(const base::DictionaryValue&)> callback) OVERRIDE {
+    base::DictionaryValue value;
+    callback.Run(value);
+  }
 };
 
 class SyncNetworkChannelTest