[PATCHv4 0/9] scsi logging update: the real thing

[PATCHv4 0/9] scsi logging update: the real thing

[Hannes Reinecke]

Hi all,

this is the second part of my scsi logging update, covering
CDB and sense code printing. With this patchset CDBs and
sense code bytes will be formatted on a single line
(where possible), and prefixed with the device and command
tag.

To ensure CDBs and sense code bytes are not broken up during
printk I've implemented a per-cpu buffer for formatting
messages. One can allocate a chunk from the buffer using
scsi_log_reserve_buffer() and return it via scsi_log_release_buffer().
Both function do an implicit preempt_disable() / preempt_enable()
to ensure we're not scheduled away from that cpu whilst writing
into the buffer.

With that I've been able to clean up constants.c to remove all the
#ifdef CONFIG_SCSI_CONSTANTS statements. It'll now be compiled in
conditionally if CONFIG_SCSI_CONSTANTS is set.

Thanks go to Stephen Rostedt who suffered my annoying questions
during LPC.

Changes to v3:
- Update to scsi-for-3.20 tree
- Drop upstreamed patches

Changes to v2:
- Include reviews and suggestions from Robert Elliott

Hannes Reinecke (9):
  scsi: Implement per-cpu logging buffer
  scsi: log request tag for scmd_printk()
  scsi: use external buffer for command logging
  libata: use __scsi_format_command()
  scsi: use per-cpu buffer for formatting sense
  scsi: use per-cpu buffer for formatting scsi_print_result()
  scsi: Conditionally compile in constants.c
  scsi: Do not display buffer pointers in scsi_log_send()
  scsi_error: do not display kernel pointer in message logs

 drivers/ata/libata-eh.c     |  17 +-
 drivers/scsi/Kconfig        |   4 +-
 drivers/scsi/Makefile       |   6 +-
 drivers/scsi/ch.c           |   6 +-
 drivers/scsi/constants.c    | 247 +---------------------
 drivers/scsi/scsi.c         |  11 +-
 drivers/scsi/scsi_error.c   |  49 ++---
 drivers/scsi/scsi_logging.c | 489 ++++++++++++++++++++++++++++++++++++++++++++
 drivers/scsi/sd.c           |   7 +-
 drivers/scsi/sr_ioctl.c     |  13 +-
 drivers/scsi/ufs/ufshcd.c   |   6 +-
 drivers/xen/xen-scsiback.c  |   1 +
 include/scsi/scsi.h         |   3 +
 include/scsi/scsi_dbg.h     |  74 ++++++-
 include/scsi/scsi_device.h  |  21 +-
 15 files changed, 624 insertions(+), 330 deletions(-)
 create mode 100644 drivers/scsi/scsi_logging.c

-- 
1.8.4.5

[PATCH 1/9] scsi: Implement per-cpu logging buffer

[Hannes Reinecke]

Implement a per-cpu buffer for formatting messages to
avoid line break up under high load.
This patch implements scmd_printk() and sdev_prefix_printk()
using the per-cpu buffer and makes sdev_printk() a wrapper
for sdev_prefix_printk().

Tested-by: Robert Elliott <elliott@hp.com>
Reviewed-by: Robert Elliott <elliott@hp.com>
Signed-off-by: Hannes Reinecke <hare@suse.de>
---
 drivers/scsi/Makefile       |   2 +-
 drivers/scsi/scsi_logging.c | 124 ++++++++++++++++++++++++++++++++++++++++++++
 include/scsi/scsi_device.h  |  21 +++-----
 3 files changed, 133 insertions(+), 14 deletions(-)
 create mode 100644 drivers/scsi/scsi_logging.c

diff --git a/drivers/scsi/Makefile b/drivers/scsi/Makefile
index 58158f1..447c2d2 100644
--- a/drivers/scsi/Makefile
+++ b/drivers/scsi/Makefile
@@ -167,7 +167,7 @@ scsi_mod-y			+= scsi_scan.o scsi_sysfs.o scsi_devinfo.o
 scsi_mod-$(CONFIG_SCSI_NETLINK)	+= scsi_netlink.o
 scsi_mod-$(CONFIG_SYSCTL)	+= scsi_sysctl.o
 scsi_mod-$(CONFIG_SCSI_PROC_FS)	+= scsi_proc.o
-scsi_mod-y			+= scsi_trace.o
+scsi_mod-y			+= scsi_trace.o scsi_logging.o
 scsi_mod-$(CONFIG_PM)		+= scsi_pm.o
 
 hv_storvsc-y			:= storvsc_drv.o
