Log if keymaster IPC takes too long
Bug: None
Test: run with very low timeout and verify it logs
Change-Id: I2818683f65c2191518373609c6171c056de55a9a
diff --git a/trusty/keymaster/Android.bp b/trusty/keymaster/Android.bp
index 7bd1d10..99d9e56 100644
--- a/trusty/keymaster/Android.bp
+++ b/trusty/keymaster/Android.bp
@@ -117,6 +117,7 @@
"libkeymint",
"liblog",
"libtrusty",
+ "libutils",
],
required: [
"android.hardware.hardware_keystore.xml",
@@ -142,6 +143,7 @@
"libtrusty",
"libhardware",
"libkeymaster_messages",
+ "libutils",
"libxml2",
],
export_include_dirs: ["include"],
@@ -169,6 +171,7 @@
"libtrusty",
"libhardware",
"libkeymaster_messages",
+ "libutils",
"libxml2",
],
cflags: [
diff --git a/trusty/keymaster/ipc/trusty_keymaster_ipc.cpp b/trusty/keymaster/ipc/trusty_keymaster_ipc.cpp
index 2d44009..5e49b69 100644
--- a/trusty/keymaster/ipc/trusty_keymaster_ipc.cpp
+++ b/trusty/keymaster/ipc/trusty_keymaster_ipc.cpp
@@ -19,6 +19,7 @@
// TODO: make this generic in libtrusty
#include <errno.h>
+#include <poll.h>
#include <stdlib.h>
#include <string.h>
#include <sys/uio.h>
@@ -33,11 +34,15 @@
#include <trusty_keymaster/ipc/keymaster_ipc.h>
#include <trusty_keymaster/ipc/trusty_keymaster_ipc.h>
+#include <utils/Timers.h>
#define TRUSTY_DEVICE_NAME "/dev/trusty-ipc-dev0"
static int handle_ = -1;
+static const int timeout_ms = 10 * 1000;
+static const int max_timeout_ms = 60 * 1000;
+
int trusty_keymaster_connect() {
int rc = tipc_connect(TRUSTY_DEVICE_NAME, KEYMASTER_PORT);
if (rc < 0) {
@@ -84,7 +89,38 @@
msg->cmd = cmd;
memcpy(msg->payload, in, in_size);
+ nsecs_t start_time_ns = systemTime(SYSTEM_TIME_MONOTONIC);
+ bool timed_out = false;
+ int poll_timeout_ms = timeout_ms;
+ while (true) {
+ struct pollfd pfd;
+ pfd.fd = handle_;
+ pfd.events = POLLOUT;
+ pfd.revents = 0;
+
+ int p = poll(&pfd, 1, poll_timeout_ms);
+ if (p == 0) {
+ ALOGW("write for cmd %d is taking more than %ld nsecs", cmd,
+ systemTime(SYSTEM_TIME_MONOTONIC) - start_time_ns);
+ timed_out = true;
+ poll_timeout_ms *= 2;
+ if (poll_timeout_ms > max_timeout_ms) {
+ poll_timeout_ms = max_timeout_ms;
+ }
+ continue;
+ } else if (p < 0) {
+ ALOGE("write poll error: %d", errno);
+ } else if (pfd.revents != POLLOUT) {
+ ALOGW("unexpected poll() result: %d", pfd.revents);
+ }
+ break;
+ }
+
ssize_t rc = write(handle_, msg, msg_size);
+ if (timed_out) {
+ ALOGW("write for cmd %d finished after %ld nsecs", cmd,
+ systemTime(SYSTEM_TIME_MONOTONIC) - start_time_ns);
+ }
free(msg);
if (rc < 0) {
@@ -122,8 +158,37 @@
return -EOVERFLOW;
}
iov[1] = {.iov_base = write_pos, .iov_len = buffer_size};
+ start_time_ns = systemTime(SYSTEM_TIME_MONOTONIC);
+ timed_out = false;
+ poll_timeout_ms = timeout_ms;
+ while (true) {
+ struct pollfd pfd;
+ pfd.fd = handle_;
+ pfd.events = POLLIN;
+ pfd.revents = 0;
+ int p = poll(&pfd, 1, poll_timeout_ms);
+ if (p == 0) {
+ ALOGW("readv for cmd %d is taking more than %ld nsecs", cmd,
+ systemTime(SYSTEM_TIME_MONOTONIC) - start_time_ns);
+ timed_out = true;
+ poll_timeout_ms *= 2;
+ if (poll_timeout_ms > max_timeout_ms) {
+ poll_timeout_ms = max_timeout_ms;
+ }
+ continue;
+ } else if (p < 0) {
+ ALOGE("read poll error: %d", errno);
+ } else if (pfd.revents != POLLIN) {
+ ALOGW("unexpected poll() result: %d", pfd.revents);
+ }
+ break;
+ }
rc = readv(handle_, iov, 2);
+ if (timed_out) {
+ ALOGW("readv for cmd %d finished after %ld nsecs", cmd,
+ systemTime(SYSTEM_TIME_MONOTONIC) - start_time_ns);
+ }
if (rc < 0) {
ALOGE("failed to retrieve response for cmd (%d) to %s: %s\n", cmd, KEYMASTER_PORT,
strerror(errno));