MFC r273163: Implement more functional CTL debug logging.

Setting bits in kern.cam.ctl.debug allows to log errors, commands and some
commands data respectively.

6 files changed, 126 insertions, 142 deletions

diff --git a/sys/cam/ctl/ctl.c b/sys/cam/ctl/ctl.c
index e0dd65b..97b2d67 100644
--- a/sys/cam/ctl/ctl.c
+++ b/sys/cam/ctl/ctl.c
@@ -315,10 +315,10 @@ static int worker_threads = -1;
 TUNABLE_INT("kern.cam.ctl.worker_threads", &worker_threads);
 SYSCTL_INT(_kern_cam_ctl, OID_AUTO, worker_threads, CTLFLAG_RDTUN,
     &worker_threads, 1, "Number of worker threads");
-static int verbose = 0;
-TUNABLE_INT("kern.cam.ctl.verbose", &verbose);
-SYSCTL_INT(_kern_cam_ctl, OID_AUTO, verbose, CTLFLAG_RWTUN,
-    &verbose, 0, "Show SCSI errors returned to initiator");
+static int ctl_debug = CTL_DEBUG_NONE;
+TUNABLE_INT("kern.cam.ctl.debug", &ctl_debug);
+SYSCTL_INT(_kern_cam_ctl, OID_AUTO, debug, CTLFLAG_RWTUN,
+    &ctl_debug, 0, "Enabled debug flags");
 
 /*
  * Supported pages (0x00), Serial number (0x80), Device ID (0x83),
@@ -5294,6 +5294,8 @@ ctl_config_move_done(union ctl_io *io)
 		 *
 		 * - Call some other function once the data is in?
 		 */
+		if (ctl_debug & CTL_DEBUG_CDB_DATA)
+			ctl_data_print(io);
 
 		/*
 		 * XXX KDM call ctl_scsiio() again for now, and check flag
@@ -13766,17 +13768,14 @@ ctl_process_done(union ctl_io *io)
 	case CTL_IO_SCSI:
 		break;
 	case CTL_IO_TASK:
-		if (bootverbose || verbose > 0)
+		if (bootverbose || (ctl_debug & CTL_DEBUG_INFO))
 			ctl_io_error_print(io, NULL);
 		if (io->io_hdr.flags & CTL_FLAG_FROM_OTHER_SC)
 			ctl_free_io(io);
 		else
 			fe_done(io);
 		return (CTL_RETVAL_COMPLETE);
-		break;
 	default:
-		printf("ctl_process_done: invalid io type %d\n",
-		       io->io_hdr.io_type);
 		panic("ctl_process_done: invalid io type %d\n",
 		      io->io_hdr.io_type);
 		break; /* NOTREACHED */
@@ -13870,74 +13869,28 @@ ctl_process_done(union ctl_io *io)
 		ctl_set_task_aborted(&io->scsiio);
 
 	/*
-	 * We print out status for every task management command.  For SCSI
-	 * commands, we filter out any unit attention errors; they happen
-	 * on every boot, and would clutter up the log.  Note:  task
-	 * management commands aren't printed here, they are printed above,
-	 * since they should never even make it down here.
+	 * If enabled, print command error status.
+	 * We don't print UAs unless debugging was enabled explicitly.
 	 */