diff --git a/drivers/scsi/scsi_logging.c b/drivers/scsi/scsi_logging.c
new file mode 100644
index 0000000..09d65de
--- /dev/null
+++ b/drivers/scsi/scsi_logging.c
@@ -0,0 +1,124 @@
+/*
+ * scsi_logging.c
+ *
+ * Copyright (C) 2014 SUSE Linux Products GmbH
+ * Copyright (C) 2014 Hannes Reinecke <hare@suse.de>
+ *
+ * This file is released under the GPLv2
+ */
+
+#include <linux/kernel.h>
+#include <linux/atomic.h>
+
+#include <scsi/scsi.h>
+#include <scsi/scsi_cmnd.h>
+#include <scsi/scsi_device.h>
+#include <scsi/scsi_dbg.h>
+
+#define SCSI_LOG_SPOOLSIZE 4096
+#define SCSI_LOG_BUFSIZE 128
+
+#if (SCSI_LOG_SPOOLSIZE / SCSI_LOG_BUFSIZE) > BITS_PER_LONG
+#warning SCSI logging bitmask too large
+#endif
+
+struct scsi_log_buf {
+	char buffer[SCSI_LOG_SPOOLSIZE];
+	unsigned long map;
+};
+
+static DEFINE_PER_CPU(struct scsi_log_buf, scsi_format_log);
+
+static char *scsi_log_reserve_buffer(size_t *len)
+{
+	struct scsi_log_buf *buf;
+	unsigned long map_bits = sizeof(buf->buffer) / SCSI_LOG_BUFSIZE;
+	unsigned long idx = 0;
+
+	preempt_disable();
+	buf = this_cpu_ptr(&scsi_format_log);
+	idx = find_first_zero_bit(&buf->map, map_bits);
+	if (likely(idx < map_bits)) {
+		while (test_and_set_bit(idx, &buf->map)) {
+			idx = find_next_zero_bit(&buf->map, map_bits, idx);
+			if (idx >= map_bits)
+				break;
+		}
+	}
+	if (WARN_ON(idx >= map_bits)) {
+		preempt_enable();
+		return NULL;
+	}
+	*len = SCSI_LOG_BUFSIZE;
+	return buf->buffer + idx * SCSI_LOG_BUFSIZE;
+}
+
+static void scsi_log_release_buffer(char *bufptr)
+{
+	struct scsi_log_buf *buf;
+	unsigned long idx;
+	int ret;
+
+	buf = this_cpu_ptr(&scsi_format_log);
+	if (bufptr >= buf->buffer &&
+	    bufptr < buf->buffer + SCSI_LOG_SPOOLSIZE) {
+		idx = (bufptr - buf->buffer) / SCSI_LOG_BUFSIZE;
+		ret = test_and_clear_bit(idx, &buf->map);
+		WARN_ON(!ret);
+	}
+	preempt_enable();
+}
+
+int sdev_prefix_printk(const char *level, const struct scsi_device *sdev,
+		       const char *name, const char *fmt, ...)
+{
+	va_list args;
+	char *logbuf;
+	size_t off = 0, logbuf_len;
+	int ret;
+
+	if (!sdev)
+		return 0;
+
+	logbuf = scsi_log_reserve_buffer(&logbuf_len);
+	if (!logbuf)
+		return 0;
+
+	if (name)
+		off += scnprintf(logbuf + off, logbuf_len - off,
+				 "[%s] ", name);
+	va_start(args, fmt);
+	off += vscnprintf(logbuf + off, logbuf_len - off, fmt, args);
+	va_end(args);
+	ret = dev_printk(level, &sdev->sdev_gendev, "%s", logbuf);
+	scsi_log_release_buffer(logbuf);
+	return ret;
+}
+EXPORT_SYMBOL(sdev_prefix_printk);
+
+int scmd_printk(const char *level, const struct scsi_cmnd *scmd,
+		const char *fmt, ...)
+{
+	struct gendisk *disk = scmd->request->rq_disk;
+	va_list args;
+	char *logbuf;
+	size_t off = 0, logbuf_len;
+	int ret;
+
+	if (!scmd || !scmd->cmnd)
+		return 0;
+
+	logbuf = scsi_log_reserve_buffer(&logbuf_len);
+	if (!logbuf)
+		return 0;
+	if (disk)
+		off += scnprintf(logbuf + off, logbuf_len - off,
+				 "[%s] ", disk->disk_name);
+	va_start(args, fmt);
+	off += vscnprintf(logbuf + off, logbuf_len - off, fmt, args);
+	va_end(args);
+	ret = dev_printk(level, &scmd->device->sdev_gendev, "%s", logbuf);
+	scsi_log_release_buffer(logbuf);
+	return ret;
+}
+EXPORT_SYMBOL(scmd_printk);
diff --git a/include/scsi/scsi_device.h b/include/scsi/scsi_device.h
index 3a4edd1..d1aad4d 100644
--- a/include/scsi/scsi_device.h
+++ b/include/scsi/scsi_device.h
@@ -230,9 +230,6 @@ struct scsi_dh_data {
 #define transport_class_to_sdev(class_dev) \
 	to_scsi_device(class_dev->parent)
 
-#define sdev_printk(prefix, sdev, fmt, a...)	\
-	dev_printk(prefix, &(sdev)->sdev_gendev, fmt, ##a)
-
 #define sdev_dbg(sdev, fmt, a...) \
 	dev_dbg(&(sdev)->sdev_gendev, fmt, ##a)
 
@@ -240,16 +237,14 @@ struct scsi_dh_data {
  * like scmd_printk, but the device name is passed in
  * as a string pointer
  */
-#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,		\
-		    (scmd)->request->rq_disk->disk_name, ##a) :		\
-	sdev_printk(prefix, (scmd)->device, fmt, ##a)
+extern int sdev_prefix_printk(const char *, const struct scsi_device *,
+			      const char *, const char *, ...);
+
+#define sdev_printk(l, sdev, fmt, a...)				\
+	sdev_prefix_printk(l, sdev, NULL, fmt, ##a)
+
+extern int scmd_printk(const char *, const struct scsi_cmnd *,
+		       const char *, ...);
 
 #define scmd_dbg(scmd, fmt, a...)					   \
 	do {								   \
-- 
1.8.4.5

[PATCH 2/9] scsi: log request tag for scmd_printk()

[Hannes Reinecke]

The request tag provides a concise identification of a SCSI
command, so we should be printing that out for scmd_printk().

Suggested-by: Christoph Hellwig <hch@lst.de>
Tested-by: Robert Elliott <elliott@hp.com>
Reviewed-by: Robert Elliott <elliott@hp.com>
Reviewed-by: Christoph Hellwig <hch@lst.de>
Signed-off-by: Hannes Reinecke <hare@suse.de>
---
 drivers/scsi/scsi_logging.c | 4 ++++
 1 file changed, 4 insertions(+)

diff --git a/drivers/scsi/scsi_logging.c b/drivers/scsi/scsi_logging.c
index 09d65de..4d20132 100644
--- a/drivers/scsi/scsi_logging.c
+++ b/drivers/scsi/scsi_logging.c
@@ -114,6 +114,10 @@ int scmd_printk(const char *level, const struct scsi_cmnd *scmd,
 	if (disk)
 		off += scnprintf(logbuf + off, logbuf_len - off,
 				 "[%s] ", disk->disk_name);
+
+	if (scmd->request->tag >= 0)
+		off += scnprintf(logbuf + off, logbuf_len - off,
+				 "tag#%d ", scmd->request->tag);
 	va_start(args, fmt);
 	off += vscnprintf(logbuf + off, logbuf_len - off, fmt, args);
 	va_end(args);
-- 
1.8.4.5

[PATCH 3/9] scsi: use external buffer for command logging

[Hannes Reinecke]

Use an external buffer for __scsi_print_command() and
move command logging over to use the per-cpu logging
buffer. With that we can guarantee the command always
will always be formatted in one line.
So we can even print out a variable length command
correctly across several lines.
Finally rename __scsi_print_command() to
__scsi_format_comment() to better reflect the
functionality.

Tested-by: Robert Elliott <elliott@hp.com>
Reviewed-by: Robert Elliott <elliott@hp.com>
Reviewed-by: Christoph Hellwig <hch@lst.de>
Signed-off-by: Hannes Reinecke <hare@suse.de>
---
 drivers/scsi/ch.c           |   6 +-
 drivers/scsi/constants.c    |  74 +-----------------
 drivers/scsi/scsi_logging.c | 182 ++++++++++++++++++++++++++++++++++++++++----
 drivers/scsi/sr_ioctl.c     |  13 +++-
 include/scsi/scsi.h         |   3 +
 include/scsi/scsi_dbg.h     |   6 +-
 6 files changed, 192 insertions(+), 92 deletions(-)

diff --git a/drivers/scsi/ch.c b/drivers/scsi/ch.c
index 6bac8a7..79e462f 100644
--- a/drivers/scsi/ch.c
+++ b/drivers/scsi/ch.c
@@ -195,8 +195,10 @@ ch_do_scsi(scsi_changer *ch, unsigned char *cmd, int cmd_len,
  retry:
 	errno = 0;
 	if (debug) {
-		DPRINTK("command: ");
-		__scsi_print_command(cmd, cmd_len);
+		char logbuf[SCSI_LOG_BUFSIZE];
+
+		__scsi_format_command(logbuf, sizeof(logbuf), cmd, cmd_len);
+		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 55a7157..7792960 100644
--- a/drivers/scsi/constants.c
+++ b/drivers/scsi/constants.c
@@ -24,8 +24,6 @@
 #define THIRD_PARTY_COPY_OUT 0x83
 #define THIRD_PARTY_COPY_IN 0x84
 
-#define VENDOR_SPECIFIC_CDB 0xc0
-
 struct sa_name_list {
 	int opcode;
 	const struct value_name_pair *arr;
@@ -281,8 +279,8 @@ static struct sa_name_list sa_names_arr[] = {
 };
 #endif /* CONFIG_SCSI_CONSTANTS */
 
-static bool scsi_opcode_sa_name(int opcode, int service_action,
-				const char **cdb_name, const char **sa_name)
+bool scsi_opcode_sa_name(int opcode, int service_action,
+			 const char **cdb_name, const char **sa_name)
 {
 	struct sa_name_list *sa_name_ptr;
 	const struct value_name_pair *arr = NULL;
@@ -315,74 +313,6 @@ static bool scsi_opcode_sa_name(int opcode, int service_action,
 	return true;
 }
 
-static void print_opcode_name(const unsigned char *cdbp, size_t cdb_len)
-{
-	int sa, cdb0;
-	const char *cdb_name = NULL, *sa_name = NULL;
-
-	cdb0 = cdbp[0];
-	if (cdb0 == VARIABLE_LENGTH_CMD) {
-		if (cdb_len < 10) {
-			printk("short variable length command, len=%zu",
-			       cdb_len);
-			return;
-		}
-		sa = (cdbp[8] << 8) + cdbp[9];
-	} else
-		sa = cdbp[1] & 0x1f;
-
-	if (!scsi_opcode_sa_name(cdb0, sa, &cdb_name, &sa_name)) {
-		if (cdb_name)
-			printk("%s", cdb_name);
-		else if (cdb0 >= VENDOR_SPECIFIC_CDB)
-			printk("cdb[0]=0x%x (vendor)", cdb0);
-		else if (cdb0 >= 0x60 && cdb0 < 0x7e)
-			printk("cdb[0]=0x%x (reserved)", cdb0);
-		else
-			printk("cdb[0]=0x%x", cdb0);
-	} else {
-		if (sa_name)
-			printk("%s", sa_name);
-		else if (cdb_name)
-			printk("%s, sa=0x%x", cdb_name, sa);
-		else
-			printk("cdb[0]=0x%x, sa=0x%x", cdb0, sa);
-	}
-}
-
-void __scsi_print_command(const unsigned char *cdb, size_t cdb_len)
-{
-	int k, len;
-
-	print_opcode_name(cdb, cdb_len);
-	len = scsi_command_size(cdb);
-	if (cdb_len < len)
-		len = cdb_len;
-	/* print out all bytes in cdb */
-	for (k = 0; k < len; ++k)
-		printk(" %02x", cdb[k]);
-	printk("\n");
-}
-EXPORT_SYMBOL(__scsi_print_command);
-
-void scsi_print_command(struct scsi_cmnd *cmd)
-{
-	int k;
-
-	if (cmd->cmnd == NULL)
-		return;
-
-	scmd_printk(KERN_INFO, cmd, "CDB: ");
-	print_opcode_name(cmd->cmnd, cmd->cmd_len);
-
-	/* print out all bytes in cdb */
-	printk(":");
-	for (k = 0; k < cmd->cmd_len; ++k)
-		printk(" %02x", cmd->cmnd[k]);
-	printk("\n");
-}
-EXPORT_SYMBOL(scsi_print_command);
-
 #ifdef CONFIG_SCSI_CONSTANTS
 
 struct error_info {
diff --git a/drivers/scsi/scsi_logging.c b/drivers/scsi/scsi_logging.c
index 4d20132..afba995 100644
--- a/drivers/scsi/scsi_logging.c
+++ b/drivers/scsi/scsi_logging.c
@@ -13,10 +13,10 @@
 #include <scsi/scsi.h>
 #include <scsi/scsi_cmnd.h>
 #include <scsi/scsi_device.h>
+#include <scsi/scsi_eh.h>
 #include <scsi/scsi_dbg.h>
 
 #define SCSI_LOG_SPOOLSIZE 4096
-#define SCSI_LOG_BUFSIZE 128
 
 #if (SCSI_LOG_SPOOLSIZE / SCSI_LOG_BUFSIZE) > BITS_PER_LONG
 #warning SCSI logging bitmask too large
@@ -69,6 +69,24 @@ static void scsi_log_release_buffer(char *bufptr)
 	preempt_enable();
 }
 
+static size_t scmd_format_header(char *logbuf, size_t logbuf_len,
+				 struct gendisk *disk, int tag)
+{
+	size_t off = 0;
+
+	if (disk)
+		off += scnprintf(logbuf + off, logbuf_len - off,
+				 "[%s] ", disk->disk_name);
+
+	if (WARN_ON(off >= logbuf_len))
+		return off;
+
+	if (tag >= 0)
+		off += scnprintf(logbuf + off, logbuf_len - off,
+				 "tag#%d ", tag);
+	return off;
+}
+
 int sdev_prefix_printk(const char *level, const struct scsi_device *sdev,
 		       const char *name, const char *fmt, ...)
 {
@@ -87,9 +105,11 @@ int sdev_prefix_printk(const char *level, const struct scsi_device *sdev,
 	if (name)
 		off += scnprintf(logbuf + off, logbuf_len - off,
 				 "[%s] ", name);
-	va_start(args, fmt);
-	off += vscnprintf(logbuf + off, logbuf_len - off, fmt, args);
-	va_end(args);
+	if (!WARN_ON(off >= logbuf_len)) {
+		va_start(args, fmt);
+		off += vscnprintf(logbuf + off, logbuf_len - off, fmt, args);
+		va_end(args);
+	}
 	ret = dev_printk(level, &sdev->sdev_gendev, "%s", logbuf);
 	scsi_log_release_buffer(logbuf);
 	return ret;
@@ -111,18 +131,152 @@ int scmd_printk(const char *level, const struct scsi_cmnd *scmd,
 	logbuf = scsi_log_reserve_buffer(&logbuf_len);
 	if (!logbuf)
 		return 0;
-	if (disk)
-		off += scnprintf(logbuf + off, logbuf_len - off,
-				 "[%s] ", disk->disk_name);
-
-	if (scmd->request->tag >= 0)
-		off += scnprintf(logbuf + off, logbuf_len - off,
-				 "tag#%d ", scmd->request->tag);
-	va_start(args, fmt);
-	off += vscnprintf(logbuf + off, logbuf_len - off, fmt, args);
-	va_end(args);
+	off = scmd_format_header(logbuf, logbuf_len, disk,
+				 scmd->request->tag);
+	if (off < logbuf_len) {
+		va_start(args, fmt);
+		off += vscnprintf(logbuf + off, logbuf_len - off, fmt, args);
+		va_end(args);
+	}
 	ret = dev_printk(level, &scmd->device->sdev_gendev, "%s", logbuf);
 	scsi_log_release_buffer(logbuf);
 	return ret;
 }
 EXPORT_SYMBOL(scmd_printk);
+
+static size_t scsi_format_opcode_name(char *buffer, size_t buf_len,
+				      const unsigned char *cdbp)
+{
+	int sa, cdb0;
+	const char *cdb_name = NULL, *sa_name = NULL;
+	size_t off;
+
+	cdb0 = cdbp[0];
+	if (cdb0 == VARIABLE_LENGTH_CMD) {
+		int len = scsi_varlen_cdb_length(cdbp);
+
+		if (len < 10) {
+			off = scnprintf(buffer, buf_len,
+					"short variable length command, len=%d",
+					len);
+			return off;
+		}
+		sa = (cdbp[8] << 8) + cdbp[9];
+	} else
+		sa = cdbp[1] & 0x1f;
+
+	if (!scsi_opcode_sa_name(cdb0, sa, &cdb_name, &sa_name)) {
+		if (cdb_name)
+			off = scnprintf(buffer, buf_len, "%s", cdb_name);
+		else {
+			off = scnprintf(buffer, buf_len, "opcode=0x%x", cdb0);
+			if (WARN_ON(off >= buf_len))
+				return off;
+			if (cdb0 >= VENDOR_SPECIFIC_CDB)
+				off += scnprintf(buffer + off, buf_len - off,
+						 " (vendor)");
+			else if (cdb0 >= 0x60 && cdb0 < 0x7e)
+				off += scnprintf(buffer + off, buf_len - off,
+						 " (reserved)");
+		}
+	} else {
+		if (sa_name)
+			off = scnprintf(buffer, buf_len, "%s", sa_name);
+		else if (cdb_name)
+			off = scnprintf(buffer, buf_len, "%s, sa=0x%x",
+					cdb_name, sa);
+		else
+			off = scnprintf(buffer, buf_len,
+					"opcode=0x%x, sa=0x%x", cdb0, sa);
+	}
+	WARN_ON(off >= buf_len);
+	return off;
+}
+
+size_t __scsi_format_command(char *logbuf, size_t logbuf_len,
+			     const unsigned char *cdb, size_t cdb_len)
+{
+	int len, k;
+	size_t off;
+
+	off = scsi_format_opcode_name(logbuf, logbuf_len, cdb);
+	if (off >= logbuf_len)
+		return off;
+	len = scsi_command_size(cdb);
+	if (cdb_len < len)
+		len = cdb_len;
+	/* print out all bytes in cdb */
+	for (k = 0; k < len; ++k) {
+		if (off > logbuf_len - 3)
+			break;
+		off += scnprintf(logbuf + off, logbuf_len - off,
+				 " %02x", cdb[k]);
+	}
+	return off;
+}
+EXPORT_SYMBOL(__scsi_format_command);
+
+void scsi_print_command(struct scsi_cmnd *cmd)
+{
+	struct gendisk *disk = cmd->request->rq_disk;
+	int k;
+	char *logbuf;
+	size_t off, logbuf_len;
+
+	if (!cmd->cmnd)
+		return;
+
+	logbuf = scsi_log_reserve_buffer(&logbuf_len);
+	if (!logbuf)
+		return;
+
+	off = scmd_format_header(logbuf, logbuf_len, disk, cmd->request->tag);
+	if (off >= logbuf_len)
+		goto out_printk;
+	off += scnprintf(logbuf + off, logbuf_len - off, "CDB: ");
+	if (WARN_ON(off >= logbuf_len))
+		goto out_printk;
+
+	off += scsi_format_opcode_name(logbuf + off, logbuf_len - off,
+				       cmd->cmnd);
+	if (off >= logbuf_len)
+		goto out_printk;
+
+	/* print out all bytes in cdb */
+	if (cmd->cmd_len > 16) {
+		/* Print opcode in one line and use separate lines for CDB */
+		off += scnprintf(logbuf + off, logbuf_len - off, "\n");
+		dev_printk(KERN_INFO, &cmd->device->sdev_gendev, logbuf);
+		scsi_log_release_buffer(logbuf);
+		for (k = 0; k < cmd->cmd_len; k += 16) {
+			size_t linelen = min(cmd->cmd_len - k, 16);
+
+			logbuf = scsi_log_reserve_buffer(&logbuf_len);
+			if (!logbuf)
+				break;
+			off = scmd_format_header(logbuf, logbuf_len, disk,
+						 cmd->request->tag);
+			if (!WARN_ON(off > logbuf_len - 58)) {
+				off += scnprintf(logbuf + off, logbuf_len - off,
+						 "CDB[%02x]: ", k);
+				hex_dump_to_buffer(&cmd->cmnd[k], linelen,
+						   16, 1, logbuf + off,
+						   logbuf_len - off, false);
+			}
+			dev_printk(KERN_INFO, &cmd->device->sdev_gendev,
+				   logbuf);
+			scsi_log_release_buffer(logbuf);
+		}
+		return;
+	}
+	if (!WARN_ON(off > logbuf_len - 49)) {
+		off += scnprintf(logbuf + off, logbuf_len - off, " ");
+		hex_dump_to_buffer(cmd->cmnd, cmd->cmd_len, 16, 1,
+				   logbuf + off, logbuf_len - off,
+				   false);
+	}
+out_printk:
+	dev_printk(KERN_INFO, &cmd->device->sdev_gendev, logbuf);
+	scsi_log_release_buffer(logbuf);
+}
+EXPORT_SYMBOL(scsi_print_command);
diff --git a/drivers/scsi/sr_ioctl.c b/drivers/scsi/sr_ioctl.c
index fb929fa..e8deb9c 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[SCSI_LOG_BUFSIZE];
 
 	SDev = cd->device;
 
@@ -257,14 +258,20 @@ 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, CDROM_PACKET_SIZE);
+			__scsi_format_command(logbuf, sizeof(logbuf),
+					      cgc->cmd, CDROM_PACKET_SIZE);
+			sr_printk(KERN_INFO, cd,
+				  "CDROM (ioctl) invalid command: %s\n",
+				  logbuf);
 			scsi_print_sense_hdr(cd->device, cd->cdi.name, &sshdr);
 #endif
 			break;
 		default:
+			__scsi_format_command(logbuf, sizeof(logbuf),
+					      cgc->cmd, CDROM_PACKET_SIZE);
 			sr_printk(KERN_ERR, cd,
-				  "CDROM (ioctl) error, command: ");
-			__scsi_print_command(cgc->cmd, CDROM_PACKET_SIZE);
+				  "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.h b/include/scsi/scsi.h
index 8a7f8ad..d0a66aa 100644
--- a/include/scsi/scsi.h
+++ b/include/scsi/scsi.h
@@ -195,6 +195,9 @@ enum scsi_timeouts {
 #define	ATA_16		      0x85	/* 16-byte pass-thru */
 #define	ATA_12		      0xa1	/* 12-byte pass-thru */
 
+/* Vendor specific CDBs start here */
+#define VENDOR_SPECIFIC_CDB 0xc0
+
 /*
  *	SCSI command lengths
  */
diff --git a/include/scsi/scsi_dbg.h b/include/scsi/scsi_dbg.h
index 7982795..c7ed7b8 100644
--- a/include/scsi/scsi_dbg.h
+++ b/include/scsi/scsi_dbg.h
@@ -5,8 +5,12 @@ struct scsi_cmnd;
 struct scsi_device;
 struct scsi_sense_hdr;
 
+#define SCSI_LOG_BUFSIZE 128
+
+extern bool scsi_opcode_sa_name(int, int, const char **, const char **);
 extern void scsi_print_command(struct scsi_cmnd *);
-extern void __scsi_print_command(const unsigned char *, size_t);
+extern size_t __scsi_format_command(char *, size_t,
+				   const unsigned char *, size_t);
 extern void scsi_show_extd_sense(const struct scsi_device *, const char *,
 				 unsigned char, unsigned char);
 extern void scsi_show_sense_hdr(const struct scsi_device *, const char *,
-- 
1.8.4.5

[PATCH 4/9] libata: use __scsi_format_command()

[Hannes Reinecke]

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

Tested-by: Robert Elliott <elliott@hp.com>
Reviewed-by: Robert Elliott <elliott@hp.com>
Reviewed-by: Christoph Hellwig <hch@lst.de>
Acked-by: Tejun Heo <tj@kernel.org>
Signed-off-by: Hannes Reinecke <hare@suse.de>
---
 drivers/ata/libata-eh.c | 17 +++++++----------
 1 file changed, 7 insertions(+), 10 deletions(-)

diff --git a/drivers/ata/libata-eh.c b/drivers/ata/libata-eh.c
index 3dbec89..9179f11 100644
--- a/drivers/ata/libata-eh.c
+++ b/drivers/ata/libata-eh.c
@@ -2482,6 +2482,7 @@ static void ata_eh_link_report(struct ata_link *link)
 		struct ata_queued_cmd *qc = __ata_qc_from_tag(ap, tag);
 		struct ata_taskfile *cmd = &qc->tf, *res = &qc->result_tf;
 		const u8 *cdb = qc->cdb;
+		size_t cdb_len = qc->dev->cdb_len;
 		char data_buf[20] = "";
 		char cdb_buf[70] = "";
 
@@ -2509,16 +2510,12 @@ 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);
-			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]);
+			if (qc->scsicmd) {
+				cdb = qc->scsicmd->cmnd;
+				cdb_len = qc->scsicmd->cmd_len;
+			}
+			__scsi_format_command(cdb_buf, sizeof(cdb_buf),
+					      cdb, cdb_len);
 		} else {
 			const char *descr = ata_get_cmd_descript(cmd->command);
 			if (descr)
-- 
1.8.4.5

[PATCH 5/9] scsi: use per-cpu buffer for formatting sense

[Hannes Reinecke]

Convert sense buffer logging to use the per-cpu
buffer to avoid line breakup.

Tested-by: Robert Elliott <elliott@hp.com>
Reviewed-by: Robert Elliott <elliott@hp.com>
Signed-off-by: Hannes Reinecke <hare@suse.de>
---
 drivers/scsi/constants.c    | 107 ----------------------------
 drivers/scsi/scsi_logging.c | 166 +++++++++++++++++++++++++++++++++++++++++---
 drivers/scsi/sd.c           |   7 +-
 drivers/scsi/ufs/ufshcd.c   |   6 +-
 4 files changed, 161 insertions(+), 125 deletions(-)

diff --git a/drivers/scsi/constants.c b/drivers/scsi/constants.c
index 7792960..a23ef75 100644
--- a/drivers/scsi/constants.c
+++ b/drivers/scsi/constants.c
@@ -1246,113 +1246,6 @@ scsi_extd_sense_format(unsigned char asc, unsigned char ascq, const char **fmt)
 }
 EXPORT_SYMBOL(scsi_extd_sense_format);
 
-void
-scsi_show_extd_sense(const struct scsi_device *sdev, const char *name,
-		     unsigned char asc, unsigned char ascq)
-{
-	const char *extd_sense_fmt = NULL;
-	const char *extd_sense_str = scsi_extd_sense_format(asc, ascq,
-							    &extd_sense_fmt);
-
-	if (extd_sense_str) {
-		if (extd_sense_fmt)
-			sdev_prefix_printk(KERN_INFO, sdev, name,
-					   "Add. Sense: %s (%s%x)",
-					   extd_sense_str, extd_sense_fmt,
-					   ascq);
-		else
-			sdev_prefix_printk(KERN_INFO, sdev, name,
-					   "Add. Sense: %s", extd_sense_str);
-
-	} else {
-		sdev_prefix_printk(KERN_INFO, sdev, name,
-				   "%sASC=0x%x %sASCQ=0x%x\n",
-				   asc >= 0x80 ? "<<vendor>> " : "", asc,
-				   ascq >= 0x80 ? "<<vendor>> " : "", ascq);
-	}
-}
-EXPORT_SYMBOL(scsi_show_extd_sense);
-
-void
-scsi_show_sense_hdr(const struct scsi_device *sdev, const char *name,
-		    const struct scsi_sense_hdr *sshdr)
-{
-	const char *sense_txt;
-
-	sense_txt = scsi_sense_key_string(sshdr->sense_key);
-	if (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
-		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);
-
-/*
- * Print normalized SCSI sense header with a prefix.
- */
-void
-scsi_print_sense_hdr(const struct scsi_device *sdev, const char *name,
-		     const struct scsi_sense_hdr *sshdr)
-{
-	scsi_show_sense_hdr(sdev, name, sshdr);
-	scsi_show_extd_sense(sdev, name, sshdr->asc, sshdr->ascq);
-}
-EXPORT_SYMBOL(scsi_print_sense_hdr);
-
-static void
-scsi_dump_sense_buffer(const unsigned char *sense_buffer, int sense_len)
-{
-	int k, num;
-
-	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;
-}
-
-/* Normalize and print sense buffer with name prefix */
-void __scsi_print_sense(const struct scsi_device *sdev, const char *name,
-			const unsigned char *sense_buffer, int sense_len)
-{
-	struct scsi_sense_hdr sshdr;
-
-	if (!scsi_normalize_sense(sense_buffer, sense_len, &sshdr)) {
-		scsi_dump_sense_buffer(sense_buffer, sense_len);
-		return;
-	}
-	scsi_show_sense_hdr(sdev, name, &sshdr);
-	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(const 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);
-}
-EXPORT_SYMBOL(scsi_print_sense);
-
 #ifdef CONFIG_SCSI_CONSTANTS
 
 static const char * const hostbyte_table[]={
diff --git a/drivers/scsi/scsi_logging.c b/drivers/scsi/scsi_logging.c
index afba995..c7cba31 100644
--- a/drivers/scsi/scsi_logging.c
+++ b/drivers/scsi/scsi_logging.c
@@ -69,14 +69,20 @@ static void scsi_log_release_buffer(char *bufptr)
 	preempt_enable();
 }
 
-static size_t scmd_format_header(char *logbuf, size_t logbuf_len,
-				 struct gendisk *disk, int tag)
+static inline const char *scmd_name(const struct scsi_cmnd *scmd)
+{
+	return scmd->request->rq_disk ?
+		scmd->request->rq_disk->disk_name : NULL;
+}
+
+static size_t sdev_format_header(char *logbuf, size_t logbuf_len,
+				 const char *name, int tag)
 {
 	size_t off = 0;
 
-	if (disk)
+	if (name)
 		off += scnprintf(logbuf + off, logbuf_len - off,
-				 "[%s] ", disk->disk_name);
+				 "[%s] ", name);
 
 	if (WARN_ON(off >= logbuf_len))
 		return off;
@@ -119,7 +125,6 @@ EXPORT_SYMBOL(sdev_prefix_printk);
 int scmd_printk(const char *level, const struct scsi_cmnd *scmd,
 		const char *fmt, ...)
 {
-	struct gendisk *disk = scmd->request->rq_disk;
 	va_list args;
 	char *logbuf;
 	size_t off = 0, logbuf_len;
@@ -131,7 +136,7 @@ int scmd_printk(const char *level, const struct scsi_cmnd *scmd,
 	logbuf = scsi_log_reserve_buffer(&logbuf_len);
 	if (!logbuf)
 		return 0;
-	off = scmd_format_header(logbuf, logbuf_len, disk,
+	off = sdev_format_header(logbuf, logbuf_len, scmd_name(scmd),
 				 scmd->request->tag);
 	if (off < logbuf_len) {
 		va_start(args, fmt);
@@ -218,7 +223,6 @@ EXPORT_SYMBOL(__scsi_format_command);
 
 void scsi_print_command(struct scsi_cmnd *cmd)
 {
-	struct gendisk *disk = cmd->request->rq_disk;
 	int k;
 	char *logbuf;
 	size_t off, logbuf_len;
@@ -230,7 +234,8 @@ void scsi_print_command(struct scsi_cmnd *cmd)
 	if (!logbuf)
 		return;
 
-	off = scmd_format_header(logbuf, logbuf_len, disk, cmd->request->tag);
+	off = sdev_format_header(logbuf, logbuf_len,
+				 scmd_name(cmd), cmd->request->tag);
 	if (off >= logbuf_len)
 		goto out_printk;
 	off += scnprintf(logbuf + off, logbuf_len - off, "CDB: ");
@@ -254,7 +259,8 @@ void scsi_print_command(struct scsi_cmnd *cmd)
 			logbuf = scsi_log_reserve_buffer(&logbuf_len);
 			if (!logbuf)
 				break;
-			off = scmd_format_header(logbuf, logbuf_len, disk,
+			off = sdev_format_header(logbuf, logbuf_len,
+						 scmd_name(cmd),
 						 cmd->request->tag);
 			if (!WARN_ON(off > logbuf_len - 58)) {
 				off += scnprintf(logbuf + off, logbuf_len - off,
@@ -280,3 +286,145 @@ out_printk:
 	scsi_log_release_buffer(logbuf);
 }
 EXPORT_SYMBOL(scsi_print_command);
+
+static size_t
+scsi_format_extd_sense(char *buffer, size_t buf_len,
+		       unsigned char asc, unsigned char ascq)
+{
+	size_t off = 0;
+	const char *extd_sense_fmt = NULL;
+	const char *extd_sense_str = scsi_extd_sense_format(asc, ascq,
+							    &extd_sense_fmt);
+
+	if (extd_sense_str) {
+		off = scnprintf(buffer, buf_len, "Add. Sense: %s",
+				extd_sense_str);
+		if (extd_sense_fmt)
+			off += scnprintf(buffer + off, buf_len - off,
+					 "(%s%x)", extd_sense_fmt, ascq);
+	} else {
+		if (asc >= 0x80)
+			off = scnprintf(buffer, buf_len, "<<vendor>>");
+		off += scnprintf(buffer + off, buf_len - off,
+				 "ASC=0x%x ", asc);
+		if (ascq >= 0x80)
+			off += scnprintf(buffer + off, buf_len - off,
+					 "<<vendor>>");
+		off += scnprintf(buffer + off, buf_len - off,
+				 "ASCQ=0x%x ", ascq);
+	}
+	return off;
+}
+
+static size_t
+scsi_format_sense_hdr(char *buffer, size_t buf_len,
+		      const struct scsi_sense_hdr *sshdr)
+{
+	const char *sense_txt;
+	size_t off;
+
+	off = scnprintf(buffer, buf_len, "Sense Key : ");
+	sense_txt = scsi_sense_key_string(sshdr->sense_key);
+	if (sense_txt)
+		off += scnprintf(buffer + off, buf_len - off,
+				 "%s ", sense_txt);
+	else
+		off += scnprintf(buffer + off, buf_len - off,
+				 "0x%x ", sshdr->sense_key);
+	off += scnprintf(buffer + off, buf_len - off,
+		scsi_sense_is_deferred(sshdr) ? "[deferred] " : "[current] ");
+
+	if (sshdr->response_code >= 0x72)
+		off += scnprintf(buffer + off, buf_len - off, "[descriptor] ");
+	return off;
+}
+
+static void
+scsi_log_dump_sense(const struct scsi_device *sdev, const char *name, int tag,
+		    const unsigned char *sense_buffer, int sense_len)
+{
+	char *logbuf;
+	size_t logbuf_len;
+	int i;
+
+	logbuf = scsi_log_reserve_buffer(&logbuf_len);
+	if (!logbuf)
+		return;
+
+	for (i = 0; i < sense_len; i += 16) {
+		int len = min(sense_len - i, 16);
+		size_t off;
+
+		off = sdev_format_header(logbuf, logbuf_len,
+					 name, tag);
+		hex_dump_to_buffer(&sense_buffer[i], len, 16, 1,
+				   logbuf + off, logbuf_len - off,
+				   false);
+		dev_printk(KERN_INFO, &sdev->sdev_gendev, logbuf);
+	}
+	scsi_log_release_buffer(logbuf);
+}
+
+static void
+scsi_log_print_sense_hdr(const struct scsi_device *sdev, const char *name,
+			 int tag, const struct scsi_sense_hdr *sshdr)
+{
+	char *logbuf;
+	size_t off, logbuf_len;
+
+	logbuf = scsi_log_reserve_buffer(&logbuf_len);
+	if (!logbuf)
+		return;
+	off = sdev_format_header(logbuf, logbuf_len, name, tag);
+	off += scsi_format_sense_hdr(logbuf + off, logbuf_len - off, sshdr);
+	dev_printk(KERN_INFO, &sdev->sdev_gendev, logbuf);
+	scsi_log_release_buffer(logbuf);
+
+	logbuf = scsi_log_reserve_buffer(&logbuf_len);
+	if (!logbuf)
+		return;
+	off = sdev_format_header(logbuf, logbuf_len, name, tag);
+	off += scsi_format_extd_sense(logbuf + off, logbuf_len - off,
+				      sshdr->asc, sshdr->ascq);
+	dev_printk(KERN_INFO, &sdev->sdev_gendev, logbuf);
+	scsi_log_release_buffer(logbuf);
+}
+
+static void
+scsi_log_print_sense(const struct scsi_device *sdev, const char *name, int tag,
+		     const unsigned char *sense_buffer, int sense_len)
+{
+	struct scsi_sense_hdr sshdr;
+
+	if (scsi_normalize_sense(sense_buffer, sense_len, &sshdr))
+		scsi_log_print_sense_hdr(sdev, name, tag, &sshdr);
+	else
+		scsi_log_dump_sense(sdev, name, tag, sense_buffer, sense_len);
+}
+
+/*
+ * Print normalized SCSI sense header with a prefix.
+ */
+void
+scsi_print_sense_hdr(const struct scsi_device *sdev, const char *name,
+		     const struct scsi_sense_hdr *sshdr)
+{
+	scsi_log_print_sense_hdr(sdev, name, -1, sshdr);
+}
+EXPORT_SYMBOL(scsi_print_sense_hdr);
+
+/* Normalize and print sense buffer with name prefix */
+void __scsi_print_sense(const struct scsi_device *sdev, const char *name,
+			const unsigned char *sense_buffer, int sense_len)
+{
+	scsi_log_print_sense(sdev, name, -1, sense_buffer, sense_len);
+}
+EXPORT_SYMBOL(__scsi_print_sense);
+
+/* Normalize and print sense buffer in SCSI command */
+void scsi_print_sense(const struct scsi_cmnd *cmd)
+{
+	scsi_log_print_sense(cmd->device, scmd_name(cmd), cmd->request->tag,
+			     cmd->sense_buffer, SCSI_SENSE_BUFFERSIZE);
+}
+EXPORT_SYMBOL(scsi_print_sense);
diff --git a/drivers/scsi/sd.c b/drivers/scsi/sd.c
index 3995169..ebf35cb6 100644
--- a/drivers/scsi/sd.c
+++ b/drivers/scsi/sd.c
@@ -3318,11 +3318,8 @@ module_exit(exit_sd);
 static void sd_print_sense_hdr(struct scsi_disk *sdkp,
 			       struct scsi_sense_hdr *sshdr)
 {
-	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);
+	scsi_print_sense_hdr(sdkp->device,
+			     sdkp->disk ? sdkp->disk->disk_name : NULL, sshdr);
 }
 
 static void sd_print_result(const struct scsi_disk *sdkp, const char *msg,
diff --git a/drivers/scsi/ufs/ufshcd.c b/drivers/scsi/ufs/ufshcd.c
index 2e4614b..5d60a86 100644
--- a/drivers/scsi/ufs/ufshcd.c
+++ b/drivers/scsi/ufs/ufshcd.c
@@ -4714,10 +4714,8 @@ static int ufshcd_set_dev_pwr_mode(struct ufs_hba *hba,
 		sdev_printk(KERN_WARNING, sdp,
 			    "START_STOP failed for power mode: %d, result %x\n",
 			    pwr_mode, ret);
-		if (driver_byte(ret) & DRIVER_SENSE) {
-			scsi_show_sense_hdr(sdp, NULL, &sshdr);
-			scsi_show_extd_sense(sdp, NULL, sshdr.asc, sshdr.ascq);
-		}
+		if (driver_byte(ret) & DRIVER_SENSE)
+			scsi_print_sense_hdr(sdp, NULL, &sshdr);
 	}
 
 	if (!ret)
-- 
1.8.4.5

[PATCH 6/9] scsi: use per-cpu buffer for formatting scsi_print_result()

[Hannes Reinecke]

Convert scsi_print_result() to use the per-cpu buffer for
decoding the command result and disposition.

Tested-by: Robert Elliott <elliott@hp.com>
Reviewed-by: Robert Elliott <elliott@hp.com>
Signed-off-by: Hannes Reinecke <hare@suse.de>
---
 drivers/scsi/constants.c    | 22 -----------------
 drivers/scsi/scsi.c         |  2 +-
 drivers/scsi/scsi_logging.c | 59 +++++++++++++++++++++++++++++++++++++++++++++
 include/scsi/scsi_dbg.h     |  2 +-
 4 files changed, 61 insertions(+), 24 deletions(-)

diff --git a/drivers/scsi/constants.c b/drivers/scsi/constants.c
index a23ef75..956fbdd 100644
--- a/drivers/scsi/constants.c
+++ b/drivers/scsi/constants.c
@@ -1316,25 +1316,3 @@ const char *scsi_mlreturn_string(int result)
 	return NULL;
 }
 EXPORT_SYMBOL(scsi_mlreturn_string);
-
-void scsi_print_result(struct scsi_cmnd *cmd, const char *msg, int disposition)
-{
-	const char *mlret_string = scsi_mlreturn_string(disposition);
-	const char *hb_string = scsi_hostbyte_string(cmd->result);
-	const char *db_string = scsi_driverbyte_string(cmd->result);
-
-	if (hb_string || db_string)
-		scmd_printk(KERN_INFO, cmd,
-			    "%s%s Result: hostbyte=%s driverbyte=%s",
-			    msg ? msg : "",
-			    mlret_string ? mlret_string : "UNKNOWN",
-			    hb_string ? hb_string : "invalid",
-			    db_string ? db_string : "invalid");
-	else
-		scmd_printk(KERN_INFO, cmd,
-			    "%s%s Result: hostbyte=0x%02x driverbyte=0x%02x",
-			    msg ? msg : "",
-			    mlret_string ? mlret_string : "UNKNOWN",
-			    host_byte(cmd->result), driver_byte(cmd->result));
-}
-EXPORT_SYMBOL(scsi_print_result);
diff --git a/drivers/scsi/scsi.c b/drivers/scsi/scsi.c
index e028854..7f028cb 100644
--- a/drivers/scsi/scsi.c
+++ b/drivers/scsi/scsi.c
@@ -572,7 +572,7 @@ void scsi_log_completion(struct scsi_cmnd *cmd, int disposition)
 				       SCSI_LOG_MLCOMPLETE_BITS);
 		if (((level > 0) && (cmd->result || disposition != SUCCESS)) ||
 		    (level > 1)) {
-			scsi_print_result(cmd, "Done: ", disposition);
+			scsi_print_result(cmd, "Done", disposition);
 			scsi_print_command(cmd);
 			if (status_byte(cmd->result) & CHECK_CONDITION)
 				scsi_print_sense(cmd);
diff --git a/drivers/scsi/scsi_logging.c b/drivers/scsi/scsi_logging.c
index c7cba31..6128303 100644
--- a/drivers/scsi/scsi_logging.c
+++ b/drivers/scsi/scsi_logging.c
@@ -428,3 +428,62 @@ void scsi_print_sense(const struct scsi_cmnd *cmd)
 			     cmd->sense_buffer, SCSI_SENSE_BUFFERSIZE);
 }
 EXPORT_SYMBOL(scsi_print_sense);
+
+void scsi_print_result(const struct scsi_cmnd *cmd, const char *msg,
+		       int disposition)
+{
+	char *logbuf;
+	size_t off, logbuf_len;
+	const char *mlret_string = scsi_mlreturn_string(disposition);
+	const char *hb_string = scsi_hostbyte_string(cmd->result);
+	const char *db_string = scsi_driverbyte_string(cmd->result);
+
+	logbuf = scsi_log_reserve_buffer(&logbuf_len);
+	if (!logbuf)
+		return;
+
+	off = sdev_format_header(logbuf, logbuf_len,
+				 scmd_name(cmd), cmd->request->tag);
+
+	if (off >= logbuf_len)
+		goto out_printk;
+
+	if (msg) {
+		off += scnprintf(logbuf + off, logbuf_len - off,
+				 "%s: ", msg);
+		if (WARN_ON(off >= logbuf_len))
+			goto out_printk;
+	}
+	if (mlret_string)
+		off += scnprintf(logbuf + off, logbuf_len - off,
+				 "%s ", mlret_string);
+	else
+		off += scnprintf(logbuf + off, logbuf_len - off,
+				 "UNKNOWN(0x%02x) ", disposition);
+	if (WARN_ON(off >= logbuf_len))
+		goto out_printk;
+
+	off += scnprintf(logbuf + off, logbuf_len - off, "Result: ");
+	if (WARN_ON(off >= logbuf_len))
+		goto out_printk;
+
+	if (hb_string)
+		off += scnprintf(logbuf + off, logbuf_len - off,
+				 "hostbyte=%s ", hb_string);
+	else
+		off += scnprintf(logbuf + off, logbuf_len - off,
+				 "hostbyte=0x%02x ", host_byte(cmd->result));
+	if (WARN_ON(off >= logbuf_len))
+		goto out_printk;
+
+	if (db_string)
+		off += scnprintf(logbuf + off, logbuf_len - off,
+				 "driverbyte=%s", db_string);
+	else
+		off += scnprintf(logbuf + off, logbuf_len - off,
+				 "driverbyte=0x%02x", driver_byte(cmd->result));
+out_printk:
+	dev_printk(KERN_INFO, &cmd->device->sdev_gendev, logbuf);
+	scsi_log_release_buffer(logbuf);
+}
+EXPORT_SYMBOL(scsi_print_result);
diff --git a/include/scsi/scsi_dbg.h b/include/scsi/scsi_dbg.h
index c7ed7b8..365b674 100644
--- a/include/scsi/scsi_dbg.h
+++ b/include/scsi/scsi_dbg.h
@@ -21,7 +21,7 @@ extern void scsi_print_sense(const struct scsi_cmnd *);
 extern void __scsi_print_sense(const struct scsi_device *, const char *name,
 			       const unsigned char *sense_buffer,
 			       int sense_len);
-extern void scsi_print_result(struct scsi_cmnd *, const char *, int);
+extern void scsi_print_result(const struct scsi_cmnd *, const char *, int);
 extern const char *scsi_hostbyte_string(int);
 extern const char *scsi_driverbyte_string(int);
 extern const char *scsi_mlreturn_string(int);
-- 
1.8.4.5

[PATCH 7/9] scsi: Conditionally compile in constants.c

[Hannes Reinecke]

Instead of having constants.c littered with ifdef statements
we should be moving dummy functions into the header and
condintionally compile in constants.c if selected.
And update the Kconfig description to reflect the
actual size difference.

Suggested-by: Christoph Hellwig <hch@infradead.org>
Tested-by: Robert Elliott <elliott@hp.com>
Reviewed-by: Christoph Hellwig <hch@lst.de>
Reviewed-by: Robert Elliott <elliott@hp.com>
Signed-off-by: Hannes Reinecke <hare@suse.de>
---
 drivers/scsi/Kconfig       |  4 +--
 drivers/scsi/Makefile      |  4 +--
 drivers/scsi/constants.c   | 44 ------------------------------
 drivers/xen/xen-scsiback.c |  1 +
 include/scsi/scsi_dbg.h    | 68 +++++++++++++++++++++++++++++++++++++++++++---
 5 files changed, 69 insertions(+), 52 deletions(-)

diff --git a/drivers/scsi/Kconfig b/drivers/scsi/Kconfig
index 9c92f41..b021bcb 100644
--- a/drivers/scsi/Kconfig
+++ b/drivers/scsi/Kconfig
@@ -201,12 +201,12 @@ config SCSI_ENCLOSURE
 	  certain enclosure conditions to be reported and is not required.
 
 config SCSI_CONSTANTS
-	bool "Verbose SCSI error reporting (kernel size +=12K)"
+	bool "Verbose SCSI error reporting (kernel size +=75K)"
 	depends on SCSI
 	help
 	  The error messages regarding your SCSI hardware will be easier to
 	  understand if you say Y here; it will enlarge your kernel by about
-	  12 KB. If in doubt, say Y.
+	  75 KB. If in doubt, say Y.
 
 config SCSI_LOGGING
 	bool "SCSI logging facility"
diff --git a/drivers/scsi/Makefile b/drivers/scsi/Makefile
index 447c2d2..dee160a 100644
--- a/drivers/scsi/Makefile
+++ b/drivers/scsi/Makefile
@@ -159,9 +159,9 @@ obj-$(CONFIG_SCSI_OSD_INITIATOR) += osd/
 
 # This goes last, so that "real" scsi devices probe earlier
 obj-$(CONFIG_SCSI_DEBUG)	+= scsi_debug.o
-
-scsi_mod-y			+= scsi.o hosts.o scsi_ioctl.o constants.o \
+scsi_mod-y			+= scsi.o hosts.o scsi_ioctl.o \
 				   scsicam.o scsi_error.o scsi_lib.o
+scsi_mod-$(CONFIG_SCSI_CONSTANTS) += constants.o
 scsi_mod-$(CONFIG_SCSI_DMA)	+= scsi_lib_dma.o
 scsi_mod-y			+= scsi_scan.o scsi_sysfs.o scsi_devinfo.o
 scsi_mod-$(CONFIG_SCSI_NETLINK)	+= scsi_netlink.o
diff --git a/drivers/scsi/constants.c b/drivers/scsi/constants.c
index 956fbdd..fa09d4b 100644
--- a/drivers/scsi/constants.c
+++ b/drivers/scsi/constants.c
@@ -18,8 +18,6 @@
 #include <scsi/scsi_eh.h>
 #include <scsi/scsi_dbg.h>
 
-
-
 /* Commands with service actions that change the command name */
 #define THIRD_PARTY_COPY_OUT 0x83
 #define THIRD_PARTY_COPY_IN 0x84
@@ -35,7 +33,6 @@ struct value_name_pair {
 	const char * name;
 };
 
-#ifdef CONFIG_SCSI_CONSTANTS
 static const char * cdb_byte0_names[] = {
 /* 00-03 */ "Test Unit Ready", "Rezero Unit/Rewind", NULL, "Request Sense",
 /* 04-07 */ "Format Unit/Medium", "Read Block Limits", NULL,
@@ -259,26 +256,6 @@ static struct sa_name_list sa_names_arr[] = {
 	{0, NULL, 0},
 };
 
-#else /* ifndef CONFIG_SCSI_CONSTANTS */
-static const char *cdb_byte0_names[0];
-
-static struct sa_name_list sa_names_arr[] = {
-	{VARIABLE_LENGTH_CMD, NULL, 0},
-	{MAINTENANCE_IN, NULL, 0},
-	{MAINTENANCE_OUT, NULL, 0},
-	{PERSISTENT_RESERVE_IN, NULL, 0},
-	{PERSISTENT_RESERVE_OUT, NULL, 0},
-	{SERVICE_ACTION_IN_12, NULL, 0},
-	{SERVICE_ACTION_OUT_12, NULL, 0},
-	{SERVICE_ACTION_BIDIRECTIONAL, NULL, 0},
-	{SERVICE_ACTION_IN_16, NULL, 0},
-	{SERVICE_ACTION_OUT_16, NULL, 0},
-	{THIRD_PARTY_COPY_IN, NULL, 0},
-	{THIRD_PARTY_COPY_OUT, NULL, 0},
-	{0, NULL, 0},
-};
-#endif /* CONFIG_SCSI_CONSTANTS */
-
 bool scsi_opcode_sa_name(int opcode, int service_action,
 			 const char **cdb_name, const char **sa_name)
 {
@@ -313,8 +290,6 @@ bool scsi_opcode_sa_name(int opcode, int service_action,
 	return true;
 }
 
-#ifdef CONFIG_SCSI_CONSTANTS
-
 struct error_info {
 	unsigned short code12;	/* 0x0302 looks better than 0x03,0x02 */
 	const char * text;
@@ -1203,15 +1178,12 @@ static const char * const snstext[] = {
 	"Completed",	    /* F: command completed sense data reported,
 				  may occur for successful command */
 };
-#endif
 
 /* Get sense key string or NULL if not available */
 const char *
 scsi_sense_key_string(unsigned char key) {
-#ifdef CONFIG_SCSI_CONSTANTS
 	if (key <= 0xE)
 		return snstext[key];
-#endif
 	return NULL;
 }
 EXPORT_SYMBOL(scsi_sense_key_string);
@@ -1223,7 +1195,6 @@ EXPORT_SYMBOL(scsi_sense_key_string);
 const char *
 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);
 
@@ -1239,15 +1210,10 @@ scsi_extd_sense_format(unsigned char asc, unsigned char ascq, const char **fmt)
 			return additional2[i].str;
 		}
 	}
-#else
-	*fmt = NULL;
-#endif
 	return NULL;
 }
 EXPORT_SYMBOL(scsi_extd_sense_format);
 
-#ifdef CONFIG_SCSI_CONSTANTS
-
 static const char * const hostbyte_table[]={
 "DID_OK", "DID_NO_CONNECT", "DID_BUS_BUSY", "DID_TIME_OUT", "DID_BAD_TARGET",
 "DID_ABORT", "DID_PARITY", "DID_ERROR", "DID_RESET", "DID_BAD_INTR",
@@ -1259,17 +1225,13 @@ static const char * const driverbyte_table[]={
 "DRIVER_OK", "DRIVER_BUSY", "DRIVER_SOFT",  "DRIVER_MEDIA", "DRIVER_ERROR",
 "DRIVER_INVALID", "DRIVER_TIMEOUT", "DRIVER_HARD", "DRIVER_SENSE"};
 
-#endif
-
 const char *scsi_hostbyte_string(int result)
 {
 	const char *hb_string = NULL;
-#ifdef CONFIG_SCSI_CONSTANTS
 	int hb = host_byte(result);
 
 	if (hb < ARRAY_SIZE(hostbyte_table))
 		hb_string = hostbyte_table[hb];
-#endif
 	return hb_string;
 }
 EXPORT_SYMBOL(scsi_hostbyte_string);
@@ -1277,17 +1239,14 @@ EXPORT_SYMBOL(scsi_hostbyte_string);
 const char *scsi_driverbyte_string(int result)
 {
 	const char *db_string = NULL;
-#ifdef CONFIG_SCSI_CONSTANTS
 	int db = driver_byte(result);
 
 	if (db < ARRAY_SIZE(driverbyte_table))
 		db_string = driverbyte_table[db];
-#endif
 	return db_string;
 }
 EXPORT_SYMBOL(scsi_driverbyte_string);
 
-#ifdef CONFIG_SCSI_CONSTANTS
 #define scsi_mlreturn_name(result)	{ result, #result }
 static const struct value_name_pair scsi_mlreturn_arr[] = {
 	scsi_mlreturn_name(NEEDS_RETRY),
@@ -1300,11 +1259,9 @@ static const struct value_name_pair scsi_mlreturn_arr[] = {
 	scsi_mlreturn_name(SCSI_RETURN_NOT_HANDLED),
 	scsi_mlreturn_name(FAST_IO_FAIL)
 };
-#endif
 
 const char *scsi_mlreturn_string(int result)
 {
-#ifdef CONFIG_SCSI_CONSTANTS
 	const struct value_name_pair *arr = scsi_mlreturn_arr;
 	int k;
 
@@ -1312,7 +1269,6 @@ const char *scsi_mlreturn_string(int result)
 		if (result == arr->value)
 			return arr->name;
 	}
-#endif
 	return NULL;
 }
 EXPORT_SYMBOL(scsi_mlreturn_string);
diff --git a/drivers/xen/xen-scsiback.c b/drivers/xen/xen-scsiback.c
index e999496e..471ab06 100644
--- a/drivers/xen/xen-scsiback.c
+++ b/drivers/xen/xen-scsiback.c
@@ -47,6 +47,7 @@
 
 #include <generated/utsrelease.h>
 
+#include <scsi/scsi.h>
 #include <scsi/scsi_dbg.h>
 #include <scsi/scsi_eh.h>
 #include <scsi/scsi_tcq.h>
diff --git a/include/scsi/scsi_dbg.h b/include/scsi/scsi_dbg.h
index 365b674..f8170e9 100644
--- a/include/scsi/scsi_dbg.h
+++ b/include/scsi/scsi_dbg.h
@@ -7,7 +7,6 @@ struct scsi_sense_hdr;
 
 #define SCSI_LOG_BUFSIZE 128
 
-extern bool scsi_opcode_sa_name(int, int, const char **, const char **);
 extern void scsi_print_command(struct scsi_cmnd *);
 extern size_t __scsi_format_command(char *, size_t,
 				   const unsigned char *, size_t);
@@ -22,11 +21,72 @@ extern void __scsi_print_sense(const struct scsi_device *, const char *name,
 			       const unsigned char *sense_buffer,
 			       int sense_len);
 extern void scsi_print_result(const struct scsi_cmnd *, const char *, int);
-extern const char *scsi_hostbyte_string(int);
-extern const char *scsi_driverbyte_string(int);
-extern const char *scsi_mlreturn_string(int);
+
+#ifdef CONFIG_SCSI_CONSTANTS
+extern bool scsi_opcode_sa_name(int, int, const char **, const 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_mlreturn_string(int);
+extern const char *scsi_hostbyte_string(int);
+extern const char *scsi_driverbyte_string(int);
+#else
+static inline bool
+scsi_opcode_sa_name(int cmd, int sa,
+		    const char **cdb_name, const char **sa_name)
+{
+	*cdb_name = NULL;
+	switch (cmd) {
+	case VARIABLE_LENGTH_CMD:
+	case MAINTENANCE_IN:
+	case MAINTENANCE_OUT:
+	case PERSISTENT_RESERVE_IN:
+	case PERSISTENT_RESERVE_OUT:
+	case SERVICE_ACTION_IN_12:
+	case SERVICE_ACTION_OUT_12:
+	case SERVICE_ACTION_BIDIRECTIONAL:
+	case SERVICE_ACTION_IN_16:
+	case SERVICE_ACTION_OUT_16:
+	case EXTENDED_COPY:
+	case RECEIVE_COPY_RESULTS:
+		*sa_name = NULL;
+		return true;
+	default:
+		return false;
+	}
+}
+
+static inline const char *
+scsi_sense_key_string(unsigned char key)
+{
+	return NULL;
+}
+
+static inline const char *
+scsi_extd_sense_format(unsigned char asc, unsigned char ascq, const char **fmt)
+{
+	*fmt = NULL;
+	return NULL;
+}
+
+static inline const char *
+scsi_mlreturn_string(int result)
+{
+	return NULL;
+}
+
+static inline const char *
+scsi_hostbyte_string(int result)
+{
+	return NULL;
+}
+
+static inline const char *
+scsi_driverbyte_string(int result)
+{
+	return NULL;
+}
+
+#endif
 
 #endif /* _SCSI_SCSI_DBG_H */
-- 
1.8.4.5

[PATCH 8/9] scsi: Do not display buffer pointers in scsi_log_send()

[Hannes Reinecke]

scsi_log_send() would display buffer pointer for higher
logging levels. This is not only of questionable value
but also exposes kernel pointer to userspace, which is
discouraged in some setups. So drop this message
altogether.

Tested-by: Robert Elliott <elliott@hp.com>
Reviewed-by: Robert Elliott <elliott@hp.com>
Signed-off-by: Hannes Reinecke <hare@suse.de>
---
 drivers/scsi/scsi.c | 9 +--------
 1 file changed, 1 insertion(+), 8 deletions(-)

diff --git a/drivers/scsi/scsi.c b/drivers/scsi/scsi.c
index 7f028cb..08c90a7 100644
--- a/drivers/scsi/scsi.c
+++ b/drivers/scsi/scsi.c
@@ -531,7 +531,7 @@ void scsi_log_send(struct scsi_cmnd *cmd)
 	 *
 	 * 3: same as 2
 	 *
-	 * 4: same as 3 plus dump extra junk
+	 * 4: same as 3
 	 */
 	if (unlikely(scsi_logging_level)) {
 		level = SCSI_LOG_LEVEL(SCSI_LOG_MLQUEUE_SHIFT,
@@ -540,13 +540,6 @@ void scsi_log_send(struct scsi_cmnd *cmd)
 			scmd_printk(KERN_INFO, cmd,
 				    "Send: scmd 0x%p\n", cmd);
 			scsi_print_command(cmd);
-			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);
-
-			}
 		}
 	}
 }
-- 
1.8.4.5

[PATCH 9/9] scsi_error: do not display kernel pointer in message logs

[Hannes Reinecke]

It is not good practice to display the kernel pointer
in any message logs, and it doesn't display any additional
information. And as we know have block-layer assigned tags
we can use them to differentiate the messages.
So remove any pointer references from the displayed messages.

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

diff --git a/drivers/scsi/scsi_error.c b/drivers/scsi/scsi_error.c
index e42fff6..10ffa21 100644
--- a/drivers/scsi/scsi_error.c
+++ b/drivers/scsi/scsi_error.c
@@ -124,41 +124,37 @@ 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));
+				    "eh timeout, not aborting\n"));
 	} else {
 		SCSI_LOG_ERROR_RECOVERY(3,
 			scmd_printk(KERN_INFO, scmd,
-				    "aborting command %p\n", scmd));
+				    "aborting command\n"));
 		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, "
-						    "not retrying aborted "
-						    "command\n", scmd));
+						    "eh timeout, not retrying "
+						    "aborted command\n"));
 			} else if (!scsi_noretry_cmd(scmd) &&
 			    (++scmd->retries <= scmd->allowed)) {
 				SCSI_LOG_ERROR_RECOVERY(3,
 					scmd_printk(KERN_WARNING, scmd,
-						    "scmd %p retry "
-						    "aborted command\n", scmd));
+						    "retry aborted command\n"));
 				scsi_queue_insert(scmd, SCSI_MLQUEUE_EH_RETRY);
 				return;
 			} else {
 				SCSI_LOG_ERROR_RECOVERY(3,
 					scmd_printk(KERN_WARNING, scmd,
-						    "scmd %p finish "
-						    "aborted command\n", scmd));
+						    "finish aborted command\n"));
 				scsi_finish_command(scmd);
 				return;
 			}
 		} else {
 			SCSI_LOG_ERROR_RECOVERY(3,
 				scmd_printk(KERN_INFO, scmd,
-					    "scmd %p abort %s\n", scmd,
+					    "cmd abort %s\n",
 					    (rtn == FAST_IO_FAIL) ?
 					    "not send" : "failed"));
 		}
