ATAPI tape drives broken with libata

https://bugzilla.redhat.com/show_bug.cgi?id=243568

Using kernel 2.6.22:

Aug 29 17:08:11 itox kernel: ata2.00: ATAPI: Seagate STT8000A, 5.51, max MWDMA2
Aug 29 17:08:11 itox kernel: ata2.00: configured for MWDMA2
Aug 29 17:08:11 itox kernel: scsi 1:0:0:0: Sequential-Access Seagate  STT8000A         5.51 PQ: 0 ANSI: 2
Aug 29 17:08:12 itox kernel: scsi 1:0:0:0: Attached scsi generic sg1 type 1
Aug 29 17:08:12 itox kernel: st: Version 20070203, fixed bufsize 32768, s/g segs 256
Aug 29 17:08:12 itox kernel: st 1:0:0:0: Attached scsi tape st0
Aug 29 17:08:12 itox kernel: st 1:0:0:0: st0: try direct i/o: yes (alignment 512 B)
Aug 29 17:08:12 itox kernel: ata2: DRQ=1 with device error, dev_stat 0x59
Aug 29 17:08:12 itox kernel: ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
Aug 29 17:08:12 itox kernel: ata2.00: cmd a0/00:00:00:00:20/00:00:00:00:00/a0 tag 0 cdb 0x0 data 0 
Aug 29 17:08:12 itox kernel:          res 51/60:03:00:00:20/00:00:00:00:00/a0 Emask 0x3 (HSM violation)
Aug 29 17:08:13 itox kernel: ata2: soft resetting port
Aug 29 17:08:13 itox kernel: ata2.00: revalidation failed (errno=-2)
Aug 29 17:08:13 itox kernel: ata2: failed to recover some devices, retrying in 5 secs
Aug 29 17:08:13 itox kernel: ata2: soft resetting port
Aug 29 17:08:13 itox kernel: ata2.00: revalidation failed (errno=-2)
Aug 29 17:08:13 itox kernel: ata2: failed to recover some devices, retrying in 5 secs
Aug 29 17:08:13 itox kernel: ata2: soft resetting port
Aug 29 17:08:13 itox kernel: ata2.00: revalidation failed (errno=-2)
Aug 29 17:08:13 itox kernel: ata2.00: disabled
Aug 29 17:08:13 itox kernel: ata2: EH complete

Opening the device returns -EIO and prints this kernel message:

Aug 29 17:20:29 itox kernel: st0: Error 40000 (sugg. bt 0x0, driver bt 0x0, host bt 0x4).

17:23:45.360014 open("/dev/nst0", O_RDONLY|O_NONBLOCK) = -1 EIO (Input/output error)

The old ide drivers with ide-scsi work.

Device Ready, Seek Complete, Data Request, Error

DRQ and Error together is a bit odd to say the least

It then commits suicide and falls off the bus. That may be due to the fact we use SRST on ATAPI device errors still rather than trying an ATAPI reset first. Shouldn't matter though.

Since you are the lucky owner of the object in question can you dump the contents of the packet command going to the device when this occurs ?

Alan

I don't have it, it's a Fedora user. Maybe I should ask Mark Lord if he'll send me the one he has.

IAC how do I dump the packet? Use ata_scsi_dump_cdb()?

Yep - if the command issued is a packet command the cdb is 12-16 bytes of SCSI command block.

Alan

More or less the same behaviour is observed here with the Conner ATAPI tape unit that I (still!) have on the shelf.

I'll see about instrumenting things for more info. It really sucks as is, though! :)

Cheers

I added code in libata-core.c at ata_qc_issue & ata_qc_issue_prot which dumps qc->cdb if protocol is ATAPI:

