[CrOS PhoneHub] Record Nearby Connections effective success rate

In this context, "effective" means that (1) a failure followed by a
successful retry is counted as a success, and (2) repeated failures
(e.g., due to users stuck in an unrecoverable state due to Bluetooth
issues) are only counted as a single failure.

Bug: 1159963, 1106937
Change-Id: If7ba88cbc1d4247300541ec579c2c55825b8a8a0
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2601756
Commit-Queue: Kyle Horimoto <khorimoto@chromium.org>
Reviewed-by: Steven Holte <holte@chromium.org>
Cr-Commit-Position: refs/heads/master@{#839639}

chromeos/services/secure_channel/BUILD.gn

@@ -110,6 +110,8 @@ static_library("secure_channel") {
     "nearby_connection_manager.h",
     "nearby_connection_manager_impl.cc",
     "nearby_connection_manager_impl.h",
+    "nearby_connection_metrics_recorder.cc",
+    "nearby_connection_metrics_recorder.h",
     "nearby_initiator_connection_attempt.cc",
     "nearby_initiator_connection_attempt.h",
     "nearby_initiator_failure_type.cc",
@@ -302,6 +304,7 @@ source_set("unit_tests") {
     "foreground_eid_generator_unittest.cc",
     "multiplexed_channel_impl_unittest.cc",
     "nearby_connection_manager_impl_unittest.cc",
+    "nearby_connection_metrics_recorder_unittest.cc",
     "nearby_connection_unittest.cc",
     "nearby_initiator_operation_unittest.cc",
     "pending_ble_connection_request_base_unittest.cc",

chromeos/services/secure_channel/nearby_connection_metrics_recorder.cc

+// Copyright 2020 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 "chromeos/services/secure_channel/nearby_connection_metrics_recorder.h"
+
+#include "base/metrics/histogram_functions.h"
+#include "base/threading/thread_task_runner_handle.h"
+#include "base/time/time.h"
+
+namespace chromeos {
+namespace secure_channel {
+namespace {
+
+static constexpr base::TimeDelta kEffectiveSuccessRateTimeout =
+    base::TimeDelta::FromMinutes(1);
+
+void RecordEffectiveConnectionResult(bool success) {
+  base::UmaHistogramBoolean(
+      "MultiDevice.SecureChannel.Nearby.EffectiveConnectionResult", success);
+}
+
+}  // namespace
+
+NearbyConnectionMetricsRecorder::NearbyConnectionMetricsRecorder() = default;
+
+NearbyConnectionMetricsRecorder::~NearbyConnectionMetricsRecorder() = default;
+
+void NearbyConnectionMetricsRecorder::HandleConnectionSuccess(
+    const DeviceIdPair& device_id_pair) {
+  RecordEffectiveConnectionResult(/*success=*/true);
+
+  // If there was a previous unsuccessful attempt, clear the unsuccessful
+  // timestamp since there was a successful retry.
+  id_pair_to_first_unsuccessful_timestamp_map_[device_id_pair] = base::Time();
+}
+
+void NearbyConnectionMetricsRecorder::HandleConnectionFailure(
+    const DeviceIdPair& device_id_pair) {
+  base::Time& first_unsuccessful_time =
+      id_pair_to_first_unsuccessful_timestamp_map_[device_id_pair];
+
+  // If the first unsuccessful timstamp for this ID pair is already set, return
+  // early to ensure that we do not log multiple repeated failures.
+  if (!first_unsuccessful_time.is_null())
+    return;
+
+  // Set the current time as the first unsuccessful timestamp.
+  first_unsuccessful_time = base::Time::Now();
+
+  // Start a timeout period; if no successful attempts occur before this period,
+  // we'll log a failure.
+  base::ThreadTaskRunnerHandle::Get()->PostDelayedTask(
+      FROM_HERE,
+      base::BindOnce(&NearbyConnectionMetricsRecorder::OnTimeout,
+                     weak_ptr_factory_.GetWeakPtr(), device_id_pair),
+      kEffectiveSuccessRateTimeout);
+}
+
+void NearbyConnectionMetricsRecorder::OnTimeout(
+    const DeviceIdPair& device_id_pair) {
+  const base::Time& first_unsuccessful_time =
+      id_pair_to_first_unsuccessful_timestamp_map_[device_id_pair];
+
+  // There was a successful retry during the timeout period; do not log a
+  // failure result.
+  if (first_unsuccessful_time.is_null() ||
+      base::Time::Now() - first_unsuccessful_time <
+          kEffectiveSuccessRateTimeout) {
+    return;
+  }
+
+  RecordEffectiveConnectionResult(/*success=*/false);
+}
+
+}  // namespace secure_channel
+}  // namespace chromeos

chromeos/services/secure_channel/nearby_connection_metrics_recorder.h

+// Copyright 2020 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.
+
+#ifndef CHROMEOS_SERVICES_SECURE_CHANNEL_NEARBY_CONNECTION_METRICS_RECORDER_H_
+#define CHROMEOS_SERVICES_SECURE_CHANNEL_NEARBY_CONNECTION_METRICS_RECORDER_H_
+
+#include "base/containers/flat_map.h"
+#include "base/memory/weak_ptr.h"
+#include "chromeos/services/secure_channel/device_id_pair.h"
+
+namespace chromeos {
+namespace secure_channel {
+
+// Records the effective success rate for Nearby Connections attempts. In this
+// context, "effective" means that (1) a failure followed by a successful retry
+// is counted as a success, and (2) repeated failures (e.g., due to users stuck
+// in an unrecoverable state due to Bluetooth issues) are only counted as a
+// single failure.
+//
+// To implement this metric, we log every successful attempt as a success. When
+// a failure occurs, we wait one minute to see whether a retry succeeds before
+// that point. If there was no success in that time frame, we then log a
+// failure.
+class NearbyConnectionMetricsRecorder {
+ public:
+  NearbyConnectionMetricsRecorder();
+  ~NearbyConnectionMetricsRecorder();
+
+  void HandleConnectionSuccess(const DeviceIdPair& device_id_pair);
+  void HandleConnectionFailure(const DeviceIdPair& device_id_pair);
+
+ private:
+  void OnTimeout(const DeviceIdPair& device_id_pair);
+
+  // Stores a null Time when the last attempt was successful.
+  base::flat_map<DeviceIdPair, base::Time>
+      id_pair_to_first_unsuccessful_timestamp_map_;
+
+  base::WeakPtrFactory<NearbyConnectionMetricsRecorder> weak_ptr_factory_{this};
+};
+
+}  // namespace secure_channel
+}  // namespace chromeos
+
+#endif  // CHROMEOS_SERVICES_SECURE_CHANNEL_NEARBY_CONNECTION_METRICS_RECORDER_H_

chromeos/services/secure_channel/nearby_connection_metrics_recorder_unittest.cc

+// Copyright 2020 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 "chromeos/services/secure_channel/nearby_connection_metrics_recorder.h"
+
+#include <memory>
+
+#include "base/bind.h"
+#include "base/test/metrics/histogram_tester.h"
+#include "base/test/task_environment.h"
+#include "base/test/test_simple_task_runner.h"
+#include "base/time/time.h"
+#include "chromeos/services/secure_channel/device_id_pair.h"
+#include "testing/gtest/include/gtest/gtest.h"
+
+namespace chromeos {
+namespace secure_channel {
+
+const char kTestRemoteDeviceId[] = "testRemoteDeviceId";
+const char kTestLocalDeviceId[] = "testLocalDeviceId";
+
+class SecureChannelNearbyConnectionMetricsRecorderTest : public testing::Test {
+ protected:
+  SecureChannelNearbyConnectionMetricsRecorderTest()
+      : device_id_pair_(kTestRemoteDeviceId, kTestLocalDeviceId) {}
+  SecureChannelNearbyConnectionMetricsRecorderTest(
+      const SecureChannelNearbyConnectionMetricsRecorderTest&) = delete;
+  SecureChannelNearbyConnectionMetricsRecorderTest& operator=(
+      const SecureChannelNearbyConnectionMetricsRecorderTest&) = delete;
+  ~SecureChannelNearbyConnectionMetricsRecorderTest() override = default;
+
+  const DeviceIdPair device_id_pair_;
+  base::test::TaskEnvironment task_environment_{
+      base::test::TaskEnvironment::TimeSource::MOCK_TIME};
+  base::HistogramTester histogram_tester_;
+
+  NearbyConnectionMetricsRecorder recorder_;
+};
+
+TEST_F(SecureChannelNearbyConnectionMetricsRecorderTest, Test) {
+  // Succeed; metric should be logged.
+  recorder_.HandleConnectionSuccess(device_id_pair_);
+  histogram_tester_.ExpectBucketCount(
+      "MultiDevice.SecureChannel.Nearby.EffectiveConnectionResult",
+      /*sample=*/true,
+      /*count=*/1);
+
+  task_environment_.FastForwardBy(base::TimeDelta::FromSeconds(10));
+
+  // Succeed again; should be logged.
+  recorder_.HandleConnectionSuccess(device_id_pair_);
+  histogram_tester_.ExpectBucketCount(
+      "MultiDevice.SecureChannel.Nearby.EffectiveConnectionResult",
+      /*sample=*/true,
+      /*count=*/2);
+
+  task_environment_.FastForwardBy(base::TimeDelta::FromSeconds(10));
+
+  // Fail; nothing should be logged since the failure just occurred.
+  recorder_.HandleConnectionFailure(device_id_pair_);
+  histogram_tester_.ExpectBucketCount(
+      "MultiDevice.SecureChannel.Nearby.EffectiveConnectionResult",
+      /*sample=*/false,
+      /*count=*/0);
+
+  // Fast forward 59 seconds (under 1min).
+  task_environment_.FastForwardBy(base::TimeDelta::FromSeconds(59));
+
+  // Fail; still nothing should have been logged.
+  recorder_.HandleConnectionFailure(device_id_pair_);
+  histogram_tester_.ExpectBucketCount(
+      "MultiDevice.SecureChannel.Nearby.EffectiveConnectionResult",
+      /*sample=*/false,
+      /*count=*/0);
+
+  // Fast forward 1 more second; a minute has passed, so a failure should have
+  // been logged.
+  task_environment_.FastForwardBy(base::TimeDelta::FromSeconds(1));
+  histogram_tester_.ExpectBucketCount(
+      "MultiDevice.SecureChannel.Nearby.EffectiveConnectionResult",
+      /*sample=*/false,
+      /*count=*/1);
+
+  task_environment_.FastForwardBy(base::TimeDelta::FromSeconds(10));
+
+  // Succeed; this should reset any ongoing timer.
+  recorder_.HandleConnectionSuccess(device_id_pair_);
+  histogram_tester_.ExpectBucketCount(
+      "MultiDevice.SecureChannel.Nearby.EffectiveConnectionResult",
+      /*sample=*/true,
+      /*count=*/3);
+
+  task_environment_.FastForwardBy(base::TimeDelta::FromSeconds(10));
+
+  // Fail; nothing should be logged.
+  recorder_.HandleConnectionFailure(device_id_pair_);
+  histogram_tester_.ExpectBucketCount(
+      "MultiDevice.SecureChannel.Nearby.EffectiveConnectionResult",
+      /*sample=*/false,
+      /*count=*/1);
+
+  // Move forward another minute and verify that another failure was logged.
+  task_environment_.FastForwardBy(base::TimeDelta::FromMinutes(1));
+  histogram_tester_.ExpectBucketCount(
+      "MultiDevice.SecureChannel.Nearby.EffectiveConnectionResult",
+      /*sample=*/false,
+      /*count=*/2);
+}
+
+}  // namespace secure_channel
+}  // namespace chromeos

chromeos/services/secure_channel/nearby_initiator_operation.cc

@@ -6,9 +6,11 @@
 
 #include "base/bind.h"
 #include "base/memory/ptr_util.h"
+#include "base/no_destructor.h"
 #include "chromeos/services/secure_channel/authenticated_channel.h"
 #include "chromeos/services/secure_channel/connection_metrics_logger.h"
 #include "chromeos/services/secure_channel/nearby_connection_manager.h"
+#include "chromeos/services/secure_channel/nearby_connection_metrics_recorder.h"
 
 namespace chromeos {
 
@@ -32,6 +34,17 @@ NearbyInitiatorConnectionResult GetMetricsConnectionResult(
   }
 }
 
+void RecordConnectionMetrics(const DeviceIdPair& device_id_pair,
+                             NearbyInitiatorConnectionResult result) {
+  LogNearbyInitiatorConnectionResult(result);
+
+  static base::NoDestructor<NearbyConnectionMetricsRecorder> recorder;
+  if (result == NearbyInitiatorConnectionResult::kConnectionSuccess)
+    recorder->HandleConnectionSuccess(device_id_pair);
+  else
+    recorder->HandleConnectionFailure(device_id_pair);
+}
+
 }  // namespace
 
 // static
@@ -112,15 +125,16 @@ void NearbyInitiatorOperation::PerformUpdateConnectionPriority(
 
 void NearbyInitiatorOperation::OnSuccessfulConnection(
     std::unique_ptr<AuthenticatedChannel> authenticated_channel) {
+  RecordConnectionMetrics(device_id_pair(),
+                          NearbyInitiatorConnectionResult::kConnectionSuccess);
   OnSuccessfulConnectionAttempt(std::move(authenticated_channel));
-  LogNearbyInitiatorConnectionResult(
-      NearbyInitiatorConnectionResult::kConnectionSuccess);
 }
 
 void NearbyInitiatorOperation::OnConnectionFailure(
     NearbyInitiatorFailureType failure_type) {
+  RecordConnectionMetrics(device_id_pair(),
+                          GetMetricsConnectionResult(failure_type));
   OnFailedConnectionAttempt(failure_type);
-  LogNearbyInitiatorConnectionResult(GetMetricsConnectionResult(failure_type));
 }
 
 }  // namespace secure_channel

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

@@ -274,6 +274,22 @@ reviews. Googlers can read more about this at go/gwsq-gerrit.
   </summary>
 </histogram>
 
+<histogram name="MultiDevice.SecureChannel.Nearby.EffectiveConnectionResult"
+    enum="BooleanSuccess" expires_after="2021-11-30">
+  <owner>khorimoto@chromium.org</owner>
+  <owner>better-together-dev@google.com</owner>
+  <summary>
+    Measures the effective success rate for Nearby Connections attempts via
+    SecureChannel. In this context, &quot;effective&quot; means that (1) a
+    failure followed by a successful retry is counted as a success, and (2)
+    repeated failures (e.g., due to users stuck in an unrecoverable state due to
+    Bluetooth issues) are only counted as a single failure.
+
+    Emitted upon each successful connection and one minute after a failed
+    connection with no subsequent successful retries.
+  </summary>
+</histogram>
+
 <histogram name="MultiDevice.SecureChannel.Nearby.MessageAction"
     enum="MultiDeviceNearbyMessageAction" expires_after="2021-11-30">
   <owner>khorimoto@chromium.org</owner>