@@ -167,8 +163,7 @@ scmd_eh_abort_handler(struct work_struct *work)
 	if (!scsi_eh_scmd_add(scmd, 0)) {
 		SCSI_LOG_ERROR_RECOVERY(3,
 			scmd_printk(KERN_WARNING, scmd,
-				    "scmd %p terminate "
-				    "aborted command\n", scmd));
+				    "terminate aborted command\n"));
 		set_host_byte(scmd, DID_TIME_OUT);
 		scsi_finish_command(scmd);
 	}
@@ -194,7 +189,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 previous abort failed\n", scmd));
+				    "previous abort failed\n"));
 		BUG_ON(delayed_work_pending(&scmd->abort_work));
 		return FAILED;
 	}
@@ -208,8 +203,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));
+				    "not aborting, host in recovery\n"));
 		return FAILED;
 	}
 
@@ -219,8 +213,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_printk(KERN_INFO, scmd, "abort scheduled\n"));
 	queue_delayed_work(shost->tmf_work_q, &scmd->abort_work, HZ / 100);
 	return SUCCESS;
 }
@@ -737,8 +730,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",
-			__func__, scmd, scmd->result));
+			"%s result: %x\n", __func__, scmd->result));
 
 	eh_action = scmd->device->host->eh_action;
 	if (eh_action)
