Skip to contentSkip to conversation

scsi: avoid linebreaks in syslog output

PATCH In review Hannes Reinecke 4 participants 17 messages Oct 12, 2012 – Dec 20, 2013

Subsystems (2)
lore
Share & tools
lore
#0 lore raw

cover scsi: avoid linebreaks in syslog output

This patchset updates the SCSI midlayer to use dev_printk() instead of the simple printk(). The main objective here is to avoid line-breaks in syslog output; with the current state it's nearly impossible to match the output to the occurring device; under high load even the CDB will be split off into individual bytes, spread randomly across the lines. Which makes debugging via scsi_logging_level _really_ hard. In addition we'll be getting the syslog messages nicely prefixed with the device, which will make userspace logging daemons happy.

Before:

[  297.300605] sd 2:0:3:2: Send: 
[  297.300607] 0xffff8802348b0980 
[  297.300610] sd 2:0:3:2: CDB: 
[  297.300615] Test Unit Ready: 00 00 00 00 00 00
[  297.300747] sd 2:0:3:2: Done: 
[  297.300750] 0xffff8802348b0980 SUCCESS
[  297.300753] sd 2:0:3:2:  
[  297.300755] Result: hostbyte=DID_OK driverbyte=DRIVER_OK
[  297.300758] sd 2:0:3:2: CDB: 
[  297.300764] Test Unit Ready: 00 00 00 00 00 00
[  297.300766] sd 2:0:3:2:  
[  297.300769] Sense Key : Unit Attention [current] 
[  297.300771] Info fld=0x0
[  297.300772] sd 2:0:3:2:  
[  297.300776] Add. Sense: Capacity data has changed

After:

[  636.683556] sd 2:0:3:2: Send: 0xffff88043145eec0
[  636.727856] sd 2:0:3:2: CDB: Test Unit Ready: 00 00 00 00 00 00
[  636.785330] sd 2:0:3:2: Done: 0xffff88043145eec0 SUCCESS
[  636.838228] sd 2:0:3:2: Result: hostbyte=DID_OK driverbyte=DRIVER_OK
[  636.899099] sd 2:0:3:2: CDB: Test Unit Ready: 00 00 00 00 00 00
[  636.955905] sd 2:0:3:2: Sense Key : Unit Attention [current] 
[  637.069179] sd 2:0:3:2: Add. Sense: Capacity data has changed

Hannes Reinecke (10):
sg: Use dev_printk
sr: Use dev_printk()
scsi: Avoid linebreaks in syslog output
scsi: Use sdev_printk() for logging
scsi: use buffer for print_opcode_name()
scsi: use single printk call in scsi_print_command()
scsi: use buffer for scsi_show_result()
scsi: open-code scsi_decode_sense_buffer()
scsi: decode descriptor sense
scsi: use local buffer for decoding sense data

 drivers/scsi/constants.c  |  406 +++++++++++++++++++++++++--------------------
 drivers/scsi/scsi.c       |   54 ++++---
 drivers/scsi/scsi_error.c |  190 ++++++++++++++-------
 drivers/scsi/scsi_lib.c   |   13 +-
 drivers/scsi/scsi_scan.c  |   68 ++++----
 drivers/scsi/sd.c         |   16 +-
 drivers/scsi/sg.c         |  187 ++++++++++++---------
 drivers/scsi/sr.c         |   47 +++---
 drivers/scsi/sr.h         |    4 +
 include/scsi/scsi_dbg.h   |    6 +-
 include/scsi/scsi_eh.h    |    8 +-
 11 files changed, 588 insertions(+), 411 deletions(-)
Signature · 1 line
1.7.4.2
#1 lore raw

PATCH 1/10 sg: Use dev_printk

Every sg device has a reference to the underlying scsi device, so this patch adds dev_printk() macros to have the messages prefixed with the correct device.

Before:

[772330.437378] sg_open: dev=2, flags=0x8800
[772330.475425] sg_add_sfp: sfp=0xffff880429d3e000

After:

[  409.399888] sr 2:0:0:0: [sg2] sg_open: flags=0x8800
[  409.446029] sr 2:0:0:0: [sg2] sg_add_sfp: sfp=0xffff880425856000
Cc Kay Sievers <[email protected]>
Cc Doug Gilbert <[email protected]>
---
 drivers/scsi/sg.c |  187 +++++++++++++++++++++++++++++++----------------------
 1 files changed, 109 insertions(+), 78 deletions(-)
drivers/scsi/sg.c +109 -78
index 9c5c5f2..2e6056f 100644
@@ -101,6 +101,13 @@ static int scatter_elem_sz_prev = SG_SCATTER_SZ;
 
 #define SG_SECTOR_SZ 512
 
