[PATCH 00/22] scsi logging update

[PATCH 00/22] scsi logging update

[Hannes Reinecke]

Hi all,

here's my next round of scsi logging updates.
Main feature is the update to have all logging
statements in one line so that they won't be broken
up even under high load.
This will dramatically improve debugging.

Additionally all printk() statements are moved
to dev_printk() variants to ensure proper device
tagging and keep the systemd journal happy.

To achieve this I had to use a on-stack
buffer for formatting opcodes and sense codes;
so the stack usage will increase somewhat.

Reviews, comments etc are welcome.

Hannes Reinecke (22):
  Remove scsi_cmd_print_sense_hdr()
  aha152x: Remove #ifdef 0 section
  sd: Remove scsi_print_sense() in sd_done()
  scsi: introduce sdev_prefix_printk()
  scsi: Use sdev as argument for sense code printing
  scsi: stop decoding if scsi_normalize_sense() fails
  scsi: do not decode sense extras
  scsi: dump sense buffer only for debugging
  Use sdev as argument for scsi_print_result
  scsi: consolidate scsi_print_status()
  Implement scsi_opcode_sa_name
  scsi: remove obsolete __scsi_print_command() usages
  scsi: use local buffer for printing the opcode
  scsi: pass in string buffer to __scsi_print_command()
  scsi: use dev_printk() variants in scsi_print_command()
  libata: use __scsi_print_command()
  scsi: print disposition in scsi_print_result()
  scsi_error: format abort error message
  scsi: use local buffer for scsi_log_(send|completion)
  scsi: align logging messages
  scsi: reduce messages for command failure
  sd: Reduce logging output

 drivers/ata/libata-eh.c       |  12 +-
 drivers/scsi/53c700.c         |   3 +-
 drivers/scsi/aha152x.c        |  32 +--
 drivers/scsi/arm/acornscsi.c  |   9 +-
 drivers/scsi/arm/fas216.c     |  30 +--
 drivers/scsi/ch.c             |   7 +-
 drivers/scsi/constants.c      | 570 ++++++++++++++++++++----------------------
 drivers/scsi/osst.c           |   8 +-
 drivers/scsi/scsi.c           |  65 ++---
 drivers/scsi/scsi_error.c     |  68 ++---
 drivers/scsi/scsi_ioctl.c     |   2 +-
 drivers/scsi/scsi_lib.c       |  10 +-
 drivers/scsi/sd.c             |  28 ++-
 drivers/scsi/sg.c             |   9 +-
 drivers/scsi/sr_ioctl.c       |  16 +-
 drivers/scsi/st.c             |  13 +-
 drivers/scsi/storvsc_drv.c    |   3 +-
 include/scsi/scsi_dbg.h       |  34 +--
 include/scsi/scsi_device.h    |   5 +
 include/trace/events/scsi.h   |  17 +-
 include/trace/events/target.h |  17 +-
 21 files changed, 457 insertions(+), 501 deletions(-)

-- 
1.8.5.2

[PATCH 01/22] Remove scsi_cmd_print_sense_hdr()

[Hannes Reinecke]

Unused.

Signed-off-by: Hannes Reinecke <hare@suse.de>
---
 drivers/scsi/constants.c | 14 --------------
 include/scsi/scsi_dbg.h  |  2 --
 2 files changed, 16 deletions(-)

diff --git a/drivers/scsi/constants.c b/drivers/scsi/constants.c
index d35a5d6..2f44707 100644
--- a/drivers/scsi/constants.c
+++ b/drivers/scsi/constants.c
@@ -1428,20 +1428,6 @@ scsi_print_sense_hdr(const char *name, struct scsi_sense_hdr *sshdr)
 }
 EXPORT_SYMBOL(scsi_print_sense_hdr);
 
-/*
- * Print normalized SCSI sense header with device information and a prefix.
- */
-void
-scsi_cmd_print_sense_hdr(struct scsi_cmnd *scmd, const char *desc,
-			  struct scsi_sense_hdr *sshdr)
-{
-	scmd_printk(KERN_INFO, scmd, "%s: ", desc);
-	scsi_show_sense_hdr(sshdr);
-	scmd_printk(KERN_INFO, scmd, "%s: ", desc);
-	scsi_show_extd_sense(sshdr->asc, sshdr->ascq);
-}
-EXPORT_SYMBOL(scsi_cmd_print_sense_hdr);
-
 static void
 scsi_decode_sense_buffer(const unsigned char *sense_buffer, int sense_len,
 		       struct scsi_sense_hdr *sshdr)
diff --git a/include/scsi/scsi_dbg.h b/include/scsi/scsi_dbg.h
index e89844c..5a43a4c 100644
--- a/include/scsi/scsi_dbg.h
+++ b/include/scsi/scsi_dbg.h
@@ -9,8 +9,6 @@ extern void __scsi_print_command(unsigned char *);
 extern void scsi_show_extd_sense(unsigned char, unsigned char);
 extern void scsi_show_sense_hdr(struct scsi_sense_hdr *);
 extern void scsi_print_sense_hdr(const char *, struct scsi_sense_hdr *);
