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 81 matching lines @@
   DCHECK(read_callback_.is_null());
   DCHECK(write_callback_.is_null());
 
   previous_backoff_ = CreateBackoffEntry(&backoff_policy_);
   backoff_entry_ = CreateBackoffEntry(&backoff_policy_);
   request_builder_ = request_builder;
   read_callback_ = read_callback;
   write_callback_ = write_callback;
 
   net::NetworkChangeNotifier::AddNetworkChangeObserver(this);
   waiting_for_network_online_ = net::NetworkChangeNotifier::IsOffline();

[Nicolas Zea, 2016/12/01 18:51:49]

You probably need to notify the event tracker that network type changed here to
net::NetworkChangeNotifier::GetConnectionType() 

[harkness, 2016/12/05 15:39:00]

Ah! That's exactly the method I needed, and somehow I overlooked. Rather than
storing/updating the network type, I'm just going to query it when we build the
event.

 }
 
 ConnectionHandler* ConnectionFactoryImpl::GetConnectionHandler() const {
   return connection_handler_.get();
 }
 
 void ConnectionFactoryImpl::Connect() {
   if (!connection_handler_) {
     connection_handler_ = CreateConnectionHandler(
         base::TimeDelta::FromMilliseconds(kReadTimeoutMs), read_callback_,
@@ skipping 85 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.
   }
 
+  if (logging_in_)
+    event_tracker_.ConnectionLoginFailed();
+  event_tracker_.EndConnectionAttempt();

[Peter Beverloo, 2016/12/02 15:19:13]

It seems to me like you'd want this to live in ConnectionHandlerCallback
instead?

SignalConnectionReset is called when the connection has been *reset* because of
an error. That could be hours after the connection attempt started, which aren't
really the semantics we want. Instead, ConnectionHandlerCallback is called when
(among other reasons) the handshake has been completed.

[harkness, 2016/12/05 15:39:01]

The problem here may be naming. The issue is that one of the fields to be filled
out is time_connection_ended_ms, which for a successful connection could be
hours long. We could fill out almost all information in
ConnectionHandlerCallback (and we do, because we call
ConnectionAttemptSucceeded() there), but we wouldn't have that info.

I could change the name of the method to EndConnection(), but the functionality
is identical for when a connection attempt fails and we end it, and in that case
EndConnectionAttempt() is definitely the right naming. 

[Peter Beverloo, 2016/12/05 16:29:34]

When a connection attempt fails, the connection itself also ends. (Following a
line of thought where a connection is not per se established.) Let's do
EndConnection()?

As an aside, consider prefixing these methods with Did to avoid ambiguity with
*actually* ending the connection:

- DidStartConnectionAttempt
- DidFinishConnectionAttempt
- ...

Not super pretty, but it would increase clarity.

+
   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) {
+  // Let the connection tracker know about the network type.

[Peter Beverloo, 2016/12/02 15:19:13]

nit: I'd drop the comment. It's already clear from the call.

[harkness, 2016/12/05 15:39:00]

Removed.

+  event_tracker_.OnNetworkChanged(type);
+
   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() {
+  event_tracker_.StartConnectionAttempt();
+  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()) {
+    event_tracker_.WriteToLoginRequest(&login_request);

[Peter Beverloo, 2016/12/02 15:19:13]

MCSClient::ResetStateAndBuildLoginRequest actually swaps out the passed
|*login_request| with another instance, so the stuff you're adding here is being
overwritten by line 340.

Instead, call WriteToLoginRequest after the DCHECK on line 341.

[harkness, 2016/12/05 15:39:00]

Nice catch! It looks like this isn't caught by the tests because they use an
empty BuildLoginRequestCallback method.

     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);
 
+    event_tracker_.ConnectionAttemptFailed(result);
+    event_tracker_.EndConnectionAttempt();
+
     // 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;
 
+  event_tracker_.ConnectionAttemptSucceeded();

[Peter Beverloo, 2016/12/02 15:19:13]

It seems to me that, logically, this would be a better fit in OnConnectDone().
(Around line 406, supposedly.)

[harkness, 2016/12/05 15:39:01]

Actually, I think this placement is correct. The most important thing that
happens in ConnectionAttemptSucceeded() is that the previous set of events is
cleared. However, in OnConnectDone() the login request hasn't been sent yet. So
if we clear it here, we'll never send any events upstream.

OnConnectDone just means that the physical connection is established. It's not
until InitHandler() is procecessed that ConnectionHandlerImpl::Login gets called
and exchanges the Login/Login ack. The result of the Login response is what
causes ConnectionHandlerCallback to be called, so that's the first place it's
safe to clear the previous event data.

[Peter Beverloo, 2016/12/05 16:29:34]

Acknowledged.

+
   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