From 6d33a144a3161acc0c2f3b1422bbd278fef2f558 Mon Sep 17 00:00:00 2001 From: Robert Nance Date: Wed, 24 Mar 2021 13:42:22 -0700 Subject: [PATCH] SMCInvoke: Add ipc_logging to improve debuggability of use The smcinvoke processing is opaque to the secure app developer, so adding some tracing capabilities to the HLOS, Android kernel, and QTEE to make it easier to diagnose some programming errors. Change-Id: I6f71f08a2497fdb0887801724f391368502f4740 Signed-off-by: Robert Nance --- drivers/soc/qcom/smcinvoke.c | 84 ++++++++++++++++++++++++++++++++++ include/uapi/linux/smcinvoke.h | 10 +++- 2 files changed, 93 insertions(+), 1 deletion(-) diff --git a/drivers/soc/qcom/smcinvoke.c b/drivers/soc/qcom/smcinvoke.c index 3cbf9e359f2a..96cf20c352b1 100644 --- a/drivers/soc/qcom/smcinvoke.c +++ b/drivers/soc/qcom/smcinvoke.c @@ -28,6 +28,8 @@ #include #include +#include + #include "smcinvoke_object.h" #include "../../misc/qseecom_kernel.h" @@ -258,6 +260,14 @@ struct smcinvoke_mem_obj { uint64_t shmbridge_handle; }; +#define IPC_LOG_PAGE_COUNT 50 +static void *ipc_logging_context; +#define IPC_LOG(fmt, args...) \ + ipc_log_string(ipc_logging_context, \ + "[%04x:%04x] %s:%d " fmt, \ + current->pid, current->tgid, __func__, __LINE__, \ + ## args) + static void destroy_cb_server(struct kref *kref) { struct smcinvoke_server_info *server = container_of(kref, @@ -491,6 +501,8 @@ static int put_pending_cbobj_locked(uint16_t srvr_id, int16_t obj_id) return ret; } + IPC_LOG("srvr_id=0x%x obj_id=0x%x", srvr_id, obj_id); + head = &srvr_info->pending_cbobjs; list_for_each_entry(cbobj, head, list) if (cbobj->cbobj_id == obj_id) { @@ -882,6 +894,8 @@ static int32_t smcinvoke_release_mem_obj_locked(void *buf, size_t buf_len) return OBJECT_ERROR_INVALID; } + IPC_LOG("tzhandle=0x%08x", msg->hdr.tzhandle); + return release_tzhandle_locked(msg->hdr.tzhandle); } @@ -1055,6 +1069,9 @@ static void process_tzcb_req(void *buf, size_t buf_len, struct file **arr_filp) /* no need for memcpy as we did kmemdup() above */ cb_req = tmp_cb_req; + IPC_LOG("tzhandle=0x%08x op=0x%02x counts=0x%04x", + cb_req->hdr.tzhandle, cb_req->hdr.op, cb_req->hdr.counts); + cb_txn->state = SMCINVOKE_REQ_PLACED; cb_txn->cb_req = cb_req; cb_txn->cb_req_bytes = buf_len; @@ -1080,6 +1097,10 @@ static void process_tzcb_req(void *buf, size_t buf_len, struct file **arr_filp) cb_txn->txn_id = ++srvr_info->txn_id; hash_add(srvr_info->reqs_table, &cb_txn->hash, cb_txn->txn_id); mutex_unlock(&g_smcinvoke_lock); + + IPC_LOG("txn_id=%d, server_id=0x%x, cb_reqs_inflight=%d", + cb_txn->txn_id, srvr_info->server_id, cb_reqs_inflight); + /* * we need not worry that server_info will be deleted because as long * as this CBObj is served by this server, srvr_info will be valid. @@ -1141,6 +1162,12 @@ out: if (srvr_info) kref_put(&srvr_info->ref_cnt, destroy_cb_server); mutex_unlock(&g_smcinvoke_lock); + + IPC_LOG("result=%d tzhandle=0x%08x op=0x%02x counts=0x%04x, cb_reqs_inflight=%d", + cb_req->result, + cb_req->hdr.tzhandle, cb_req->hdr.op, cb_req->hdr.counts, + cb_reqs_inflight); + } static int marshal_out_invoke_req(const uint8_t *buf, uint32_t buf_size, @@ -1199,6 +1226,10 @@ static int marshal_out_invoke_req(const uint8_t *buf, uint32_t buf_size, if (ret) goto out; + IPC_LOG("OO[%d]: tzhandle=0x%x server=0x%x fd=0x%x", + i, tz_args->handle, + TZHANDLE_GET_SERVER(tz_args->handle), temp_fd); + tz_args++; } ret = 0; @@ -1390,6 +1421,9 @@ static int marshal_in_invoke_req(const struct smcinvoke_cmd_req *req, &(tz_args[i].handle)); if (ret) goto out; + IPC_LOG("OI[%d]: fd=0x%x cb_server_fd=0x%x tzhandle=0x%x", + i, args_buf[i].o.fd, args_buf[i].o.cb_server_fd, + tz_args[i].handle); tzhandles_to_release[k++] = tz_args[i].handle; } ret = 0; @@ -1424,6 +1458,9 @@ static int marshal_in_tzcb_req(const struct smcinvoke_cb_txn *cb_txn, user_req->op = tzcb_req->hdr.op; user_req->counts = tzcb_req->hdr.counts; user_req->argsize = sizeof(union smcinvoke_arg); + IPC_LOG("tzhandle=0x%x srvr_id=0x%x cbobj_id=0x%08x op=0x%02x counts=0x%04x", + tzcb_req->hdr.tzhandle, srvr_id, user_req->cbobj_id, + user_req->op, user_req->counts); FOR_ARGS(i, tzcb_req->hdr.counts, BI) { user_req_buf_offset = size_align(user_req_buf_offset, @@ -1495,6 +1532,8 @@ static int marshal_in_tzcb_req(const struct smcinvoke_cb_txn *cb_txn, ret = -EFAULT; goto out; } + IPC_LOG("OI[%d]: tzhandle=0x%x srvr_id=0x%x fd=0x%x", + i, tz_args[i].handle, srvr_id, temp_fd); } out: return ret; @@ -1545,6 +1584,8 @@ static int marshal_out_tzcb_req(const struct smcinvoke_accept *user_req, if (ret) goto out; tzhandles_to_release[i] = tz_args[i].handle; + IPC_LOG("OO[%d]: fd=0x%x cb_server_fd=0x%x tzhandle=0x%x", + i, tmp_arg.o.fd, tmp_arg.o.cb_server_fd, tz_args[i].handle); } FOR_ARGS(i, tzcb_req->hdr.counts, OI) { if (TZHANDLE_IS_CB_OBJ(tz_args[i].handle)) @@ -1871,6 +1912,9 @@ static long process_invoke_req(struct file *filp, unsigned int cmd, } out_msg = out_shm.vaddr; + IPC_LOG("tzhandle=0x%08x op=0x%02x counts=0x%04x", + tzobj->tzhandle, req.op, req.counts); + ret = marshal_in_invoke_req(&req, args_buf, tzobj->tzhandle, in_msg, inmsg_size, filp_to_release, tzhandles_to_release); if (ret) { @@ -1914,6 +1958,10 @@ static long process_invoke_req(struct file *filp, unsigned int cmd, /* Outbuf could be carrying local objs to be released. */ process_piggyback_data(out_msg, outmsg_size); out: + IPC_LOG("ret=%d result=%d tzhandle=0x%08x op=0x%02x counts=0x%04x", + ret, req.result, + tzobj->tzhandle, req.op, req.counts); + release_filp(filp_to_release, OBJECT_COUNTS_MAX_OO); if (ret) release_tzhandles(tzhandles_to_release, OBJECT_COUNTS_MAX_OO); @@ -1927,6 +1975,24 @@ out: return ret; } +static long process_log_info(struct file *filp, unsigned int cmd, + unsigned long arg) +{ + int ret = 0; + char buf[SMCINVOKE_LOG_BUF_SIZE]; + struct smcinvoke_file_data *tzobj = filp->private_data; + + ret = copy_from_user(buf, (void __user *)arg, SMCINVOKE_LOG_BUF_SIZE); + if (ret) { + pr_err("logging HLOS info copy failed\n"); + return -EFAULT; + } + buf[SMCINVOKE_LOG_BUF_SIZE - 1] = '\0'; + IPC_LOG("%s context_type=%d tzhandle=0x%08x", buf, tzobj->context_type, + tzobj->tzhandle); + return ret; +} + static long smcinvoke_ioctl(struct file *filp, unsigned int cmd, unsigned long arg) { @@ -1935,20 +2001,35 @@ static long smcinvoke_ioctl(struct file *filp, unsigned int cmd, switch (cmd) { case SMCINVOKE_IOCTL_INVOKE_REQ: ret = process_invoke_req(filp, cmd, arg); + if (ret) + IPC_LOG("cmd=SMCINVOKE_IOCTL_INVOKE_REQ ret=%ld", ret); break; case SMCINVOKE_IOCTL_ACCEPT_REQ: ret = process_accept_req(filp, cmd, arg); + if (ret) + IPC_LOG("cmd=SMCINVOKE_IOCTL_ACCEPT_REQ ret=%ld", ret); break; case SMCINVOKE_IOCTL_SERVER_REQ: ret = process_server_req(filp, cmd, arg); + if (ret) + IPC_LOG("cmd=SMCINVOKE_IOCTL_SERVER_REQ ret=%ld", ret); break; case SMCINVOKE_IOCTL_ACK_LOCAL_OBJ: ret = process_ack_local_obj(filp, cmd, arg); + if (ret) + IPC_LOG("cmd=SMCINVOKE_IOCTL_ACK_LOCAL_OBJ ret=%ld", ret); + break; + case SMCINVOKE_IOCTL_LOG: + ret = process_log_info(filp, cmd, arg); + if (ret) + IPC_LOG("cmd=SMCINVOKE_IOCTL_LOG ret=%ld", ret); break; default: ret = -ENOIOCTLCMD; + IPC_LOG("invalid cmd=%x ret=%ld", cmd, ret); break; } + return ret; } @@ -2140,11 +2221,14 @@ static struct platform_driver smcinvoke_plat_driver = { static int smcinvoke_init(void) { + ipc_logging_context = ipc_log_context_create(IPC_LOG_PAGE_COUNT, + "smcinvoke", 0); return platform_driver_register(&smcinvoke_plat_driver); } static void smcinvoke_exit(void) { + ipc_log_context_destroy(ipc_logging_context); platform_driver_unregister(&smcinvoke_plat_driver); } diff --git a/include/uapi/linux/smcinvoke.h b/include/uapi/linux/smcinvoke.h index 33649754502f..4d9b5b86fd8b 100644 --- a/include/uapi/linux/smcinvoke.h +++ b/include/uapi/linux/smcinvoke.h @@ -1,6 +1,6 @@ /* SPDX-License-Identifier: GPL-2.0-only WITH Linux-syscall-note */ /* - * Copyright (c) 2017-2020, The Linux Foundation. All rights reserved. + * Copyright (c) 2017-2021, The Linux Foundation. All rights reserved. */ #ifndef _UAPI_SMCINVOKE_H_ #define _UAPI_SMCINVOKE_H_ @@ -92,4 +92,12 @@ struct smcinvoke_server { #define SMCINVOKE_IOCTL_ACK_LOCAL_OBJ \ _IOWR(SMCINVOKE_IOC_MAGIC, 4, __s32) +/* + * smcinvoke logging buffer is for communicating with the smcinvoke driver additional + * info for debugging to be included in driver's log (if any) + */ +#define SMCINVOKE_LOG_BUF_SIZE 100 +#define SMCINVOKE_IOCTL_LOG \ + _IOC(_IOC_READ|_IOC_WRITE, SMCINVOKE_IOC_MAGIC, 255, SMCINVOKE_LOG_BUF_SIZE) + #endif /* _UAPI_SMCINVOKE_H_ */