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

Commit 0255766d authored by Stephen Crane's avatar Stephen Crane
Browse files

storageproxyd: Add watchdog to log stuck requests 

Adds a background watchdog thread to the Trusty storageproxy to monitor
and log any requests that are delayed for too long. This is intended to
assist in recognizing and debugging any sources of hangs related to
servicing Trusty storage requests in Android.

Test: Add sleep() and run trusty storage tests
Bug: 266595872
Change-Id: I98dfaff0dff04f97d5c657ee131e746f63b39739
parent 4c80eb13

trusty/storage/proxy/Android.bp

+1 −0
Original line number Diff line number Diff line
@@ -28,6 +28,7 @@ cc_binary { 
        "rpmb.c",

        "storage.c",

        "proxy.c",

        "watchdog.cpp",

    ],



    shared_libs: [

trusty/storage/proxy/proxy.c

+26 −19
Original line number Diff line number Diff line
@@ -31,6 +31,7 @@ 
#include "log.h"

#include "rpmb.h"

#include "storage.h"

#include "watchdog.h"



#define REQ_BUFFER_SIZE 4096

static uint8_t req_buffer[REQ_BUFFER_SIZE + 1];
@@ -73,6 +74,8 @@ static void show_usage_and_exit(int code) { 
static int handle_req(struct storage_msg* msg, const void* req, size_t req_len) {

    int rc;



    struct watcher* watcher = watch_start("request", msg);



    if ((msg->flags & STORAGE_MSG_FLAG_POST_COMMIT) && msg->cmd != STORAGE_RPMB_SEND &&

        msg->cmd != STORAGE_FILE_WRITE) {

        /*
@@ -81,14 +84,14 @@ static int handle_req(struct storage_msg* msg, const void* req, size_t req_len) 
         */

        ALOGE("cmd 0x%x: post commit option is not implemented\n", msg->cmd);

        msg->result = STORAGE_ERR_UNIMPLEMENTED;

        return ipc_respond(msg, NULL, 0);

        goto err_response;

    }



    if (msg->flags & STORAGE_MSG_FLAG_PRE_COMMIT) {

        rc = storage_sync_checkpoint();

        rc = storage_sync_checkpoint(watcher);

        if (rc < 0) {

            msg->result = STORAGE_ERR_SYNC_FAILURE;

            return ipc_respond(msg, NULL, 0);

            goto err_response;

        }

    }
@@ -99,61 +102,65 @@ static int handle_req(struct storage_msg* msg, const void* req, size_t req_len) 
        if (rc != 0) {

            ALOGE("is_data_checkpoint_active failed in an unexpected way. Aborting.\n");

            msg->result = STORAGE_ERR_GENERIC;

            return ipc_respond(msg, NULL, 0);

            goto err_response;

        } else if (is_checkpoint_active) {

            ALOGE("Checkpoint in progress, dropping write ...\n");

            msg->result = STORAGE_ERR_GENERIC;

            return ipc_respond(msg, NULL, 0);

            goto err_response;

        }

    }



    switch (msg->cmd) {

        case STORAGE_FILE_DELETE:

            rc = storage_file_delete(msg, req, req_len);

            rc = storage_file_delete(msg, req, req_len, watcher);

            break;



        case STORAGE_FILE_OPEN:

            rc = storage_file_open(msg, req, req_len);

            rc = storage_file_open(msg, req, req_len, watcher);

            break;



        case STORAGE_FILE_CLOSE:

            rc = storage_file_close(msg, req, req_len);

            rc = storage_file_close(msg, req, req_len, watcher);

            break;



        case STORAGE_FILE_WRITE:

            rc = storage_file_write(msg, req, req_len);

            rc = storage_file_write(msg, req, req_len, watcher);

            break;



        case STORAGE_FILE_READ:

            rc = storage_file_read(msg, req, req_len);

            rc = storage_file_read(msg, req, req_len, watcher);

            break;



        case STORAGE_FILE_GET_SIZE:

            rc = storage_file_get_size(msg, req, req_len);

            rc = storage_file_get_size(msg, req, req_len, watcher);

            break;



        case STORAGE_FILE_SET_SIZE:

            rc = storage_file_set_size(msg, req, req_len);

            rc = storage_file_set_size(msg, req, req_len, watcher);

            break;



        case STORAGE_FILE_GET_MAX_SIZE:

            rc = storage_file_get_max_size(msg, req, req_len);

            rc = storage_file_get_max_size(msg, req, req_len, watcher);

            break;



        case STORAGE_RPMB_SEND:

            rc = rpmb_send(msg, req, req_len);

            rc = rpmb_send(msg, req, req_len, watcher);

            break;



        default:

            ALOGE("unhandled command 0x%x\n", msg->cmd);

            msg->result = STORAGE_ERR_UNIMPLEMENTED;

            rc = 1;

            goto err_response;

    }



    if (rc > 0) {

        /* still need to send response */

    /* response was sent in handler */

    goto finish;



err_response:

    rc = ipc_respond(msg, NULL, 0);

    }



finish:

    watch_finish(watcher);

    return rc;

}

trusty/storage/proxy/rpmb.c

+15 −5
Original line number Diff line number Diff line
@@ -321,7 +321,8 @@ static enum scsi_result check_sg_io_hdr(const sg_io_hdr_t* io_hdrp) { 
    return SCSI_RES_ERR;

}



static int send_mmc_rpmb_req(int mmc_fd, const struct storage_rpmb_send_req* req) {

static int send_mmc_rpmb_req(int mmc_fd, const struct storage_rpmb_send_req* req,

                             struct watcher* watcher) {

    union {

        struct mmc_ioc_multi_cmd multi;

        uint8_t raw[sizeof(struct mmc_ioc_multi_cmd) + sizeof(struct mmc_ioc_cmd) * 3];
@@ -375,14 +376,17 @@ static int send_mmc_rpmb_req(int mmc_fd, const struct storage_rpmb_send_req* req 
        cmd++;

    }



    watch_progress(watcher, "rpmb mmc ioctl");

    rc = ioctl(mmc_fd, MMC_IOC_MULTI_CMD, &mmc.multi);

    watch_progress(watcher, "rpmb mmc ioctl done");

    if (rc < 0) {

        ALOGE("%s: mmc ioctl failed: %d, %s\n", __func__, rc, strerror(errno));

    }

    return rc;

}



static int send_ufs_rpmb_req(int sg_fd, const struct storage_rpmb_send_req* req) {

static int send_ufs_rpmb_req(int sg_fd, const struct storage_rpmb_send_req* req,

                             struct watcher* watcher) {

    int rc;

    int wl_rc;

    const uint8_t* write_buf = req->payload;
@@ -410,7 +414,9 @@ static int send_ufs_rpmb_req(int sg_fd, const struct storage_rpmb_send_req* req) 
            set_sg_io_hdr(&io_hdr, SG_DXFER_TO_DEV, sizeof(out_cdb), sizeof(sense_buffer),

                          req->reliable_write_size, (void*)write_buf, (unsigned char*)&out_cdb,

                          sense_buffer);

            watch_progress(watcher, "rpmb ufs reliable write");

            rc = ioctl(sg_fd, SG_IO, &io_hdr);

            watch_progress(watcher, "rpmb ufs reliable write done");

            if (rc < 0) {

                ALOGE("%s: ufs ioctl failed: %d, %s\n", __func__, rc, strerror(errno));

                goto err_op;
@@ -435,7 +441,9 @@ static int send_ufs_rpmb_req(int sg_fd, const struct storage_rpmb_send_req* req) 
            set_sg_io_hdr(&io_hdr, SG_DXFER_TO_DEV, sizeof(out_cdb), sizeof(sense_buffer),

                          req->write_size, (void*)write_buf, (unsigned char*)&out_cdb,

                          sense_buffer);

            watch_progress(watcher, "rpmb ufs write");

            rc = ioctl(sg_fd, SG_IO, &io_hdr);

            watch_progress(watcher, "rpmb ufs write done");

            if (rc < 0) {

                ALOGE("%s: ufs ioctl failed: %d, %s\n", __func__, rc, strerror(errno));

                goto err_op;
@@ -450,7 +458,9 @@ static int send_ufs_rpmb_req(int sg_fd, const struct storage_rpmb_send_req* req) 
        sg_io_hdr_t io_hdr;

        set_sg_io_hdr(&io_hdr, SG_DXFER_FROM_DEV, sizeof(in_cdb), sizeof(sense_buffer),

                      req->read_size, read_buf, (unsigned char*)&in_cdb, sense_buffer);

        watch_progress(watcher, "rpmb ufs read");

        rc = ioctl(sg_fd, SG_IO, &io_hdr);

        watch_progress(watcher, "rpmb ufs read done");

        if (rc < 0) {

            ALOGE("%s: ufs ioctl failed: %d, %s\n", __func__, rc, strerror(errno));

        }
@@ -487,7 +497,7 @@ static int send_virt_rpmb_req(int rpmb_fd, void* read_buf, size_t read_size, con 
    return rc;

}



int rpmb_send(struct storage_msg* msg, const void* r, size_t req_len) {

int rpmb_send(struct storage_msg* msg, const void* r, size_t req_len, struct watcher* watcher) {

    int rc;

    const struct storage_rpmb_send_req* req = r;
@@ -523,13 +533,13 @@ int rpmb_send(struct storage_msg* msg, const void* r, size_t req_len) { 
    }



    if (dev_type == MMC_RPMB) {

        rc = send_mmc_rpmb_req(rpmb_fd, req);

        rc = send_mmc_rpmb_req(rpmb_fd, req, watcher);

        if (rc < 0) {

            msg->result = STORAGE_ERR_GENERIC;

            goto err_response;

        }

    } else if (dev_type == UFS_RPMB) {

        rc = send_ufs_rpmb_req(rpmb_fd, req);

        rc = send_ufs_rpmb_req(rpmb_fd, req, watcher);

        if (rc < 0) {

            ALOGE("send_ufs_rpmb_req failed: %d, %s\n", rc, strerror(errno));

            msg->result = STORAGE_ERR_GENERIC;

trusty/storage/proxy/rpmb.h

+3 −1
Original line number Diff line number Diff line
@@ -18,8 +18,10 @@ 
#include <stdint.h>

#include <trusty/interface/storage.h>



#include "watchdog.h"



enum dev_type { UNKNOWN_RPMB, MMC_RPMB, VIRT_RPMB, UFS_RPMB, SOCK_RPMB };



int rpmb_open(const char* rpmb_devname, enum dev_type dev_type);

int rpmb_send(struct storage_msg* msg, const void* r, size_t req_len);

int rpmb_send(struct storage_msg* msg, const void* r, size_t req_len, struct watcher* watcher);

void rpmb_close(void);

trusty/storage/proxy/storage.c

+44 −33
Original line number Diff line number Diff line
@@ -31,6 +31,7 @@ 
#include "ipc.h"

#include "log.h"

#include "storage.h"

#include "watchdog.h"



#define FD_TBL_SIZE 64

#define MAX_READ_SIZE 4096
@@ -180,9 +181,8 @@ static ssize_t read_with_retry(int fd, void *buf_, size_t size, off_t offset) 
    return rcnt;

}



int storage_file_delete(struct storage_msg *msg,

                        const void *r, size_t req_len)

{

int storage_file_delete(struct storage_msg* msg, const void* r, size_t req_len,

                        struct watcher* watcher) {

    char *path = NULL;

    const struct storage_file_delete_req *req = r;
@@ -208,6 +208,7 @@ int storage_file_delete(struct storage_msg *msg, 
        goto err_response;

    }



    watch_progress(watcher, "unlinking file");

    rc = unlink(path);

    if (rc < 0) {

        rc = errno;
@@ -231,8 +232,9 @@ err_response: 
    return ipc_respond(msg, NULL, 0);

}



static void sync_parent(const char* path) {

static void sync_parent(const char* path, struct watcher* watcher) {

    int parent_fd;

    watch_progress(watcher, "syncing parent");

    char* parent_path = dirname(path);

    parent_fd = TEMP_FAILURE_RETRY(open(parent_path, O_RDONLY));

    if (parent_fd >= 0) {
@@ -242,9 +244,11 @@ static void sync_parent(const char* path) { 
        ALOGE("%s: failed to open parent directory \"%s\" for sync: %s\n", __func__, parent_path,

              strerror(errno));

    }

    watch_progress(watcher, "done syncing parent");

}



int storage_file_open(struct storage_msg* msg, const void* r, size_t req_len) {

int storage_file_open(struct storage_msg* msg, const void* r, size_t req_len,

                      struct watcher* watcher) {

    char* path = NULL;

    const struct storage_file_open_req *req = r;

    struct storage_file_open_resp resp = {0};
@@ -306,7 +310,7 @@ int storage_file_open(struct storage_msg* msg, const void* r, size_t req_len) { 
            char* parent_path = dirname(path);

            rc = mkdir(parent_path, S_IRWXU);

            if (rc == 0) {

                sync_parent(parent_path);

                sync_parent(parent_path, watcher);

            } else if (errno != EEXIST) {

                ALOGE("%s: Could not create parent directory \"%s\": %s\n", __func__, parent_path,

                      strerror(errno));
@@ -347,7 +351,7 @@ int storage_file_open(struct storage_msg* msg, const void* r, size_t req_len) { 
    }



    if (open_flags & O_CREAT) {

        sync_parent(path);

        sync_parent(path, watcher);

    }

    free(path);
@@ -375,9 +379,8 @@ err_response: 
    return ipc_respond(msg, NULL, 0);

}



int storage_file_close(struct storage_msg *msg,

                       const void *r, size_t req_len)

{

int storage_file_close(struct storage_msg* msg, const void* r, size_t req_len,

                       struct watcher* watcher) {

    const struct storage_file_close_req *req = r;



    if (req_len != sizeof(*req)) {
@@ -390,7 +393,9 @@ int storage_file_close(struct storage_msg *msg, 
    int fd = remove_fd(req->handle);

    ALOGV("%s: handle = %u: fd = %u\n", __func__, req->handle, fd);



    watch_progress(watcher, "fsyncing before file close");

    int rc = fsync(fd);

    watch_progress(watcher, "done fsyncing before file close");

    if (rc < 0) {

        rc = errno;

        ALOGE("%s: fsync failed for fd=%u: %s\n",
@@ -414,10 +419,8 @@ err_response: 
    return ipc_respond(msg, NULL, 0);

}





int storage_file_write(struct storage_msg *msg,

                       const void *r, size_t req_len)

{

int storage_file_write(struct storage_msg* msg, const void* r, size_t req_len,

                       struct watcher* watcher) {

    int rc;

    const struct storage_file_write_req *req = r;
@@ -429,17 +432,20 @@ int storage_file_write(struct storage_msg *msg, 
    }



    int fd = lookup_fd(req->handle, true);

    watch_progress(watcher, "writing");

    if (write_with_retry(fd, &req->data[0], req_len - sizeof(*req),

                         req->offset) < 0) {

        watch_progress(watcher, "writing done w/ error");

        rc = errno;

        ALOGW("%s: error writing file (fd=%d): %s\n",

              __func__, fd, strerror(errno));

        msg->result = translate_errno(rc);

        goto err_response;

    }

    watch_progress(watcher, "writing done");



    if (msg->flags & STORAGE_MSG_FLAG_POST_COMMIT) {

        rc = storage_sync_checkpoint();

        rc = storage_sync_checkpoint(watcher);

        if (rc < 0) {

            msg->result = STORAGE_ERR_SYNC_FAILURE;

            goto err_response;
@@ -452,10 +458,8 @@ err_response: 
    return ipc_respond(msg, NULL, 0);

}





int storage_file_read(struct storage_msg *msg,

                      const void *r, size_t req_len)

{

int storage_file_read(struct storage_msg* msg, const void* r, size_t req_len,

                      struct watcher* watcher) {

    int rc;

    const struct storage_file_read_req *req = r;
@@ -474,8 +478,10 @@ int storage_file_read(struct storage_msg *msg, 
    }



    int fd = lookup_fd(req->handle, false);

    watch_progress(watcher, "reading");

    ssize_t read_res = read_with_retry(fd, read_rsp.hdr.data, req->size,

                                       (off_t)req->offset);

    watch_progress(watcher, "reading done");

    if (read_res < 0) {

        rc = errno;

        ALOGW("%s: error reading file (fd=%d): %s\n",
@@ -491,10 +497,8 @@ err_response: 
    return ipc_respond(msg, NULL, 0);

}





int storage_file_get_size(struct storage_msg *msg,

                          const void *r, size_t req_len)

{

int storage_file_get_size(struct storage_msg* msg, const void* r, size_t req_len,

                          struct watcher* watcher) {

    const struct storage_file_get_size_req *req = r;

    struct storage_file_get_size_resp resp = {0};
@@ -507,7 +511,9 @@ int storage_file_get_size(struct storage_msg *msg, 


    struct stat stat;

    int fd = lookup_fd(req->handle, false);

    watch_progress(watcher, "fstat");

    int rc = fstat(fd, &stat);

    watch_progress(watcher, "fstat done");

    if (rc < 0) {

        rc = errno;

        ALOGE("%s: error stat'ing file (fd=%d): %s\n",
@@ -524,10 +530,8 @@ err_response: 
    return ipc_respond(msg, NULL, 0);

}





int storage_file_set_size(struct storage_msg *msg,

                          const void *r, size_t req_len)

{

int storage_file_set_size(struct storage_msg* msg, const void* r, size_t req_len,

                          struct watcher* watcher) {

    const struct storage_file_set_size_req *req = r;



    if (req_len != sizeof(*req)) {
@@ -538,7 +542,9 @@ int storage_file_set_size(struct storage_msg *msg, 
    }



    int fd = lookup_fd(req->handle, true);

    watch_progress(watcher, "ftruncate");

    int rc = TEMP_FAILURE_RETRY(ftruncate(fd, req->size));

    watch_progress(watcher, "ftruncate done");

    if (rc < 0) {

        rc = errno;

        ALOGE("%s: error truncating file (fd=%d): %s\n",
@@ -553,7 +559,8 @@ err_response: 
    return ipc_respond(msg, NULL, 0);

}



int storage_file_get_max_size(struct storage_msg* msg, const void* r, size_t req_len) {

int storage_file_get_max_size(struct storage_msg* msg, const void* r, size_t req_len,

                              struct watcher* watcher) {

    const struct storage_file_get_max_size_req* req = r;

    struct storage_file_get_max_size_resp resp = {0};

    uint64_t max_size = 0;
@@ -566,7 +573,9 @@ int storage_file_get_max_size(struct storage_msg* msg, const void* r, size_t req 


    struct stat stat;

    int fd = lookup_fd(req->handle, false);

    watch_progress(watcher, "fstat to get max size");

    int rc = fstat(fd, &stat);

    watch_progress(watcher, "fstat to get max size done");

    if (rc < 0) {

        ALOGE("%s: error stat'ing file (fd=%d): %s\n", __func__, fd, strerror(errno));

        goto err_response;
@@ -606,10 +615,10 @@ int storage_init(const char *dirname) 
    return 0;

}



int storage_sync_checkpoint(void)

{

int storage_sync_checkpoint(struct watcher* watcher) {

    int rc;



    watch_progress(watcher, "sync fd table");

    /* sync fd table and reset it to clean state first */

    for (uint fd = 0; fd < FD_TBL_SIZE; fd++) {

         if (fd_state[fd] == SS_DIRTY) {
@@ -634,10 +643,12 @@ int storage_sync_checkpoint(void) 
         * because our fd table is large enough to handle the few open files we

         * use.

         */

         watch_progress(watcher, "all fs sync");

         sync();

         fs_state = SS_CLEAN;

    }



    watch_progress(watcher, "done syncing");



    return 0;

}