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

[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 {
   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,
+                                         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,
   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: ";

[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));
   }
 
   // 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