14:10:48 root: writing to the tape next
14:11:01 kernel: qc_issue: CDB 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
14:11:01 kernel: qc_issue_prot: CDB 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
14:11:01 kernel: qc_issue: CDB 03 00 00 00 60 00 00 00 00 00 00 00 00 00 00 00
14:11:01 kernel: qc_issue_prot: CDB 03 00 00 00 60 00 00 00 00 00 00 00 00 00 00 00 14:11:01 kernel: ata3: DRQ=1 with device error, dev_stat 0x59
14:11:01 kernel: ata3.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen 14:11:01 kernel: ata3.00: cmd a0/00:00:00:00:20/00:00:00:00:00/a0 tag 0 cdb 0x0 data 0
14:11:01 kernel: res 51/60:03:00:00:20/00:00:00:00:00/a0 Emask 0x3 (HSM violation)
14:11:01 kernel: ata3: soft resetting port
14:11:02 kernel: ata3.00: revalidation failed (errno=-2)
14:11:02 kernel: ata3: failed to recover some devices, retrying in 5 secs 14:11:07 kernel: ata3: soft resetting port
14:11:08 kernel: spurious 8259A interrupt: IRQ7.
14:11:09 kernel: ata3.01: failed to IDENTIFY (I/O error, err_mask=0x1) 14:11:09 kernel: ata3: failed to recover some devices, retrying in 5 secs 14:11:14 kernel: ata3: soft resetting port
14:11:15 kernel: ata3.01: failed to IDENTIFY (I/O error, err_mask=0x1) 14:11:15 kernel: ata3.01: limiting speed to UDMA7:PIO4
14:11:15 kernel: ata3: failed to recover some devices, retrying in 5 secs 14:11:20 kernel: ata3: soft resetting port
14:11:20 kernel: ata3.01: failed to IDENTIFY (I/O error, err_mask=0x1) 14:11:20 kernel: ata3: failed to recover some devices, retrying in 5 secs 14:11:25 kernel: ata3: soft resetting port
14:11:26 kernel: ata3.00: configured for PIO2
14:11:26 kernel: ata3: EH pending after completion, repeating EH (cnt=4) 14:11:26 kernel: ata3: EH complete

...

Okay, if I simply change the code to ignore the test for "DRQ=1 with device error", things appear to work.

14:26:48 root: writing
14:26:54 kernel: qc_issue: CDB 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 14:26:54 kernel: qc_issue_prot: CDB 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 14:26:54 kernel: qc_issue: CDB 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 14:26:54 kernel: qc_issue_prot: CDB 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 14:26:54 kernel: qc_issue: CDB 03 00 00 00 60 00 00 00 00 00 00 00 00 00 00 00 14:26:54 kernel: qc_issue_prot: CDB 03 00 00 00 60 00 00 00 00 00 00 00 00 00 00 00 14:26:54 kernel: ata3: DRQ=1 with device error, dev_stat 0x59
14:26:54 kernel: st0: Sense Key : Illegal Request [current]
14:26:54 kernel: st0: Add. Sense: Invalid command operation code 14:26:54 kernel: qc_issue: CDB 1a 00 00 00 0c 00 00 00 00 00 00 00 00 00 00 00 14:26:54 kernel: qc_issue_prot: CDB 1a 00 00 00 0c 00 00 00 00 00 00 00 00 00 00 00 14:26:54 kernel: qc_issue: CDB 0a 01 00 00 08 00 00 00 00 00 00 00 00 00 00 00 14:26:54 kernel: qc_issue_prot: CDB 0a 01 00 00 08 00 00 00 00 00 00 00 00 00 00 00 14:27:01 kernel: qc_issue: CDB 0a 01 00 00 08 00 00 00 00 00 00 00 00 00 00 00 14:27:01 kernel: qc_issue_prot: CDB 0a 01 00 00 08 00 00 00 00 00 00 00 00 00 00 00 14:27:01 kernel: qc_issue: CDB 0a 01 00 00 08 00 00 00 00 00 00 00 00 00 00 00 14:27:01 kernel: qc_issue_prot: CDB 0a 01 00 00 08 00 00 00 00 00 00 00 00 00 00 00 14:27:01 kernel: qc_issue: CDB 0a 01 00 00 08 00 00 00 00 00 00 00 00 00 00 00 14:27:01 kernel: qc_issue_prot: CDB 0a 01 00 00 08 00 00 00 00 00 00 00 00 00 00 00 14:27:01 kernel: qc_issue: CDB 0a 01 00 00 08 00 00 00 00 00 00 00 00 00 00 00 14:27:01 kernel: qc_issue_prot: CDB 0a 01 00 00 08 00 00 00 00 00 00 00 00 00 00 00 14:27:01 kernel: qc_issue: CDB 0a 01 00 00 08 00 00 00 00 00 00 00 00 00 00 00 14:27:01 kernel: qc_issue_prot: CDB 0a 01 00 00 08 00 00 00 00 00 00 00 00 00 00 00 14:27:01 kernel: qc_issue: CDB 0a 01 00 00 08 00 00 00 00 00 00 00 00 00 00 00 14:27:01 kernel: qc_issue_prot: CDB 0a 01 00 00 08 00 00 00 00 00 00 00 00 00 00 00

