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..e36e66fde1a85d7c611a59f01bcd4ca1e97a24f3 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";

[Alexei Svitkine (slow), 2015/08/10 20:12:45]

Nit: const char kBaseStandardServiceUUID[] =

[ortuno, 2015/08/10 21:47:38]

Done.

+// Current Max Standard Service UUID:
+// https://developer.bluetooth.org/gatt/services/Pages/ServicesHome.aspx?SortField=AssignedNumber&SortDir=Asc
+const uint16_t kMaxStandardServiceUUID = 0x22;
+
 // 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,
+                                         kBaseStandardServiceUUID)  // 000018
+      ||
+      !service.canonical_value().compare(
+          8, 28, kBaseStandardServiceUUID))  // -0000-1000-8000-00805f9b34fb

[Alexei Svitkine (slow), 2015/08/10 20:12:45]

Nit: {}'s

[ortuno, 2015/08/10 21:47:38]

Done.

+    return 0;                                // Unknown Service
+
+  uint16_t serviceEnum = 0;
+  for (int i = 0; i < 2; i++) {
+    serviceEnum <<= 4;
+    serviceEnum += base::HexDigitToInt(service.canonical_value()[i + 6]);
+  }
+  if (serviceEnum > kMaxStandardServiceUUID) {
+    return 0;  // Unknown Service
+  }
+  // We shift everything by one because of the unknown service at 0.
+  return serviceEnum + 1;

[Alexei Svitkine (slow), 2015/08/10 20:12:45]

nit: hacker_style

[ortuno, 2015/08/10 21:47:38]

Done?

+}
+
+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), 0xFF);
+    }
+  }
+}
+
+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), 0xFF);

[Alexei Svitkine (slow), 2015/08/10 20:12:45]

Why is the max value 0xFF?

[ortuno, 2015/08/10 21:47:38]

Changed it to 0x101. Standard Service UUIDs are between 0x1800 and 0x18FF but we
only histogram the last two digits and since we shift everything by 1 the max
value becomes 0x101.

+  }
+}
+
+void RecordUnionOfServices(
+    const std::vector<content::BluetoothScanFilter>& filters,
+    const std::vector<BluetoothUUID>& optional_services) {
+  const std::set<BluetoothUUID> unionOfServices(optional_services.begin(),

[Alexei Svitkine (slow), 2015/08/10 20:12:45]

Nit: camel_case

[ortuno, 2015/08/10 21:47:38]

Done.

+                                                optional_services.end());
+  for (const content::BluetoothScanFilter& filter : filters)
+    unionOfServices.insert(filter.services.begin(), filter.services.end());
+
+  UMA_HISTOGRAM_COUNTS("Bluetooth.Web.RequestDevice.UnionOfServices.Count",
+                       unionOfServices.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: ";

[Alexei Svitkine (slow), 2015/08/10 20:12:45]

VLOGs are generally discouraged (search chromium-dev), consider using DVLOG
instead of removing entirely from the CL.

[ortuno, 2015/08/10 21:47:38]

I read the email thread about VLOG. Since we are actively monitoring and
debugging problems with Web Bluetooth we are keeping the VLOGs. Eventually we
will add a about:bluetooth-devices page, but we suspect it might have a bigger
binary size impact than VLOGs. See: http://crbug.com/519010

+  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);