-extern void scsi_cmd_print_sense_hdr(struct scsi_cmnd *, const char *,
-				     struct scsi_sense_hdr *);
 extern void scsi_print_sense(char *, struct scsi_cmnd *);
 extern void __scsi_print_sense(const char *name,
 			       const unsigned char *sense_buffer,
-- 
1.8.5.2

[PATCH 02/22] aha152x: Remove #ifdef 0 section

[Hannes Reinecke]

Signed-off-by: Hannes Reinecke <hare@suse.de>
---
 drivers/scsi/aha152x.c | 7 -------
 1 file changed, 7 deletions(-)

diff --git a/drivers/scsi/aha152x.c b/drivers/scsi/aha152x.c
index e77b72f..4da3a3b 100644
--- a/drivers/scsi/aha152x.c
+++ b/drivers/scsi/aha152x.c
@@ -1553,13 +1553,6 @@ static void busfree_run(struct Scsi_Host *shpnt)
 			struct scsi_cmnd *cmd = HOSTDATA(shpnt)->done_SC;
 			struct aha152x_scdata *sc = SCDATA(cmd);
 
-#if 0
-			if(HOSTDATA(shpnt)->debug & debug_eh) {
-				printk(ERR_LEAD "received sense: ", CMDINFO(DONE_SC));
-				scsi_print_sense("bh", DONE_SC);
-			}
-#endif
-
 			scsi_eh_restore_cmnd(cmd, &sc->ses);
 
 			cmd->SCp.Status = SAM_STAT_CHECK_CONDITION;
-- 
1.8.5.2

[PATCH 03/22] sd: Remove scsi_print_sense() in sd_done()

[Hannes Reinecke]

sd_done() was calling scsi_print_sense() for a sense code
of 'NO_SENSE'.

Signed-off-by: Hannes Reinecke <hare@suse.de>
---
 drivers/scsi/sd.c | 1 -
 1 file changed, 1 deletion(-)

diff --git a/drivers/scsi/sd.c b/drivers/scsi/sd.c
index aa43496..f5ca203 100644
--- a/drivers/scsi/sd.c
+++ b/drivers/scsi/sd.c
@@ -1730,7 +1730,6 @@ static int sd_done(struct scsi_cmnd *SCpnt)
 		 * unknown amount of data was transferred so treat it as an
 		 * error.
 		 */
-		scsi_print_sense("sd", SCpnt);
 		SCpnt->result = 0;
 		memset(SCpnt->sense_buffer, 0, SCSI_SENSE_BUFFERSIZE);
 		break;
-- 
1.8.5.2

[PATCH 04/22] scsi: introduce sdev_prefix_printk()

[Hannes Reinecke]

Signed-off-by: Hannes Reinecke <hare@suse.de>
---
 include/scsi/scsi_device.h | 5 +++++
 1 file changed, 5 insertions(+)

diff --git a/include/scsi/scsi_device.h b/include/scsi/scsi_device.h
index 1a0d184..91ac2e6 100644
--- a/include/scsi/scsi_device.h
+++ b/include/scsi/scsi_device.h
@@ -243,6 +243,11 @@ struct scsi_dh_data {
 #define sdev_dbg(sdev, fmt, a...) \
 	dev_dbg(&(sdev)->sdev_gendev, fmt, ##a)
 
+#define sdev_prefix_printk(l, sdev, p, fmt, a...)			\
+	(p) ?								\
+	sdev_printk(l, sdev, "[%s] " fmt, p, ##a) :			\
+	sdev_printk(l, sdev, fmt, ##a)
+
 #define scmd_printk(prefix, scmd, fmt, a...)				\
         (scmd)->request->rq_disk ?					\
 	sdev_printk(prefix, (scmd)->device, "[%s] " fmt,		\
-- 
1.8.5.2

[PATCH 05/22] scsi: Use sdev as argument for sense code printing

[Hannes Reinecke]

We should be using the standard dev_printk() variants for
sense code printing.

Signed-off-by: Hannes Reinecke <hare@suse.de>
---
 drivers/scsi/53c700.c      |   2 +-
 drivers/scsi/ch.c          |   2 +-
 drivers/scsi/constants.c   | 113 +++++++++++++++++++++------------------------
 drivers/scsi/osst.c        |   8 ++--
 drivers/scsi/scsi.c        |   2 +-
 drivers/scsi/scsi_error.c  |   2 +-
 drivers/scsi/scsi_ioctl.c  |   2 +-
 drivers/scsi/scsi_lib.c    |   4 +-
 drivers/scsi/sd.c          |   9 ++--
 drivers/scsi/sg.c          |   2 +-
 drivers/scsi/sr_ioctl.c    |   6 +--
 drivers/scsi/st.c          |   6 ++-
 drivers/scsi/storvsc_drv.c |   3 +-
 include/scsi/scsi_dbg.h    |  17 ++++---
 14 files changed, 91 insertions(+), 87 deletions(-)

diff --git a/drivers/scsi/53c700.c b/drivers/scsi/53c700.c
index fabd4be..68bf423 100644
--- a/drivers/scsi/53c700.c
+++ b/drivers/scsi/53c700.c
@@ -602,7 +602,7 @@ NCR_700_scsi_done(struct NCR_700_Host_Parameters *hostdata,
 #ifdef NCR_700_DEBUG
 			printk(" ORIGINAL CMD %p RETURNED %d, new return is %d sense is\n",
 			       SCp, SCp->cmnd[7], result);
-			scsi_print_sense("53c700", SCp);
+			scsi_print_sense(SCp);
 
 #endif
 			dma_unmap_single(hostdata->dev, slot->dma_handle,
diff --git a/drivers/scsi/ch.c b/drivers/scsi/ch.c
index ef5ae0d..eea94a9 100644
--- a/drivers/scsi/ch.c
+++ b/drivers/scsi/ch.c
@@ -207,7 +207,7 @@ ch_do_scsi(scsi_changer *ch, unsigned char *cmd,
 	DPRINTK("result: 0x%x\n",result);
 	if (driver_byte(result) & DRIVER_SENSE) {
 		if (debug)
-			scsi_print_sense_hdr(ch->name, &sshdr);
+			scsi_print_sense_hdr(ch->device, ch->name, &sshdr);
 		errno = ch_find_errno(&sshdr);
 
 		switch(sshdr.sense_key) {
diff --git a/drivers/scsi/constants.c b/drivers/scsi/constants.c
index 2f44707..36e1ffd 100644
--- a/drivers/scsi/constants.c
+++ b/drivers/scsi/constants.c
@@ -1292,18 +1292,19 @@ static const struct error_info additional[] =
 
 struct error_info2 {
 	unsigned char code1, code2_min, code2_max;
+	const char * str;
 	const char * fmt;
 };
 
 static const struct error_info2 additional2[] =
 {
-	{0x40, 0x00, 0x7f, "Ram failure (%x)"},
-	{0x40, 0x80, 0xff, "Diagnostic failure on component (%x)"},
-	{0x41, 0x00, 0xff, "Data path failure (%x)"},
-	{0x42, 0x00, 0xff, "Power-on or self-test failure (%x)"},
-	{0x4D, 0x00, 0xff, "Tagged overlapped commands (task tag %x)"},
-	{0x70, 0x00, 0xff, "Decompression exception short algorithm id of %x"},
-	{0, 0, 0, NULL}
+	{0x40, 0x00, 0x7f, "Ram failure", ""},
+	{0x40, 0x80, 0xff, "Diagnostic failure on component", ""},
+	{0x41, 0x00, 0xff, "Data path failure", ""},
+	{0x42, 0x00, 0xff, "Power-on or self-test failure", ""},
+	{0x4D, 0x00, 0xff, "Tagged overlapped commands", "task tag "},
+	{0x70, 0x00, 0xff, "Decompression exception", "short algorithm id of "},
+	{0, 0, 0, NULL, NULL}
 };
 
 /* description of the sense key values */
@@ -1349,7 +1350,8 @@ EXPORT_SYMBOL(scsi_sense_key_string);
  * This string may contain a "%x" and should be printed with ascq as arg.
  */
 const char *
-scsi_extd_sense_format(unsigned char asc, unsigned char ascq) {
+scsi_extd_sense_format(unsigned char asc, unsigned char ascq,
+		       const char **fmt) {
 #ifdef CONFIG_SCSI_CONSTANTS
 	int i;
 	unsigned short code = ((asc << 8) | ascq);
@@ -1361,7 +1363,8 @@ scsi_extd_sense_format(unsigned char asc, unsigned char ascq) {
 		if (additional2[i].code1 == asc &&
 		    ascq >= additional2[i].code2_min &&
 		    ascq <= additional2[i].code2_max)
-			return additional2[i].fmt;
+			*fmt = additional2[i].fmt;
+			return additional2[i].str;
 	}
 #endif
 	return NULL;
@@ -1369,49 +1372,47 @@ scsi_extd_sense_format(unsigned char asc, unsigned char ascq) {
 EXPORT_SYMBOL(scsi_extd_sense_format);
 
 void
-scsi_show_extd_sense(unsigned char asc, unsigned char ascq)
+scsi_show_extd_sense(struct scsi_device *sdev, const char *name,
+		     unsigned char asc, unsigned char ascq)
 {
-        const char *extd_sense_fmt = scsi_extd_sense_format(asc, ascq);
-
-	if (extd_sense_fmt) {
-		if (strstr(extd_sense_fmt, "%x")) {
-			printk("Add. Sense: ");
-			printk(extd_sense_fmt, ascq);
-		} else
-			printk("Add. Sense: %s", extd_sense_fmt);
+	const char *extd_sense_fmt = NULL;
+	const char *extd_sense_str = scsi_extd_sense_format(asc, ascq,
+							    &extd_sense_str);
+
+	if (extd_sense_str) {
+		sdev_prefix_printk(KERN_INFO, sdev, name,
+				   "Add. Sense: %s (%s%x)",
+				   extd_sense_str, extd_sense_fmt, ascq);
 	} else {
-		if (asc >= 0x80)
-			printk("<<vendor>> ASC=0x%x ASCQ=0x%x", asc,
-			       ascq);
-		if (ascq >= 0x80)
-			printk("ASC=0x%x <<vendor>> ASCQ=0x%x", asc,
-			       ascq);
-		else
-			printk("ASC=0x%x ASCQ=0x%x", asc, ascq);
+		sdev_prefix_printk(KERN_INFO, sdev, name,
+				   "%sASC=0x%x %sASCQ=0x%x\n",
+				   asc >= 0x80 ? "<<vendor>> " : "", asc,
+				   ascq >= 0x80 ? "<<vendor>> " : "", ascq);
 	}
-
-	printk("\n");
 }
 EXPORT_SYMBOL(scsi_show_extd_sense);
 
 void
-scsi_show_sense_hdr(struct scsi_sense_hdr *sshdr)
+scsi_show_sense_hdr(struct scsi_device *sdev, const char *name,
+		    struct scsi_sense_hdr *sshdr)
 {
 	const char *sense_txt;
 
 	sense_txt = scsi_sense_key_string(sshdr->sense_key);
 	if (sense_txt)
-		printk("Sense Key : %s ", sense_txt);
+		sdev_prefix_printk(KERN_INFO, sdev, name,
+				   "Sense Key : %s [%s]%s\n", sense_txt,
+				   scsi_sense_is_deferred(sshdr) ?
+				   "deferred" : "current",
+				   sshdr->response_code >= 0x72 ?
+				   " [descriptor]" : "");
 	else
-		printk("Sense Key : 0x%x ", sshdr->sense_key);
-
-	printk("%s", scsi_sense_is_deferred(sshdr) ? "[deferred] " :
-	       "[current] ");
-
-	if (sshdr->response_code >= 0x72)
-		printk("[descriptor]");
-
-	printk("\n");
+		sdev_prefix_printk(KERN_INFO, sdev, name,
+				   "Sense Key : 0x%x [%s]%s", sshdr->sense_key,
+				   scsi_sense_is_deferred(sshdr) ?
+				   "deferred" : "current",
+				   sshdr->response_code >= 0x72 ?
+				   " [descriptor]" : "");
 }
 EXPORT_SYMBOL(scsi_show_sense_hdr);
 
@@ -1419,12 +1420,11 @@ EXPORT_SYMBOL(scsi_show_sense_hdr);
  * Print normalized SCSI sense header with a prefix.
  */
 void
-scsi_print_sense_hdr(const char *name, struct scsi_sense_hdr *sshdr)
+scsi_print_sense_hdr(struct scsi_device *sdev, const char *name,
+		     struct scsi_sense_hdr *sshdr)
 {
-	printk(KERN_INFO "%s: ", name);
-	scsi_show_sense_hdr(sshdr);
-	printk(KERN_INFO "%s: ", name);
-	scsi_show_extd_sense(sshdr->asc, sshdr->ascq);
+	scsi_show_sense_hdr(sdev, name, sshdr);
+	scsi_show_extd_sense(sdev, name, sshdr->asc, sshdr->ascq);
 }
 EXPORT_SYMBOL(scsi_print_sense_hdr);
 
@@ -1513,33 +1513,26 @@ scsi_decode_sense_extras(const unsigned char *sense_buffer, int sense_len,
 }
 
 /* Normalize and print sense buffer with name prefix */
-void __scsi_print_sense(const char *name, const unsigned char *sense_buffer,
-			int sense_len)
+void __scsi_print_sense(struct scsi_device *sdev, const char *name,
+			const unsigned char *sense_buffer, int sense_len)
 {
 	struct scsi_sense_hdr sshdr;
 
-	printk(KERN_INFO "%s: ", name);
 	scsi_decode_sense_buffer(sense_buffer, sense_len, &sshdr);
-	scsi_show_sense_hdr(&sshdr);
+	scsi_show_sense_hdr(sdev, name, &sshdr);
 	scsi_decode_sense_extras(sense_buffer, sense_len, &sshdr);
-	printk(KERN_INFO "%s: ", name);
-	scsi_show_extd_sense(sshdr.asc, sshdr.ascq);
+	scsi_show_extd_sense(sdev, name, sshdr.asc, sshdr.ascq);
 }
 EXPORT_SYMBOL(__scsi_print_sense);
 
 /* Normalize and print sense buffer in SCSI command */
-void scsi_print_sense(char *name, struct scsi_cmnd *cmd)
+void scsi_print_sense(struct scsi_cmnd *cmd)
 {
-	struct scsi_sense_hdr sshdr;
+	struct gendisk *disk = cmd->request->rq_disk;
+	const char *disk_name = disk ? disk->disk_name : NULL;
 
-	scmd_printk(KERN_INFO, cmd, " ");
-	scsi_decode_sense_buffer(cmd->sense_buffer, SCSI_SENSE_BUFFERSIZE,
-				 &sshdr);
-	scsi_show_sense_hdr(&sshdr);
-	scsi_decode_sense_extras(cmd->sense_buffer, SCSI_SENSE_BUFFERSIZE,
-				 &sshdr);
-	scmd_printk(KERN_INFO, cmd, " ");
-	scsi_show_extd_sense(sshdr.asc, sshdr.ascq);
+	__scsi_print_sense(cmd->device, disk_name, cmd->sense_buffer,
+			   SCSI_SENSE_BUFFERSIZE);
 }
 EXPORT_SYMBOL(scsi_print_sense);
 
diff --git a/drivers/scsi/osst.c b/drivers/scsi/osst.c
index 0727ea7..4ba2a9f 100644
--- a/drivers/scsi/osst.c
+++ b/drivers/scsi/osst.c
@@ -259,9 +259,10 @@ static int osst_chk_result(struct osst_tape * STp, struct osst_request * SRpnt)
 		   SRpnt->cmd[0], SRpnt->cmd[1], SRpnt->cmd[2],
 		   SRpnt->cmd[3], SRpnt->cmd[4], SRpnt->cmd[5]);
 		if (scode) printk(OSST_DEB_MSG "%s:D: Sense: %02x, ASC: %02x, ASCQ: %02x\n",
-			       	name, scode, sense[12], sense[13]);
+				  name, scode, sense[12], sense[13]);
 		if (cmdstatp->have_sense)
-			__scsi_print_sense("osst ", SRpnt->sense, SCSI_SENSE_BUFFERSIZE);
+			__scsi_print_sense(STp->device, name,
+					   SRpnt->sense, SCSI_SENSE_BUFFERSIZE);
 	}
 	else
 #endif
@@ -275,7 +276,8 @@ static int osst_chk_result(struct osst_tape * STp, struct osst_request * SRpnt)
 		 SRpnt->cmd[0] != TEST_UNIT_READY)) { /* Abnormal conditions for tape */
 		if (cmdstatp->have_sense) {
 			printk(KERN_WARNING "%s:W: Command with sense data:\n", name);
-			__scsi_print_sense("osst ", SRpnt->sense, SCSI_SENSE_BUFFERSIZE);
+			__scsi_print_sense(STp->device, name,
+					   SRpnt->sense, SCSI_SENSE_BUFFERSIZE);
 		}
 		else {
 			static	int	notyetprinted = 1;
diff --git a/drivers/scsi/scsi.c b/drivers/scsi/scsi.c
index df33060..8954036 100644
--- a/drivers/scsi/scsi.c
+++ b/drivers/scsi/scsi.c
@@ -598,7 +598,7 @@ void scsi_log_completion(struct scsi_cmnd *cmd, int disposition)
 			scsi_print_result(cmd);
 			scsi_print_command(cmd);
 			if (status_byte(cmd->result) & CHECK_CONDITION)
-				scsi_print_sense("", cmd);
+				scsi_print_sense(cmd);
 			if (level > 3)
 				scmd_printk(KERN_INFO, cmd,
 					    "scsi host busy %d failed %d\n",
diff --git a/drivers/scsi/scsi_error.c b/drivers/scsi/scsi_error.c
index 6b20ef3..6c99624 100644
--- a/drivers/scsi/scsi_error.c
+++ b/drivers/scsi/scsi_error.c
@@ -1180,7 +1180,7 @@ int scsi_eh_get_sense(struct list_head *work_q,
 		SCSI_LOG_ERROR_RECOVERY(3, scmd_printk(KERN_INFO, scmd,
 			"sense requested for %p result %x\n",
 			scmd, scmd->result));
-		SCSI_LOG_ERROR_RECOVERY(3, scsi_print_sense("bh", scmd));
+		SCSI_LOG_ERROR_RECOVERY(3, scsi_print_sense(scmd));
 
 		rtn = scsi_decide_disposition(scmd);
 
diff --git a/drivers/scsi/scsi_ioctl.c b/drivers/scsi/scsi_ioctl.c
index 1aaaf43..7d2de08 100644
--- a/drivers/scsi/scsi_ioctl.c
+++ b/drivers/scsi/scsi_ioctl.c
@@ -126,7 +126,7 @@ static int ioctl_internal_command(struct scsi_device *sdev, char *cmd,
 			sdev_printk(KERN_INFO, sdev,
 				    "ioctl_internal_command return code = %x\n",
 				    result);
-			scsi_print_sense_hdr("   ", &sshdr);
+			scsi_print_sense_hdr(sdev, NULL, &sshdr);
 			break;
 		}
 	}
diff --git a/drivers/scsi/scsi_lib.c b/drivers/scsi/scsi_lib.c
index 8b76231..de178f7 100644
--- a/drivers/scsi/scsi_lib.c
+++ b/drivers/scsi/scsi_lib.c
@@ -911,7 +911,7 @@ void scsi_io_completion(struct scsi_cmnd *cmd, unsigned int good_bytes)
 		if ((sshdr.asc == 0x0) && (sshdr.ascq == 0x1d))
 			;
 		else if (!(req->cmd_flags & REQ_QUIET))
-			scsi_print_sense("", cmd);
+			scsi_print_sense(cmd);
 		result = 0;
 		/* BLOCK_PC may have set error */
 		error = 0;
@@ -1040,7 +1040,7 @@ void scsi_io_completion(struct scsi_cmnd *cmd, unsigned int good_bytes)
 		if (!(req->cmd_flags & REQ_QUIET)) {
 			scsi_print_result(cmd);
 			if (driver_byte(result) & DRIVER_SENSE)
-				scsi_print_sense("", cmd);
+				scsi_print_sense(cmd);
 			scsi_print_command(cmd);
 		}
 		if (!scsi_end_request(req, error, blk_rq_err_bytes(req), 0))
diff --git a/drivers/scsi/sd.c b/drivers/scsi/sd.c
index f5ca203..aac267a 100644
--- a/drivers/scsi/sd.c
+++ b/drivers/scsi/sd.c
@@ -3319,10 +3319,11 @@ module_exit(exit_sd);
 static void sd_print_sense_hdr(struct scsi_disk *sdkp,
 			       struct scsi_sense_hdr *sshdr)
 {
-	sd_printk(KERN_INFO, sdkp, " ");
-	scsi_show_sense_hdr(sshdr);
-	sd_printk(KERN_INFO, sdkp, " ");
-	scsi_show_extd_sense(sshdr->asc, sshdr->ascq);
+	scsi_show_sense_hdr(sdkp->device,
+			    sdkp->disk ? sdkp->disk->disk_name : NULL, sshdr);
+	scsi_show_extd_sense(sdkp->device,
+			     sdkp->disk ? sdkp->disk->disk_name : NULL,
+			     sshdr->asc, sshdr->ascq);
 }
 
 static void sd_print_result(struct scsi_disk *sdkp, int result)
diff --git a/drivers/scsi/sg.c b/drivers/scsi/sg.c
index 01cf888..16f826e 100644
--- a/drivers/scsi/sg.c
+++ b/drivers/scsi/sg.c
@@ -1360,7 +1360,7 @@ sg_rq_end_io(struct request *rq, int uptodate)
 		if ((sdp->sgdebug > 0) &&
 		    ((CHECK_CONDITION == srp->header.masked_status) ||
 		     (COMMAND_TERMINATED == srp->header.masked_status)))
-			__scsi_print_sense(__func__, sense,
+			__scsi_print_sense(sdp->device, __func__, sense,
 					   SCSI_SENSE_BUFFERSIZE);
 
 		/* Following if statement is a patch supplied by Eric Youngdale */
diff --git a/drivers/scsi/sr_ioctl.c b/drivers/scsi/sr_ioctl.c
index 6389fcf..17e0c2b 100644
--- a/drivers/scsi/sr_ioctl.c
+++ b/drivers/scsi/sr_ioctl.c
@@ -246,7 +246,7 @@ int sr_do_ioctl(Scsi_CD *cd, struct packet_command *cgc)
 					  "CDROM not ready.  Make sure there "
 					  "is a disc in the drive.\n");
 #ifdef DEBUG
-			scsi_print_sense_hdr("sr", &sshdr);
+			scsi_print_sense_hdr(cd->device, cd->cdi.name, &sshdr);
 #endif
 			err = -ENOMEDIUM;
 			break;
@@ -258,14 +258,14 @@ int sr_do_ioctl(Scsi_CD *cd, struct packet_command *cgc)
 				err = -EDRIVE_CANT_DO_THIS;
 #ifdef DEBUG
 			__scsi_print_command(cgc->cmd);
-			scsi_print_sense_hdr("sr", &sshdr);
+			scsi_print_sense_hdr(cd->device, cd->cdi.name, &sshdr);
 #endif
 			break;
 		default:
 			sr_printk(KERN_ERR, cd,
 				  "CDROM (ioctl) error, command: ");
 			__scsi_print_command(cgc->cmd);
-			scsi_print_sense_hdr("sr", &sshdr);
+			scsi_print_sense_hdr(cd->device, cd->cdi.name, &sshdr);
 			err = -EIO;
 		}
 	}
diff --git a/drivers/scsi/st.c b/drivers/scsi/st.c
index aff9689..c0cc4ca 100644
--- a/drivers/scsi/st.c
+++ b/drivers/scsi/st.c
@@ -374,7 +374,8 @@ static int st_chk_result(struct scsi_tape *STp, struct st_request * SRpnt)
 			    SRpnt->cmd[0], SRpnt->cmd[1], SRpnt->cmd[2],
 			    SRpnt->cmd[3], SRpnt->cmd[4], SRpnt->cmd[5]);
 		if (cmdstatp->have_sense)
-			 __scsi_print_sense(name, SRpnt->sense, SCSI_SENSE_BUFFERSIZE);
+			__scsi_print_sense(STp->device, name,
+					   SRpnt->sense, SCSI_SENSE_BUFFERSIZE);
 	} ) /* end DEB */
 	if (!debugging) { /* Abnormal conditions for tape */
 		if (!cmdstatp->have_sense)
@@ -390,7 +391,8 @@ static int st_chk_result(struct scsi_tape *STp, struct st_request * SRpnt)
 			 SRpnt->cmd[0] != MODE_SENSE &&
 			 SRpnt->cmd[0] != TEST_UNIT_READY) {
 
-			__scsi_print_sense(name, SRpnt->sense, SCSI_SENSE_BUFFERSIZE);
+			__scsi_print_sense(STp->device, name,
+					   SRpnt->sense, SCSI_SENSE_BUFFERSIZE);
 		}
 	}
 
diff --git a/drivers/scsi/storvsc_drv.c b/drivers/scsi/storvsc_drv.c
index fecac5d0..9168d1b 100644
--- a/drivers/scsi/storvsc_drv.c
+++ b/drivers/scsi/storvsc_drv.c
@@ -1097,7 +1097,8 @@ static void storvsc_command_completion(struct storvsc_cmd_request *cmd_request)
 	if (scmnd->result) {
 		if (scsi_normalize_sense(scmnd->sense_buffer,
 				SCSI_SENSE_BUFFERSIZE, &sense_hdr))
-			scsi_print_sense_hdr("storvsc", &sense_hdr);
+			scsi_print_sense_hdr(scmnd->device, "storvsc",
+					     &sense_hdr);
 	}
 
 	if (vm_srb->srb_status != SRB_STATUS_SUCCESS)
diff --git a/include/scsi/scsi_dbg.h b/include/scsi/scsi_dbg.h
index 5a43a4c..cd0c873 100644
--- a/include/scsi/scsi_dbg.h
+++ b/include/scsi/scsi_dbg.h
@@ -2,21 +2,26 @@
 #define _SCSI_SCSI_DBG_H
 
 struct scsi_cmnd;
+struct scsi_device;
 struct scsi_sense_hdr;
 
 extern void scsi_print_command(struct scsi_cmnd *);
 extern void __scsi_print_command(unsigned char *);
-extern void scsi_show_extd_sense(unsigned char, unsigned char);
-extern void scsi_show_sense_hdr(struct scsi_sense_hdr *);
-extern void scsi_print_sense_hdr(const char *, struct scsi_sense_hdr *);
-extern void scsi_print_sense(char *, struct scsi_cmnd *);
-extern void __scsi_print_sense(const char *name,
+extern void scsi_show_extd_sense(struct scsi_device *, const char *,
+				 unsigned char, unsigned char);
+extern void scsi_show_sense_hdr(struct scsi_device *, const char *,
+				struct scsi_sense_hdr *);
+extern void scsi_print_sense_hdr(struct scsi_device *, const char *,
+				 struct scsi_sense_hdr *);
+extern void scsi_print_sense(struct scsi_cmnd *);
+extern void __scsi_print_sense(struct scsi_device *, const char *name,
 			       const unsigned char *sense_buffer,
 			       int sense_len);
 extern void scsi_show_result(int);
 extern void scsi_print_result(struct scsi_cmnd *);
 extern void scsi_print_status(unsigned char);
 extern const char *scsi_sense_key_string(unsigned char);
-extern const char *scsi_extd_sense_format(unsigned char, unsigned char);
+extern const char *scsi_extd_sense_format(unsigned char, unsigned char,
+					  const char **);
 
 #endif /* _SCSI_SCSI_DBG_H */
-- 
1.8.5.2

[PATCH 06/22] scsi: stop decoding if scsi_normalize_sense() fails

[Hannes Reinecke]

If scsi_normalize_sense() fails we couldn't decode the sense
buffer, so we should not try to interpret the result.
We should rather dump the sense buffer instead and stop decoding.

Signed-off-by: Hannes Reinecke <hare@suse.de>
---
 drivers/scsi/constants.c | 37 +++++++++++++++++++------------------
 1 file changed, 19 insertions(+), 18 deletions(-)

diff --git a/drivers/scsi/constants.c b/drivers/scsi/constants.c
index 36e1ffd..6b05575 100644
--- a/drivers/scsi/constants.c
+++ b/drivers/scsi/constants.c
@@ -1429,25 +1429,21 @@ scsi_print_sense_hdr(struct scsi_device *sdev, const char *name,
 EXPORT_SYMBOL(scsi_print_sense_hdr);
 
 static void
-scsi_decode_sense_buffer(const unsigned char *sense_buffer, int sense_len,
-		       struct scsi_sense_hdr *sshdr)
+scsi_dump_sense_buffer(struct scsi_device *sdev, const char *name,
+		       const unsigned char *sense_buffer, int sense_len)
 {
-	int k, num, res;
+	char linebuf[128];
+	int i, linelen, remaining;
 
-	res = scsi_normalize_sense(sense_buffer, sense_len, sshdr);
-	if (0 == res) {
-		/* this may be SCSI-1 sense data */
-		num = (sense_len < 32) ? sense_len : 32;
-		printk("Unrecognized sense data (in hex):");
-		for (k = 0; k < num; ++k) {
-			if (0 == (k % 16)) {
-				printk("\n");
-				printk(KERN_INFO "        ");
-			}
-			printk("%02x ", sense_buffer[k]);
-		}
-		printk("\n");
-		return;
+	remaining = sense_len;
+	for (i = 0; i < sense_len; i += 16) {
+		linelen = min(remaining, 16);
+		remaining -= 16;
+
+		hex_dump_to_buffer(sense_buffer + i, linelen, 16, 1,
+				   linebuf, sizeof(linebuf), false);
+		sdev_prefix_printk(KERN_INFO, sdev, name,
+				   "Sense: %s\n", linebuf);
 	}
 }
 
@@ -1517,8 +1513,13 @@ void __scsi_print_sense(struct scsi_device *sdev, const char *name,
 			const unsigned char *sense_buffer, int sense_len)
 {
 	struct scsi_sense_hdr sshdr;
+	int res;
 
-	scsi_decode_sense_buffer(sense_buffer, sense_len, &sshdr);
+	res = scsi_normalize_sense(sense_buffer, sense_len, &sshdr);
+	if (res == 0) {
+		scsi_dump_sense_buffer(sdev, name, sense_buffer, sense_len);
+		return;
+	}
 	scsi_show_sense_hdr(sdev, name, &sshdr);
 	scsi_decode_sense_extras(sense_buffer, sense_len, &sshdr);
 	scsi_show_extd_sense(sdev, name, sshdr.asc, sshdr.ascq);
-- 
1.8.5.2

[PATCH 07/22] scsi: do not decode sense extras

[Hannes Reinecke]

Currently we're only decoding sense extras for tape devices.
And even there only for fixed format sense formats.
As this is of rather limited use in the general case we should
be stop trying to decode things here and rather dump the entire
sense code.

Signed-off-by: Hannes Reinecke <hare@suse.de>
---
 drivers/scsi/constants.c | 63 +-----------------------------------------------
 1 file changed, 1 insertion(+), 62 deletions(-)

diff --git a/drivers/scsi/constants.c b/drivers/scsi/constants.c
index 6b05575..f0a6595 100644
--- a/drivers/scsi/constants.c
+++ b/drivers/scsi/constants.c
@@ -1447,67 +1447,6 @@ scsi_dump_sense_buffer(struct scsi_device *sdev, const char *name,
 	}
 }
 
-static void
-scsi_decode_sense_extras(const unsigned char *sense_buffer, int sense_len,
-			 struct scsi_sense_hdr *sshdr)
-{
-	int k, num, res;
-
-	if (sshdr->response_code < 0x72)
-	{
-		/* only decode extras for "fixed" format now */
-		char buff[80];
-		int blen, fixed_valid;
-		unsigned int info;
-
-		fixed_valid = sense_buffer[0] & 0x80;
-		info = ((sense_buffer[3] << 24) | (sense_buffer[4] << 16) |
-			(sense_buffer[5] << 8) | sense_buffer[6]);
-		res = 0;
-		memset(buff, 0, sizeof(buff));
-		blen = sizeof(buff) - 1;
-		if (fixed_valid)
-			res += snprintf(buff + res, blen - res,
-					"Info fld=0x%x", info);
-		if (sense_buffer[2] & 0x80) {
-			/* current command has read a filemark */
-			if (res > 0)
-				res += snprintf(buff + res, blen - res, ", ");
-			res += snprintf(buff + res, blen - res, "FMK");
-		}
-		if (sense_buffer[2] & 0x40) {
-			/* end-of-medium condition exists */
-			if (res > 0)
-				res += snprintf(buff + res, blen - res, ", ");
-			res += snprintf(buff + res, blen - res, "EOM");
-		}
-		if (sense_buffer[2] & 0x20) {
-			/* incorrect block length requested */
-			if (res > 0)
-				res += snprintf(buff + res, blen - res, ", ");
-			res += snprintf(buff + res, blen - res, "ILI");
-		}
-		if (res > 0)
-			printk("%s\n", buff);
-	} else if (sshdr->additional_length > 0) {
-		/* descriptor format with sense descriptors */
-		num = 8 + sshdr->additional_length;
-		num = (sense_len < num) ? sense_len : num;
-		printk("Descriptor sense data with sense descriptors "
-		       "(in hex):");
-		for (k = 0; k < num; ++k) {
-			if (0 == (k % 16)) {
-				printk("\n");
-				printk(KERN_INFO "        ");
-			}
-			printk("%02x ", sense_buffer[k]);
-		}
-
-		printk("\n");
-	}
-
-}
-
 /* Normalize and print sense buffer with name prefix */
 void __scsi_print_sense(struct scsi_device *sdev, const char *name,
 			const unsigned char *sense_buffer, int sense_len)
@@ -1521,8 +1460,8 @@ void __scsi_print_sense(struct scsi_device *sdev, const char *name,
 		return;
 	}
 	scsi_show_sense_hdr(sdev, name, &sshdr);
-	scsi_decode_sense_extras(sense_buffer, sense_len, &sshdr);
 	scsi_show_extd_sense(sdev, name, sshdr.asc, sshdr.ascq);
+	scsi_dump_sense_buffer(sdev, name, sense_buffer, sense_len);
 }
 EXPORT_SYMBOL(__scsi_print_sense);
 
-- 
1.8.5.2

[PATCH 08/22] scsi: dump sense buffer only for debugging

[Hannes Reinecke]

Dumping the entire sense buffer might overwhelm the logging functions,
so suppress it per default.

Signed-off-by: Hannes Reinecke <hare@suse.de.
---
 drivers/scsi/53c700.c    |  1 -
 drivers/scsi/constants.c | 32 ++++++++++++++++++++++----------
 drivers/scsi/scsi.c      |  6 ++++--
 drivers/scsi/sg.c        |  9 ++++++---
 drivers/scsi/st.c        | 11 ++++++++---
 include/scsi/scsi_dbg.h  | 10 ++++++----
 6 files changed, 46 insertions(+), 23 deletions(-)

diff --git a/drivers/scsi/53c700.c b/drivers/scsi/53c700.c
index 68bf423..8752481 100644
--- a/drivers/scsi/53c700.c
+++ b/drivers/scsi/53c700.c
@@ -603,7 +603,6 @@ NCR_700_scsi_done(struct NCR_700_Host_Parameters *hostdata,
 			printk(" ORIGINAL CMD %p RETURNED %d, new return is %d sense is\n",
 			       SCp, SCp->cmnd[7], result);
 			scsi_print_sense(SCp);
-
 #endif
 			dma_unmap_single(hostdata->dev, slot->dma_handle,
 					 SCSI_SENSE_BUFFERSIZE, DMA_FROM_DEVICE);
diff --git a/drivers/scsi/constants.c b/drivers/scsi/constants.c
index f0a6595..ecce5b3 100644
--- a/drivers/scsi/constants.c
+++ b/drivers/scsi/constants.c
@@ -1428,9 +1428,9 @@ scsi_print_sense_hdr(struct scsi_device *sdev, const char *name,
 }
 EXPORT_SYMBOL(scsi_print_sense_hdr);
 
-static void
-scsi_dump_sense_buffer(struct scsi_device *sdev, const char *name,
-		       const unsigned char *sense_buffer, int sense_len)
+void
+__scsi_dump_sense(struct scsi_device *sdev, const char *name,
+		  const unsigned char *sense_buffer, int sense_len)
 {
 	char linebuf[128];
 	int i, linelen, remaining;
@@ -1446,9 +1446,21 @@ scsi_dump_sense_buffer(struct scsi_device *sdev, const char *name,
 				   "Sense: %s\n", linebuf);
 	}
 }
+EXPORT_SYMBOL(__scsi_dump_sense);
+
+void
+scsi_dump_sense(struct scsi_cmnd *cmd)
+{
+	struct gendisk *disk = cmd->request->rq_disk;
+	const char *disk_name = disk ? disk->disk_name : NULL;
+
+	__scsi_dump_sense(cmd->device, disk_name, cmd->sense_buffer,
+			  SCSI_SENSE_BUFFERSIZE);
+}
+EXPORT_SYMBOL(scsi_dump_sense);
 
 /* Normalize and print sense buffer with name prefix */
-void __scsi_print_sense(struct scsi_device *sdev, const char *name,
+int __scsi_print_sense(struct scsi_device *sdev, const char *name,
 			const unsigned char *sense_buffer, int sense_len)
 {
 	struct scsi_sense_hdr sshdr;
@@ -1456,23 +1468,23 @@ void __scsi_print_sense(struct scsi_device *sdev, const char *name,
 
 	res = scsi_normalize_sense(sense_buffer, sense_len, &sshdr);
 	if (res == 0) {
-		scsi_dump_sense_buffer(sdev, name, sense_buffer, sense_len);
-		return;
+		__scsi_dump_sense(sdev, name, sense_buffer, sense_len);
+		return 0;
 	}
 	scsi_show_sense_hdr(sdev, name, &sshdr);
 	scsi_show_extd_sense(sdev, name, sshdr.asc, sshdr.ascq);
-	scsi_dump_sense_buffer(sdev, name, sense_buffer, sense_len);
+	return res;
 }
 EXPORT_SYMBOL(__scsi_print_sense);
 
 /* Normalize and print sense buffer in SCSI command */
-void scsi_print_sense(struct scsi_cmnd *cmd)
+int scsi_print_sense(struct scsi_cmnd *cmd)
 {
 	struct gendisk *disk = cmd->request->rq_disk;
 	const char *disk_name = disk ? disk->disk_name : NULL;
 
-	__scsi_print_sense(cmd->device, disk_name, cmd->sense_buffer,
-			   SCSI_SENSE_BUFFERSIZE);
+	return __scsi_print_sense(cmd->device, disk_name, cmd->sense_buffer,
+				  SCSI_SENSE_BUFFERSIZE);
 }
 EXPORT_SYMBOL(scsi_print_sense);
 
diff --git a/drivers/scsi/scsi.c b/drivers/scsi/scsi.c
index 8954036..283f053 100644
--- a/drivers/scsi/scsi.c
+++ b/drivers/scsi/scsi.c
@@ -597,8 +597,10 @@ void scsi_log_completion(struct scsi_cmnd *cmd, int disposition)
 			}
 			scsi_print_result(cmd);
 			scsi_print_command(cmd);
-			if (status_byte(cmd->result) & CHECK_CONDITION)
-				scsi_print_sense(cmd);
+			if (status_byte(cmd->result) & CHECK_CONDITION) {
+				if (scsi_print_sense(cmd))
+					scsi_dump_sense(cmd);
+			}
 			if (level > 3)
 				scmd_printk(KERN_INFO, cmd,
 					    "scsi host busy %d failed %d\n",
diff --git a/drivers/scsi/sg.c b/drivers/scsi/sg.c
index 16f826e..6bed135 100644
--- a/drivers/scsi/sg.c
+++ b/drivers/scsi/sg.c
@@ -1359,9 +1359,12 @@ sg_rq_end_io(struct request *rq, int uptodate)
 		srp->header.driver_status = driver_byte(result);
 		if ((sdp->sgdebug > 0) &&
 		    ((CHECK_CONDITION == srp->header.masked_status) ||
-		     (COMMAND_TERMINATED == srp->header.masked_status)))
-			__scsi_print_sense(sdp->device, __func__, sense,
-					   SCSI_SENSE_BUFFERSIZE);
+		     (COMMAND_TERMINATED == srp->header.masked_status))) {
+			if (__scsi_print_sense(sdp->device, __func__, sense,
+					       SCSI_SENSE_BUFFERSIZE))
+				__scsi_dump_sense(sdp->device, __func__,
+						  sense, SCSI_SENSE_BUFFERSIZE);
+		}
 
 		/* Following if statement is a patch supplied by Eric Youngdale */
 		if (driver_byte(result) != 0
diff --git a/drivers/scsi/st.c b/drivers/scsi/st.c
index c0cc4ca..8107e03 100644
--- a/drivers/scsi/st.c
+++ b/drivers/scsi/st.c
@@ -373,9 +373,14 @@ static int st_chk_result(struct scsi_tape *STp, struct st_request * SRpnt)
 			    "Error: %x, cmd: %x %x %x %x %x %x\n", result,
 			    SRpnt->cmd[0], SRpnt->cmd[1], SRpnt->cmd[2],
 			    SRpnt->cmd[3], SRpnt->cmd[4], SRpnt->cmd[5]);
-		if (cmdstatp->have_sense)
-			__scsi_print_sense(STp->device, name,
-					   SRpnt->sense, SCSI_SENSE_BUFFERSIZE);
+		if (cmdstatp->have_sense) {
+			if (__scsi_print_sense(STp->device, name,
+					       SRpnt->sense,
+					       SCSI_SENSE_BUFFERSIZE))
+				__scsi_dump_sense(STp->device, name,
+						  SRpnt->sense,
+						  SCSI_SENSE_BUFFERSIZE);
+		}
 	} ) /* end DEB */
 	if (!debugging) { /* Abnormal conditions for tape */
 		if (!cmdstatp->have_sense)
diff --git a/include/scsi/scsi_dbg.h b/include/scsi/scsi_dbg.h
index cd0c873..0bbf118 100644
--- a/include/scsi/scsi_dbg.h
+++ b/include/scsi/scsi_dbg.h
@@ -13,10 +13,12 @@ extern void scsi_show_sense_hdr(struct scsi_device *, const char *,
 				struct scsi_sense_hdr *);
 extern void scsi_print_sense_hdr(struct scsi_device *, const char *,
 				 struct scsi_sense_hdr *);
-extern void scsi_print_sense(struct scsi_cmnd *);
-extern void __scsi_print_sense(struct scsi_device *, const char *name,
-			       const unsigned char *sense_buffer,
-			       int sense_len);
+extern int scsi_print_sense(struct scsi_cmnd *);
+extern int __scsi_print_sense(struct scsi_device *, const char *,
+			      const unsigned char *, int);
+extern void scsi_dump_sense(struct scsi_cmnd *);
+extern void __scsi_dump_sense(struct scsi_device *, const char *,
+			      const unsigned char *, int);
 extern void scsi_show_result(int);
 extern void scsi_print_result(struct scsi_cmnd *);
 extern void scsi_print_status(unsigned char);
-- 
1.8.5.2

[PATCH 09/22] Use sdev as argument for scsi_print_result

[Hannes Reinecke]

Passing in the SCSI device will tag the logging message with
the originating device.

Signed-off-by: Hannes Reinecke <hare@suse.de>
---
 drivers/scsi/constants.c | 28 ++++++++++++++++++----------
 drivers/scsi/sd.c        |  3 +--
 include/scsi/scsi_dbg.h  |  2 +-
 3 files changed, 20 insertions(+), 13 deletions(-)

diff --git a/drivers/scsi/constants.c b/drivers/scsi/constants.c
index ecce5b3..c0d7b3d 100644
--- a/drivers/scsi/constants.c
+++ b/drivers/scsi/constants.c
@@ -1503,31 +1503,39 @@ static const char * const driverbyte_table[]={
 "DRIVER_INVALID", "DRIVER_TIMEOUT", "DRIVER_HARD", "DRIVER_SENSE"};
 #define NUM_DRIVERBYTE_STRS ARRAY_SIZE(driverbyte_table)
 
-void scsi_show_result(int result)
+void scsi_show_result(struct scsi_device *sdev, const char *name, int result)
 {
 	int hb = host_byte(result);
 	int db = driver_byte(result);
+	const char *hb_string;
+	const char *db_string;
 
-	printk("Result: hostbyte=%s driverbyte=%s\n",
-	       (hb < NUM_HOSTBYTE_STRS ? hostbyte_table[hb]     : "invalid"),
-	       (db < NUM_DRIVERBYTE_STRS ? driverbyte_table[db] : "invalid"));
+	hb_string = (hb < NUM_HOSTBYTE_STRS) ? hostbyte_table[hb] : "invalid";
+	db_string = (db < NUM_DRIVERBYTE_STRS) ?
+		driverbyte_table[db] : "invalid";
+
+
+	sdev_prefix_printk(KERN_INFO, sdev, name,
+			   "Result: hostbyte=%s driverbyte=%s\n",
+			   hb_string, db_string);
 }
 
 #else
 
-void scsi_show_result(int result)
+void scsi_show_result(struct scsi_device *sdev, const char *name, int result)
 {
-	printk("Result: hostbyte=0x%02x driverbyte=0x%02x\n",
-	       host_byte(result), driver_byte(result));
+	sdev_prefix_printk(KERN_INFO, sdev, name,
+			   "Result: hostbyte=0x%02x driverbyte=0x%02x\n",
+			   host_byte(result), driver_byte(result));
 }
 
 #endif
 EXPORT_SYMBOL(scsi_show_result);
 
-
 void scsi_print_result(struct scsi_cmnd *cmd)
 {
-	scmd_printk(KERN_INFO, cmd, " ");
-	scsi_show_result(cmd->result);
+	const char *devname = cmd->request->rq_disk ?
+		cmd->request->rq_disk->disk_name : NULL;
+	scsi_show_result(cmd->device, devname, cmd->result);
 }
 EXPORT_SYMBOL(scsi_print_result);
diff --git a/drivers/scsi/sd.c b/drivers/scsi/sd.c
index aac267a..e780644 100644
--- a/drivers/scsi/sd.c
+++ b/drivers/scsi/sd.c
@@ -3328,7 +3328,6 @@ static void sd_print_sense_hdr(struct scsi_disk *sdkp,
 
 static void sd_print_result(struct scsi_disk *sdkp, int result)
 {
-	sd_printk(KERN_INFO, sdkp, " ");
-	scsi_show_result(result);
+	scsi_show_result(sdkp->device, sdkp->disk->disk_name, result);
 }
 
diff --git a/include/scsi/scsi_dbg.h b/include/scsi/scsi_dbg.h
index 0bbf118..3d9ac9f 100644
--- a/include/scsi/scsi_dbg.h
+++ b/include/scsi/scsi_dbg.h
@@ -19,7 +19,7 @@ extern int __scsi_print_sense(struct scsi_device *, const char *,
 extern void scsi_dump_sense(struct scsi_cmnd *);
 extern void __scsi_dump_sense(struct scsi_device *, const char *,
 			      const unsigned char *, int);
-extern void scsi_show_result(int);
+extern void scsi_show_result(struct scsi_device *, const char *, int);
 extern void scsi_print_result(struct scsi_cmnd *);
 extern void scsi_print_status(unsigned char);
 extern const char *scsi_sense_key_string(unsigned char);
-- 
1.8.5.2

[PATCH 10/22] scsi: consolidate scsi_print_status()

[Hannes Reinecke]

Update scsi_print_status() to return a const string and remove
the open-coded versions.

Signed-off-by: Hannes Reinecke <hare@suse.de>
---
 drivers/scsi/aha152x.c        |  7 ++----
 drivers/scsi/constants.c      | 50 ++++++++++++++++++++++++-------------------
 include/scsi/scsi_dbg.h       |  2 +-
 include/trace/events/scsi.h   | 17 +--------------
 include/trace/events/target.h | 17 ++-------------
 5 files changed, 34 insertions(+), 59 deletions(-)

diff --git a/drivers/scsi/aha152x.c b/drivers/scsi/aha152x.c
index 4da3a3b..4287f86 100644
--- a/drivers/scsi/aha152x.c
+++ b/drivers/scsi/aha152x.c
@@ -2130,11 +2130,8 @@ static void status_run(struct Scsi_Host *shpnt)
 	CURRENT_SC->SCp.Status = GETPORT(SCSIDAT);
 
 #if defined(AHA152X_DEBUG)
-	if (HOSTDATA(shpnt)->debug & debug_status) {
-		printk(DEBUG_LEAD "inbound status %02x ", CMDINFO(CURRENT_SC), CURRENT_SC->SCp.Status);
-		scsi_print_status(CURRENT_SC->SCp.Status);
-		printk("\n");
-	}
+	if (HOSTDATA(shpnt)->debug & debug_status)
+		printk(DEBUG_LEAD "inbound status %02x\n", CMDINFO(CURRENT_SC), CURRENT_SC->SCp.Status);
 #endif
 }
 
diff --git a/drivers/scsi/constants.c b/drivers/scsi/constants.c
index c0d7b3d..323e944 100644
--- a/drivers/scsi/constants.c
+++ b/drivers/scsi/constants.c
@@ -437,34 +437,40 @@ EXPORT_SYMBOL(scsi_print_command);
  *	scsi_print_status - print scsi status description
  *	@scsi_status: scsi status value
  *
- *	If the status is recognized, the description is printed.
- *	Otherwise "Unknown status" is output. No trailing space.
- *	If CONFIG_SCSI_CONSTANTS is not set, then print status in hex
- *	(e.g. "0x2" for Check Condition).
+ *	If the status is recognized, the description is returned.
+ *	Otherwise "Unknown status" is returned.
  **/
-void
+const char *
 scsi_print_status(unsigned char scsi_status) {
-#ifdef CONFIG_SCSI_CONSTANTS
 	const char * ccp;
 
 	switch (scsi_status) {
-	case 0:    ccp = "Good"; break;
-	case 0x2:  ccp = "Check Condition"; break;
-	case 0x4:  ccp = "Condition Met"; break;
-	case 0x8:  ccp = "Busy"; break;
-	case 0x10: ccp = "Intermediate"; break;
-	case 0x14: ccp = "Intermediate-Condition Met"; break;
-	case 0x18: ccp = "Reservation Conflict"; break;
-	case 0x22: ccp = "Command Terminated"; break;	/* obsolete */
-	case 0x28: ccp = "Task set Full"; break;	/* was: Queue Full */
-	case 0x30: ccp = "ACA Active"; break;
-	case 0x40: ccp = "Task Aborted"; break;
-	default:   ccp = "Unknown status";
+	case SAM_STAT_GOOD:
+		ccp = "Good"; break;
+	case SAM_STAT_CHECK_CONDITION:
+		ccp = "Check Condition"; break;
+	case SAM_STAT_CONDITION_MET:
+		ccp = "Condition Met"; break;
+	case SAM_STAT_BUSY:
+		ccp = "Busy"; break;
+	case SAM_STAT_INTERMEDIATE:
+		ccp = "Intermediate"; break;
+	case SAM_STAT_INTERMEDIATE_CONDITION_MET:
+		ccp = "Intermediate-Condition Met"; break;
+	case SAM_STAT_RESERVATION_CONFLICT:
+		ccp = "Reservation Conflict"; break;
+	case SAM_STAT_COMMAND_TERMINATED:
+		ccp = "Command Terminated"; break;	/* obsolete */
+	case SAM_STAT_TASK_SET_FULL:
+		ccp = "Task set Full"; break;	/* was: Queue Full */
+	case SAM_STAT_ACA_ACTIVE:
+		ccp = "ACA Active"; break;
+	case SAM_STAT_TASK_ABORTED:
+		ccp = "Task Aborted"; break;
+	default:
+		ccp = "Unknown status";
 	}
-	printk(KERN_INFO "%s", ccp);
-#else
-	printk(KERN_INFO "0x%0x", scsi_status);
-#endif
+	return ccp;
 }
 EXPORT_SYMBOL(scsi_print_status);
 
diff --git a/include/scsi/scsi_dbg.h b/include/scsi/scsi_dbg.h
index 3d9ac9f..a46bc55 100644
--- a/include/scsi/scsi_dbg.h
+++ b/include/scsi/scsi_dbg.h
@@ -21,7 +21,7 @@ extern void __scsi_dump_sense(struct scsi_device *, const char *,
 			      const unsigned char *, int);
 extern void scsi_show_result(struct scsi_device *, const char *, int);
 extern void scsi_print_result(struct scsi_cmnd *);
-extern void scsi_print_status(unsigned char);
+extern const char *scsi_print_status(unsigned char);
 extern const char *scsi_sense_key_string(unsigned char);
 extern const char *scsi_extd_sense_format(unsigned char, unsigned char,
 					  const char **);
diff --git a/include/trace/events/scsi.h b/include/trace/events/scsi.h
index db6c935..0a6835b 100644
--- a/include/trace/events/scsi.h
+++ b/include/trace/events/scsi.h
@@ -169,21 +169,6 @@
 		scsi_msgbyte_name(BUS_DEVICE_RESET),		\
 		scsi_msgbyte_name(ABORT))
 
-#define scsi_statusbyte_name(result)	{ result, #result }
-#define show_statusbyte_name(val)				\
-	__print_symbolic(val,					\
-		scsi_statusbyte_name(SAM_STAT_GOOD),		\
-		scsi_statusbyte_name(SAM_STAT_CHECK_CONDITION),	\
-		scsi_statusbyte_name(SAM_STAT_CONDITION_MET),	\
-		scsi_statusbyte_name(SAM_STAT_BUSY),		\
-		scsi_statusbyte_name(SAM_STAT_INTERMEDIATE),	\
-		scsi_statusbyte_name(SAM_STAT_INTERMEDIATE_CONDITION_MET), \
-		scsi_statusbyte_name(SAM_STAT_RESERVATION_CONFLICT),	\
-		scsi_statusbyte_name(SAM_STAT_COMMAND_TERMINATED),	\
-		scsi_statusbyte_name(SAM_STAT_TASK_SET_FULL),	\
-		scsi_statusbyte_name(SAM_STAT_ACA_ACTIVE),	\
-		scsi_statusbyte_name(SAM_STAT_TASK_ABORTED))
-
 #define scsi_prot_op_name(result)	{ result, #result }
 #define show_prot_op_name(val)					\
 	__print_symbolic(val,					\
@@ -331,7 +316,7 @@ DECLARE_EVENT_CLASS(scsi_cmd_done_timeout_template,
 		  show_driverbyte_name(((__entry->result) >> 24) & 0xff),
 		  show_hostbyte_name(((__entry->result) >> 16) & 0xff),
 		  show_msgbyte_name(((__entry->result) >> 8) & 0xff),
-		  show_statusbyte_name(__entry->result & 0xff))
+		  scsi_print_status(__entry->result & 0xff))
 );
 
 DEFINE_EVENT(scsi_cmd_done_timeout_template, scsi_dispatch_cmd_done,
diff --git a/include/trace/events/target.h b/include/trace/events/target.h
index da9cc0f..de5d594 100644
--- a/include/trace/events/target.h
+++ b/include/trace/events/target.h
@@ -8,6 +8,7 @@
 #include <linux/trace_seq.h>
 #include <scsi/scsi.h>
 #include <scsi/scsi_tcq.h>
+#include <scsi/scsi_dbg.h>
 #include <target/target_core_base.h>
 
 /* cribbed verbatim from <trace/event/scsi.h> */
@@ -114,20 +115,6 @@
 		{ MSG_ORDERED_TAG,	"ORDERED"	},	\
 		{ MSG_ACA_TAG,		"ACA"		} )
 
-#define show_scsi_status_name(val)				\
-	__print_symbolic(val,					\
-		{ SAM_STAT_GOOD,	"GOOD" },		\
-		{ SAM_STAT_CHECK_CONDITION, "CHECK CONDITION" }, \
-		{ SAM_STAT_CONDITION_MET, "CONDITION MET" },	\
-		{ SAM_STAT_BUSY,	"BUSY" },		\
-		{ SAM_STAT_INTERMEDIATE, "INTERMEDIATE" },	\
-		{ SAM_STAT_INTERMEDIATE_CONDITION_MET, "INTERMEDIATE CONDITION MET" }, \
-		{ SAM_STAT_RESERVATION_CONFLICT, "RESERVATION CONFLICT" }, \
-		{ SAM_STAT_COMMAND_TERMINATED, "COMMAND TERMINATED" }, \
-		{ SAM_STAT_TASK_SET_FULL, "TASK SET FULL" },	\
-		{ SAM_STAT_ACA_ACTIVE, "ACA ACTIVE" },		\
-		{ SAM_STAT_TASK_ABORTED, "TASK ABORTED" } )
-
 TRACE_EVENT(target_sequencer_start,
 
 	TP_PROTO(struct se_cmd *cmd),
@@ -196,7 +183,7 @@ TRACE_EVENT(target_cmd_complete,
 
 	TP_printk("%s <- LUN %03u status %s (sense len %d%s%s)  %s data_length %6u  CDB %s  (TA:%s C:%02x)",
 		  __get_str(initiator), __entry->unpacked_lun,
-		  show_scsi_status_name(__entry->scsi_status),
+		  scsi_print_status(__entry->scsi_status),
 		  __entry->sense_length, __entry->sense_length ? " / " : "",
 		  __print_hex(__entry->sense_data, __entry->sense_length),
 		  show_opcode_name(__entry->opcode),
-- 
1.8.5.2

[PATCH 11/22] Implement scsi_opcode_sa_name

[Hannes Reinecke]

Implement a lookup array for SERVICE ACTION commands instead
of hardcoding it in a large switch statement.

Signed-off-by: Hannes Reinecke <hare@suse.de>
---
 drivers/scsi/constants.c | 130 +++++++++++++++++++----------------------------
 1 file changed, 53 insertions(+), 77 deletions(-)

diff --git a/drivers/scsi/constants.c b/drivers/scsi/constants.c
index 323e944..813c482 100644
--- a/drivers/scsi/constants.c
+++ b/drivers/scsi/constants.c
@@ -244,102 +244,77 @@ static const struct value_name_pair variable_length_arr[] = {
 };
 #define VARIABLE_LENGTH_SZ ARRAY_SIZE(variable_length_arr)
 
-static const char * get_sa_name(const struct value_name_pair * arr,
-			        int arr_sz, int service_action)
+struct sa_name_list {
+	int cmd;
+	const struct value_name_pair *arr;
+	int arr_sz;
+};
+
+static struct sa_name_list sa_names_arr[] = {
+	{VARIABLE_LENGTH_CMD, variable_length_arr, VARIABLE_LENGTH_SZ},
+	{MAINTENANCE_IN, maint_in_arr, MAINT_IN_SZ},
+	{MAINTENANCE_OUT, maint_out_arr, MAINT_OUT_SZ},
+	{PERSISTENT_RESERVE_IN, pr_in_arr, PR_IN_SZ},
+	{PERSISTENT_RESERVE_OUT, pr_out_arr, PR_OUT_SZ},
+	{SERVICE_ACTION_IN_12, serv_in12_arr, SERV_IN12_SZ},
+	{SERVICE_ACTION_OUT_12, serv_out12_arr, SERV_OUT12_SZ},
+	{SERVICE_ACTION_BIDIRECTIONAL, serv_bidi_arr, SERV_BIDI_SZ},
+	{SERVICE_ACTION_IN_16, serv_in16_arr, SERV_IN16_SZ},
+	{SERVICE_ACTION_OUT_16, serv_out16_arr, SERV_OUT16_SZ},
+	{THIRD_PARTY_COPY_IN, tpc_in_arr, TPC_IN_SZ},
+	{THIRD_PARTY_COPY_OUT, tpc_out_arr, TPC_OUT_SZ},
+	{0, NULL, 0},
+};
+#define SA_NAME_LIST_SZ ARRAY_SIZE(sa_names_arr)
+
+static int scsi_opcode_sa_name(int cmd, int service_action,
+			       const char **sa_name)
 {
-	int k;
+	struct sa_name_list *sa_name_ptr = sa_names_arr;
+	const struct value_name_pair * arr = NULL;
+	int arr_sz, k;
+
+	for (k = 0; k < SA_NAME_LIST_SZ; ++k, ++sa_name_ptr) {
+		if (sa_name_ptr->cmd == cmd) {
+			arr = sa_name_ptr->arr;
+			arr_sz = sa_name_ptr->arr_sz;
+			break;
+		}
+	}
+	if (!arr)
+		return 0;
 
 	for (k = 0; k < arr_sz; ++k, ++arr) {
 		if (service_action == arr->value)
 			break;
 	}
-	return (k < arr_sz) ? arr->name : NULL;
+	if (k < arr_sz)
+		*sa_name = arr->name;
+
+	return 1;
 }
 
 /* attempt to guess cdb length if cdb_len==0 . No trailing linefeed. */
 static void print_opcode_name(unsigned char * cdbp, int cdb_len)
 {
 	int sa, len, cdb0;
-	int fin_name = 0;
 	const char * name;
 
 	cdb0 = cdbp[0];
-	switch(cdb0) {
-	case VARIABLE_LENGTH_CMD:
+	if (cdb0 == VARIABLE_LENGTH_CMD) {
 		len = scsi_varlen_cdb_length(cdbp);
 		if (len < 10) {
 			printk("short variable length command, "
 			       "len=%d ext_len=%d", len, cdb_len);
-			break;
+			return;
 		}
 		sa = (cdbp[8] << 8) + cdbp[9];
-		name = get_sa_name(variable_length_arr, VARIABLE_LENGTH_SZ,
-				   sa);
-		if (name)
-			printk("%s", name);
-		else
-			printk("cdb[0]=0x%x, sa=0x%x", cdb0, sa);
-
-		if ((cdb_len > 0) && (len != cdb_len))
-			printk(", in_cdb_len=%d, ext_len=%d", len, cdb_len);
-
-		break;
-	case MAINTENANCE_IN:
-		sa = cdbp[1] & 0x1f;
-		name = get_sa_name(maint_in_arr, MAINT_IN_SZ, sa);
-		fin_name = 1;
-		break;
-	case MAINTENANCE_OUT:
-		sa = cdbp[1] & 0x1f;
-		name = get_sa_name(maint_out_arr, MAINT_OUT_SZ, sa);
-		fin_name = 1;
-		break;
-	case PERSISTENT_RESERVE_IN:
-		sa = cdbp[1] & 0x1f;
-		name = get_sa_name(pr_in_arr, PR_IN_SZ, sa);
-		fin_name = 1;
-		break;
-	case PERSISTENT_RESERVE_OUT:
-		sa = cdbp[1] & 0x1f;
-		name = get_sa_name(pr_out_arr, PR_OUT_SZ, sa);
-		fin_name = 1;
-		break;
-	case SERVICE_ACTION_IN_12:
-		sa = cdbp[1] & 0x1f;
-		name = get_sa_name(serv_in12_arr, SERV_IN12_SZ, sa);
-		fin_name = 1;
-		break;
-	case SERVICE_ACTION_OUT_12:
-		sa = cdbp[1] & 0x1f;
-		name = get_sa_name(serv_out12_arr, SERV_OUT12_SZ, sa);
-		fin_name = 1;
-		break;
-	case SERVICE_ACTION_BIDIRECTIONAL:
-		sa = cdbp[1] & 0x1f;
-		name = get_sa_name(serv_bidi_arr, SERV_BIDI_SZ, sa);
-		fin_name = 1;
-		break;
-	case SERVICE_ACTION_IN_16:
-		sa = cdbp[1] & 0x1f;
-		name = get_sa_name(serv_in16_arr, SERV_IN16_SZ, sa);
-		fin_name = 1;
-		break;
-	case SERVICE_ACTION_OUT_16:
-		sa = cdbp[1] & 0x1f;
-		name = get_sa_name(serv_out16_arr, SERV_OUT16_SZ, sa);
-		fin_name = 1;
-		break;
-	case THIRD_PARTY_COPY_IN:
-		sa = cdbp[1] & 0x1f;
-		name = get_sa_name(tpc_in_arr, TPC_IN_SZ, sa);
-		fin_name = 1;
-		break;
-	case THIRD_PARTY_COPY_OUT:
+	} else {
 		sa = cdbp[1] & 0x1f;
-		name = get_sa_name(tpc_out_arr, TPC_OUT_SZ, sa);
-		fin_name = 1;
-		break;
-	default:
+		len = cdb_len;
+	}
+
+	if (!scsi_opcode_sa_name(cdb0, sa, &name)) {
 		if (cdb0 < 0xc0) {
 			name = cdb_byte0_names[cdb0];
 			if (name)
@@ -348,13 +323,14 @@ static void print_opcode_name(unsigned char * cdbp, int cdb_len)
 				printk("cdb[0]=0x%x (reserved)", cdb0);
 		} else
 			printk("cdb[0]=0x%x (vendor)", cdb0);
-		break;
-	}
-	if (fin_name) {
+	} else {
 		if (name)
 			printk("%s", name);
 		else
 			printk("cdb[0]=0x%x, sa=0x%x", cdb0, sa);
+
+		if ((cdb_len > 0) && (len != cdb_len))
+			printk(", in_cdb_len=%d, ext_len=%d", len, cdb_len);
 	}
 }
 
-- 
1.8.5.2

[PATCH 12/22] scsi: remove obsolete __scsi_print_command() usages

[Hannes Reinecke]

Some drivers still use the __scsi_print_command() function although
they infact refer to the scsi command. So move them over to use
scsi_print_command() instead.

Signed-off-by: Hannes Reinecke <hare@suse.de>
---
 drivers/scsi/aha152x.c       | 18 ++++++++----------
 drivers/scsi/arm/acornscsi.c |  9 +++++----
 drivers/scsi/arm/fas216.c    | 30 +++++++++++++-----------------
 3 files changed, 26 insertions(+), 31 deletions(-)

diff --git a/drivers/scsi/aha152x.c b/drivers/scsi/aha152x.c
index 4287f86..68af777 100644
--- a/drivers/scsi/aha152x.c
+++ b/drivers/scsi/aha152x.c
@@ -988,10 +988,11 @@ static int aha152x_internal_queue(Scsi_Cmnd *SCpnt, struct completion *complete,
 
 #if defined(AHA152X_DEBUG)
 	if (HOSTDATA(shpnt)->debug & debug_queue) {
-		printk(INFO_LEAD "queue: %p; cmd_len=%d pieces=%d size=%u cmnd=",
-		       CMDINFO(SCpnt), SCpnt, SCpnt->cmd_len,
-		       scsi_sg_count(SCpnt), scsi_bufflen(SCpnt));
-		__scsi_print_command(SCpnt->cmnd);
+		scmd_printk(KERN_INFO, SCpnt,
+			    "queue: %p; cmd_len=%d pieces=%d size=%u\n",
+			    SCpnt, SCpnt->cmd_len,
+			    scsi_sg_count(SCpnt), scsi_bufflen(SCpnt));
+		scsi_print_command(SCpnt);
 	}
 #endif
 
@@ -2077,8 +2078,7 @@ static void cmd_init(struct Scsi_Host *shpnt)
 
 #if defined(AHA152X_DEBUG)
 	if (HOSTDATA(shpnt)->debug & debug_cmd) {
-		printk(DEBUG_LEAD "cmd_init: ", CMDINFO(CURRENT_SC));
-		__scsi_print_command(CURRENT_SC->cmnd);
+		scsi_print_command(CURRENT_SC);
 	}
 #endif
 
@@ -2906,11 +2906,9 @@ static void disp_enintr(struct Scsi_Host *shpnt)
  */
 static void show_command(Scsi_Cmnd *ptr)
 {
-	scmd_printk(KERN_DEBUG, ptr, "%p: cmnd=(", ptr);
+	scsi_print_command(ptr);
 
-	__scsi_print_command(ptr->cmnd);
-
-	printk(KERN_DEBUG "); request_bufflen=%d; resid=%d; phase |",
+	scmd_printk(KERN_DEBUG, ptr, "request_bufflen=%d; resid=%d; phase |",
 	       scsi_bufflen(ptr), scsi_get_resid(ptr));
 
 	if (ptr->SCp.phase & not_issued)
diff --git a/drivers/scsi/arm/acornscsi.c b/drivers/scsi/arm/acornscsi.c
index d89b9b4..78dd881 100644
--- a/drivers/scsi/arm/acornscsi.c
+++ b/drivers/scsi/arm/acornscsi.c
@@ -850,11 +850,12 @@ static void acornscsi_done(AS_Host *host, struct scsi_cmnd **SCpntp,
 			break;
 
 		    default:
-			printk(KERN_ERR "scsi%d.H: incomplete data transfer detected: result=%08X command=",
-				host->host->host_no, SCpnt->result);
-			__scsi_print_command(SCpnt->cmnd);
+			scmd_printk(KERN_ERR, SCPnt,
+				    "incomplete data transfer detected:"
+				    " result=%08X\n", SCpnt->result);
+			scsi_print_command(SCpnt);
 			acornscsi_dumpdma(host, "done");
-		 	acornscsi_dumplog(host, SCpnt->device->id);
+			acornscsi_dumplog(host, SCpnt->device->id);
 			SCpnt->result &= 0xffff;
 			SCpnt->result |= DID_ERROR << 16;
 		    }
diff --git a/drivers/scsi/arm/fas216.c b/drivers/scsi/arm/fas216.c
index 71cfb1e..778fd36 100644
--- a/drivers/scsi/arm/fas216.c
+++ b/drivers/scsi/arm/fas216.c
@@ -308,8 +308,7 @@ static void fas216_log_command(FAS216_Info *info, int level,
 	fas216_do_log(info, '0' + SCpnt->device->id, fmt, args);
 	va_end(args);
 
-	printk(" CDB: ");
-	__scsi_print_command(SCpnt->cmnd);
+	scsi_print_command(SCpnt);
 }
 
 static void
@@ -2079,12 +2078,12 @@ fas216_std_done(FAS216_Info *info, struct scsi_cmnd *SCpnt, unsigned int result)
 			break;
 
 		default:
-			printk(KERN_ERR "scsi%d.%c: incomplete data transfer "
-				"detected: res=%08X ptr=%p len=%X CDB: ",
-				info->host->host_no, '0' + SCpnt->device->id,
-				SCpnt->result, info->scsi.SCp.ptr,
-				info->scsi.SCp.this_residual);
-			__scsi_print_command(SCpnt->cmnd);
+			scmd_printk(KERN_ERR, SCpnt,
+				    "incomplete data transfer "
+				    "detected: res=%08X ptr=%p len=%X\n",
+				    SCpnt->result, info->scsi.SCp.ptr,
+				    info->scsi.SCp.this_residual);
+			scsi_print_command(SCpnt->cmnd);
 			SCpnt->result &= ~(255 << 16);
 			SCpnt->result |= DID_BAD_TARGET << 16;
 			goto request_sense;
@@ -2158,12 +2157,11 @@ static void fas216_done(FAS216_Info *info, unsigned int result)
 	 * to transfer, we should not have a valid pointer.
 	 */
 	if (info->scsi.SCp.ptr && info->scsi.SCp.this_residual == 0) {
-		printk("scsi%d.%c: zero bytes left to transfer, but "
-		       "buffer pointer still valid: ptr=%p len=%08x CDB: ",
-		       info->host->host_no, '0' + SCpnt->device->id,
-		       info->scsi.SCp.ptr, info->scsi.SCp.this_residual);
+		scmd_printk(KERN_INFO, SCpnt, "zero bytes left to transfer, "
+			    "but buffer pointer still valid: ptr=%p len=%08x\n",
+			    info->scsi.SCp.ptr, info->scsi.SCp.this_residual);
 		info->scsi.SCp.ptr = NULL;
-		__scsi_print_command(SCpnt->cmnd);
+		scsi_print_command(SCpnt);
 	}
 
 	/*
@@ -2427,14 +2425,12 @@ int fas216_eh_abort(struct scsi_cmnd *SCpnt)
 
 	info->stats.aborts += 1;
 
-	printk(KERN_WARNING "scsi%d: abort command ", info->host->host_no);
-	__scsi_print_command(SCpnt->cmnd);
+	scmd_printk(KERN_WARNING, SCpnt, "abort command %p\n", SCpnt);
+	scsi_print_command(SCpnt);
 
 	print_debug_list();
 	fas216_dumpstate(info);
 
-	printk(KERN_WARNING "scsi%d: abort %p ", info->host->host_no, SCpnt);
-
 	switch (fas216_find_command(info, SCpnt)) {
 	/*
 	 * We found the command, and cleared it out.  Either
-- 
1.8.5.2

[PATCH 13/22] scsi: use local buffer for printing the opcode

[Hannes Reinecke]

SCSI opcode printing is tricky and needs to take into account
several different corner cases. So instead of trying to come
up with an elaborate printk() statement we should be printing
it into a local buffer.

Signed-off-by: Hannes Reinecke <hare@suse.de>
---
 drivers/scsi/constants.c | 72 ++++++++++++++++++++++++++++++------------------
 1 file changed, 45 insertions(+), 27 deletions(-)

diff --git a/drivers/scsi/constants.c b/drivers/scsi/constants.c
index 813c482..e9c099d 100644
--- a/drivers/scsi/constants.c
+++ b/drivers/scsi/constants.c
@@ -295,18 +295,20 @@ static int scsi_opcode_sa_name(int cmd, int service_action,
 }
 
 /* attempt to guess cdb length if cdb_len==0 . No trailing linefeed. */
-static void print_opcode_name(unsigned char * cdbp, int cdb_len)
+static int print_opcode_name(unsigned char * cdbp, int cdb_len,
+			     char *buf, int buf_len)
 {
-	int sa, len, cdb0;
-	const char * name;
+	int sa, len, cdb0, off;
+	const char * name = NULL;
 
 	cdb0 = cdbp[0];
 	if (cdb0 == VARIABLE_LENGTH_CMD) {
 		len = scsi_varlen_cdb_length(cdbp);
 		if (len < 10) {
-			printk("short variable length command, "
-			       "len=%d ext_len=%d", len, cdb_len);
-			return;
+			off = scnprintf(buf, buf_len,
+					"short variable length command, "
+					"len=%d ext_len=%d", len, cdb_len);
+			return off;
 		}
 		sa = (cdbp[8] << 8) + cdbp[9];
 	} else {
@@ -318,41 +320,51 @@ static void print_opcode_name(unsigned char * cdbp, int cdb_len)
 		if (cdb0 < 0xc0) {
 			name = cdb_byte0_names[cdb0];
 			if (name)
-				printk("%s", name);
+				off = scnprintf(buf, buf_len, "%s", name);
 			else
-				printk("cdb[0]=0x%x (reserved)", cdb0);
+				off = scnprintf(buf, buf_len,
+						"cdb[0]=0x%x (reserved)", cdb0);
 		} else
-			printk("cdb[0]=0x%x (vendor)", cdb0);
+			off = scnprintf(buf, buf_len,
+					"cdb[0]=0x%x (vendor)", cdb0);
 	} else {
 		if (name)
-			printk("%s", name);
+			off = scnprintf(buf, buf_len, "%s", name);
 		else
-			printk("cdb[0]=0x%x, sa=0x%x", cdb0, sa);
+			off = scnprintf(buf, buf_len,
+					"cdb[0]=0x%x, sa=0x%x", cdb0, sa);
 
 		if ((cdb_len > 0) && (len != cdb_len))
-			printk(", in_cdb_len=%d, ext_len=%d", len, cdb_len);
+			off += scnprintf(buf + off, buf_len - off,
+					 ", in_cdb_len=%d, ext_len=%d",
+					 len, cdb_len);
 	}
+	return off;
 }
 
 #else /* ifndef CONFIG_SCSI_CONSTANTS */
 
-static void print_opcode_name(unsigned char * cdbp, int cdb_len)
+static int print_opcode_name(unsigned char * cdbp, int cdb_len,
+			     char *buf, int buf_len)
 {
-	int sa, len, cdb0;
+	int sa, len, cdb0, off;
 
 	cdb0 = cdbp[0];
 	switch(cdb0) {
 	case VARIABLE_LENGTH_CMD:
 		len = scsi_varlen_cdb_length(cdbp);
 		if (len < 10) {
-			printk("short opcode=0x%x command, len=%d "
-			       "ext_len=%d", cdb0, len, cdb_len);
+			off = scnprintf(buf, buf_len,
+					"short opcode=0x%x command, len=%d "
+					"ext_len=%d", cdb0, len, cdb_len);
 			break;
 		}
 		sa = (cdbp[8] << 8) + cdbp[9];
-		printk("cdb[0]=0x%x, sa=0x%x", cdb0, sa);
+		off = scnprintf(buf, buf_len, "cdb[0]=0x%x, sa=0x%x", cdb0, sa);
 		if (len != cdb_len)
-			printk(", in_cdb_len=%d, ext_len=%d", len, cdb_len);
+			off += scnprintf(buf + off, buflen - off,
+					 ", in_cdb_len=%d, ext_len=%d",
+					 len, cdb_len);
 		break;
 	case MAINTENANCE_IN:
 	case MAINTENANCE_OUT:
@@ -366,23 +378,29 @@ static void print_opcode_name(unsigned char * cdbp, int cdb_len)
 	case THIRD_PARTY_COPY_IN:
 	case THIRD_PARTY_COPY_OUT:
 		sa = cdbp[1] & 0x1f;
-		printk("cdb[0]=0x%x, sa=0x%x", cdb0, sa);
+		off = scnprintf(buf + off, buflen - off,
+				"cdb[0]=0x%x, sa=0x%x", cdb0, sa);
 		break;
 	default:
 		if (cdb0 < 0xc0)
-			printk("cdb[0]=0x%x", cdb0);
+			off = scnprintf(buf + off, buf_len - off,
+					"cdb[0]=0x%x", cdb0);
 		else
-			printk("cdb[0]=0x%x (vendor)", cdb0);
+			off = scnprintf(buf + off, buf_len - off,
+					"cdb[0]=0x%x (vendor)", cdb0);
 		break;
 	}
+	return off;
 }
 #endif
 
 void __scsi_print_command(unsigned char *cdb)
 {
-	int k, len;
+	char buf[80];
+	int k, len, off = 0;
 
-	print_opcode_name(cdb, 0);
+	off = print_opcode_name(cdb, 0, buf, 80);
+	printk("%s", buf);
 	len = scsi_command_size(cdb);
 	/* print out all bytes in cdb */
 	for (k = 0; k < len; ++k)
@@ -393,16 +411,16 @@ EXPORT_SYMBOL(__scsi_print_command);
 
 void scsi_print_command(struct scsi_cmnd *cmd)
 {
-	int k;
+	char buf[80];
+	int k, off = 0;
 
 	if (cmd->cmnd == NULL)
 		return;
 
-	scmd_printk(KERN_INFO, cmd, "CDB: ");
-	print_opcode_name(cmd->cmnd, cmd->cmd_len);
+	off = print_opcode_name(cmd->cmnd, cmd->cmd_len, buf, 80);
+	scmd_printk(KERN_INFO, cmd, "CDB: %s:", buf);
 
 	/* print out all bytes in cdb */
-	printk(":");
 	for (k = 0; k < cmd->cmd_len; ++k)
 		printk(" %02x", cmd->cmnd[k]);
 	printk("\n");
-- 
1.8.5.2

[PATCH 14/22] scsi: pass in string buffer to __scsi_print_command()

[Hannes Reinecke]

Instead of using an on-stack buffer for __scsi_print_command()
we should pass in the string buffer directly.
This allows us to simplify the caller.

Signed-off-by: Hannes Reinecke <hare@suse.de>
---
 drivers/scsi/ch.c        |  5 +++--
 drivers/scsi/constants.c | 16 ++++++++--------
 drivers/scsi/sr_ioctl.c  | 10 +++++++---
 include/scsi/scsi_dbg.h  |  2 +-
 4 files changed, 19 insertions(+), 14 deletions(-)

diff --git a/drivers/scsi/ch.c b/drivers/scsi/ch.c
index eea94a9..ed023cc 100644
--- a/drivers/scsi/ch.c
+++ b/drivers/scsi/ch.c
@@ -189,6 +189,7 @@ ch_do_scsi(scsi_changer *ch, unsigned char *cmd,
 {
 	int errno, retries = 0, timeout, result;
 	struct scsi_sense_hdr sshdr;
+	char logbuf[80];
 
 	timeout = (cmd[0] == INITIALIZE_ELEMENT_STATUS)
 		? timeout_init : timeout_move;
@@ -196,8 +197,8 @@ ch_do_scsi(scsi_changer *ch, unsigned char *cmd,
  retry:
 	errno = 0;
 	if (debug) {
-		DPRINTK("command: ");
-		__scsi_print_command(cmd);
+		__scsi_print_command(cmd, logbuf, 80);
+		DPRINTK("command: %s", logbuf);
 	}
 
 	result = scsi_execute_req(ch->device, cmd, direction, buffer,
diff --git a/drivers/scsi/constants.c b/drivers/scsi/constants.c
index e9c099d..c74cb85 100644
--- a/drivers/scsi/constants.c
+++ b/drivers/scsi/constants.c
@@ -394,18 +394,18 @@ static int print_opcode_name(unsigned char * cdbp, int cdb_len,
 }
 #endif
 
-void __scsi_print_command(unsigned char *cdb)
+void __scsi_print_command(unsigned char *cdb, char *buf, int buf_len)
 {
-	char buf[80];
-	int k, len, off = 0;
+	int len, off = 0;
 
-	off = print_opcode_name(cdb, 0, buf, 80);
-	printk("%s", buf);
+	off = print_opcode_name(cdb, 0, buf, buf_len);
 	len = scsi_command_size(cdb);
 	/* print out all bytes in cdb */
-	for (k = 0; k < len; ++k)
-		printk(" %02x", cdb[k]);
-	printk("\n");
+	strcat(buf, ": ");
+	off += 2;
+
+	hex_dump_to_buffer(cdb, len, 32, 1,
+			   buf + off, buf_len - off, false);
 }
 EXPORT_SYMBOL(__scsi_print_command);
 
diff --git a/drivers/scsi/sr_ioctl.c b/drivers/scsi/sr_ioctl.c
index 17e0c2b..3e82e66 100644
--- a/drivers/scsi/sr_ioctl.c
+++ b/drivers/scsi/sr_ioctl.c
@@ -188,6 +188,7 @@ int sr_do_ioctl(Scsi_CD *cd, struct packet_command *cgc)
 	struct scsi_sense_hdr sshdr;
 	int result, err = 0, retries = 0;
 	struct request_sense *sense = cgc->sense;
+	char logbuf[80];
 
 	SDev = cd->device;
 
@@ -257,14 +258,17 @@ int sr_do_ioctl(Scsi_CD *cd, struct packet_command *cgc)
 				/* sense: Invalid command operation code */
 				err = -EDRIVE_CANT_DO_THIS;
 #ifdef DEBUG
-			__scsi_print_command(cgc->cmd);
+			__scsi_print_command(cgc->cmd, logbuf, 80);
+			sr_printk(KERN_DEBUG, cd,
+				  "CDROM (ioctl) illegal request, "
+				  "command: %s\n", logbuf);
 			scsi_print_sense_hdr(cd->device, cd->cdi.name, &sshdr);
 #endif
 			break;
 		default:
+			__scsi_print_command(cgc->cmd, logbuf, 80);
 			sr_printk(KERN_ERR, cd,
-				  "CDROM (ioctl) error, command: ");
-			__scsi_print_command(cgc->cmd);
+				  "CDROM (ioctl) error, command: %s\n", logbuf);
 			scsi_print_sense_hdr(cd->device, cd->cdi.name, &sshdr);
 			err = -EIO;
 		}
diff --git a/include/scsi/scsi_dbg.h b/include/scsi/scsi_dbg.h
index a46bc55..e682fe3 100644
--- a/include/scsi/scsi_dbg.h
+++ b/include/scsi/scsi_dbg.h
@@ -6,7 +6,7 @@ struct scsi_device;
 struct scsi_sense_hdr;
 
 extern void scsi_print_command(struct scsi_cmnd *);
-extern void __scsi_print_command(unsigned char *);
+extern void __scsi_print_command(unsigned char *, char *, int);
 extern void scsi_show_extd_sense(struct scsi_device *, const char *,
 				 unsigned char, unsigned char);
 extern void scsi_show_sense_hdr(struct scsi_device *, const char *,
-- 
1.8.5.2

[PATCH 15/22] scsi: use dev_printk() variants in scsi_print_command()

[Hannes Reinecke]

We already have a local buffer, so we can use it to format
the cdb, too.

Signed-off-by: Hannes Reinecke <hare@suse.de>
---
 drivers/scsi/constants.c | 24 ++++++++++++++++++------
 1 file changed, 18 insertions(+), 6 deletions(-)

diff --git a/drivers/scsi/constants.c b/drivers/scsi/constants.c
index c74cb85..771cd8e 100644
--- a/drivers/scsi/constants.c
+++ b/drivers/scsi/constants.c
@@ -412,18 +412,30 @@ EXPORT_SYMBOL(__scsi_print_command);
 void scsi_print_command(struct scsi_cmnd *cmd)
 {
 	char buf[80];
-	int k, off = 0;
+	int k, off = 0, linelen, remaining = cmd->cmd_len;
 
 	if (cmd->cmnd == NULL)
 		return;
 
 	off = print_opcode_name(cmd->cmnd, cmd->cmd_len, buf, 80);
-	scmd_printk(KERN_INFO, cmd, "CDB: %s:", buf);
+	if (cmd->cmd_len <= 16) {
+		strcat(buf, " CDB:");
+		off += 5;
 
-	/* print out all bytes in cdb */
-	for (k = 0; k < cmd->cmd_len; ++k)
-		printk(" %02x", cmd->cmnd[k]);
-	printk("\n");
+		hex_dump_to_buffer(cmd->cmnd, cmd->cmd_len, 16, 1,
+				   buf + off, sizeof(buf) - off, false);
+		scmd_printk(KERN_INFO, cmd, "%s\n", buf);
+	} else {
+		scmd_printk(KERN_INFO, cmd, "%s:\n", buf);
+		/* print out all bytes in cdb */
+		for (k = 0; k < cmd->cmd_len; k += 16) {
+			linelen = min(remaining, 16);
+			remaining -= 16;
+			hex_dump_to_buffer(cmd->cmnd + k, linelen, 16, 1,
+					   buf, sizeof(buf), false);
+			scmd_printk(KERN_INFO, cmd, "CDB: %s\n", buf);
+		}
+	}
 }
 EXPORT_SYMBOL(scsi_print_command);
 
-- 
1.8.5.2

[PATCH 16/22] libata: use __scsi_print_command()

[Hannes Reinecke]

libata already uses an internal buffer, so we should be using
__scsi_print_command() here.

Signed-off-by: Hannes Reinecke <hare@suse.de>
---
 drivers/ata/libata-eh.c | 12 ++++--------
 1 file changed, 4 insertions(+), 8 deletions(-)

diff --git a/drivers/ata/libata-eh.c b/drivers/ata/libata-eh.c
index dad83df..acf06ba 100644
--- a/drivers/ata/libata-eh.c
+++ b/drivers/ata/libata-eh.c
@@ -2509,15 +2509,11 @@ static void ata_eh_link_report(struct ata_link *link)
 
 		if (ata_is_atapi(qc->tf.protocol)) {
 			if (qc->scsicmd)
-				scsi_print_command(qc->scsicmd);
+				__scsi_print_command(qc->scsicmd->cmnd,
+						     cdb_buf, sizeof(cdb_buf));
 			else
-				snprintf(cdb_buf, sizeof(cdb_buf),
-				 "cdb %02x %02x %02x %02x %02x %02x %02x %02x  "
-				 "%02x %02x %02x %02x %02x %02x %02x %02x\n         ",
-				 cdb[0], cdb[1], cdb[2], cdb[3],
-				 cdb[4], cdb[5], cdb[6], cdb[7],
-				 cdb[8], cdb[9], cdb[10], cdb[11],
-				 cdb[12], cdb[13], cdb[14], cdb[15]);
+				__scsi_print_command((unsigned char *)cdb,
+						     cdb_buf, sizeof(cdb_buf));
 		} else {
 			const char *descr = ata_get_cmd_descript(cmd->command);
 			if (descr)
-- 
1.8.5.2

[PATCH 17/22] scsi: print disposition in scsi_print_result()

[Hannes Reinecke]

Print the result disposition in scsi_print_result() to simplify
code.

Signed-off-by: Hannes Reinecke <hare@suse.de>
---
 drivers/scsi/constants.c | 43 +++++++++++++++++++++++++++++++++++++------
 drivers/scsi/scsi.c      | 28 +---------------------------
 drivers/scsi/scsi_lib.c  |  2 +-
 drivers/scsi/sd.c        |  6 ++++--
 include/scsi/scsi_dbg.h  |  4 ++--
 5 files changed, 45 insertions(+), 38 deletions(-)

diff --git a/drivers/scsi/constants.c b/drivers/scsi/constants.c
index 771cd8e..c59d128 100644
--- a/drivers/scsi/constants.c
+++ b/drivers/scsi/constants.c
@@ -1501,6 +1501,33 @@ int scsi_print_sense(struct scsi_cmnd *cmd)
 EXPORT_SYMBOL(scsi_print_sense);
 
 #ifdef CONFIG_SCSI_CONSTANTS
+static const struct error_info disposition_table[] =
+{
+	{ NEEDS_RETRY, "NEEDS_RETRY " },
+	{ SUCCESS, "SUCCESS " },
+	{ FAILED, "FAILED " },
+	{ QUEUED, "QUEUED " },
+	{ SOFT_ERROR, "SOFT_ERROR " },
+	{ ADD_TO_MLQUEUE, "ADD_TO_MLQUEUE " },
+	{ TIMEOUT_ERROR, "TIMEOUT " },
+	{ SCSI_RETURN_NOT_HANDLED, "NOT_HANDLED " },
+	{ FAST_IO_FAIL, "FAST_IO_FAIL " },
+};
+#endif
+
+const char *
+scsi_disposition_string(unsigned int disposition) {
+#ifdef CONFIG_SCSI_CONSTANTS
+	int i;
+
+	for (i = 0; disposition_table[i].text; i++)
+		if (disposition_table[i].code12 == disposition)
+			return disposition_table[i].text;
+#endif
+	return NULL;
+}
+
+#ifdef CONFIG_SCSI_CONSTANTS
 
 static const char * const hostbyte_table[]={
 "DID_OK", "DID_NO_CONNECT", "DID_BUS_BUSY", "DID_TIME_OUT", "DID_BAD_TARGET",
@@ -1515,7 +1542,8 @@ static const char * const driverbyte_table[]={
 "DRIVER_INVALID", "DRIVER_TIMEOUT", "DRIVER_HARD", "DRIVER_SENSE"};
 #define NUM_DRIVERBYTE_STRS ARRAY_SIZE(driverbyte_table)
 
-void scsi_show_result(struct scsi_device *sdev, const char *name, int result)
+void scsi_show_result(struct scsi_device *sdev, const char *name,
+		      int result, int disposition)
 {
 	int hb = host_byte(result);
 	int db = driver_byte(result);
@@ -1528,26 +1556,29 @@ void scsi_show_result(struct scsi_device *sdev, const char *name, int result)
 
 
 	sdev_prefix_printk(KERN_INFO, sdev, name,
-			   "Result: hostbyte=%s driverbyte=%s\n",
+			   "%sResult: hostbyte=%s driverbyte=%s\n",
+			   scsi_disposition_string(disposition),
 			   hb_string, db_string);
 }
 
 #else
 
-void scsi_show_result(struct scsi_device *sdev, const char *name, int result)
+void scsi_show_result(struct scsi_device *sdev, const char *name,
+		      int result, int disposition)
 {
 	sdev_prefix_printk(KERN_INFO, sdev, name,
-			   "Result: hostbyte=0x%02x driverbyte=0x%02x\n",
+			   "%sResult: hostbyte=0x%02x driverbyte=0x%02x\n",
+			   scsi_disposition_string(disposition),
 			   host_byte(result), driver_byte(result));
 }
 
 #endif
 EXPORT_SYMBOL(scsi_show_result);
 
-void scsi_print_result(struct scsi_cmnd *cmd)
+void scsi_print_result(struct scsi_cmnd *cmd, int disposition)
 {
 	const char *devname = cmd->request->rq_disk ?
 		cmd->request->rq_disk->disk_name : NULL;
-	scsi_show_result(cmd->device, devname, cmd->result);
+	scsi_show_result(cmd->device, devname, cmd->result, disposition);
 }
 EXPORT_SYMBOL(scsi_print_result);
diff --git a/drivers/scsi/scsi.c b/drivers/scsi/scsi.c
index 283f053..d267e61 100644
--- a/drivers/scsi/scsi.c
+++ b/drivers/scsi/scsi.c
@@ -569,33 +569,7 @@ void scsi_log_completion(struct scsi_cmnd *cmd, int disposition)
 			scmd_printk(KERN_INFO, cmd, "Done: ");
 			if (level > 2)
 				printk("0x%p ", cmd);
-			/*
-			 * Dump truncated values, so we usually fit within
-			 * 80 chars.
-			 */
-			switch (disposition) {
-			case SUCCESS:
-				printk("SUCCESS\n");
-				break;
-			case NEEDS_RETRY:
-				printk("RETRY\n");
-				break;
-			case ADD_TO_MLQUEUE:
-				printk("MLQUEUE\n");
-				break;
-			case FAILED:
-				printk("FAILED\n");
-				break;
-			case TIMEOUT_ERROR:
-				/* 
-				 * If called via scsi_times_out.
-				 */
-				printk("TIMEOUT\n");
-				break;
-			default:
-				printk("UNKNOWN\n");
-			}
-			scsi_print_result(cmd);
+			scsi_print_result(cmd, disposition);
 			scsi_print_command(cmd);
 			if (status_byte(cmd->result) & CHECK_CONDITION) {
 				if (scsi_print_sense(cmd))
diff --git a/drivers/scsi/scsi_lib.c b/drivers/scsi/scsi_lib.c
index de178f7..d3657b6 100644
--- a/drivers/scsi/scsi_lib.c
+++ b/drivers/scsi/scsi_lib.c
@@ -1038,7 +1038,7 @@ void scsi_io_completion(struct scsi_cmnd *cmd, unsigned int good_bytes)
 	case ACTION_FAIL:
 		/* Give up and fail the remainder of the request */
 		if (!(req->cmd_flags & REQ_QUIET)) {
-			scsi_print_result(cmd);
+			scsi_print_result(cmd, SUCCESS);
 			if (driver_byte(result) & DRIVER_SENSE)
 				scsi_print_sense(cmd);
 			scsi_print_command(cmd);
diff --git a/drivers/scsi/sd.c b/drivers/scsi/sd.c
index e780644..624692c 100644
--- a/drivers/scsi/sd.c
+++ b/drivers/scsi/sd.c
@@ -1701,7 +1701,7 @@ static int sd_done(struct scsi_cmnd *SCpnt)
 			sense_deferred = scsi_sense_is_deferred(&sshdr);
 	}
 #ifdef CONFIG_SCSI_LOGGING
-	SCSI_LOG_HLCOMPLETE(1, scsi_print_result(SCpnt));
+	SCSI_LOG_HLCOMPLETE(1, scsi_print_result(SCpnt, SUCCESS));
 	if (sense_valid) {
 		SCSI_LOG_HLCOMPLETE(1, scmd_printk(KERN_INFO, SCpnt,
 						   "sd_done: sb[respc,sk,asc,"
@@ -3328,6 +3328,8 @@ static void sd_print_sense_hdr(struct scsi_disk *sdkp,
 
 static void sd_print_result(struct scsi_disk *sdkp, int result)
 {
-	scsi_show_result(sdkp->device, sdkp->disk->disk_name, result);
+	scsi_show_result(sdkp->device,
+			 sdkp->disk ? sdkp->disk->disk_name : NULL,
+			 result, SUCCESS);
 }
 
diff --git a/include/scsi/scsi_dbg.h b/include/scsi/scsi_dbg.h
index e682fe3..fa04587 100644
--- a/include/scsi/scsi_dbg.h
+++ b/include/scsi/scsi_dbg.h
@@ -19,8 +19,8 @@ extern int __scsi_print_sense(struct scsi_device *, const char *,
 extern void scsi_dump_sense(struct scsi_cmnd *);
 extern void __scsi_dump_sense(struct scsi_device *, const char *,
 			      const unsigned char *, int);
-extern void scsi_show_result(struct scsi_device *, const char *, int);
-extern void scsi_print_result(struct scsi_cmnd *);
+extern void scsi_show_result(struct scsi_device *, const char *, int, int);
+extern void scsi_print_result(struct scsi_cmnd *, int);
 extern const char *scsi_print_status(unsigned char);
 extern const char *scsi_sense_key_string(unsigned char);
 extern const char *scsi_extd_sense_format(unsigned char, unsigned char,
-- 
1.8.5.2

[PATCH 18/22] scsi_error: format abort error message

[Hannes Reinecke]

Suggested-by: Robert Elliot <elliot@hp.com>
Signed-off-by: Hannes Reinecke <hare@suse.de>
---
 drivers/scsi/scsi_error.c | 16 ++++++++++++----
 include/scsi/scsi_dbg.h   |  1 +
 2 files changed, 13 insertions(+), 4 deletions(-)

diff --git a/drivers/scsi/scsi_error.c b/drivers/scsi/scsi_error.c
index 6c99624..07887b1 100644
--- a/drivers/scsi/scsi_error.c
+++ b/drivers/scsi/scsi_error.c
@@ -155,10 +155,18 @@ scmd_eh_abort_handler(struct work_struct *work)
 				return;
 			}
 		} else {
-			SCSI_LOG_ERROR_RECOVERY(3,
-				scmd_printk(KERN_INFO, scmd,
-					    "scmd %p abort failed, rtn %d\n",
-					    scmd, rtn));
+			const char *rtn_str = scsi_disposition_string(rtn);
+			if (rtn_str) {
+				SCSI_LOG_ERROR_RECOVERY(3,
+					scmd_printk(KERN_INFO, scmd,
+						    "scmd %p abort failed,"
+						    " %s\n", scmd, rtn_str));
+			} else {
+				SCSI_LOG_ERROR_RECOVERY(3,
+					scmd_printk(KERN_INFO, scmd,
+						    "scmd %p abort failed,"
+						    " 0x%x\n", scmd, rtn));
+			}
 		}
 	}
 
diff --git a/include/scsi/scsi_dbg.h b/include/scsi/scsi_dbg.h
index fa04587..d60e7d8 100644
--- a/include/scsi/scsi_dbg.h
+++ b/include/scsi/scsi_dbg.h
@@ -25,5 +25,6 @@ extern const char *scsi_print_status(unsigned char);
 extern const char *scsi_sense_key_string(unsigned char);
 extern const char *scsi_extd_sense_format(unsigned char, unsigned char,
 					  const char **);
+extern const char *scsi_disposition_string(unsigned int);
 
 #endif /* _SCSI_SCSI_DBG_H */
-- 
1.8.5.2

[PATCH 19/22] scsi: use local buffer for scsi_log_(send|completion)

[Hannes Reinecke]

scsi_logging is somewhat special, and so instead of tweaking
scsi_print_command() we should be using __scsi_print_command()
with a local buffer, which then can be formatted according
to the logging level.

Signed-off-by: Hannes Reinecke <hare@suse.de>
---
 drivers/scsi/scsi.c | 40 ++++++++++++++++++++++++----------------
 1 file changed, 24 insertions(+), 16 deletions(-)

diff --git a/drivers/scsi/scsi.c b/drivers/scsi/scsi.c
index d267e61..58e2d7f 100644
--- a/drivers/scsi/scsi.c
+++ b/drivers/scsi/scsi.c
@@ -529,17 +529,23 @@ void scsi_log_send(struct scsi_cmnd *cmd)
 		level = SCSI_LOG_LEVEL(SCSI_LOG_MLQUEUE_SHIFT,
 				       SCSI_LOG_MLQUEUE_BITS);
 		if (level > 1) {
-			scmd_printk(KERN_INFO, cmd, "Send: ");
+			char buf[80];
+
+			__scsi_print_command(cmd->cmnd, buf, 80);
 			if (level > 2)
-				printk("0x%p ", cmd);
-			printk("\n");
-			scsi_print_command(cmd);
+				scmd_printk(KERN_INFO, cmd, "Send: 0x%p %s\n",
+					    cmd, buf);
+			else
+				scmd_printk(KERN_INFO, cmd, "Send: %s\n", buf);
 			if (level > 3) {
-				printk(KERN_INFO "buffer = 0x%p, bufflen = %d,"
-				       " queuecommand 0x%p\n",
-					scsi_sglist(cmd), scsi_bufflen(cmd),
-					cmd->device->host->hostt->queuecommand);
-
+				struct Scsi_Host *shost = cmd->device->host;
+				scmd_printk(KERN_INFO, cmd,
+					    "Send: 0x%p buffer = 0x%p,"
+					    " bufflen = %d,"
+					    " queuecommand 0x%p\n",
+					    cmd, scsi_sglist(cmd),
+					    scsi_bufflen(cmd),
+					    shost->hostt->queuecommand);
 			}
 		}
 	}
@@ -566,15 +572,17 @@ void scsi_log_completion(struct scsi_cmnd *cmd, int disposition)
 				       SCSI_LOG_MLCOMPLETE_BITS);
 		if (((level > 0) && (cmd->result || disposition != SUCCESS)) ||
 		    (level > 1)) {
-			scmd_printk(KERN_INFO, cmd, "Done: ");
+			char buf[80];
+
+			__scsi_print_command(cmd->cmnd, buf, 80);
 			if (level > 2)
-				printk("0x%p ", cmd);
+				scmd_printk(KERN_INFO, cmd,
+					    "Done: 0x%p %s\n", cmd, buf);
+			else
+				scmd_printk(KERN_INFO, cmd, "Done: %s\n", buf);
 			scsi_print_result(cmd, disposition);
-			scsi_print_command(cmd);
-			if (status_byte(cmd->result) & CHECK_CONDITION) {
-				if (scsi_print_sense(cmd))
-					scsi_dump_sense(cmd);
-			}
+			if (status_byte(cmd->result) & CHECK_CONDITION)
+				scsi_print_sense(cmd);
 			if (level > 3)
 				scmd_printk(KERN_INFO, cmd,
 					    "scsi host busy %d failed %d\n",
-- 
1.8.5.2

[PATCH 20/22] scsi: align logging messages

[Hannes Reinecke]

Always use 'scmd 0x%p' when logging a command pointer.

Suggested-by: Robert Elliot <elliot@hp.com>
Signed-off-by: Hannes Reinecke <hare@suse.de>
---
 drivers/scsi/scsi.c       |  7 +++---
 drivers/scsi/scsi_error.c | 58 +++++++++++++++++++++++------------------------
 drivers/scsi/scsi_lib.c   |  2 +-
 3 files changed, 34 insertions(+), 33 deletions(-)

diff --git a/drivers/scsi/scsi.c b/drivers/scsi/scsi.c
index 58e2d7f..7e677d0 100644
--- a/drivers/scsi/scsi.c
+++ b/drivers/scsi/scsi.c
@@ -533,14 +533,15 @@ void scsi_log_send(struct scsi_cmnd *cmd)
 
 			__scsi_print_command(cmd->cmnd, buf, 80);
 			if (level > 2)
-				scmd_printk(KERN_INFO, cmd, "Send: 0x%p %s\n",
+				scmd_printk(KERN_INFO, cmd,
+					    "Send: scmd 0x%p %s\n",
 					    cmd, buf);
 			else
 				scmd_printk(KERN_INFO, cmd, "Send: %s\n", buf);
 			if (level > 3) {
 				struct Scsi_Host *shost = cmd->device->host;
 				scmd_printk(KERN_INFO, cmd,
-					    "Send: 0x%p buffer = 0x%p,"
+					    "Send: scmd 0x%p buffer = 0x%p,"
 					    " bufflen = %d,"
 					    " queuecommand 0x%p\n",
 					    cmd, scsi_sglist(cmd),
@@ -577,7 +578,7 @@ void scsi_log_completion(struct scsi_cmnd *cmd, int disposition)
 			__scsi_print_command(cmd->cmnd, buf, 80);
 			if (level > 2)
 				scmd_printk(KERN_INFO, cmd,
-					    "Done: 0x%p %s\n", cmd, buf);
+					    "Done: scmd 0x%p %s\n", cmd, buf);
 			else
 				scmd_printk(KERN_INFO, cmd, "Done: %s\n", buf);
 			scsi_print_result(cmd, disposition);
diff --git a/drivers/scsi/scsi_error.c b/drivers/scsi/scsi_error.c
index 07887b1..5736570 100644
--- a/drivers/scsi/scsi_error.c
+++ b/drivers/scsi/scsi_error.c
@@ -123,33 +123,33 @@ scmd_eh_abort_handler(struct work_struct *work)
 	if (scsi_host_eh_past_deadline(sdev->host)) {
 		SCSI_LOG_ERROR_RECOVERY(3,
 			scmd_printk(KERN_INFO, scmd,
-				    "scmd %p eh timeout, not aborting\n",
+				    "scmd 0x%p eh timeout, not aborting\n",
 				    scmd));
 	} else {
-		SCSI_LOG_ERROR_RECOVERY(3,
+		SCSI_LOG_ERROR_RECOVERY(2,
 			scmd_printk(KERN_INFO, scmd,
-				    "aborting command %p\n", scmd));
+				    "aborting scmd 0x%p\n", scmd));
 		rtn = scsi_try_to_abort_cmd(sdev->host->hostt, scmd);
 		if (rtn == SUCCESS) {
 			set_host_byte(scmd, DID_TIME_OUT);
 			if (scsi_host_eh_past_deadline(sdev->host)) {
 				SCSI_LOG_ERROR_RECOVERY(3,
 					scmd_printk(KERN_INFO, scmd,
-						    "scmd %p eh timeout, "
+						    "scmd 0x%p eh timeout, "
 						    "not retrying aborted "
 						    "command\n", scmd));
 			} else if (!scsi_noretry_cmd(scmd) &&
 			    (++scmd->retries <= scmd->allowed)) {
 				SCSI_LOG_ERROR_RECOVERY(3,
 					scmd_printk(KERN_WARNING, scmd,
-						    "scmd %p retry "
+						    "scmd 0x%p retry "
 						    "aborted command\n", scmd));
 				scsi_queue_insert(scmd, SCSI_MLQUEUE_EH_RETRY);
 				return;
 			} else {
 				SCSI_LOG_ERROR_RECOVERY(3,
 					scmd_printk(KERN_WARNING, scmd,
-						    "scmd %p finish "
+						    "scmd 0x%p finish "
 						    "aborted command\n", scmd));
 				scsi_finish_command(scmd);
 				return;
@@ -157,23 +157,23 @@ scmd_eh_abort_handler(struct work_struct *work)
 		} else {
 			const char *rtn_str = scsi_disposition_string(rtn);
 			if (rtn_str) {
-				SCSI_LOG_ERROR_RECOVERY(3,
+				SCSI_LOG_ERROR_RECOVERY(2,
 					scmd_printk(KERN_INFO, scmd,
-						    "scmd %p abort failed,"
+						    "scmd 0x%p abort failed,"
 						    " %s\n", scmd, rtn_str));
 			} else {
-				SCSI_LOG_ERROR_RECOVERY(3,
+				SCSI_LOG_ERROR_RECOVERY(2,
 					scmd_printk(KERN_INFO, scmd,
-						    "scmd %p abort failed,"
+						    "scmd 0x%p abort failed,"
 						    " 0x%x\n", scmd, rtn));
 			}
 		}
 	}
 
 	if (!scsi_eh_scmd_add(scmd, 0)) {
-		SCSI_LOG_ERROR_RECOVERY(3,
+		SCSI_LOG_ERROR_RECOVERY(2,
 			scmd_printk(KERN_WARNING, scmd,
-				    "scmd %p terminate "
+				    "scmd 0x%p terminate "
 				    "aborted command\n", scmd));
 		set_host_byte(scmd, DID_TIME_OUT);
 		scsi_finish_command(scmd);
@@ -198,9 +198,9 @@ scsi_abort_command(struct scsi_cmnd *scmd)
 		 * Retry after abort failed, escalate to next level.
 		 */
 		scmd->eh_eflags &= ~SCSI_EH_ABORT_SCHEDULED;
-		SCSI_LOG_ERROR_RECOVERY(3,
+		SCSI_LOG_ERROR_RECOVERY(2,
 			scmd_printk(KERN_INFO, scmd,
-				    "scmd %p previous abort failed\n", scmd));
+				    "scmd 0x%p previous abort failed\n", scmd));
 		BUG_ON(delayed_work_pending(&scmd->abort_work));
 		return FAILED;
 	}
@@ -214,7 +214,7 @@ scsi_abort_command(struct scsi_cmnd *scmd)
 		spin_unlock_irqrestore(shost->host_lock, flags);
 		SCSI_LOG_ERROR_RECOVERY(3,
 			scmd_printk(KERN_INFO, scmd,
-				    "scmd %p not aborting, host in recovery\n",
+				    "scmd 0x%p not aborting, host in recovery\n",
 				    scmd));
 		return FAILED;
 	}
@@ -226,7 +226,7 @@ scsi_abort_command(struct scsi_cmnd *scmd)
 	scmd->eh_eflags |= SCSI_EH_ABORT_SCHEDULED;
 	SCSI_LOG_ERROR_RECOVERY(3,
 		scmd_printk(KERN_INFO, scmd,
-			    "scmd %p abort scheduled\n", scmd));
+			    "scmd 0x%p abort scheduled\n", scmd));
 	queue_delayed_work(shost->tmf_work_q, &scmd->abort_work, HZ / 100);
 	return SUCCESS;
 }
@@ -748,7 +748,7 @@ static void scsi_eh_done(struct scsi_cmnd *scmd)
 	struct completion *eh_action;
 
 	SCSI_LOG_ERROR_RECOVERY(3, scmd_printk(KERN_INFO, scmd,
-			"%s scmd: %p result: %x\n",
+			"%s scmd 0x%p result: %x\n",
 			__func__, scmd, scmd->result));
 
 	eh_action = scmd->device->host->eh_action;
@@ -1046,7 +1046,7 @@ retry:
 	scsi_log_completion(scmd, rtn);
 
 	SCSI_LOG_ERROR_RECOVERY(3, scmd_printk(KERN_INFO, scmd,
-			"%s: scmd: %p, timeleft: %ld\n",
+			"%s: scmd 0x%p timeleft: %ld\n",
 			__func__, scmd, timeleft));
 
 	/*
@@ -1186,7 +1186,7 @@ int scsi_eh_get_sense(struct list_head *work_q,
 			continue;
 
 		SCSI_LOG_ERROR_RECOVERY(3, scmd_printk(KERN_INFO, scmd,
-			"sense requested for %p result %x\n",
+			"sense requested for scmd 0x%p result %x\n",
 			scmd, scmd->result));
 		SCSI_LOG_ERROR_RECOVERY(3, scsi_print_sense(scmd));
 
@@ -1331,15 +1331,15 @@ static int scsi_eh_abort_cmds(struct list_head *work_q,
 					     __func__));
 			return list_empty(work_q);
 		}
-		SCSI_LOG_ERROR_RECOVERY(3,
+		SCSI_LOG_ERROR_RECOVERY(2,
 			shost_printk(KERN_INFO, shost,
-				     "%s: aborting cmd: 0x%p\n",
+				     "%s: aborting scmd 0x%p\n",
 				     current->comm, scmd));
 		rtn = scsi_try_to_abort_cmd(shost->hostt, scmd);
 		if (rtn == FAILED) {
-			SCSI_LOG_ERROR_RECOVERY(3,
+			SCSI_LOG_ERROR_RECOVERY(2,
 				shost_printk(KERN_INFO, shost,
-					     "%s: aborting cmd failed: 0x%p\n",
+					     "%s: aborting scmd 0x%p failed\n",
 					     current->comm, scmd));
 			list_splice_init(&check_list, work_q);
 			return list_empty(work_q);
@@ -1416,7 +1416,7 @@ static int scsi_eh_stu(struct Scsi_Host *shost,
 
 		SCSI_LOG_ERROR_RECOVERY(3,
 			shost_printk(KERN_INFO, shost,
-				     "%s: Sending START_UNIT to sdev: 0x%p\n",
+				     "%s: Sending START_UNIT to sdev 0x%p\n",
 				     current->comm, sdev));
 
 		if (!scsi_eh_try_stu(stu_scmd)) {
@@ -1432,7 +1432,7 @@ static int scsi_eh_stu(struct Scsi_Host *shost,
 		} else {
 			SCSI_LOG_ERROR_RECOVERY(3,
 				shost_printk(KERN_INFO, shost,
-					     "%s: START_UNIT failed to sdev:"
+					     "%s: START_UNIT failed to sdev"
 					     " 0x%p\n", current->comm, sdev));
 		}
 	}
@@ -1481,7 +1481,7 @@ static int scsi_eh_bus_device_reset(struct Scsi_Host *shost,
 
 		SCSI_LOG_ERROR_RECOVERY(3,
 			shost_printk(KERN_INFO, shost,
-				     "%s: Sending BDR sdev: 0x%p\n",
+				     "%s: Sending BDR sdev 0x%p\n",
 				     current->comm, sdev));
 		rtn = scsi_try_bus_device_reset(bdr_scmd);
 		if (rtn == SUCCESS || rtn == FAST_IO_FAIL) {
@@ -1499,7 +1499,7 @@ static int scsi_eh_bus_device_reset(struct Scsi_Host *shost,
 		} else {
 			SCSI_LOG_ERROR_RECOVERY(3,
 				shost_printk(KERN_INFO, shost,
-					     "%s: BDR failed sdev: 0x%p\n",
+					     "%s: BDR failed sdev 0x%p\n",
 					     current->comm, sdev));
 		}
 	}
@@ -2085,7 +2085,7 @@ void scsi_eh_flush_done_q(struct list_head *done_q)
 		    (++scmd->retries <= scmd->allowed)) {
 			SCSI_LOG_ERROR_RECOVERY(3,
 				scmd_printk(KERN_INFO, scmd,
-					     "%s: flush retry cmd: %p\n",
+					     "%s: flush retry scmd 0x%p\n",
 					     current->comm, scmd));
 				scsi_queue_insert(scmd, SCSI_MLQUEUE_EH_RETRY);
 		} else {
@@ -2098,7 +2098,7 @@ void scsi_eh_flush_done_q(struct list_head *done_q)
 				scmd->result |= (DRIVER_TIMEOUT << 24);
 			SCSI_LOG_ERROR_RECOVERY(3,
 				scmd_printk(KERN_INFO, scmd,
-					     "%s: flush finish cmd: %p\n",
+					     "%s: flush finish scmd 0x%p\n",
 					     current->comm, scmd));
 			scsi_finish_command(scmd);
 		}
diff --git a/drivers/scsi/scsi_lib.c b/drivers/scsi/scsi_lib.c
index d3657b6..ed5e40f 100644
--- a/drivers/scsi/scsi_lib.c
+++ b/drivers/scsi/scsi_lib.c
@@ -144,7 +144,7 @@ static void __scsi_queue_insert(struct scsi_cmnd *cmd, int reason, int unbusy)
 	unsigned long flags;
 
 	SCSI_LOG_MLQUEUE(1, scmd_printk(KERN_INFO, cmd,
-		"Inserting command %p into mlqueue\n", cmd));
+		"Inserting scmd %p into mlqueue\n", cmd));
 
 	scsi_set_blocked(cmd, reason);
 
-- 
1.8.5.2

[PATCH 21/22] scsi: reduce messages for command failure

[Hannes Reinecke]

When devices fail they can generate quite a lot of error
messages, possibly overloading the logging system.
So we should be putting these messages under logging control
to be able to silence them if requested.
And we should shorten the overall message; more verbose
logging can be requested by the normal scsi logging.

Signed-off-by: Hannes Reinecke <hare@suse.de>
---
 drivers/scsi/scsi_lib.c | 6 ++----
 1 file changed, 2 insertions(+), 4 deletions(-)

diff --git a/drivers/scsi/scsi_lib.c b/drivers/scsi/scsi_lib.c
index ed5e40f..64f8e33 100644
--- a/drivers/scsi/scsi_lib.c
+++ b/drivers/scsi/scsi_lib.c
@@ -1038,10 +1038,8 @@ void scsi_io_completion(struct scsi_cmnd *cmd, unsigned int good_bytes)
 	case ACTION_FAIL:
 		/* Give up and fail the remainder of the request */
 		if (!(req->cmd_flags & REQ_QUIET)) {
-			scsi_print_result(cmd, SUCCESS);
-			if (driver_byte(result) & DRIVER_SENSE)
-				scsi_print_sense(cmd);
-			scsi_print_command(cmd);
+			SCSI_LOG_HLCOMPLETE(1, scmd_printk(KERN_INFO, cmd,
+				"Failed command, error %d\n", error));
 		}
 		if (!scsi_end_request(req, error, blk_rq_err_bytes(req), 0))
 			return;
-- 
1.8.5.2

[PATCH 22/22] sd: Reduce logging output

[Hannes Reinecke]

There is no need to print out the command result verbatim;
that will be done by the scsi stack if required.
Here we just should log the result in short if requested.

Signed-off-by: Hannes Reinecke <hare@suse.de>
---
 drivers/scsi/sd.c | 13 +++++++------
 1 file changed, 7 insertions(+), 6 deletions(-)

diff --git a/drivers/scsi/sd.c b/drivers/scsi/sd.c
index 624692c..3061acf 100644
--- a/drivers/scsi/sd.c
+++ b/drivers/scsi/sd.c
@@ -1701,14 +1701,15 @@ static int sd_done(struct scsi_cmnd *SCpnt)
 			sense_deferred = scsi_sense_is_deferred(&sshdr);
 	}
 #ifdef CONFIG_SCSI_LOGGING
-	SCSI_LOG_HLCOMPLETE(1, scsi_print_result(SCpnt, SUCCESS));
+	SCSI_LOG_HLCOMPLETE(1, scmd_printk(KERN_INFO, SCpnt,
+		"sd_done: result[status,msg,host,driver]=%x,%x,%x,%x\n",
+		status_byte(result), msg_byte(result),
+		host_byte(result), driver_byte(result)));
 	if (sense_valid) {
 		SCSI_LOG_HLCOMPLETE(1, scmd_printk(KERN_INFO, SCpnt,
-						   "sd_done: sb[respc,sk,asc,"
-						   "ascq]=%x,%x,%x,%x\n",
-						   sshdr.response_code,
-						   sshdr.sense_key, sshdr.asc,
-						   sshdr.ascq));
+			"sd_done: sb[respc,sk,asc,ascq]=%x,%x,%x,%x\n",
+			sshdr.response_code, sshdr.sense_key,
+			sshdr.asc, sshdr.ascq));
 	}
 #endif
 	sdkp->medium_access_timed_out = 0;
-- 
1.8.5.2

Re: [PATCH 00/22] scsi logging update

[Douglas Gilbert]

On 14-08-28 01:33 PM, Hannes Reinecke wrote:
> Hi all,
>
> here's my next round of scsi logging updates.
> Main feature is the update to have all logging
> statements in one line so that they won't be broken
> up even under high load.
> This will dramatically improve debugging.
>
> Additionally all printk() statements are moved
> to dev_printk() variants to ensure proper device
> tagging and keep the systemd journal happy.

s/all/most/ ??

Surely there are situations where a "dev" cannot be
associated with a printk(). For example in transport
discovery before any devices are found (or after,
if none are found). LLDs often helpfully log their HBA's
firmware details prior to discovery (and may fail
before discovery).

And it is possible to write via sysfs to a driver
that has no devices attached. How does one log that?

Doug Gilbert

> To achieve this I had to use a on-stack
> buffer for formatting opcodes and sense codes;
> so the stack usage will increase somewhat.
>
> Reviews, comments etc are welcome.
>
> Hannes Reinecke (22):
>    Remove scsi_cmd_print_sense_hdr()
>    aha152x: Remove #ifdef 0 section
>    sd: Remove scsi_print_sense() in sd_done()
>    scsi: introduce sdev_prefix_printk()
>    scsi: Use sdev as argument for sense code printing
>    scsi: stop decoding if scsi_normalize_sense() fails
>    scsi: do not decode sense extras
>    scsi: dump sense buffer only for debugging
>    Use sdev as argument for scsi_print_result
>    scsi: consolidate scsi_print_status()
>    Implement scsi_opcode_sa_name
>    scsi: remove obsolete __scsi_print_command() usages
>    scsi: use local buffer for printing the opcode
>    scsi: pass in string buffer to __scsi_print_command()
>    scsi: use dev_printk() variants in scsi_print_command()
>    libata: use __scsi_print_command()
>    scsi: print disposition in scsi_print_result()
>    scsi_error: format abort error message
>    scsi: use local buffer for scsi_log_(send|completion)
>    scsi: align logging messages
>    scsi: reduce messages for command failure
>    sd: Reduce logging output
>
>   drivers/ata/libata-eh.c       |  12 +-
>   drivers/scsi/53c700.c         |   3 +-
>   drivers/scsi/aha152x.c        |  32 +--
>   drivers/scsi/arm/acornscsi.c  |   9 +-
>   drivers/scsi/arm/fas216.c     |  30 +--
>   drivers/scsi/ch.c             |   7 +-
>   drivers/scsi/constants.c      | 570 ++++++++++++++++++++----------------------
>   drivers/scsi/osst.c           |   8 +-
>   drivers/scsi/scsi.c           |  65 ++---
>   drivers/scsi/scsi_error.c     |  68 ++---
>   drivers/scsi/scsi_ioctl.c     |   2 +-
>   drivers/scsi/scsi_lib.c       |  10 +-
>   drivers/scsi/sd.c             |  28 ++-
>   drivers/scsi/sg.c             |   9 +-
>   drivers/scsi/sr_ioctl.c       |  16 +-
>   drivers/scsi/st.c             |  13 +-
>   drivers/scsi/storvsc_drv.c    |   3 +-
>   include/scsi/scsi_dbg.h       |  34 +--
>   include/scsi/scsi_device.h    |   5 +
>   include/trace/events/scsi.h   |  17 +-
>   include/trace/events/target.h |  17 +-
>   21 files changed, 457 insertions(+), 501 deletions(-)
>

Re: [PATCH 11/22] Implement scsi_opcode_sa_name

[Douglas Gilbert]

On 14-08-28 01:33 PM, Hannes Reinecke wrote:
> Implement a lookup array for SERVICE ACTION commands instead
> of hardcoding it in a large switch statement.
>
> Signed-off-by: Hannes Reinecke <hare@suse.de>
> ---
>   drivers/scsi/constants.c | 130 +++++++++++++++++++----------------------------
>   1 file changed, 53 insertions(+), 77 deletions(-)
>
> diff --git a/drivers/scsi/constants.c b/drivers/scsi/constants.c
> index 323e944..813c482 100644
> --- a/drivers/scsi/constants.c
> +++ b/drivers/scsi/constants.c
> @@ -244,102 +244,77 @@ static const struct value_name_pair variable_length_arr[] = {
>   };
>   #define VARIABLE_LENGTH_SZ ARRAY_SIZE(variable_length_arr)
>
> -static const char * get_sa_name(const struct value_name_pair * arr,
> -			        int arr_sz, int service_action)
> +struct sa_name_list {
> +	int cmd;
> +	const struct value_name_pair *arr;
> +	int arr_sz;
> +};
> +
> +static struct sa_name_list sa_names_arr[] = {
> +	{VARIABLE_LENGTH_CMD, variable_length_arr, VARIABLE_LENGTH_SZ},
> +	{MAINTENANCE_IN, maint_in_arr, MAINT_IN_SZ},
> +	{MAINTENANCE_OUT, maint_out_arr, MAINT_OUT_SZ},
> +	{PERSISTENT_RESERVE_IN, pr_in_arr, PR_IN_SZ},
> +	{PERSISTENT_RESERVE_OUT, pr_out_arr, PR_OUT_SZ},
> +	{SERVICE_ACTION_IN_12, serv_in12_arr, SERV_IN12_SZ},
> +	{SERVICE_ACTION_OUT_12, serv_out12_arr, SERV_OUT12_SZ},
> +	{SERVICE_ACTION_BIDIRECTIONAL, serv_bidi_arr, SERV_BIDI_SZ},
> +	{SERVICE_ACTION_IN_16, serv_in16_arr, SERV_IN16_SZ},
> +	{SERVICE_ACTION_OUT_16, serv_out16_arr, SERV_OUT16_SZ},
> +	{THIRD_PARTY_COPY_IN, tpc_in_arr, TPC_IN_SZ},
> +	{THIRD_PARTY_COPY_OUT, tpc_out_arr, TPC_OUT_SZ},
> +	{0, NULL, 0},
> +};

Plus I added these recently (after observing the output from
REPORT SUPPORTED OPERATION CODES):
     READ BUFFER
     WRITE BUFFER
     SANITIZE

[And I'll take your lead and remove the big switch
  statement from sg3_utils.]

Doug Gilbert



/* Read buffer [0x3c] service actions */
struct sg_lib_value_name_t sg_lib_read_buff_arr[] = {
     {0x0, 0, "combined header and data [or multiple modes]"},
     {0x2, 0, "data"},
     {0x3, 0, "descriptor"},
     {0xa, 0, "read data from echo buffer"},
     {0xb, 0, "echo buffer descriptor"},
     {0x1a, 0, "enable expander comms protocol and echo buffer"},
     {0x1c, 0, "error history"},
     {0xffff, 0, NULL},
};

/* Write buffer [0x3b] service actions */
struct sg_lib_value_name_t sg_lib_write_buff_arr[] = {
     {0x0, 0, "combined header and data [or multiple modes]"},
     {0x2, 0, "data"},
     {0x4, 0, "download microcode and activate"},
     {0x5, 0, "download microcode, save, and activate"},
     {0x6, 0, "download microcode with offsets and activate"},
     {0x7, 0, "download microcode with offsets, save, and activate"},
     {0xa, 0, "write data to echo buffer"},
     {0xd, 0, "download microcode with offsets, select activation events, "
              "save and defer activate"},
     {0xe, 0, "download microcode with offsets, save and defer activate"},
     {0xf, 0, "activate deferred microcode"},
     {0x1a, 0, "enable expander comms protocol and echo buffer"},
     {0x1b, 0, "disable expander comms protocol"},
     {0x1c, 0, "download application client error history"},
     {0xffff, 0, NULL},
};

/* Sanitize [0x48] service actions */
struct sg_lib_value_name_t sg_lib_sanitize_sa_arr[] = {
     {0x1, 0, "Sanitize, overwrite"},
     {0x2, 0, "Sanitize, block erase"},
     {0x3, 0, "Sanitize, cryptographic erase"},
     {0x1f, 0, "Sanitize, exit failure mode"},
     {0xffff, 0, NULL},
};

Re: [PATCH 00/22] scsi logging update

[Hannes Reinecke]

On 08/28/2014 09:24 PM, Douglas Gilbert wrote:
> On 14-08-28 01:33 PM, Hannes Reinecke wrote:
>> Hi all,
>>
>> here's my next round of scsi logging updates.
>> Main feature is the update to have all logging
>> statements in one line so that they won't be broken
>> up even under high load.
>> This will dramatically improve debugging.
>>
>> Additionally all printk() statements are moved
>> to dev_printk() variants to ensure proper device
>> tagging and keep the systemd journal happy.
>
> s/all/most/ ??
>
My, you are picky.

> Surely there are situations where a "dev" cannot be
> associated with a printk(). For example in transport
> discovery before any devices are found (or after,
> if none are found). LLDs often helpfully log their HBA's
> firmware details prior to discovery (and may fail
> before discovery).
>
Indeed there are some printks left, eg during
SCSI initialization where we don't have any device.
And I didn't modify the LLDDs, which have their
own logging.
(But most don't use dev_printk(), neither).

> And it is possible to write via sysfs to a driver
> that has no devices attached. How does one log that?
>
Well, I haven't come across any logging messages here,
so the question has never arisen.

Cheers,

Hannes
-- 
Dr. Hannes Reinecke		      zSeries & Storage
hare@suse.de			      +49 911 74053 688
SUSE LINUX Products GmbH, Maxfeldstr. 5, 90409 Nürnberg
GF: J. Hawn, J. Guild, F. Imendörffer, HRB 16746 (AG Nürnberg)
--
To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [PATCH 01/22] Remove scsi_cmd_print_sense_hdr()

[Christoph Hellwig]

On Thu, Aug 28, 2014 at 07:33:15PM +0200, Hannes Reinecke wrote:
> Unused.
> 
> Signed-off-by: Hannes Reinecke <hare@suse.de>

Looks good,

Reviewed-by: Christoph Hellwig <hch@lst.de>

Re: [PATCH 02/22] aha152x: Remove #ifdef 0 section

[Christoph Hellwig]

On Thu, Aug 28, 2014 at 07:33:16PM +0200, Hannes Reinecke wrote:
> Signed-off-by: Hannes Reinecke <hare@suse.de>

Looks good,

Reviewed-by: Christoph Hellwig <hch@lst.de>

Re: [PATCH 03/22] sd: Remove scsi_print_sense() in sd_done()

[Christoph Hellwig]

On Thu, Aug 28, 2014 at 07:33:17PM +0200, Hannes Reinecke wrote:
> sd_done() was calling scsi_print_sense() for a sense code
> of 'NO_SENSE'.
> 
> Signed-off-by: Hannes Reinecke <hare@suse.de>

Looks good,

Reviewed-by: Christoph Hellwig <hch@lst.de>

Re: [PATCH 04/22] scsi: introduce sdev_prefix_printk()

[Christoph Hellwig]

Needs a bit more description in the patch body and preferable also
in a comment next to the macro.  What's the benefit of it over simply
using sdev_printk with another argument?

Re: [PATCH 05/22] scsi: Use sdev as argument for sense code printing

[Christoph Hellwig]

> -scsi_extd_sense_format(unsigned char asc, unsigned char ascq) {
> +scsi_extd_sense_format(unsigned char asc, unsigned char ascq,
> +		       const char **fmt) {

please move the opening brace to a new line per normal Linux style.

Otherwise looks good,

Reviewed-by: Christoph Hellwig <hch@lst.de>

Re: [PATCH 06/22] scsi: stop decoding if scsi_normalize_sense() fails

[Christoph Hellwig]

On Thu, Aug 28, 2014 at 07:33:20PM +0200, Hannes Reinecke wrote:
> If scsi_normalize_sense() fails we couldn't decode the sense
> buffer, so we should not try to interpret the result.
> We should rather dump the sense buffer instead and stop decoding.

as far as I can tell the old code doesn't interpret it, it just does a
slightly more convoluted hexdump than your version.  Care to come up
with a better description for this patch?

>  static void
> +scsi_dump_sense_buffer(struct scsi_device *sdev, const char *name,
> +		       const unsigned char *sense_buffer, int sense_len)
>  {
> +	char linebuf[128];
> +	int i, linelen, remaining;
>  
> +	remaining = sense_len;
> +	for (i = 0; i < sense_len; i += 16) {
> +		linelen = min(remaining, 16);
> +		remaining -= 16;
> +
> +		hex_dump_to_buffer(sense_buffer + i, linelen, 16, 1,
> +				   linebuf, sizeof(linebuf), false);
> +		sdev_prefix_printk(KERN_INFO, sdev, name,
> +				   "Sense: %s\n", linebuf);
>  	}

This would be more readanle without the remaining variable:

	for (i = 0; i < sense_len; i += 16) {
		linelen = min(senselen - i, 16);
	
		...
	}

> @@ -1517,8 +1513,13 @@ void __scsi_print_sense(struct scsi_device *sdev, const char *name,
>  			const unsigned char *sense_buffer, int sense_len)
>  {
>  	struct scsi_sense_hdr sshdr;
> +	int res;
>  
> -	scsi_decode_sense_buffer(sense_buffer, sense_len, &sshdr);
> +	res = scsi_normalize_sense(sense_buffer, sense_len, &sshdr);
> +	if (res == 0) {
> +		scsi_dump_sense_buffer(sdev, name, sense_buffer, sense_len);
> +		return;
> +	}

no need for the res variable.  In fact due to the boolean-like return
value of scsi_normalize_sense it would be a lot more readable without
the variable.

Re: [PATCH 07/22] scsi: do not decode sense extras

[Christoph Hellwig]

On Thu, Aug 28, 2014 at 07:33:21PM +0200, Hannes Reinecke wrote:
> Currently we're only decoding sense extras for tape devices.
> And even there only for fixed format sense formats.
> As this is of rather limited use in the general case we should
> be stop trying to decode things here and rather dump the entire
> sense code.

I don't like this one at all.  Not that I'm attached to decoding the
extra sense buffer, but:

  - __scsi_print_sense now prints both decoded sense data as well as a
    full dump, which is rather ugly
  - __scsi_print_sense prints that buffer unconditionally

I'd say let's sit down and work with the tape driver maintainers on
finding a better way to deal with their sense printing needs.  And part
of that should probably be to get rid of __scsi_print_sense entirely
and make the tape drivers use pre-decoded and normalized sense buffers.

Re: [PATCH 08/22] scsi: dump sense buffer only for debugging

[Christoph Hellwig]

On Thu, Aug 28, 2014 at 07:33:22PM +0200, Hannes Reinecke wrote:
> Dumping the entire sense buffer might overwhelm the logging functions,
> so suppress it per default.

Call me dumb, but I don't see anything in here that limits the dumps
to debug output.

Also if you return boolean-like values please use the bool type for it.
Also please switch scsi_normalize_sense over to return bool as well
while you're at it.

Re: [PATCH 09/22] Use sdev as argument for scsi_print_result

[Christoph Hellwig]

Please also remove the now useless sd_print_result wrapper.

Otherwise looks good,

Reviewed-by: Christoph Hellwig <hch@lst.de>

Re: [PATCH 10/22] scsi: consolidate scsi_print_status()

[Christoph Hellwig]

>  #if defined(AHA152X_DEBUG)
> -	if (HOSTDATA(shpnt)->debug & debug_status) {
> -		printk(DEBUG_LEAD "inbound status %02x ", CMDINFO(CURRENT_SC), CURRENT_SC->SCp.Status);
> -		scsi_print_status(CURRENT_SC->SCp.Status);
> -		printk("\n");
> -	}
> +	if (HOSTDATA(shpnt)->debug & debug_status)
> +		printk(DEBUG_LEAD "inbound status %02x\n", CMDINFO(CURRENT_SC), CURRENT_SC->SCp.Status);

This one just removes the call.  While this is fine with me it needs to
be mentioned in the changelog.

Also if you change the line above it please make sure it fits into an
80 character line.

> +const char *
>  scsi_print_status(unsigned char scsi_status) {
> -#ifdef CONFIG_SCSI_CONSTANTS

Please explain in the changelog why you're removing this ifdef.

> +	case SAM_STAT_BUSY:
> +		ccp = "Busy"; break;

Please put the break statements on separate lines per normal Linux
style.

>  #define scsi_prot_op_name(result)	{ result, #result }
>  #define show_prot_op_name(val)					\
>  	__print_symbolic(val,					\
> @@ -331,7 +316,7 @@ DECLARE_EVENT_CLASS(scsi_cmd_done_timeout_template,
>  		  show_driverbyte_name(((__entry->result) >> 24) & 0xff),
>  		  show_hostbyte_name(((__entry->result) >> 16) & 0xff),
>  		  show_msgbyte_name(((__entry->result) >> 8) & 0xff),
> -		  show_statusbyte_name(__entry->result & 0xff))
> +		  scsi_print_status(__entry->result & 0xff))


Not using __print_symbolic for trace events breaks all tracing tools
that parse the binary trace buffers, please drop the tracing changes
(which weren't mentioned in the changelog anyway and should have been a
separate patch).

Re: [PATCH 11/22] Implement scsi_opcode_sa_name

[Christoph Hellwig]

> +		if ((cdb_len > 0) && (len != cdb_len))
> +			printk(", in_cdb_len=%d, ext_len=%d", len, cdb_len);

not need for both sets of inner braces here.

Otherwise looks good,

Reviewed-by: Christoph Hellwig <hch@lst.de>

Re: [PATCH 12/22] scsi: remove obsolete __scsi_print_command() usages

[Christoph Hellwig]

Can you change the subject a bit?  There's nothing obsolete in
__scsi_print_command, you're just moving it to a higher level helper.

>  #if defined(AHA152X_DEBUG)
>  	if (HOSTDATA(shpnt)->debug & debug_queue) {
> -		printk(INFO_LEAD "queue: %p; cmd_len=%d pieces=%d size=%u cmnd=",
> -		       CMDINFO(SCpnt), SCpnt, SCpnt->cmd_len,
> -		       scsi_sg_count(SCpnt), scsi_bufflen(SCpnt));
> -		__scsi_print_command(SCpnt->cmnd);
> +		scmd_printk(KERN_INFO, SCpnt,
> +			    "queue: %p; cmd_len=%d pieces=%d size=%u\n",
> +			    SCpnt, SCpnt->cmd_len,
> +			    scsi_sg_count(SCpnt), scsi_bufflen(SCpnt));
> +		scsi_print_command(SCpnt);

This also has a printk -> scmd_printk change that's unrelated to the
patch.

Honestly I think we should just kill much of the AHA152X_DEBUG code at
the start of this series to avoid all the churn in it.

Re: [PATCH 13/22] scsi: use local buffer for printing the opcode

[Christoph Hellwig]

On Thu, Aug 28, 2014 at 07:33:27PM +0200, Hannes Reinecke wrote:
> SCSI opcode printing is tricky and needs to take into account
> several different corner cases. So instead of trying to come
> up with an elaborate printk() statement we should be printing
> it into a local buffer.

scsi_print_command callers are usually deep down the call chain., so I'd
rather avoid using up even more stack here.  What are the exact reasons
that we need the local buffer?

Re: [PATCH 17/22] scsi: print disposition in scsi_print_result()

[Christoph Hellwig]

> +const char *
> +scsi_disposition_string(unsigned int disposition) {

The brace placement will need a fix.

> +void scsi_print_result(struct scsi_cmnd *cmd, int disposition)
>  {
>  	const char *devname = cmd->request->rq_disk ?
>  		cmd->request->rq_disk->disk_name : NULL;
> -	scsi_show_result(cmd->device, devname, cmd->result);
> +	scsi_show_result(cmd->device, devname, cmd->result, disposition);

It seems like scsi_show_result should just take a disk argument instead
of the name one, and both scsi_print_result and sd_print_result can
just go away.

Re: [PATCH 18/22] scsi_error: format abort error message

[Christoph Hellwig]

What's the point?  eh_abort_handler is only supposed to return SUCCESS
or FAILURE, so I'd rather remove printing of rtn entirely.

Re: [PATCH 20/22] scsi: align logging messages

[Christoph Hellwig]

On Thu, Aug 28, 2014 at 07:33:34PM +0200, Hannes Reinecke wrote:
> Always use 'scmd 0x%p' when logging a command pointer.

Is there any good reason to print the address of a command pointer?

Re: [PATCH 21/22] scsi: reduce messages for command failure

[Christoph Hellwig]

On Thu, Aug 28, 2014 at 07:33:35PM +0200, Hannes Reinecke wrote:
> When devices fail they can generate quite a lot of error
> messages, possibly overloading the logging system.
> So we should be putting these messages under logging control
> to be able to silence them if requested.
> And we should shorten the overall message; more verbose
> logging can be requested by the normal scsi logging.

While the logging mask magic always confused me I'm fairly sure this
disables logging the completion errors entirely by default.  If that
was the intention it should be mentioned in the changelog.

I do however think printing them in a ratelimit way might be useful,
so I'd like to see a few more arguments for not doing it that way if
you really prefer it.

Re: [PATCH 22/22] sd: Reduce logging output

[Christoph Hellwig]

On Thu, Aug 28, 2014 at 07:33:36PM +0200, Hannes Reinecke wrote:
> There is no need to print out the command result verbatim;
> that will be done by the scsi stack if required.
> Here we just should log the result in short if requested.

Is there any good reason to keep this logging in sd at all?

RE: [PATCH 20/22] scsi: align logging messages

[Elliott, Robert (Server Storage)]

> -----Original Message-----
> From: linux-scsi-owner@vger.kernel.org [mailto:linux-scsi-
> owner@vger.kernel.org] On Behalf Of Christoph Hellwig
> Sent: Sunday, 31 August, 2014 5:26 PM
...
> On Thu, Aug 28, 2014 at 07:33:34PM +0200, Hannes Reinecke wrote:
> > Always use 'scmd 0x%p' when logging a command pointer.
> 
> Is there any good reason to print the address of a command pointer?
 
It relates the messages to each other.  When you get lots of
interleaved messages like:

[ 3161.441116] sd 2:0:0:2: [sdt] scmd ffff88041a874e70 abort scheduled
[ 3161.444258] sd 2:0:0:2: [sdt] scmd ffff88041a8b3b30 abort scheduled
...
[ 3162.707427] sd 2:0:0:2: [sdt] aborting command ffff88041a8b3b30
[ 3162.710445] sd 2:0:0:2: [sdt] scmd ffff88041a8b3b30 abort failed, rtn 8195
[ 3162.713092] sd 2:0:0:2: [sdt] aborting command ffff88041a8dd530
[ 3162.715172] sd 2:0:0:2: [sdt] scmd ffff88041a8dd530 abort failed, rtn 8195
...
[ 3171.052277] sd 2:0:0:2: [sdt] scsi_eh_2: flush retry cmd: ffff88041a8b3b30
[ 3171.054910] sd 2:0:0:2: [sdt] scsi_eh_2: flush retry cmd: ffff88041a8dd530
...
[ 3203.406218] sd 2:0:0:0: [sdr] scmd ffff88041a8214b0 not aborting, host in recovery
[ 3203.406424] sd 2:0:0:0: [sdr] scmd ffff88041a8474f0 not aborting, host in recovery

scmd ties the messages together so you can tell which command
has gotten to which state.  grep works.

---
Rob Elliott    HP Server Storage

RE: [PATCH 21/22] scsi: reduce messages for command failure

[Elliott, Robert (Server Storage)]

> -----Original Message-----
> From: linux-scsi-owner@vger.kernel.org [mailto:linux-scsi-
> owner@vger.kernel.org] On Behalf Of Christoph Hellwig
> Sent: Sunday, 31 August, 2014 5:29 PM
> To: Hannes Reinecke
> Cc: James Bottomley; Ewan Milne; Christoph Hellwig; linux-
> scsi@vger.kernel.org; Hoffmann, Elliot; Yoshihiro Yunomae
> Subject: Re: [PATCH 21/22] scsi: reduce messages for command failure
> 
> On Thu, Aug 28, 2014 at 07:33:35PM +0200, Hannes Reinecke wrote:
> > When devices fail they can generate quite a lot of error
> > messages, possibly overloading the logging system.
> > So we should be putting these messages under logging control
> > to be able to silence them if requested.
> > And we should shorten the overall message; more verbose
> > logging can be requested by the normal scsi logging.
> 
> While the logging mask magic always confused me I'm fairly sure this
> disables logging the completion errors entirely by default.  If that
> was the intention it should be mentioned in the changelog.
> 
> I do however think printing them in a ratelimit way might be useful,
> so I'd like to see a few more arguments for not doing it that way if
> you really prefer it.

Before this patch set, ratelimited printing was impossible because
there were so many partial-line printk calls.  This patch set
may resolve that problem.

Multiple related lines may still cause problems; if it prints
CDB, sense key, and additional sense code on three lines, you
don't want the CDB and sense key suppressed with the additional
sense code still sneaking out (because command completions
are concurrent).

If those issues can be overcome, then I'd favor offering ratelimited
calls.  Maybe the logging level could be used to select the amount,
like:
	0 = no prints
	1..n = ratelimited versions of the prints
	n+1..m = not ratelimited versions of the prints


---
Rob Elliott    HP Server Storage

Re: [PATCH 12/22] scsi: remove obsolete __scsi_print_command() usages

[Hannes Reinecke]

On 09/01/2014 12:18 AM, Christoph Hellwig wrote:
> Can you change the subject a bit?  There's nothing obsolete in
> __scsi_print_command, you're just moving it to a higher level helper.
> 
>>  #if defined(AHA152X_DEBUG)
>>  	if (HOSTDATA(shpnt)->debug & debug_queue) {
>> -		printk(INFO_LEAD "queue: %p; cmd_len=%d pieces=%d size=%u cmnd=",
>> -		       CMDINFO(SCpnt), SCpnt, SCpnt->cmd_len,
>> -		       scsi_sg_count(SCpnt), scsi_bufflen(SCpnt));
>> -		__scsi_print_command(SCpnt->cmnd);
>> +		scmd_printk(KERN_INFO, SCpnt,
>> +			    "queue: %p; cmd_len=%d pieces=%d size=%u\n",
>> +			    SCpnt, SCpnt->cmd_len,
>> +			    scsi_sg_count(SCpnt), scsi_bufflen(SCpnt));
>> +		scsi_print_command(SCpnt);
> 
> This also has a printk -> scmd_printk change that's unrelated to the
> patch.
> 
> Honestly I think we should just kill much of the AHA152X_DEBUG code at
> the start of this series to avoid all the churn in it.
> 
I'm all for it.
The 152x is a _really_ old card (that's the one which used to get
shipped with the old parallel SCSI scanner, before they switched
to ncr53c4xx) and it's ISA only. So the overall exposure will be
rather limited, and I sincerely doubt anyone will be missing the
debugging stubs.
Will be removing them with the next patchset.

Cheers,

Hannes
-- 
Dr. Hannes Reinecke		      zSeries & Storage
hare@suse.de			      +49 911 74053 688
SUSE LINUX Products GmbH, Maxfeldstr. 5, 90409 Nürnberg
GF: J. Hawn, J. Guild, F. Imendörffer, HRB 16746 (AG Nürnberg)
--
To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [PATCH 04/22] scsi: introduce sdev_prefix_printk()

[Hannes Reinecke]

On 08/31/2014 11:43 PM, Christoph Hellwig wrote:
> Needs a bit more description in the patch body and preferable also
> in a comment next to the macro.  What's the benefit of it over simply
> using sdev_printk with another argument?
> 
This is particularly useful for ULDs which do not have access to the
scsi command directly.
I'll be updating the comments here.

Cheers,

Hannes
-- 
Dr. Hannes Reinecke		      zSeries & Storage
hare@suse.de			      +49 911 74053 688
SUSE LINUX Products GmbH, Maxfeldstr. 5, 90409 Nürnberg
GF: J. Hawn, J. Guild, F. Imendörffer, HRB 16746 (AG Nürnberg)
--
To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [PATCH 05/22] scsi: Use sdev as argument for sense code printing

[Hannes Reinecke]

On 08/31/2014 11:55 PM, Christoph Hellwig wrote:
>> -scsi_extd_sense_format(unsigned char asc, unsigned char ascq) {
>> +scsi_extd_sense_format(unsigned char asc, unsigned char ascq,
>> +		       const char **fmt) {
> 
> please move the opening brace to a new line per normal Linux style.
> 
Done.

Cheers,

Hannes
-- 
Dr. Hannes Reinecke		      zSeries & Storage
hare@suse.de			      +49 911 74053 688
SUSE LINUX Products GmbH, Maxfeldstr. 5, 90409 Nürnberg
GF: J. Hawn, J. Guild, F. Imendörffer, HRB 16746 (AG Nürnberg)
--
To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [PATCH 06/22] scsi: stop decoding if scsi_normalize_sense() fails

[Hannes Reinecke]

On 09/01/2014 12:00 AM, Christoph Hellwig wrote:
> On Thu, Aug 28, 2014 at 07:33:20PM +0200, Hannes Reinecke wrote:
>> If scsi_normalize_sense() fails we couldn't decode the sense
>> buffer, so we should not try to interpret the result.
>> We should rather dump the sense buffer instead and stop decoding.
> 
> as far as I can tell the old code doesn't interpret it, it just does a
> slightly more convoluted hexdump than your version.  Care to come up
> with a better description for this patch?
> 
Yep, done.

>>  static void
>> +scsi_dump_sense_buffer(struct scsi_device *sdev, const char *name,
>> +		       const unsigned char *sense_buffer, int sense_len)
>>  {
>> +	char linebuf[128];
>> +	int i, linelen, remaining;
>>  
>> +	remaining = sense_len;
>> +	for (i = 0; i < sense_len; i += 16) {
>> +		linelen = min(remaining, 16);
>> +		remaining -= 16;
>> +
>> +		hex_dump_to_buffer(sense_buffer + i, linelen, 16, 1,
>> +				   linebuf, sizeof(linebuf), false);
>> +		sdev_prefix_printk(KERN_INFO, sdev, name,
>> +				   "Sense: %s\n", linebuf);
>>  	}
> 
> This would be more readanle without the remaining variable:
> 
> 	for (i = 0; i < sense_len; i += 16) {
> 		linelen = min(senselen - i, 16);
> 	
> 		...
> 	}
> 
Ok, fixed.

>> @@ -1517,8 +1513,13 @@ void __scsi_print_sense(struct scsi_device *sdev, const char *name,
>>  			const unsigned char *sense_buffer, int sense_len)
>>  {
>>  	struct scsi_sense_hdr sshdr;
>> +	int res;
>>  
>> -	scsi_decode_sense_buffer(sense_buffer, sense_len, &sshdr);
>> +	res = scsi_normalize_sense(sense_buffer, sense_len, &sshdr);
>> +	if (res == 0) {
>> +		scsi_dump_sense_buffer(sdev, name, sense_buffer, sense_len);
>> +		return;
>> +	}
> 
> no need for the res variable.  In fact due to the boolean-like return
> value of scsi_normalize_sense it would be a lot more readable without
> the variable.
> 
Ok, fixed.

Cheers,

Hannes
-- 
Dr. Hannes Reinecke		      zSeries & Storage
hare@suse.de			      +49 911 74053 688
SUSE LINUX Products GmbH, Maxfeldstr. 5, 90409 Nürnberg
GF: J. Hawn, J. Guild, F. Imendörffer, HRB 16746 (AG Nürnberg)
--
To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [PATCH 07/22] scsi: do not decode sense extras

[Hannes Reinecke]

On 09/01/2014 12:06 AM, Christoph Hellwig wrote:
> On Thu, Aug 28, 2014 at 07:33:21PM +0200, Hannes Reinecke wrote:
>> Currently we're only decoding sense extras for tape devices.
>> And even there only for fixed format sense formats.
>> As this is of rather limited use in the general case we should
>> be stop trying to decode things here and rather dump the entire
>> sense code.
> 
> I don't like this one at all.  Not that I'm attached to decoding the
> extra sense buffer, but:
> 
>   - __scsi_print_sense now prints both decoded sense data as well as a
>     full dump, which is rather ugly
>   - __scsi_print_sense prints that buffer unconditionally
> 
> I'd say let's sit down and work with the tape driver maintainers on
> finding a better way to deal with their sense printing needs.  And part
> of that should probably be to get rid of __scsi_print_sense entirely
> and make the tape drivers use pre-decoded and normalized sense buffers.
> 
Well, thing is the tape driver does it's own sense decoding anyway.
So there's no need for that to be done here.

I've updated the patch to not dump any sense code and adapted the
descriptions somewhat.

Cheers,

Hannes
-- 
Dr. Hannes Reinecke		      zSeries & Storage
hare@suse.de			      +49 911 74053 688
SUSE LINUX Products GmbH, Maxfeldstr. 5, 90409 Nürnberg
GF: J. Hawn, J. Guild, F. Imendörffer, HRB 16746 (AG Nürnberg)
--
To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [PATCH 08/22] scsi: dump sense buffer only for debugging

[Hannes Reinecke]

On 09/01/2014 12:09 AM, Christoph Hellwig wrote:
> On Thu, Aug 28, 2014 at 07:33:22PM +0200, Hannes Reinecke wrote:
>> Dumping the entire sense buffer might overwhelm the logging functions,
>> so suppress it per default.
> 
> Call me dumb, but I don't see anything in here that limits the dumps
> to debug output.
> 
Yeah, you're right. This patch is pretty pointless.
I'll be removing it.

> Also if you return boolean-like values please use the bool type for it.
> Also please switch scsi_normalize_sense over to return bool as well
> while you're at it.
> 
Ok.

Cheers,

Hannes
-- 
Dr. Hannes Reinecke		      zSeries & Storage
hare@suse.de			      +49 911 74053 688
SUSE LINUX Products GmbH, Maxfeldstr. 5, 90409 Nürnberg
GF: J. Hawn, J. Guild, F. Imendörffer, HRB 16746 (AG Nürnberg)
--
To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [PATCH 09/22] Use sdev as argument for scsi_print_result

[Hannes Reinecke]

On 09/01/2014 12:11 AM, Christoph Hellwig wrote:
> Please also remove the now useless sd_print_result wrapper.
> 
Done.

> Otherwise looks good,
> 
> Reviewed-by: Christoph Hellwig <hch@lst.de>
> 
Cheers,

Hannes
-- 
Dr. Hannes Reinecke		      zSeries & Storage
hare@suse.de			      +49 911 74053 688
SUSE LINUX Products GmbH, Maxfeldstr. 5, 90409 Nürnberg
GF: J. Hawn, J. Guild, F. Imendörffer, HRB 16746 (AG Nürnberg)
--
To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [PATCH 10/22] scsi: consolidate scsi_print_status()

[Hannes Reinecke]

On 09/01/2014 12:14 AM, Christoph Hellwig wrote:
>>  #if defined(AHA152X_DEBUG)
>> -	if (HOSTDATA(shpnt)->debug & debug_status) {
>> -		printk(DEBUG_LEAD "inbound status %02x ", CMDINFO(CURRENT_SC), CURRENT_SC->SCp.Status);
>> -		scsi_print_status(CURRENT_SC->SCp.Status);
>> -		printk("\n");
>> -	}
>> +	if (HOSTDATA(shpnt)->debug & debug_status)
>> +		printk(DEBUG_LEAD "inbound status %02x\n", CMDINFO(CURRENT_SC), CURRENT_SC->SCp.Status);
> 
> This one just removes the call.  While this is fine with me it needs to
> be mentioned in the changelog.
> 
> Also if you change the line above it please make sure it fits into an
> 80 character line.
> 
>> +const char *
>>  scsi_print_status(unsigned char scsi_status) {
>> -#ifdef CONFIG_SCSI_CONSTANTS
> 
> Please explain in the changelog why you're removing this ifdef.
> 
>> +	case SAM_STAT_BUSY:
>> +		ccp = "Busy"; break;
> 
> Please put the break statements on separate lines per normal Linux
> style.
> 
>>  #define scsi_prot_op_name(result)	{ result, #result }
>>  #define show_prot_op_name(val)					\
>>  	__print_symbolic(val,					\
>> @@ -331,7 +316,7 @@ DECLARE_EVENT_CLASS(scsi_cmd_done_timeout_template,
>>  		  show_driverbyte_name(((__entry->result) >> 24) & 0xff),
>>  		  show_hostbyte_name(((__entry->result) >> 16) & 0xff),
>>  		  show_msgbyte_name(((__entry->result) >> 8) & 0xff),
>> -		  show_statusbyte_name(__entry->result & 0xff))
>> +		  scsi_print_status(__entry->result & 0xff))
> 
> 
> Not using __print_symbolic for trace events breaks all tracing tools
> that parse the binary trace buffers, please drop the tracing changes
> (which weren't mentioned in the changelog anyway and should have been a
> separate patch).
> 
I've now taken another approach; I've updated the logging functions
aha152x.c and removed all debugging code. And with that we can
remove scsi_print_status() altogether.

Cheers,

Hannes
-- 
Dr. Hannes Reinecke		      zSeries & Storage
hare@suse.de			      +49 911 74053 688
SUSE LINUX Products GmbH, Maxfeldstr. 5, 90409 Nürnberg
GF: J. Hawn, J. Guild, F. Imendörffer, HRB 16746 (AG Nürnberg)
--
To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [PATCH 13/22] scsi: use local buffer for printing the opcode

[Hannes Reinecke]

On 09/01/2014 12:19 AM, Christoph Hellwig wrote:
> On Thu, Aug 28, 2014 at 07:33:27PM +0200, Hannes Reinecke wrote:
>> SCSI opcode printing is tricky and needs to take into account
>> several different corner cases. So instead of trying to come
>> up with an elaborate printk() statement we should be printing
>> it into a local buffer.
> 
> scsi_print_command callers are usually deep down the call chain., so I'd
> rather avoid using up even more stack here.  What are the exact reasons
> that we need the local buffer?
> 
I know, and I'm not happy with this patch, either.

However, we really, _really_, want to print the decode command name
and the CDB in one line ie with one printk() statement.
If we don't we'll end up with individual logging messages with one
byte per line under high load.
Making it impossible to figure out to which CDB these individual
bytes are related to.

It would be possible to unroll the CDB decoding loop, as we're
typically have only 3 formats. But it's near impossible to find some
common ground when decoding the command; I've ended up having
really convoluted #defines calling into each other, making debugging
that code really horrible.

You're more than welcome to try...

But for now I fear we have to bite the bullet, and ensure the
additional stack space it only used when logging is enabled.

Cheers,

Hannes
-- 
Dr. Hannes Reinecke		      zSeries & Storage
hare@suse.de			      +49 911 74053 688
SUSE LINUX Products GmbH, Maxfeldstr. 5, 90409 Nürnberg
GF: J. Hawn, J. Guild, F. Imendörffer, HRB 16746 (AG Nürnberg)
--
To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [PATCH 13/22] scsi: use local buffer for printing the opcode

[Hannes Reinecke]

On 09/01/2014 10:57 AM, Hannes Reinecke wrote:
> On 09/01/2014 12:19 AM, Christoph Hellwig wrote:
>> On Thu, Aug 28, 2014 at 07:33:27PM +0200, Hannes Reinecke wrote:
>>> SCSI opcode printing is tricky and needs to take into account
>>> several different corner cases. So instead of trying to come
>>> up with an elaborate printk() statement we should be printing
>>> it into a local buffer.
>>
>> scsi_print_command callers are usually deep down the call chain., so I'd
>> rather avoid using up even more stack here.  What are the exact reasons
>> that we need the local buffer?
>>
> I know, and I'm not happy with this patch, either.
> 
> However, we really, _really_, want to print the decode command name
> and the CDB in one line ie with one printk() statement.
> If we don't we'll end up with individual logging messages with one
> byte per line under high load.
> Making it impossible to figure out to which CDB these individual
> bytes are related to.
> 
> It would be possible to unroll the CDB decoding loop, as we're
> typically have only 3 formats. But it's near impossible to find some
> common ground when decoding the command; I've ended up having
> really convoluted #defines calling into each other, making debugging
> that code really horrible.
> 

Actually, I'm not sure we _can_ avoid increase stack usage when
printing the CDB.

At the end of the day, we want to print a CDB with one printk()
statement. So we'll be having at least 9 arguments to printk per CDB
(format, device name, opcode name, and CDB bytes).
And as we only have a limited register set available we'll be ending
up putting most things on the stack _anyway_, especially for larger
CDBs.
Hiding that behind an elaborate set of preprocessor definitions
and va_format thingies just serves to obfuscate the matter.

Hence I'll be voting to make this explicit and use a local buffer
and only two or three function arguments.
We can optimize it by calling printk() directly for smaller CDB
lengths, but with 16-byte CDBs we'll be using probably the stack
size as with a local buffer.

Cheers,

Hannes
-- 
Dr. Hannes Reinecke		      zSeries & Storage
hare@suse.de			      +49 911 74053 688
SUSE LINUX Products GmbH, Maxfeldstr. 5, 90409 Nürnberg
GF: J. Hawn, J. Guild, F. Imendörffer, HRB 16746 (AG Nürnberg)
--
To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [PATCH 22/22] sd: Reduce logging output

[Hannes Reinecke]

On 09/01/2014 12:29 AM, Christoph Hellwig wrote:
> On Thu, Aug 28, 2014 at 07:33:36PM +0200, Hannes Reinecke wrote:
>> There is no need to print out the command result verbatim;
>> that will be done by the scsi stack if required.
>> Here we just should log the result in short if requested.
> 
> Is there any good reason to keep this logging in sd at all?
> 
Mainly orthogonality.
SCSI_LOG_HL(QUEUE|COMPLETE) is meant for ULDs to print out
some extra logging.
So as sd.c already uses SCSI_LOG_HLQUEUE to print information
about I/O start it should also be using SCSI_LOG_HLCOMPLETE
upon I/O finish.
And should preferable record the same information at both
instances so that any admin can match them together.

Cheers,

Hannes
-- 
Dr. Hannes Reinecke		      zSeries & Storage
hare@suse.de			      +49 911 74053 688
SUSE LINUX Products GmbH, Maxfeldstr. 5, 90409 Nürnberg
GF: J. Hawn, J. Guild, F. Imendörffer, HRB 16746 (AG Nürnberg)
--
To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [PATCH 20/22] scsi: align logging messages

[Christoph Hellwig]

On Mon, Sep 01, 2014 at 01:00:26AM +0000, Elliott, Robert (Server Storage) wrote:
> > -----Original Message-----
> > From: linux-scsi-owner@vger.kernel.org [mailto:linux-scsi-
> > owner@vger.kernel.org] On Behalf Of Christoph Hellwig
> > Sent: Sunday, 31 August, 2014 5:26 PM
> ...
> > On Thu, Aug 28, 2014 at 07:33:34PM +0200, Hannes Reinecke wrote:
> > > Always use 'scmd 0x%p' when logging a command pointer.
> > 
> > Is there any good reason to print the address of a command pointer?
>  
> It relates the messages to each other.  When you get lots of
> interleaved messages like:
> 
> [ 3161.441116] sd 2:0:0:2: [sdt] scmd ffff88041a874e70 abort scheduled
> [ 3161.444258] sd 2:0:0:2: [sdt] scmd ffff88041a8b3b30 abort scheduled
> ...
> [ 3162.707427] sd 2:0:0:2: [sdt] aborting command ffff88041a8b3b30
> [ 3162.710445] sd 2:0:0:2: [sdt] scmd ffff88041a8b3b30 abort failed, rtn 8195
> [ 3162.713092] sd 2:0:0:2: [sdt] aborting command ffff88041a8dd530
> [ 3162.715172] sd 2:0:0:2: [sdt] scmd ffff88041a8dd530 abort failed, rtn 8195
> ...
> [ 3171.052277] sd 2:0:0:2: [sdt] scsi_eh_2: flush retry cmd: ffff88041a8b3b30
> [ 3171.054910] sd 2:0:0:2: [sdt] scsi_eh_2: flush retry cmd: ffff88041a8dd530
> ...
> [ 3203.406218] sd 2:0:0:0: [sdr] scmd ffff88041a8214b0 not aborting, host in recovery
> [ 3203.406424] sd 2:0:0:0: [sdr] scmd ffff88041a8474f0 not aborting, host in recovery
> 
> scmd ties the messages together so you can tell which command
> has gotten to which state.  grep works.

Can we just print the tag instead, that would be a much more human
readable number normally.

Re: [PATCH 21/22] scsi: reduce messages for command failure

[Christoph Hellwig]

On Mon, Sep 01, 2014 at 01:14:23AM +0000, Elliott, Robert (Server Storage) wrote:
> Before this patch set, ratelimited printing was impossible because
> there were so many partial-line printk calls.  This patch set
> may resolve that problem.
> 
> Multiple related lines may still cause problems; if it prints
> CDB, sense key, and additional sense code on three lines, you
> don't want the CDB and sense key suppressed with the additional
> sense code still sneaking out (because command completions
> are concurrent).
> 
> If those issues can be overcome, then I'd favor offering ratelimited
> calls.  Maybe the logging level could be used to select the amount,
> like:
> 	0 = no prints
> 	1..n = ratelimited versions of the prints
> 	n+1..m = not ratelimited versions of the prints

I don't think an unlimited output into the printk buffer is sensible
with the number of IOPS we get from modern devices.  If you need
detailed output you should be using the binary trace buffer.

RE: [PATCH 20/22] scsi: align logging messages

[Elliott, Robert (Server Storage)]

> -----Original Message-----
> From: Christoph Hellwig [mailto:hch@infradead.org]
...
> > scmd ties the messages together so you can tell which command
> > has gotten to which state.  grep works.
> 
> Can we just print the tag instead, that would be a much more human
> readable number normally.

I made a local patch to add the tag (scmd->request->tag), and it does
look good.  I endorse dropping scmd %p in favor of just the tag,
and trying to include the tag in all the lines (here, the Done,
Result, CDB, Sense Key, and Add. Sense lines do not)

[  624.607501] sd 2:0:0:3: [sdv] Done: TIMEOUT
[  624.609121] sd 2:0:0:3: [sdv] Result: hostbyte=DID_OK driverbyte=DRIVER_OK
[  624.611542] sd 2:0:0:3: [sdv] CDB: 28 00 43 03 24 98 00 00 08 00
[  624.613637] sd 2:0:0:3: [sdv] scmd ffff880420891470 tag 1 abort scheduled
[  624.616015] sd 2:0:0:3: [sdv] Done: TIMEOUT
[  624.617510] sd 2:0:0:3: [sdv] Result: hostbyte=DID_OK driverbyte=DRIVER_OK
[  624.619792] sd 2:0:0:3: [sdv] CDB: 28 00 52 83 20 80 00 00 08 00
[  624.621855] sd 2:0:0:3: [sdv] scmd ffff880420893a70 tag 3 abort scheduled
[  624.624148] sd 2:0:0:3: [sdv] Done: TIMEOUT
[  624.625739] sd 2:0:0:3: [sdv] Result: hostbyte=DID_OK driverbyte=DRIVER_OK
[  624.628062] sd 2:0:0:3: [sdv] CDB: 28 00 58 a4 64 70 00 00 08 00
[  624.630132] sd 2:0:0:3: [sdv] scmd ffff880420894d70 tag 4 abort scheduled
[  624.632477] sd 2:0:0:3: [sdv] Done: TIMEOUT
[  624.633913] sd 2:0:0:3: [sdv] Result: hostbyte=DID_OK driverbyte=DRIVER_OK
[  624.636291] sd 2:0:0:3: [sdv] CDB: 28 00 16 90 5c 98 00 00 08 00
[  624.638378] sd 2:0:0:3: [sdv] scmd ffff880420899970 tag 8 abort scheduled
...
[  624.780177] sd 2:0:0:3: [sdv] scmd ffff880420976070 tag 161 abort scheduled
[  624.782661] sd 2:0:0:3: [sdv] Done: TIMEOUT
[  624.784092] sd 2:0:0:3: [sdv] Result: hostbyte=DID_OK driverbyte=DRIVER_OK
[  624.786553] sd 2:0:0:3: [sdv] CDB: 28 00 1e dc 59 e0 00 00 08 00
[  624.788617] sd 2:0:0:3: [sdv] scmd ffff880420977370 tag 162 abort scheduled
[  624.790995] sd 2:0:0:3: [sdv] Done: TIMEOUT
[  624.792443] sd 2:0:0:3: [sdv] Result: hostbyte=DID_OK driverbyte=DRIVER_OK
[  624.794835] sd 2:0:0:3: [sdv] CDB: 28 00 1e 83 1f b8 00 00 08 00
[  624.796965] sd 2:0:0:3: [sdv] scmd ffff88042099ac70 tag 191 abort scheduled 

[  624.799433] sd 2:0:0:3: [sdv] aborting scmd ffff880420891470 tag 1
[  624.801601] sd 2:0:0:3: [sdv] scmd ffff880420891470 tag 1 abort failed, rtn FAILED
[  624.804172] sd 2:0:0:3: [sdv] aborting scmd ffff880420893a70 tag 3
[  624.806417] sd 2:0:0:3: [sdv] scmd ffff880420893a70 tag 3 abort failed, rtn FAILED
[  624.808980] sd 2:0:0:3: [sdv] aborting scmd ffff880420894d70 tag 4
[  624.811086] sd 2:0:0:3: [sdv] scmd ffff880420894d70 tag 4 abort failed, rtn FAILED
[  624.813776] sd 2:0:0:3: [sdv] aborting scmd ffff880420899970 tag 8
[  624.815978] sd 2:0:0:3: [sdv] scmd ffff880420899970 tag 8 abort failed, rtn FAILED
[  624.818653] sd 2:0:0:3: [sdv] aborting scmd ffff88042089ac70 tag 9
...
[  624.852244] sd 2:0:0:3: [sdv] scmd ffff880420976070 tag 161 abort failed, rtn FAILED
[  624.855200] sd 2:0:0:3: [sdv] aborting scmd ffff880420977370 tag 162
[  624.857380] sd 2:0:0:3: [sdv] scmd ffff880420977370 tag 162 abort failed, rtn FAILED
[  624.860057] sd 2:0:0:3: [sdv] aborting scmd ffff88042099ac70 tag 191
[  624.862250] sd 2:0:0:3: [sdv] scmd ffff88042099ac70 tag 191 abort failed, rtn FAILED 

[  624.865174] scsi host2: scsi_eh_2: waking up 0/11/11
[  624.866977] sd 2:0:0:3: scsi_eh_prt_fail_stats: cmds failed: 11, cancel: 0
[  624.869276] scsi host2: Total of 11 commands on 1 devices require eh work
[  624.871683] scsi host2: scsi_eh_2: Sending BDR sdev:ffff88042b162800
[  624.974058] hpsa 0000:04:00.0: resetting scsi 2:0:0:3: Direct-Access     HP       LOGICAL VOLUME   RAID-6 SSDSmartPathCap+ En- Exp=3
[  624.978450] sd 2:0:0:3: [sdv] scsi_eh_done scmd ffff880420891470 tag 1 result: 2
[  624.981114] sd 2:0:0:3: [sdv] Done: SUCCESS
[  624.982719] sd 2:0:0:3: [sdv] Result: hostbyte=DID_OK driverbyte=DRIVER_OK
[  624.985083] sd 2:0:0:3: [sdv] CDB: 00 00 00 00 00 00
[  624.986874] sd 2:0:0:3: [sdv] Sense Key : Unit Attention [current]
[  624.988997] sd 2:0:0:3: [sdv] Add. Sense: Bus device reset function occurred ((null)3)

[  624.991727] sd 2:0:0:3: [sdv] scsi_send_eh_cmnd: scmd ffff880420891470 tag 1 timeleft: 9998
[  624.994927] sd 2:0:0:3: [sdv] scsi_send_eh_cmnd: scsi_eh_completed_normally rtn 2001
[  624.997560] sd 2:0:0:3: [sdv] scsi_eh_tur: scmd ffff880420891470 tag 1 rtn 2001
[  625.001243] sd 2:0:0:3: [sdv] scsi_eh_done scmd ffff880420891470 tag 1 result: 0
[  625.003856] sd 2:0:0:3: [sdv] scsi_send_eh_cmnd: scmd ffff880420891470 tag 1 timeleft: 9997
[  625.006864] sd 2:0:0:3: [sdv] scsi_send_eh_cmnd: scsi_eh_completed_normally rtn 2002
[  625.009481] sd 2:0:0:3: [sdv] scsi_eh_tur: scmd ffff880420891470 tag 1 rtn 2002
[  625.011971] sd 2:0:0:3: [sdv] scsi_eh_2: flush retry scmd ffff880420891470 tag 1
[  625.014925] sd 2:0:0:3: [sdv] scsi_eh_2: flush retry scmd ffff880420893a70 tag 3
[  625.017444] sd 2:0:0:3: [sdv] scsi_eh_2: flush retry scmd ffff880420894d70 tag 4
[  625.019984] sd 2:0:0:3: [sdv] scsi_eh_2: flush retry scmd ffff880420899970 tag 8
...
[  625.032918] sd 2:0:0:3: [sdv] scsi_eh_2: flush retry scmd ffff880420976070 tag 161
[  625.035539] sd 2:0:0:3: [sdv] scsi_eh_2: flush retry scmd ffff880420977370 tag 162
[  625.138124] sd 2:0:0:3: [sdv] scsi_eh_2: flush retry scmd ffff88042099ac70 tag 191


---
Rob Elliott    HP Server Storage

Re: [PATCH 20/22] scsi: align logging messages

[Hannes Reinecke]

On 09/19/2014 01:58 AM, Elliott, Robert (Server Storage) wrote:
>
>
>> -----Original Message-----
>> From: Christoph Hellwig [mailto:hch@infradead.org]
> ...
>>> scmd ties the messages together so you can tell which command
>>> has gotten to which state.  grep works.
>>
>> Can we just print the tag instead, that would be a much more human
>> readable number normally.
>
> I made a local patch to add the tag (scmd->request->tag), and it does
> look good.  I endorse dropping scmd %p in favor of just the tag,
> and trying to include the tag in all the lines (here, the Done,
> Result, CDB, Sense Key, and Add. Sense lines do not)
>
I would rather use 'scmd->tag', as this should be a straight copy
of scmd->request->tag, but we wouldn't need to reference the request
when doing so.

But yeah, I was planning on doing the same, only I'd rather include
it right a the start like

sd 2:0:0:3 [sdv] tag#1: abort scheduled

and print out a mapping when I/O is submitted

sd 2:0:0:3 [sdv] tag#1: scmd 0xffff880420891470

Cheers,

Hannes
-- 
Dr. Hannes Reinecke		      zSeries & Storage
hare@suse.de			      +49 911 74053 688
SUSE LINUX Products GmbH, Maxfeldstr. 5, 90409 Nürnberg
GF: J. Hawn, J. Guild, F. Imendörffer, HRB 16746 (AG Nürnberg)
--
To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [PATCH 20/22] scsi: align logging messages

[Christoph Hellwig]

On Fri, Sep 19, 2014 at 08:26:29AM +0200, Hannes Reinecke wrote:
> I would rather use 'scmd->tag', as this should be a straight copy
> of scmd->request->tag, but we wouldn't need to reference the request
> when doing so.

Yes, for now scmd->tag is correct as drivers might not be using the
block level tagging.  Once we get rid of the legacy request path I
plan to entirely remove scmd->tag, though.

> But yeah, I was planning on doing the same, only I'd rather include
> it right a the start like
> 
> sd 2:0:0:3 [sdv] tag#1: abort scheduled

Sounds fine.

> and print out a mapping when I/O is submitted
> 
> sd 2:0:0:3 [sdv] tag#1: scmd 0xffff880420891470

I don't really see a need for that.

Re: [PATCH 20/22] scsi: align logging messages

[Hannes Reinecke]

On 09/19/2014 01:35 PM, Christoph Hellwig wrote:
> On Fri, Sep 19, 2014 at 08:26:29AM +0200, Hannes Reinecke wrote:
>> I would rather use 'scmd->tag', as this should be a straight copy
>> of scmd->request->tag, but we wouldn't need to reference the request
>> when doing so.
>
> Yes, for now scmd->tag is correct as drivers might not be using the
> block level tagging.  Once we get rid of the legacy request path I
> plan to entirely remove scmd->tag, though.
>
>> But yeah, I was planning on doing the same, only I'd rather include
>> it right a the start like
>>
>> sd 2:0:0:3 [sdv] tag#1: abort scheduled
>
> Sounds fine.
>
>> and print out a mapping when I/O is submitted
>>
>> sd 2:0:0:3 [sdv] tag#1: scmd 0xffff880420891470
>
> I don't really see a need for that.
>
That's mainly for debugging; it gives you a nice starting point
for debugging crash dumps.
Otherwise it's really hard to get to the actual commands.

Unless you have a better idea ...

Cheers,

Hannes
-- 
Dr. Hannes Reinecke		      zSeries & Storage
hare@suse.de			      +49 911 74053 688
SUSE LINUX Products GmbH, Maxfeldstr. 5, 90409 Nürnberg
GF: J. Hawn, J. Guild, F. Imendörffer, HRB 16746 (AG Nürnberg)
--
To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html