@@ -1052,8 +1044,8 @@ retry:
 	scsi_log_completion(scmd, rtn);
 
 	SCSI_LOG_ERROR_RECOVERY(3, scmd_printk(KERN_INFO, scmd,
-			"%s: scmd: %p, timeleft: %ld\n",
-			__func__, scmd, timeleft));
+			"%s timeleft: %ld\n",
+			__func__, timeleft));
 
 	/*
 	 * If there is time left scsi_eh_done got called, and we will examine
@@ -1192,8 +1184,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",
-			scmd, scmd->result));
+			"sense requested, result %x\n", scmd->result));
 		SCSI_LOG_ERROR_RECOVERY(3, scsi_print_sense(scmd));
 
 		rtn = scsi_decide_disposition(scmd);
@@ -1235,7 +1226,7 @@ retry_tur:
 				scmd->device->eh_timeout, 0);
 
 	SCSI_LOG_ERROR_RECOVERY(3, scmd_printk(KERN_INFO, scmd,
-		"%s: scmd %p rtn %x\n", __func__, scmd, rtn));
+		"%s return: %x\n", __func__, rtn));
 
 	switch (rtn) {
 	case NEEDS_RETRY:
@@ -2092,8 +2083,8 @@ 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",
-					     current->comm, scmd));
+					     "%s: flush retry cmd\n",
+					     current->comm));
 				scsi_queue_insert(scmd, SCSI_MLQUEUE_EH_RETRY);
 		} else {
 			/*
@@ -2105,8 +2096,8 @@ 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",
-					     current->comm, scmd));
+					     "%s: flush finish cmd\n",
+					     current->comm));
 			scsi_finish_command(scmd);
 		}
 	}
-- 
1.8.4.5

Re: [PATCHv4 0/9] scsi logging update: the real thing

[Christoph Hellwig]

Thanks, I've applied patches 1 to 8 to scsi-for-3.20.  The last one
still needs a review.

RE: [PATCH 9/9] scsi_error: do not display kernel pointer in message logs

[Elliott, Robert (Server Storage)]

> -----Original Message-----
> From: linux-scsi-owner@vger.kernel.org [mailto:linux-scsi-
> owner@vger.kernel.org] On Behalf Of Hannes Reinecke
> Sent: Thursday, January 08, 2015 12:44 AM
> To: James Bottomley
> Cc: Christoph Hellwig; linux-scsi@vger.kernel.org; Hannes Reinecke
> Subject: [PATCH 9/9] scsi_error: do not display kernel pointer in
> message logs
> 
> It is not good practice to display the kernel pointer
> in any message logs, and it doesn't display any additional
> information. And as we know have block-layer assigned tags
> we can use them to differentiate the messages.
> So remove any pointer references from the displayed messages.
> 
> Signed-off-by: Hannes Reinecke <hare@suse.de>
> ---
>  drivers/scsi/scsi_error.c | 49 +++++++++++++++++++---------------------
> -------
>  1 file changed, 20 insertions(+), 29 deletions(-)
> 
> diff --git a/drivers/scsi/scsi_error.c b/drivers/scsi/scsi_error.c
> index e42fff6..10ffa21 100644
> --- a/drivers/scsi/scsi_error.c
> +++ b/drivers/scsi/scsi_error.c
> @@ -124,41 +124,37 @@ scmd_eh_abort_handler(struct work_struct *work)
...
>  				SCSI_LOG_ERROR_RECOVERY(3,
>  					scmd_printk(KERN_INFO, scmd,
> -						    "scmd %p eh timeout, "
> -						    "not retrying aborted "
> -						    "command\n", scmd));
> +						    "eh timeout, not retrying "
> +						    "aborted command\n"));

checkpatch allows/encourages keeping strings on one line even when
they go past the 80th column.  So, I recommend joining those two
lines.

Reviewed-by: Robert Elliott <elliott@hp.com>

Re: [PATCH 9/9] scsi_error: do not display kernel pointer in message logs

[Douglas Gilbert]

On 15-01-10 02:17 PM, Elliott, Robert (Server Storage) wrote:
>
>
>> -----Original Message-----
>> From: linux-scsi-owner@vger.kernel.org [mailto:linux-scsi-
>> owner@vger.kernel.org] On Behalf Of Hannes Reinecke
>> Sent: Thursday, January 08, 2015 12:44 AM
>> To: James Bottomley
>> Cc: Christoph Hellwig; linux-scsi@vger.kernel.org; Hannes Reinecke
>> Subject: [PATCH 9/9] scsi_error: do not display kernel pointer in
>> message logs
>>
>> It is not good practice to display the kernel pointer
>> in any message logs, and it doesn't display any additional
>> information. And as we know have block-layer assigned tags
>> we can use them to differentiate the messages.
>> So remove any pointer references from the displayed messages.
>>
>> Signed-off-by: Hannes Reinecke <hare@suse.de>
>> ---
>>   drivers/scsi/scsi_error.c | 49 +++++++++++++++++++---------------------
>> -------
>>   1 file changed, 20 insertions(+), 29 deletions(-)
>>
>> diff --git a/drivers/scsi/scsi_error.c b/drivers/scsi/scsi_error.c
>> index e42fff6..10ffa21 100644
>> --- a/drivers/scsi/scsi_error.c
>> +++ b/drivers/scsi/scsi_error.c
>> @@ -124,41 +124,37 @@ scmd_eh_abort_handler(struct work_struct *work)
> ...
>>   				SCSI_LOG_ERROR_RECOVERY(3,
>>   					scmd_printk(KERN_INFO, scmd,
>> -						    "scmd %p eh timeout, "
>> -						    "not retrying aborted "
>> -						    "command\n", scmd));
>> +						    "eh timeout, not retrying "
>> +						    "aborted command\n"));
>
> checkpatch allows/encourages keeping strings on one line even when
> they go past the 80th column.  So, I recommend joining those two
> lines.

Which in turn conflicts with cleanfile which is another kernel
supplied utility. So I would suggest checkpatch should back off
with that particular warning (and several other of its nags).
Also new code (say a complete new function) should be treated
differently compared to a patch (e.g. the 2 lines shown above)
on existing code.

I use cleanfile in the user space since it warns of lines
greater than 79 characters and trims trailing spaces
(whitespaces ?) from the end of a line. And I would never use
checkpatch in the user space since the coherence of the
resulting source is much more important than the route to
get there :-)

Doug Gilbert

Re: [PATCH 9/9] scsi_error: do not display kernel pointer in message logs

[Ewan Milne]

On Thu, 2015-01-08 at 07:43 +0100, Hannes Reinecke wrote:
> It is not good practice to display the kernel pointer
> in any message logs, and it doesn't display any additional
> information. And as we know have block-layer assigned tags
> we can use them to differentiate the messages.
> So remove any pointer references from the displayed messages.
> 

I'd actually be sad to see this go -- I have found it useful
in the past when debugging crash dumps from customer sites
to be able to look in the kernel messages and see that a
particular scsi_cmnd had been aborted just before the crash
(and then later completed).

-Ewan

Re: [PATCH 9/9] scsi_error: do not display kernel pointer in message logs

[Hannes Reinecke]

On 01/12/2015 02:12 PM, Ewan Milne wrote:
> On Thu, 2015-01-08 at 07:43 +0100, Hannes Reinecke wrote:
>> It is not good practice to display the kernel pointer
>> in any message logs, and it doesn't display any additional
>> information. And as we know have block-layer assigned tags
>> we can use them to differentiate the messages.
>> So remove any pointer references from the displayed messages.
>>
> 
> I'd actually be sad to see this go -- I have found it useful
> in the past when debugging crash dumps from customer sites
> to be able to look in the kernel messages and see that a
> particular scsi_cmnd had been aborted just before the crash
> (and then later completed).
> 
But that's precisely why we've prefixed the scmd messages with the
tag number; with that you'll be able to extract the same information.

And now that hch separated out the block layer tagging from SCSI-2
TCQ we should have the tag number available for any command, not
just those from drivers which use TCQ.

Let me know if that isn't the case; this patch indeed only makes
sense if the tag number is always available.

Cheers,

Hannes
-- 
Dr. Hannes Reinecke		               zSeries & Storage
hare@suse.de			               +49 911 74053 688
SUSE LINUX GmbH, Maxfeldstr. 5, 90409 Nürnberg
GF: F. Imendörffer, J. Smithard, J. Guild, D. Upmanyu, G. Norton
HRB 21284 (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 9/9] scsi_error: do not display kernel pointer in message logs

[Ewan Milne]

On Mon, 2015-01-12 at 14:29 +0100, Hannes Reinecke wrote:
> On 01/12/2015 02:12 PM, Ewan Milne wrote:
> > On Thu, 2015-01-08 at 07:43 +0100, Hannes Reinecke wrote:
> >> It is not good practice to display the kernel pointer
> >> in any message logs, and it doesn't display any additional
> >> information. And as we know have block-layer assigned tags
> >> we can use them to differentiate the messages.
> >> So remove any pointer references from the displayed messages.
> >>
> > 
> > I'd actually be sad to see this go -- I have found it useful
> > in the past when debugging crash dumps from customer sites
> > to be able to look in the kernel messages and see that a
> > particular scsi_cmnd had been aborted just before the crash
> > (and then later completed).
> > 
> But that's precisely why we've prefixed the scmd messages with the
> tag number; with that you'll be able to extract the same information.
> 
> And now that hch separated out the block layer tagging from SCSI-2
> TCQ we should have the tag number available for any command, not
> just those from drivers which use TCQ.
> 
> Let me know if that isn't the case; this patch indeed only makes
> sense if the tag number is always available.

Ah, yes, I think you may be right -- I ran into this when debugging some
double completion panics, so my concern is whether the tag field
remains valid after it completes the first time.  I'll check.

-Ewan

Re: [PATCH 9/9] scsi_error: do not display kernel pointer in message logs

[Ewan Milne]

On Mon, 2015-01-12 at 09:57 -0500, Ewan Milne wrote:
> On Mon, 2015-01-12 at 14:29 +0100, Hannes Reinecke wrote:
> > On 01/12/2015 02:12 PM, Ewan Milne wrote:
> > > On Thu, 2015-01-08 at 07:43 +0100, Hannes Reinecke wrote:
> > >> It is not good practice to display the kernel pointer
> > >> in any message logs, and it doesn't display any additional
> > >> information. And as we know have block-layer assigned tags
> > >> we can use them to differentiate the messages.
> > >> So remove any pointer references from the displayed messages.
> > >>
> > > 
> > > I'd actually be sad to see this go -- I have found it useful
> > > in the past when debugging crash dumps from customer sites
> > > to be able to look in the kernel messages and see that a
> > > particular scsi_cmnd had been aborted just before the crash
> > > (and then later completed).
> > > 
> > But that's precisely why we've prefixed the scmd messages with the
> > tag number; with that you'll be able to extract the same information.
> > 
> > And now that hch separated out the block layer tagging from SCSI-2
> > TCQ we should have the tag number available for any command, not
> > just those from drivers which use TCQ.
> > 
> > Let me know if that isn't the case; this patch indeed only makes
> > sense if the tag number is always available.
> 
> Ah, yes, I think you may be right -- I ran into this when debugging some
> double completion panics, so my concern is whether the tag field
> remains valid after it completes the first time.  I'll check.

Looks like if the scmd completes twice, the req could be getting reused,
so scmd->request->tag might be different.  However, for crash analysis,
scmd->tag gets a copy of the request tag so that would be good enough
to match up with an earlier logged abort message.

Reviewed-by: Ewan D. Milne <emilne@redhat.com>

Re: [PATCH 1/9] scsi: Implement per-cpu logging buffer

[James Bottomley]

On Thu, 2015-01-08 at 07:43 +0100, Hannes Reinecke wrote:
> -	sdev_printk(prefix, (scmd)->device, fmt, ##a)
> +extern int sdev_prefix_printk(const char *, const struct scsi_device *,
> +			      const char *, const char *, ...);
> +
> +#define sdev_printk(l, sdev, fmt, a...)				\
> +	sdev_prefix_printk(l, sdev, NULL, fmt, ##a)
> +
> +extern int scmd_printk(const char *, const struct scsi_cmnd *,
> +		       const char *, ...);
>  
>  #define scmd_dbg(scmd, fmt, a...)					   \
>  	do {								   \

These new prototypes need to be printf format checked, otherwise you
lose us some type checking that gcc was doing:

extern __printf(4, 5)
int sdev_prefix_printk(const char *, const struct scsi_device *,
		      const char *, const char *, ...);

James

Re: [PATCH 3/9] scsi: use external buffer for command logging

[James Bottomley]

On Thu, 2015-01-08 at 07:43 +0100, Hannes Reinecke wrote:
> Use an external buffer for __scsi_print_command() and
> move command logging over to use the per-cpu logging
> buffer. With that we can guarantee the command always
> will always be formatted in one line.
> So we can even print out a variable length command
> correctly across several lines.
> Finally rename __scsi_print_command() to
> __scsi_format_comment() to better reflect the
> functionality.
> 
> Tested-by: Robert Elliott <elliott@hp.com>
> Reviewed-by: Robert Elliott <elliott@hp.com>
> Reviewed-by: Christoph Hellwig <hch@lst.de>
> Signed-off-by: Hannes Reinecke <hare@suse.de>
> ---
>  drivers/scsi/ch.c           |   6 +-
>  drivers/scsi/constants.c    |  74 +-----------------
>  drivers/scsi/scsi_logging.c | 182 ++++++++++++++++++++++++++++++++++++++++----
>  drivers/scsi/sr_ioctl.c     |  13 +++-
>  include/scsi/scsi.h         |   3 +
>  include/scsi/scsi_dbg.h     |   6 +-
>  6 files changed, 192 insertions(+), 92 deletions(-)
> 
> diff --git a/drivers/scsi/ch.c b/drivers/scsi/ch.c
> index 6bac8a7..79e462f 100644
> --- a/drivers/scsi/ch.c
> +++ b/drivers/scsi/ch.c
> @@ -195,8 +195,10 @@ ch_do_scsi(scsi_changer *ch, unsigned char *cmd, int cmd_len,
>   retry:
>  	errno = 0;
>  	if (debug) {
> -		DPRINTK("command: ");
> -		__scsi_print_command(cmd, cmd_len);
> +		char logbuf[SCSI_LOG_BUFSIZE];
> +
> +		__scsi_format_command(logbuf, sizeof(logbuf), cmd, cmd_len);
> +		DPRINTK("command: %s", logbuf);

I really hate using an on-stack buffer here ... we're pretty deep in the
call chain already.

Since it's just required for printing a "command: " prefix, why not just
use scsi_print_command()?


> diff --git a/drivers/scsi/sr_ioctl.c b/drivers/scsi/sr_ioctl.c
> index fb929fa..e8deb9c 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[SCSI_LOG_BUFSIZE];

Same issue here.

>         SDev = cd->device;
>  
> @@ -257,14 +258,20 @@ 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, CDROM_PACKET_SIZE);
> +                       __scsi_format_command(logbuf, sizeof(logbuf),
> +                                             cgc->cmd, CDROM_PACKET_SIZE);
> +                       sr_printk(KERN_INFO, cd,
> +                                 "CDROM (ioctl) invalid command: %s\n",
> +                                 logbuf);

Looks like scsi_print_command() will work here too.

>                         scsi_print_sense_hdr(cd->device, cd->cdi.name, &sshdr);
>  #endif
>                         break;
>                 default:
> +                       __scsi_format_command(logbuf, sizeof(logbuf),
> +                                             cgc->cmd, CDROM_PACKET_SIZE);
>                         sr_printk(KERN_ERR, cd,
> -                                 "CDROM (ioctl) error, command: ");
> -                       __scsi_print_command(cgc->cmd, CDROM_PACKET_SIZE);
> +                                 "CDROM (ioctl) error, command: %s\n",
> +                                 logbuf);

And realistically here (with the appropriate sdev_print()'s preceding).

>                         scsi_print_sense_hdr(cd->device, cd->cdi.name, &sshdr);
>                         err = -EIO;
>                 }

James

Re: [PATCH 3/9] scsi: use external buffer for command logging

[hch]

On Tue, Jan 13, 2015 at 06:56:17PM +0000, James Bottomley wrote:
> I really hate using an on-stack buffer here ... we're pretty deep in the
> call chain already.
> 
> Since it's just required for printing a "command: " prefix, why not just
> use scsi_print_command()?

Both the ch and sr callers are not really a problem in terms of stack
usage, as they are directly in file operations of character or block
devices, so the whole FS/MM stack stack problem isn't an issue.

But using higher level functions might still be useful here.

Re: [PATCH 3/9] scsi: use external buffer for command logging

[James Bottomley]

On Wed, 2015-01-14 at 10:36 +0100, hch@lst.de wrote:
> On Tue, Jan 13, 2015 at 06:56:17PM +0000, James Bottomley wrote:
> > I really hate using an on-stack buffer here ... we're pretty deep in the
> > call chain already.
> > 
> > Since it's just required for printing a "command: " prefix, why not just
> > use scsi_print_command()?
> 
> Both the ch and sr callers are not really a problem in terms of stack
> usage, as they are directly in file operations of character or block
> devices, so the whole FS/MM stack stack problem isn't an issue.

Trying to calculate minutely how much additional overhead there is isn't
really the point.  The point is we can just use a different function
that doesn't consume the on stack buffer, so we should, just as a matter
of best practise.  I agree it would have been a more finely balanced
problem if we definitely needed the allocation

> But using higher level functions might still be useful here.

James