From 3bb483b196678a9cae7237c9abad3e3c7ad3781f Mon Sep 17 00:00:00 2001 From: Stephen Crane Date: Wed, 18 Aug 2021 15:10:14 -0700 Subject: [PATCH 1/3] storageproxyd: Add file handle param to debug buffer print Adds a file handle parameter to the debug print_buf function to allow printing to either stdout or stderr. Test: m storageproxyd Bug: 195544379 Change-Id: Iade322a21312a676b3599bddafdfc43b599617ea Merged-In: Iade322a21312a676b3599bddafdfc43b599617ea --- trusty/storage/proxy/rpmb.c | 19 +++++++++---------- 1 file changed, 9 insertions(+), 10 deletions(-) diff --git a/trusty/storage/proxy/rpmb.c b/trusty/storage/proxy/rpmb.c index b59fb67f6..094e5687f 100644 --- a/trusty/storage/proxy/rpmb.c +++ b/trusty/storage/proxy/rpmb.c @@ -105,17 +105,16 @@ static enum dev_type dev_type = UNKNOWN_RPMB; static const char* UFS_WAKE_LOCK_NAME = "ufs_seq_wakelock"; #ifdef RPMB_DEBUG - -static void print_buf(const char* prefix, const uint8_t* buf, size_t size) { +static void print_buf(FILE* handle, const char* prefix, const uint8_t* buf, size_t size) { size_t i; - printf("%s @%p [%zu]", prefix, buf, size); + fprintf(handle, "%s @%p [%zu]", prefix, buf, size); for (i = 0; i < size; i++) { - if (i && i % 32 == 0) printf("\n%*s", (int)strlen(prefix), ""); - printf(" %02x", buf[i]); + if (i && i % 32 == 0) fprintf(handle, "\n%*s", (int)strlen(prefix), ""); + fprintf(handle, " %02x", buf[i]); } - printf("\n"); - fflush(stdout); + fprintf(handle, "\n"); + fflush(handle); } #endif @@ -153,7 +152,7 @@ static int send_mmc_rpmb_req(int mmc_fd, const struct storage_rpmb_send_req* req mmc_ioc_cmd_set_data((*cmd), write_buf); #ifdef RPMB_DEBUG ALOGI("opcode: 0x%x, write_flag: 0x%x\n", cmd->opcode, cmd->write_flag); - print_buf("request: ", write_buf, req->reliable_write_size); + print_buf(stdout, "request: ", write_buf, req->reliable_write_size); #endif write_buf += req->reliable_write_size; mmc.multi.num_of_cmds++; @@ -169,7 +168,7 @@ static int send_mmc_rpmb_req(int mmc_fd, const struct storage_rpmb_send_req* req mmc_ioc_cmd_set_data((*cmd), write_buf); #ifdef RPMB_DEBUG ALOGI("opcode: 0x%x, write_flag: 0x%x\n", cmd->opcode, cmd->write_flag); - print_buf("request: ", write_buf, req->write_size); + print_buf(stdout, "request: ", write_buf, req->write_size); #endif write_buf += req->write_size; mmc.multi.num_of_cmds++; @@ -353,7 +352,7 @@ int rpmb_send(struct storage_msg* msg, const void* r, size_t req_len) { goto err_response; } #ifdef RPMB_DEBUG - if (req->read_size) print_buf("response: ", read_buf, req->read_size); + if (req->read_size) print_buf(stdout, "response: ", read_buf, req->read_size); #endif if (msg->flags & STORAGE_MSG_FLAG_POST_COMMIT) { From 642d977bc81dda949b4b20b7b09777f2348feae2 Mon Sep 17 00:00:00 2001 From: Stephen Crane Date: Wed, 18 Aug 2021 02:22:57 -0700 Subject: [PATCH 2/3] storageproxyd: Add logging of failed RPMB transactions Adds parsing and logging of SCSI errors from SG_IO calls for RPMB. Does not alter behavior of the RPMB proxy in response to these errors. Test: m storageproxyd Bug: 195544379 Change-Id: I928ddebcb65aa6c305d3dcab7c64bd19d11a50fa Merged-In: I928ddebcb65aa6c305d3dcab7c64bd19d11a50fa --- trusty/storage/proxy/rpmb.c | 114 +++++++++++++++++++++++++++++++++++- 1 file changed, 111 insertions(+), 3 deletions(-) diff --git a/trusty/storage/proxy/rpmb.c b/trusty/storage/proxy/rpmb.c index 094e5687f..a40105f45 100644 --- a/trusty/storage/proxy/rpmb.c +++ b/trusty/storage/proxy/rpmb.c @@ -16,7 +16,10 @@ #include #include +#include +#include #include +#include #include #include #include @@ -104,7 +107,6 @@ static enum dev_type dev_type = UNKNOWN_RPMB; static const char* UFS_WAKE_LOCK_NAME = "ufs_seq_wakelock"; -#ifdef RPMB_DEBUG static void print_buf(FILE* handle, const char* prefix, const uint8_t* buf, size_t size) { size_t i; @@ -117,8 +119,6 @@ static void print_buf(FILE* handle, const char* prefix, const uint8_t* buf, size fflush(handle); } -#endif - static void set_sg_io_hdr(sg_io_hdr_t* io_hdrp, int dxfer_direction, unsigned char cmd_len, unsigned char mx_sb_len, unsigned int dxfer_len, void* dxferp, unsigned char* cmdp, void* sbp) { @@ -134,6 +134,111 @@ static void set_sg_io_hdr(sg_io_hdr_t* io_hdrp, int dxfer_direction, unsigned ch io_hdrp->timeout = TIMEOUT; } +/* Returns false if the sense data was valid and no errors were present */ +static bool check_scsi_sense(const uint8_t* sense_buf, size_t len) { + uint8_t response_code = 0; + uint8_t sense_key = 0; + uint8_t additional_sense_code = 0; + uint8_t additional_sense_code_qualifier = 0; + uint8_t additional_length = 0; + + if (!sense_buf || len == 0) { + ALOGE("Invalid SCSI sense buffer, length: %zu\n", len); + return false; + } + + response_code = 0x7f & sense_buf[0]; + + if (response_code < 0x70 || response_code > 0x73) { + ALOGE("Invalid SCSI sense response code: %hhu\n", response_code); + return false; + } + + if (response_code >= 0x72) { + /* descriptor format, SPC-6 4.4.2 */ + if (len > 1) { + sense_key = 0xf & sense_buf[1]; + } + if (len > 2) { + additional_sense_code = sense_buf[2]; + } + if (len > 3) { + additional_sense_code_qualifier = sense_buf[3]; + } + if (len > 7) { + additional_length = sense_buf[7]; + } + } else { + /* fixed format, SPC-6 4.4.3 */ + if (len > 2) { + sense_key = 0xf & sense_buf[2]; + } + if (len > 7) { + additional_length = sense_buf[7]; + } + if (len > 12) { + additional_sense_code = sense_buf[12]; + } + if (len > 13) { + additional_sense_code_qualifier = sense_buf[13]; + } + } + + switch (sense_key) { + case NO_SENSE: + case 0x0f: /* COMPLETED, not present in kernel headers */ + ALOGD("SCSI success with sense data: key=%hhu, asc=%hhu, ascq=%hhu\n", sense_key, + additional_sense_code, additional_sense_code_qualifier); + return true; + } + + ALOGE("Unexpected SCSI sense data: key=%hhu, asc=%hhu, ascq=%hhu\n", sense_key, + additional_sense_code, additional_sense_code_qualifier); + print_buf(stderr, "sense buffer: ", sense_buf, len); + return false; +} + +static void check_sg_io_hdr(const sg_io_hdr_t* io_hdrp) { + if (io_hdrp->status == 0 && io_hdrp->host_status == 0 && io_hdrp->driver_status == 0) { + return; + } + + if (io_hdrp->status & 0x01) { + ALOGE("SG_IO received unknown status, LSB is set: %hhu", io_hdrp->status); + } + + if (io_hdrp->masked_status != GOOD && io_hdrp->sb_len_wr > 0) { + bool sense_error = check_scsi_sense(io_hdrp->sbp, io_hdrp->sb_len_wr); + if (sense_error) { + ALOGE("Unexpected SCSI sense. masked_status: %hhu, host_status: %hu, driver_status: " + "%hu\n", + io_hdrp->masked_status, io_hdrp->host_status, io_hdrp->driver_status); + return; + } + } + + switch (io_hdrp->masked_status) { + case GOOD: + break; + case CHECK_CONDITION: + /* handled by check_sg_sense above */ + break; + default: + ALOGE("SG_IO failed with masked_status: %hhu, host_status: %hu, driver_status: %hu\n", + io_hdrp->masked_status, io_hdrp->host_status, io_hdrp->driver_status); + return; + } + + if (io_hdrp->host_status != 0) { + ALOGE("SG_IO failed with host_status: %hu, driver_status: %hu\n", io_hdrp->host_status, + io_hdrp->driver_status); + } + + if (io_hdrp->resid != 0) { + ALOGE("SG_IO resid was non-zero: %d\n", io_hdrp->resid); + } +} + static int send_mmc_rpmb_req(int mmc_fd, const struct storage_rpmb_send_req* req) { struct { struct mmc_ioc_multi_cmd multi; @@ -224,6 +329,7 @@ static int send_ufs_rpmb_req(int sg_fd, const struct storage_rpmb_send_req* req) ALOGE("%s: ufs ioctl failed: %d, %s\n", __func__, rc, strerror(errno)); goto err_op; } + check_sg_io_hdr(&io_hdr); write_buf += req->reliable_write_size; } @@ -238,6 +344,7 @@ static int send_ufs_rpmb_req(int sg_fd, const struct storage_rpmb_send_req* req) ALOGE("%s: ufs ioctl failed: %d, %s\n", __func__, rc, strerror(errno)); goto err_op; } + check_sg_io_hdr(&io_hdr); write_buf += req->write_size; } @@ -251,6 +358,7 @@ static int send_ufs_rpmb_req(int sg_fd, const struct storage_rpmb_send_req* req) if (rc < 0) { ALOGE("%s: ufs ioctl failed: %d, %s\n", __func__, rc, strerror(errno)); } + check_sg_io_hdr(&io_hdr); } err_op: From f64722182782e4fe05caf6258abc75c69f9652b4 Mon Sep 17 00:00:00 2001 From: Stephen Crane Date: Tue, 14 Sep 2021 14:20:01 -0700 Subject: [PATCH 3/3] [storageproxyd] Dump binary buffers to log instead of stderr Rewrites the buffer logging to print to the Android log instead of stderr. The storageproxyd service is started by init and stderr is not logged anywhere. Because we want to log sense data errors under normal operation, we need to log to logcat instead of stderr. Test: Define RPMB_DEBUG, build for qemu-trusty, run, inspect logcat Bug: 195544379 Change-Id: Iecc0d4680420bb92c94be628789093888a2f1941 Merged-In: Iecc0d4680420bb92c94be628789093888a2f1941 --- trusty/storage/proxy/rpmb.c | 67 +++++++++++++++++++++++++++++++------ 1 file changed, 56 insertions(+), 11 deletions(-) diff --git a/trusty/storage/proxy/rpmb.c b/trusty/storage/proxy/rpmb.c index a40105f45..48e164124 100644 --- a/trusty/storage/proxy/rpmb.c +++ b/trusty/storage/proxy/rpmb.c @@ -107,16 +107,61 @@ static enum dev_type dev_type = UNKNOWN_RPMB; static const char* UFS_WAKE_LOCK_NAME = "ufs_seq_wakelock"; -static void print_buf(FILE* handle, const char* prefix, const uint8_t* buf, size_t size) { +/** + * log_buf - Log a byte buffer to the android log. + * @priority: One of ANDROID_LOG_* priority levels from android_LogPriority in + * android/log.h + * @prefix: A null-terminated string that identifies this buffer. Must be less + * than 128 bytes. + * @buf: Buffer to dump. + * @size: Length of @buf in bytes. + */ +#define LOG_BUF_SIZE 256 +static int log_buf(int priority, const char* prefix, const uint8_t* buf, size_t size) { + int rc; size_t i; + char line[LOG_BUF_SIZE] = {0}; + char* cur = line; - fprintf(handle, "%s @%p [%zu]", prefix, buf, size); - for (i = 0; i < size; i++) { - if (i && i % 32 == 0) fprintf(handle, "\n%*s", (int)strlen(prefix), ""); - fprintf(handle, " %02x", buf[i]); + rc = snprintf(line, LOG_BUF_SIZE, "%s @%p [%zu]", prefix, buf, size); + if (rc < 0 || rc >= LOG_BUF_SIZE) { + goto err; + } + cur += rc; + for (i = 0; i < size; i++) { + if (i % 32 == 0) { + /* + * Flush the line out to the log after we have printed 32 bytes + * (also flushes the header line on the first iteration and sets up + * for printing the buffer itself) + */ + LOG_PRI(priority, LOG_TAG, "%s", line); + memset(line, 0, LOG_BUF_SIZE); + cur = line; + /* Shift output over by the length of the prefix */ + rc = snprintf(line, LOG_BUF_SIZE, "%*s", (int)strlen(prefix), ""); + if (rc < 0 || rc >= LOG_BUF_SIZE) { + goto err; + } + cur += rc; + } + rc = snprintf(cur, LOG_BUF_SIZE - (cur - line), "%02x ", buf[i]); + if (rc < 0 || rc >= LOG_BUF_SIZE - (cur - line)) { + goto err; + } + cur += rc; + } + LOG_PRI(priority, LOG_TAG, "%s", line); + + return 0; + +err: + if (rc < 0) { + return rc; + } else { + ALOGE("log_buf prefix was too long"); + return -1; } - fprintf(handle, "\n"); - fflush(handle); } static void set_sg_io_hdr(sg_io_hdr_t* io_hdrp, int dxfer_direction, unsigned char cmd_len, @@ -194,7 +239,7 @@ static bool check_scsi_sense(const uint8_t* sense_buf, size_t len) { ALOGE("Unexpected SCSI sense data: key=%hhu, asc=%hhu, ascq=%hhu\n", sense_key, additional_sense_code, additional_sense_code_qualifier); - print_buf(stderr, "sense buffer: ", sense_buf, len); + log_buf(ANDROID_LOG_ERROR, "sense buffer: ", sense_buf, len); return false; } @@ -257,7 +302,7 @@ static int send_mmc_rpmb_req(int mmc_fd, const struct storage_rpmb_send_req* req mmc_ioc_cmd_set_data((*cmd), write_buf); #ifdef RPMB_DEBUG ALOGI("opcode: 0x%x, write_flag: 0x%x\n", cmd->opcode, cmd->write_flag); - print_buf(stdout, "request: ", write_buf, req->reliable_write_size); + log_buf(ANDROID_LOG_INFO, "request: ", write_buf, req->reliable_write_size); #endif write_buf += req->reliable_write_size; mmc.multi.num_of_cmds++; @@ -273,7 +318,7 @@ static int send_mmc_rpmb_req(int mmc_fd, const struct storage_rpmb_send_req* req mmc_ioc_cmd_set_data((*cmd), write_buf); #ifdef RPMB_DEBUG ALOGI("opcode: 0x%x, write_flag: 0x%x\n", cmd->opcode, cmd->write_flag); - print_buf(stdout, "request: ", write_buf, req->write_size); + log_buf(ANDROID_LOG_INFO, "request: ", write_buf, req->write_size); #endif write_buf += req->write_size; mmc.multi.num_of_cmds++; @@ -460,7 +505,7 @@ int rpmb_send(struct storage_msg* msg, const void* r, size_t req_len) { goto err_response; } #ifdef RPMB_DEBUG - if (req->read_size) print_buf(stdout, "response: ", read_buf, req->read_size); + if (req->read_size) log_buf(ANDROID_LOG_INFO, "response: ", read_buf, req->read_size); #endif if (msg->flags & STORAGE_MSG_FLAG_POST_COMMIT) {