+#define sgdev_printk(prefix, sgdev, fmt, a...)	\
+	dev_printk(prefix, &(sgdev)->device->sdev_gendev, "[%s] " fmt, \
+		   (sgdev)->disk->disk_name, ##a)
+
+#define sgfp_printk(prefix, sgfp, fmt, a...)				\
+	sgdev_printk(prefix, (sgfp)->parentdp, fmt, ##a)
+
 static int sg_add(struct device *, struct class_interface *);
 static void sg_remove(struct device *, struct class_interface *);
 
@@ -196,7 +203,7 @@ static ssize_t sg_new_write(Sg_fd *sfp, struct file *file,
 static int sg_common_write(Sg_fd * sfp, Sg_request * srp,
 			   unsigned char *cmnd, int timeout, int blocking);
 static int sg_read_oxfer(Sg_request * srp, char __user *outp, int num_read_xfer);
-static void sg_remove_scat(Sg_scatter_hold * schp);
+static void sg_remove_scat(Sg_scatter_hold * schp, Sg_fd * sfp);
 static void sg_build_reserve(Sg_fd * sfp, int req_size);
 static void sg_link_reserve(Sg_fd * sfp, Sg_request * srp, int size);
 static void sg_unlink_reserve(Sg_fd * sfp, Sg_request * srp);
@@ -268,13 +275,14 @@ sg_open(struct inode *inode, struct file *filp)
 	int retval;
 
 	nonseekable_open(inode, filp);
-	SCSI_LOG_TIMEOUT(3, printk("sg_open: dev=%d, flags=0x%x\n", dev, flags));
 	sdp = sg_get_dev(dev);
 	if (IS_ERR(sdp)) {
 		retval = PTR_ERR(sdp);
 		sdp = NULL;
 		goto sg_put;
 	}
+	SCSI_LOG_TIMEOUT(3, sgdev_printk(KERN_INFO, sdp,
+					 "sg_open: flags=0x%x\n", flags));
 
 	/* This driver's module count bumped by fops_get in <linux/fs.h> */
 	/* Prevent the device driver from vanishing while we sleep */
@@ -360,7 +368,7 @@ sg_release(struct inode *inode, struct file *filp)
 
 	if ((!(sfp = (Sg_fd *) filp->private_data)) || (!(sdp = sfp->parentdp)))
 		return -ENXIO;
-	SCSI_LOG_TIMEOUT(3, printk("sg_release: %s\n", sdp->disk->disk_name));
+	SCSI_LOG_TIMEOUT(3, sgdev_printk(KERN_INFO, sdp, "sg_release"));
 
 	set_exclude(sdp, 0);
 	wake_up_interruptible(&sdp->o_excl_wait);
@@ -383,8 +391,8 @@ sg_read(struct file *filp, char __user *buf, size_t count, loff_t * ppos)
 
 	if ((!(sfp = (Sg_fd *) filp->private_data)) || (!(sdp = sfp->parentdp)))
 		return -ENXIO;
-	SCSI_LOG_TIMEOUT(3, printk("sg_read: %s, count=%d\n",
-				   sdp->disk->disk_name, (int) count));
+	SCSI_LOG_TIMEOUT(3, sgdev_printk(KERN_INFO, sdp, "sg_read: count=%d",
+					 (int) count));
 
 	if (!access_ok(VERIFY_WRITE, buf, count))
 		return -EFAULT;
@@ -569,8 +577,8 @@ sg_write(struct file *filp, const char __user *buf, size_t count, loff_t * ppos)
 
 	if ((!(sfp = (Sg_fd *) filp->private_data)) || (!(sdp = sfp->parentdp)))
 		return -ENXIO;
-	SCSI_LOG_TIMEOUT(3, printk("sg_write: %s, count=%d\n",
-				   sdp->disk->disk_name, (int) count));
+	SCSI_LOG_TIMEOUT(3, sgdev_printk(KERN_INFO, sdp, "sg_write: count=%d",
+					 (int) count));
 	if (sdp->detached)
 		return -ENODEV;
 	if (!((filp->f_flags & O_NONBLOCK) ||
@@ -591,14 +599,17 @@ sg_write(struct file *filp, const char __user *buf, size_t count, loff_t * ppos)
 		return -EIO;	/* The minimum scsi command length is 6 bytes. */
 
 	if (!(srp = sg_add_request(sfp))) {
-		SCSI_LOG_TIMEOUT(1, printk("sg_write: queue full\n"));
+		SCSI_LOG_TIMEOUT(1, sgdev_printk(KERN_INFO, sdp,
+						 "sg_write: queue full"));
 		return -EDOM;
 	}
 	buf += SZ_SG_HEADER;
 	__get_user(opcode, buf);
 	if (sfp->next_cmd_len > 0) {
 		if (sfp->next_cmd_len > MAX_COMMAND_SIZE) {
-			SCSI_LOG_TIMEOUT(1, printk("sg_write: command length too long\n"));
+			SCSI_LOG_TIMEOUT(1, sgdev_printk(KERN_INFO, sdp,
+							 "sg_write: command "
+							 "length too long\n"));
 			sfp->next_cmd_len = 0;
 			sg_remove_request(sfp, srp);
 			return -EIO;
@@ -610,7 +621,7 @@ sg_write(struct file *filp, const char __user *buf, size_t count, loff_t * ppos)
 		if ((opcode >= 0xc0) && old_hdr.twelve_byte)
 			cmd_size = 12;
 	}
-	SCSI_LOG_TIMEOUT(4, printk(
+	SCSI_LOG_TIMEOUT(4, sgdev_printk(KERN_INFO, sdp,
 		"sg_write:   scsi opcode=0x%02x, cmd_size=%d\n", (int) opcode, cmd_size));
 /* Determine buffer size.  */
 	input_size = count - cmd_size;
@@ -685,7 +696,8 @@ sg_new_write(Sg_fd *sfp, struct file *file, const char __user *buf,
 
 	sfp->cmd_q = 1;	/* when sg_io_hdr seen, set command queuing on */
 	if (!(srp = sg_add_request(sfp))) {
-		SCSI_LOG_TIMEOUT(1, printk("sg_new_write: queue full\n"));
+		SCSI_LOG_TIMEOUT(1, sgfp_printk(KERN_INFO, sfp,
+						"sg_new_write: queue full\n"));
 		return -EDOM;
 	}
 	srp->sg_io_owned = sg_io_owned;
@@ -754,12 +766,14 @@ sg_common_write(Sg_fd * sfp, Sg_request * srp,
 	hp->host_status = 0;
 	hp->driver_status = 0;
 	hp->resid = 0;
-	SCSI_LOG_TIMEOUT(4, printk("sg_common_write:  scsi opcode=0x%02x, cmd_size=%d\n",
-			  (int) cmnd[0], (int) hp->cmd_len));
+	SCSI_LOG_TIMEOUT(4, sgfp_printk(KERN_INFO, sfp,
+			"sg_common_write:  scsi opcode=0x%02x, cmd_size=%d\n",
+			(int) cmnd[0], (int) hp->cmd_len));
 
 	k = sg_start_req(srp, cmnd);
 	if (k) {
-		SCSI_LOG_TIMEOUT(1, printk("sg_common_write: start_req err=%d\n", k));
+		SCSI_LOG_TIMEOUT(1, sgfp_printk(KERN_INFO, sfp,
+				"sg_common_write: start_req err=%d\n", k));
 		sg_finish_rem_req(srp);
 		return k;	/* probably out of space --> ENOMEM */
 	}
@@ -819,8 +833,8 @@ sg_ioctl(struct file *filp, unsigned int cmd_in, unsigned long arg)
 	if ((!(sfp = (Sg_fd *) filp->private_data)) || (!(sdp = sfp->parentdp)))
 		return -ENXIO;
 
-	SCSI_LOG_TIMEOUT(3, printk("sg_ioctl: %s, cmd=0x%x\n",
-				   sdp->disk->disk_name, (int) cmd_in));
+	SCSI_LOG_TIMEOUT(3, sgdev_printk(KERN_INFO, sdp, "sg_ioctl: cmd=0x%x\n",
+				   (int) cmd_in));
 	read_only = (O_RDWR != (filp->f_flags & O_ACCMODE));
 
 	switch (cmd_in) {
@@ -872,7 +886,7 @@ sg_ioctl(struct file *filp, unsigned int cmd_in, unsigned long arg)
 			sfp->low_dma = 1;
 			if ((0 == sfp->low_dma) && (0 == sg_res_in_use(sfp))) {
 				val = (int) sfp->reserve.bufflen;
-				sg_remove_scat(&sfp->reserve);
+				sg_remove_scat(&sfp->reserve, sfp);
 				sg_build_reserve(sfp, val);
 			}
 		} else {
@@ -948,7 +962,7 @@ sg_ioctl(struct file *filp, unsigned int cmd_in, unsigned long arg)
 		if (val != sfp->reserve.bufflen) {
 			if (sg_res_in_use(sfp) || sfp->mmap_called)
 				return -EBUSY;
-			sg_remove_scat(&sfp->reserve);
+			sg_remove_scat(&sfp->reserve, sfp);
 			sg_build_reserve(sfp, val);
 		}
 		return 0;
@@ -1171,8 +1185,8 @@ sg_poll(struct file *filp, poll_table * wait)
 			res |= POLLOUT | POLLWRNORM;
 	} else if (count < SG_MAX_QUEUE)
 		res |= POLLOUT | POLLWRNORM;
-	SCSI_LOG_TIMEOUT(3, printk("sg_poll: %s, res=0x%x\n",
-				   sdp->disk->disk_name, (int) res));
+	SCSI_LOG_TIMEOUT(3, sgdev_printk(KERN_INFO, sdp, "sg_poll: res=0x%x\n",
+				   (int) res));
 	return res;
 }
 
@@ -1184,8 +1198,8 @@ sg_fasync(int fd, struct file *filp, int mode)
 
 	if ((!(sfp = (Sg_fd *) filp->private_data)) || (!(sdp = sfp->parentdp)))
 		return -ENXIO;
-	SCSI_LOG_TIMEOUT(3, printk("sg_fasync: %s, mode=%d\n",
-				   sdp->disk->disk_name, mode));
+	SCSI_LOG_TIMEOUT(3, sgdev_printk(KERN_INFO, sdp, "sg_fasync: mode=%d",
+					 mode));
 
 	return fasync_helper(fd, filp, mode, &sfp->async_qp);
 }
@@ -1204,8 +1218,9 @@ sg_vma_fault(struct vm_area_struct *vma, struct vm_fault *vmf)
 	offset = vmf->pgoff << PAGE_SHIFT;
 	if (offset >= rsv_schp->bufflen)
 		return VM_FAULT_SIGBUS;
-	SCSI_LOG_TIMEOUT(3, printk("sg_vma_fault: offset=%lu, scatg=%d\n",
-				   offset, rsv_schp->k_use_sg));
+	SCSI_LOG_TIMEOUT(3, sgfp_printk(KERN_INFO, sfp,
+				"sg_vma_fault: offset=%lu, scatg=%d\n",
+				offset, rsv_schp->k_use_sg));
 	sa = vma->vm_start;
 	length = 1 << (PAGE_SHIFT + rsv_schp->page_order);
 	for (k = 0; k < rsv_schp->k_use_sg && sa < vma->vm_end; k++) {
@@ -1240,8 +1255,9 @@ sg_mmap(struct file *filp, struct vm_area_struct *vma)
 	if ((!filp) || (!vma) || (!(sfp = (Sg_fd *) filp->private_data)))
 		return -ENXIO;
 	req_sz = vma->vm_end - vma->vm_start;
-	SCSI_LOG_TIMEOUT(3, printk("sg_mmap starting, vm_start=%p, len=%d\n",
-				   (void *) vma->vm_start, (int) req_sz));
+	SCSI_LOG_TIMEOUT(3, sgfp_printk(KERN_INFO, sfp,
+				"sg_mmap starting, vm_start=%p, len=%d\n",
+				(void *) vma->vm_start, (int) req_sz));
 	if (vma->vm_pgoff)
 		return -EINVAL;	/* want no offset */
 	rsv_schp = &sfp->reserve;
@@ -1295,14 +1311,15 @@ static void sg_rq_end_io(struct request *rq, int uptodate)
 
 	sdp = sfp->parentdp;
 	if (unlikely(sdp->detached))
-		printk(KERN_INFO "sg_rq_end_io: device detached\n");
+		sgdev_printk(KERN_INFO, sdp, "sg_rq_end_io: device detached");
 
 	sense = rq->sense;
 	result = rq->errors;
 	resid = rq->resid_len;
 
-	SCSI_LOG_TIMEOUT(4, printk("sg_cmd_done: %s, pack_id=%d, res=0x%x\n",
-		sdp->disk->disk_name, srp->header.pack_id, result));
+	SCSI_LOG_TIMEOUT(4, sgdev_printk(KERN_INFO, sdp,
+		"sg_cmd_done: pack_id=%d, res=0x%x",
+		srp->header.pack_id, result));
 	srp->header.resid = resid;
 	ms = jiffies_to_msecs(jiffies);
 	srp->header.duration = (ms > srp->header.duration) ?
@@ -1387,12 +1404,14 @@ static Sg_device *sg_alloc(struct gendisk *disk, struct scsi_device *scsidp)
 
 	sdp = kzalloc(sizeof(Sg_device), GFP_KERNEL);
 	if (!sdp) {
-		printk(KERN_WARNING "kmalloc Sg_device failure\n");
+		sdev_printk(KERN_WARNING, scsidp,
+			   "kmalloc Sg_device failure");
 		return ERR_PTR(-ENOMEM);
 	}
 
 	if (!idr_pre_get(&sg_index_idr, GFP_KERNEL)) {
-		printk(KERN_WARNING "idr expansion Sg_device failure\n");
+		sdev_printk(KERN_WARNING, scsidp,
+			   "idr expansion Sg_device failure");
 		error = -ENOMEM;
 		goto out;
 	}
@@ -1402,19 +1421,20 @@ static Sg_device *sg_alloc(struct gendisk *disk, struct scsi_device *scsidp)
 	error = idr_get_new(&sg_index_idr, sdp, &k);
 	if (error) {
 		write_unlock_irqrestore(&sg_index_lock, iflags);
-		printk(KERN_WARNING "idr allocation Sg_device failure: %d\n",
-		       error);
+		sdev_printk(KERN_WARNING, scsidp,
+			   "idr allocation Sg_device failure: %d\n",
+			   error);
 		goto out;
 	}
 
 	if (unlikely(k >= SG_MAX_DEVS))
 		goto overflow;
 
-	SCSI_LOG_TIMEOUT(3, printk("sg_alloc: dev=%d \n", k));
 	sprintf(disk->disk_name, "sg%d", k);
 	disk->first_minor = k;
 	sdp->disk = disk;
 	sdp->device = scsidp;
+	SCSI_LOG_TIMEOUT(3, sgdev_printk(KERN_INFO, sdp, "sg_alloc"));
 	INIT_LIST_HEAD(&sdp->sfds);
 	init_waitqueue_head(&sdp->o_excl_wait);
 	sdp->sg_tablesize = queue_max_segments(q);
@@ -1453,7 +1473,7 @@ sg_add(struct device *cl_dev, struct class_interface *cl_intf)
 
 	disk = alloc_disk(1);
 	if (!disk) {
-		printk(KERN_WARNING "alloc_disk failed\n");
+		sdev_printk(KERN_WARNING, scsidp, "alloc_disk failed");
 		return -ENOMEM;
 	}
 	disk->major = SCSI_GENERIC_MAJOR;
@@ -1461,7 +1481,7 @@ sg_add(struct device *cl_dev, struct class_interface *cl_intf)
 	error = -ENOMEM;
 	cdev = cdev_alloc();
 	if (!cdev) {
-		printk(KERN_WARNING "cdev_alloc failed\n");
+		sdev_printk(KERN_WARNING, scsidp, "cdev_alloc failed");
 		goto out;
 	}
 	cdev->owner = THIS_MODULE;
@@ -1469,7 +1489,7 @@ sg_add(struct device *cl_dev, struct class_interface *cl_intf)
 
 	sdp = sg_alloc(disk, scsidp);
 	if (IS_ERR(sdp)) {
-		printk(KERN_WARNING "sg_alloc failed\n");
+		sdev_printk(KERN_WARNING, scsidp, "sg_alloc failed");
 		error = PTR_ERR(sdp);
 		goto out;
 	}
@@ -1487,18 +1507,19 @@ sg_add(struct device *cl_dev, struct class_interface *cl_intf)
 						      sdp->index),
 						sdp, "%s", disk->disk_name);
 		if (IS_ERR(sg_class_member)) {
-			printk(KERN_ERR "sg_add: "
-			       "device_create failed\n");
+			sdev_printk(KERN_ERR, scsidp, "sg_add: "
+				     "device_create failed");
 			error = PTR_ERR(sg_class_member);
 			goto cdev_add_err;
 		}
 		error = sysfs_create_link(&scsidp->sdev_gendev.kobj,
 					  &sg_class_member->kobj, "generic");
 		if (error)
-			printk(KERN_ERR "sg_add: unable to make symlink "
-					"'generic' back to sg%d\n", sdp->index);
+			sdev_printk(KERN_ERR, scsidp,
+				    "sg_add: unable to make symlink "
+				    "'generic' back to sg%d", sdp->index);
 	} else
-		printk(KERN_WARNING "sg_add: sg_sys Invalid\n");
+		sdev_printk(KERN_WARNING, scsidp, "sg_add: sg_sys Invalid\n");
 
 	sdev_printk(KERN_NOTICE, scsidp,
 		    "Attached scsi generic sg%d type %d\n", sdp->index,
@@ -1535,9 +1556,7 @@ static void sg_device_destroy(struct kref *kref)
 	idr_remove(&sg_index_idr, sdp->index);
 	write_unlock_irqrestore(&sg_index_lock, flags);
 
-	SCSI_LOG_TIMEOUT(3,
-		printk("sg_device_destroy: %s\n",
-			sdp->disk->disk_name));
+	SCSI_LOG_TIMEOUT(3, sgdev_printk(KERN_INFO, sdp, "sg_device_destroy"));
 
 	put_disk(sdp->disk);
 	kfree(sdp);
@@ -1553,7 +1572,7 @@ static void sg_remove(struct device *cl_dev, struct class_interface *cl_intf)
 	if (!sdp || sdp->detached)
 		return;
 
-	SCSI_LOG_TIMEOUT(3, printk("sg_remove: %s\n", sdp->disk->disk_name));
+	SCSI_LOG_TIMEOUT(3, sgdev_printk(KERN_INFO, sdp, "sg_remove"));
 
 	/* Need a write lock to set sdp->detached. */
 	write_lock_irqsave(&sg_index_lock, iflags);
@@ -1654,8 +1673,9 @@ static int sg_start_req(Sg_request *srp, unsigned char *cmd)
 	struct rq_map_data *md, map_data;
 	int rw = hp->dxfer_direction == SG_DXFER_TO_DEV ? WRITE : READ;
 
-	SCSI_LOG_TIMEOUT(4, printk(KERN_INFO "sg_start_req: dxfer_len=%d\n",
-				   dxfer_len));
+	SCSI_LOG_TIMEOUT(4, sgfp_printk(KERN_INFO, sfp,
+					"sg_start_req: dxfer_len=%d",
+					dxfer_len));
 
 	rq = blk_get_request(q, rw, GFP_ATOMIC);
 	if (!rq)
@@ -1742,7 +1762,9 @@ static int sg_finish_rem_req(Sg_request * srp)
 	Sg_fd *sfp = srp->parentfp;
 	Sg_scatter_hold *req_schp = &srp->data;
 
-	SCSI_LOG_TIMEOUT(4, printk("sg_finish_rem_req: res_used=%d\n", (int) srp->res_used));
+	SCSI_LOG_TIMEOUT(4, sgfp_printk(KERN_INFO, sfp,
+					"sg_finish_rem_req: res_used=%d",
+					(int) srp->res_used));
 	if (srp->rq) {
 		if (srp->bio)
 			ret = blk_rq_unmap_user(srp->bio);
@@ -1753,7 +1775,7 @@ static int sg_finish_rem_req(Sg_request * srp)
 	if (srp->res_used)
 		sg_unlink_reserve(sfp, srp);
 	else
-		sg_remove_scat(req_schp);
+		sg_remove_scat(req_schp, sfp);
 
 	sg_remove_request(sfp, srp);
 
@@ -1787,8 +1809,9 @@ sg_build_indirect(Sg_scatter_hold * schp, Sg_fd * sfp, int buff_size)
 		++blk_size;	/* don't know why */
 	/* round request up to next highest SG_SECTOR_SZ byte boundary */
 	blk_size = ALIGN(blk_size, SG_SECTOR_SZ);
-	SCSI_LOG_TIMEOUT(4, printk("sg_build_indirect: buff_size=%d, blk_size=%d\n",
-				   buff_size, blk_size));
+	SCSI_LOG_TIMEOUT(4, sgfp_printk(KERN_INFO, sfp, "sg_build_indirect: "
+					"buff_size=%d, blk_size=%d",
+					buff_size, blk_size));
 
 	/* N.B. ret_sz carried into this block ... */
 	mx_sc_elems = sg_build_sgat(schp, sfp, sg_tablesize);
@@ -1831,14 +1854,16 @@ retry:
 			}
 		}
 
-		SCSI_LOG_TIMEOUT(5, printk("sg_build_indirect: k=%d, num=%d, "
-				 "ret_sz=%d\n", k, num, ret_sz));
+		SCSI_LOG_TIMEOUT(5, sgfp_printk(KERN_INFO, sfp,
+				"sg_build_indirect: k=%d, num=%d, "
+				"ret_sz=%d", k, num, ret_sz));
 	}		/* end of for loop */
 
 	schp->page_order = order;
 	schp->k_use_sg = k;
-	SCSI_LOG_TIMEOUT(5, printk("sg_build_indirect: k_use_sg=%d, "
-			 "rem_sz=%d\n", k, rem_sz));
+	SCSI_LOG_TIMEOUT(5, sgfp_printk(KERN_INFO, sfp,
+			"sg_build_indirect: k_use_sg=%d, "
+			 "rem_sz=%d", k, rem_sz));
 
 	schp->bufflen = blk_size;
 	if (rem_sz > 0)	/* must have failed */
@@ -1855,16 +1880,17 @@ out:
 }
 
 static void
-sg_remove_scat(Sg_scatter_hold * schp)
+sg_remove_scat(Sg_scatter_hold * schp, Sg_fd * sfp)
 {
-	SCSI_LOG_TIMEOUT(4, printk("sg_remove_scat: k_use_sg=%d\n", schp->k_use_sg));
+	SCSI_LOG_TIMEOUT(4, sgfp_printk(KERN_INFO, sfp,
+		"sg_remove_scat: k_use_sg=%d", schp->k_use_sg));
 	if (schp->pages && schp->sglist_len > 0) {
 		if (!schp->dio_in_use) {
 			int k;
 
 			for (k = 0; k < schp->k_use_sg && schp->pages[k]; k++) {
-				SCSI_LOG_TIMEOUT(5, printk(
-				    "sg_remove_scat: k=%d, pg=0x%p\n",
+				SCSI_LOG_TIMEOUT(5, sgfp_printk(KERN_INFO, sfp,
+				    "sg_remove_scat: k=%d, pg=0x%p",
 				    k, schp->pages[k]));
 				__free_pages(schp->pages[k], schp->page_order);
 			}
@@ -1881,8 +1907,8 @@ sg_read_oxfer(Sg_request * srp, char __user *outp, int num_read_xfer)
 	Sg_scatter_hold *schp = &srp->data;
 	int k, num;
 
-	SCSI_LOG_TIMEOUT(4, printk("sg_read_oxfer: num_read_xfer=%d\n",
-				   num_read_xfer));
+	SCSI_LOG_TIMEOUT(4, sgfp_printk(KERN_INFO, srp->parentfp,
+		"sg_read_oxfer: num_read_xfer=%d", num_read_xfer));
 	if ((!outp) || (num_read_xfer <= 0))
 		return 0;
 
@@ -1912,14 +1938,15 @@ sg_build_reserve(Sg_fd * sfp, int req_size)
 {
 	Sg_scatter_hold *schp = &sfp->reserve;
 
-	SCSI_LOG_TIMEOUT(4, printk("sg_build_reserve: req_size=%d\n", req_size));
+	SCSI_LOG_TIMEOUT(4, sgfp_printk(KERN_INFO, sfp,
+		"sg_build_reserve: req_size=%d", req_size));
 	do {
 		if (req_size < PAGE_SIZE)
 			req_size = PAGE_SIZE;
 		if (0 == sg_build_indirect(schp, sfp, req_size))
 			return;
 		else
-			sg_remove_scat(schp);
+			sg_remove_scat(schp, sfp);
 		req_size >>= 1;	/* divide by 2 */
 	} while (req_size > (PAGE_SIZE / 2));
 }
@@ -1932,7 +1959,8 @@ sg_link_reserve(Sg_fd * sfp, Sg_request * srp, int size)
 	int k, num, rem;
 
 	srp->res_used = 1;
-	SCSI_LOG_TIMEOUT(4, printk("sg_link_reserve: size=%d\n", size));
+	SCSI_LOG_TIMEOUT(4, sgfp_printk(KERN_INFO, sfp,
+		"sg_link_reserve: size=%d", size));
 	rem = size;
 
 	num = 1 << (PAGE_SHIFT + rsv_schp->page_order);
@@ -1950,7 +1978,8 @@ sg_link_reserve(Sg_fd * sfp, Sg_request * srp, int size)
 	}
 
 	if (k >= rsv_schp->k_use_sg)
-		SCSI_LOG_TIMEOUT(1, printk("sg_link_reserve: BAD size\n"));
+		SCSI_LOG_TIMEOUT(1, sgfp_printk(KERN_INFO, sfp,
+			"sg_link_reserve: BAD size"));
 }
 
 static void
@@ -1958,8 +1987,9 @@ sg_unlink_reserve(Sg_fd * sfp, Sg_request * srp)
 {
 	Sg_scatter_hold *req_schp = &srp->data;
 
-	SCSI_LOG_TIMEOUT(4, printk("sg_unlink_reserve: req->k_use_sg=%d\n",
-				   (int) req_schp->k_use_sg));
+	SCSI_LOG_TIMEOUT(4, sgfp_printk(KERN_INFO, sfp,
+		"sg_unlink_reserve: req->k_use_sg=%d",
+		(int) req_schp->k_use_sg));
 	req_schp->k_use_sg = 0;
 	req_schp->bufflen = 0;
 	req_schp->pages = NULL;
@@ -2089,15 +2119,17 @@ sg_add_sfp(Sg_device * sdp, int dev)
 	write_lock_irqsave(&sg_index_lock, iflags);
 	list_add_tail(&sfp->sfd_siblings, &sdp->sfds);
 	write_unlock_irqrestore(&sg_index_lock, iflags);
-	SCSI_LOG_TIMEOUT(3, printk("sg_add_sfp: sfp=0x%p\n", sfp));
+	SCSI_LOG_TIMEOUT(3, sgdev_printk(KERN_INFO, sdp,
+		"sg_add_sfp: sfp=0x%p", sfp));
 	if (unlikely(sg_big_buff != def_reserved_size))
 		sg_big_buff = def_reserved_size;
 
 	bufflen = min_t(int, sg_big_buff,
 			queue_max_sectors(sdp->device->request_queue) * 512);
 	sg_build_reserve(sfp, bufflen);
-	SCSI_LOG_TIMEOUT(3, printk("sg_add_sfp:   bufflen=%d, k_use_sg=%d\n",
-			   sfp->reserve.bufflen, sfp->reserve.k_use_sg));
+	SCSI_LOG_TIMEOUT(3, sgdev_printk(KERN_INFO, sdp,
+		"sg_add_sfp:   bufflen=%d, k_use_sg=%d",
+		sfp->reserve.bufflen, sfp->reserve.k_use_sg));
 
 	kref_get(&sdp->d_ref);
 	__module_get(THIS_MODULE);
@@ -2115,16 +2147,15 @@ static void sg_remove_sfp_usercontext(struct work_struct *work)
 
 	if (sfp->reserve.bufflen > 0) {
 		SCSI_LOG_TIMEOUT(6,
-			printk("sg_remove_sfp:    bufflen=%d, k_use_sg=%d\n",
-				(int) sfp->reserve.bufflen,
-				(int) sfp->reserve.k_use_sg));
-		sg_remove_scat(&sfp->reserve);
+			sgdev_printk(KERN_INFO, sdp,
+				     "sg_remove_sfp:   bufflen=%d, k_use_sg=%d",
+				     (int) sfp->reserve.bufflen,
+				     (int) sfp->reserve.k_use_sg));
+		sg_remove_scat(&sfp->reserve, sfp);
 	}
 
 	SCSI_LOG_TIMEOUT(6,
-		printk("sg_remove_sfp: %s, sfp=0x%p\n",
-			sdp->disk->disk_name,
-			sfp));
+		sgdev_printk(KERN_INFO, sdp, "sg_remove_sfp: sfp=0x%p", sfp));
 	kfree(sfp);
 
 	scsi_device_put(sdp->device);
Signature · 1 line
1.7.4.2
maintainer Acked-by on v1 1/10
#2 lore raw

Re: [PATCH 01/10] sg: Use dev_printk

Quoted 8 lines · Hannes Reinecke

Every sg device has a reference to the underlying scsi device, so this patch adds dev_printk() macros to have the messages prefixed with the correct device.

Before:

[772330.437378] sg_open: dev=2, flags=0x8800
[772330.475425] sg_add_sfp: sfp=0xffff880429d3e000
Quoted 7 lines

After:

[  409.399888] sr 2:0:0:0: [sg2] sg_open: flags=0x8800
[  409.446029] sr 2:0:0:0: [sg2] sg_add_sfp: sfp=0xffff880425856000
Cc Kay Sievers <[email protected]>
Cc Doug Gilbert <[email protected]>
#3 lore raw

PATCH 2/10 sr: Use dev_printk()

In reply to Hannes Reinecke

Convert sr to use dev_printk() to avoid linebreaks in kernel messages.

---
 drivers/scsi/sr.c |   47 ++++++++++++++++++++++++++---------------------
 drivers/scsi/sr.h |    4 ++++
 2 files changed, 30 insertions(+), 21 deletions(-)
drivers/scsi/sr.c +26 -21
index 5fc97d2..26404ca 100644
@@ -276,8 +276,8 @@ do_tur:
 	if (!cd->tur_changed) {
 		if (cd->get_event_changed) {
 			if (cd->tur_mismatch++ > 8) {
-				sdev_printk(KERN_WARNING, cd->device,
-					    "GET_EVENT and TUR disagree continuously, suppress GET_EVENT events\n");
+				sr_printk(KERN_WARNING, cd,
+					  "GET_EVENT and TUR disagree continuously, suppress GET_EVENT events\n");
 				cd->ignore_get_event = true;
 			}
 		} else {
@@ -306,7 +306,7 @@ static int sr_done(struct scsi_cmnd *SCpnt)
 	struct scsi_cd *cd = scsi_cd(SCpnt->request->rq_disk);
 
 #ifdef DEBUG
-	printk("sr.c done: %x\n", result);
+	sr_printk(KERN_INFO, cd, "sr.c done: %x\n", result);
 #endif
 
 	/*
@@ -389,13 +389,16 @@ static int sr_prep_fn(struct request_queue *q, struct request *rq)
 	 * is used for a killable error condition */
 	ret = BLKPREP_KILL;
 
-	SCSI_LOG_HLQUEUE(1, printk("Doing sr request, dev = %s, block = %d\n",
-				cd->disk->disk_name, block));
+	SCSI_LOG_HLQUEUE(1,
+		scmd_printk(KERN_INFO, SCpnt,
+			    "Doing sr request, block = %d\n", block));
 
 	if (!cd->device || !scsi_device_online(cd->device)) {
-		SCSI_LOG_HLQUEUE(2, printk("Finishing %u sectors\n",
-					   blk_rq_sectors(rq)));
-		SCSI_LOG_HLQUEUE(2, printk("Retry with 0x%p\n", SCpnt));
+		SCSI_LOG_HLQUEUE(2, scmd_printk(KERN_INFO, SCpnt,
+						"Finishing %u sectors\n",
+					      blk_rq_sectors(rq)));
+		SCSI_LOG_HLQUEUE(2, scmd_printk(KERN_INFO, SCpnt,
+						"Retry with 0x%p\n", SCpnt));
 		goto out;
 	}
 
@@ -416,7 +419,8 @@ static int sr_prep_fn(struct request_queue *q, struct request *rq)
 		if (!in_interrupt())
 			sr_set_blocklength(cd, 2048);
 		else
-			printk("sr: can't switch blocksize: in interrupt\n");
+			scmd_printk(KERN_INFO, SCpnt,
+				  "sr: can't switch blocksize: in interrupt\n");
 	}
 
 	if (s_size != 512 && s_size != 1024 && s_size != 2048) {
@@ -429,7 +433,7 @@ static int sr_prep_fn(struct request_queue *q, struct request *rq)
 			goto out;
 		SCpnt->cmnd[0] = WRITE_10;
 		SCpnt->sc_data_direction = DMA_TO_DEVICE;
- 	 	cd->cdi.media_written = 1;
+		cd->cdi.media_written = 1;
 	} else if (rq_data_dir(rq) == READ) {
 		SCpnt->cmnd[0] = READ_10;
 		SCpnt->sc_data_direction = DMA_FROM_DEVICE;
@@ -447,8 +451,8 @@ static int sr_prep_fn(struct request_queue *q, struct request *rq)
 
 		if (size != scsi_bufflen(SCpnt)) {
 			scmd_printk(KERN_ERR, SCpnt,
-				"mismatch count %d, bytes %d\n",
-				size, scsi_bufflen(SCpnt));
+				    "mismatch count %d, bytes %d\n",
+				    size, scsi_bufflen(SCpnt));
 			if (scsi_bufflen(SCpnt) > size)
 				SCpnt->sdb.length = size;
 		}
@@ -466,11 +470,11 @@ static int sr_prep_fn(struct request_queue *q, struct request *rq)
 	this_count = (scsi_bufflen(SCpnt) >> 9) / (s_size >> 9);
 
 
-	SCSI_LOG_HLQUEUE(2, printk("%s : %s %d/%u 512 byte blocks.\n",
-				cd->cdi.name,
-				(rq_data_dir(rq) == WRITE) ?
-					"writing" : "reading",
-				this_count, blk_rq_sectors(rq)));
+	SCSI_LOG_HLQUEUE(2, sr_printk(KERN_INFO, cd,
+				      "%s %d/%u 512 byte blocks.\n",
+				      (rq_data_dir(rq) == WRITE) ?
+				      "writing" : "reading",
+				      this_count, blk_rq_sectors(rq)));
 
 	SCpnt->cmnd[1] = 0;
 	block = (unsigned int)blk_rq_pos(rq) / (s_size >> 9);
@@ -790,8 +794,9 @@ static void get_sectorsize(struct scsi_cd *cd)
 		case 512:
 			break;
 		default:
-			printk("%s: unsupported sector size %d.\n",
-			       cd->cdi.name, sector_size);
+			sr_printk(KERN_INFO, cd,
+				  "unsupported sector size %d.\n",
+				  sector_size);
 			cd->capacity = 0;
 		}
 
@@ -852,7 +857,7 @@ static void get_capabilities(struct scsi_cd *cd)
 				 CDC_SELECT_DISC | CDC_SELECT_SPEED |
 				 CDC_MRW | CDC_MRW_W | CDC_RAM);
 		kfree(buffer);
-		printk("%s: scsi-1 drive\n", cd->cdi.name);
+		sr_printk(KERN_INFO, cd, "scsi-1 drive");
 		return;
 	}
 
@@ -861,7 +866,7 @@ static void get_capabilities(struct scsi_cd *cd)
 	cd->readcd_known = 1;
 	cd->readcd_cdda = buffer[n + 5] & 0x01;
 	/* print some capability bits */
-	printk("%s: scsi3-mmc drive: %dx/%dx %s%s%s%s%s%s\n", cd->cdi.name,
+	sr_printk(KERN_INFO, cd, "scsi3-mmc drive: %dx/%dx %s%s%s%s%s%s",
 	       ((buffer[n + 14] << 8) + buffer[n + 15]) / 176,
 	       cd->cdi.speed,
 	       buffer[n + 3] & 0x01 ? "writer " : "", /* CD Writer */
drivers/scsi/sr.h +4 -0
index 37c8f6b..1610cac 100644
@@ -55,6 +55,10 @@ typedef struct scsi_cd {
 	struct gendisk *disk;
 } Scsi_CD;
 
+#define sr_printk(prefix, scd, fmt, a...)				\
+	sdev_printk(prefix, (scd)->device, "[%s] " fmt,		\
+		    (scd)->cdi.name, ##a)
+
 int sr_do_ioctl(Scsi_CD *, struct packet_command *);
 
 int sr_lock_door(struct cdrom_device_info *, int);
Signature · 1 line
1.7.4.2
#4 lore raw

PATCH 3/10 scsi: Avoid linebreaks in syslog output

In reply to Hannes Reinecke

sdev_printk() is adding a linebreak automatically, causing the syslog output to be garbled:

[  542.494393] sr 2:0:0:0: Send:
[  542.494394] 0xffff8804291e5dc0

which will make debuggging painful.
So reshuffle sdev_printk invokation to have it printed on the same line.

---
 drivers/scsi/scsi.c |   38 ++++++++++++++++++++++----------------
 1 files changed, 22 insertions(+), 16 deletions(-)
drivers/scsi/scsi.c +22 -16
index 2936b44..28b294b 100644
@@ -551,14 +551,15 @@ 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: ");
 			if (level > 2)
-				printk("0x%p ", cmd);
-			printk("\n");
+				scmd_printk(KERN_INFO, cmd, "Send: 0x%p", cmd);
+			else
+				scmd_printk(KERN_INFO, cmd, "Send:");
 			scsi_print_command(cmd);
 			if (level > 3) {
-				printk(KERN_INFO "buffer = 0x%p, bufflen = %d,"
-				       " queuecommand 0x%p\n",
+				scmd_printk(KERN_INFO, cmd,
+				       "buffer = 0x%p, bufflen = %d,"
+				       " queuecommand 0x%p",
 					scsi_sglist(cmd), scsi_bufflen(cmd),
 					cmd->device->host->hostt->queuecommand);
 
@@ -588,42 +589,47 @@ 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: ");
-			if (level > 2)
-				printk("0x%p ", cmd);
+			const char *disp_str;
+
 			/*
 			 * Dump truncated values, so we usually fit within
 			 * 80 chars.
 			 */
 			switch (disposition) {
 			case SUCCESS:
-				printk("SUCCESS\n");
+				disp_str = "SUCCESS";
 				break;
 			case NEEDS_RETRY:
-				printk("RETRY\n");
+				disp_str = "RETRY";
 				break;
 			case ADD_TO_MLQUEUE:
-				printk("MLQUEUE\n");
+				disp_str = "MLQUEUE";
 				break;
 			case FAILED:
-				printk("FAILED\n");
+				disp_str = "FAILED";
 				break;
 			case TIMEOUT_ERROR:
-				/* 
+				/*
 				 * If called via scsi_times_out.
 				 */
-				printk("TIMEOUT\n");
+				disp_str = "TIMEOUT";
 				break;
 			default:
-				printk("UNKNOWN\n");
+				disp_str = "UNKNOWN";
 			}
+			if (level > 2)
+				scmd_printk(KERN_INFO, cmd, "Done: 0x%p %s",
+					    cmd, disp_str);
+			else
+				scmd_printk(KERN_INFO, cmd, "Done: %s",
+					    disp_str);
 			scsi_print_result(cmd);
 			scsi_print_command(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",
+					    "scsi host busy %d failed %d",
 					    cmd->device->host->host_busy,
 					    cmd->device->host->host_failed);
 		}
Signature · 1 line
1.7.4.2
#5 lore raw

PATCH 4/10 scsi: Use sdev_printk() for logging

In reply to Hannes Reinecke

Most scsi logging messages are using a plain printk, making it hard to relate to the originating device.
This patchs moves the scsi logging messages to use sdev_printk() and friends.

---
 drivers/scsi/scsi.c       |   16 +++--
 drivers/scsi/scsi_error.c |  147 ++++++++++++++++++++++++++-------------------
 drivers/scsi/scsi_lib.c   |   13 +++--
 drivers/scsi/scsi_scan.c  |   68 +++++++++++----------
 4 files changed, 139 insertions(+), 105 deletions(-)
drivers/scsi/scsi.c +10 -6
index 28b294b..5797f61 100644
@@ -691,7 +691,8 @@ int scsi_dispatch_cmd(struct scsi_cmnd *cmd)
 
 		scsi_queue_insert(cmd, SCSI_MLQUEUE_DEVICE_BUSY);
 
-		SCSI_LOG_MLQUEUE(3, printk("queuecommand : device blocked \n"));
+		SCSI_LOG_MLQUEUE(3, scmd_printk(KERN_INFO, cmd,
+			"queuecommand : device blocked"));
 
 		/*
 		 * NOTE: rtn is still zero here because we don't need the
@@ -739,8 +740,9 @@ int scsi_dispatch_cmd(struct scsi_cmnd *cmd)
 	 */
 	if (cmd->cmd_len > cmd->device->host->max_cmd_len) {
 		SCSI_LOG_MLQUEUE(3,
-			printk("queuecommand : command too long. "
-			       "cdb_size=%d host->max_cmd_len=%d\n",
+			       scmd_printk(KERN_INFO, cmd,
+			       "queuecommand : command too long. "
+			       "cdb_size=%d host->max_cmd_len=%d",
 			       cmd->cmd_len, cmd->device->host->max_cmd_len));
 		cmd->result = (DID_ABORT << 16);
 
@@ -766,11 +768,13 @@ int scsi_dispatch_cmd(struct scsi_cmnd *cmd)
 		scsi_queue_insert(cmd, rtn);
 
 		SCSI_LOG_MLQUEUE(3,
-		    printk("queuecommand : request rejected\n"));
+			scmd_printk(KERN_INFO, cmd,
+				    "queuecommand : request rejected"));
 	}
 
  out:
-	SCSI_LOG_MLQUEUE(3, printk("leaving scsi_dispatch_cmnd()\n"));
+	SCSI_LOG_MLQUEUE(3, scmd_printk(KERN_INFO, cmd,
+					"leaving scsi_dispatch_cmnd()"));
 	return rtn;
 }
 
@@ -830,7 +834,7 @@ void scsi_finish_command(struct scsi_cmnd *cmd)
 	if (SCSI_SENSE_VALID(cmd))
 		cmd->result |= (DRIVER_SENSE << 24);
 
-	SCSI_LOG_MLCOMPLETE(4, sdev_printk(KERN_INFO, sdev,
+	SCSI_LOG_MLCOMPLETE(4, scmd_printk(KERN_INFO, cmd,
 				"Notifying upper driver of completion "
 				"(result %x)\n", cmd->result));
 
drivers/scsi/scsi_error.c +86 -61

329 lines not on this page · raw message

drivers/scsi/scsi_lib.c +8 -5
index da36a3a..a8dbbb1 100644
@@ -135,7 +135,8 @@ static void __scsi_queue_insert(struct scsi_cmnd *cmd, int reason, int unbusy)
 	unsigned long flags;
 
 	SCSI_LOG_MLQUEUE(1,
-		 printk("Inserting command %p into mlqueue\n", cmd));
+		scmd_printk(KERN_INFO, cmd,
+			    "Inserting command %p into mlqueue", cmd));
 
 	/*
 	 * Set the appropriate busy bit for the device/host.
@@ -820,8 +821,8 @@ void scsi_io_completion(struct scsi_cmnd *cmd, unsigned int good_bytes)
 	 * Next deal with any sectors which we were able to correctly
 	 * handle.
 	 */
-	SCSI_LOG_HLCOMPLETE(1, printk("%u sectors total, "
-				      "%d bytes done.\n",
+	SCSI_LOG_HLCOMPLETE(1, scmd_printk(KERN_INFO, cmd,
+				      "%u sectors total, %d bytes done.",
 				      blk_rq_sectors(req), good_bytes));
 
 	/*
@@ -1370,7 +1371,8 @@ static inline int scsi_host_queue_ready(struct request_queue *q,
 		 */
 		if (--shost->host_blocked == 0) {
 			SCSI_LOG_MLQUEUE(3,
-				printk("scsi%d unblocking host at zero depth\n",
+				sdev_printk(KERN_INFO, sdev,
+					"scsi%d unblocking host at zero depth",
 					shost->host_no));
 		} else {
 			return 0;
@@ -1555,7 +1557,8 @@ static void scsi_request_fn(struct request_queue *q)
 		spin_unlock(q->queue_lock);
 		cmd = req->special;
 		if (unlikely(cmd == NULL)) {
-			printk(KERN_CRIT "impossible request in %s.\n"
+			sdev_printk(KERN_CRIT, sdev,
+					 "impossible request in %s.\n"
 					 "please mail a stack trace to "
 					 "[email protected]\n",
 					 __func__);
drivers/scsi/scsi_scan.c +35 -33

178 lines not on this page · raw message

Signature · 1 line
1.7.4.2
#6 lore raw

PATCH 5/10 scsi: use buffer for print_opcode_name()

In reply to Hannes Reinecke

Instead of printing directly to syslog print_opcode_name() should be using a private buffer to avoid linebreaks during printout.

---
 drivers/scsi/constants.c |   98 +++++++++++++++++++++++++++------------------
 1 files changed, 59 insertions(+), 39 deletions(-)
drivers/scsi/constants.c +59 -39
index 76e4c03..b469798 100644
@@ -204,9 +204,10 @@ static const char * get_sa_name(const struct value_name_pair * arr,
 }
 
 /* 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(char *buf, int buf_len,
+			      unsigned char *cdbp, int cdb_len)
 {
-	int sa, len, cdb0;
+	int sa, len, cdb0, sz = 0;
 	const char * name;
 
 	cdb0 = cdbp[0];
@@ -214,101 +215,119 @@ static void print_opcode_name(unsigned char * cdbp, int cdb_len)
 	case 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;
+			sz = snprintf(buf, buf_len,
+				      "short variable length command, "
+				      "len=%d ext_len=%d", len, cdb_len);
+			return sz;
 		}
 		sa = (cdbp[8] << 8) + cdbp[9];
 		name = get_sa_name(variable_length_arr, VARIABLE_LENGTH_SZ, sa);
 		if (name)
-			printk("%s", name);
+			sz = snprintf(buf, buf_len, "%s", name);
 		else
-			printk("cdb[0]=0x%x, sa=0x%x", cdb0, sa);
+			sz = snprintf(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);
+			sz = snprintf(buf + sz, buf_len - sz,
+				      ", 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);
 		if (name)
-			printk("%s", name);
+			sz = snprintf(buf, buf_len, "%s", name);
 		else
-			printk("cdb[0]=0x%x, sa=0x%x", cdb0, sa);
+			sz = snprintf(buf, buf_len, "cdb[0]=0x%x, sa=0x%x",
+				      cdb0, sa);
 		break;
 	case MAINTENANCE_OUT:
 		sa = cdbp[1] & 0x1f;
 		name = get_sa_name(maint_out_arr, MAINT_OUT_SZ, sa);
 		if (name)
-			printk("%s", name);
+			sz = snprintf(buf, buf_len, "%s", name);
 		else
-			printk("cdb[0]=0x%x, sa=0x%x", cdb0, sa);
+			sz = snprintf(buf, buf_len, "cdb[0]=0x%x, sa=0x%x",
+				      cdb0, sa);
 		break;
 	case SERVICE_ACTION_IN_12:
 		sa = cdbp[1] & 0x1f;
 		name = get_sa_name(serv_in12_arr, SERV_IN12_SZ, sa);
 		if (name)
-			printk("%s", name);
+			sz = snprintf(buf, buf_len, "%s", name);
 		else
-			printk("cdb[0]=0x%x, sa=0x%x", cdb0, sa);
+			sz = snprintf(buf, buf_len, "cdb[0]=0x%x, sa=0x%x",
+				      cdb0, sa);
 		break;
 	case SERVICE_ACTION_OUT_12:
 		sa = cdbp[1] & 0x1f;
 		name = get_sa_name(serv_out12_arr, SERV_OUT12_SZ, sa);
 		if (name)
-			printk("%s", name);
+			sz = snprintf(buf, buf_len, "%s", name);
 		else
-			printk("cdb[0]=0x%x, sa=0x%x", cdb0, sa);
+			sz = snprintf(buf, buf_len, "cdb[0]=0x%x, sa=0x%x",
+				      cdb0, sa);
 		break;
 	case SERVICE_ACTION_IN_16:
 		sa = cdbp[1] & 0x1f;
 		name = get_sa_name(serv_in16_arr, SERV_IN16_SZ, sa);
 		if (name)
-			printk("%s", name);
+			sz = snprintf(buf, buf_len, "%s", name);
 		else
-			printk("cdb[0]=0x%x, sa=0x%x", cdb0, sa);
+			sz = snprintf(buf, buf_len, "cdb[0]=0x%x, sa=0x%x",
+				      cdb0, sa);
 		break;
 	case SERVICE_ACTION_OUT_16:
 		sa = cdbp[1] & 0x1f;
 		name = get_sa_name(serv_out16_arr, SERV_OUT16_SZ, sa);
 		if (name)
-			printk("%s", name);
+			sz = snprintf(buf, buf_len, "%s", name);
 		else
-			printk("cdb[0]=0x%x, sa=0x%x", cdb0, sa);
+			sz = snprintf(buf, buf_len, "cdb[0]=0x%x, sa=0x%x",
+				      cdb0, sa);
 		break;
 	default:
 		if (cdb0 < 0xc0) {
 			name = cdb_byte0_names[cdb0];
 			if (name)
-				printk("%s", name);
+				sz = snprintf(buf, buf_len, "%s", name);
 			else
-				printk("cdb[0]=0x%x (reserved)", cdb0);
+				sz = snprintf(buf, buf_len,
+					      "cdb[0]=0x%x (reserved)", cdb0);
 		} else
-			printk("cdb[0]=0x%x (vendor)", cdb0);
+			sz = snprintf(buf, buf_len, "cdb[0]=0x%x (vendor)",
+				      cdb0);
 		break;
 	}
+	return sz;
 }
 
 #else /* ifndef CONFIG_SCSI_CONSTANTS */
 
-static void print_opcode_name(unsigned char * cdbp, int cdb_len)
+static int print_opcode_name(char *buf, int buf_len,
+			     unsigned char *cdbp, int cdb_len)
 {
-	int sa, len, cdb0;
+	int sa, len, cdb0, sz = 0;
 
 	cdb0 = cdbp[0];
+	sz = snprintf(buf, buf_len, "cdb[0]=0x%x", cdb0);
 	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);
+			sz += snprintf(buf + sz, buf_size - sz,
+				       "short command, len=%d ext_len=%d",
+				       len, cdb_len);
 			break;
 		}
 		sa = (cdbp[8] << 8) + cdbp[9];
-		printk("cdb[0]=0x%x, sa=0x%x", cdb0, sa);
+		sz += snprintf(buf + sz, buf_len - sz, ", sa=0x%x", sa);
 		if (len != cdb_len)
-			printk(", in_cdb_len=%d, ext_len=%d", len, cdb_len);
+			sz += snprintf(buf + sz, buf_len - sz,
+				       ", in_cdb_len=%d, ext_len=%d",
+				       len, cdb_len);
 		break;
 	case MAINTENANCE_IN:
 	case MAINTENANCE_OUT:
@@ -317,23 +336,24 @@ static void print_opcode_name(unsigned char * cdbp, int cdb_len)
 	case SERVICE_ACTION_IN_16:
 	case SERVICE_ACTION_OUT_16:
 		sa = cdbp[1] & 0x1f;
-		printk("cdb[0]=0x%x, sa=0x%x", cdb0, sa);
+		sz += snprintf(buf + sz, buf_len - sz, ", sa=0x%x", sa);
 		break;
 	default:
-		if (cdb0 < 0xc0)
-			printk("cdb[0]=0x%x", cdb0);
-		else
-			printk("cdb[0]=0x%x (vendor)", cdb0);
+		if (cdb0 >= 0xc0)
+			sz += snprintf(buf + sz, buf_len - sz, " (vendor)");
 		break;
 	}
+	return sz;
 }
-#endif  
+#endif
 
 void __scsi_print_command(unsigned char *cdb)
 {
 	int k, len;
+	char cdb_str[64];
 
-	print_opcode_name(cdb, 0);
+	print_opcode_name(cdb_str, 64, cdb, 0);
+	pr_info("%s", cdb_str);
 	len = scsi_command_size(cdb);
 	/* print out all bytes in cdb */
 	for (k = 0; k < len; ++k) 
@@ -345,15 +365,15 @@ EXPORT_SYMBOL(__scsi_print_command);
 void scsi_print_command(struct scsi_cmnd *cmd)
 {
 	int k;
+	char cdb_str[64];
 
 	if (cmd->cmnd == NULL)
 		return;
 
-	scmd_printk(KERN_INFO, cmd, "CDB: ");
-	print_opcode_name(cmd->cmnd, cmd->cmd_len);
+	print_opcode_name(cdb_str, 64, cmd->cmnd, cmd->cmd_len);
+	scmd_printk(KERN_INFO, cmd, "CDB: %s:", cdb_str);
 
 	/* print out all bytes in cdb */
-	printk(":");
 	for (k = 0; k < cmd->cmd_len; ++k)
 		printk(" %02x", cmd->cmnd[k]);
 	printk("\n");
Signature · 1 line
1.7.4.2
#7 lore raw

PATCH 6/10 scsi: use single printk call in scsi_print_command()

In reply to Hannes Reinecke

scsi_print_command is using several calls to printk(), causing the output to be garbled. Modify it to use a single call to printk().

---
 drivers/scsi/constants.c |   71 +++++++++++++++++++++++++++++++++++++++------
 1 files changed, 61 insertions(+), 10 deletions(-)
drivers/scsi/constants.c +61 -10
index b469798..65367e8 100644
@@ -349,34 +349,85 @@ static int print_opcode_name(char *buf, int buf_len,
 
 void __scsi_print_command(unsigned char *cdb)
 {
-	int k, len;
+	int k, len, rem, linelen;
 	char cdb_str[64];
+	char line[16 * 3 + 1];
 
 	print_opcode_name(cdb_str, 64, cdb, 0);
-	pr_info("%s", cdb_str);
 	len = scsi_command_size(cdb);
 	/* print out all bytes in cdb */
-	for (k = 0; k < len; ++k) 
-		printk(" %02x", cdb[k]);
-	printk("\n");
+	switch (len) {
+	case 6:
+		pr_info("%s %6ph\n", cdb_str, cdb);
+		break;
+	case 10:
+		pr_info("%s %10ph\n", cdb_str, cdb);
+		break;
+	case 12:
+		pr_info("%s %12ph\n", cdb_str, cdb);
+		break;
+	case 16:
+		pr_info("%s %16ph\n", cdb_str, cdb);
+		break;
+	default:
+		pr_info("%s\n", cdb_str);
+		rem = len;
+		for (k = 0; k < len; k += 16) {
+			linelen = min(rem, 16);
+			rem -= 16;
+
+			hex_dump_to_buffer(cdb + k, linelen, 16, 1,
+					   line, sizeof(line), false);
+			pr_info("%s\n", line);
+		}
+		break;
+	}
 }
 EXPORT_SYMBOL(__scsi_print_command);
 
 void scsi_print_command(struct scsi_cmnd *cmd)
 {
-	int k;
+	int k, rem, linelen;
 	char cdb_str[64];
+	char line[16 * 3 + 1];
 
 	if (cmd->cmnd == NULL)
 		return;
 
 	print_opcode_name(cdb_str, 64, cmd->cmnd, cmd->cmd_len);
-	scmd_printk(KERN_INFO, cmd, "CDB: %s:", cdb_str);
 
 	/* print out all bytes in cdb */
-	for (k = 0; k < cmd->cmd_len; ++k)
-		printk(" %02x", cmd->cmnd[k]);
-	printk("\n");
+	switch (cmd->cmd_len) {
+	case 6:
+		scmd_printk(KERN_INFO, cmd, "CDB: %s: %6ph\n",
+			    cdb_str, cmd->cmnd);
+		break;
+	case 10:
+		scmd_printk(KERN_INFO, cmd, "CDB: %s: %10ph\n",
+			    cdb_str, cmd->cmnd);
+		break;
+	case 12:
+		scmd_printk(KERN_INFO, cmd, "CDB: %s: %12ph\n",
+			    cdb_str, cmd->cmnd);
+		break;
+	case 16:
+		scmd_printk(KERN_INFO, cmd, "CDB: %s: %16ph\n",
+			    cdb_str, cmd->cmnd);
+		break;
+	default:
+		scmd_printk(KERN_INFO, cmd, "CDB: %s\n", cdb_str);
+		rem = cmd->cmd_len;
+		for (k = 0; k < cmd->cmd_len; k += 16) {
+			linelen = min(rem, 16);
+			rem -= 16;
+
+			hex_dump_to_buffer(cmd->cmnd + k, linelen, 16, 1,
+					   line, sizeof(line), false);
+			scmd_printk(KERN_INFO, cmd, "        %d: %s\n",
+				    k, line);
+		}
+		break;
+	}
 }
 EXPORT_SYMBOL(scsi_print_command);
 
Signature · 1 line
1.7.4.2
#8 lore raw

PATCH 7/10 scsi: use buffer for scsi_show_result()

In reply to Hannes Reinecke

scsi_show_result() should be printing the message into a supplied buffer to avoid linebreaks during output.

---
 drivers/scsi/constants.c |   23 +++++++++++++----------
 drivers/scsi/sd.c        |    6 ++++--
 include/scsi/scsi_dbg.h  |    2 +-
 3 files changed, 18 insertions(+), 13 deletions(-)
drivers/scsi/constants.c +13 -10
index 65367e8..ded16d9 100644
@@ -1502,32 +1502,35 @@ 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(char *buf, int buf_size, int result)
 {
 	int hb = host_byte(result);
 	int db = driver_byte(result);
 
-	printk("Result: hostbyte=%s driverbyte=%s\n",
-	       (hb < NUM_HOSTBYTE_STRS ? hostbyte_table[hb]     : "invalid"),
-	       (db < NUM_DRIVERBYTE_STRS ? driverbyte_table[db] : "invalid"));
+	snprintf(buf, buf_size,
+		"Result: hostbyte=%s driverbyte=%s\n",
+		(hb < NUM_HOSTBYTE_STRS ? hostbyte_table[hb]     : "invalid"),
+		(db < NUM_DRIVERBYTE_STRS ? driverbyte_table[db] : "invalid"));
 }
 
 #else
 
-void scsi_show_result(int result)
+void scsi_show_result(char *buf, int buf_size, int result)
 {
-	printk("Result: hostbyte=0x%02x driverbyte=0x%02x\n",
-	       host_byte(result), driver_byte(result));
+	snprintf(buf, buf_size,
+		 "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);
+	char result_buf[70];
+
+	scsi_show_result(result_buf, 70, cmd->result);
+	scmd_printk(KERN_INFO, cmd, "%s", result_buf);
 }
 EXPORT_SYMBOL(scsi_print_result);
 
drivers/scsi/sd.c +4 -2
index 12f6fdf..f6165e6 100644
@@ -3025,7 +3025,9 @@ 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);
+	char result_buf[70];
+
+	scsi_show_result(result_buf, 70, result);
+	sd_printk(KERN_INFO, sdkp, "%s", result_buf);
 }
 
include/scsi/scsi_dbg.h +1 -1
index e89844c..cc6abb4 100644
@@ -15,7 +15,7 @@ extern void scsi_print_sense(char *, struct scsi_cmnd *);
 extern void __scsi_print_sense(const char *name,
 			       const unsigned char *sense_buffer,
 			       int sense_len);
-extern void scsi_show_result(int);
+extern void scsi_show_result(char *, int, 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);
Signature · 1 line
1.7.4.2
#9 lore raw

PATCH 8/10 scsi: open-code scsi_decode_sense_buffer()

In reply to Hannes Reinecke

Pointless, and actually wrong as there is no point in trying to decode invalid sense data.

---
 drivers/scsi/constants.c |   43 +++++++++++++++++--------------------------
 1 files changed, 17 insertions(+), 26 deletions(-)
drivers/scsi/constants.c +17 -26
index ded16d9..8bf2616 100644
@@ -1373,29 +1373,6 @@ scsi_cmd_print_sense_hdr(struct scsi_cmnd *scmd, const char *desc,
 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)
-{
-	int k, num, res;
-    
-	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;
-	}
-}
-
-static void
 scsi_decode_sense_extras(const unsigned char *sense_buffer, int sense_len,
 			 struct scsi_sense_hdr *sshdr)
 {
@@ -1462,8 +1439,15 @@ void __scsi_print_sense(const char *name, const unsigned char *sense_buffer,
 {
 	struct scsi_sense_hdr sshdr;
 
+	if (!scsi_normalize_sense(sense_buffer, sense_len, &sshdr)) {
+		/* this may be SCSI-1 sense data */
+		int num = (sense_len < 32) ? sense_len : 32;
+		pr_info("%s: Unrecognized sense data (in hex):", name);
+		print_hex_dump(KERN_INFO, "        ", DUMP_PREFIX_OFFSET,
+			       16, 1, sense_buffer, num, false);
+		return;
+	}
 	printk(KERN_INFO "%s: ", name);
-	scsi_decode_sense_buffer(sense_buffer, sense_len, &sshdr);
 	scsi_show_sense_hdr(&sshdr);
 	scsi_decode_sense_extras(sense_buffer, sense_len, &sshdr);
 	printk(KERN_INFO "%s: ", name);
@@ -1476,9 +1460,16 @@ void scsi_print_sense(char *name, struct scsi_cmnd *cmd)
 {
 	struct scsi_sense_hdr sshdr;
 
+	if (!scsi_normalize_sense(cmd->sense_buffer, SCSI_SENSE_BUFFERSIZE,
+				  &sshdr)) {
+		scmd_printk(KERN_INFO, cmd,
+			    "Unrecognized sense data (in hex):");
+		print_hex_dump(KERN_INFO, "        ", DUMP_PREFIX_OFFSET,
+			       16, 1, cmd->sense_buffer, SCSI_SENSE_BUFFERSIZE,
+			       false);
+		return;
+	}
 	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);
Signature · 1 line
1.7.4.2
#10 lore raw

PATCH 9/10 scsi: decode descriptor sense

In reply to Hannes Reinecke

Decode descriptor sense buffer to provide the same information as we are already getting from fixed format sense.

---
 drivers/scsi/constants.c  |   79 +++++++++++++++------------------------------
 drivers/scsi/scsi_error.c |   43 +++++++++++++++++++++++-
 include/scsi/scsi_eh.h    |    8 +++-
 3 files changed, 73 insertions(+), 57 deletions(-)
drivers/scsi/constants.c +26 -53
index 8bf2616..df69ba3 100644
@@ -1376,61 +1376,34 @@ 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]);
-		}
+	int res = 0;
+	char buff[80];
+	int blen = sense_len;
 
-		printk("\n");
-	}
+	if (sshdr->info)
+		res += snprintf(buff + res, blen - res,
+				"Info fld=0x%llx", sshdr->info);
 
+	if (sshdr->flags & SCSI_SENSE_FLAG_FMK) {
+		/* current command has read a filemark */
+		if (res > 0)
+			res += snprintf(buff + res, blen - res, ", ");
+		res += snprintf(buff + res, blen - res, "FMK");
+	}
+	if (sshdr->flags & SCSI_SENSE_FLAG_EOM) {
+		/* end-of-medium condition exists */
+		if (res > 0)
+			res += snprintf(buff + res, blen - res, ", ");
+		res += snprintf(buff + res, blen - res, "EOM");
+	}
+	if (sshdr->flags & SCSI_SENSE_FLAG_ILI) {
+		/* incorrect block length requested */
+		if (res > 0)
+			res += snprintf(buff + res, blen - res, ", ");
+		res += snprintf(buff + res, blen - res, "ILI");
+	}
+	if (res > 0)
+		pr_info("%s\n", buff);
 }
 
 /* Normalize and print sense buffer with name prefix */
drivers/scsi/scsi_error.c +41 -2

73 lines not on this page · raw message

include/scsi/scsi_eh.h +6 -2
index 06a8790..3472448 100644
@@ -21,10 +21,14 @@ struct scsi_sense_hdr {		/* See SPC-3 section 4.5 */
 	u8 sense_key;
 	u8 asc;
 	u8 ascq;
-	u8 byte4;
-	u8 byte5;
+	u8 flags;
+#define SCSI_SENSE_FLAG_FMK  0x8
+#define SCSI_SENSE_FLAG_EOM 0x4
+#define SCSI_SENSE_FLAG_ILI 0x2
+	u8 fru;
 	u8 byte6;
 	u8 additional_length;	/* always 0 for fixed sense format */
+	u64 info;
 };
 
 static inline int scsi_sense_valid(struct scsi_sense_hdr *sshdr)
Signature · 1 line
1.7.4.2
#11 lore raw

PATCH 10/10 scsi: use local buffer for decoding sense data

In reply to Hannes Reinecke

Instead of printing directly to console we should be using a local buffer for formatting sense data.
This will avoid garbled output.

---
 drivers/scsi/constants.c |  102 +++++++++++++++++++++++++--------------------
 drivers/scsi/sd.c        |   10 +++--
 include/scsi/scsi_dbg.h  |    4 +-
 3 files changed, 65 insertions(+), 51 deletions(-)
drivers/scsi/constants.c +57 -45
index df69ba3..9115233 100644
@@ -1299,49 +1299,52 @@ 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(char *buf, int buf_len,
+		     unsigned char asc, unsigned char ascq)
 {
-        const char *extd_sense_fmt = scsi_extd_sense_format(asc, ascq);
+	const char *extd_sense_fmt = scsi_extd_sense_format(asc, ascq);
+	int sz = 0;
 
 	if (extd_sense_fmt) {
 		if (strstr(extd_sense_fmt, "%x")) {
-			printk("Add. Sense: ");
-			printk(extd_sense_fmt, ascq);
+			sz = snprintf(buf, buf_len, "Add. Sense: ");
+			sz += snprintf(buf + sz, buf_len - sz,
+				       extd_sense_fmt, ascq);
 		} else
-			printk("Add. Sense: %s", extd_sense_fmt);
+			sz = snprintf(buf, buf_len, "Add. Sense: %s",
+				      extd_sense_fmt);
 	} 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);
+			snprintf(buf, buf_len, "<<vendor>> ASC=0x%x ASCQ=0x%x",
+				 asc, ascq);
+		else if (ascq >= 0x80)
+			snprintf(buf, buf_len, "ASC=0x%x <<vendor>> ASCQ=0x%x",
+				 asc, ascq);
 		else
-			printk("ASC=0x%x ASCQ=0x%x", asc, ascq);
+			snprintf(buf, buf_len, "ASC=0x%x ASCQ=0x%x", asc, ascq);
 	}
-
-	printk("\n");
 }
 EXPORT_SYMBOL(scsi_show_extd_sense);
 
 void
-scsi_show_sense_hdr(struct scsi_sense_hdr *sshdr)
+scsi_show_sense_hdr(char *buf, int buf_len, struct scsi_sense_hdr *sshdr)
 {
 	const char *sense_txt;
+	int sz;
 
 	sense_txt = scsi_sense_key_string(sshdr->sense_key);
 	if (sense_txt)
-		printk("Sense Key : %s ", sense_txt);
+		sz = snprintf(buf, buf_len, "Sense Key : %s ", sense_txt);
 	else
-		printk("Sense Key : 0x%x ", sshdr->sense_key);
+		sz = snprintf(buf, buf_len, "Sense Key : 0x%x ",
+			      sshdr->sense_key);
 
-	printk("%s", scsi_sense_is_deferred(sshdr) ? "[deferred] " :
-	       "[current] ");
+	sz += snprintf(buf + sz, buf_len - sz, "%s",
+		       scsi_sense_is_deferred(sshdr) ?
+		       "[deferred] " : "[current] ");
 
 	if (sshdr->response_code >= 0x72)
-		printk("[descriptor]");
-
-	printk("\n");
+		sz += snprintf(buf + sz, buf_len - sz, "[descriptor]");
 }
 EXPORT_SYMBOL(scsi_show_sense_hdr);
 
@@ -1351,10 +1354,12 @@ EXPORT_SYMBOL(scsi_show_sense_hdr);
 void
 scsi_print_sense_hdr(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);
+	char sense_buf[128];
+
+	scsi_show_sense_hdr(sense_buf, 128, sshdr);
+	pr_info("%s: %s", name, sense_buf);
+	scsi_show_extd_sense(sense_buf, 128, sshdr->asc, sshdr->ascq);
+	pr_info("%s: %s", name, sense_buf);
 }
 EXPORT_SYMBOL(scsi_print_sense_hdr);
 
@@ -1365,20 +1370,21 @@ 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);
+	char sense_buf[128];
+
+	scsi_show_sense_hdr(sense_buf, 128, sshdr);
+	scmd_printk(KERN_INFO, scmd, "%s: %s", desc, sense_buf);
+	scsi_show_extd_sense(sense_buf, 128, sshdr->asc, sshdr->ascq);
+	scmd_printk(KERN_INFO, scmd, "%s: %s", desc, sense_buf);
 }
 EXPORT_SYMBOL(scsi_cmd_print_sense_hdr);
 
-static void
-scsi_decode_sense_extras(const unsigned char *sense_buffer, int sense_len,
+static int
+scsi_decode_sense_extras(char *buff, int buff_len,
 			 struct scsi_sense_hdr *sshdr)
 {
 	int res = 0;
-	char buff[80];
-	int blen = sense_len;
+	int blen = buff_len;
 
 	if (sshdr->info)
 		res += snprintf(buff + res, blen - res,
@@ -1402,8 +1408,7 @@ scsi_decode_sense_extras(const unsigned char *sense_buffer, int sense_len,
 			res += snprintf(buff + res, blen - res, ", ");
 		res += snprintf(buff + res, blen - res, "ILI");
 	}
-	if (res > 0)
-		pr_info("%s\n", buff);
+	return res;
 }
 
 /* Normalize and print sense buffer with name prefix */
@@ -1411,6 +1416,8 @@ void __scsi_print_sense(const char *name, const unsigned char *sense_buffer,
 			int sense_len)
 {
 	struct scsi_sense_hdr sshdr;
+	char sense_buf[128];
+	int len;
 
 	if (!scsi_normalize_sense(sense_buffer, sense_len, &sshdr)) {
 		/* this may be SCSI-1 sense data */
@@ -1420,11 +1427,13 @@ void __scsi_print_sense(const char *name, const unsigned char *sense_buffer,
 			       16, 1, sense_buffer, num, false);
 		return;
 	}
+	scsi_show_sense_hdr(sense_buf, 128, &sshdr);
+	pr_info("%s: %s", name, sense_buf);
+	len = scsi_decode_sense_extras(sense_buf, 128, &sshdr);
+	if (len)
+		pr_info("%s: %s", name, sense_buf);
+	scsi_show_extd_sense(sense_buf, 128, sshdr.asc, sshdr.ascq);
 	printk(KERN_INFO "%s: ", name);
-	scsi_show_sense_hdr(&sshdr);
-	scsi_decode_sense_extras(sense_buffer, sense_len, &sshdr);
-	printk(KERN_INFO "%s: ", name);
-	scsi_show_extd_sense(sshdr.asc, sshdr.ascq);
 }
 EXPORT_SYMBOL(__scsi_print_sense);
 
@@ -1432,6 +1441,8 @@ EXPORT_SYMBOL(__scsi_print_sense);
 void scsi_print_sense(char *name, struct scsi_cmnd *cmd)
 {
 	struct scsi_sense_hdr sshdr;
+	char sense_buf[128];
+	int len;
 
 	if (!scsi_normalize_sense(cmd->sense_buffer, SCSI_SENSE_BUFFERSIZE,
 				  &sshdr)) {
@@ -1442,12 +1453,13 @@ void scsi_print_sense(char *name, struct scsi_cmnd *cmd)
 			       false);
 		return;
 	}
-	scmd_printk(KERN_INFO, cmd, " ");
-	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_show_sense_hdr(sense_buf, 128, &sshdr);
+	scmd_printk(KERN_INFO, cmd, "%s", sense_buf);
+	len = scsi_decode_sense_extras(sense_buf, 128, &sshdr);
+	if (len)
+		scmd_printk(KERN_INFO, cmd, "%s", sense_buf);
+	scsi_show_extd_sense(sense_buf, 128, sshdr.asc, sshdr.ascq);
+	scmd_printk(KERN_INFO, cmd, "%s", sense_buf);
 }
 EXPORT_SYMBOL(scsi_print_sense);
 
drivers/scsi/sd.c +6 -4
index f6165e6..0c3d8e6 100644
@@ -3017,10 +3017,12 @@ 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);
+	char sense_buf[128];
+
+	scsi_show_sense_hdr(sense_buf, 128, sshdr);
+	sd_printk(KERN_INFO, sdkp, "%s", sense_buf);
+	scsi_show_extd_sense(sense_buf, 128, sshdr->asc, sshdr->ascq);
+	sd_printk(KERN_INFO, sdkp, "%s", sense_buf);
 }
 
 static void sd_print_result(struct scsi_disk *sdkp, int result)
include/scsi/scsi_dbg.h +2 -2
index cc6abb4..301ce7d 100644
@@ -6,8 +6,8 @@ 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_show_extd_sense(char *, int, unsigned char, unsigned char);
+extern void scsi_show_sense_hdr(char *, int, 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 *);
Signature · 1 line
1.7.4.2
#12 lore raw
In reply to Hannes Reinecke
Quoted 26 lines · Hannes Reinecke

This patchset updates the SCSI midlayer to use dev_printk() instead of the simple printk(). The main objective here is to avoid line-breaks in syslog output; with the current state it's nearly impossible to match the output to the occurring device; under high load even the CDB will be split off into individual bytes, spread randomly across the lines. Which makes debugging via scsi_logging_level _really_ hard. In addition we'll be getting the syslog messages nicely prefixed with the device, which will make userspace logging daemons happy.

Before:

[  297.300605] sd 2:0:3:2: Send:
[  297.300607] 0xffff8802348b0980
[  297.300610] sd 2:0:3:2: CDB:
[  297.300615] Test Unit Ready: 00 00 00 00 00 00
[  297.300747] sd 2:0:3:2: Done:
[  297.300750] 0xffff8802348b0980 SUCCESS
[  297.300753] sd 2:0:3:2:
[  297.300755] Result: hostbyte=DID_OK driverbyte=DRIVER_OK
[  297.300758] sd 2:0:3:2: CDB:
[  297.300764] Test Unit Ready: 00 00 00 00 00 00
[  297.300766] sd 2:0:3:2:
[  297.300769] Sense Key : Unit Attention [current]
[  297.300771] Info fld=0x0
[  297.300772] sd 2:0:3:2:
[  297.300776] Add. Sense: Capacity data has changed
Quoted 8 lines

After:

[  636.683556] sd 2:0:3:2: Send: 0xffff88043145eec0
[  636.727856] sd 2:0:3:2: CDB: Test Unit Ready: 00 00 00 00 00 00
[  636.785330] sd 2:0:3:2: Done: 0xffff88043145eec0 SUCCESS
[  636.838228] sd 2:0:3:2: Result: hostbyte=DID_OK driverbyte=DRIVER_OK
[  636.899099] sd 2:0:3:2: CDB: Test Unit Ready: 00 00 00 00 00 00
[  636.955905] sd 2:0:3:2: Sense Key : Unit Attention [current]
[  637.069179] sd 2:0:3:2: Add. Sense: Capacity data has changed

I know there are a lot of changes here but shouldn't all this get fixed in stable 3.5+?

Thanks for sorting all this out Hannes.

#13 lore raw
Quoted 36 lines · Mike Snitzer
Quoted 26 lines · Hannes Reinecke

This patchset updates the SCSI midlayer to use dev_printk() instead of the simple printk(). The main objective here is to avoid line-breaks in syslog output; with the current state it's nearly impossible to match the output to the occurring device; under high load even the CDB will be split off into individual bytes, spread randomly across the lines. Which makes debugging via scsi_logging_level _really_ hard. In addition we'll be getting the syslog messages nicely prefixed with the device, which will make userspace logging daemons happy.

Before:

[  297.300605] sd 2:0:3:2: Send:
[  297.300607] 0xffff8802348b0980
[  297.300610] sd 2:0:3:2: CDB:
[  297.300615] Test Unit Ready: 00 00 00 00 00 00
[  297.300747] sd 2:0:3:2: Done:
[  297.300750] 0xffff8802348b0980 SUCCESS
[  297.300753] sd 2:0:3:2:
[  297.300755] Result: hostbyte=DID_OK driverbyte=DRIVER_OK
[  297.300758] sd 2:0:3:2: CDB:
[  297.300764] Test Unit Ready: 00 00 00 00 00 00
[  297.300766] sd 2:0:3:2:
[  297.300769] Sense Key : Unit Attention [current]
[  297.300771] Info fld=0x0
[  297.300772] sd 2:0:3:2:
[  297.300776] Add. Sense: Capacity data has changed
Quoted 8 lines

After:

[  636.683556] sd 2:0:3:2: Send: 0xffff88043145eec0
[  636.727856] sd 2:0:3:2: CDB: Test Unit Ready: 00 00 00 00 00 00
[  636.785330] sd 2:0:3:2: Done: 0xffff88043145eec0 SUCCESS
[  636.838228] sd 2:0:3:2: Result: hostbyte=DID_OK driverbyte=DRIVER_OK
[  636.899099] sd 2:0:3:2: CDB: Test Unit Ready: 00 00 00 00 00 00
[  636.955905] sd 2:0:3:2: Sense Key : Unit Attention [current]
[  637.069179] sd 2:0:3:2: Add. Sense: Capacity data has changed
Quoted 3 lines

I know there are a lot of changes here but shouldn't all this get fixed in stable 3.5+?

If you ask me, yes, of course.
I can easily post a v2 of the patchset (meanwhile I've got another patch for st :-), Cc'ing stable with it.

Cheers,

Hannes

Signature · 8 lines
Dr. Hannes Reinecke		      zSeries & Storage
[email protected]			      +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 [email protected]
More majordomo info at  http://vger.kernel.org/majordomo-info.html
#14 lore raw
In reply to Hannes Reinecke

Hi Hannes, James,

I'm wondering what happened to this patch-set? I think it could make parsing of the output for userspace programs much easier. Are there some problems still to solve or is this just forgotten?

Thanks,
Tomas

Quoted 61 lines · Hannes Reinecke

This patchset updates the SCSI midlayer to use dev_printk() instead of the simple printk(). The main objective here is to avoid line-breaks in syslog output; with the current state it's nearly impossible to match the output to the occurring device; under high load even the CDB will be split off into individual bytes, spread randomly across the lines. Which makes debugging via scsi_logging_level _really_ hard. In addition we'll be getting the syslog messages nicely prefixed with the device, which will make userspace logging daemons happy.

Before:

[  297.300605] sd 2:0:3:2: Send: 
[  297.300607] 0xffff8802348b0980 
[  297.300610] sd 2:0:3:2: CDB: 
[  297.300615] Test Unit Ready: 00 00 00 00 00 00
[  297.300747] sd 2:0:3:2: Done: 
[  297.300750] 0xffff8802348b0980 SUCCESS
[  297.300753] sd 2:0:3:2:  
[  297.300755] Result: hostbyte=DID_OK driverbyte=DRIVER_OK
[  297.300758] sd 2:0:3:2: CDB: 
[  297.300764] Test Unit Ready: 00 00 00 00 00 00
[  297.300766] sd 2:0:3:2:  
[  297.300769] Sense Key : Unit Attention [current] 
[  297.300771] Info fld=0x0
[  297.300772] sd 2:0:3:2:  
[  297.300776] Add. Sense: Capacity data has changed

After:

[  636.683556] sd 2:0:3:2: Send: 0xffff88043145eec0
[  636.727856] sd 2:0:3:2: CDB: Test Unit Ready: 00 00 00 00 00 00
[  636.785330] sd 2:0:3:2: Done: 0xffff88043145eec0 SUCCESS
[  636.838228] sd 2:0:3:2: Result: hostbyte=DID_OK driverbyte=DRIVER_OK
[  636.899099] sd 2:0:3:2: CDB: Test Unit Ready: 00 00 00 00 00 00
[  636.955905] sd 2:0:3:2: Sense Key : Unit Attention [current] 
[  637.069179] sd 2:0:3:2: Add. Sense: Capacity data has changed

Hannes Reinecke (10):
sg: Use dev_printk
sr: Use dev_printk()
scsi: Avoid linebreaks in syslog output
scsi: Use sdev_printk() for logging
scsi: use buffer for print_opcode_name()
scsi: use single printk call in scsi_print_command()
scsi: use buffer for scsi_show_result()
scsi: open-code scsi_decode_sense_buffer()
scsi: decode descriptor sense
scsi: use local buffer for decoding sense data

 drivers/scsi/constants.c  |  406 +++++++++++++++++++++++++--------------------
 drivers/scsi/scsi.c       |   54 ++++---
 drivers/scsi/scsi_error.c |  190 ++++++++++++++-------
 drivers/scsi/scsi_lib.c   |   13 +-
 drivers/scsi/scsi_scan.c  |   68 ++++----
 drivers/scsi/sd.c         |   16 +-
 drivers/scsi/sg.c         |  187 ++++++++++++---------
 drivers/scsi/sr.c         |   47 +++---
 drivers/scsi/sr.h         |    4 +
 include/scsi/scsi_dbg.h   |    6 +-
 include/scsi/scsi_eh.h    |    8 +-
 11 files changed, 588 insertions(+), 411 deletions(-)
#15 lore raw
Quoted 6 lines · Tomas Henzl

Hi Hannes, James,

I'm wondering what happened to this patch-set? I think it could make parsing of the output for userspace programs much easier. Are there some problems still to solve or is this just forgotten?

Oh, no. Quite the contrary.
As James has now merged my previous patchsets I'm in the process of updating this one, too.

It'll be part of a larger patchset having a per-device scsi_logging_level; something I was wanting to have for a _LONG_ time now.

Currently I'm fiddling with sense code printing, so I won't be able to send anything this year. But early next year I should have something presentable.

Cheers,

Hannes

Signature · 8 lines
Dr. Hannes Reinecke		      zSeries & Storage
[email protected]			      +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 [email protected]
More majordomo info at  http://vger.kernel.org/majordomo-info.html
#16 lore raw
Quoted 11 lines · Hannes Reinecke
Quoted 6 lines · Tomas Henzl

Hi Hannes, James,

I'm wondering what happened to this patch-set? I think it could make parsing of the output for userspace programs much easier. Are there some problems still to solve or is this just forgotten?

Oh, no. Quite the contrary.
As James has now merged my previous patchsets I'm in the process of updating this one, too.

Quoted 7 lines

It'll be part of a larger patchset having a per-device scsi_logging_level; something I was wanting to have for a _LONG_ time now.

Currently I'm fiddling with sense code printing, so I won't be able to send anything this year. But early next year I should have something presentable.

Great news! thanks.

Quoted 4 lines

Cheers,

Hannes