-	switch (io->io_hdr.io_type) {
-	case CTL_IO_SCSI: {
-		int error_code, sense_key, asc, ascq;
-
-		sense_key = 0;
+	do {
+		if ((io->io_hdr.status & CTL_STATUS_MASK) == CTL_SUCCESS)
+			break;
+		if (!bootverbose && (ctl_debug & CTL_DEBUG_INFO) == 0)
+			break;
+		if ((ctl_debug & CTL_DEBUG_INFO) == 0 &&
+		    ((io->io_hdr.status & CTL_STATUS_MASK) == CTL_SCSI_ERROR) &&
+		     (io->scsiio.scsi_status == SCSI_STATUS_CHECK_COND)) {
+			int error_code, sense_key, asc, ascq;
 
-		if (((io->io_hdr.status & CTL_STATUS_MASK) == CTL_SCSI_ERROR)
-		 && (io->scsiio.scsi_status == SCSI_STATUS_CHECK_COND)) {
-			/*
-			 * Since this is just for printing, no need to
-			 * show errors here.
-			 */
 			scsi_extract_sense_len(&io->scsiio.sense_data,
-					       io->scsiio.sense_len,
-					       &error_code,
-					       &sense_key,
-					       &asc,
-					       &ascq,
-					       /*show_errors*/ 0);
+			    io->scsiio.sense_len, &error_code, &sense_key,
+			    &asc, &ascq, /*show_errors*/ 0);
+			if (sense_key == SSD_KEY_UNIT_ATTENTION)
+				break;
 		}
 
-		if (((io->io_hdr.status & CTL_STATUS_MASK) != CTL_SUCCESS)
-		 && (((io->io_hdr.status & CTL_STATUS_MASK) != CTL_SCSI_ERROR)
-		  || (io->scsiio.scsi_status != SCSI_STATUS_CHECK_COND)
-		  || (sense_key != SSD_KEY_UNIT_ATTENTION))) {
-
-			if ((time_uptime - ctl_softc->last_print_jiffies) <= 0){
-				ctl_softc->skipped_prints++;
-			} else {
-				uint32_t skipped_prints;
-
-				skipped_prints = ctl_softc->skipped_prints;
-
-				ctl_softc->skipped_prints = 0;
-				ctl_softc->last_print_jiffies = time_uptime;
-
-				if (skipped_prints > 0) {
-#ifdef NEEDTOPORT
-					csevent_log(CSC_CTL | CSC_SHELF_SW |
-					    CTL_ERROR_REPORT,
-					    csevent_LogType_Trace,
-					    csevent_Severity_Information,
-					    csevent_AlertLevel_Green,
-					    csevent_FRU_Firmware,
-					    csevent_FRU_Unknown,
-					    "High CTL error volume, %d prints "
-					    "skipped", skipped_prints);
-#endif
-				}
-				if (bootverbose || verbose > 0)
-					ctl_io_error_print(io, NULL);
-			}
-		}
-		break;
-	}
-	case CTL_IO_TASK:
-		if (bootverbose || verbose > 0)
-			ctl_io_error_print(io, NULL);
-		break;
-	default:
-		break;
-	}
+		ctl_io_error_print(io, NULL);
+	} while (0);
 
 	/*
 	 * Tell the FETD or the other shelf controller we're done with this
@@ -14082,6 +14035,8 @@ ctl_queue(union ctl_io *io)
 	switch (io->io_hdr.io_type) {
 	case CTL_IO_SCSI:
 	case CTL_IO_TASK:
+		if (ctl_debug & CTL_DEBUG_CDB)
+			ctl_io_print(io);
 		ctl_enqueue_incoming(io);
 		break;
 	default:
diff --git a/sys/cam/ctl/ctl_debug.h b/sys/cam/ctl/ctl_debug.h
index 53f406b..8bd0870 100644
--- a/sys/cam/ctl/ctl_debug.h
+++ b/sys/cam/ctl/ctl_debug.h
@@ -39,6 +39,16 @@
 #ifndef	_CTL_DEBUG_H_
 #define	_CTL_DEBUG_H_
 
+/*
+ * Debugging flags.
+ */
+typedef enum {
+	CTL_DEBUG_NONE		= 0x00,	/* no debugging */
+	CTL_DEBUG_INFO		= 0x01,	/* SCSI errors */
+	CTL_DEBUG_CDB		= 0x02,	/* SCSI CDBs and tasks */
+	CTL_DEBUG_CDB_DATA	= 0x04	/* SCSI CDB DATA */
+} ctl_debug_flags;
+
 #ifdef	CAM_CTL_DEBUG
 #define	CTL_DEBUG_PRINT(X)		\
 	do {				\
diff --git a/sys/cam/ctl/ctl_private.h b/sys/cam/ctl/ctl_private.h
index 30418df..d3c1092 100644
--- a/sys/cam/ctl/ctl_private.h
+++ b/sys/cam/ctl/ctl_private.h
@@ -456,8 +456,6 @@ struct ctl_softc {
 	uint32_t num_pools;
 	uint32_t cur_pool_id;
 	STAILQ_HEAD(, ctl_io_pool) io_pools;
-	time_t last_print_jiffies;
-	uint32_t skipped_prints;
 	struct ctl_thread threads[CTL_MAX_THREADS];
 	TAILQ_HEAD(tpc_tokens, tpc_token) tpc_tokens;
 	struct callout tpc_timeout;
diff --git a/sys/cam/ctl/ctl_scsi_all.c b/sys/cam/ctl/ctl_scsi_all.c
index 91b79f3..815e383 100644
--- a/sys/cam/ctl/ctl_scsi_all.c
+++ b/sys/cam/ctl/ctl_scsi_all.c
@@ -112,32 +112,10 @@ ctl_scsi_command_string(struct ctl_scsiio *ctsio,
 void
 ctl_scsi_path_string(union ctl_io *io, char *path_str, int len)
 {
-	if (io->io_hdr.nexus.targ_target.wwid[0] == 0) {
-		snprintf(path_str, len, "(%ju:%d:%ju:%d): ",
-			 (uintmax_t)io->io_hdr.nexus.initid.id,
-			 io->io_hdr.nexus.targ_port,
-			 (uintmax_t)io->io_hdr.nexus.targ_target.id,
-			 io->io_hdr.nexus.targ_lun);
-	} else {
-		/*
-		 * XXX KDM find a better way to display FC WWIDs.
-		 */
-#ifdef _KERNEL
-		snprintf(path_str, len, "(%ju:%d:%#jx,%#jx:%d): ",
-			 (uintmax_t)io->io_hdr.nexus.initid.id,
-			 io->io_hdr.nexus.targ_port,
-			 (intmax_t)io->io_hdr.nexus.targ_target.wwid[0],
-			 (intmax_t)io->io_hdr.nexus.targ_target.wwid[1],
-			 io->io_hdr.nexus.targ_lun);
-#else /* _KERNEL */
-		snprintf(path_str, len, "(%ju:%d:%#jx,%#jx:%d): ",
-			 (uintmax_t)io->io_hdr.nexus.initid.id,
-			 io->io_hdr.nexus.targ_port,
-			 (intmax_t)io->io_hdr.nexus.targ_target.wwid[0],
-			 (intmax_t)io->io_hdr.nexus.targ_target.wwid[1],
-			 io->io_hdr.nexus.targ_lun);
-#endif /* _KERNEL */
-	}
+
+	snprintf(path_str, len, "(%u:%u:%u/%u): ",
+	    io->io_hdr.nexus.initid.id, io->io_hdr.nexus.targ_port,
+	    io->io_hdr.nexus.targ_lun, io->io_hdr.nexus.targ_mapped_lun);
 }
 
 /*
diff --git a/sys/cam/ctl/ctl_util.c b/sys/cam/ctl/ctl_util.c
index 61b0085..a991cfb 100644
--- a/sys/cam/ctl/ctl_util.c
+++ b/sys/cam/ctl/ctl_util.c
@@ -731,69 +731,64 @@ ctl_scsi_task_string(struct ctl_taskio *taskio)
 }
 
 void
-ctl_io_error_sbuf(union ctl_io *io, struct scsi_inquiry_data *inq_data,
-		  struct sbuf *sb)
+ctl_io_sbuf(union ctl_io *io, struct sbuf *sb)
 {
-	struct ctl_status_desc *status_desc;
+	const char *task_desc;
 	char path_str[64];
-	unsigned int i;
-
-	status_desc = NULL;
-
-	for (i = 0; i < (sizeof(ctl_status_table)/sizeof(ctl_status_table[0]));
-	     i++) {
-		if ((io->io_hdr.status & CTL_STATUS_MASK) ==
-		     ctl_status_table[i].status) {
-			status_desc = &ctl_status_table[i];
-			break;
-		}
-	}
 
 	ctl_scsi_path_string(io, path_str, sizeof(path_str));
 
 	switch (io->io_hdr.io_type) {
 	case CTL_IO_SCSI:
 		sbuf_cat(sb, path_str);
-
 		ctl_scsi_command_string(&io->scsiio, NULL, sb);
-
-		sbuf_printf(sb, "\n");
-
-		sbuf_printf(sb, "%sTag: 0x%04x, Type: %d\n", path_str,
+		sbuf_printf(sb, " Tag: %#x/%d\n",
 			    io->scsiio.tag_num, io->scsiio.tag_type);
 		break;
-	case CTL_IO_TASK: {
-		const char *task_desc;
-
+	case CTL_IO_TASK:
 		sbuf_cat(sb, path_str);
-
 		task_desc = ctl_scsi_task_string(&io->taskio);
-
 		if (task_desc == NULL)
 			sbuf_printf(sb, "Unknown Task Action %d (%#x)",
-				    io->taskio.task_action,
-				    io->taskio.task_action);
+			    io->taskio.task_action, io->taskio.task_action);
 		else
 			sbuf_printf(sb, "Task Action: %s", task_desc);
-
-		sbuf_printf(sb, "\n");
-
 		switch (io->taskio.task_action) {
 		case CTL_TASK_ABORT_TASK:
-		case CTL_TASK_ABORT_TASK_SET:
-		case CTL_TASK_CLEAR_TASK_SET:
-			sbuf_printf(sb, "%sTag: 0x%04x, Type: %d\n", path_str,
-				    io->taskio.tag_num,
-				    io->taskio.tag_type);
+			sbuf_printf(sb, " Tag: %#x/%d\n",
+			    io->taskio.tag_num, io->taskio.tag_type);
 			break;
 		default:
+			sbuf_printf(sb, "\n");
 			break;
 		}
 		break;
-	}
 	default:
 		break;
 	}
+}
+
+void
+ctl_io_error_sbuf(union ctl_io *io, struct scsi_inquiry_data *inq_data,
+		  struct sbuf *sb)
+{
+	struct ctl_status_desc *status_desc;
+	char path_str[64];
+	unsigned int i;
+
+	ctl_io_sbuf(io, sb);
+
+	status_desc = NULL;
+	for (i = 0; i < (sizeof(ctl_status_table)/sizeof(ctl_status_table[0]));
+	     i++) {
+		if ((io->io_hdr.status & CTL_STATUS_MASK) ==
+		     ctl_status_table[i].status) {
+			status_desc = &ctl_status_table[i];
+			break;
+		}
+	}
+
+	ctl_scsi_path_string(io, path_str, sizeof(path_str));
 
 	sbuf_cat(sb, path_str);
 	if (status_desc == NULL)
@@ -815,23 +810,39 @@ ctl_io_error_sbuf(union ctl_io *io, struct scsi_inquiry_data *inq_data,
 }
 
 char *
+ctl_io_string(union ctl_io *io, char *str, int str_len)
+{
+	struct sbuf sb;
+
+	sbuf_new(&sb, str, str_len, SBUF_FIXEDLEN);
+	ctl_io_sbuf(io, &sb);
+	sbuf_finish(&sb);
+	return (sbuf_data(&sb));
+}
+
+char *
 ctl_io_error_string(union ctl_io *io, struct scsi_inquiry_data *inq_data,
 		    char *str, int str_len)
 {
 	struct sbuf sb;
 
 	sbuf_new(&sb, str, str_len, SBUF_FIXEDLEN);
-
 	ctl_io_error_sbuf(io, inq_data, &sb);
-
 	sbuf_finish(&sb);
-
 	return (sbuf_data(&sb));
 }
 
 #ifdef _KERNEL
 
 void
+ctl_io_print(union ctl_io *io)
+{
+	char str[512];
+
+	printf("%s", ctl_io_string(io, str, sizeof(str)));
+}
+
+void
 ctl_io_error_print(union ctl_io *io, struct scsi_inquiry_data *inq_data)
 {
 	char str[512];
@@ -856,6 +867,37 @@ ctl_io_error_print(union ctl_io *io, struct scsi_inquiry_data *inq_data)
 
 }
 
+void
+ctl_data_print(union ctl_io *io)
+{
+	char str[128];
+	char path_str[64];
+	struct sbuf sb;
+	int i, j, len;
+
+	if (io->io_hdr.io_type != CTL_IO_SCSI)
+		return;
+	if (io->io_hdr.flags & CTL_FLAG_BUS_ADDR)
+		return;
+	if (io->io_hdr.flags & CTL_FLAG_EDPTR_SGLIST)	/* XXX: Implement */
+		return;
+	ctl_scsi_path_string(io, path_str, sizeof(path_str));
+	len = min(io->scsiio.kern_data_len, 4096);
+	for (i = 0; i < len; ) {
+		sbuf_new(&sb, str, sizeof(str), SBUF_FIXEDLEN);
+		sbuf_cat(&sb, path_str);
+		sbuf_printf(&sb, " %#6x:%04x:", io->scsiio.tag_num, i);
+		for (j = 0; j < 16 && i < len; i++, j++) {
+			if (j == 8)
+				sbuf_cat(&sb, " ");
+			sbuf_printf(&sb, " %02x", io->scsiio.kern_data_ptr[i]);
+		}
+		sbuf_cat(&sb, "\n");
+		sbuf_finish(&sb);
+		printf("%s", sbuf_data(&sb));
+	}
+}
+
 #else /* _KERNEL */
 
 void
diff --git a/sys/cam/ctl/ctl_util.h b/sys/cam/ctl/ctl_util.h
index 774ac27..af5e55f 100644
--- a/sys/cam/ctl/ctl_util.h
+++ b/sys/cam/ctl/ctl_util.h
@@ -99,19 +99,20 @@ void ctl_scsi_free_io(union ctl_io *io);
 #endif /* !_KERNEL */
 void ctl_scsi_zero_io(union ctl_io *io);
 const char *ctl_scsi_task_string(struct ctl_taskio *taskio);
+void ctl_io_sbuf(union ctl_io *io, struct sbuf *sb);
 void ctl_io_error_sbuf(union ctl_io *io,
 		       struct scsi_inquiry_data *inq_data, struct sbuf *sb);
+char *ctl_io_string(union ctl_io *io, char *str, int str_len);
 char *ctl_io_error_string(union ctl_io *io,
 			  struct scsi_inquiry_data *inq_data, char *str,
 			  int str_len);
 #ifdef _KERNEL
-
+void ctl_io_print(union ctl_io *io);
 void ctl_io_error_print(union ctl_io *io, struct scsi_inquiry_data *inq_data);
+void ctl_data_print(union ctl_io *io);
 #else /* _KERNEL */
-void
-ctl_io_error_print(union ctl_io *io, struct scsi_inquiry_data *inq_data,
+void ctl_io_error_print(union ctl_io *io, struct scsi_inquiry_data *inq_data,
 		   FILE *ofile);
-
 #endif /* _KERNEL */
 
 __END_DECLS