bluetooth: Add histograms and logging for requestDevice()

content/browser/bluetooth/bluetooth_dispatcher_host.cc

 // Copyright 2014 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.
 
 // NETWORK_ERROR Note:
 // When a device can't be found in the BluetoothAdapter, that generally
 // indicates that it's gone out of range. We reject with a NetworkError in that
 // case.
 // https://webbluetoothchrome.github.io/web-bluetooth/#dom-bluetoothdevice-connectgatt
 
 #include "content/browser/bluetooth/bluetooth_dispatcher_host.h"
 
 #include "base/metrics/histogram.h"
+#include "base/strings/string_util.h"
 #include "base/strings/utf_string_conversions.h"
 #include "content/browser/bad_message.h"
 #include "content/browser/frame_host/render_frame_host_impl.h"
 #include "content/common/bluetooth/bluetooth_messages.h"
 #include "device/bluetooth/bluetooth_adapter.h"
 #include "device/bluetooth/bluetooth_adapter_factory.h"
 #include "device/bluetooth/bluetooth_device.h"
 #include "device/bluetooth/bluetooth_discovery_session.h"
 #include "device/bluetooth/bluetooth_gatt_characteristic.h"
 #include "device/bluetooth/bluetooth_gatt_service.h"
 
 using blink::WebBluetoothError;
 using device::BluetoothAdapter;
 using device::BluetoothAdapterFactory;
 using device::BluetoothGattCharacteristic;
 using device::BluetoothGattService;
 using device::BluetoothUUID;
 
 namespace {
 
+const char kBaseStandardServiceUUID[] = "00001800-0000-1000-8000-00805f9b34fb";
+// Current Max Standard Service UUID:
+// https://developer.bluetooth.org/gatt/services/Pages/ServicesHome.aspx?SortField=AssignedNumber&SortDir=Asc
+const uint16_t kMaxStandardServiceUUID = 0x22;

[Jeffrey Yasskin, 2015/08/10 22:18:56]

Let's not force ourselves to update this every time they come up with a new
service UUID. Just pass the full 2 hexdigits?

However, a constant for the 0x101 would be useful.

[ortuno, 2015/08/11 20:10:55]

Changing to hash function instead.

+
 // These types of errors aren't as common. We log them to understand
 // how common they are and if we need to investigate more.
 enum class BluetoothGATTError {
   UNKNOWN,
   FAILED,
   IN_PROGRESS,
   NOT_PAIRED,
   // Add errors above this line and update corresponding histograms.xml enum.
   MAX_ERROR,
 };
 
 enum class UMARequestDeviceOutcome {
   SUCCESS = 0,
   NO_BLUETOOTH_ADAPTER = 1,
   NO_RENDER_FRAME = 2,
   DISCOVERY_START_FAILED = 3,
   DISCOVERY_STOP_FAILED = 4,
   NO_MATCHING_DEVICES_FOUND = 5,
   BLUETOOTH_ADAPTER_NOT_PRESENT = 6,
   BLUETOOTH_ADAPTER_OFF = 7,
   // NOTE: Add new requestDevice() outcomes immediately above this line. Make
   // sure to update the enum list in
   // tools/metrics/histogram/histograms.xml accordingly.
   COUNT
 };
 
 void RecordRequestDeviceOutcome(UMARequestDeviceOutcome outcome) {
-  UMA_HISTOGRAM_ENUMERATION("Bluetooth.RequestDevice.Outcome",
+  UMA_HISTOGRAM_ENUMERATION("Bluetooth.Web.RequestDevice.Outcome",
                             static_cast<int>(outcome),
                             static_cast<int>(UMARequestDeviceOutcome::COUNT));
 }
 
+int GetServiceEnum(const BluetoothUUID& service) {
+  if (!service.canonical_value().compare(0, 6,

[Jeffrey Yasskin, 2015/08/10 22:18:56]

Please use ==0 for .compare(). It's a tri-valued function, not a boolean, and !
tends to be confusing.

[ortuno, 2015/08/11 20:10:55]

Sorry. Should have looked at the documentation closer.

+                                         kBaseStandardServiceUUID)  // 000018
+      ||
+      !service.canonical_value().compare(
+          8, 28, kBaseStandardServiceUUID)) {  // -0000-1000-8000-00805f9b34fb

[Jeffrey Yasskin, 2015/08/10 22:18:56]

This comparison isn't quite right. kBaseStandardServiceUUID will be compared
from the beginning, but you want to compare from kBaseStandardServiceUUID + 8.
Can we have a unittest for this?

[ortuno, 2015/08/11 20:10:55]

Changing to hash based histogram.

+    return 0;                                  // Unknown Service
+  }
+  uint16_t service_enum = 0;
+  for (int i = 0; i < 2; i++) {
+    service_enum <<= 4;

[Alexei Svitkine (slow), 2015/08/10 22:03:35]

Instead of doing this complicated logic, have you considered just logging the
hash of service.canonical_value() in an enumerated histogram>

[Jeffrey Yasskin, 2015/08/10 22:18:56]

We didn't consider that, but 1) what's the maximum value for that enumeration?
2) The BT standards body gives us a contiguous range of values; it seems odd to
spread them out and risk collisions by hashing.

However, we don't need a loop here.

  const std::string& uuid = service.canonical_value();
  uint16_t service_enum = base::HexDigitToInt(uuid[6]) * 0x10 +
base::HexDigitToInt(uuid[7]);

should be enough. We could CHECK_EQ(36, uuid.size()) if that makes anyone more
comfortable.

On the other hand, if we can easily send a 32-bit hash of the 128-bit UUID,
that'll make it easier to check for the popularity of non-standard services,
which would be better. How do we do that with the histogram macros? They seem to
always want a maximum+1 that fits in an int, and they allocate 'maximum' ints,
which is a lot of memory.

[Alexei Svitkine (slow), 2015/08/11 15:15:08]

The UMA macro for a sparse histogram is UMA_HISTOGRAM_SPARSE_SLOWLY() and
doesn't require a max value param. It uses a map behind the scenes - unlike the
other macros that pre-allocate the bucket array.

The macro supports an int32 range - although it's a bit nicer to use 1 bit less
to ensure the values are positive (make histograms.xml a bit more pleasant).

Here's a few example hash functions people use:
https://code.google.com/p/chromium/codesearch#chromium/src/chrome_elf/dll_has...
https://code.google.com/p/chromium/codesearch#chromium/src/components/proximi...
https://code.google.com/p/chromium/codesearch#chromium/src/chrome/browser/abo...

(Makes me think that we should maybe make a version of that macro that takes a
string param and does the hashing itself, rather than everyone re-inventing
their own hash.)

[ortuno, 2015/08/11 20:10:55]

Done.

+    service_enum += base::HexDigitToInt(service.canonical_value()[i + 6]);

[Alexei Svitkine (slow), 2015/08/10 22:03:36]

What guarantees that i+6 is in range?

[Jeffrey Yasskin, 2015/08/10 22:18:56]

https://code.google.com/p/chromium/codesearch/#chromium/src/device/bluetooth/...,
but it'd make sense to CHECK.

[ortuno, 2015/08/11 20:10:55]

No longer being used.

+  }
+  if (service_enum > kMaxStandardServiceUUID) {
+    return 0;  // Unknown Service
+  }
+  // We shift everything by one because of the unknown service at 0.
+  return ++service_enum;

[Alexei Svitkine (slow), 2015/08/10 22:03:35]

This should be service_enum + 1, since incrementing the local doesn't do
anything here.

[ortuno, 2015/08/11 20:10:55]

Removed.

+}
+
+void RecordRequestDeviceFilters(
+    const std::vector<content::BluetoothScanFilter>& filters) {
+  UMA_HISTOGRAM_COUNTS("Bluetooth.Web.RequestDevice.Filters.Count",
+                       filters.size());
+  for (const content::BluetoothScanFilter& filter : filters) {
+    UMA_HISTOGRAM_COUNTS("Bluetooth.Web.RequestDevice.FilterSize",
+                         filter.services.size());
+    for (const BluetoothUUID& service : filter.services) {
+      UMA_HISTOGRAM_ENUMERATION("Bluetooth.Web.RequestDevice.Filters.Services",
+                                GetServiceEnum(service), 0x101);
+    }
+  }
+}
+
+void RecordRequestDeviceOptionalServices(
+    const std::vector<BluetoothUUID>& optional_services) {
+  UMA_HISTOGRAM_COUNTS("Bluetooth.Web.RequestDevice.OptionalServices.Count",
+                       optional_services.size());
+  for (const BluetoothUUID& service : optional_services) {
+    UMA_HISTOGRAM_ENUMERATION(
+        "Bluetooth.Web.RequestDevice.OptionalServices.Services",
+        GetServiceEnum(service), 0x101);
+  }
+}
+
+void RecordUnionOfServices(
+    const std::vector<content::BluetoothScanFilter>& filters,
+    const std::vector<BluetoothUUID>& optional_services) {
+  const std::set<BluetoothUUID> union_of_services(optional_services.begin(),
+                                                  optional_services.end());
+  for (const content::BluetoothScanFilter& filter : filters)
+    union_of_services.insert(filter.services.begin(), filter.services.end());
+
+  UMA_HISTOGRAM_COUNTS("Bluetooth.Web.RequestDevice.UnionOfServices.Count",
+                       union_of_services.size());
+}
+
 enum class UMAWebBluetoothFunction {
   REQUEST_DEVICE,
   CONNECT_GATT,
   GET_PRIMARY_SERVICE,
   GET_CHARACTERISTIC,
   CHARACTERISTIC_READ_VALUE,
   CHARACTERISTIC_WRITE_VALUE,
   // NOTE: Add new actions immediately above this line. Make sure to update the
   // enum list in tools/metrics/histogram/histograms.xml accordingly.
   COUNT
@@ skipping 188 matching lines @@
 }
 
 void BluetoothDispatcherHost::OnRequestDevice(
     int thread_id,
     int request_id,
     int frame_routing_id,
     const std::vector<BluetoothScanFilter>& filters,
     const std::vector<BluetoothUUID>& optional_services) {
   DCHECK_CURRENTLY_ON(content::BrowserThread::UI);
   RecordWebBluetoothFunctionCall(UMAWebBluetoothFunction::REQUEST_DEVICE);
+  RecordRequestDeviceFilters(filters);
+  RecordRequestDeviceOptionalServices(optional_services);
+  RecordUnionOfServices(filters, optional_services);
+
+  VLOG(1) << "requestDevice called with the following filters: ";
+  for (const BluetoothScanFilter& filter : filters) {
+    VLOG(1) << "[";
+    for (const BluetoothUUID& service : filter.services)
+      VLOG(1) << "\t" << service.value();
+    VLOG(1) << "]";
+  }
+
+  VLOG(1) << "requestDevice called with the following optional services: ";
+  for (const BluetoothUUID& service : optional_services)
+    VLOG(1) << "\t" << service.value();
 
   RenderFrameHostImpl* render_frame_host =
       RenderFrameHostImpl::FromID(render_process_id_, frame_routing_id);
 
   if (!render_frame_host) {
-    DLOG(WARNING)
-        << "Got a requestDevice IPC without a matching RenderFrameHost: "
-        << render_process_id_ << ", " << frame_routing_id;
+    VLOG(1) << "Got a requestDevice IPC without a matching RenderFrameHost: "
+            << render_process_id_ << ", " << frame_routing_id;
     RecordRequestDeviceOutcome(UMARequestDeviceOutcome::NO_RENDER_FRAME);
     Send(new BluetoothMsg_RequestDeviceError(
         thread_id, request_id, WebBluetoothError::RequestDeviceWithoutFrame));
   }
 
   // TODO(scheib): Device selection UI: crbug.com/436280
   // TODO(scheib): Utilize BluetoothAdapter::Observer::DeviceAdded/Removed.
   if (adapter_.get()) {
     if (!request_device_sessions_
              .insert(std::make_pair(
@@ skipping 30 matching lines @@
       request_device_sessions_.erase(std::make_pair(thread_id, request_id));
       return;
     }
     adapter_->StartDiscoverySessionWithFilter(
         ComputeScanFilter(filters),
         base::Bind(&BluetoothDispatcherHost::OnDiscoverySessionStarted,
                    weak_ptr_factory_.GetWeakPtr(), thread_id, request_id),
         base::Bind(&BluetoothDispatcherHost::OnDiscoverySessionStartedError,
                    weak_ptr_factory_.GetWeakPtr(), thread_id, request_id));
   } else {
-    DLOG(WARNING) << "No BluetoothAdapter. Can't serve requestDevice.";
+    VLOG(1) << "No BluetoothAdapter. Can't serve requestDevice.";
     RecordRequestDeviceOutcome(UMARequestDeviceOutcome::NO_BLUETOOTH_ADAPTER);
     Send(new BluetoothMsg_RequestDeviceError(
         thread_id, request_id, WebBluetoothError::NoBluetoothAdapter));
   }
   return;
 }
 
 void BluetoothDispatcherHost::OnConnectGATT(
     int thread_id,
     int request_id,
@@ skipping 263 matching lines @@
 }
 
 void BluetoothDispatcherHost::OnDiscoverySessionStopped(int thread_id,
                                                         int request_id) {
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
   auto session =
       request_device_sessions_.find(std::make_pair(thread_id, request_id));
   CHECK(session != request_device_sessions_.end());
   BluetoothAdapter::DeviceList devices = adapter_->GetDevices();
   for (device::BluetoothDevice* device : devices) {
+    VLOG(1) << "Device: " << device->GetName();
+    VLOG(1) << "UUIDs: ";
+    for (BluetoothUUID uuid : device->GetUUIDs())
+      VLOG(1) << "\t" << uuid.canonical_value();
     if (MatchesFilters(*device, session->second.filters)) {
       content::BluetoothDevice device_ipc(
           device->GetAddress(),         // instance_id
           device->GetName(),            // name
           device->GetBluetoothClass(),  // device_class
           device->GetVendorIDSource(),  // vendor_id_source
           device->GetVendorID(),        // vendor_id
           device->GetProductID(),       // product_id
           device->GetDeviceID(),        // product_version
           device->IsPaired(),           // paired
           content::BluetoothDevice::UUIDsFromBluetoothUUIDs(
               device->GetUUIDs()));  // uuids
       RecordRequestDeviceOutcome(UMARequestDeviceOutcome::SUCCESS);
       Send(new BluetoothMsg_RequestDeviceSuccess(thread_id, request_id,
                                                  device_ipc));
       request_device_sessions_.erase(session);
       return;
     }
   }
   RecordRequestDeviceOutcome(
       UMARequestDeviceOutcome::NO_MATCHING_DEVICES_FOUND);
+  VLOG(1) << "No matching Bluetooth Devices found";
   Send(new BluetoothMsg_RequestDeviceError(thread_id, request_id,
                                            WebBluetoothError::NoDevicesFound));
   request_device_sessions_.erase(session);
 }
 
 void BluetoothDispatcherHost::OnDiscoverySessionStoppedError(int thread_id,
                                                              int request_id) {
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
   DLOG(WARNING) << "BluetoothDispatcherHost::OnDiscoverySessionStoppedError";
   RecordRequestDeviceOutcome(UMARequestDeviceOutcome::DISCOVERY_STOP_FAILED);
@@ skipping 82 matching lines @@
 
 void BluetoothDispatcherHost::OnWriteValueFailed(
     int thread_id,
     int request_id,
     device::BluetoothGattService::GattErrorCode error_code) {
   Send(new BluetoothMsg_WriteCharacteristicValueError(
       thread_id, request_id, TranslateGATTError(error_code)));
 }
 
 }  // namespace content