Log device/hid messages to chrome://device-log.

Log events and debugging information related to HID devices through the
device event log component so that these errors are visible at
chrome://device-log. A DEVICE_PLOG macro has been added which includes
the last reported system error in the log message.

BUG=448901

Review URL: https://codereview.chromium.org/947663002

Cr-Commit-Position: refs/heads/master@{#317722}

10 files changed, 84 insertions, 56 deletions

diff --git a/device/hid/BUILD.gn b/device/hid/BUILD.gn
index 64e99c4..b037573 100644
--- a/device/hid/BUILD.gn
+++ b/device/hid/BUILD.gn
@@ -42,6 +42,7 @@ source_set("hid") {
 
   deps = [
     "//base",
+    "//components/device_event_log",
     "//device/core",
     "//net",
   ]
diff --git a/device/hid/hid.gyp b/device/hid/hid.gyp
index 27ced27..42215d7 100644
--- a/device/hid/hid.gyp
+++ b/device/hid/hid.gyp
@@ -14,6 +14,8 @@
         '../..',
       ],
       'dependencies': [
+        '../../components/components.gyp:device_event_log_component',
+        '../../net/net.gyp:net',
         '../core/core.gyp:device_core',
       ],
       'sources': [
diff --git a/device/hid/hid_connection.cc b/device/hid/hid_connection.cc
index c43667a..208a565 100644
--- a/device/hid/hid_connection.cc
+++ b/device/hid/hid_connection.cc
@@ -6,6 +6,8 @@
 
 #include <algorithm>
 
+#include "components/device_event_log/device_event_log.h"
+
 namespace device {
 
 namespace {
@@ -82,7 +84,7 @@ void HidConnection::Close() {
 void HidConnection::Read(const ReadCallback& callback) {
   DCHECK(thread_checker_.CalledOnValidThread());
   if (device_info_->max_input_report_size() == 0) {
-    VLOG(1) << "This device does not support input reports.";
+    HID_LOG(USER) << "This device does not support input reports.";
     callback.Run(false, NULL, 0);
     return;
   }
@@ -95,25 +97,25 @@ void HidConnection::Write(scoped_refptr<net::IOBuffer> buffer,
                           const WriteCallback& callback) {
   DCHECK(thread_checker_.CalledOnValidThread());
   if (device_info_->max_output_report_size() == 0) {
-    VLOG(1) << "This device does not support output reports.";
+    HID_LOG(USER) << "This device does not support output reports.";
     callback.Run(false);
     return;
   }
   if (size > device_info_->max_output_report_size() + 1) {
-    VLOG(1) << "Output report buffer too long (" << size << " > "
-            << (device_info_->max_output_report_size() + 1) << ").";
+    HID_LOG(USER) << "Output report buffer too long (" << size << " > "
+                  << (device_info_->max_output_report_size() + 1) << ").";
     callback.Run(false);
     return;
   }
   DCHECK_GE(size, 1u);
   uint8_t report_id = buffer->data()[0];
   if (device_info_->has_report_id() != (report_id != 0)) {
-    VLOG(1) << "Invalid output report ID.";
+    HID_LOG(USER) << "Invalid output report ID.";
     callback.Run(false);
     return;
   }
   if (IsReportIdProtected(report_id)) {
-    VLOG(1) << "Attempt to set a protected output report.";
+    HID_LOG(USER) << "Attempt to set a protected output report.";
     callback.Run(false);
     return;
   }
@@ -125,17 +127,17 @@ void HidConnection::GetFeatureReport(uint8_t report_id,
                                      const ReadCallback& callback) {
   DCHECK(thread_checker_.CalledOnValidThread());
   if (device_info_->max_feature_report_size() == 0) {
-    VLOG(1) << "This device does not support feature reports.";
+    HID_LOG(USER) << "This device does not support feature reports.";
     callback.Run(false, NULL, 0);
     return;
   }
   if (device_info_->has_report_id() != (report_id != 0)) {
-    VLOG(1) << "Invalid feature report ID.";
+    HID_LOG(USER) << "Invalid feature report ID.";
     callback.Run(false, NULL, 0);
     return;
   }
   if (IsReportIdProtected(report_id)) {
-    VLOG(1) << "Attempt to get a protected feature report.";
+    HID_LOG(USER) << "Attempt to get a protected feature report.";
     callback.Run(false, NULL, 0);
     return;
   }
@@ -148,19 +150,19 @@ void HidConnection::SendFeatureReport(scoped_refptr<net::IOBuffer> buffer,
                                       const WriteCallback& callback) {
   DCHECK(thread_checker_.CalledOnValidThread());
   if (device_info_->max_feature_report_size() == 0) {
-    VLOG(1) << "This device does not support feature reports.";
+    HID_LOG(USER) << "This device does not support feature reports.";
     callback.Run(false);
     return;
   }
   DCHECK_GE(size, 1u);
   uint8_t report_id = buffer->data()[0];
   if (device_info_->has_report_id() != (report_id != 0)) {
-    VLOG(1) << "Invalid feature report ID.";
+    HID_LOG(USER) << "Invalid feature report ID.";
     callback.Run(false);
     return;
   }
   if (IsReportIdProtected(report_id)) {
-    VLOG(1) << "Attempt to set a protected feature report.";
+    HID_LOG(USER) << "Attempt to set a protected feature report.";
     callback.Run(false);
     return;
   }
@@ -174,7 +176,7 @@ bool HidConnection::CompleteRead(scoped_refptr<net::IOBuffer> buffer,
   DCHECK_GE(size, 1u);
   uint8_t report_id = buffer->data()[0];
   if (IsReportIdProtected(report_id)) {
-    VLOG(1) << "Filtered a protected input report.";
+    HID_LOG(EVENT) << "Filtered a protected input report.";
     return false;
   }
 
diff --git a/device/hid/hid_connection_linux.cc b/device/hid/hid_connection_linux.cc
index c653f4b..b2a2fc5 100644
--- a/device/hid/hid_connection_linux.cc
+++ b/device/hid/hid_connection_linux.cc
@@ -17,6 +17,7 @@
 #include "base/posix/eintr_wrapper.h"
 #include "base/thread_task_runner_handle.h"
 #include "base/threading/thread_restrictions.h"
+#include "components/device_event_log/device_event_log.h"
 #include "device/hid/hid_service.h"
 
 // These are already defined in newer versions of linux/hidraw.h.
@@ -57,7 +58,7 @@ class HidConnectionLinux::FileThreadHelper
     if (!base::MessageLoopForIO::current()->WatchFileDescriptor(
             platform_file_, true, base::MessageLoopForIO::WATCH_READ,
             &file_watcher_, this)) {
-      LOG(ERROR) << "Failed to start watching device file.";
+      HID_LOG(ERROR) << "Failed to start watching device file.";
     }
   }
 
@@ -80,7 +81,7 @@ class HidConnectionLinux::FileThreadHelper
     ssize_t bytes_read = HANDLE_EINTR(read(platform_file_, data, length));
     if (bytes_read < 0) {
       if (errno != EAGAIN) {
-        VPLOG(1) << "Read failed";
+        HID_PLOG(EVENT) << "Read failed";
         // This assumes that the error is unrecoverable and disables reading
         // from the device until it has been re-opened.
         // TODO(reillyg): Investigate starting and stopping the file descriptor
@@ -212,12 +213,12 @@ void HidConnectionLinux::FinishWrite(size_t expected_size,
                                      const WriteCallback& callback,
                                      ssize_t result) {
   if (result < 0) {
-    VPLOG(1) << "Write failed";
+    HID_PLOG(EVENT) << "Write failed";
     callback.Run(false);
   } else {
     if (static_cast<size_t>(result) != expected_size) {
-      LOG(WARNING) << "Incomplete HID write: " << result
-                   << " != " << expected_size;
+      HID_LOG(EVENT) << "Incomplete HID write: " << result
+                     << " != " << expected_size;
     }
     callback.Run(true);
   }
@@ -229,10 +230,10 @@ void HidConnectionLinux::FinishGetFeatureReport(
     const ReadCallback& callback,
     int result) {
   if (result < 0) {
-    VPLOG(1) << "Failed to get feature report";
+    HID_PLOG(EVENT) << "Failed to get feature report";
     callback.Run(false, NULL, 0);
   } else if (result == 0) {
-    VLOG(1) << "Get feature result too short.";
+    HID_LOG(EVENT) << "Get feature result too short.";
     callback.Run(false, NULL, 0);
   } else if (report_id == 0) {
     // Linux adds a 0 to the beginning of the data received from the device.
@@ -247,7 +248,7 @@ void HidConnectionLinux::FinishGetFeatureReport(
 void HidConnectionLinux::FinishSendFeatureReport(const WriteCallback& callback,
                                                  int result) {
   if (result < 0) {
-    VPLOG(1) << "Failed to send feature report";
+    HID_PLOG(EVENT) << "Failed to send feature report";
     callback.Run(false);
   } else {
     callback.Run(true);
diff --git a/device/hid/hid_connection_mac.cc b/device/hid/hid_connection_mac.cc
index fe485f7..de93cc6 100644
--- a/device/hid/hid_connection_mac.cc
+++ b/device/hid/hid_connection_mac.cc
@@ -10,10 +10,19 @@
 #include "base/single_thread_task_runner.h"
 #include "base/strings/stringprintf.h"
 #include "base/thread_task_runner_handle.h"
+#include "components/device_event_log/device_event_log.h"
 #include "device/hid/hid_connection_mac.h"
 
 namespace device {
 
+namespace {
+
+std::string HexErrorCode(IOReturn error_code) {
+  return base::StringPrintf("0x%04x", error_code);
+}
+
+}  // namespace
+
 HidConnectionMac::HidConnectionMac(
     IOHIDDeviceRef device,
     scoped_refptr<HidDeviceInfo> device_info,
@@ -59,8 +68,7 @@ void HidConnectionMac::PlatformClose() {
       device_.get(), CFRunLoopGetMain(), kCFRunLoopDefaultMode);
   IOReturn result = IOHIDDeviceClose(device_.get(), 0);
   if (result != kIOReturnSuccess) {
-    VLOG(1) << "Failed to close HID device: "
-            << base::StringPrintf("0x%04x", result);
+    HID_LOG(EVENT) << "Failed to close HID device: " << HexErrorCode(result);
   }
 
   while (!pending_reads_.empty()) {
@@ -120,8 +128,7 @@ void HidConnectionMac::InputReportCallback(void* context,
                                            CFIndex report_length) {
   HidConnectionMac* connection = static_cast<HidConnectionMac*>(context);
   if (result != kIOReturnSuccess) {
-    VLOG(1) << "Failed to read input report: "
-            << base::StringPrintf("0x%08x", result);
+    HID_LOG(EVENT) << "Failed to read input report: " << HexErrorCode(result);
     return;
   }
 
@@ -186,8 +193,7 @@ void HidConnectionMac::GetFeatureReportAsync(uint8_t report_id,
                    this,
                    base::Bind(callback, true, buffer, report_size)));
   } else {
-    VLOG(1) << "Failed to get feature report: "
-            << base::StringPrintf("0x%08x", result);
+    HID_LOG(EVENT) << "Failed to get feature report: " << HexErrorCode(result);
     task_runner_->PostTask(FROM_HERE,
                            base::Bind(&HidConnectionMac::ReturnAsyncResult,
                                       this,
@@ -222,7 +228,7 @@ void HidConnectionMac::SetReportAsync(IOHIDReportType report_type,
                                       this,
                                       base::Bind(callback, true)));
   } else {
-    VLOG(1) << "Failed to set report: " << base::StringPrintf("0x%08x", result);
+    HID_LOG(EVENT) << "Failed to set report: " << HexErrorCode(result);
     task_runner_->PostTask(FROM_HERE,
                            base::Bind(&HidConnectionMac::ReturnAsyncResult,
                                       this,
diff --git a/device/hid/hid_connection_win.cc b/device/hid/hid_connection_win.cc
index 3b1a9c3..87845eb 100644
--- a/device/hid/hid_connection_win.cc
+++ b/device/hid/hid_connection_win.cc
@@ -12,6 +12,7 @@
 #include "base/numerics/safe_conversions.h"
 #include "base/profiler/scoped_tracker.h"
 #include "base/win/object_watcher.h"
+#include "components/device_event_log/device_event_log.h"
 
 #define INITGUID
 
@@ -83,7 +84,7 @@ void PendingHidTransfer::TakeResultFromWindowsAPI(BOOL result) {
     AddRef();
     watcher_.StartWatching(event_.Get(), this);
   } else {
-    VPLOG(1) << "HID transfer failed";
+    HID_PLOG(EVENT) << "HID transfer failed";
     callback_.Run(this, false);
   }
 }
@@ -216,7 +217,7 @@ void HidConnectionWin::OnReadComplete(scoped_refptr<net::IOBuffer> buffer,
           file_.Get(), transfer->GetOverlapped(), &bytes_transferred, FALSE)) {
     CompleteRead(buffer, bytes_transferred, callback);
   } else {
-    VPLOG(1) << "HID read failed";
+    HID_PLOG(EVENT) << "HID read failed";
     callback.Run(false, NULL, 0);
   }
 }
@@ -236,7 +237,7 @@ void HidConnectionWin::OnReadFeatureComplete(
           file_.Get(), transfer->GetOverlapped(), &bytes_transferred, FALSE)) {
     callback.Run(true, buffer, bytes_transferred);
   } else {
-    VPLOG(1) << "HID read failed";
+    HID_PLOG(EVENT) << "HID read failed";
     callback.Run(false, NULL, 0);
   }
 }
@@ -254,7 +255,7 @@ void HidConnectionWin::OnWriteComplete(const WriteCallback& callback,
           file_.Get(), transfer->GetOverlapped(), &bytes_transferred, FALSE)) {
     callback.Run(true);
   } else {
-    VPLOG(1) << "HID write failed";
+    HID_PLOG(EVENT) << "HID write failed";
     callback.Run(false);
   }
 }
diff --git a/device/hid/hid_service.cc b/device/hid/hid_service.cc
index 8f502df..4b824ff 100644
--- a/device/hid/hid_service.cc
+++ b/device/hid/hid_service.cc
@@ -9,6 +9,7 @@
 #include "base/logging.h"
 #include "base/message_loop/message_loop.h"
 #include "base/stl_util.h"
+#include "components/device_event_log/device_event_log.h"
 
 #if defined(OS_LINUX) && defined(USE_UDEV)
 #include "device/hid/hid_service_linux.h"
@@ -103,6 +104,12 @@ void HidService::AddDevice(scoped_refptr<HidDeviceInfo> device_info) {
   if (!ContainsKey(devices_, device_info->device_id())) {
     devices_[device_info->device_id()] = device_info;
 
+    HID_LOG(USER) << "HID device "
+                  << (enumeration_ready_ ? "added" : "detected")
+                  << ": vendorId = " << device_info->vendor_id()
+                  << ", productId = " << device_info->product_id()
+                  << ", deviceId = '" << device_info->device_id() << "'";
+
     if (enumeration_ready_) {
       FOR_EACH_OBSERVER(Observer, observer_list_, OnDeviceAdded(device_info));
     }
@@ -113,6 +120,8 @@ void HidService::RemoveDevice(const HidDeviceId& device_id) {
   DCHECK(thread_checker_.CalledOnValidThread());
   DeviceMap::iterator it = devices_.find(device_id);
   if (it != devices_.end()) {
+    HID_LOG(USER) << "HID device removed: deviceId = '" << device_id << "'";
+
     if (enumeration_ready_) {
       FOR_EACH_OBSERVER(Observer, observer_list_, OnDeviceRemoved(it->second));
     }
diff --git a/device/hid/hid_service_linux.cc b/device/hid/hid_service_linux.cc
index 6174d41..500f7b8 100644
--- a/device/hid/hid_service_linux.cc
+++ b/device/hid/hid_service_linux.cc
@@ -13,12 +13,12 @@
 #include "base/files/file_path.h"
 #include "base/files/file_util.h"
 #include "base/location.h"
-#include "base/logging.h"
 #include "base/scoped_observer.h"
 #include "base/strings/string_number_conversions.h"
 #include "base/strings/string_split.h"
 #include "base/thread_task_runner_handle.h"
 #include "base/threading/thread_restrictions.h"
+#include "components/device_event_log/device_event_log.h"
 #include "device/hid/device_monitor_linux.h"
 #include "device/hid/hid_connection_linux.h"
 #include "device/hid/hid_device_info_linux.h"
@@ -282,29 +282,30 @@ void HidServiceLinux::OpenDevice(scoped_ptr<ConnectParams> params) {
     base::File::Error file_error = device_file.error_details();
 
     if (file_error == base::File::FILE_ERROR_ACCESS_DENIED) {
-      VLOG(1) << "Access denied opening device read-write, trying read-only.";
+      HID_LOG(EVENT)
+          << "Access denied opening device read-write, trying read-only.";
       flags = base::File::FLAG_OPEN | base::File::FLAG_READ;
       device_file.Initialize(device_path, flags);
     }
   }
   if (!device_file.IsValid()) {
-    LOG(ERROR) << "Failed to open '" << params->device_info->device_node()
-               << "': "
-               << base::File::ErrorToString(device_file.error_details());
+    HID_LOG(EVENT) << "Failed to open '" << params->device_info->device_node()
+                   << "': "
+                   << base::File::ErrorToString(device_file.error_details());
     task_runner->PostTask(FROM_HERE, base::Bind(params->callback, nullptr));
     return;
   }
 
   int result = fcntl(device_file.GetPlatformFile(), F_GETFL);
   if (result == -1) {
-    PLOG(ERROR) << "Failed to get flags from the device file descriptor";
+    HID_PLOG(ERROR) << "Failed to get flags from the device file descriptor";
     task_runner->PostTask(FROM_HERE, base::Bind(params->callback, nullptr));
     return;
   }
 
   result = fcntl(device_file.GetPlatformFile(), F_SETFL, result | O_NONBLOCK);
   if (result == -1) {
-    PLOG(ERROR) << "Failed to set the non-blocking flag on the device fd";
+    HID_PLOG(ERROR) << "Failed to set the non-blocking flag on the device fd";
     task_runner->PostTask(FROM_HERE, base::Bind(params->callback, nullptr));
     return;
   }
diff --git a/device/hid/hid_service_mac.cc b/device/hid/hid_service_mac.cc
index de6861d..dec4e70 100644
--- a/device/hid/hid_service_mac.cc
+++ b/device/hid/hid_service_mac.cc
@@ -21,12 +21,17 @@
 #include "base/strings/sys_string_conversions.h"
 #include "base/thread_task_runner_handle.h"
 #include "base/threading/thread_restrictions.h"
+#include "components/device_event_log/device_event_log.h"
 #include "device/hid/hid_connection_mac.h"
 
 namespace device {
 
 namespace {
 
+std::string HexErrorCode(IOReturn error_code) {
+  return base::StringPrintf("0x%04x", error_code);
+}
+
 bool TryGetHidIntProperty(IOHIDDeviceRef device,
                           CFStringRef key,
                           int32_t* result) {
@@ -96,8 +101,8 @@ HidServiceMac::HidServiceMac(
                                        this,
                                        &iterator);
   if (result != kIOReturnSuccess) {
-    LOG(ERROR) << "Failed to listen for device arrival: "
-               << base::StringPrintf("0x%04x", result);
+    HID_LOG(ERROR) << "Failed to listen for device arrival: "
+                   << HexErrorCode(result);
     return;
   }
 
@@ -113,8 +118,8 @@ HidServiceMac::HidServiceMac(
                                             this,
                                             &iterator);
   if (result != kIOReturnSuccess) {
-    LOG(ERROR) << "Failed to listen for device removal: "
-               << base::StringPrintf("0x%04x", result);
+    HID_LOG(ERROR) << "Failed to listen for device removal: "
+                   << HexErrorCode(result);
     return;
   }
 
@@ -140,7 +145,7 @@ void HidServiceMac::Connect(const HidDeviceId& device_id,
   base::mac::ScopedIOObject<io_service_t> service(
       IORegistryEntryFromPath(kIOMasterPortDefault, service_path));
   if (!service.get()) {
-    VLOG(1) << "IOService not found for path: " << device_id;
+    HID_LOG(EVENT) << "IOService not found for path: " << device_id;
     task_runner_->PostTask(FROM_HERE, base::Bind(callback, nullptr));
     return;
   }
@@ -148,15 +153,14 @@ void HidServiceMac::Connect(const HidDeviceId& device_id,
   base::ScopedCFTypeRef<IOHIDDeviceRef> hid_device(
       IOHIDDeviceCreate(kCFAllocatorDefault, service));
   if (!hid_device) {
-    VLOG(1) << "Unable to create IOHIDDevice object.";
+    HID_LOG(EVENT) << "Unable to create IOHIDDevice object.";
     task_runner_->PostTask(FROM_HERE, base::Bind(callback, nullptr));
     return;
   }
 
   IOReturn result = IOHIDDeviceOpen(hid_device, kIOHIDOptionsTypeNone);
   if (result != kIOReturnSuccess) {
-    VLOG(1) << "Failed to open device: " << base::StringPrintf("0x%04x",
-                                                               result);
+    HID_LOG(EVENT) << "Failed to open device: " << HexErrorCode(result);
     task_runner_->PostTask(FROM_HERE, base::Bind(callback, nullptr));
     return;
   }
@@ -229,23 +233,23 @@ scoped_refptr<HidDeviceInfo> HidServiceMac::CreateDeviceInfo(
   IOReturn result =
       IORegistryEntryGetPath(service, kIOServicePlane, service_path);
   if (result != kIOReturnSuccess) {
-    VLOG(1) << "Failed to get IOService path: " << base::StringPrintf("0x%04x",
-                                                                      result);
+    HID_LOG(EVENT) << "Failed to get IOService path: " << HexErrorCode(result);
     return nullptr;
   }
 
   base::ScopedCFTypeRef<IOHIDDeviceRef> hid_device(
       IOHIDDeviceCreate(kCFAllocatorDefault, service));
   if (!hid_device) {
-    VLOG(1) << "Unable to create IOHIDDevice object for " << service_path
-            << ".";
+    HID_LOG(EVENT) << "Unable to create IOHIDDevice object for " << service_path
+                   << ".";
     return nullptr;
   }
 
   std::vector<uint8> report_descriptor;
   if (!TryGetHidDataProperty(hid_device, CFSTR(kIOHIDReportDescriptorKey),
                              &report_descriptor)) {
-    VLOG(1) << "Unable to get report descriptor for " << service_path << ".";
+    HID_LOG(EVENT) << "Unable to get report descriptor for " << service_path
+                   << ".";
     return nullptr;
   }
 
diff --git a/device/hid/hid_service_win.cc b/device/hid/hid_service_win.cc
index 3ab8286..8c4ce11 100644
--- a/device/hid/hid_service_win.cc
+++ b/device/hid/hid_service_win.cc
@@ -18,6 +18,7 @@
 #include "base/strings/sys_string_conversions.h"
 #include "base/thread_task_runner_handle.h"
 #include "base/threading/thread_restrictions.h"
+#include "components/device_event_log/device_event_log.h"
 #include "device/hid/hid_connection_win.h"
 #include "device/hid/hid_device_info.h"
 #include "net/base/io_buffer.h"
@@ -64,7 +65,7 @@ void HidServiceWin::Connect(const HidDeviceId& device_id,
 
   base::win::ScopedHandle file(OpenDevice(device_info->device_id()));
   if (!file.IsValid()) {
-    PLOG(ERROR) << "Failed to open device";
+    HID_PLOG(EVENT) << "Failed to open device";
     task_runner_->PostTask(FROM_HERE, base::Bind(callback, nullptr));
     return;
   }
@@ -186,20 +187,20 @@ void HidServiceWin::AddDeviceOnFileThread(
   HIDD_ATTRIBUTES attrib = {0};
   attrib.Size = sizeof(HIDD_ATTRIBUTES);
   if (!HidD_GetAttributes(device_handle.Get(), &attrib)) {
-    VLOG(1) << "Failed to get device attributes.";
+    HID_LOG(EVENT) << "Failed to get device attributes.";
     return;
   }
 
   PHIDP_PREPARSED_DATA preparsed_data = nullptr;
   if (!HidD_GetPreparsedData(device_handle.Get(), &preparsed_data) ||
       !preparsed_data) {
-    VLOG(1) << "Failed to get device data.";
+    HID_LOG(EVENT) << "Failed to get device data.";
     return;
   }
 
   HIDP_CAPS capabilities = {0};
   if (HidP_GetCaps(preparsed_data, &capabilities) != HIDP_STATUS_SUCCESS) {
-    VLOG(1) << "Failed to get device capabilities.";
+    HID_LOG(EVENT) << "Failed to get device capabilities.";
     HidD_FreePreparsedData(preparsed_data);
     return;
   }