recipes-connectivity/libnvme/libnvme/0010-mi-trace-NVMe-MI-command-request-after-failure.patch

From cc62162c773f0ba84840ddbd8c62bcd59defda1b Mon Sep 17 00:00:00 2001
From: Jinliang Wang <jinliangw@google.com>
Date: Thu, 26 Oct 2023 15:49:34 -0700
Subject: [PATCH] mi: trace NVMe-MI command request after failure

Print command request detail to help debug.

Patch Tracking Bug: b/311315898
Upstream info / review: N/A
Upstream-Status: Pending
Justification: Improve NVMe-MI debuggability

Signed-off-by: Jinliang Wang <jinliangw@google.com>
---
 src/nvme/mi.c | 75 +++++++++++++++++++++++++++++++++++++++++++++------
 1 file changed, 67 insertions(+), 8 deletions(-)

diff --git a/src/nvme/mi.c b/src/nvme/mi.c
index cd129be..01f2a86 100644
--- a/src/nvme/mi.c
+++ b/src/nvme/mi.c
@@ -378,10 +378,61 @@ static int nvme_mi_verify_resp_mic(struct nvme_mi_resp *resp)
 	return resp->mic != ~crc;
 }
 
+#define GET_MI_MSG_TYPE(x) ((x >> 3) & 0xF)
+static void nvme_mi_trace_request(nvme_mi_ep_t ep,
+								  const struct nvme_mi_req *req, int rc,
+								  int error_no, const struct timespec *submit_time)
+{
+	struct timespec complete_time = {0, 0};
+	struct timespec elapsed = {0, 0};
+	struct nvme_mi_admin_req_hdr *admin_req_hdr = NULL;
+	struct nvme_mi_mi_req_hdr *mi_req_hdr = NULL;
+
+	clock_gettime(CLOCK_MONOTONIC, &complete_time);
+
+	timespec_sub(&complete_time, submit_time, &elapsed);
+
+	if (req->hdr->type == NVME_MI_MSGTYPE_NVME &&
+		GET_MI_MSG_TYPE(req->hdr->nmp) == NVME_MI_MT_ADMIN)
+	{
+		admin_req_hdr = (struct nvme_mi_admin_req_hdr *)req->hdr;
+		nvme_mi_msg(ep, LOG_WARNING,
+					"Admin op:0x%02x, cdw(1:0x%x, 10:0x%x, 11:0x%x,"
+					" 12:0x%x 13:0x%x, 14:0x%x, 15:0x%x) "
+					"T:%dms, elapsed:%dms, rc:%d, errno:%d\n",
+					admin_req_hdr->opcode,
+					admin_req_hdr->cdw1,
+					admin_req_hdr->cdw10,
+					admin_req_hdr->cdw11,
+					admin_req_hdr->cdw12,
+					admin_req_hdr->cdw13,
+					admin_req_hdr->cdw14,
+					admin_req_hdr->cdw15,
+					ep->timeout,
+					(int)(elapsed.tv_sec * 1000 + elapsed.tv_nsec / 1000000),
+					rc, error_no);
+	}
+	else if (req->hdr->type == NVME_MI_MSGTYPE_NVME &&
+			 GET_MI_MSG_TYPE(req->hdr->nmp) == NVME_MI_MT_MI)
+	{
+		mi_req_hdr = (struct nvme_mi_mi_req_hdr *)req->hdr;
+		nvme_mi_msg(ep, LOG_WARNING,
+					"MI op:0x%02x, cdw0:0x%x, cdw1:0x%x T:%dms, elapsed:%dms"
+					", rc:%d, errno:%d\n",
+					mi_req_hdr->opcode,
+					mi_req_hdr->cdw0,
+					mi_req_hdr->cdw1,
+					ep->timeout,
+					(int)(elapsed.tv_sec * 1000 + elapsed.tv_nsec / 1000000),
+					rc, error_no);
+	}
+}
+
 int nvme_mi_submit(nvme_mi_ep_t ep, struct nvme_mi_req *req,
 		   struct nvme_mi_resp *resp)
 {
 	int rc;
+	struct timespec submit_time = {0, 0};
 
 	if (req->hdr_len < sizeof(struct nvme_mi_msg_hdr)) {
 		errno = EINVAL;
@@ -419,6 +470,8 @@ int nvme_mi_submit(nvme_mi_ep_t ep, struct nvme_mi_req *req,
 	if (nvme_mi_ep_has_quirk(ep, NVME_QUIRK_MIN_INTER_COMMAND_TIME))
 		nvme_mi_insert_delay(ep);
 
+	clock_gettime(CLOCK_MONOTONIC, &submit_time);
+
 	rc = ep->transport->submit(ep, req, resp);
 
 	if (nvme_mi_ep_has_quirk(ep, NVME_QUIRK_MIN_INTER_COMMAND_TIME))
@@ -426,14 +479,14 @@ int nvme_mi_submit(nvme_mi_ep_t ep, struct nvme_mi_req *req,
 
 	if (rc) {
 		nvme_mi_msg(ep, LOG_INFO, "transport failure\n");
-		return rc;
+		goto submit_return;
 	}
 
 	if (ep->transport->mic_enabled) {
 		rc = nvme_mi_verify_resp_mic(resp);
 		if (rc) {
 			nvme_mi_msg(ep, LOG_ERR, "crc mismatch\n");
-			return rc;
+			goto submit_return;
 		}
 	}
 
@@ -442,21 +495,24 @@ int nvme_mi_submit(nvme_mi_ep_t ep, struct nvme_mi_req *req,
 		nvme_mi_msg(ep, LOG_ERR,
 			 "Bad response header len: %zd\n", resp->hdr_len);
 		errno = EPROTO;
-		return -1;
+		rc = -1;
+		goto submit_return;
 	}
 
 	if (resp->hdr->type != NVME_MI_MSGTYPE_NVME) {
 		nvme_mi_msg(ep, LOG_ERR,
 			 "Invalid message type 0x%02x\n", resp->hdr->type);
 		errno = EPROTO;
-		return -1;
+		rc = -1;
+		goto submit_return;
 	}
 
 	if (!(resp->hdr->nmp & (NVME_MI_ROR_RSP << 7))) {
 		nvme_mi_msg(ep, LOG_ERR,
 			 "ROR value in response indicates a request\n");
 		errno = EIO;
-		return -1;
+		rc = -1;
+		goto submit_return;
 	}
 
 	if ((resp->hdr->nmp & 0x1) != (req->hdr->nmp & 0x1)) {
@@ -465,10 +521,13 @@ int nvme_mi_submit(nvme_mi_ep_t ep, struct nvme_mi_req *req,
 			 req->hdr->nmp & 0x1,
 			 resp->hdr->nmp & 0x1);
 		errno = EIO;
-		return -1;
+		rc = -1;
+		goto submit_return;
 	}
-
-	return 0;
+submit_return:
+	if (rc)
+		nvme_mi_trace_request(ep, req, rc, errno, &submit_time);
+	return rc;
 }
 
 static void nvme_mi_admin_init_req(struct nvme_mi_req *req,
-- 
2.45.0.rc1.225.g2a3ae87e7f-goog