Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 08fec49a authored by Marco Nelissen's avatar Marco Nelissen
Browse files

Log if keymaster IPC takes too long 

Bug: None
Test: run with very low timeout and verify it logs
Change-Id: I2818683f65c2191518373609c6171c056de55a9a
parent d08b1f77

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));