Add path open errors from the permission broker to the device log.

This change adds an additional ErrorCallback parameter to the permission
broker client so that the caller can get a better log message when its
request to open a device node fails.

This will hopefully help to determine the cause of the many "Did not get
valid device handle from permission broker" errors that some users are
seeing.

BUG=570784

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

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

11 files changed, 140 insertions, 50 deletions

diff --git a/chromeos/dbus/fake_permission_broker_client.cc b/chromeos/dbus/fake_permission_broker_client.cc
index 548173b..2abd285 100644
--- a/chromeos/dbus/fake_permission_broker_client.cc
+++ b/chromeos/dbus/fake_permission_broker_client.cc
@@ -12,6 +12,7 @@
 #include "base/location.h"
 #include "base/logging.h"
 #include "base/posix/eintr_wrapper.h"
+#include "base/strings/stringprintf.h"
 #include "base/thread_task_runner_handle.h"
 #include "base/threading/worker_pool.h"
 #include "dbus/file_descriptor.h"
@@ -20,6 +21,8 @@ namespace chromeos {
 
 namespace {
 
+const char kOpenFailedError[] = "open_failed";
+
 // So that real devices can be accessed by tests and "Chromium OS on Linux" this
 // function implements a simplified version of the method implemented by the
 // permission broker by opening the path specified and returning the resulting
@@ -27,15 +30,23 @@ namespace {
 void OpenPathAndValidate(
     const std::string& path,
     const PermissionBrokerClient::OpenPathCallback& callback,
+    const PermissionBrokerClient::ErrorCallback& error_callback,
     scoped_refptr<base::TaskRunner> task_runner) {
-  dbus::FileDescriptor dbus_fd;
   int fd = HANDLE_EINTR(open(path.c_str(), O_RDWR));
   if (fd < 0) {
-    PLOG(WARNING) << "Failed to open '" << path << "'";
-  } else {
-    dbus_fd.PutValue(fd);
-    dbus_fd.CheckValidity();
+    int error_code = logging::GetLastSystemErrorCode();
+    task_runner->PostTask(
+        FROM_HERE,
+        base::Bind(error_callback, kOpenFailedError,
+                   base::StringPrintf(
+                       "Failed to open '%s': %s", path.c_str(),
+                       logging::SystemErrorCodeToString(error_code).c_str())));
+    return;
   }
+
+  dbus::FileDescriptor dbus_fd;
+  dbus_fd.PutValue(fd);
+  dbus_fd.CheckValidity();
   task_runner->PostTask(FROM_HERE,
                         base::Bind(callback, base::Passed(&dbus_fd)));
 }
@@ -55,11 +66,13 @@ void FakePermissionBrokerClient::CheckPathAccess(
 }
 
 void FakePermissionBrokerClient::OpenPath(const std::string& path,
-                                          const OpenPathCallback& callback) {
-  base::WorkerPool::PostTask(FROM_HERE,
-                             base::Bind(&OpenPathAndValidate, path, callback,
-                                        base::ThreadTaskRunnerHandle::Get()),
-                             false);
+                                          const OpenPathCallback& callback,
+                                          const ErrorCallback& error_callback) {
+  base::WorkerPool::PostTask(
+      FROM_HERE,
+      base::Bind(&OpenPathAndValidate, path, callback, error_callback,
+                 base::ThreadTaskRunnerHandle::Get()),
+      false);
 }
 
 void FakePermissionBrokerClient::RequestTcpPortAccess(
diff --git a/chromeos/dbus/fake_permission_broker_client.h b/chromeos/dbus/fake_permission_broker_client.h
index ee46101..3ce9111 100644
--- a/chromeos/dbus/fake_permission_broker_client.h
+++ b/chromeos/dbus/fake_permission_broker_client.h
@@ -23,7 +23,8 @@ class CHROMEOS_EXPORT FakePermissionBrokerClient
   void CheckPathAccess(const std::string& path,
                        const ResultCallback& callback) override;
   void OpenPath(const std::string& path,
-                const OpenPathCallback& callback) override;
+                const OpenPathCallback& callback,
+                const ErrorCallback& error_callback) override;
   void RequestTcpPortAccess(uint16_t port,
                             const std::string& interface,
                             const dbus::FileDescriptor& lifeline_fd,
diff --git a/chromeos/dbus/mock_permission_broker_client.h b/chromeos/dbus/mock_permission_broker_client.h
index 4d97b06..acc3efa 100644
--- a/chromeos/dbus/mock_permission_broker_client.h
+++ b/chromeos/dbus/mock_permission_broker_client.h
@@ -24,8 +24,10 @@ class MockPermissionBrokerClient : public PermissionBrokerClient {
   MOCK_METHOD1(Init, void(dbus::Bus* bus));
   MOCK_METHOD2(CheckPathAccess,
                void(const std::string& path, const ResultCallback& callback));
-  MOCK_METHOD2(OpenPath,
-               void(const std::string& path, const OpenPathCallback& callback));
+  MOCK_METHOD3(OpenPath,
+               void(const std::string& path,
+                    const OpenPathCallback& callback,
+                    const ErrorCallback& error_callback));
   MOCK_METHOD4(RequestTcpPortAccess,
                void(uint16_t port,
                     const std::string& interface,
diff --git a/chromeos/dbus/permission_broker_client.cc b/chromeos/dbus/permission_broker_client.cc
index fb0c934..c56d801 100644
--- a/chromeos/dbus/permission_broker_client.cc
+++ b/chromeos/dbus/permission_broker_client.cc
@@ -27,6 +27,10 @@ using permission_broker::kRequestUdpPortAccess;
 
 namespace chromeos {
 
+namespace {
+const char kNoResponseError[] = "org.chromium.Error.NoResponse";
+}
+
 class PermissionBrokerClientImpl : public PermissionBrokerClient {
  public:
   PermissionBrokerClientImpl() : proxy_(NULL), weak_ptr_factory_(this) {}
@@ -42,14 +46,17 @@ class PermissionBrokerClientImpl : public PermissionBrokerClient {
   }
 
   void OpenPath(const std::string& path,
-                const OpenPathCallback& callback) override {
+                const OpenPathCallback& callback,
+                const ErrorCallback& error_callback) override {
     dbus::MethodCall method_call(kPermissionBrokerInterface, kOpenPath);
     dbus::MessageWriter writer(&method_call);
     writer.AppendString(path);
-    proxy_->CallMethod(
+    proxy_->CallMethodWithErrorCallback(
         &method_call, dbus::ObjectProxy::TIMEOUT_USE_DEFAULT,
         base::Bind(&PermissionBrokerClientImpl::OnOpenPathResponse,
-                   weak_ptr_factory_.GetWeakPtr(), callback));
+                   weak_ptr_factory_.GetWeakPtr(), callback),
+        base::Bind(&PermissionBrokerClientImpl::OnError,
+                   weak_ptr_factory_.GetWeakPtr(), error_callback));
   }
 
   void RequestTcpPortAccess(uint16_t port,
@@ -133,15 +140,23 @@ class PermissionBrokerClientImpl : public PermissionBrokerClient {
   void OnOpenPathResponse(const OpenPathCallback& callback,
                           dbus::Response* response) {
     dbus::FileDescriptor fd;
+    dbus::MessageReader reader(response);
+    if (!reader.PopFileDescriptor(&fd))
+      LOG(WARNING) << "Could not parse response: " << response->ToString();
+    callback.Run(std::move(fd));
+  }
+
+  void OnError(const ErrorCallback& callback, dbus::ErrorResponse* response) {
+    std::string error_name;
+    std::string error_message;
     if (response) {
       dbus::MessageReader reader(response);
-      if (!reader.PopFileDescriptor(&fd))
-        LOG(WARNING) << "Could not parse response: " << response->ToString();
+      error_name = response->GetErrorName();
+      reader.PopString(&error_message);
     } else {
-      LOG(WARNING) << "Access request method call failed.";
+      error_name = kNoResponseError;
     }
-
-    callback.Run(std::move(fd));
+    callback.Run(error_name, error_message);
   }
 
   dbus::ObjectProxy* proxy_;
diff --git a/chromeos/dbus/permission_broker_client.h b/chromeos/dbus/permission_broker_client.h
index 276bfba..f56bfcc 100644
--- a/chromeos/dbus/permission_broker_client.h
+++ b/chromeos/dbus/permission_broker_client.h
@@ -34,6 +34,12 @@ class CHROMEOS_EXPORT PermissionBrokerClient : public DBusClient {
   // An OpenPathCallback callback is run when an OpenPath request is completed.
   typedef base::Callback<void(dbus::FileDescriptor)> OpenPathCallback;
 
+  // An ErrorCallback callback is run when an error is returned by the
+  // permission broker.
+  typedef base::Callback<void(const std::string& error_name,
+                              const std::string& message)>
+      ErrorCallback;
+
   ~PermissionBrokerClient() override;
 
   static PermissionBrokerClient* Create();
@@ -46,9 +52,11 @@ class CHROMEOS_EXPORT PermissionBrokerClient : public DBusClient {
                                const ResultCallback& callback) = 0;
 
   // OpenPath requests that the permission broker open the device node
-  // identified by |path| and return the resulting file descriptor.
+  // identified by |path| and return the resulting file descriptor. One of
+  // |callback| or |error_callback| is called.
   virtual void OpenPath(const std::string& path,
-                        const OpenPathCallback& callback) = 0;
+                        const OpenPathCallback& callback,
+                        const ErrorCallback& error_callback) = 0;
 
   // Requests the |port| be opened on the firewall for incoming TCP/IP
   // connections received on |interface| (an empty string indicates all
diff --git a/device/hid/hid_service_linux.cc b/device/hid/hid_service_linux.cc
index 0829576..057d18c 100644
--- a/device/hid/hid_service_linux.cc
+++ b/device/hid/hid_service_linux.cc
@@ -241,9 +241,13 @@ void HidServiceLinux::Connect(const HidDeviceId& device_id,
   chromeos::PermissionBrokerClient* client =
       chromeos::DBusThreadManager::Get()->GetPermissionBrokerClient();
   DCHECK(client) << "Could not get permission broker client.";
+  chromeos::PermissionBrokerClient::ErrorCallback error_callback =
+      base::Bind(&HidServiceLinux::OnPathOpenError,
+                 params->device_info->device_node(), params->callback);
   client->OpenPath(
       device_info->device_node(),
-      base::Bind(&HidServiceLinux::OnPathOpened, base::Passed(&params)));
+      base::Bind(&HidServiceLinux::OnPathOpenComplete, base::Passed(&params)),
+      error_callback);
 #else
   file_task_runner_->PostTask(FROM_HERE,
                               base::Bind(&HidServiceLinux::OpenOnBlockingThread,
@@ -254,8 +258,8 @@ void HidServiceLinux::Connect(const HidDeviceId& device_id,
 #if defined(OS_CHROMEOS)
 
 // static
-void HidServiceLinux::OnPathOpened(scoped_ptr<ConnectParams> params,
-                                   dbus::FileDescriptor fd) {
+void HidServiceLinux::OnPathOpenComplete(scoped_ptr<ConnectParams> params,
+                                         dbus::FileDescriptor fd) {
   scoped_refptr<base::SingleThreadTaskRunner> file_task_runner =
       params->file_task_runner;
   file_task_runner->PostTask(
@@ -264,21 +268,24 @@ void HidServiceLinux::OnPathOpened(scoped_ptr<ConnectParams> params,
 }
 
 // static
+void HidServiceLinux::OnPathOpenError(const std::string& device_path,
+                                      const ConnectCallback& callback,
+                                      const std::string& error_name,
+                                      const std::string& error_message) {
+  HID_LOG(EVENT) << "Permission broker failed to open '" << device_path
+                 << "': " << error_name << ": " << error_message;
+  callback.Run(nullptr);
+}
+
+// static
 void HidServiceLinux::ValidateFdOnBlockingThread(
     scoped_ptr<ConnectParams> params,
     dbus::FileDescriptor fd) {
   base::ThreadRestrictions::AssertIOAllowed();
-
   fd.CheckValidity();
-  if (fd.is_valid()) {
-    params->device_file = base::File(fd.TakeValue());
-    FinishOpen(std::move(params));
-  } else {
-    HID_LOG(EVENT) << "Permission broker denied access to '"
-                   << params->device_info->device_node() << "'.";
-    params->task_runner->PostTask(FROM_HERE,
-                                  base::Bind(params->callback, nullptr));
-  }
+  DCHECK(fd.is_valid());
+  params->device_file = base::File(fd.TakeValue());
+  FinishOpen(std::move(params));
 }
 
 #else
diff --git a/device/hid/hid_service_linux.h b/device/hid/hid_service_linux.h
index 9f87504..7d92830 100644
--- a/device/hid/hid_service_linux.h
+++ b/device/hid/hid_service_linux.h
@@ -37,8 +37,12 @@ class HidServiceLinux : public HidService {
   // functions are static and the necessary parameters are passed as a single
   // struct.
 #if defined(OS_CHROMEOS)
-  static void OnPathOpened(scoped_ptr<ConnectParams> params,
-                           dbus::FileDescriptor fd);
+  static void OnPathOpenComplete(scoped_ptr<ConnectParams> params,
+                                 dbus::FileDescriptor fd);
+  static void OnPathOpenError(const std::string& device_path,
+                              const ConnectCallback& callback,
+                              const std::string& error_name,
+                              const std::string& error_message);
   static void ValidateFdOnBlockingThread(scoped_ptr<ConnectParams> params,
                                          dbus::FileDescriptor fd);
 #else
diff --git a/device/serial/serial_io_handler.cc b/device/serial/serial_io_handler.cc
index 35b41f7..a5257ed 100644
--- a/device/serial/serial_io_handler.cc
+++ b/device/serial/serial_io_handler.cc
@@ -54,12 +54,15 @@ void SerialIoHandler::Open(const std::string& port,
       chromeos::DBusThreadManager::Get()->GetPermissionBrokerClient();
   DCHECK(client) << "Could not get permission_broker client.";
   // PermissionBrokerClient should be called on the UI thread.
+  scoped_refptr<base::SingleThreadTaskRunner> task_runner =
+      base::ThreadTaskRunnerHandle::Get();
   ui_thread_task_runner_->PostTask(
-      FROM_HERE, base::Bind(&chromeos::PermissionBrokerClient::OpenPath,
-                            base::Unretained(client), port,
-                            base::Bind(&SerialIoHandler::OnPathOpened, this,
-                                       file_thread_task_runner_,
-                                       base::ThreadTaskRunnerHandle::Get())));
+      FROM_HERE,
+      base::Bind(
+          &chromeos::PermissionBrokerClient::OpenPath, base::Unretained(client),
+          port, base::Bind(&SerialIoHandler::OnPathOpened, this,
+                           file_thread_task_runner_, task_runner),
+          base::Bind(&SerialIoHandler::OnPathOpenError, this, task_runner)));
 #else
   file_thread_task_runner_->PostTask(
       FROM_HERE, base::Bind(&SerialIoHandler::StartOpen, this, port,
@@ -73,12 +76,20 @@ void SerialIoHandler::OnPathOpened(
     scoped_refptr<base::SingleThreadTaskRunner> file_thread_task_runner,
     scoped_refptr<base::SingleThreadTaskRunner> io_thread_task_runner,
     dbus::FileDescriptor fd) {
-  DCHECK(CalledOnValidThread());
   file_thread_task_runner->PostTask(
       FROM_HERE, base::Bind(&SerialIoHandler::ValidateOpenPort, this,
                             io_thread_task_runner, base::Passed(&fd)));
 }
 
+void SerialIoHandler::OnPathOpenError(
+    scoped_refptr<base::SingleThreadTaskRunner> io_thread_task_runner,
+    const std::string& error_name,
+    const std::string& error_message) {
+  io_thread_task_runner->PostTask(
+      FROM_HERE, base::Bind(&SerialIoHandler::ReportPathOpenError, this,
+                            error_name, error_message));
+}
+
 void SerialIoHandler::ValidateOpenPort(
     scoped_refptr<base::SingleThreadTaskRunner> io_thread_task_runner,
     dbus::FileDescriptor fd) {
@@ -93,6 +104,17 @@ void SerialIoHandler::ValidateOpenPort(
       base::Bind(&SerialIoHandler::FinishOpen, this, base::Passed(&file)));
 }
 
+void SerialIoHandler::ReportPathOpenError(const std::string& error_name,
+                                          const std::string& error_message) {
+  DCHECK(CalledOnValidThread());
+  DCHECK(!open_complete_.is_null());
+  LOG(ERROR) << "Permission broker failed to open '" << port_
+             << "': " << error_name << ": " << error_message;
+  OpenCompleteCallback callback = open_complete_;
+  open_complete_.Reset();
+  callback.Run(false);
+}
+
 #endif
 
 void SerialIoHandler::MergeConnectionOptions(
diff --git a/device/serial/serial_io_handler.h b/device/serial/serial_io_handler.h
index f494743..d1a4827 100644
--- a/device/serial/serial_io_handler.h
+++ b/device/serial/serial_io_handler.h
@@ -50,10 +50,20 @@ class SerialIoHandler : public base::NonThreadSafe,
       scoped_refptr<base::SingleThreadTaskRunner> io_thread_task_runner,
       dbus::FileDescriptor fd);
 
+  // Signals that the permission broker failed to open the port.
+  void OnPathOpenError(
+      scoped_refptr<base::SingleThreadTaskRunner> io_thread_task_runner,
+      const std::string& error_name,
+      const std::string& error_message);
+
   // Validates the file descriptor provided by the permission broker.
   void ValidateOpenPort(
       scoped_refptr<base::SingleThreadTaskRunner> io_thread_task_runner,
       dbus::FileDescriptor fd);
+
+  // Reports the open error from the permission broker.
+  void ReportPathOpenError(const std::string& error_name,
+                           const std::string& error_message);
 #endif  // defined(OS_CHROMEOS)
 
   // Performs an async Read operation. Behavior is undefined if this is called
diff --git a/device/usb/usb_device_impl.cc b/device/usb/usb_device_impl.cc
index 271b631..5280699 100644
--- a/device/usb/usb_device_impl.cc
+++ b/device/usb/usb_device_impl.cc
@@ -196,7 +196,8 @@ void UsbDeviceImpl::Open(const OpenCallback& callback) {
   DCHECK(client) << "Could not get permission broker client.";
   client->OpenPath(
       device_path_,
-      base::Bind(&UsbDeviceImpl::OnOpenRequestComplete, this, callback));
+      base::Bind(&UsbDeviceImpl::OnOpenRequestComplete, this, callback),
+      base::Bind(&UsbDeviceImpl::OnOpenRequestError, this, callback));
 #else
   blocking_task_runner_->PostTask(
       FROM_HERE,
@@ -291,14 +292,18 @@ void UsbDeviceImpl::OnOpenRequestComplete(const OpenCallback& callback,
                             base::Passed(&fd), callback));
 }
 
+void UsbDeviceImpl::OnOpenRequestError(const OpenCallback& callback,
+                                       const std::string& error_name,
+                                       const std::string& error_message) {
+  USB_LOG(EVENT) << "Permission broker failed to open the device: "
+                 << error_name << ": " << error_message;
+  callback.Run(nullptr);
+}
+
 void UsbDeviceImpl::OpenOnBlockingThreadWithFd(dbus::FileDescriptor fd,
                                                const OpenCallback& callback) {
   fd.CheckValidity();
-  if (!fd.is_valid()) {
-    USB_LOG(EVENT) << "Did not get valid device handle from permission broker.";
-    task_runner_->PostTask(FROM_HERE, base::Bind(callback, nullptr));
-    return;
-  }
+  DCHECK(fd.is_valid());
 
   PlatformUsbDeviceHandle handle;
   const int rv = libusb_open_fd(platform_device_, fd.TakeValue(), &handle);
diff --git a/device/usb/usb_device_impl.h b/device/usb/usb_device_impl.h
index e41dac0..40bfd1e 100644
--- a/device/usb/usb_device_impl.h
+++ b/device/usb/usb_device_impl.h
@@ -97,6 +97,9 @@ class UsbDeviceImpl : public UsbDevice {
 #if defined(OS_CHROMEOS)
   void OnOpenRequestComplete(const OpenCallback& callback,
                              dbus::FileDescriptor fd);
+  void OnOpenRequestError(const OpenCallback& callback,
+                          const std::string& error_name,
+                          const std::string& error_message);
   void OpenOnBlockingThreadWithFd(dbus::FileDescriptor fd,
                                   const OpenCallback& callback);
 #endif