bluetooth: update bluetooth_dispatcher_host VLOG to BLUETOOTH_LOG

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.
 
 // ID Not In Map Note:
 // A service, characteristic, or descriptor ID not in the corresponding
 // BluetoothDispatcherHost map [service_to_device_, characteristic_to_service_,
 // descriptor_to_characteristic_] implies a hostile renderer because a renderer
 // obtains the corresponding ID from this class and it will be added to the map
 // at that time.
 
 #include "content/browser/bluetooth/bluetooth_dispatcher_host.h"
 
 #include <stddef.h>
 
 #include <utility>
 
 #include "base/bind.h"
 #include "base/single_thread_task_runner.h"
 #include "base/strings/utf_string_conversions.h"
 #include "base/thread_task_runner_handle.h"
+#include "components/device_event_log/device_event_log.h"
 #include "content/browser/bad_message.h"
 #include "content/browser/bluetooth/bluetooth_metrics.h"
 #include "content/browser/bluetooth/first_device_bluetooth_chooser.h"
 #include "content/browser/frame_host/render_frame_host_impl.h"
 #include "content/common/bluetooth/bluetooth_messages.h"
 #include "content/public/browser/web_contents.h"
 #include "content/public/browser/web_contents_delegate.h"
 #include "device/bluetooth/bluetooth_adapter.h"
 #include "device/bluetooth/bluetooth_adapter_factory.h"
 #include "device/bluetooth/bluetooth_device.h"
@@ skipping 38 matching lines @@
 
 // Defined at
 // https://webbluetoothchrome.github.io/web-bluetooth/#dfn-matches-a-filter
 bool MatchesFilter(const device::BluetoothDevice& device,
                    const content::BluetoothScanFilter& filter) {
   DCHECK(!IsEmptyOrInvalidFilter(filter));
 
   const std::string device_name = base::UTF16ToUTF8(device.GetName());
 
   if (!filter.name.empty() && (device_name != filter.name)) {
       return false;

[ortuno, 2016/01/27 19:15:36]

Hmm I wonder if we should log these so that we know why a device isn't showing
up for someone.

[ortuno, 2016/01/27 19:15:36]

Hmm I wonder if we should log these so that we know why a device isn't showing
up for someone.

[fbeaufortchromium, 2016/01/28 08:46:52]

I've added BLUETOOTH_LOG(DEBUG) for all filters.

   }
 
   if (!filter.namePrefix.empty() &&
       (!base::StartsWith(device_name, filter.namePrefix,
                          base::CompareCase::SENSITIVE))) {
     return false;
   }
 
   if (!filter.services.empty()) {
     const auto& device_uuid_list = device.GetUUIDs();
@@ skipping 123 matching lines @@
   discovery_session->Stop(base::Bind(&base::DoNothing),
                           base::Bind(&base::DoNothing));
 }
 
 // TODO(ortuno): This should really be a BluetoothDevice method.
 // Replace when implemented. http://crbug.com/552022
 std::vector<BluetoothGattService*> GetPrimaryServicesByUUID(
     device::BluetoothDevice* device,
     const std::string& service_uuid) {
   std::vector<BluetoothGattService*> services;
-  VLOG(1) << "Looking for service: " << service_uuid;
+  BLUETOOTH_LOG(EVENT) << "Looking for service: " << service_uuid;
   for (BluetoothGattService* service : device->GetGattServices()) {
-    VLOG(1) << "Service in cache: " << service->GetUUID().canonical_value();
+    BLUETOOTH_LOG(EVENT) << "Service in cache: "
+                         << service->GetUUID().canonical_value();
     if (service->GetUUID().canonical_value() == service_uuid &&
         service->IsPrimary()) {
       services.push_back(service);
     }
   }
   return services;
 }
 
 }  //  namespace
 
