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

device/usb/usb_device_handle_impl.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.
 
 #include "device/usb/usb_device_handle_impl.h"
 
 #include <algorithm>
 #include <vector>
 
 #include "base/bind.h"
 #include "base/location.h"
 #include "base/single_thread_task_runner.h"
 #include "base/stl_util.h"
 #include "base/strings/string16.h"
 #include "base/synchronization/lock.h"
 #include "base/thread_task_runner_handle.h"
 #include "device/usb/usb_context.h"
 #include "device/usb/usb_descriptors.h"
 #include "device/usb/usb_device_impl.h"
 #include "device/usb/usb_error.h"
+#include "device/usb/usb_log.h"
 #include "device/usb/usb_service.h"
 #include "third_party/libusb/src/libusb/libusb.h"
 
 namespace device {
 
 typedef libusb_device* PlatformUsbDevice;
 
 void HandleTransferCompletion(PlatformUsbTransferHandle transfer);
 
 namespace {
@@ skipping 107 matching lines @@
       alternate_setting_(0) {
 }
 
 UsbDeviceHandleImpl::InterfaceClaimer::~InterfaceClaimer() {
   libusb_release_interface(handle_->handle(), interface_number_);
 }
 
 bool UsbDeviceHandleImpl::InterfaceClaimer::Claim() const {
   const int rv = libusb_claim_interface(handle_->handle(), interface_number_);
   if (rv != LIBUSB_SUCCESS) {
-    VLOG(1) << "Failed to claim interface: "
-            << ConvertPlatformUsbErrorToString(rv);
+    USB_LOG(DEBUG) << "Failed to claim interface " << interface_number_ << ": "
+                   << ConvertPlatformUsbErrorToString(rv);

[stevenjb, 2015/02/20 00:01:27]

You might want to use type EVENT here. DEBUG doesn't show up in Feedback
reports. 

General Note: Anything that might be spammy (e.g. an event that occurs every
second) is not a good candidate for DEVICE_LOG.

[Reilly Grant (use Gerrit), 2015/02/20 00:10:22]

Spamminess is somewhat controlled by the Chrome app driving this code. If it
does something that generates an error every second, then there will be a log
every second. That said, such failures should be rare and so I'm willing to
accept the possibility of a message becoming spammy if things are really broken.

   }
   return rv == LIBUSB_SUCCESS;
 }
 
 // This inner class owns the underlying libusb_transfer and may outlast
 // the UsbDeviceHandle that created it.
 class UsbDeviceHandleImpl::Transfer {
  public:
   static scoped_ptr<Transfer> CreateControlTransfer(
       uint8 type,
@@ skipping 66 matching lines @@
     uint16 length,
     scoped_refptr<net::IOBuffer> buffer,
     unsigned int timeout,
     const UsbTransferCallback& callback) {
   scoped_ptr<Transfer> transfer(new Transfer(USB_TRANSFER_CONTROL, buffer,
                                              length + LIBUSB_CONTROL_SETUP_SIZE,
                                              callback));
 
   transfer->platform_transfer_ = libusb_alloc_transfer(0);
   if (!transfer->platform_transfer_) {
-    LOG(ERROR) << "Failed to allocate control transfer.";
+    USB_LOG(DEBUG) << "Failed to allocate control transfer.";

[stevenjb, 2015/02/20 00:01:27]

If LOG(ERROR) was correct before, this should also use ERROR. Anything that
shouldn't normally occur should be fine as type ERROR (which will also output to
the chrome log).

     return nullptr;
   }
 
   libusb_fill_control_setup(reinterpret_cast<uint8*>(buffer->data()), type,
                             request, value, index, length);
   libusb_fill_control_transfer(transfer->platform_transfer_,
                                nullptr, /* filled in by Submit() */
                                reinterpret_cast<uint8*>(buffer->data()),
                                &UsbDeviceHandleImpl::Transfer::PlatformCallback,
                                transfer.get(), timeout);
 
   return transfer.Pass();
 }
 
 // static
 scoped_ptr<UsbDeviceHandleImpl::Transfer>
 UsbDeviceHandleImpl::Transfer::CreateBulkTransfer(
     uint8 endpoint,
     scoped_refptr<net::IOBuffer> buffer,
     int length,
     unsigned int timeout,
     const UsbTransferCallback& callback) {
   scoped_ptr<Transfer> transfer(
       new Transfer(USB_TRANSFER_BULK, buffer, length, callback));
 
   transfer->platform_transfer_ = libusb_alloc_transfer(0);
   if (!transfer->platform_transfer_) {
-    LOG(ERROR) << "Failed to allocate bulk transfer.";
+    USB_LOG(DEBUG) << "Failed to allocate bulk transfer.";

[stevenjb, 2015/02/20 00:01:27]

Double check all of these for ERROR / USER / EVENT / DEBUG

     return nullptr;
   }
 
   libusb_fill_bulk_transfer(transfer->platform_transfer_,
                             nullptr, /* filled in by Submit() */
                             endpoint, reinterpret_cast<uint8*>(buffer->data()),
                             static_cast<int>(length),
                             &UsbDeviceHandleImpl::Transfer::PlatformCallback,
                             transfer.get(), timeout);
 
   return transfer.Pass();
 }
 
 // static
 scoped_ptr<UsbDeviceHandleImpl::Transfer>
 UsbDeviceHandleImpl::Transfer::CreateInterruptTransfer(
     uint8 endpoint,
     scoped_refptr<net::IOBuffer> buffer,
     int length,
     unsigned int timeout,
     const UsbTransferCallback& callback) {
   scoped_ptr<Transfer> transfer(
       new Transfer(USB_TRANSFER_INTERRUPT, buffer, length, callback));
 
   transfer->platform_transfer_ = libusb_alloc_transfer(0);
   if (!transfer->platform_transfer_) {
-    LOG(ERROR) << "Failed to allocate interrupt transfer.";
+    USB_LOG(DEBUG) << "Failed to allocate interrupt transfer.";
     return nullptr;
   }
 
   libusb_fill_interrupt_transfer(
       transfer->platform_transfer_, nullptr, /* filled in by Submit() */
       endpoint, reinterpret_cast<uint8*>(buffer->data()),
       static_cast<int>(length),
       &UsbDeviceHandleImpl::Transfer::PlatformCallback, transfer.get(),
       timeout);
 
@@ skipping 11 matching lines @@
     unsigned int timeout,
     const UsbTransferCallback& callback) {
   DCHECK(packets <= length && (packets * packet_length) <= length)
       << "transfer length is too small";
 
   scoped_ptr<Transfer> transfer(
       new Transfer(USB_TRANSFER_ISOCHRONOUS, buffer, length, callback));
 
   transfer->platform_transfer_ = libusb_alloc_transfer(packets);
   if (!transfer->platform_transfer_) {
-    LOG(ERROR) << "Failed to allocate isochronous transfer.";
+    USB_LOG(DEBUG) << "Failed to allocate isochronous transfer.";
     return nullptr;
   }
 
   libusb_fill_iso_transfer(
       transfer->platform_transfer_, nullptr, /* filled in by Submit() */
       endpoint, reinterpret_cast<uint8*>(buffer->data()),
       static_cast<int>(length), packets, &Transfer::PlatformCallback,
       transfer.get(), timeout);
   libusb_set_iso_packet_lengths(transfer->platform_transfer_, packet_length);
 
@@ skipping 29 matching lines @@
   // GetClaimedInterfaceForEndpoint may return nullptr. libusb_submit_transfer
   // will fail if it requires an interface we didn't claim.
   claimed_interface_ = device_handle->GetClaimedInterfaceForEndpoint(
       platform_transfer_->endpoint);
   platform_transfer_->dev_handle = device_handle_->handle_;
 
   const int rv = libusb_submit_transfer(platform_transfer_);
   if (rv == LIBUSB_SUCCESS) {
     return true;
   } else {
-    VLOG(1) << "Failed to submit transfer: "
-            << ConvertPlatformUsbErrorToString(rv);
+    USB_LOG(DEBUG) << "Failed to submit transfer: "
+                   << ConvertPlatformUsbErrorToString(rv);
     Complete(USB_TRANSFER_ERROR, 0);
     return false;
   }
 }
 
 void UsbDeviceHandleImpl::Transfer::Cancel() {
   if (!cancelled_) {
     libusb_cancel_transfer(platform_transfer_);
     claimed_interface_ = nullptr;
   }
@@ skipping 133 matching lines @@
   for (Transfer* transfer : transfers_) {
     transfer->Cancel();
   }
   claimed_interfaces_.clear();
 
   int rv = libusb_set_configuration(handle_, configuration_value);
   if (rv == LIBUSB_SUCCESS) {
     device_->RefreshConfiguration();
     RefreshEndpointMap();
   } else {
-    VLOG(1) << "Failed to set configuration " << configuration_value << ": "
-            << ConvertPlatformUsbErrorToString(rv);
+    USB_LOG(DEBUG) << "Failed to set configuration " << configuration_value
+                   << ": " << ConvertPlatformUsbErrorToString(rv);
   }
   return rv == LIBUSB_SUCCESS;
 }
 
 bool UsbDeviceHandleImpl::ClaimInterface(const int interface_number) {
   DCHECK(thread_checker_.CalledOnValidThread());
   if (!device_)
     return false;
   if (ContainsKey(claimed_interfaces_, interface_number))
     return true;
@@ skipping 38 matching lines @@
     return false;
   if (!ContainsKey(claimed_interfaces_, interface_number))
     return false;
   const int rv = libusb_set_interface_alt_setting(
       handle_, interface_number, alternate_setting);
   if (rv == LIBUSB_SUCCESS) {
     claimed_interfaces_[interface_number]->set_alternate_setting(
         alternate_setting);
     RefreshEndpointMap();
   } else {
-    VLOG(1) << "Failed to set interface (" << interface_number << ", "
-            << alternate_setting
-            << "): " << ConvertPlatformUsbErrorToString(rv);
+    USB_LOG(DEBUG) << "Failed to set interface " << interface_number
+                   << " to alternate setting " << alternate_setting << ": "
+                   << ConvertPlatformUsbErrorToString(rv);
   }
   return rv == LIBUSB_SUCCESS;
 }
 
 bool UsbDeviceHandleImpl::ResetDevice() {
   DCHECK(thread_checker_.CalledOnValidThread());
   if (!device_)
     return false;
 
   const int rv = libusb_reset_device(handle_);
   if (rv != LIBUSB_SUCCESS) {
-    VLOG(1) << "Failed to reset device: "
-            << ConvertPlatformUsbErrorToString(rv);
+    USB_LOG(DEBUG) << "Failed to reset device: "
+                   << ConvertPlatformUsbErrorToString(rv);
   }
   return rv == LIBUSB_SUCCESS;
 }
 
 bool UsbDeviceHandleImpl::GetStringDescriptor(uint8 string_id,
                                               base::string16* string) {
   if (!GetSupportedLanguages()) {
     return false;
   }
 
   std::map<uint8, base::string16>::const_iterator it = strings_.find(string_id);
   if (it != strings_.end()) {
     *string = it->second;
     return true;
   }
 
   for (size_t i = 0; i < languages_.size(); ++i) {
     // Get the string using language ID.
     uint16 language_id = languages_[i];
     // The 1-byte length field limits the descriptor to 256-bytes (128 char16s).
     base::char16 text[128];
     int size =
         libusb_get_string_descriptor(handle_,
                                      string_id,
                                      language_id,
                                      reinterpret_cast<unsigned char*>(&text[0]),
                                      sizeof(text));
     if (size < 0) {
-      VLOG(1) << "Failed to get string descriptor " << string_id << " (langid "
-              << language_id << "): " << ConvertPlatformUsbErrorToString(size);
+      USB_LOG(DEBUG) << "Failed to get string descriptor " << string_id
+                     << " (langid " << language_id
+                     << "): " << ConvertPlatformUsbErrorToString(size);
       continue;
     } else if (size < 2) {
-      VLOG(1) << "String descriptor " << string_id << " (langid " << language_id
-              << ") has no header.";
+      USB_LOG(DEBUG) << "String descriptor " << string_id << " (langid "
+                     << language_id << ") has no header.";
       continue;
       // The first 2 bytes of the descriptor are the total length and type tag.
     } else if ((text[0] & 0xff) != size) {
-      VLOG(1) << "String descriptor " << string_id << " (langid " << language_id
-              << ") size mismatch: " << (text[0] & 0xff) << " != " << size;
+      USB_LOG(DEBUG) << "String descriptor " << string_id << " (langid "
+                     << language_id << ") size mismatch: " << (text[0] & 0xff)
+                     << " != " << size;
       continue;
     } else if ((text[0] >> 8) != LIBUSB_DT_STRING) {
-      VLOG(1) << "String descriptor " << string_id << " (langid " << language_id
-              << ") is not a string descriptor.";
+      USB_LOG(DEBUG) << "String descriptor " << string_id << " (langid "
+                     << language_id << ") is not a string descriptor.";
       continue;
     }
 
     *string = base::string16(text + 1, (size - 2) / 2);
     strings_[string_id] = *string;
     return true;
   }
 
   return false;
 }
 
 void UsbDeviceHandleImpl::ControlTransfer(UsbEndpointDirection direction,
                                           TransferRequestType request_type,
                                           TransferRecipient recipient,
                                           uint8 request,
                                           uint16 value,
                                           uint16 index,
                                           net::IOBuffer* buffer,
                                           size_t length,
                                           unsigned int timeout,
                                           const UsbTransferCallback& callback) {
   if (length > UINT16_MAX) {
-    LOG(ERROR) << "Transfer too long.";
+    USB_LOG(DEBUG) << "Transfer too long.";
     callback.Run(USB_TRANSFER_ERROR, buffer, 0);
     return;
   }
 
   const size_t resized_length = LIBUSB_CONTROL_SETUP_SIZE + length;
   scoped_refptr<net::IOBuffer> resized_buffer(
       new net::IOBufferWithSize(static_cast<int>(resized_length)));
   if (!resized_buffer.get()) {
     callback.Run(USB_TRANSFER_ERROR, buffer, 0);
     return;
@@ skipping 12 matching lines @@
   PostOrSubmitTransfer(transfer.Pass());
 }
 
 void UsbDeviceHandleImpl::BulkTransfer(const UsbEndpointDirection direction,
                                        const uint8 endpoint,
                                        net::IOBuffer* buffer,
                                        const size_t length,
                                        const unsigned int timeout,
                                        const UsbTransferCallback& callback) {
   if (length > INT_MAX) {
-    LOG(ERROR) << "Transfer too long.";
+    USB_LOG(DEBUG) << "Transfer too long.";
     callback.Run(USB_TRANSFER_ERROR, buffer, 0);
     return;
   }
 
   scoped_ptr<Transfer> transfer = Transfer::CreateBulkTransfer(
       ConvertTransferDirection(direction) | endpoint, buffer,
       static_cast<int>(length), timeout, callback);
 
   PostOrSubmitTransfer(transfer.Pass());
 }
 
 void UsbDeviceHandleImpl::InterruptTransfer(
     UsbEndpointDirection direction,
     uint8 endpoint,
     net::IOBuffer* buffer,
     size_t length,
     unsigned int timeout,
     const UsbTransferCallback& callback) {
   if (length > INT_MAX) {
-    LOG(ERROR) << "Transfer too long.";
+    USB_LOG(DEBUG) << "Transfer too long.";
     callback.Run(USB_TRANSFER_ERROR, buffer, 0);
     return;
   }
 
   scoped_ptr<Transfer> transfer = Transfer::CreateInterruptTransfer(
       ConvertTransferDirection(direction) | endpoint, buffer,
       static_cast<int>(length), timeout, callback);
 
   PostOrSubmitTransfer(transfer.Pass());
 }
 
 void UsbDeviceHandleImpl::IsochronousTransfer(
     const UsbEndpointDirection direction,
     const uint8 endpoint,
     net::IOBuffer* buffer,
     const size_t length,
     const unsigned int packets,
     const unsigned int packet_length,
     const unsigned int timeout,
     const UsbTransferCallback& callback) {
   if (length > INT_MAX) {
-    LOG(ERROR) << "Transfer too long.";
+    USB_LOG(DEBUG) << "Transfer too long.";
     callback.Run(USB_TRANSFER_ERROR, buffer, 0);
     return;
   }
 
   scoped_ptr<Transfer> transfer = Transfer::CreateIsochronousTransfer(
       ConvertTransferDirection(direction) | endpoint, buffer,
       static_cast<int>(length), packets, packet_length, timeout, callback);
 
   PostOrSubmitTransfer(transfer.Pass());
 }
@@ skipping 65 matching lines @@
 
   // The 1-byte length field limits the descriptor to 256-bytes (128 uint16s).
   uint16 languages[128];
   int size = libusb_get_string_descriptor(
       handle_,
       0,
       0,
       reinterpret_cast<unsigned char*>(&languages[0]),
       sizeof(languages));
   if (size < 0) {
-    VLOG(1) << "Failed to get list of supported languages: "
-            << ConvertPlatformUsbErrorToString(size);
+    USB_LOG(DEBUG) << "Failed to get list of supported languages: "
+                   << ConvertPlatformUsbErrorToString(size);
     return false;
   } else if (size < 2) {
-    VLOG(1) << "String descriptor zero has no header.";
+    USB_LOG(DEBUG) << "String descriptor zero has no header.";
     return false;
     // The first 2 bytes of the descriptor are the total length and type tag.
   } else if ((languages[0] & 0xff) != size) {
-    VLOG(1) << "String descriptor zero size mismatch: " << (languages[0] & 0xff)
-            << " != " << size;
+    USB_LOG(DEBUG) << "String descriptor zero size mismatch: "
+                   << (languages[0] & 0xff) << " != " << size;
     return false;
   } else if ((languages[0] >> 8) != LIBUSB_DT_STRING) {
-    VLOG(1) << "String descriptor zero is not a string descriptor.";
+    USB_LOG(DEBUG) << "String descriptor zero is not a string descriptor.";
     return false;
   }
 
   languages_.assign(languages[1], languages[(size - 2) / 2]);
   return true;
 }
 
 void UsbDeviceHandleImpl::InternalClose() {
   DCHECK(thread_checker_.CalledOnValidThread());
   if (!device_)
     return;
 
   // Cancel all the transfers.
   for (Transfer* transfer : transfers_) {
     // The callback will be called some time later.
     transfer->Cancel();
   }
 
   // Attempt-release all the interfaces.
   // It will be retained until the transfer cancellation is finished.
   claimed_interfaces_.clear();
 
   // Cannot close device handle here. Need to wait for libusb_cancel_transfer to
   // finish.
   device_ = NULL;
 }
 
 }  // namespace device