nvme: add functions to pretty-print commands and completions

This change attempts to address the Trello request to decode I/O errors in
NVMe hello_world example.

See https://trello.com/c/MzJJw7hM/2-decode-io-errors-in-nvme-helloworld-example

As part of this change, spdk_nvme_cpl_get_status_string was declared
in nvme.h, and spdk_nvme_qpair_print_command and
spdk_nvme_qpair_print_completion were renamed and added to nvme.h,
allowing all three to used "externally."

To test the failing paths, two compile time defines were added to force a
write or read error (bad LBA) respectively.

As the example does a read after write, if the write fails, the example fails.

Signed-off-by: James Bergsten <jamesx.bergsten@intel.com>
Change-Id: Ib94b4a02495eb40966e3f49517a5bdf64485538a
Reviewed-on: https://review.gerrithub.io/c/spdk/spdk/+/457076
Reviewed-by: Darek Stojaczyk <dariusz.stojaczyk@intel.com>
Tested-by: SPDK CI Jenkins <sys_sgci@intel.com>

examples/nvme/hello_world/hello_world.c

@@ -105,6 +105,19 @@ read_complete(void *arg, const struct spdk_nvme_cpl *completion)
 {
 	struct hello_world_sequence *sequence = arg;
 
+	/* Assume the I/O was successful */
+	sequence->is_completed = 1;
+	/* See if an error occurred. If so, display information
+	 * about it, and set completion value so that I/O
+	 * caller is aware that an error occurred.
+	 */
+	if (spdk_nvme_cpl_is_error(completion)) {
+		spdk_nvme_qpair_print_completion(sequence->ns_entry->qpair, (struct spdk_nvme_cpl *)completion);
+		fprintf(stderr, "I/O error status: %s\n", spdk_nvme_cpl_get_status_string(&completion->status));
+		fprintf(stderr, "Read I/O failed, aborting run\n");
+		sequence->is_completed = 2;
+	}
+
 	/*
 	 * The read I/O has completed.  Print the contents of the
 	 *  buffer, free the buffer, then mark the sequence as
@@ -113,7 +126,6 @@ read_complete(void *arg, const struct spdk_nvme_cpl *completion)
 	 */
 	printf("%s", sequence->buf);
 	spdk_free(sequence->buf);
-	sequence->is_completed = 1;
 }
 
 static void
@@ -123,6 +135,17 @@ write_complete(void *arg, const struct spdk_nvme_cpl *completion)
 	struct ns_entry			*ns_entry = sequence->ns_entry;
 	int				rc;
 
+	/* See if an error occurred. If so, display information
+	 * about it, and set completion value so that I/O
+	 * caller is aware that an error occurred.
+	 */
+	if (spdk_nvme_cpl_is_error(completion)) {
+		spdk_nvme_qpair_print_completion(sequence->ns_entry->qpair, (struct spdk_nvme_cpl *)completion);
+		fprintf(stderr, "I/O error status: %s\n", spdk_nvme_cpl_get_status_string(&completion->status));
+		fprintf(stderr, "Write I/O failed, aborting run\n");
+		sequence->is_completed = 2;
+		exit(1);
+	}
 	/*
 	 * The write I/O has completed.  Free the buffer associated with
 	 *  the write I/O and allocate a new zeroed buffer for reading

include/spdk/nvme.h

@@ -2346,6 +2346,32 @@ void spdk_nvme_qpair_remove_cmd_error_injection(struct spdk_nvme_ctrlr *ctrlr,
 		struct spdk_nvme_qpair *qpair,
 		uint8_t opc);
 
+/**
+ * \brief Given NVMe status, return ASCII string for that error.
+ *
+ * \param status Status from NVMe completion queue element.
+ * \return Returns status as an ASCII string.
+ */
+const char *spdk_nvme_cpl_get_status_string(const struct spdk_nvme_status *status);
+
+/**
+ * \brief Prints (SPDK_NOTICELOG) the contents of an NVMe submission queue entry (command).
+ *
+ * \param qpair Pointer to the NVMe queue pair - used to determine admin versus I/O queue.
+ * \param cmd Pointer to the submission queue command to be formatted.
+ */
+void spdk_nvme_qpair_print_command(struct spdk_nvme_qpair *qpair,
+				   struct spdk_nvme_cmd *cmd);
+
+/**
+ * \brief Prints (SPDK_NOTICELOG) the contents of an NVMe completion queue entry.
+ *
+ * \param qpair Pointer to the NVMe queue pair - presently unused.
+ * \param cpl Pointer to the completion queue element to be formatted.
+ */
+void spdk_nvme_qpair_print_completion(struct spdk_nvme_qpair *qpair,
+				      struct spdk_nvme_cpl *cpl);
+
 #ifdef SPDK_CONFIG_RDMA
 struct ibv_context;
 struct ibv_pd;

lib/nvme/nvme_internal.h