@@ skipping 219 matching lines @@
         session->ComputeScanFilter(),
         base::Bind(&BluetoothDispatcherHost::OnDiscoverySessionStarted,
                    weak_ptr_on_ui_thread_, chooser_id),
         base::Bind(&BluetoothDispatcherHost::OnDiscoverySessionStartedError,
                    weak_ptr_on_ui_thread_, chooser_id));
   }
 }
 
 void BluetoothDispatcherHost::StopDeviceDiscovery() {
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
   for (IDMap<RequestDeviceSession, IDMapOwnPointer>::iterator iter(

[ortuno, 2016/01/27 19:15:36]

Can you add a log statement here? Something like: Stopping discovery session.

[fbeaufortchromium, 2016/01/28 08:46:52]

Done.

            &request_device_sessions_);
        !iter.IsAtEnd(); iter.Advance()) {
     RequestDeviceSession* session = iter.GetCurrentValue();
     if (session->discovery_session) {
       StopDiscoverySession(std::move(session->discovery_session));
     }
     if (session->chooser) {
       session->chooser->ShowDiscoveryState(
           BluetoothChooser::DiscoveryState::IDLE);
     }
@@ skipping 12 matching lines @@
        !iter.IsAtEnd(); iter.Advance()) {
     RequestDeviceSession* session = iter.GetCurrentValue();
     if (session->chooser)
       session->chooser->SetAdapterPresence(presence);
   }
 }
 
 void BluetoothDispatcherHost::DeviceAdded(device::BluetoothAdapter* adapter,
                                           device::BluetoothDevice* device) {
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
-  VLOG(1) << "Adding device to all choosers: " << device->GetAddress();
+  BLUETOOTH_LOG(EVENT) << "Adding device to all choosers: "
+                       << device->GetAddress();
   for (IDMap<RequestDeviceSession, IDMapOwnPointer>::iterator iter(
            &request_device_sessions_);
        !iter.IsAtEnd(); iter.Advance()) {
     RequestDeviceSession* session = iter.GetCurrentValue();
     session->AddFilteredDevice(*device);
   }
 }
 
 void BluetoothDispatcherHost::DeviceRemoved(device::BluetoothAdapter* adapter,
                                             device::BluetoothDevice* device) {
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
-  VLOG(1) << "Marking device removed on all choosers: " << device->GetAddress();
+  BLUETOOTH_LOG(EVENT) << "Marking device removed on all choosers: "
+                       << device->GetAddress();
   for (IDMap<RequestDeviceSession, IDMapOwnPointer>::iterator iter(
            &request_device_sessions_);
        !iter.IsAtEnd(); iter.Advance()) {
     RequestDeviceSession* session = iter.GetCurrentValue();
     if (session->chooser) {
       session->chooser->RemoveDevice(device->GetAddress());
     }
   }
 }
 
 void BluetoothDispatcherHost::GattServicesDiscovered(
     device::BluetoothAdapter* adapter,
     device::BluetoothDevice* device) {
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
   const std::string& device_address = device->GetAddress();
-  VLOG(1) << "Services discovered for device: " << device_address;
+  BLUETOOTH_LOG(EVENT) << "Services discovered for device: " << device_address;
 
   auto iter = pending_primary_services_requests_.find(device_address);
   if (iter == pending_primary_services_requests_.end()) {
     return;
   }
   std::vector<PrimaryServicesRequest> requests;
   requests.swap(iter->second);
   pending_primary_services_requests_.erase(iter);
 
   for (const PrimaryServicesRequest& request : requests) {
     std::vector<BluetoothGattService*> services =
         GetPrimaryServicesByUUID(device, request.service_uuid);
     switch (request.func) {
       case PrimaryServicesRequest::GET_PRIMARY_SERVICE:
         if (!services.empty()) {
           AddToServicesMapAndSendGetPrimaryServiceSuccess(
               *services[0], request.thread_id, request.request_id);
         } else {
-          VLOG(1) << "No service found";
+          BLUETOOTH_LOG(EVENT) << "No service found";
           RecordGetPrimaryServiceOutcome(
               UMAGetPrimaryServiceOutcome::NOT_FOUND);
           Send(new BluetoothMsg_GetPrimaryServiceError(
               request.thread_id, request.request_id,
               WebBluetoothError::ServiceNotFound));
         }
         break;
       case PrimaryServicesRequest::GET_PRIMARY_SERVICES:
         NOTIMPLEMENTED();
         break;
     }
   }
   DCHECK(!ContainsKey(pending_primary_services_requests_, device_address))
       << "Sending get-service responses unexpectedly queued another request.";
 }
 
 void BluetoothDispatcherHost::GattCharacteristicValueChanged(
     device::BluetoothAdapter* adapter,
     device::BluetoothGattCharacteristic* characteristic,
     const std::vector<uint8_t>& value) {
-  VLOG(1) << "Characteristic updated: " << characteristic->GetIdentifier();
+  BLUETOOTH_LOG(EVENT) << "Characteristic updated: "
+                       << characteristic->GetIdentifier();
   auto iter =
       active_characteristic_threads_.find(characteristic->GetIdentifier());
 
   if (iter == active_characteristic_threads_.end()) {
     return;
   }
 
   for (int thread_id : iter->second) {
     // Yield to the event loop so that the event gets dispatched after the
     // readValue promise resolves.
@@ skipping 21 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);
   RecordRequestDeviceArguments(filters, optional_services);
 
-  VLOG(1) << "requestDevice called with the following filters: ";
+  BLUETOOTH_LOG(USER) << "requestDevice called with the following filters: ";
   for (const BluetoothScanFilter& filter : filters) {
-    VLOG(1) << "Name: " << filter.name;
-    VLOG(1) << "Name Prefix: " << filter.namePrefix;
-    VLOG(1) << "Services:";
-    VLOG(1) << "\t[";
+    BLUETOOTH_LOG(USER) << "Name: " << filter.name;
+    BLUETOOTH_LOG(USER) << "Name Prefix: " << filter.namePrefix;
+    BLUETOOTH_LOG(USER) << "Services:";
+    BLUETOOTH_LOG(USER) << "\t[";
     for (const BluetoothUUID& service : filter.services)
-      VLOG(1) << "\t\t" << service.value();
-    VLOG(1) << "\t]";
+      BLUETOOTH_LOG(USER) << "\t\t" << service.value();
+    BLUETOOTH_LOG(USER) << "\t]";
   }
 
-  VLOG(1) << "requestDevice called with the following optional services: ";
+  BLUETOOTH_LOG(USER)
+      << "requestDevice called with the following optional services: ";
   for (const BluetoothUUID& service : optional_services)
-    VLOG(1) << "\t" << service.value();
+    BLUETOOTH_LOG(USER) << "\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;
     RecordRequestDeviceOutcome(UMARequestDeviceOutcome::NO_RENDER_FRAME);
     Send(new BluetoothMsg_RequestDeviceError(
         thread_id, request_id, WebBluetoothError::RequestDeviceWithoutFrame));
     return;
   }
 
   if (!adapter_) {
-    VLOG(1) << "No BluetoothAdapter. Can't serve requestDevice.";
+    BLUETOOTH_LOG(EVENT) << "No BluetoothAdapter. Can't serve requestDevice.";
     RecordRequestDeviceOutcome(UMARequestDeviceOutcome::NO_BLUETOOTH_ADAPTER);
     Send(new BluetoothMsg_RequestDeviceError(
         thread_id, request_id, WebBluetoothError::NoBluetoothAdapter));
     return;
   }
 
   if (!adapter_->IsPresent()) {
-    VLOG(1) << "Bluetooth Adapter not present. Can't serve requestDevice.";
+    BLUETOOTH_LOG(EVENT)
+        << "Bluetooth Adapter not present. Can't serve requestDevice.";
     RecordRequestDeviceOutcome(
         UMARequestDeviceOutcome::BLUETOOTH_ADAPTER_NOT_PRESENT);
     Send(new BluetoothMsg_RequestDeviceError(
         thread_id, request_id, WebBluetoothError::NoBluetoothAdapter));
     return;
   }
 
   // The renderer should never send empty filters.
   if (HasEmptyOrInvalidFilter(filters)) {
     bad_message::ReceivedBadMessage(this,
@@ skipping 15 matching lines @@
           WebContents::FromRenderFrameHost(render_frame_host)) {
     if (WebContentsDelegate* delegate = web_contents->GetDelegate()) {
       session->chooser = delegate->RunBluetoothChooser(
           web_contents, chooser_event_handler,
           // TODO(ortuno): Replace with GetLastCommittedOrigin.
           // http://crbug.com/577451
           render_frame_host->GetLastCommittedURL().GetOrigin());
     }
   }
   if (!session->chooser) {
-    LOG(WARNING)
+    BLUETOOTH_LOG(EVENT)
         << "No Bluetooth chooser implementation; falling back to first device.";
     session->chooser.reset(
         new FirstDeviceBluetoothChooser(chooser_event_handler));
   }
 
   if (!session->chooser->CanAskForScanningPermission()) {
-    VLOG(1) << "Closing immediately because Chooser cannot obtain permission.";
+    BLUETOOTH_LOG(EVENT)
+        << "Closing immediately because Chooser cannot obtain permission.";
     OnBluetoothChooserEvent(chooser_id,
                             BluetoothChooser::Event::DENIED_PERMISSION, "");
     return;
   }
 
   // Populate the initial list of devices.
-  VLOG(1) << "Populating " << adapter_->GetDevices().size()
-          << " devices in chooser " << chooser_id;
+  BLUETOOTH_LOG(EVENT) << "Populating " << adapter_->GetDevices().size()
+                       << " devices in chooser " << chooser_id;
   for (const device::BluetoothDevice* device : adapter_->GetDevices()) {
-    VLOG(1) << "\t" << device->GetAddress();
+    BLUETOOTH_LOG(EVENT) << "\t" << device->GetAddress();
     session->AddFilteredDevice(*device);
   }
 
   if (!session->chooser) {
     // If the dialog's closing, no need to do any of the rest of this.
     return;
   }
 
   if (!adapter_->IsPowered()) {
     session->chooser->SetAdapterPresence(
@@ skipping 19 matching lines @@
     RecordConnectGATTOutcome(query_result.outcome);
     Send(new BluetoothMsg_ConnectGATTError(thread_id, request_id,
                                            query_result.GetWebError()));
     return;
   }
 
   // If we are already connected no need to connect again.
   auto connection_iter = device_id_to_connection_map_.find(device_id);
   if (connection_iter != device_id_to_connection_map_.end()) {
     if (connection_iter->second->IsConnected()) {
-      VLOG(1) << "Already connected.";
+      BLUETOOTH_LOG(EVENT) << "Already connected.";
       Send(new BluetoothMsg_ConnectGATTSuccess(thread_id, request_id,
                                                device_id));
       return;
     }
   }
 
   query_result.device->CreateGattConnection(
       base::Bind(&BluetoothDispatcherHost::OnGATTConnectionCreated,
                  weak_ptr_on_ui_thread_, thread_id, request_id, device_id,
                  start_time),
@@ skipping 16 matching lines @@
                                             device_id)
           .empty()) {
     bad_message::ReceivedBadMessage(
         this, bad_message::BDH_DEVICE_NOT_ALLOWED_FOR_ORIGIN);
     return;
   }
 
   // The last BluetoothGattConnection for a device closes the connection when
   // it's destroyed.
   if (device_id_to_connection_map_.erase(device_id)) {
-    VLOG(1) << "Disconnecting device: " << device_id;
+    BLUETOOTH_LOG(EVENT) << "Disconnecting device: " << device_id;
   }
 }
 
 void BluetoothDispatcherHost::OnGetPrimaryService(
     int thread_id,
     int request_id,
     int frame_routing_id,
     const std::string& device_id,
     const std::string& service_uuid) {
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
@@ skipping 21 matching lines @@
   // 3. Services discovered and service not present in |device|: Send back not
   //    found error.
   // 4. Services not discovered and service not present in |device|: Add request
   //    to map of pending getPrimaryService requests.
 
   std::vector<BluetoothGattService*> services =
       GetPrimaryServicesByUUID(query_result.device, service_uuid);
 
   // 1. & 2.
   if (!services.empty()) {
-    VLOG(1) << "Service found in device.";
+    BLUETOOTH_LOG(EVENT) << "Service found in device.";
     const BluetoothGattService& service = *services[0];
     DCHECK(service.IsPrimary());
     AddToServicesMapAndSendGetPrimaryServiceSuccess(service, thread_id,
                                                     request_id);
     return;
   }
 
   // 3.
   if (query_result.device->IsGattServicesDiscoveryComplete()) {
-    VLOG(1) << "Service not found in device.";
+    BLUETOOTH_LOG(EVENT) << "Service not found in device.";
     RecordGetPrimaryServiceOutcome(UMAGetPrimaryServiceOutcome::NOT_FOUND);
     Send(new BluetoothMsg_GetPrimaryServiceError(
         thread_id, request_id, WebBluetoothError::ServiceNotFound));
     return;
   }
 
-  VLOG(1) << "Adding service request to pending requests.";
+  BLUETOOTH_LOG(EVENT) << "Adding service request to pending requests.";
   // 4.
   AddToPendingPrimaryServicesRequest(
       query_result.device->GetAddress(),
       PrimaryServicesRequest(thread_id, request_id, service_uuid,
                              PrimaryServicesRequest::GET_PRIMARY_SERVICE));
 }
 
 void BluetoothDispatcherHost::OnGetCharacteristic(
     int thread_id,
     int request_id,
@@ skipping 215 matching lines @@
   thread_ids_set.erase(thread_id);
   if (thread_ids_set.empty()) {
     active_characteristic_threads_.erase(active_iter);
   }
 }
 
 void BluetoothDispatcherHost::OnDiscoverySessionStarted(
     int chooser_id,
     scoped_ptr<device::BluetoothDiscoverySession> discovery_session) {
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
-  VLOG(1) << "Started discovery session for " << chooser_id;
+  BLUETOOTH_LOG(EVENT) << "Started discovery session for " << chooser_id;
   if (RequestDeviceSession* session =
           request_device_sessions_.Lookup(chooser_id)) {
     session->discovery_session = std::move(discovery_session);
 
     // Arrange to stop discovery later.
     discovery_session_timer_.Reset();
   } else {
-    VLOG(1) << "Chooser " << chooser_id
-            << " was closed before the session finished starting. Stopping.";
+    BLUETOOTH_LOG(EVENT)
+        << "Chooser " << chooser_id
+        << " was closed before the session finished starting. Stopping.";
     StopDiscoverySession(std::move(discovery_session));
   }
 }
 
 void BluetoothDispatcherHost::OnDiscoverySessionStartedError(int chooser_id) {
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
-  VLOG(1) << "Failed to start discovery session for " << chooser_id;
+  BLUETOOTH_LOG(EVENT) << "Failed to start discovery session for "
+                       << chooser_id;
   if (RequestDeviceSession* session =
           request_device_sessions_.Lookup(chooser_id)) {
     if (session->chooser && !session->discovery_session) {
       session->chooser->ShowDiscoveryState(
           BluetoothChooser::DiscoveryState::FAILED_TO_START);
     }
   }
   // Ignore discovery session start errors when the dialog was already closed by
   // the time they happen.
 }
