device/bluetooth: log WinRT API calls to chrome://device-log

We have been debugging various FIDO caBLE related issues that often only
appear sporadically on a particular combination of (computer, OS
version, phone). In some of them, WinRT behaving in exciting and
unexpected ways was at least a contributing factor. The WinRT Bluetooth
code currently VLOGs, which makes it difficult to obtain logs in these
cases. Replace them with BLUETOOTH_LOG(), which can easily be collected
by end users after the fact.

These log statements can be converted to DVLOG once the WinRT Bluetooth
and FIDO caBLE stacks have sufficiently stabilized.

Change-Id: Id13f9e107167ecdc3e0230aee86ecf90219697d5
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2021331
Commit-Queue: Martin Kreichgauer <martinkr@google.com>
Reviewed-by: Giovanni Ortuño Urquidi <ortuno@chromium.org>
Cr-Commit-Position: refs/heads/master@{#737149}

device/bluetooth/bluetooth_remote_gatt_descriptor_winrt.cc

@@ -13,6 +13,7 @@
 #include "base/threading/thread_task_runner_handle.h"
 #include "base/win/post_async_results.h"
 #include "base/win/winrt_storage_util.h"
+#include "components/device_event_log/device_event_log.h"
 #include "device/bluetooth/bluetooth_remote_gatt_service_winrt.h"
 #include "device/bluetooth/event_utils_winrt.h"
 
@@ -53,15 +54,16 @@ BluetoothRemoteGattDescriptorWinrt::Create(
   GUID guid;
   HRESULT hr = descriptor->get_Uuid(&guid);
   if (FAILED(hr)) {
-    VLOG(2) << "Getting UUID failed: " << logging::SystemErrorCodeToString(hr);
+    BLUETOOTH_LOG(ERROR) << "Getting UUID failed: "
+                         << logging::SystemErrorCodeToString(hr);
     return nullptr;
   }
 
   uint16_t attribute_handle;
   hr = descriptor->get_AttributeHandle(&attribute_handle);
   if (FAILED(hr)) {
-    VLOG(2) << "Getting AttributeHandle failed: "
-            << logging::SystemErrorCodeToString(hr);
+    BLUETOOTH_LOG(ERROR) << "Getting AttributeHandle failed: "
+                         << logging::SystemErrorCodeToString(hr);
     return nullptr;
   }
 
@@ -112,8 +114,9 @@ void BluetoothRemoteGattDescriptorWinrt::ReadRemoteDescriptor(
   HRESULT hr = descriptor_->ReadValueWithCacheModeAsync(
       BluetoothCacheMode_Uncached, &read_value_op);
   if (FAILED(hr)) {
-    VLOG(2) << "GattDescriptor::ReadValueWithCacheModeAsync failed: "
-            << logging::SystemErrorCodeToString(hr);
+    BLUETOOTH_LOG(ERROR)
+        << "GattDescriptor::ReadValueWithCacheModeAsync failed: "
+        << logging::SystemErrorCodeToString(hr);
     base::ThreadTaskRunnerHandle::Get()->PostTask(
         FROM_HERE,
         base::BindOnce(std::move(error_callback),
@@ -127,8 +130,8 @@ void BluetoothRemoteGattDescriptorWinrt::ReadRemoteDescriptor(
                      weak_ptr_factory_.GetWeakPtr()));
 
   if (FAILED(hr)) {
-    VLOG(2) << "PostAsyncResults failed: "
-            << logging::SystemErrorCodeToString(hr);
+    BLUETOOTH_LOG(ERROR) << "PostAsyncResults failed: "
+                         << logging::SystemErrorCodeToString(hr);
     base::ThreadTaskRunnerHandle::Get()->PostTask(
         FROM_HERE,
         base::BindOnce(std::move(error_callback),
@@ -155,8 +158,8 @@ void BluetoothRemoteGattDescriptorWinrt::WriteRemoteDescriptor(
   ComPtr<IGattDescriptor2> descriptor_2;
   HRESULT hr = descriptor_.As(&descriptor_2);
   if (FAILED(hr)) {
-    VLOG(2) << "As IGattDescriptor2 failed: "
-            << logging::SystemErrorCodeToString(hr);
+    BLUETOOTH_LOG(ERROR) << "As IGattDescriptor2 failed: "
+                         << logging::SystemErrorCodeToString(hr);
     base::ThreadTaskRunnerHandle::Get()->PostTask(
         FROM_HERE,
         base::BindOnce(std::move(error_callback),
@@ -167,8 +170,8 @@ void BluetoothRemoteGattDescriptorWinrt::WriteRemoteDescriptor(
   ComPtr<IBuffer> buffer;
   hr = base::win::CreateIBufferFromData(value.data(), value.size(), &buffer);
   if (FAILED(hr)) {
-    VLOG(2) << "base::win::CreateIBufferFromData failed: "
-            << logging::SystemErrorCodeToString(hr);
+    BLUETOOTH_LOG(ERROR) << "base::win::CreateIBufferFromData failed: "
+                         << logging::SystemErrorCodeToString(hr);
     base::ThreadTaskRunnerHandle::Get()->PostTask(
         FROM_HERE,
         base::BindOnce(std::move(error_callback),
@@ -179,8 +182,8 @@ void BluetoothRemoteGattDescriptorWinrt::WriteRemoteDescriptor(
   ComPtr<IAsyncOperation<GattWriteResult*>> write_value_op;
   hr = descriptor_2->WriteValueWithResultAsync(buffer.Get(), &write_value_op);
   if (FAILED(hr)) {
-    VLOG(2) << "GattDescriptor::WriteValueWithResultAsync failed: "
-            << logging::SystemErrorCodeToString(hr);
+    BLUETOOTH_LOG(ERROR) << "GattDescriptor::WriteValueWithResultAsync failed: "
+                         << logging::SystemErrorCodeToString(hr);
     base::ThreadTaskRunnerHandle::Get()->PostTask(
         FROM_HERE,
         base::BindOnce(std::move(error_callback),
@@ -195,8 +198,8 @@ void BluetoothRemoteGattDescriptorWinrt::WriteRemoteDescriptor(
           weak_ptr_factory_.GetWeakPtr()));
 
   if (FAILED(hr)) {
-    VLOG(2) << "PostAsyncResults failed: "
-            << logging::SystemErrorCodeToString(hr);
+    BLUETOOTH_LOG(ERROR) << "PostAsyncResults failed: "
+                         << logging::SystemErrorCodeToString(hr);
     base::ThreadTaskRunnerHandle::Get()->PostTask(
         FROM_HERE,
         base::BindOnce(std::move(error_callback),
@@ -251,6 +254,8 @@ void BluetoothRemoteGattDescriptorWinrt::OnReadValue(
   auto pending_read_callbacks = std::move(pending_read_callbacks_);
 
   if (!read_result) {
+    BLUETOOTH_LOG(ERROR)
+        << "GattDescriptor::ReadValueWithCacheModeAsync returned no result";
     std::move(pending_read_callbacks->error_callback)
         .Run(BluetoothGattService::GATT_ERROR_FAILED);
     return;
@@ -259,20 +264,20 @@ void BluetoothRemoteGattDescriptorWinrt::OnReadValue(
   GattCommunicationStatus status;
   HRESULT hr = read_result->get_Status(&status);
   if (FAILED(hr)) {
-    VLOG(2) << "Getting GATT Communication Status failed: "
-            << logging::SystemErrorCodeToString(hr);
+    BLUETOOTH_LOG(ERROR) << "Getting GATT Communication Status failed: "
+                         << logging::SystemErrorCodeToString(hr);
     std::move(pending_read_callbacks->error_callback)
         .Run(BluetoothGattService::GATT_ERROR_FAILED);
     return;
   }
 
   if (status != GattCommunicationStatus_Success) {
-    VLOG(2) << "Unexpected GattCommunicationStatus: " << status;
+    BLUETOOTH_LOG(ERROR) << "Unexpected GattCommunicationStatus: " << status;
     ComPtr<IGattReadResult2> read_result_2;
     hr = read_result.As(&read_result_2);
     if (FAILED(hr)) {
-      VLOG(2) << "As IGattReadResult2 failed: "
-              << logging::SystemErrorCodeToString(hr);
+      BLUETOOTH_LOG(ERROR) << "As IGattReadResult2 failed: "
+                           << logging::SystemErrorCodeToString(hr);
       std::move(pending_read_callbacks->error_callback)
           .Run(BluetoothGattService::GATT_ERROR_FAILED);
       return;
@@ -287,8 +292,8 @@ void BluetoothRemoteGattDescriptorWinrt::OnReadValue(
   ComPtr<IBuffer> value;
   hr = read_result->get_Value(&value);
   if (FAILED(hr)) {
-    VLOG(2) << "Getting Descriptor Value failed: "
-            << logging::SystemErrorCodeToString(hr);
+    BLUETOOTH_LOG(ERROR) << "Getting Descriptor Value failed: "
+                         << logging::SystemErrorCodeToString(hr);
     std::move(pending_read_callbacks->error_callback)
         .Run(BluetoothGattService::GATT_ERROR_FAILED);
     return;
@@ -298,8 +303,8 @@ void BluetoothRemoteGattDescriptorWinrt::OnReadValue(
   uint32_t length = 0;
   hr = base::win::GetPointerToBufferData(value.Get(), &data, &length);
   if (FAILED(hr)) {
-    VLOG(2) << "Getting Pointer To Buffer Data failed: "
-            << logging::SystemErrorCodeToString(hr);
+    BLUETOOTH_LOG(ERROR) << "Getting Pointer To Buffer Data failed: "
+                         << logging::SystemErrorCodeToString(hr);
     std::move(pending_read_callbacks->error_callback)
         .Run(BluetoothGattService::GATT_ERROR_FAILED);
     return;
@@ -315,6 +320,8 @@ void BluetoothRemoteGattDescriptorWinrt::OnWriteValueWithResult(
   auto pending_write_callbacks = std::move(pending_write_callbacks_);
 
   if (!write_result) {
+    BLUETOOTH_LOG(ERROR)
+        << "GattDescriptor::WriteValueWithResultAsync returned no result";
     std::move(pending_write_callbacks->error_callback)
         .Run(BluetoothGattService::GATT_ERROR_FAILED);
     return;
@@ -323,15 +330,15 @@ void BluetoothRemoteGattDescriptorWinrt::OnWriteValueWithResult(
   GattCommunicationStatus status;
   HRESULT hr = write_result->get_Status(&status);
   if (FAILED(hr)) {
-    VLOG(2) << "Getting GATT Communication Status failed: "
-            << logging::SystemErrorCodeToString(hr);
+    BLUETOOTH_LOG(ERROR) << "Getting GATT Communication Status failed: "
+                         << logging::SystemErrorCodeToString(hr);
     std::move(pending_write_callbacks->error_callback)
         .Run(BluetoothGattService::GATT_ERROR_FAILED);
     return;
   }
 
   if (status != GattCommunicationStatus_Success) {
-    VLOG(2) << "Unexpected GattCommunicationStatus: " << status;
+    BLUETOOTH_LOG(ERROR) << "Unexpected GattCommunicationStatus: " << status;
     std::move(pending_write_callbacks->error_callback)
         .Run(BluetoothRemoteGattServiceWinrt::GetGattErrorCode(
             write_result.Get()));