libnvme: Improve libnvme-mi debuggability
Tested:
Before this fix, we only have limited error message:
crc mismatch
After this fix, we have the net/eid/request/timing/rc/errno info:
[mctp: net 1 eid 12] crc mismatch
[mctp: net 1 eid 12] Admin op:0x02, cdw(1:0x0, 10:0x3ff80d8, 11:0x0, 12:0x200 13:0x0, 14:0x0, 15:0x0) T:5000ms, elapsed:333ms, rc:1, errno:0
[mctp: net 1 eid 13] crc mismatch
[mctp: net 1 eid 13] MI op:0x01, cdw0:0x0, cdw1:0x80000000 T:5000ms, elapsed:247ms, rc:1, errno:0
[network: 1, EID: 13 | bus: 8, address: 0x35] fail to subsystem_health_status_poll: More Processing Required
error reading ctemp from subsystem, reason:Bad message
[mctp: net 1 eid 13] Timeout on MCTP socket
[mctp: net 1 eid 13] Admin op:0x02, cdw(1:0x0, 10:0x3ff80d8, 11:0x0, 12:0x2200 13:0x0, 14:0x0, 15:0x0) T:5000ms, elapsed:5005ms, rc:-1, errno:110
[network: 1, EID: 13 | bus: 8, address: 0x35]failed to nvme_mi_admin_xfer
fail to GetLogPage: Connection timed out
Fusion-link: http://fusion2/15f61579-6b22-3afa-bb92-aac5e92dfe83
Google-Bug-Id: 339022737
Change-Id: I6a0bc1ec76a65276717b49cca7a738f11c81c24c
Signed-off-by: Jinliang Wang <jinliangw@google.com>
diff --git a/recipes-connectivity/libnvme/libnvme/0007-mi-check-and-print-OOB-NVMe-MI-command-execution-tim.patch b/recipes-connectivity/libnvme/libnvme/0007-mi-check-and-print-OOB-NVMe-MI-command-execution-tim.patch
deleted file mode 100644
index ecec32e..0000000
--- a/recipes-connectivity/libnvme/libnvme/0007-mi-check-and-print-OOB-NVMe-MI-command-execution-tim.patch
+++ /dev/null
@@ -1,106 +0,0 @@
-From e825dd67cd8bb02a1da8faefd244b2a50dc62dbc 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: check and print OOB NVMe-MI command execution time
-
-Check command execution time, if it exceeds WARNING_THRESHOLD
-(3 seconds), print a warning message about the command.
-
-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 | 61 +++++++++++++++++++++++++++++++++++++++++++++++++++
- 1 file changed, 61 insertions(+)
-
-diff --git a/src/nvme/mi.c b/src/nvme/mi.c
-index a41f786..4c5e5eb 100644
---- a/src/nvme/mi.c
-+++ b/src/nvme/mi.c
-@@ -378,10 +378,63 @@ 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)
-+#define WARNING_THRESHOLD 3 /* seconds */
-+static void check_execution_time(nvme_mi_ep_t ep,
-+ const struct nvme_mi_req *req,
-+ const struct timespec *submit_time)
-+{
-+ struct timespec complete_time = {0, 0};
-+ struct timespec deta_time = {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, &deta_time);
-+ if (deta_time.tv_sec >= WARNING_THRESHOLD)
-+ {
-+ 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_msg(ep->root, LOG_WARNING,
-+ "%s, 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\n",
-+ nvme_mi_endpoint_desc(ep),
-+ 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)(deta_time.tv_sec * 1000 + deta_time.tv_nsec / 1000000));
-+ }
-+ 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_msg(ep->root, LOG_WARNING,
-+ "%s, MI op:0x%02x, cdw0:0x%x, cdw1:0x%x T:%dms, elapsed:%dms\n",
-+ nvme_mi_endpoint_desc(ep),
-+ mi_req_hdr->opcode,
-+ mi_req_hdr->cdw0,
-+ mi_req_hdr->cdw1,
-+ ep->timeout,
-+ (int)(deta_time.tv_sec * 1000 + deta_time.tv_nsec / 1000000));
-+ }
-+ }
-+}
-+
- 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,8 +472,16 @@ 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 ((rc == 0) || (errno == ETIMEDOUT))
-+ {
-+ /* We are interested on commands which succeed or timed out*/
-+ check_execution_time(ep, req, &submit_time);
-+ }
-+
- if (nvme_mi_ep_has_quirk(ep, NVME_QUIRK_MIN_INTER_COMMAND_TIME))
- nvme_mi_record_resp_time(ep);
-
---
-2.43.0.rc0.421.g78406f8d94-goog
-
diff --git a/recipes-connectivity/libnvme/libnvme/0007-mi-use-more-reasonable-log-level.patch b/recipes-connectivity/libnvme/libnvme/0007-mi-use-more-reasonable-log-level.patch
new file mode 100644
index 0000000..2a1ec12
--- /dev/null
+++ b/recipes-connectivity/libnvme/libnvme/0007-mi-use-more-reasonable-log-level.patch
@@ -0,0 +1,140 @@
+From f5f926f50b026ecb65a5d076c5183a5d92d021d5 Mon Sep 17 00:00:00 2001
+From: Jinliang Wang <jinliangw@google.com>
+Date: Fri, 3 May 2024 14:41:18 -0700
+Subject: [PATCH] mi: use more reasonable log level
+
+Most of these conditions should belong to ERROR category.
+
+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-mctp.c | 10 +++++-----
+ src/nvme/mi.c | 16 ++++++++--------
+ 2 files changed, 13 insertions(+), 13 deletions(-)
+
+diff --git a/src/nvme/mi-mctp.c b/src/nvme/mi-mctp.c
+index a083157..cb77d0d 100644
+--- a/src/nvme/mi-mctp.c
++++ b/src/nvme/mi-mctp.c
+@@ -331,13 +331,13 @@ retry:
+ goto retry;
+ errno_save = errno;
+ nvme_msg(ep->root, LOG_ERR,
+- "Failed polling on MCTP socket: %m");
++ "Failed polling on MCTP socket: %m\n");
+ errno = errno_save;
+ goto out;
+ }
+
+ if (rc == 0) {
+- nvme_msg(ep->root, LOG_DEBUG, "Timeout on MCTP socket");
++ nvme_msg(ep->root, LOG_ERR, "Timeout on MCTP socket\n");
+ errno = ETIMEDOUT;
+ rc = -1;
+ goto out;
+@@ -356,7 +356,7 @@ retry:
+
+
+ if (len == 0) {
+- nvme_msg(ep->root, LOG_WARNING, "No data from MCTP endpoint\n");
++ nvme_msg(ep->root, LOG_ERR, "No data from MCTP endpoint\n");
+ errno = EIO;
+ goto out;
+ }
+@@ -378,7 +378,7 @@ retry:
+
+ /* We can't have header/payload data that isn't a multiple of 4 bytes */
+ if (len & 0x3) {
+- nvme_msg(ep->root, LOG_WARNING,
++ nvme_msg(ep->root, LOG_ERR,
+ "Response message has unaligned length (%zd)!\n",
+ len);
+ errno = EPROTO;
+@@ -391,7 +391,7 @@ retry:
+ * to keep the tag allocated and retry the recvmsg
+ */
+ if (nvme_mi_mctp_resp_is_mpr(resp, len, mic, &mpr_time)) {
+- nvme_msg(ep->root, LOG_DEBUG,
++ nvme_msg(ep->root, LOG_NOTICE,
+ "Received More Processing Required, waiting for response\n");
+
+ /* if the controller hasn't set MPRT, fall back to our command/
+diff --git a/src/nvme/mi.c b/src/nvme/mi.c
+index a41f786..aa79599 100644
+--- a/src/nvme/mi.c
++++ b/src/nvme/mi.c
+@@ -184,7 +184,7 @@ void nvme_mi_ep_probe(struct nvme_mi_ep *ep)
+ char tmp[sizeof(id.mn) + 1];
+
+ nvme_mi_format_mn(&id, tmp);
+- nvme_msg(ep->root, LOG_DEBUG,
++ nvme_msg(ep->root, LOG_NOTICE,
+ "device %02x:%s: applying quirks 0x%08lx\n",
+ id.vid, tmp, ep->quirks);
+ }
+@@ -432,35 +432,35 @@ int nvme_mi_submit(nvme_mi_ep_t ep, struct nvme_mi_req *req,
+ if (ep->transport->mic_enabled) {
+ rc = nvme_mi_verify_resp_mic(resp);
+ if (rc) {
+- nvme_msg(ep->root, LOG_WARNING, "crc mismatch\n");
++ nvme_msg(ep->root, LOG_ERR, "crc mismatch\n");
+ return rc;
+ }
+ }
+
+ /* basic response checks */
+ if (resp->hdr_len < sizeof(struct nvme_mi_msg_hdr)) {
+- nvme_msg(ep->root, LOG_DEBUG,
++ nvme_msg(ep->root, LOG_ERR,
+ "Bad response header len: %zd\n", resp->hdr_len);
+ errno = EPROTO;
+ return -1;
+ }
+
+ if (resp->hdr->type != NVME_MI_MSGTYPE_NVME) {
+- nvme_msg(ep->root, LOG_DEBUG,
++ nvme_msg(ep->root, LOG_ERR,
+ "Invalid message type 0x%02x\n", resp->hdr->type);
+ errno = EPROTO;
+ return -1;
+ }
+
+ if (!(resp->hdr->nmp & (NVME_MI_ROR_RSP << 7))) {
+- nvme_msg(ep->root, LOG_DEBUG,
++ nvme_msg(ep->root, LOG_ERR,
+ "ROR value in response indicates a request\n");
+ errno = EIO;
+ return -1;
+ }
+
+ if ((resp->hdr->nmp & 0x1) != (req->hdr->nmp & 0x1)) {
+- nvme_msg(ep->root, LOG_WARNING,
++ nvme_msg(ep->root, LOG_ERR,
+ "Command slot mismatch: req %d, resp %d\n",
+ req->hdr->nmp & 0x1,
+ resp->hdr->nmp & 0x1);
+@@ -1431,7 +1431,7 @@ int nvme_mi_mi_read_mi_data_subsys(nvme_mi_ep_t ep,
+ return rc;
+
+ if (len != sizeof(*s)) {
+- nvme_msg(ep->root, LOG_WARNING,
++ nvme_msg(ep->root, LOG_ERR,
+ "MI read data length mismatch: "
+ "got %zd bytes, expected %zd\n",
+ len, sizeof(*s));
+@@ -1537,7 +1537,7 @@ int nvme_mi_mi_subsystem_health_status_poll(nvme_mi_ep_t ep, bool clear,
+ return resp_hdr.status;
+
+ if (resp.data_len != sizeof(*sshs)) {
+- nvme_msg(ep->root, LOG_WARNING,
++ nvme_msg(ep->root, LOG_ERR,
+ "MI Subsystem Health Status length mismatch: "
+ "got %zd bytes, expected %zd\n",
+ resp.data_len, sizeof(*sshs));
+--
+2.45.0.rc1.225.g2a3ae87e7f-goog
+
diff --git a/recipes-connectivity/libnvme/libnvme/0008-mi-add-nvme_mi_msg-marco-to-print-MCTP-endpoint-desc.patch b/recipes-connectivity/libnvme/libnvme/0008-mi-add-nvme_mi_msg-marco-to-print-MCTP-endpoint-desc.patch
new file mode 100644
index 0000000..d50cdfd
--- /dev/null
+++ b/recipes-connectivity/libnvme/libnvme/0008-mi-add-nvme_mi_msg-marco-to-print-MCTP-endpoint-desc.patch
@@ -0,0 +1,104 @@
+From 82d0f27eeb36c71aa0cb7fc11d7e51cd5fcf026e Mon Sep 17 00:00:00 2001
+From: Jinliang Wang <jinliangw@google.com>
+Date: Fri, 3 May 2024 15:29:52 -0700
+Subject: [PATCH] mi: add nvme_mi_msg marco to print MCTP endpoint description
+
+Typical libnvme-mi application will open multiple MCTP endpoints, so
+it's necessary to know the debug or error message comes from which
+MCTP endpoint.
+
+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/log.c | 16 +++++++++++++---
+ src/nvme/private.h | 16 +++++++++++++---
+ 2 files changed, 26 insertions(+), 6 deletions(-)
+
+diff --git a/src/nvme/log.c b/src/nvme/log.c
+index e4697df..9b2cb70 100644
+--- a/src/nvme/log.c
++++ b/src/nvme/log.c
+@@ -26,8 +26,8 @@
+ #define LOG_CLOCK CLOCK_MONOTONIC
+ #endif
+
+-void __attribute__((format(printf, 4, 5)))
+-__nvme_msg(nvme_root_t r, int lvl,
++void __attribute__((format(printf, 5, 6)))
++__nvme_msg(nvme_root_t r, nvme_mi_ep_t ep, int lvl,
+ const char *func, const char *format, ...)
+ {
+ FILE *fp = r ? r->fp : stderr;
+@@ -45,6 +45,7 @@ __nvme_msg(nvme_root_t r, int lvl,
+ "[%s] <%s> %s: ",
+ };
+ char *header __cleanup__(cleanup_charp) = NULL;
++ char *endpoint __cleanup__(cleanup_charp) = NULL;
+ char *message __cleanup__(cleanup_charp) = NULL;
+ int idx = 0;
+
+@@ -74,13 +75,22 @@ __nvme_msg(nvme_root_t r, int lvl,
+ timebuf, pidbuf, func ? func : "") == -1)
+ header = NULL;
+
++ if (ep)
++ {
++ if (asprintf(&endpoint, "[%s] ", nvme_mi_endpoint_desc(ep)) == -1)
++ {
++ endpoint = NULL;
++ }
++ }
++
+ va_start(ap, format);
+ if (vasprintf(&message, format, ap) == -1)
+ message = NULL;
+ va_end(ap);
+
+- fprintf(fp, "%s%s",
++ fprintf(fp, "%s%s%s",
+ header ? header : "<error>",
++ endpoint,
+ message ? message : "<error>");
+ }
+
+diff --git a/src/nvme/private.h b/src/nvme/private.h
+index fbaaaa4..a3d2003 100644
+--- a/src/nvme/private.h
++++ b/src/nvme/private.h
+@@ -147,16 +147,26 @@ nvme_ctrl_t __nvme_lookup_ctrl(nvme_subsystem_t s, const char *transport,
+ #define __nvme_log_func NULL
+ #endif
+
+-void __attribute__((format(printf, 4, 5)))
+-__nvme_msg(nvme_root_t r, int lvl, const char *func, const char *format, ...);
++void __attribute__((format(printf, 5, 6)))
++__nvme_msg(nvme_root_t r, nvme_mi_ep_t ep, int lvl, const char *func, const char *format, ...);
+
+ #define nvme_msg(r, lvl, format, ...) \
+ do { \
+ if ((lvl) <= MAX_LOGLEVEL) \
+- __nvme_msg(r, lvl, __nvme_log_func, \
++ __nvme_msg(r, NULL, lvl, __nvme_log_func, \
+ format, ##__VA_ARGS__); \
+ } while (0)
+
++#define nvme_mi_msg(ep, lvl, format, ...) \
++ do \
++ { \
++ if ((lvl) <= MAX_LOGLEVEL) \
++ { \
++ __nvme_msg(ep->root, ep, lvl, __nvme_log_func, format, \
++ ##__VA_ARGS__); \
++ } \
++ } while (0)
++
+ /* mi internal headers */
+
+ /* internal transport API */
+--
+2.45.0.rc1.225.g2a3ae87e7f-goog
+
diff --git a/recipes-connectivity/libnvme/libnvme/0009-mi-use-nvme_mi_msg-macro-for-nvme-mi-message.patch b/recipes-connectivity/libnvme/libnvme/0009-mi-use-nvme_mi_msg-macro-for-nvme-mi-message.patch
new file mode 100644
index 0000000..c389d41
--- /dev/null
+++ b/recipes-connectivity/libnvme/libnvme/0009-mi-use-nvme_mi_msg-macro-for-nvme-mi-message.patch
@@ -0,0 +1,262 @@
+From 936d1aa6c90a02c4ca07455359a6a0d7861c9073 Mon Sep 17 00:00:00 2001
+From: Jinliang Wang <jinliangw@google.com>
+Date: Fri, 3 May 2024 15:43:07 -0700
+Subject: [PATCH] mi: use nvme_mi_msg macro for nvme-mi message
+
+print endpoint info so we know which endpoint has problem.
+
+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-mctp.c | 18 +++++++++---------
+ src/nvme/mi.c | 36 ++++++++++++++++++------------------
+ 2 files changed, 27 insertions(+), 27 deletions(-)
+
+diff --git a/src/nvme/mi-mctp.c b/src/nvme/mi-mctp.c
+index cb77d0d..f7e45ab 100644
+--- a/src/nvme/mi-mctp.c
++++ b/src/nvme/mi-mctp.c
+@@ -121,7 +121,7 @@ static __u8 nvme_mi_mctp_tag_alloc(struct nvme_mi_ep *ep)
+ if (!logged) {
+ /* not necessarily fatal, just means we can't handle
+ * "more processing required" messages */
+- nvme_msg(ep->root, LOG_INFO,
++ nvme_mi_msg(ep, LOG_INFO,
+ "System does not support explicit tag allocation\n");
+ logged = true;
+ }
+@@ -153,7 +153,7 @@ static __u8 nvme_mi_mctp_tag_alloc(struct nvme_mi_ep *ep)
+ {
+ static bool logged;
+ if (!logged) {
+- nvme_msg(ep->root, LOG_INFO,
++ nvme_mi_msg(ep, LOG_INFO,
+ "Build does not support explicit tag allocation\n");
+ logged = true;
+ }
+@@ -299,7 +299,7 @@ static int nvme_mi_mctp_submit(struct nvme_mi_ep *ep,
+ len = ops.sendmsg(mctp->sd, &req_msg, 0);
+ if (len < 0) {
+ errno_save = errno;
+- nvme_msg(ep->root, LOG_ERR,
++ nvme_mi_msg(ep, LOG_ERR,
+ "Failure sending MCTP message: %m\n");
+ errno = errno_save;
+ rc = -1;
+@@ -337,7 +337,7 @@ retry:
+ }
+
+ if (rc == 0) {
+- nvme_msg(ep->root, LOG_ERR, "Timeout on MCTP socket\n");
++ nvme_mi_msg(ep, LOG_ERR, "Timeout on MCTP socket\n");
+ errno = ETIMEDOUT;
+ rc = -1;
+ goto out;
+@@ -348,7 +348,7 @@ retry:
+
+ if (len < 0) {
+ errno_save = errno;
+- nvme_msg(ep->root, LOG_ERR,
++ nvme_mi_msg(ep, LOG_ERR,
+ "Failure receiving MCTP message: %m\n");
+ errno = errno_save;
+ goto out;
+@@ -356,7 +356,7 @@ retry:
+
+
+ if (len == 0) {
+- nvme_msg(ep->root, LOG_ERR, "No data from MCTP endpoint\n");
++ nvme_mi_msg(ep, LOG_ERR, "No data from MCTP endpoint\n");
+ errno = EIO;
+ goto out;
+ }
+@@ -369,7 +369,7 @@ retry:
+ * plus four bytes of error data (excluding MIC). Ensure we have enough.
+ */
+ if (len < 8 + sizeof(mic)) {
+- nvme_msg(ep->root, LOG_ERR,
++ nvme_mi_msg(ep, LOG_ERR,
+ "Invalid MCTP response: too short (%zd bytes, needed %zd)\n",
+ len, 8 + sizeof(mic));
+ errno = EPROTO;
+@@ -378,7 +378,7 @@ retry:
+
+ /* We can't have header/payload data that isn't a multiple of 4 bytes */
+ if (len & 0x3) {
+- nvme_msg(ep->root, LOG_ERR,
++ nvme_mi_msg(ep, LOG_ERR,
+ "Response message has unaligned length (%zd)!\n",
+ len);
+ errno = EPROTO;
+@@ -391,7 +391,7 @@ retry:
+ * to keep the tag allocated and retry the recvmsg
+ */
+ if (nvme_mi_mctp_resp_is_mpr(resp, len, mic, &mpr_time)) {
+- nvme_msg(ep->root, LOG_NOTICE,
++ nvme_mi_msg(ep, LOG_NOTICE,
+ "Received More Processing Required, waiting for response\n");
+
+ /* if the controller hasn't set MPRT, fall back to our command/
+diff --git a/src/nvme/mi.c b/src/nvme/mi.c
+index aa79599..cd129be 100644
+--- a/src/nvme/mi.c
++++ b/src/nvme/mi.c
+@@ -88,7 +88,7 @@ static bool nvme_mi_compare_vid_mn(struct nvme_mi_ep *ep,
+
+ len = strlen(mn);
+ if (len >= sizeof(id->mn)) {
+- nvme_msg(ep->root, LOG_ERR,
++ nvme_mi_msg(ep, LOG_ERR,
+ "Internal error: invalid model number for %s\n",
+ __func__);
+ return false;
+@@ -160,7 +160,7 @@ void nvme_mi_ep_probe(struct nvme_mi_ep *ep)
+ rc = nvme_mi_admin_identify_partial(ctrl, &id_args, 0,
+ offsetof(struct nvme_id_ctrl, rab));
+ if (rc) {
+- nvme_msg(ep->root, LOG_WARNING,
++ nvme_mi_msg(ep, LOG_WARNING,
+ "Identify Controller failed, no quirks applied\n");
+ goto out_close;
+ }
+@@ -184,7 +184,7 @@ void nvme_mi_ep_probe(struct nvme_mi_ep *ep)
+ char tmp[sizeof(id.mn) + 1];
+
+ nvme_mi_format_mn(&id, tmp);
+- nvme_msg(ep->root, LOG_NOTICE,
++ nvme_mi_msg(ep, LOG_NOTICE,
+ "device %02x:%s: applying quirks 0x%08lx\n",
+ id.vid, tmp, ep->quirks);
+ }
+@@ -425,42 +425,42 @@ int nvme_mi_submit(nvme_mi_ep_t ep, struct nvme_mi_req *req,
+ nvme_mi_record_resp_time(ep);
+
+ if (rc) {
+- nvme_msg(ep->root, LOG_INFO, "transport failure\n");
++ nvme_mi_msg(ep, LOG_INFO, "transport failure\n");
+ return rc;
+ }
+
+ if (ep->transport->mic_enabled) {
+ rc = nvme_mi_verify_resp_mic(resp);
+ if (rc) {
+- nvme_msg(ep->root, LOG_ERR, "crc mismatch\n");
++ nvme_mi_msg(ep, LOG_ERR, "crc mismatch\n");
+ return rc;
+ }
+ }
+
+ /* basic response checks */
+ if (resp->hdr_len < sizeof(struct nvme_mi_msg_hdr)) {
+- nvme_msg(ep->root, LOG_ERR,
++ nvme_mi_msg(ep, LOG_ERR,
+ "Bad response header len: %zd\n", resp->hdr_len);
+ errno = EPROTO;
+ return -1;
+ }
+
+ if (resp->hdr->type != NVME_MI_MSGTYPE_NVME) {
+- nvme_msg(ep->root, LOG_ERR,
++ nvme_mi_msg(ep, LOG_ERR,
+ "Invalid message type 0x%02x\n", resp->hdr->type);
+ errno = EPROTO;
+ return -1;
+ }
+
+ if (!(resp->hdr->nmp & (NVME_MI_ROR_RSP << 7))) {
+- nvme_msg(ep->root, LOG_ERR,
++ nvme_mi_msg(ep, LOG_ERR,
+ "ROR value in response indicates a request\n");
+ errno = EIO;
+ return -1;
+ }
+
+ if ((resp->hdr->nmp & 0x1) != (req->hdr->nmp & 0x1)) {
+- nvme_msg(ep->root, LOG_ERR,
++ nvme_mi_msg(ep, LOG_ERR,
+ "Command slot mismatch: req %d, resp %d\n",
+ req->hdr->nmp & 0x1,
+ resp->hdr->nmp & 0x1);
+@@ -585,35 +585,35 @@ int nvme_mi_admin_xfer(nvme_mi_ctrl_t ctrl,
+ int direction = admin_req->opcode & 0x3;
+ if (direction == NVME_DATA_TFR_BIDIRECTIONAL || (req_data_size && *resp_data_size))
+ {
+- nvme_msg(ctrl->ep->root, LOG_ERR,
++ nvme_mi_msg(ctrl->ep, LOG_ERR,
+ "nvme_mi_admin_xfer doesn't support bidirectional commands\n");
+ errno = EINVAL;
+ return -1;
+ }
+ else if (direction == NVME_DATA_TFR_HOST_TO_CTRL && *resp_data_size)
+ {
+- nvme_msg(ctrl->ep->root, LOG_ERR,
++ nvme_mi_msg(ctrl->ep, LOG_ERR,
+ "nvme_mi_admin_xfer doesn't support response data on WRITE commands\n");
+ errno = EINVAL;
+ return -1;
+ }
+ else if (direction == NVME_DATA_TFR_CTRL_TO_HOST && req_data_size)
+ {
+- nvme_msg(ctrl->ep->root, LOG_ERR,
++ nvme_mi_msg(ctrl->ep, LOG_ERR,
+ "nvme_mi_admin_xfer doesn't support request data on READ commands\n");
+ errno = EINVAL;
+ return -1;
+ }
+ else if (resp_data_offset && (direction != NVME_DATA_TFR_CTRL_TO_HOST || !*resp_data_size))
+ {
+- nvme_msg(ctrl->ep->root, LOG_ERR,
++ nvme_mi_msg(ctrl->ep, LOG_ERR,
+ "nvme_mi_admin_xfer invalid offset value\n");
+ errno = EINVAL;
+ return -1;
+ }
+ else if (direction == NVME_DATA_TFR_NO_DATA_TFR && req_data_size && *resp_data_size)
+ {
+- nvme_msg(ctrl->ep->root, LOG_ERR,
++ nvme_mi_msg(ctrl->ep, LOG_ERR,
+ "nvme_mi_admin_xfer doesn't support data on NONE_DATA_TRANSFER commands\n");
+ errno = EINVAL;
+ return -1;
+@@ -703,14 +703,14 @@ int nvme_mi_admin_admin_passthru(nvme_mi_ctrl_t ctrl, __u8 opcode, __u8 flags,
+ bool has_read_data = false;
+
+ if (direction == NVME_DATA_TFR_BIDIRECTIONAL) {
+- nvme_msg(ctrl->ep->root, LOG_ERR,
++ nvme_mi_msg(ctrl->ep, LOG_ERR,
+ "nvme_mi_admin_admin_passthru doesn't support bidirectional commands\n");
+ errno = EINVAL;
+ return -1;
+ }
+
+ if (data_len > 4096) {
+- nvme_msg(ctrl->ep->root, LOG_ERR,
++ nvme_mi_msg(ctrl->ep, LOG_ERR,
+ "nvme_mi_admin_admin_passthru doesn't support data_len over 4096 bytes.\n");
+ errno = EINVAL;
+ return -1;
+@@ -1431,7 +1431,7 @@ int nvme_mi_mi_read_mi_data_subsys(nvme_mi_ep_t ep,
+ return rc;
+
+ if (len != sizeof(*s)) {
+- nvme_msg(ep->root, LOG_ERR,
++ nvme_mi_msg(ep, LOG_ERR,
+ "MI read data length mismatch: "
+ "got %zd bytes, expected %zd\n",
+ len, sizeof(*s));
+@@ -1537,7 +1537,7 @@ int nvme_mi_mi_subsystem_health_status_poll(nvme_mi_ep_t ep, bool clear,
+ return resp_hdr.status;
+
+ if (resp.data_len != sizeof(*sshs)) {
+- nvme_msg(ep->root, LOG_ERR,
++ nvme_mi_msg(ep, LOG_ERR,
+ "MI Subsystem Health Status length mismatch: "
+ "got %zd bytes, expected %zd\n",
+ resp.data_len, sizeof(*sshs));
+--
+2.45.0.rc1.225.g2a3ae87e7f-goog
+
diff --git a/recipes-connectivity/libnvme/libnvme/0010-mi-trace-NVMe-MI-command-request-after-failure.patch b/recipes-connectivity/libnvme/libnvme/0010-mi-trace-NVMe-MI-command-request-after-failure.patch
new file mode 100644
index 0000000..0668a05
--- /dev/null
+++ b/recipes-connectivity/libnvme/libnvme/0010-mi-trace-NVMe-MI-command-request-after-failure.patch
@@ -0,0 +1,157 @@
+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
+
diff --git a/recipes-connectivity/libnvme/libnvme_git.bb b/recipes-connectivity/libnvme/libnvme_git.bb
index f1c4992..3ff5709 100644
--- a/recipes-connectivity/libnvme/libnvme_git.bb
+++ b/recipes-connectivity/libnvme/libnvme_git.bb
@@ -19,7 +19,10 @@
file://0004-mi-avoid-changing-default-ep-timeout-during-admin_pa.patch \
file://0005-libnvme-mi-add-timeout-functions-to-.map.patch \
file://0006-mi-don-t-return-from-mi_mctp_submit-with-a-tag-held.patch \
- file://0007-mi-check-and-print-OOB-NVMe-MI-command-execution-tim.patch \
+ file://0007-mi-use-more-reasonable-log-level.patch \
+ file://0008-mi-add-nvme_mi_msg-marco-to-print-MCTP-endpoint-desc.patch \
+ file://0009-mi-use-nvme_mi_msg-macro-for-nvme-mi-message.patch \
+ file://0010-mi-trace-NVMe-MI-command-request-after-failure.patch \
"
S = "${WORKDIR}/git"
