From dc0be68106295bd26ea3ecfa436080f3e27c3828 Mon Sep 17 00:00:00 2001
From: Drew Fisher <zarvox@google.com>
Date: Tue, 30 Apr 2019 17:40:12 +0000
Subject: [PATCH] [devmgr] Add more logging around driver binding
We suspect that something may be causing occasional deadlock around the
time that we attempt to bind the zxcrypt driver. Add more logging, and
increase verbosity in a couple places to see if we can narrow down where
we're going awry.
DNO-492 #comment
TEST: no behavioral change, just more logging
Change-Id: Ib03af33da1d67533599c80e4453ef27dc160950e
---
zircon/system/core/devmgr/devcoordinator/device.cpp | 4 +++-
zircon/system/core/devmgr/devhost/devhost.cpp | 5 +++++
zircon/system/core/devmgr/devhost/rpc-server.cpp | 7 +++++++
3 files changed, 15 insertions(+), 1 deletion(-)
diff --git a/zircon/system/core/devmgr/devcoordinator/device.cpp b/zircon/system/core/devmgr/devcoordinator/device.cpp
index abac8991e19..14c26330150 100644
--- a/zircon/system/core/devmgr/devcoordinator/device.cpp
+++ b/zircon/system/core/devmgr/devcoordinator/device.cpp
@@ -536,7 +536,9 @@ static zx_status_t fidl_BindDevice(void* ctx, const char* driver_path_data, size
log(ERROR, "devcoordinator: rpc: bind-device '%s' forbidden in suspend\n", dev->name().data());
return fuchsia_device_manager_CoordinatorBindDevice_reply(txn, ZX_ERR_BAD_STATE);
}
- log(RPC_IN, "devcoordinator: rpc: bind-device '%s'\n", dev->name().data());
+ // Made this log at ERROR instead of RPC_IN to help debug DNO-492; we should
+ // take it back down when done with that bug.
+ log(ERROR, "devcoordinator: rpc: bind-device '%s'\n", dev->name().data());
zx_status_t status = dev->coordinator->BindDevice(dev, driver_path, false /* new device */);
return fuchsia_device_manager_CoordinatorBindDevice_reply(txn, status);
}
diff --git a/zircon/system/core/devmgr/devhost/devhost.cpp b/zircon/system/core/devmgr/devhost/devhost.cpp
index e6a51b30e2f..bef9e0a1898 100644
--- a/zircon/system/core/devmgr/devhost/devhost.cpp
+++ b/zircon/system/core/devmgr/devhost/devhost.cpp
@@ -549,6 +549,11 @@ static zx_status_t fidl_BindDriver(void* raw_ctx, const char* driver_path_data,
zx::vmo driver_vmo(raw_driver_vmo);
fbl::StringPiece driver_path(driver_path_data, driver_path_size);
+ // TODO: added to help debug DNO-492, remove when done
+ if (driver_path == "/boot/driver/zxcrypt.so") {
+ log(ERROR, "devhost[%s] bind zxcrypt\n", ctx->path);
+ }
+
// TODO: api lock integration
log(RPC_IN, "devhost[%s] bind driver '%.*s'\n", ctx->path, static_cast<int>(driver_path_size),
driver_path_data);
diff --git a/zircon/system/core/devmgr/devhost/rpc-server.cpp b/zircon/system/core/devmgr/devhost/rpc-server.cpp
index 99e3f86eb2d..ead3d34f2e5 100644
--- a/zircon/system/core/devmgr/devhost/rpc-server.cpp
+++ b/zircon/system/core/devmgr/devhost/rpc-server.cpp
@@ -23,6 +23,7 @@
#include <zircon/device/vfs.h>
#include <zircon/processargs.h>
+#include <zircon/status.h>
#include <zircon/syscalls.h>
#include <zircon/types.h>
@@ -583,10 +584,16 @@ static zx_status_t fidl_DeviceControllerBind(void* ctx, const char* driver_data,
memcpy(drv_libname, driver_data, driver_count);
drv_libname[driver_count] = 0;
+ // TODO(DNO-492): additional logging for debugging what looks like a
+ // deadlock. Remove once bug is resolved.
+ printf("DeviceControllerBind running: %s\n", drv_libname);
// TODO(ZX-3431): We ignore the status from device_bind() for
// bug-compatibility reasons. Once this bug is resolved, we can return the
// actual status.
__UNUSED zx_status_t status = device_bind(conn->dev, drv_libname);
+ // TODO(DNO-492): additional logging for debugging what looks like a
+ // deadlock. Remove once bug is resolved.
+ printf("DeviceControllerBind finished: %s %s\n", drv_libname, zx_status_get_string(status));
return fuchsia_device_ControllerBind_reply(txn, ZX_OK);
}
--
GitLab