bluetooth: Add histograms and logging for requestDevice()

content/browser/bluetooth/bluetooth_dispatcher_host.cc

Index: content/browser/bluetooth/bluetooth_dispatcher_host.cc
diff --git a/content/browser/bluetooth/bluetooth_dispatcher_host.cc b/content/browser/bluetooth/bluetooth_dispatcher_host.cc
index eff5a668cd974e6058511b2e8bb560725439700c..7e22d2f7522003f81d7da44a930515b201acf115 100644
--- a/content/browser/bluetooth/bluetooth_dispatcher_host.cc
+++ b/content/browser/bluetooth/bluetooth_dispatcher_host.cc
@@ -11,6 +11,7 @@
 #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"
@@ -31,6 +32,11 @@ 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 {
@@ -58,11 +64,68 @@ enum class UMARequestDeviceOutcome {
 };
 
 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,
@@ -271,14 +334,28 @@ void BluetoothDispatcherHost::OnRequestDevice(
     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));
@@ -329,7 +406,7 @@ void BluetoothDispatcherHost::OnRequestDevice(
         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));
@@ -613,6 +690,10 @@ void BluetoothDispatcherHost::OnDiscoverySessionStopped(int thread_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
@@ -634,6 +715,7 @@ void BluetoothDispatcherHost::OnDiscoverySessionStopped(int thread_id,
   }
   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);