[CrOS PhoneHub] Add Nearby Connection disconnection reason metric

This metric provides insight into the ways that Nearby Connections
disconnect, including failures reasons. This will help us dig into
potential failure reasons for connection stability.

Bug: 1163979
Change-Id: I1e685ea6863cfe2bb12a7bbdd20decd9887337ef
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2616478
Commit-Queue: Kyle Horimoto <khorimoto@chromium.org>
Reviewed-by: Ryan Hansberry <hansberry@chromium.org>
Reviewed-by: Michael Lippautz <mlippautz@chromium.org>
Reviewed-by: Mark Pearson <mpearson@chromium.org>
Auto-Submit: Kyle Horimoto <khorimoto@chromium.org>
Cr-Commit-Position: refs/heads/master@{#841643}

chrome/browser/chromeos/secure_channel/nearby_connection_broker_impl.cc

@@ -142,7 +142,15 @@ void NearbyConnectionBrokerImpl::TransitionToStatus(
           weak_ptr_factory_.GetWeakPtr()));
 }
 
-void NearbyConnectionBrokerImpl::Disconnect() {
+void NearbyConnectionBrokerImpl::Disconnect(
+    util::NearbyDisconnectionReason reason) {
+  // Only log a single disconnection reason per connection attempt. Edge cases
+  // can cause this function to be invoked multiple times.
+  if (!has_disconnect_reason_been_logged_) {
+    has_disconnect_reason_been_logged_ = true;
+    util::RecordNearbyDisconnection(reason);
+  }
+
   if (!need_to_disconnect_endpoint_) {
     TransitionToDisconnectedAndInvokeCallback();
     return;
@@ -190,7 +198,7 @@ void NearbyConnectionBrokerImpl::OnEndpointDiscovered(
 
 void NearbyConnectionBrokerImpl::OnDiscoveryFailure() {
   DCHECK_EQ(ConnectionStatus::kDiscoveringEndpoint, connection_status_);
-  Disconnect();
+  Disconnect(util::NearbyDisconnectionReason::kFailedDiscovery);
 }
 
 void NearbyConnectionBrokerImpl::OnRequestConnectionResult(Status status) {
@@ -200,7 +208,7 @@ void NearbyConnectionBrokerImpl::OnRequestConnectionResult(Status status) {
     return;
 
   PA_LOG(WARNING) << "RequestConnection() failed: " << status;
-  Disconnect();
+  Disconnect(util::NearbyDisconnectionReason::kFailedRequestingConnection);
 }
 
 void NearbyConnectionBrokerImpl::OnAcceptConnectionResult(Status status) {
@@ -212,7 +220,7 @@ void NearbyConnectionBrokerImpl::OnAcceptConnectionResult(Status status) {
   }
 
   PA_LOG(WARNING) << "AcceptConnection() failed: " << status;
-  Disconnect();
+  Disconnect(util::NearbyDisconnectionReason::kFailedAcceptingConnection);
 }
 
 void NearbyConnectionBrokerImpl::OnSendPayloadResult(
@@ -228,7 +236,7 @@ void NearbyConnectionBrokerImpl::OnSendPayloadResult(
     return;
 
   PA_LOG(WARNING) << "OnSendPayloadResult() failed: " << status;
-  Disconnect();
+  Disconnect(util::NearbyDisconnectionReason::kSendMessageFailed);
 }
 
 void NearbyConnectionBrokerImpl::OnDisconnectFromEndpointResult(Status status) {
@@ -240,7 +248,7 @@ void NearbyConnectionBrokerImpl::OnDisconnectFromEndpointResult(Status status) {
   PA_LOG(WARNING) << "Failed to disconnect from endpoint with ID "
                   << remote_endpoint_id_ << ": " << status;
   need_to_disconnect_endpoint_ = false;
-  Disconnect();
+  Disconnect(util::NearbyDisconnectionReason::kDisconnectionRequestedByClient);
 }
 
 void NearbyConnectionBrokerImpl::OnConnectionStatusChangeTimeout() {
@@ -257,11 +265,32 @@ void NearbyConnectionBrokerImpl::OnConnectionStatusChangeTimeout() {
     need_to_disconnect_endpoint_ = true;
 
   PA_LOG(WARNING) << "Timeout changing connection status";
-  Disconnect();
+  util::NearbyDisconnectionReason reason;
+  switch (connection_status_) {
+    case ConnectionStatus::kDiscoveringEndpoint:
+      reason = util::NearbyDisconnectionReason::kTimeoutDuringDiscovery;
+      break;
+    case ConnectionStatus::kRequestingConnection:
+      reason = util::NearbyDisconnectionReason::kTimeoutDuringRequestConnection;
+      break;
+    case ConnectionStatus::kAcceptingConnection:
+      reason = util::NearbyDisconnectionReason::kTimeoutDuringAcceptConnection;
+      break;
+    case ConnectionStatus::kWaitingForConnectionToBeAcceptedByRemoteDevice:
+      reason =
+          util::NearbyDisconnectionReason::kTimeoutWaitingForConnectionAccepted;
+      break;
+    default:
+      NOTREACHED() << "Unexpected timeout with connection status "
+                   << connection_status_;
+      reason = util::NearbyDisconnectionReason::kConnectionLost;
+      break;
+  }
+  Disconnect(reason);
 }
 
 void NearbyConnectionBrokerImpl::OnMojoDisconnection() {
-  Disconnect();
+  Disconnect(util::NearbyDisconnectionReason::kDisconnectionRequestedByClient);
 }
 
 void NearbyConnectionBrokerImpl::SendMessage(const std::string& message,
@@ -339,7 +368,7 @@ void NearbyConnectionBrokerImpl::OnConnectionRejected(
   }
 
   PA_LOG(WARNING) << "Connection rejected: " << status;
-  Disconnect();
+  Disconnect(util::NearbyDisconnectionReason::kConnectionRejected);
 }
 
 void NearbyConnectionBrokerImpl::OnDisconnected(
@@ -354,7 +383,7 @@ void NearbyConnectionBrokerImpl::OnDisconnected(
     PA_LOG(WARNING) << "Connection disconnected unexpectedly";
   }
   need_to_disconnect_endpoint_ = false;
-  Disconnect();
+  Disconnect(util::NearbyDisconnectionReason::kConnectionLost);
 }
 
 void NearbyConnectionBrokerImpl::OnBandwidthChanged(
@@ -390,7 +419,7 @@ void NearbyConnectionBrokerImpl::OnPayloadReceived(
   if (!payload->content->is_bytes()) {
     PA_LOG(WARNING) << "OnPayloadReceived(): Received unexpected payload type "
                     << "(was expecting bytes type). Disconnecting.";
-    Disconnect();
+    Disconnect(util::NearbyDisconnectionReason::kReceivedUnexpectedPayloadType);
     return;
   }
 

chrome/browser/chromeos/secure_channel/nearby_connection_broker_impl.h

@@ -13,6 +13,7 @@
 #include "base/time/time.h"
 #include "base/timer/timer.h"
 #include "chrome/browser/chromeos/secure_channel/nearby_connection_broker.h"
+#include "chrome/browser/chromeos/secure_channel/util/histogram_util.h"
 #include "chromeos/services/nearby/public/mojom/nearby_connections.mojom.h"
 #include "mojo/public/cpp/bindings/shared_remote.h"
 
@@ -102,7 +103,7 @@ class NearbyConnectionBrokerImpl
       std::unique_ptr<base::OneShotTimer> timer);
 
   void TransitionToStatus(ConnectionStatus connection_status);
-  void Disconnect();
+  void Disconnect(util::NearbyDisconnectionReason reason);
   void TransitionToDisconnectedAndInvokeCallback();
 
   void OnEndpointDiscovered(
@@ -174,6 +175,8 @@ class NearbyConnectionBrokerImpl
   // Starts as null; set in OnConnectionAccepted().
   base::Time time_when_connection_accepted_;
 
+  bool has_disconnect_reason_been_logged_ = false;
+
   base::WeakPtrFactory<NearbyConnectionBrokerImpl> weak_ptr_factory_{this};
 };
 

chrome/browser/chromeos/secure_channel/nearby_connector_impl.cc

@@ -7,6 +7,7 @@
 #include "base/bind.h"
 #include "chrome/browser/chromeos/secure_channel/nearby_connection_broker_impl.h"
 #include "chrome/browser/chromeos/secure_channel/nearby_endpoint_finder_impl.h"
+#include "chrome/browser/chromeos/secure_channel/util/histogram_util.h"
 #include "chromeos/components/multidevice/logging/logging.h"
 #include "chromeos/services/nearby/public/cpp/nearby_process_manager.h"
 #include "chromeos/services/secure_channel/public/cpp/client/nearby_connector.h"
@@ -132,6 +133,12 @@ void NearbyConnectorImpl::OnNearbyProcessStopped() {
   PA_LOG(WARNING) << "Nearby process stopped unexpectedly. Destroying active "
                   << "connections.";
 
+  // Record the disconnection reason for each of the active brokers.
+  for (size_t i = 0; i < id_to_brokers_map_.size(); ++i) {
+    util::RecordNearbyDisconnection(
+        util::NearbyDisconnectionReason::kNearbyProcessCrash);
+  }
+
   ClearActiveAndPendingConnections();
   ProcessQueuedConnectionRequests();
 }

chrome/browser/chromeos/secure_channel/util/histogram_util.cc

@@ -15,6 +15,11 @@ void LogMessageAction(MessageAction message_action) {
       "MultiDevice.SecureChannel.Nearby.MessageAction", message_action);
 }
 
+void RecordNearbyDisconnection(NearbyDisconnectionReason reason) {
+  base::UmaHistogramEnumeration(
+      "MultiDevice.SecureChannel.Nearby.DisconnectionReason", reason);
+}
+
 }  // namespace util
 }  // namespace secure_channel
 }  // namespace chromeos

chrome/browser/chromeos/secure_channel/util/histogram_util.h

@@ -22,6 +22,28 @@ enum class MessageAction {
 // Logs a given message transfer action.
 void LogMessageAction(MessageAction message_action);
 
+// Reasons why a Nearby Connection may become disconnected. These values are
+// persisted to logs. Entries should not be renumbered and numeric values should
+// never be reused.
+enum class NearbyDisconnectionReason {
+  kDisconnectionRequestedByClient = 0,
+  kFailedDiscovery = 1,
+  kTimeoutDuringDiscovery = 2,
+  kFailedRequestingConnection = 3,
+  kTimeoutDuringRequestConnection = 4,
+  kFailedAcceptingConnection = 5,
+  kTimeoutDuringAcceptConnection = 6,
+  kConnectionRejected = 7,
+  kTimeoutWaitingForConnectionAccepted = 8,
+  kSendMessageFailed = 9,
+  kReceivedUnexpectedPayloadType = 10,
+  kConnectionLost = 11,
+  kNearbyProcessCrash = 12,
+  kMaxValue = kNearbyProcessCrash
+};
+
+void RecordNearbyDisconnection(NearbyDisconnectionReason reason);
+
 }  // namespace util
 }  // namespace secure_channel
 }  // namespace chromeos

tools/metrics/histograms/enums.xml

@@ -50329,6 +50329,22 @@ Called by update_use_counter_css.py.-->
   <int value="5" label="Authentication Error"/>
 </enum>
 
+<enum name="MultiDeviceNearbyDisconnectionReason">
+  <int value="0" label="Disconnection requested by client"/>
+  <int value="1" label="Failed discovery"/>
+  <int value="2" label="Timeout during discovery"/>
+  <int value="3" label="Failed requesting connection"/>
+  <int value="4" label="Timeout during RequestConnection() call"/>
+  <int value="5" label="Failed accepting connection"/>
+  <int value="6" label="Timeout during AcceptConnection() call"/>
+  <int value="7" label="Connection rejected"/>
+  <int value="8" label="Timeout waiting for connection to be accepted"/>
+  <int value="9" label="SendMessage() failed"/>
+  <int value="10" label="Received unexpected payload type"/>
+  <int value="11" label="Connection lost"/>
+  <int value="12" label="Nearby process crash"/>
+</enum>
+
 <enum name="MultiDeviceNearbyMessageAction">
   <int value="0" label="Message Sent"/>
   <int value="1" label="Message Received"/>

tools/metrics/histograms/histograms_xml/multi_device/histograms.xml

@@ -274,6 +274,21 @@ reviews. Googlers can read more about this at go/gwsq-gerrit.
   </summary>
 </histogram>
 
+<histogram name="MultiDevice.SecureChannel.Nearby.DisconnectionReason"
+    enum="MultiDeviceNearbyDisconnectionReason" expires_after="2022-01-01">
+  <owner>khorimoto@chromium.org</owner>
+  <owner>better-together-dev@google.com</owner>
+  <summary>
+    Tracks reasons why a Nearby Connection established via SecureChannel ends up
+    disconnecting. Includes a &quot;Disconnection requested by client&quot;
+    value emitted during intentional disconnections as well as several error
+    enum values.
+
+    Emitted when a connection fails to become established, or emitted after it
+    is already established when it becomes disconnected.
+  </summary>
+</histogram>
+
 <histogram name="MultiDevice.SecureChannel.Nearby.EffectiveConnectionResult"
     enum="BooleanSuccess" expires_after="2021-11-30">
   <owner>khorimoto@chromium.org</owner>