I can read and write the tape successfully, and the written data matches what is later read back from it.

Here's the hack I used. Not ready for mainline, but perhaps it will help Alan or whomever come up with something nice for Jeff.

@@ -4932,9 +4932,9 @@
               if (unlikely(status & (ATA_ERR | ATA_DF))) {
                       ata_port_printk(ap, KERN_WARNING, "DRQ=1 with device "
                                       "error, dev_stat 0x%X\n", status);
-                       qc->err_mask |= AC_ERR_HSM;
-                       ap->hsm_task_state = HSM_ST_ERR;
-                       goto fsm_start;
+                       //qc->err_mask |= AC_ERR_HSM;
+                       //ap->hsm_task_state = HSM_ST_ERR;
+                       //goto fsm_start;
               }
 
               /* Send the CDB (atapi) or the first data block (ata pio out).

One more bit of possibly helpful information here.

The last time I wrote a working ATAPI Tape driver,
it always translated SCSI opcode 0x05 (READ_BLOCK_LIMITS) into MODE_SENSE.

I don't remember why it did that, but it was necessary at the time. So I wonder if the error above has anything to do with the READ_BLOCK_LIMITS command that can be seen just above the TEST_UNIT_READY and REQUEST_SENSE CDBs ?

Cheers

Ah.. my notes to myself from that era say:

// ATAPI tape drives do not implement the "READ_BLOCK_LIMITS" command, // but the same information can be obtained from a MODE_SENSE instead. // So here we emulate the former, using the latter.

Cheers

Its possible we should just scream and shout but for robustness and paranoia I just added ATA_HORKAGE_DRQ and skip the error setup in the case that HORKAGE_DRQ is set.

Just need the identify data now..

I duspect it's *all* ATAPI tape units. Mine (Conner) is quite a bit older than the other (Seagate) one that began this thread. And ide-tape has no problem with either drive. Perhaps a whitelist rather than a blacklist here.

Meanwhile, my old Conner tape unit is several hundred miles away from me at present.

Cheers

It's strange that the device reports DRQ + ERR at this point since if it knows something wrong, asking to transfer the CDB doesn't help...

Is the device configured to MWDMA? If yes, maybe it's ATAPI DMA of the previous command makes the device state machine confused...

Could you please try if the attached debug patch helps? Thanks. --
albert

diff -Nrup 00_libata-dev/drivers/ata/libata-core.c 01_atapi_dma/drivers/ata/libata-core.c
@@ -4193,6 +4193,8 @@ static void ata_fill_sg_dumb(struct ata_
 int ata_check_atapi_dma(struct ata_queued_cmd *qc)
 {
 	struct ata_port *ap = qc->ap;
+	struct scsi_cmnd *cmd = qc->scsicmd;
+	u8 *scsicmd = cmd->cmnd;
 
 	/* Don't allow DMA if it isn't multiple of 16 bytes.  Quite a
 	 * few ATAPI devices choke on such DMA requests.

@@ -4200,6 +4202,21 @@ int ata_check_atapi_dma(struct ata_queue
 	if (unlikely(qc->nbytes & 15))
 		return 1;
 
+	switch (scsicmd[0]) {
+	case READ_10:
+	case WRITE_10:
+	case READ_12:
+	case WRITE_12:
+	case READ_6:
+	case WRITE_6:
+	case 0xad: /* READ_DVD_STRUCTURE */
+	case 0xbe: /* READ_CD */
+		/* ATAPI DMA maybe ok */
+		break;
+	default:
+		return 1;
+	}
+
 	if (ap->ops->check_atapi_dma)
 		return ap->ops->check_atapi_dma(qc);
 

DRQ=1 is quite unusual, and would definitely trigger the problems further down (that I snipped)...

Jeff