Merge "Log if keymaster IPC takes too long" (1e7a8bd4) · Commits · e / os / android_system_core

trusty/keymaster/Android.bp

+3 −0

Original line number	Diff line number	Diff line
		@@ -117,6 +117,7 @@ cc_binary {
		"libkeymint",
		"liblog",
		"libtrusty",
		"libutils",
		],
		required: [
		"android.hardware.hardware_keystore.xml",
		@@ -142,6 +143,7 @@ cc_library {
		"libtrusty",
		"libhardware",
		"libkeymaster_messages",
		"libutils",
		"libxml2",
		],
		export_include_dirs: ["include"],
		@@ -169,6 +171,7 @@ cc_binary {
		"libtrusty",
		"libhardware",
		"libkeymaster_messages",
		"libutils",
		"libxml2",
		],
		cflags: [

trusty/keymaster/ipc/trusty_keymaster_ipc.cpp

+66 −1

Original line number	Diff line number	Diff line
		@@ -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 @@ std::variant<int, std::vector<uint8_t>> trusty_keymaster_call_2(uint32_t cmd, vo
		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 @@ std::variant<int, std::vector<uint8_t>> trusty_keymaster_call_2(uint32_t cmd, vo
		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));