[GCM] Track connection failures properly

google_apis/gcm/engine/connection_factory_impl.cc

Index: google_apis/gcm/engine/connection_factory_impl.cc
diff --git a/google_apis/gcm/engine/connection_factory_impl.cc b/google_apis/gcm/engine/connection_factory_impl.cc
index fcab2c2de251689427705b6a9eaf8374f88e8161..3c2e412ce38922e0e39a9c1ad815f34e70f4969c 100644
--- a/google_apis/gcm/engine/connection_factory_impl.cc
+++ b/google_apis/gcm/engine/connection_factory_impl.cc
@@ -29,6 +29,15 @@ const int kReadTimeoutMs = 30000;  // 30 seconds.
 // as if it was transient).
 const int kConnectionResetWindowSecs = 10;  // 10 seconds.
 
+// Decides whether the last login was within kConnectionResetWindowSecs of now
+// or not.
+bool ShouldRestorePreviousBackoff(const base::TimeTicks& login_time,
+                                  const base::TimeTicks& now_ticks) {
+  return !login_time.is_null() &&
+      now_ticks - login_time <=
+          base::TimeDelta::FromSeconds(kConnectionResetWindowSecs);
+}
+
 }  // namespace
 
 ConnectionFactoryImpl::ConnectionFactoryImpl(
@@ -41,6 +50,7 @@ ConnectionFactoryImpl::ConnectionFactoryImpl(
     network_session_(network_session),
     net_log_(net_log),
     connecting_(false),
+    logging_in_(false),
     weak_ptr_factory_(this) {
 }
 
@@ -98,21 +108,52 @@ bool ConnectionFactoryImpl::IsEndpointReachable() const {
       !connecting_;
 }
 
-void ConnectionFactoryImpl::SignalConnectionReset() {
+void ConnectionFactoryImpl::SignalConnectionReset(
+    ConnectionResetReason reason) {
+  // A failure can trigger multiple resets, so no need to do anything if a
+  // connection is already in progress.
   if (connecting_)
-    return;  // Already attempting to reconnect.
+    return;
+
+  UMA_HISTOGRAM_ENUMERATION("GCM.ConnectionResetReason",

[fgorski, 2014/02/12 19:24:01]

Perhaps we could wrap that in LogConnectionResetReason so that we can laster add
diagnostic observers for GCM-internals in the Logging methods. It applies to
other UMA Methods, like the whole if below (could be LogConnectionUptime or
something like that)

[Nicolas Zea, 2014/02/12 21:50:16]

I think that these methods are already the ones that would hook up to diagnostic
observers. None of the histograms are repeated (unlike in the
registration/checkin requests); they're all for different kinds of events
(external connection reset, internal reset, connection complete, etc).

[fgorski, 2014/02/12 21:56:27]

OK, I guess we can figure it out when we are closer to actually showing the data
on the internals page.

+                            reason,
+                            CONNECTION_RESET_COUNT);
+  if (!last_login_time_.is_null()) {
+    UMA_HISTOGRAM_CUSTOM_TIMES("GCM.ConnectionUpTime",
+                               NowTicks() - last_login_time_,
+                               base::TimeDelta::FromSeconds(1),
+                               base::TimeDelta::FromHours(24),
+                               50);
+    // |last_login_time_| will be reset below, before attempting the new
+    // connection.
+  }
 
   if (connection_handler_)
     connection_handler_->Reset();
 
-  if (!backoff_reset_time_.is_null() &&
-      NowTicks() - backoff_reset_time_ <=
-          base::TimeDelta::FromSeconds(kConnectionResetWindowSecs)) {
+  if (socket_handle_.socket() && socket_handle_.socket()->IsConnected())
+    socket_handle_.socket()->Disconnect();
+  socket_handle_.Reset();
+
+  if (logging_in_) {
+    // Failures prior to login completion just reuse the existing backoff entry.
+    logging_in_ = false;
+    backoff_entry_->InformOfRequest(false);
+  } else if (reason == LOGIN_FAILURE ||
+             ShouldRestorePreviousBackoff(last_login_time_, NowTicks())) {
+    // Failures due to login, or within the reset window of a login, restore
+    // the backoff entry that was saved off at login completion time.
     backoff_entry_.swap(previous_backoff_);
     backoff_entry_->InformOfRequest(false);
+  } else {
+    // We shouldn't be in backoff in thise case.
+    DCHECK(backoff_entry_->CanDiscard());
   }
-  backoff_reset_time_ = base::TimeTicks();
-  previous_backoff_->Reset();
+
+  // At this point the last login time has been consumed or deemed irrelevant,
+  // reset it.
+  last_login_time_ = base::TimeTicks();
+
   Connect();
 }
 
@@ -143,10 +184,8 @@ void ConnectionFactoryImpl::OnIPAddressChanged() {
 }
 
 void ConnectionFactoryImpl::ConnectImpl() {
-  DCHECK(!connection_handler_->CanSendMessage());
-  if (socket_handle_.socket() && socket_handle_.socket()->IsConnected())
-    socket_handle_.socket()->Disconnect();
-  socket_handle_.Reset();
+  DCHECK(connecting_);
+  DCHECK(!socket_handle_.socket());
 
   // TODO(zea): resolve proxies.
   net::ProxyInfo proxy_info;
@@ -190,6 +229,8 @@ base::TimeTicks ConnectionFactoryImpl::NowTicks() {
 }
 
 void ConnectionFactoryImpl::OnConnectDone(int result) {
+  UMA_HISTOGRAM_BOOLEAN("GCM.ConnectionSuccessRate", (result == net::OK));
+
   if (result != net::OK) {
     LOG(ERROR) << "Failed to connect to MCS endpoint with error " << result;
     backoff_entry_->InformOfRequest(false);
@@ -198,31 +239,29 @@ void ConnectionFactoryImpl::OnConnectDone(int result) {
     return;
   }
 
-  DVLOG(1) << "MCS endpoint socket connection success, starting handshake.";
+  connecting_ = false;
+  logging_in_ = true;
+  DVLOG(1) << "MCS endpoint socket connection success, starting login.";
   InitHandler();
 }
 
 void ConnectionFactoryImpl::ConnectionHandlerCallback(int result) {
-  if (result == net::OK) {
-    // Handshake succeeded, reset the backoff.
-    connecting_ = false;
-    backoff_reset_time_ = NowTicks();
-    previous_backoff_.swap(backoff_entry_);
-    backoff_entry_->Reset();
+  DCHECK(!connecting_);
+  if (result != net::OK) {
+    // TODO(zea): Consider how to handle errors that may require some sort of
+    // user intervention (login page, etc.).
+    UMA_HISTOGRAM_SPARSE_SLOWLY("GCM.ConnectionDisconnectErrorCode", result);
+    SignalConnectionReset(SOCKET_FAILURE);
     return;
   }
 
-  if (!connecting_)
-    UMA_HISTOGRAM_SPARSE_SLOWLY("GCM.ConnectionDisconnectErrorCode", result);
-
-  if (connection_handler_)
-    connection_handler_->Reset();
-
-  // TODO(zea): Consider how to handle errors that may require some sort of
-  // user intervention (login page, etc.).
-  LOG(ERROR) << "Connection reset with error " << result;
-  backoff_entry_->InformOfRequest(false);
-  Connect();
+  // Handshake complete, reset backoff. If the login failed with an error,
+  // the client should invoke SignalConnectionReset(LOGIN_FAILURE), which will
+  // restore the previous backoff.
+  last_login_time_ = NowTicks();
+  previous_backoff_.swap(backoff_entry_);
+  backoff_entry_->Reset();
+  logging_in_ = false;
 }
 
 }  // namespace gcm