@@ skipping 50 matching lines @@
     int chooser_id,
     BluetoothChooser::Event event,
     const std::string& device_id) {
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
   RequestDeviceSession* session = request_device_sessions_.Lookup(chooser_id);
   DCHECK(session) << "Session removed unexpectedly.";
 
   if (event == BluetoothChooser::Event::CANCELLED) {
     RecordRequestDeviceOutcome(
         UMARequestDeviceOutcome::BLUETOOTH_CHOOSER_CANCELLED);
-    VLOG(1) << "Bluetooth chooser cancelled";
+    BLUETOOTH_LOG(EVENT) << "Bluetooth chooser cancelled";
     Send(new BluetoothMsg_RequestDeviceError(
         session->thread_id, session->request_id,
         WebBluetoothError::ChooserCancelled));
     request_device_sessions_.Remove(chooser_id);
     return;
   }
   if (event == BluetoothChooser::Event::DENIED_PERMISSION) {
     RecordRequestDeviceOutcome(
         UMARequestDeviceOutcome::BLUETOOTH_CHOOSER_DENIED_PERMISSION);
-    VLOG(1) << "Bluetooth chooser denied permission";
+    BLUETOOTH_LOG(EVENT) << "Bluetooth chooser denied permission";
     Send(new BluetoothMsg_RequestDeviceError(
         session->thread_id, session->request_id,
         WebBluetoothError::ChooserDeniedPermission));
     request_device_sessions_.Remove(chooser_id);
     return;
   }
   DCHECK_EQ(static_cast<int>(event),
             static_cast<int>(BluetoothChooser::Event::SELECTED));
 
   // |device_id| is the Device Address that RequestDeviceSession passed to
   // chooser->AddDevice().
   const device::BluetoothDevice* const device = adapter_->GetDevice(device_id);
   if (device == nullptr) {
-    VLOG(1) << "Device " << device_id << " no longer in adapter";
+    BLUETOOTH_LOG(EVENT) << "Device " << device_id << " no longer in adapter";
     RecordRequestDeviceOutcome(UMARequestDeviceOutcome::CHOSEN_DEVICE_VANISHED);
     Send(new BluetoothMsg_RequestDeviceError(
         session->thread_id, session->request_id,
         WebBluetoothError::ChosenDeviceVanished));
     request_device_sessions_.Remove(chooser_id);
     return;
   }
 
-  VLOG(1) << "Device: " << device->GetName();
-  VLOG(1) << "UUIDs: ";
+  BLUETOOTH_LOG(EVENT) << "Device: " << device->GetName();
+  BLUETOOTH_LOG(EVENT) << "UUIDs: ";
   for (BluetoothUUID uuid : device->GetUUIDs())
-    VLOG(1) << "\t" << uuid.canonical_value();
+    BLUETOOTH_LOG(EVENT) << "\t" << uuid.canonical_value();
 
   const std::string& device_id_for_origin = allowed_devices_map_.AddDevice(
       session->origin, device->GetAddress(), session->filters,
       session->optional_services);
 
   content::BluetoothDevice device_ipc(
       device_id_for_origin,  // id
       device->GetName(),     // name
       content::BluetoothDevice::ValidatePower(
           device->GetInquiryTxPower()),  // tx_power
@@ skipping 253 matching lines @@
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
   NOTIMPLEMENTED();
 }
 
 void BluetoothDispatcherHost::ShowNeedLocationLink() {
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
   NOTIMPLEMENTED();
 }
 
 }  // namespace content