Added ClientEvent proto and structure for storing events in the factory.

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 <string>
 
 #include "base/location.h"
 #include "base/memory/ptr_util.h"
@@ skipping 27 matching lines @@
 
 // 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);
 }
 
+const int kMaxClientEvents = 30;

[Peter Beverloo, 2016/11/28 15:05:15]

++docs. Explain what it is and how this number was decided on.

[harkness, 2016/12/01 10:34:34]

Done.

+
 }  // namespace
 
 ConnectionFactoryImpl::ConnectionFactoryImpl(
     const std::vector<GURL>& mcs_endpoints,
     const net::BackoffEntry::Policy& backoff_policy,
     net::HttpNetworkSession* gcm_network_session,
     net::HttpNetworkSession* http_network_session,
     net::NetLog* net_log,
     GCMStatsRecorder* recorder)
     : mcs_endpoints_(mcs_endpoints),
@@ skipping 140 matching lines @@
   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.
   }
 
+  // Record that the connection has ended.
+  if (logging_in_) {
+    // If this was a login failure, the connection established time would have
+    // been set and it would have marked a successful connection, so explicitly
+    // clear that.
+    current_event_.set_type(mcs_proto::ClientEvent::FAILED_CONNECTION);
+    current_event_.clear_time_connection_established_ms();
+    // TODO(harkness): What error code do we want to set?
+  }
+  current_event_.set_time_connection_ended_ms(NowTicks().ToInternalValue());

[Peter Beverloo, 2016/11/28 15:05:14]

Here and elsewhere:

I'm not comfortable using ToInternalValue() for values that we send to and store
on the server. There is no guarantee that this value is portable between
platforms, nor that it will remain so in the future if it is.

Can we use base::Time::Now().ToJavaTime() instead, which returns the number of
elapsed milliseconds since the Unix epoch?

[harkness, 2016/12/01 10:34:34]

Sure, that seems reasonable.

+
   CloseSocket();
   DCHECK(!IsEndpointReachable());
 
   // TODO(zea): if the network is offline, don't attempt to connect.
   // See crbug.com/396687
 
   // Network changes get special treatment as they can trigger a one-off canary
   // request that bypasses backoff (but does nothing if a connection is in
   // progress). Other connection reset events can be ignored as a connection
   // is already awaiting backoff expiration.