@@ -977,10 +977,7 @@ uint64_t nvme_get_quirks(const struct spdk_pci_id *id);
 int	nvme_robust_mutex_init_shared(pthread_mutex_t *mtx);
 int	nvme_robust_mutex_init_recursive_shared(pthread_mutex_t *mtx);
 
-const char *spdk_nvme_cpl_get_status_string(const struct spdk_nvme_status *status);
 bool	nvme_completion_is_retry(const struct spdk_nvme_cpl *cpl);
-void	nvme_qpair_print_command(struct spdk_nvme_qpair *qpair, struct spdk_nvme_cmd *cmd);
-void	nvme_qpair_print_completion(struct spdk_nvme_qpair *qpair, struct spdk_nvme_cpl *cpl);
 
 struct spdk_nvme_ctrlr *spdk_nvme_get_ctrlr_by_trid_unsafe(
 	const struct spdk_nvme_transport_id *trid);

lib/nvme/nvme_pcie.c

@@ -1319,8 +1319,8 @@ nvme_pcie_qpair_complete_tracker(struct spdk_nvme_qpair *qpair, struct nvme_trac
 		req->retries < spdk_nvme_retry_count;
 
 	if (error && print_on_error && !qpair->ctrlr->opts.disable_error_logging) {
-		nvme_qpair_print_command(qpair, &req->cmd);
+		spdk_nvme_qpair_print_command(qpair, &req->cmd);
-		nvme_qpair_print_completion(qpair, cpl);
+		spdk_nvme_qpair_print_completion(qpair, cpl);
 	}
 
 	assert(cpl->cid == req->cmd.cid);
@@ -2151,7 +2151,7 @@ nvme_pcie_qpair_process_completions(struct spdk_nvme_qpair *qpair, uint32_t max_
 			nvme_pcie_qpair_complete_tracker(qpair, tr, cpl, true);
 		} else {
 			SPDK_ERRLOG("cpl does not map to outstanding cmd\n");
-			nvme_qpair_print_completion(qpair, cpl);
+			spdk_nvme_qpair_print_completion(qpair, cpl);
 			assert(0);
 		}
 

lib/nvme/nvme_qpair.c

@@ -151,7 +151,7 @@ nvme_io_qpair_print_command(struct spdk_nvme_qpair *qpair,
 }
 
 void
-nvme_qpair_print_command(struct spdk_nvme_qpair *qpair, struct spdk_nvme_cmd *cmd)
+spdk_nvme_qpair_print_command(struct spdk_nvme_qpair *qpair, struct spdk_nvme_cmd *cmd)
 {
 	assert(qpair != NULL);
 	assert(cmd != NULL);
@@ -297,8 +297,8 @@ spdk_nvme_cpl_get_status_string(const struct spdk_nvme_status *status)
 }
 
 void
-nvme_qpair_print_completion(struct spdk_nvme_qpair *qpair,
+spdk_nvme_qpair_print_completion(struct spdk_nvme_qpair *qpair,
-			    struct spdk_nvme_cpl *cpl)
+				 struct spdk_nvme_cpl *cpl)
 {
 	SPDK_NOTICELOG("%s (%02x/%02x) sqid:%d cid:%d cdw0:%x sqhd:%04x p:%x m:%x dnr:%x\n",
 		       spdk_nvme_cpl_get_status_string(&cpl->status),
@@ -379,8 +379,8 @@ nvme_qpair_manual_complete_request(struct spdk_nvme_qpair *qpair,
 
 	if (error && print_on_error && !qpair->ctrlr->opts.disable_error_logging) {
 		SPDK_NOTICELOG("Command completed manually:\n");
-		nvme_qpair_print_command(qpair, &req->cmd);
+		spdk_nvme_qpair_print_command(qpair, &req->cmd);
-		nvme_qpair_print_completion(qpair, &cpl);
+		spdk_nvme_qpair_print_completion(qpair, &cpl);
 	}
 
 	nvme_complete_request(req->cb_fn, req->cb_arg, qpair, req, &cpl);

test/unit/lib/nvme/nvme_pcie.c/nvme_pcie_ut.c

@@ -235,13 +235,13 @@ nvme_completion_is_retry(const struct spdk_nvme_cpl *cpl)
 }
 
 void
-nvme_qpair_print_command(struct spdk_nvme_qpair *qpair, struct spdk_nvme_cmd *cmd)
+spdk_nvme_qpair_print_command(struct spdk_nvme_qpair *qpair, struct spdk_nvme_cmd *cmd)
 {
 	abort();
 }
 
 void
-nvme_qpair_print_completion(struct spdk_nvme_qpair *qpair, struct spdk_nvme_cpl *cpl)
+spdk_nvme_qpair_print_completion(struct spdk_nvme_qpair *qpair, struct spdk_nvme_cpl *cpl)
 {
 	abort();
 }