[PATCH 0/4] ide-tape: misc stuff

[PATCH 0/4] ide-tape: misc stuff

[Borislav Petkov]

Hi David,

here is some ide-tape stuff.

* 0001: somehow fell through the cracks, DEBUG build fix

* 0002: mostly code unification

* 0003: this one converts ide-tape to the debugging scheme we use with ide-cd
  and ide-floppy. It adds some debug calls at important places and has proven
  very helpful when working on bug reports with users. No functional change.

* 0004: real bugfix

The patches are also at

	git://git.kernel.org/pub/scm/linux/kernel/git/bp/bp.git ide-tape-postponed


--
Thanks,
Boris.

[PATCH 1/4] ide-tape: fix debug call

[Borislav Petkov]

From: Mark de Wever <koraq@xs4all.nl>

This error only occurs when IDETAPE_DEBUG_LOG is enabled.

Signed-off-by: Mark de Wever <koraq@xs4all.nl>
---
 drivers/ide/ide-tape.c |    2 +-
 1 files changed, 1 insertions(+), 1 deletions(-)

diff --git a/drivers/ide/ide-tape.c b/drivers/ide/ide-tape.c
index 013dc59..60d5c41 100644
--- a/drivers/ide/ide-tape.c
+++ b/drivers/ide/ide-tape.c
@@ -583,7 +583,7 @@ static ide_startstop_t idetape_do_request(ide_drive_t *drive,
 	struct ide_cmd cmd;
 	u8 stat;
 
-	debug_log(DBG_SENSE, "sector: %llu, nr_sectors: %u\n"
+	debug_log(DBG_SENSE, "sector: %llu, nr_sectors: %u\n",
 		  (unsigned long long)blk_rq_pos(rq), blk_rq_sectors(rq));
 
 	BUG_ON(!(blk_special_request(rq) || blk_sense_request(rq)));
-- 
1.6.3.1

[PATCH 2/4] ide-tape: use PFX to all printks

[Borislav Petkov]

There should be no functional change resulting from this patch.

Signed-off-by: Borislav Petkov <petkovbb@gmail.com>
---
 drivers/ide/ide-tape.c |   95 ++++++++++++++++++++++++------------------------
 1 files changed, 47 insertions(+), 48 deletions(-)

diff --git a/drivers/ide/ide-tape.c b/drivers/ide/ide-tape.c
index 60d5c41..db05a95 100644
--- a/drivers/ide/ide-tape.c
+++ b/drivers/ide/ide-tape.c
@@ -16,6 +16,7 @@
  */
 
 #define DRV_NAME "ide-tape"
+#define PFX DRV_NAME ": "
 
 #define IDETAPE_VERSION "1.20"
 
@@ -356,8 +357,8 @@ static int ide_tape_callback(ide_drive_t *drive, int dsc)
 		if (uptodate)
 			idetape_analyze_error(drive);
 		else
-			printk(KERN_ERR "ide-tape: Error in REQUEST SENSE "
-					"itself - Aborting request!\n");
+			printk(KERN_ERR PFX "Error in REQUEST SENSE itself -  "
+			       "Aborting request!\n");
 	} else if (pc->c[0] == READ_6 || pc->c[0] == WRITE_6) {
 		unsigned int blocks =
 			(blk_rq_bytes(rq) - rq->resid_len) / tape->blk_size;
@@ -472,9 +473,9 @@ static ide_startstop_t ide_tape_issue_pc(ide_drive_t *drive,
 			if (!(pc->c[0] == TEST_UNIT_READY &&
 			      tape->sense_key == 2 && tape->asc == 4 &&
 			     (tape->ascq == 1 || tape->ascq == 8))) {
-				printk(KERN_ERR "ide-tape: %s: I/O error, "
-						"pc = %2x, key = %2x, "
-						"asc = %2x, ascq = %2x\n",
+				printk(KERN_ERR PFX "%s: I/O error, pc = %2x, "
+						"key = %2x, asc = %2x, "
+						"ascq = %2x\n",
 						tape->name, pc->c[0],
 						tape->sense_key, tape->asc,
 						tape->ascq);
@@ -535,8 +536,8 @@ static ide_startstop_t idetape_media_access_finished(ide_drive_t *drive)
 		if (stat & ATA_ERR) {
 			/* Error detected */
 			if (pc->c[0] != TEST_UNIT_READY)
-				printk(KERN_ERR "ide-tape: %s: I/O error, ",
-						tape->name);
+				printk(KERN_ERR PFX "%s: I/O error, ",
+				       tape->name);
 			/* Retry operation */
 			ide_retry_pc(drive);
 			return ide_stopped;
@@ -596,8 +597,9 @@ static ide_startstop_t idetape_do_request(ide_drive_t *drive,
 
 	if (postponed_rq != NULL)
 		if (rq != postponed_rq) {
-			printk(KERN_ERR "ide-tape: ide-tape.c bug - "
-					"Two DSC requests were queued\n");
+			printk(KERN_ERR PFX "%s: BUG: Two DSC requests "
+					    "queued!\n",
+					    tape->name);
 			drive->failed_pc = NULL;
 			rq->errors = 0;
 			ide_complete_rq(drive, 0, blk_rq_bytes(rq));
@@ -628,8 +630,8 @@ static ide_startstop_t idetape_do_request(ide_drive_t *drive,
 			tape->dsc_poll_freq = tape->best_dsc_rw_freq;
 			tape->dsc_timeout = jiffies + IDETAPE_DSC_RW_TIMEOUT;
 		} else if (time_after(jiffies, tape->dsc_timeout)) {
-			printk(KERN_ERR "ide-tape: %s: DSC timeout\n",
-				tape->name);
+			printk(KERN_ERR PFX "%s: DSC timeout\n", tape->name);
+
 			if (rq->cmd[13] & REQ_IDETAPE_PC2) {
 				idetape_media_access_finished(drive);
 				return ide_stopped;
@@ -762,8 +764,8 @@ static int ide_tape_read_position(ide_drive_t *drive)
 				(buf[0] & 0x40) ? "Yes" : "No");
 
 		if (buf[0] & 0x4) {
-			printk(KERN_INFO "ide-tape: Block location is unknown"
-					 "to the tape\n");
+			printk(KERN_INFO PFX "%s: Block location unknown\n",
+			       tape->name);
 			clear_bit(ilog2(IDE_AFLAG_ADDRESS_VALID),
 				  &drive->atapi_flags);
 			return -1;
@@ -849,8 +851,8 @@ static void ide_tape_discard_merge_buffer(ide_drive_t *drive,
 		position = ide_tape_read_position(drive);
 		seek = position > 0 ? position : 0;
 		if (idetape_position_tape(drive, seek, 0, 0)) {
-			printk(KERN_INFO "ide-tape: %s: position_tape failed in"
-					 " %s\n", tape->name, __func__);
+			printk(KERN_INFO PFX "position_tape failed in %s\n",
+			       tape->name);
 			return;
 		}
 	}
@@ -939,8 +941,8 @@ static void ide_tape_flush_merge_buffer(ide_drive_t *drive)
 	idetape_tape_t *tape = drive->driver_data;
 
 	if (tape->chrdev_dir != IDETAPE_DIR_WRITE) {
-		printk(KERN_ERR "ide-tape: bug: Trying to empty merge buffer"
-				" but we are not writing.\n");
+		printk(KERN_ERR PFX "BUG: Trying to empty merge buffer"
+			" but we are not writing.\n");
 		return;
 	}
 	if (tape->buf) {
@@ -972,7 +974,7 @@ static int idetape_init_rw(ide_drive_t *drive, int dir)
 	}
 
 	if (tape->buf || tape->valid) {
-		printk(KERN_ERR "ide-tape: valid should be 0 now\n");
+		printk(KERN_ERR PFX "valid should be 0 now\n");
 		tape->valid = 0;
 	}
 
@@ -1117,7 +1119,7 @@ static int idetape_space_over_filemarks(ide_drive_t *drive, short mt_op,
 		count = (MTBSFM == mt_op ? 1 : -1);
 		return idetape_space_over_filemarks(drive, MTFSF, count);
 	default:
-		printk(KERN_ERR "ide-tape: MTIO operation %d not supported\n",
+		printk(KERN_ERR PFX "MTIO operation %d not supported\n",
 				mt_op);
 		return -EIO;
 	}
@@ -1246,7 +1248,7 @@ static int idetape_write_filemark(ide_drive_t *drive)
 	/* Write a filemark */
 	idetape_create_write_filemark_cmd(drive, &pc, 1);
 	if (ide_queue_pc_tail(drive, tape->disk, &pc, NULL, 0)) {
-		printk(KERN_ERR "ide-tape: Couldn't write a filemark\n");
+		printk(KERN_ERR PFX "Couldn't write a filemark\n");
 		return -EIO;
 	}
 	return 0;
@@ -1370,8 +1372,7 @@ static int idetape_mtioctop(ide_drive_t *drive, short mt_op, int mt_count)
 		tape->door_locked = DOOR_UNLOCKED;
 		return 0;
 	default:
-		printk(KERN_ERR "ide-tape: MTIO operation %d not supported\n",
-				mt_op);
+		printk(KERN_ERR PFX "MTIO operation %d not supported\n", mt_op);
 		return -EIO;
 	}
 }
@@ -1448,10 +1449,10 @@ static void ide_tape_get_bsize_from_bdesc(ide_drive_t *drive)
 
 	idetape_create_mode_sense_cmd(&pc, IDETAPE_BLOCK_DESCRIPTOR);
 	if (ide_queue_pc_tail(drive, tape->disk, &pc, buf, pc.req_xfer)) {
-		printk(KERN_ERR "ide-tape: Can't get block descriptor\n");
+		printk(KERN_ERR PFX "Can't get block descriptor\n");
 		if (tape->blk_size == 0) {
-			printk(KERN_WARNING "ide-tape: Cannot deal with zero "
-					    "block size, assuming 32k\n");
+			printk(KERN_WARNING PFX "Cannot deal with zero block "
+						"size, assuming 32k\n");
 			tape->blk_size = 32768;
 		}
 		return;
@@ -1500,7 +1501,7 @@ static int idetape_chrdev_open(struct inode *inode, struct file *filp)
 	retval = idetape_wait_ready(drive, 60 * HZ);
 	if (retval) {
 		clear_bit(ilog2(IDE_AFLAG_BUSY), &drive->atapi_flags);
-		printk(KERN_ERR "ide-tape: %s: drive not ready\n", tape->name);
+		printk(KERN_ERR PFX "%s: drive not ready\n", tape->name);
 		goto out_put_tape;
 	}
 
@@ -1603,8 +1604,8 @@ static void idetape_get_inquiry_results(ide_drive_t *drive)
 
 	idetape_create_inquiry_cmd(&pc);
 	if (ide_queue_pc_tail(drive, tape->disk, &pc, pc_buf, pc.req_xfer)) {
-		printk(KERN_ERR "ide-tape: %s: can't get INQUIRY results\n",
-				tape->name);
+		printk(KERN_ERR PFX "%s: can't get INQUIRY results\n",
+		       tape->name);
 		return;
 	}
 	memcpy(vendor_id, &pc_buf[8], 8);
@@ -1615,8 +1616,8 @@ static void idetape_get_inquiry_results(ide_drive_t *drive)
 	ide_fixstring(product_id, 16, 0);
 	ide_fixstring(fw_rev, 4, 0);
 
-	printk(KERN_INFO "ide-tape: %s <-> %s: %.8s %.16s rev %.4s\n",
-			drive->name, tape->name, vendor_id, product_id, fw_rev);
+	printk(KERN_INFO PFX "%s <-> %s: %.8s %.16s rev %.4s\n",
+	       drive->name, tape->name, vendor_id, product_id, fw_rev);
 }
 
 /*
@@ -1632,8 +1633,8 @@ static void idetape_get_mode_sense_results(ide_drive_t *drive)
 
 	idetape_create_mode_sense_cmd(&pc, IDETAPE_CAPABILITIES_PAGE);
 	if (ide_queue_pc_tail(drive, tape->disk, &pc, buf, pc.req_xfer)) {
-		printk(KERN_ERR "ide-tape: Can't get tape parameters - assuming"
-				" some default values\n");
+		printk(KERN_ERR PFX "Can't get tape parameters - assuming"
+				    " some default values\n");
 		tape->blk_size = 512;
 		put_unaligned(52,   (u16 *)&tape->caps[12]);
 		put_unaligned(540,  (u16 *)&tape->caps[14]);
@@ -1652,13 +1653,13 @@ static void idetape_get_mode_sense_results(ide_drive_t *drive)
 	*(u16 *)&caps[16] = be16_to_cpup((__be16 *)&caps[16]);
 
 	if (!speed) {
-		printk(KERN_INFO "ide-tape: %s: invalid tape speed "
-				"(assuming 650KB/sec)\n", drive->name);
+		printk(KERN_INFO PFX "%s: invalid tape speed "
+		       "(assuming 650KB/sec)\n", drive->name);
 		*(u16 *)&caps[14] = 650;
 	}
 	if (!max_speed) {
-		printk(KERN_INFO "ide-tape: %s: invalid max_speed "
-				"(assuming 650KB/sec)\n", drive->name);
+		printk(KERN_INFO PFX "%s: invalid max_speed "
+		       "(assuming 650KB/sec)\n", drive->name);
 		*(u16 *)&caps[8] = 650;
 	}
 
@@ -1750,8 +1751,7 @@ static void idetape_setup(ide_drive_t *drive, idetape_tape_t *tape, int minor)
 	drive->dev_flags |= IDE_DFLAG_DSC_OVERLAP;
 
 	if (drive->hwif->host_flags & IDE_HFLAG_NO_DSC) {
-		printk(KERN_INFO "ide-tape: %s: disabling DSC overlap\n",
-				 tape->name);
+		printk(KERN_INFO PFX "%s: disabling DSC overlap\n", tape->name);
 		drive->dev_flags &= ~IDE_DFLAG_DSC_OVERLAP;
 	}
 
@@ -1771,7 +1771,7 @@ static void idetape_setup(ide_drive_t *drive, idetape_tape_t *tape, int minor)
 	tape->user_bs_factor = 1;
 	tape->buffer_size = *ctl * tape->blk_size;
 	while (tape->buffer_size > 0xffff) {
-		printk(KERN_NOTICE "ide-tape: decreasing stage size\n");
+		printk(KERN_NOTICE PFX "decreasing stage size\n");
 		*ctl /= 2;
 		tape->buffer_size = *ctl * tape->blk_size;
 	}
@@ -1788,7 +1788,7 @@ static void idetape_setup(ide_drive_t *drive, idetape_tape_t *tape, int minor)
 	 */
 	tape->best_dsc_rw_freq = clamp_t(unsigned long, t, IDETAPE_DSC_RW_MIN,
 					 IDETAPE_DSC_RW_MAX);
-	printk(KERN_INFO "ide-tape: %s <-> %s: %dKBps, %d*%dkB buffer, "
+	printk(KERN_INFO PFX "%s <-> %s: %dKBps, %d*%dkB buffer, "
 		"%lums tDSC%s\n",
 		drive->name, tape->name, *(u16 *)&tape->caps[14],
 		(*(u16 *)&tape->caps[16] * 512) / tape->buffer_size,
@@ -1866,7 +1866,7 @@ static int ide_tape_probe(ide_drive_t *);
 static struct ide_driver idetape_driver = {
 	.gen_driver = {
 		.owner		= THIS_MODULE,
-		.name		= "ide-tape",
+		.name		= DRV_NAME,
 		.bus		= &ide_bus_type,
 	},
 	.probe			= ide_tape_probe,
@@ -1939,14 +1939,14 @@ static int ide_tape_probe(ide_drive_t *drive)
 
 	if ((drive->dev_flags & IDE_DFLAG_ID_READ) &&
 	    ide_check_atapi_device(drive, DRV_NAME) == 0) {
-		printk(KERN_ERR "ide-tape: %s: not supported by this version of"
-				" the driver\n", drive->name);
+		printk(KERN_ERR PFX "%s: not supported by this version of"
+		       " the driver\n", drive->name);
 		goto failed;
 	}
 	tape = kzalloc(sizeof(idetape_tape_t), GFP_KERNEL);
 	if (tape == NULL) {
-		printk(KERN_ERR "ide-tape: %s: Can't allocate a tape struct\n",
-				drive->name);
+		printk(KERN_ERR PFX "%s: Can't allocate a tape struct\n",
+		       drive->name);
 		goto failed;
 	}
 
@@ -2011,14 +2011,13 @@ static int __init idetape_init(void)
 	idetape_sysfs_class = class_create(THIS_MODULE, "ide_tape");
 	if (IS_ERR(idetape_sysfs_class)) {
 		idetape_sysfs_class = NULL;
-		printk(KERN_ERR "Unable to create sysfs class for ide tapes\n");
+		printk(KERN_ERR PFX "Unable to create sysfs class\n");
 		error = -EBUSY;
 		goto out;
 	}
 
 	if (register_chrdev(IDETAPE_MAJOR, "ht", &idetape_fops)) {
-		printk(KERN_ERR "ide-tape: Failed to register chrdev"
-				" interface\n");
+		printk(KERN_ERR PFX "Failed to register chrdev interface\n");
 		error = -EBUSY;
 		goto out_free_class;
 	}
-- 
1.6.3.1

[PATCH 3/4] ide-tape: convert to ide_debug_log macro

[Borislav Petkov]

Remove tape->debug_mask and use drive->debug_mask instead.

There should be no functional change resulting from this patch.

Signed-off-by: Borislav Petkov <petkovbb@gmail.com>
---
 drivers/ide/ide-tape.c |  102 +++++++++++++++++++++++-------------------------
 1 files changed, 49 insertions(+), 53 deletions(-)

diff --git a/drivers/ide/ide-tape.c b/drivers/ide/ide-tape.c
index db05a95..688667b 100644
--- a/drivers/ide/ide-tape.c
+++ b/drivers/ide/ide-tape.c
@@ -48,28 +48,13 @@
 #include <asm/unaligned.h>
 #include <linux/mtio.h>
 
-enum {
-	/* output errors only */
-	DBG_ERR =		(1 << 0),
-	/* output all sense key/asc */
-	DBG_SENSE =		(1 << 1),
-	/* info regarding all chrdev-related procedures */
-	DBG_CHRDEV =		(1 << 2),
-	/* all remaining procedures */
-	DBG_PROCS =		(1 << 3),
-};
-
 /* define to see debug info */
-#define IDETAPE_DEBUG_LOG		0
+#undef IDETAPE_DEBUG_LOG
 
-#if IDETAPE_DEBUG_LOG
-#define debug_log(lvl, fmt, args...)			\
-{							\
-	if (tape->debug_mask & lvl)			\
-	printk(KERN_INFO "ide-tape: " fmt, ## args);	\
-}
+#ifdef IDETAPE_DEBUG_LOG
+#define ide_debug_log(lvl, fmt, args...) __ide_debug_log(lvl, fmt, ## args)
 #else
-#define debug_log(lvl, fmt, args...) do {} while (0)
+#define ide_debug_log(lvl, fmt, args...) do {} while (0)
 #endif
 
 /**************************** Tunable parameters *****************************/
@@ -231,8 +216,6 @@ typedef struct ide_tape_obj {
 	char drv_write_prot;
 	/* the tape is write protected (hardware or opened as read-only) */
 	char write_prot;
-
-	u32 debug_mask;
 } idetape_tape_t;
 
 static DEFINE_MUTEX(idetape_ref_mutex);
@@ -291,8 +274,9 @@ static void idetape_analyze_error(ide_drive_t *drive)
 	tape->asc       = sense[12];
 	tape->ascq      = sense[13];
 
-	debug_log(DBG_ERR, "pc = %x, sense key = %x, asc = %x, ascq = %x\n",
-		 pc->c[0], tape->sense_key, tape->asc, tape->ascq);
+	ide_debug_log(IDE_DBG_FUNC,
+		      "cmd: 0x%x, sense key = %x, asc = %x, ascq = %x",
+		      rq->cmd[0], tape->sense_key, tape->asc, tape->ascq);
 
 	/* correct remaining bytes to transfer */
 	if (pc->flags & PC_FLAG_DMA_ERROR)
@@ -345,7 +329,8 @@ static int ide_tape_callback(ide_drive_t *drive, int dsc)
 	int uptodate = pc->error ? 0 : 1;
 	int err = uptodate ? 0 : IDE_DRV_ERROR_GENERAL;
 
-	debug_log(DBG_PROCS, "Enter %s\n", __func__);
+	ide_debug_log(IDE_DBG_FUNC, "cmd: 0x%x, dsc: %d, err: %d", rq->cmd[0],
+		      dsc, err);
 
 	if (dsc)
 		ide_tape_handle_dsc(drive);
@@ -391,10 +376,12 @@ static int ide_tape_callback(ide_drive_t *drive, int dsc)
 static void idetape_postpone_request(ide_drive_t *drive)
 {
 	idetape_tape_t *tape = drive->driver_data;
+	struct request *rq = drive->hwif->rq;
 
-	debug_log(DBG_PROCS, "Enter %s\n", __func__);
+	ide_debug_log(IDE_DBG_FUNC, "cmd: 0x%x, dsc_poll_freq: %lu",
+		      rq->cmd[0], tape->dsc_poll_freq);
 
-	tape->postponed_rq = drive->hwif->rq;
+	tape->postponed_rq = rq;
 
 	ide_stall_queue(drive, tape->dsc_poll_freq);
 }
@@ -489,7 +476,8 @@ static ide_startstop_t ide_tape_issue_pc(ide_drive_t *drive,
 		ide_complete_rq(drive, -EIO, blk_rq_bytes(rq));
 		return ide_stopped;
 	}
-	debug_log(DBG_SENSE, "Retry #%d, cmd = %02X\n", pc->retries, pc->c[0]);
+	ide_debug_log(IDE_DBG_SENSE, "retry #%d, cmd: 0x%02x", pc->retries,
+		      pc->c[0]);
 
 	pc->retries++;
 
@@ -584,8 +572,9 @@ static ide_startstop_t idetape_do_request(ide_drive_t *drive,
 	struct ide_cmd cmd;
 	u8 stat;
 
-	debug_log(DBG_SENSE, "sector: %llu, nr_sectors: %u\n",
-		  (unsigned long long)blk_rq_pos(rq), blk_rq_sectors(rq));
+	ide_debug_log(IDE_DBG_RQ, "cmd: 0x%x, sector: %llu, nr_sectors: %u",
+		      rq->cmd[0], (unsigned long long)blk_rq_pos(rq),
+		      blk_rq_sectors(rq));
 
 	BUG_ON(!(blk_special_request(rq) || blk_sense_request(rq)));
 
@@ -747,7 +736,7 @@ static int ide_tape_read_position(ide_drive_t *drive)
 	struct ide_atapi_pc pc;
 	u8 buf[20];
 
-	debug_log(DBG_PROCS, "Enter %s\n", __func__);
+	ide_debug_log(IDE_DBG_FUNC, "enter");
 
 	/* prep cmd */
 	ide_init_pc(&pc);
@@ -758,9 +747,9 @@ static int ide_tape_read_position(ide_drive_t *drive)
 		return -1;
 
 	if (!pc.error) {
-		debug_log(DBG_SENSE, "BOP - %s\n",
+		ide_debug_log(IDE_DBG_FUNC, "BOP - %s",
 				(buf[0] & 0x80) ? "Yes" : "No");
-		debug_log(DBG_SENSE, "EOP - %s\n",
+		ide_debug_log(IDE_DBG_FUNC, "EOP - %s",
 				(buf[0] & 0x40) ? "Yes" : "No");
 
 		if (buf[0] & 0x4) {
@@ -770,8 +759,8 @@ static int ide_tape_read_position(ide_drive_t *drive)
 				  &drive->atapi_flags);
 			return -1;
 		} else {
-			debug_log(DBG_SENSE, "Block Location - %u\n",
-					be32_to_cpup((__be32 *)&buf[4]));
+			ide_debug_log(IDE_DBG_FUNC, "Block Location: %u",
+				      be32_to_cpup((__be32 *)&buf[4]));
 
 			tape->partition = buf[1];
 			tape->first_frame = be32_to_cpup((__be32 *)&buf[4]);
@@ -868,7 +857,8 @@ static int idetape_queue_rw_tail(ide_drive_t *drive, int cmd, int size)
 	struct request *rq;
 	int ret;
 
-	debug_log(DBG_SENSE, "%s: cmd=%d\n", __func__, cmd);
+	ide_debug_log(IDE_DBG_FUNC, "cmd: 0x%x, size: %d", cmd, size);
+
 	BUG_ON(cmd != REQ_IDETAPE_READ && cmd != REQ_IDETAPE_WRITE);
 	BUG_ON(size < 0 || size % tape->blk_size);
 
@@ -1031,7 +1021,7 @@ static int idetape_rewind_tape(ide_drive_t *drive)
 	struct ide_atapi_pc pc;
 	int ret;
 
-	debug_log(DBG_SENSE, "Enter %s\n", __func__);
+	ide_debug_log(IDE_DBG_FUNC, "enter");
 
 	idetape_create_rewind_cmd(drive, &pc);
 	ret = ide_queue_pc_tail(drive, disk, &pc, NULL, 0);
@@ -1057,7 +1047,7 @@ static int idetape_blkdev_ioctl(ide_drive_t *drive, unsigned int cmd,
 		int nr_stages;
 	} config;
 
-	debug_log(DBG_PROCS, "Enter %s\n", __func__);
+	ide_debug_log(IDE_DBG_FUNC, "cmd: 0x%04x", cmd);
 
 	switch (cmd) {
 	case 0x0340:
@@ -1086,6 +1076,9 @@ static int idetape_space_over_filemarks(ide_drive_t *drive, short mt_op,
 	int retval, count = 0;
 	int sprev = !!(tape->caps[4] & 0x20);
 
+
+	ide_debug_log(IDE_DBG_FUNC, "mt_op: %d, mt_count: %d", mt_op, mt_count);
+
 	if (mt_count == 0)
 		return 0;
 	if (MTBSF == mt_op || MTBSFM == mt_op) {
@@ -1149,7 +1142,7 @@ static ssize_t idetape_chrdev_read(struct file *file, char __user *buf,
 	ssize_t ret = 0;
 	int rc;
 
-	debug_log(DBG_CHRDEV, "Enter %s, count %Zd\n", __func__, count);
+	ide_debug_log(IDE_DBG_FUNC, "count %Zd", count);
 
 	if (tape->chrdev_dir != IDETAPE_DIR_READ) {
 		if (test_bit(ilog2(IDE_AFLAG_DETECT_BS), &drive->atapi_flags))
@@ -1188,8 +1181,6 @@ static ssize_t idetape_chrdev_read(struct file *file, char __user *buf,
 	}
 
 	if (!done && test_bit(ilog2(IDE_AFLAG_FILEMARK), &drive->atapi_flags)) {
-		debug_log(DBG_SENSE, "%s: spacing over filemark\n", tape->name);
-
 		idetape_space_over_filemarks(drive, MTFSF, 1);
 		return 0;
 	}
@@ -1210,7 +1201,7 @@ static ssize_t idetape_chrdev_write(struct file *file, const char __user *buf,
 	if (tape->write_prot)
 		return -EACCES;
 
-	debug_log(DBG_CHRDEV, "Enter %s, count %Zd\n", __func__, count);
+	ide_debug_log(IDE_DBG_FUNC, "count %Zd\n", count);
 
 	/* Initialize write operation */
 	rc = idetape_init_rw(drive, IDETAPE_DIR_WRITE);
@@ -1274,8 +1265,8 @@ static int idetape_mtioctop(ide_drive_t *drive, short mt_op, int mt_count)
 	struct ide_atapi_pc pc;
 	int i, retval;
 
-	debug_log(DBG_ERR, "Handling MTIOCTOP ioctl: mt_op=%d, mt_count=%d\n",
-			mt_op, mt_count);
+	ide_debug_log(IDE_DBG_FUNC, "MTIOCTOP ioctl: mt_op: %d, mt_count: %d",
+		      mt_op, mt_count);
 
 	switch (mt_op) {
 	case MTFSF:
@@ -1393,7 +1384,7 @@ static int idetape_chrdev_ioctl(struct inode *inode, struct file *file,
 	int block_offset = 0, position = tape->first_frame;
 	void __user *argp = (void __user *)arg;
 
-	debug_log(DBG_CHRDEV, "Enter %s, cmd=%u\n", __func__, cmd);
+	ide_debug_log(IDE_DBG_FUNC, "cmd: 0x%x", cmd);
 
 	if (tape->chrdev_dir == IDETAPE_DIR_WRITE) {
 		ide_tape_flush_merge_buffer(drive);
@@ -1461,6 +1452,9 @@ static void ide_tape_get_bsize_from_bdesc(ide_drive_t *drive)
 				(buf[4 + 6] << 8)  +
 				 buf[4 + 7];
 	tape->drv_write_prot = (buf[2] & 0x80) >> 7;
+
+	ide_debug_log(IDE_DBG_FUNC, "blk_size: %d, write_prot: %d",
+		      tape->blk_size, tape->drv_write_prot);
 }
 
 static int idetape_chrdev_open(struct inode *inode, struct file *filp)
@@ -1480,7 +1474,10 @@ static int idetape_chrdev_open(struct inode *inode, struct file *filp)
 		return -ENXIO;
 	}
 
-	debug_log(DBG_CHRDEV, "Enter %s\n", __func__);
+	drive = tape->drive;
+	filp->private_data = tape;
+
+	ide_debug_log(IDE_DBG_FUNC, "enter");
 
 	/*
 	 * We really want to do nonseekable_open(inode, filp); here, but some
@@ -1489,9 +1486,6 @@ static int idetape_chrdev_open(struct inode *inode, struct file *filp)
 	 */
 	filp->f_mode &= ~(FMODE_PREAD | FMODE_PWRITE);
 
-	drive = tape->drive;
-
-	filp->private_data = tape;
 
 	if (test_and_set_bit(ilog2(IDE_AFLAG_BUSY), &drive->atapi_flags)) {
 		retval = -EBUSY;
@@ -1570,7 +1564,7 @@ static int idetape_chrdev_release(struct inode *inode, struct file *filp)
 	lock_kernel();
 	tape = drive->driver_data;
 
-	debug_log(DBG_CHRDEV, "Enter %s\n", __func__);
+	ide_debug_log(IDE_DBG_FUNC, "enter");
 
 	if (tape->chrdev_dir == IDETAPE_DIR_WRITE)
 		idetape_write_release(drive, minor);
@@ -1707,7 +1701,6 @@ static int divf_buffer_size(ide_drive_t *drive)	{ return 1024; }
 
 ide_devset_rw_flag(dsc_overlap, IDE_DFLAG_DSC_OVERLAP);
 
-ide_tape_devset_rw_field(debug_mask, debug_mask);
 ide_tape_devset_rw_field(tdsc, best_dsc_rw_freq);
 
 ide_tape_devset_r_field(avg_speed, avg_speed);
@@ -1719,7 +1712,6 @@ static const struct ide_proc_devset idetape_settings[] = {
 	__IDE_PROC_DEVSET(avg_speed,	0, 0xffff, NULL, NULL),
 	__IDE_PROC_DEVSET(buffer,	0, 0xffff, NULL, divf_buffer),
 	__IDE_PROC_DEVSET(buffer_size,	0, 0xffff, NULL, divf_buffer_size),
-	__IDE_PROC_DEVSET(debug_mask,	0, 0xffff, NULL, NULL),
 	__IDE_PROC_DEVSET(dsc_overlap,	0,      1, NULL, NULL),
 	__IDE_PROC_DEVSET(speed,	0, 0xffff, NULL, NULL),
 	__IDE_PROC_DEVSET(tdsc,		IDETAPE_DSC_RW_MIN, IDETAPE_DSC_RW_MAX,
@@ -1746,7 +1738,9 @@ static void idetape_setup(ide_drive_t *drive, idetape_tape_t *tape, int minor)
 	int buffer_size;
 	u16 *ctl = (u16 *)&tape->caps[12];
 
-	drive->pc_callback	 = ide_tape_callback;
+	ide_debug_log(IDE_DBG_FUNC, "minor: %d", minor);
+
+	drive->pc_callback = ide_tape_callback;
 
 	drive->dev_flags |= IDE_DFLAG_DSC_OVERLAP;
 
@@ -1931,7 +1925,9 @@ static int ide_tape_probe(ide_drive_t *drive)
 	struct gendisk *g;
 	int minor;
 
-	if (!strstr("ide-tape", drive->driver_req))
+	ide_debug_log(IDE_DBG_FUNC, "enter");
+
+	if (!strstr(DRV_NAME, drive->driver_req))
 		goto failed;
 
 	if (drive->media != ide_tape)
-- 
1.6.3.1

[PATCH 4/4] ide-tape: fix handling of postponed rqs

[Borislav Petkov]

ide-tape used to hit

[   58.614854] ide-tape: ht0: BUG: Two DSC requests queued!

due to the fact that another rq was being issued while the driver was
waiting for DSC to get set for the device executing ATAPI commands which
set the DSC to 1 to indicate completion.

Here's a sample output of that case:

issue REZERO_UNIT

[  143.088505] ide-tape: ide_tape_issue_pc: retry #0, cmd: 0x01
[  143.095122] ide: Enter ide_pc_intr - interrupt handler
[  143.096118] ide: Packet command completed, 0 bytes transferred
[  143.106319] ide-tape: ide_tape_callback: cmd: 0x1, dsc: 1, err: 0
[  143.112601] ide-tape: idetape_postpone_request: cmd: 0x1, dsc_poll_freq: 2000

we stall the ide-tape queue here waiting for DSC

[  143.119936] ide-tape: ide_tape_read_position: enter
[  145.119019] ide-tape: idetape_do_request: sector: 4294967295, nr_sectors: 0

and issue the new READ_POSITION rq and hit the check.

[  145.126247] ide-tape: ht0: BUG: Two DSC requests queued!
[  145.131748] ide-tape: ide_tape_read_position: BOP - No
[  145.137059] ide-tape: ide_tape_read_position: EOP - No

Also, ->postponed_rq used to point to that postponed request. To make
things worse, in certain circumstances the rq it was pointing to got
replaced unterneath it by swiftly reusing the same rq from the mempool
of the block layer practically confusing stuff even more.

However, we don't need to keep a pointer to that rq but simply wait for
DSC to be set first before issuing the follow-up request in the drive's
queue. In order to do that, we make idetape_do_request() first check the
DSC and if not set, we stall the drive queue giving the other device on
that IDE channel a chance.

Signed-off-by: Borislav Petkov <petkovbb@gmail.com>
---
 drivers/ide/ide-tape.c |   31 ++++++++++---------------------
 1 files changed, 10 insertions(+), 21 deletions(-)

diff --git a/drivers/ide/ide-tape.c b/drivers/ide/ide-tape.c
index 688667b..0b9607b 100644
--- a/drivers/ide/ide-tape.c
+++ b/drivers/ide/ide-tape.c
@@ -156,7 +156,8 @@ typedef struct ide_tape_obj {
 	 * other device. Note that at most we will have only one DSC (usually
 	 * data transfer) request in the device request queue.
 	 */
-	struct request *postponed_rq;
+	bool postponed_rq;
+
 	/* The time in which we started polling for DSC */
 	unsigned long dsc_polling_start;
 	/* Timer used to poll for dsc */
@@ -373,7 +374,7 @@ static int ide_tape_callback(ide_drive_t *drive, int dsc)
  * Postpone the current request so that ide.c will be able to service requests
  * from another device on the same port while we are polling for DSC.
  */
-static void idetape_postpone_request(ide_drive_t *drive)
+static void ide_tape_stall_queue(ide_drive_t *drive)
 {
 	idetape_tape_t *tape = drive->driver_data;
 	struct request *rq = drive->hwif->rq;
@@ -381,7 +382,7 @@ static void idetape_postpone_request(ide_drive_t *drive)
 	ide_debug_log(IDE_DBG_FUNC, "cmd: 0x%x, dsc_poll_freq: %lu",
 		      rq->cmd[0], tape->dsc_poll_freq);
 
-	tape->postponed_rq = rq;
+	tape->postponed_rq = true;
 
 	ide_stall_queue(drive, tape->dsc_poll_freq);
 }
@@ -395,7 +396,7 @@ static void ide_tape_handle_dsc(ide_drive_t *drive)
 	tape->dsc_poll_freq = IDETAPE_DSC_MA_FAST;
 	tape->dsc_timeout = jiffies + IDETAPE_DSC_MA_TIMEOUT;
 	/* Allow ide.c to handle other requests */
-	idetape_postpone_request(drive);
+	ide_tape_stall_queue(drive);
 }
 
 /*
@@ -568,7 +569,6 @@ static ide_startstop_t idetape_do_request(ide_drive_t *drive,
 	ide_hwif_t *hwif = drive->hwif;
 	idetape_tape_t *tape = drive->driver_data;
 	struct ide_atapi_pc *pc = NULL;
-	struct request *postponed_rq = tape->postponed_rq;
 	struct ide_cmd cmd;
 	u8 stat;
 
@@ -584,19 +584,6 @@ static ide_startstop_t idetape_do_request(ide_drive_t *drive,
 		goto out;
 	}
 
-	if (postponed_rq != NULL)
-		if (rq != postponed_rq) {
-			printk(KERN_ERR PFX "%s: BUG: Two DSC requests "
-					    "queued!\n",
-					    tape->name);
-			drive->failed_pc = NULL;
-			rq->errors = 0;
-			ide_complete_rq(drive, 0, blk_rq_bytes(rq));
-			return ide_stopped;
-		}
-
-	tape->postponed_rq = NULL;
-
 	/*
 	 * If the tape is still busy, postpone our request and service
 	 * the other device meanwhile.
@@ -614,7 +601,7 @@ static ide_startstop_t idetape_do_request(ide_drive_t *drive,
 
 	if (!(drive->atapi_flags & IDE_AFLAG_IGNORE_DSC) &&
 	    !(stat & ATA_DSC)) {
-		if (postponed_rq == NULL) {
+		if (!tape->postponed_rq) {
 			tape->dsc_polling_start = jiffies;
 			tape->dsc_poll_freq = tape->best_dsc_rw_freq;
 			tape->dsc_timeout = jiffies + IDETAPE_DSC_RW_TIMEOUT;
@@ -631,10 +618,12 @@ static ide_startstop_t idetape_do_request(ide_drive_t *drive,
 					tape->dsc_polling_start +
 					IDETAPE_DSC_MA_THRESHOLD))
 			tape->dsc_poll_freq = IDETAPE_DSC_MA_SLOW;
-		idetape_postpone_request(drive);
+		ide_tape_stall_queue(drive);
 		return ide_stopped;
-	} else
+	} else {
 		drive->atapi_flags &= ~IDE_AFLAG_IGNORE_DSC;
+		tape->postponed_rq = false;
+	}
 
 	if (rq->cmd[13] & REQ_IDETAPE_READ) {
 		pc = &tape->queued_pc;
-- 
1.6.3.1

Re: [PATCH 0/4] ide-tape: misc stuff

[David Miller]

From: Borislav Petkov <petkovbb@googlemail.com>
Date: Wed, 15 Jul 2009 17:18:16 +0200

> here is some ide-tape stuff.
> 
> * 0001: somehow fell through the cracks, DEBUG build fix

This is OK.

> * 0002: mostly code unification

I'm not applying this.  IDE is in deep maintainence mode and
we really need to avoid changes that don't fix real bugs and
have only marginal benefit, like this change.

> * 0003: this one converts ide-tape to the debugging scheme we use with ide-cd
>   and ide-floppy. It adds some debug calls at important places and has proven
>   very helpful when working on bug reports with users. No functional change.

I'm not applying this for the same reason as patch #2.

> * 0004: real bugfix

Ok, did you test this?

Please respin patch #1 and #4 as a two patch set and resubmit.

Thank you.

Re: [PATCH 0/4] ide-tape: misc stuff

[Borislav Petkov]

On Wed, Jul 15, 2009 at 11:16:06AM -0700, David Miller wrote:
> From: Borislav Petkov <petkovbb@googlemail.com>
> Date: Wed, 15 Jul 2009 17:18:16 +0200
> 
> > here is some ide-tape stuff.
> > 
> > * 0001: somehow fell through the cracks, DEBUG build fix
> 
> This is OK.
> 
> > * 0002: mostly code unification
> 
> I'm not applying this.  IDE is in deep maintainence mode and
> we really need to avoid changes that don't fix real bugs and
> have only marginal benefit, like this change.
> 
> > * 0003: this one converts ide-tape to the debugging scheme we use with ide-cd
> >   and ide-floppy. It adds some debug calls at important places and has proven
> >   very helpful when working on bug reports with users. No functional change.
> 
> I'm not applying this for the same reason as patch #2.

Well, the downside to that is whenever there's a bug report and I want
the user to do a debug build and send me the output, I'll have to rehash
that debug patch and send it to her/him, maybe teach her/him how to
patch a kernel, build it and catch the output and send it my way before
we do some real work. Having the change upstream makes it _a_ _lot_
_more_ easier to do that and this is experience talking, we had several
scenarious like that already.

So, applying those would be of great help to me without the danger of
introducing any regressions but I guess, it's your call. Still, I'd
really appreciate it if you reconsidered.

Thanks.

> > * 0004: real bugfix
>
> Ok, did you test this?

Yes.

-- 
Regards/Gruss,
    Boris.

Re: [PATCH 0/4] ide-tape: misc stuff

[David Miller]

From: Borislav Petkov <petkovbb@googlemail.com>
Date: Wed, 15 Jul 2009 20:43:50 +0200

> Well, the downside to that is whenever there's a bug report and I want
> the user to do a debug build and send me the output, I'll have to rehash
> that debug patch and send it to her/him, maybe teach her/him how to
> patch a kernel, build it and catch the output and send it my way before
> we do some real work. Having the change upstream makes it _a_ _lot_
> _more_ easier to do that and this is experience talking, we had several
> scenarious like that already.

Your PFX patch has no effect at all, it's just cleanup noise.

The other patch moves the debug mask from one place to another,
why can't the debug selections bet set properly as is?

Re: [PATCH 0/4] ide-tape: misc stuff

[Borislav Petkov]

On Wed, Jul 15, 2009 at 12:41:50PM -0700, David Miller wrote:
> From: Borislav Petkov <petkovbb@googlemail.com>
> Date: Wed, 15 Jul 2009 20:43:50 +0200
> 
> > Well, the downside to that is whenever there's a bug report and I want
> > the user to do a debug build and send me the output, I'll have to rehash
> > that debug patch and send it to her/him, maybe teach her/him how to
> > patch a kernel, build it and catch the output and send it my way before
> > we do some real work. Having the change upstream makes it _a_ _lot_
> > _more_ easier to do that and this is experience talking, we had several
> > scenarious like that already.
> 
> Your PFX patch has no effect at all, it's just cleanup noise.

Yes, that one I don't need, I can drop it.

> The other patch moves the debug mask from one place to another,
> why can't the debug selections bet set properly as is?

Where the debug_mask is set is all the same to me, its the additional
information added to the debug calls that I care about. I don't mention
that in the commit message which is my bad, sorry, will fix. With those
you can actually follow what happens, for example:

[   51.945800] ide-tape: ide_tape_get_bsize_from_bdesc: blk_size: 512, write_prot: 0
[   51.945821] ide-tape: idetape_chrdev_ioctl: cmd: 0x40086d01
[   51.945826] ide-tape: idetape_mtioctop: MTIOCTOP ioctl: mt_op: 13, mt_count: 1
[   51.945830] ide-tape: idetape_rewind_tape: enter
[   51.945843] ide-tape: idetape_do_request: cmd: 0x1, sector: 4294967295, nr_sectors: 0

Those debug calls were simply not there/not complete wrt to the
information they were dumping because nobody had an ide-tape to play
with. After I got one and started debugging, I've added that missing
information which made a dbg output more understandable (e.g. request
cmd, args the ioctl is being called with, etc.)

This is the only reason for that change and because it doesn't break
anything but helps a whole lot when debugging, it's a win-win thing and
that's why I advocate its inclusion so vehemently :).

Thanks.

-- 
Regards/Gruss,
    Boris.