[GCM] Track connection failures properly

google_apis/gcm/engine/connection_factory_impl.cc

 // Copyright (c) 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 "google_apis/gcm/engine/connection_factory_impl.h"
 
 #include "base/message_loop/message_loop.h"
 #include "base/metrics/histogram.h"
 #include "base/metrics/sparse_histogram.h"
 #include "google_apis/gcm/engine/connection_handler_impl.h"
@@ skipping 11 matching lines @@
 namespace {
 
 // The amount of time a Socket read should wait before timing out.
 const int kReadTimeoutMs = 30000;  // 30 seconds.
 
 // If a connection is reset after succeeding within this window of time,
 // the previous backoff entry is restored (and the connection success is treated
 // 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(
     const GURL& mcs_endpoint,
     const net::BackoffEntry::Policy& backoff_policy,
     scoped_refptr<net::HttpNetworkSession> network_session,
     net::NetLog* net_log)
   : mcs_endpoint_(mcs_endpoint),
     backoff_policy_(backoff_policy),
     network_session_(network_session),
     net_log_(net_log),
     connecting_(false),
+    logging_in_(false),
     weak_ptr_factory_(this) {
 }
 
 ConnectionFactoryImpl::~ConnectionFactoryImpl() {
 }
 
 void ConnectionFactoryImpl::Initialize(
     const BuildLoginRequestCallback& request_builder,
     const ConnectionHandler::ProtoReceivedCallback& read_callback,
     const ConnectionHandler::ProtoSentCallback& write_callback) {
@@ skipping 37 matching lines @@
   DVLOG(1) << "Attempting connection to MCS endpoint.";
   ConnectImpl();
 }
 
 bool ConnectionFactoryImpl::IsEndpointReachable() const {
   return connection_handler_ &&
       connection_handler_->CanSendMessage() &&
       !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();
 }
 
 base::TimeTicks ConnectionFactoryImpl::NextRetryAttempt() const {
   if (!backoff_entry_)
     return base::TimeTicks();
   return backoff_entry_->GetReleaseTime();
 }
 
 void ConnectionFactoryImpl::OnConnectionTypeChanged(
@@ skipping 10 matching lines @@
 }
 
 void ConnectionFactoryImpl::OnIPAddressChanged() {
   DVLOG(1) << "IP Address changed, resetting backoff.";
   backoff_entry_->Reset();
   // Connect(..) should be retrying with backoff already if a connection is
   // necessary, so no need to call again.
 }
 
 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;
   proxy_info.UseDirect();
   net::SSLConfig ssl_config;
   network_session_->ssl_config_service()->GetSSLConfig(&ssl_config);
 
   int status = net::InitSocketHandleForTlsConnect(
       net::HostPortPair::FromURL(mcs_endpoint_),
       network_session_.get(),
@@ skipping 23 matching lines @@
 scoped_ptr<net::BackoffEntry> ConnectionFactoryImpl::CreateBackoffEntry(
     const net::BackoffEntry::Policy* const policy) {
   return scoped_ptr<net::BackoffEntry>(new net::BackoffEntry(policy));
 }
 
 base::TimeTicks ConnectionFactoryImpl::NowTicks() {
   return base::TimeTicks::Now();
 }
 
 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);
     UMA_HISTOGRAM_SPARSE_SLOWLY("GCM.ConnectionFailureErrorCode", result);
     Connect();
     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