@@ skipping 35 matching lines @@
 }
 
 base::TimeTicks ConnectionFactoryImpl::NextRetryAttempt() const {
   if (!backoff_entry_)
     return base::TimeTicks();
   return backoff_entry_->GetReleaseTime();
 }
 
 void ConnectionFactoryImpl::OnNetworkChanged(
     net::NetworkChangeNotifier::ConnectionType type) {
+  // Record the current network type.
+  network_type_ = type;

[Peter Beverloo, 2016/11/28 15:05:15]

Since we only fire OnNetworkChanged() when it actually changes, presumably this
will cause a huge bias to CONNECTION_NONE in our stats, especially on desktop.

Is there any way we can init |network_type_| with a real value?

[harkness, 2016/12/01 10:34:34]

You're right, that is going to be a problem. I haven't found a way to query for
the current state. I'll ask zea.

+
   if (type == net::NetworkChangeNotifier::CONNECTION_NONE) {
     DVLOG(1) << "Network lost, resettion connection.";
     waiting_for_network_online_ = true;
 
     // Will do nothing due to |waiting_for_network_online_ == true|.
     // TODO(zea): make the above statement actually true. See crbug.com/396687
     SignalConnectionReset(NETWORK_CHANGE);
     return;
   }
 
@@ skipping 16 matching lines @@
 
   net::IPEndPoint ip_endpoint;
   int result = socket_handle_.socket()->GetPeerAddress(&ip_endpoint);
   if (result != net::OK)
     return net::IPEndPoint();
 
   return ip_endpoint;
 }
 
 void ConnectionFactoryImpl::ConnectImpl() {
+  if (total_client_events_ >= 0) {

[Peter Beverloo, 2016/11/28 15:05:15]

Instead of having |total_client_events_|, I think it'd be a lot clearer to just
use |client_events_.size()| in the code, and maintaining a
|discarded_client_events_| counter when we override a previous entry (which
matches the semantics of DISCARDED_EVENTS).

That also allows you to get rid of the magic value of "0".

[harkness, 2016/12/01 10:34:34]

Refactored this into the ClientEventTracker, which just uses a STL structure to
hold the events. This reduces the need for tracking at the expense of copies,
but the connections are rare, so that's worth it for the code complexity
reduction.

+    // If starting a new connection, the previous connection is completed, so
+    // move
+    // the current client event onto the list of past events.
+    mcs_proto::ClientEvent* client_event = nullptr;
+    if (total_client_events_ < kMaxClientEvents) {
+      client_event = client_events_.Add();
+    } else {
+      // If the maximum number of stored events has been exceeded, start
+      // overwriting older entries.
+      client_event =
+          client_events_.Mutable(total_client_events_ % kMaxClientEvents);
+    }
+    client_event->CopyFrom(current_event_);
+    current_event_.Clear();

[Peter Beverloo, 2016/11/28 15:05:15]

it seems to me like this code would become *a lot* clearer if we'd store the
mcs_proto::ClientEvent in a std::deque<> and use an anonymous function to do the
insertion for us:

https://cs.chromium.org/chromium/src/components/gcm_driver/gcm_stats_recorder...

It'd create some data copies in the worst case, but this is (a) data of tiny
size, and (b) a very infrequent event.

[harkness, 2016/12/01 10:34:34]

Done.

+  }
+  total_client_events_++;
+
+  current_event_.set_time_connection_started_ms(NowTicks().ToInternalValue());
+  current_event_.set_network_type(network_type_);
+
+  StartConnection();
+}
+
+void ConnectionFactoryImpl::StartConnection() {
   DCHECK(!IsEndpointReachable());
   // TODO(zea): Make this a dcheck again. crbug.com/462319
   CHECK(!socket_handle_.socket());
 
   // TODO(zea): if the network is offline, don't attempt to connect.
   // See crbug.com/396687
 
   connecting_ = true;
   GURL current_endpoint = GetCurrentEndpoint();
   recorder_->RecordConnectionInitiated(current_endpoint.host());
   RebuildNetworkSessionAuthCache();
   int status = gcm_network_session_->proxy_service()->ResolveProxy(
       current_endpoint,
       std::string(),
       &proxy_info_,
       base::Bind(&ConnectionFactoryImpl::OnProxyResolveDone,
                  weak_ptr_factory_.GetWeakPtr()),
       &pac_request_,
       NULL,
       net_log_);
   if (status != net::ERR_IO_PENDING)
     OnProxyResolveDone(status);
 }
 
 void ConnectionFactoryImpl::InitHandler() {
   // May be null in tests.
   mcs_proto::LoginRequest login_request;
   if (!request_builder_.is_null()) {
+    // TODO(harkness): Pass the previous ClientEvents into the request builder.

[Peter Beverloo, 2016/11/28 15:05:15]

This also needs to build a ClientEvent for DISCARDED_EVENTS.

[harkness, 2016/12/01 10:34:34]

TODO added.

     request_builder_.Run(&login_request);
     DCHECK(login_request.IsInitialized());
   }
 
   connection_handler_->Init(login_request, socket_handle_.socket());
 }
 
 std::unique_ptr<net::BackoffEntry> ConnectionFactoryImpl::CreateBackoffEntry(
     const net::BackoffEntry::Policy* const policy) {
   return std::unique_ptr<net::BackoffEntry>(new net::BackoffEntry(policy));
@@ skipping 27 matching lines @@
     DCHECK_NE(result, net::OK);
     if (result == net::ERR_IO_PENDING)
       return;  // Proxy reconsideration pending. Return.
     LOG(ERROR) << "Failed to connect to MCS endpoint with error " << result;
     UMA_HISTOGRAM_BOOLEAN("GCM.ConnectionSuccessRate", false);
     recorder_->RecordConnectionFailure(result);
     CloseSocket();
     backoff_entry_->InformOfRequest(false);
     UMA_HISTOGRAM_SPARSE_SLOWLY("GCM.ConnectionFailureErrorCode", result);
 
+    // Record the failed connection so information about it can be sent in the
+    // next login request.
+    current_event_.set_type(mcs_proto::ClientEvent::FAILED_CONNECTION);
+    current_event_.set_time_connection_ended_ms(NowTicks().ToInternalValue());
+    current_event_.set_error_code(result);
+
     // If there are other endpoints available, use the next endpoint on the
     // subsequent retry.
     next_endpoint_++;
     if (next_endpoint_ >= mcs_endpoints_.size())
       next_endpoint_ = 0;
     connecting_ = false;
     Connect();
     return;
   }
 
@@ skipping 28 matching lines @@
 
   // Handshake complete, reset backoff. If the login failed with an error,
   // the client should invoke SignalConnectionReset(LOGIN_FAILURE), which will
   // restore the previous backoff.
   DVLOG(1) << "Handshake complete.";
   last_login_time_ = NowTicks();
   previous_backoff_.swap(backoff_entry_);
   backoff_entry_->Reset();
   logging_in_ = false;
 
+  // Record the successful connection so information about it can be sent in the
+  // next login request. If there is a login failure, this will need to be
+  // updated to a failed connection.
+  current_event_.set_type(mcs_proto::ClientEvent::SUCCESSFUL_CONNECTION);
+  current_event_.set_time_connection_established_ms(
+      NowTicks().ToInternalValue());
+
+  // A completed connection means that the old client event data has now been
+  // sent to GCM. Delete old data and reinitialize the count.
+  client_events_.Clear();
+  total_client_events_ = 0;
+
   if (listener_)
     listener_->OnConnected(GetCurrentEndpoint(), GetPeerIP());
 }
 
 // This has largely been copied from
 // HttpStreamFactoryImpl::Job::DoResolveProxyComplete. This should be
 // refactored into some common place.
 void ConnectionFactoryImpl::OnProxyResolveDone(int status) {
   pac_request_ = NULL;
   DVLOG(1) << "Proxy resolution status: " << status;
@@ skipping 141 matching lines @@
 
 void ConnectionFactoryImpl::RebuildNetworkSessionAuthCache() {
   if (!http_network_session_ || !http_network_session_->http_auth_cache())
     return;
 
   gcm_network_session_->http_auth_cache()->UpdateAllFrom(
       *http_network_session_->http_auth_cache());
 }
 
 }  // namespace gcm