[CrOS PhoneHub] Add logging to help debug BLE scans

We've seen some intermittent connectivity issues where BLE scans do not
pick up advertisements sent by the phone. However, it's hard for us to
tell what service data is being scanned so that we can match this logged
data up with bug reports on the phone.

This CL logs this metadata during BLE scans.

Bug: 1164572
Change-Id: Icefbd5624a7c5987db944883d1e77d6530951f31
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2626316Reviewed-by: Josh Nohle <nohle@chromium.org>
Commit-Queue: Kyle Horimoto <khorimoto@chromium.org>
Cr-Commit-Position: refs/heads/master@{#843034}

chromeos/services/secure_channel/ble_scanner_impl.cc

@@ -9,6 +9,8 @@
 
 #include "base/bind.h"
 #include "base/memory/ptr_util.h"
+#include "base/strings/strcat.h"
+#include "base/strings/string_number_conversions.h"
 #include "base/strings/string_util.h"
 #include "chromeos/components/multidevice/logging/logging.h"
 #include "chromeos/components/multidevice/remote_device_ref.h"
@@ -78,6 +80,14 @@ BleScannerImpl::~BleScannerImpl() {
 }
 
 void BleScannerImpl::HandleScanRequestChange() {
+  if (GetAllDeviceIdPairs().empty()) {
+    PA_LOG(INFO) << "No devices to scan for";
+  } else {
+    PA_LOG(INFO) << "Scanning for: "
+                 << bluetooth_helper_->ExpectedServiceDataToString(
+                        GetAllDeviceIdPairs());
+  }
+
   UpdateDiscoveryStatus();
 }
 
@@ -258,17 +268,15 @@ void BleScannerImpl::HandlePotentialScanResult(
   }
 
   // Prepare a hex string of |service_data|.
-  std::stringstream ss;
-  ss << "0x" << std::hex;
-  for (const auto& character : service_data)
-    ss << static_cast<uint32_t>(character);
+  std::string hex_service_data = base::StrCat(
+      {"0x", base::HexEncode(service_data.data(), service_data.size())});
 
   if (results.empty()) {
     PA_LOG(WARNING) << "BleScannerImpl::HandleDeviceUpdated(): Received scan "
                     << "result from device with ID \""
                     << potential_result.first.GetTruncatedDeviceIdForLogs()
                     << "\", but it did not correspond to an active scan "
-                    << "request. Service data: " << ss.str()
+                    << "request. Service data: " << hex_service_data
                     << ", Background advertisement: "
                     << (potential_result.second ? "true" : "false");
     return;
@@ -277,7 +285,7 @@ void BleScannerImpl::HandlePotentialScanResult(
   PA_LOG(INFO) << "BleScannerImpl::HandleDeviceUpdated(): Received scan result "
                << "from device with ID \""
                << potential_result.first.GetTruncatedDeviceIdForLogs() << "\""
-               << ". Service data: " << ss.str()
+               << ". Service data: " << hex_service_data
                << ", Background advertisement: "
                << (potential_result.second ? "true" : "false");
 

chromeos/services/secure_channel/bluetooth_helper.h

@@ -50,6 +50,11 @@ class BluetoothHelper {
   virtual std::string GetBluetoothPublicAddress(
       const std::string& device_id) = 0;
 
+  // Prints a string containing the expected service data for the provided
+  // device IDs.
+  virtual std::string ExpectedServiceDataToString(
+      const DeviceIdPairSet& device_id_pair_set) = 0;
+
  protected:
   BluetoothHelper();
 

chromeos/services/secure_channel/bluetooth_helper_impl.cc

@@ -140,6 +140,40 @@ std::string BluetoothHelperImpl::GetBluetoothPublicAddress(
   return std::string();
 }
 
+std::string BluetoothHelperImpl::ExpectedServiceDataToString(
+    const DeviceIdPairSet& device_id_pair_set) {
+  std::stringstream ss;
+
+  for (const DeviceIdPair& pair : device_id_pair_set) {
+    ss << "{Device ID: "
+       << multidevice::RemoteDeviceRef::TruncateDeviceIdForLogs(
+              pair.remote_device_id())
+       << " - ";
+
+    base::Optional<multidevice::RemoteDeviceRef> device =
+        remote_device_cache_->GetRemoteDevice(
+            base::nullopt /* instance_id */,
+            pair.remote_device_id() /* legacy_device_id */);
+
+    if (!device) {
+      ss << "<missing metadata>},";
+      continue;
+    }
+
+    std::vector<DataWithTimestamp> data_for_device =
+        background_eid_generator_->GenerateNearestEids(
+            multidevice::ToCryptAuthSeedList(device->beacon_seeds()));
+    if (data_for_device.empty()) {
+      ss << "[]},";
+      continue;
+    }
+
+    ss << DataWithTimestamp::ToDebugString(data_for_device) << "},";
+  }
+
+  return ss.str();
+}
+
 base::Optional<BluetoothHelper::DeviceWithBackgroundBool>
 BluetoothHelperImpl::PerformIdentifyRemoteDevice(
     const std::string& service_data,

chromeos/services/secure_channel/bluetooth_helper_impl.h

@@ -58,6 +58,8 @@ class BluetoothHelperImpl : public BluetoothHelper {
       const std::string& service_data,
       const DeviceIdPairSet& device_id_pair_set) override;
   std::string GetBluetoothPublicAddress(const std::string& device_id) override;
+  std::string ExpectedServiceDataToString(
+      const DeviceIdPairSet& device_id_pair_set) override;
 
   base::Optional<BluetoothHelper::DeviceWithBackgroundBool>
   PerformIdentifyRemoteDevice(

chromeos/services/secure_channel/fake_bluetooth_helper.cc

@@ -68,6 +68,12 @@ std::string FakeBluetoothHelper::GetBluetoothPublicAddress(
   return device_id_to_bluetooth_public_address_map_[device_id];
 }
 
+std::string FakeBluetoothHelper::ExpectedServiceDataToString(
+    const DeviceIdPairSet& device_id_pair_set) {
+  // Stub implementation.
+  return std::string();
+}
+
 }  // namespace secure_channel
 
 }  // namespace chromeos

chromeos/services/secure_channel/fake_bluetooth_helper.h

@@ -49,6 +49,8 @@ class FakeBluetoothHelper : public BluetoothHelper {
       const std::string& service_data,
       const DeviceIdPairSet& device_id_pair_set) override;
   std::string GetBluetoothPublicAddress(const std::string& device_id) override;
+  std::string ExpectedServiceDataToString(
+      const DeviceIdPairSet& device_id_pair_set) override;
 
   std::unordered_map<DeviceIdPair, DataWithTimestamp, DeviceIdPairHash>
       device_id_pair_to_service_data_map_;