Zip 100 ATAPI not working, "qc timeout" and "failed to clear UNIT ATTENTION"

Zip 100 ATAPI not working, "qc timeout" and "failed to clear UNIT ATTENTION"

[Philip Pemberton]

I'm trying to connect an old Iomega Zip 100 ATAPI to a B550-chipset 
Ryzen system, to exchange files with an even older system. The Gigabyte 
B550 AORUS ELITE AX V2 rev1.3 motherboard doesn't have any PATA ports, 
so I'm using a SATA to PATA adapter.

Sadly it will not work in the B550 system (Kernel 6.8.0-51-generic 
x86_64, Linux Mint 21.3 based on Ubuntu 22.04). When I have the Zip 
drive connected, I get the following in dmesg and the sd device never 
appears:

ata3: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
ata3.00: ATAPI: IOMEGA  ZIP 100       ATAPI, 12.A, max PIO3, CDB intr, 
DMADIR
ata3.00: applying bridge limits
ata3.00: configured for PIO0
ata3.00: qc timeout after 5000 msecs (cmd 0xa0)
ata3.00: failed to clear UNIT ATTENTION (err_mask=0x5)

I've included a more complete dmesg at the bottom of this message.

I currently have the following in the kernel command line:
   libata.atapi_dmadir=1 
libata.force=3.00:atapi_dmadir,dump_id,nodmalog,noncq,pio0

I started with only having the DMADIR option as suggested in this old 
patch from LKML:
   https://lkml.org/lkml/2013/6/18/933

With "atapi_dmadir=1" and DMADIR forced, I have the same messages in the 
kernel log - except obviously none of the other "horkage" messages or 
the ATA IDENTIFY dump, and I think the "xfer mask" starts at a higher speed.


The BIOS can see and access the Zip drive fine, as can Windows.

I've also tried the same setup (SATA bridge) in a Pentium 4 PCI+AGP 
machine I had sitting around. Admittedly this isn't much of a test as it 
was running a much older and 32bit OS (Knoppix 7.2, kernel 3.9.6) but 
the sd device appeared and the drive could be accessed fine.

Is there anything else I can try to get the drive working?

If you're curious, my use case is, predictably enough, copying data 
to/from old systems which don't have USB. (a mix of Acorn ARM systems 
running RISC OS and PCs with parallel port Zip drives)

Thanks,
Phil.


Full dmesg:

[ 4465.211914] ata3: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[ 4465.218528] ata3.00: FORCE: horkage modified (atapi_dmadir)
[ 4465.218531] ata3.00: FORCE: horkage modified (dump_id)
[ 4465.218532] ata3.00: FORCE: horkage modified (nodmalog)
[ 4465.218533] ata3.00: FORCE: horkage modified (noncq)
[ 4465.218535] ata3.00: ATAPI: IOMEGA  ZIP 100       ATAPI, 12.A, max 
PIO3, CDB intr, DMADIR
[ 4465.218538] ata3.00: applying bridge limits
[ 4465.218540] ata3.00: FORCE: xfer_mask set to pio0
[ 4465.225708] ata3.00: dumping IDENTIFY data, class=3 may_fallback=1 
tried_spinup=0
[ 4465.225713] 00000000: 80a0 0000 0000 0000 0000 0000 0000 0000 
................
[ 4465.225716] 00000010: 0000 0000 2020 2020 2020 2020 2020 2020  .... 

[ 4465.225718] 00000020: 2020 2020 2020 2020 0000 0000 0000 3132 
  ......21
[ 4465.225720] 00000030: 2e41 2020 2020 494f 4d45 4741 2020 5a49  A. 
OIEMAG  IZ
[ 4465.225723] 00000040: 5020 3130 3020 2020 2020 2020 4154 4150   P01 0 
      TAPA
[ 4465.225725] 00000050: 4920 2020 2020 2020 2020 2020 2020 0000   I 
        ..
[ 4465.225727] 00000060: 0000 0e00 4002 0200 0000 0002 0000 0000 
.....@..........
[ 4465.225729] 00000070: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4465.225731] 00000080: 0001 0000 0000 01f4 00b4 0000 0000 0000 
................
[ 4465.225733] 00000090: 0000 0006 0009 0000 0202 0000 0000 0000 
................
[ 4465.225735] 000000a0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4465.225738] 000000b0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4465.225740] 000000c0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4465.225742] 000000d0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4465.225744] 000000e0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4465.225746] 000000f0: 0000 0000 0000 0000 0000 0000 0000 0101 
................
[ 4465.225748] 00000100: 2863 2920 436f 7079 7269 6768 7420 494f  c( 
)oCypirhg tOI
[ 4465.225750] 00000110: 4d45 4741 2031 3939 3720 0000 0000 0000  EMAG1 
99 7......
[ 4465.225753] 00000120: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4465.225755] 00000130: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4465.225757] 00000140: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4465.225759] 00000150: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4465.225761] 00000160: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4465.225763] 00000170: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4465.225767] 00000180: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4465.225769] 00000190: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4465.225772] 000001a0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4465.225774] 000001b0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4465.225776] 000001c0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4465.225778] 000001d0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4465.225780] 000001e0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4465.225782] 000001f0: 0000 0000 0000 0000 0000 0000 0116 1900 
................
[ 4465.225787] ata3.00: configured for PIO0
[ 4470.419775] ata3.00: qc timeout after 5000 msecs (cmd 0xa0)
[ 4470.419794] ata3.00: failed to clear UNIT ATTENTION (err_mask=0x5)
[ 4470.883747] ata3: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[ 4470.890363] ata3.00: dumping IDENTIFY data, class=3 may_fallback=1 
tried_spinup=0
[ 4470.890371] 00000000: 80a0 0000 0000 0000 0000 0000 0000 0000 
................
[ 4470.890376] 00000010: 0000 0000 2020 2020 2020 2020 2020 2020  .... 

[ 4470.890380] 00000020: 2020 2020 2020 2020 0000 0000 0000 3132 
  ......21
[ 4470.890384] 00000030: 2e41 2020 2020 494f 4d45 4741 2020 5a49  A. 
OIEMAG  IZ
[ 4470.890387] 00000040: 5020 3130 3020 2020 2020 2020 4154 4150   P01 0 
      TAPA
[ 4470.890391] 00000050: 4920 2020 2020 2020 2020 2020 2020 0000   I 
        ..
[ 4470.890395] 00000060: 0000 0e00 4002 0200 0000 0002 0000 0000 
.....@..........
[ 4470.890398] 00000070: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4470.890402] 00000080: 0001 0000 0000 01f4 00b4 0000 0000 0000 
................
[ 4470.890406] 00000090: 0000 0006 0009 0000 0202 0000 0000 0000 
................
[ 4470.890409] 000000a0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4470.890413] 000000b0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4470.890416] 000000c0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4470.890420] 000000d0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4470.890424] 000000e0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4470.890427] 000000f0: 0000 0000 0000 0000 0000 0000 0000 0101 
................
[ 4470.890431] 00000100: 2863 2920 436f 7079 7269 6768 7420 494f  c( 
)oCypirhg tOI
[ 4470.890435] 00000110: 4d45 4741 2031 3939 3720 0000 0000 0000  EMAG1 
99 7......
[ 4470.890438] 00000120: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4470.890442] 00000130: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4470.890445] 00000140: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4470.890449] 00000150: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4470.890453] 00000160: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4470.890456] 00000170: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4470.890460] 00000180: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4470.890463] 00000190: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4470.890467] 000001a0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4470.890471] 000001b0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4470.890474] 000001c0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4470.890478] 000001d0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4470.890481] 000001e0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4470.890485] 000001f0: 0000 0000 0000 0000 0000 0000 0116 1900 
................
[ 4470.890500] ata3.00: FORCE: xfer_mask set to pio0
[ 4470.897720] ata3.00: dumping IDENTIFY data, class=3 may_fallback=1 
tried_spinup=0
[ 4470.897735] 00000000: 80a0 0000 0000 0000 0000 0000 0000 0000 
................
[ 4470.897740] 00000010: 0000 0000 2020 2020 2020 2020 2020 2020  .... 

[ 4470.897744] 00000020: 2020 2020 2020 2020 0000 0000 0000 3132 
  ......21
[ 4470.897748] 00000030: 2e41 2020 2020 494f 4d45 4741 2020 5a49  A. 
OIEMAG  IZ
[ 4470.897752] 00000040: 5020 3130 3020 2020 2020 2020 4154 4150   P01 0 
      TAPA
[ 4470.897755] 00000050: 4920 2020 2020 2020 2020 2020 2020 0000   I 
        ..
[ 4470.897759] 00000060: 0000 0e00 4002 0200 0000 0002 0000 0000 
.....@..........
[ 4470.897763] 00000070: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4470.897766] 00000080: 0001 0000 0000 01f4 00b4 0000 0000 0000 
................
[ 4470.897770] 00000090: 0000 0006 0009 0000 0202 0000 0000 0000 
................
[ 4470.897774] 000000a0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4470.897777] 000000b0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4470.897781] 000000c0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4470.897785] 000000d0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4470.897788] 000000e0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4470.897792] 000000f0: 0000 0000 0000 0000 0000 0000 0000 0101 
................
[ 4470.897796] 00000100: 2863 2920 436f 7079 7269 6768 7420 494f  c( 
)oCypirhg tOI
[ 4470.897799] 00000110: 4d45 4741 2031 3939 3720 0000 0000 0000  EMAG1 
99 7......
[ 4470.897803] 00000120: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4470.897807] 00000130: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4470.897810] 00000140: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4470.897814] 00000150: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4470.897818] 00000160: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4470.897821] 00000170: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4470.897825] 00000180: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4470.897828] 00000190: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4470.897832] 000001a0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4470.897836] 000001b0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4470.897839] 000001c0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4470.897843] 000001d0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4470.897847] 000001e0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4470.897850] 000001f0: 0000 0000 0000 0000 0000 0000 0116 1900 
................
[ 4470.897858] ata3.00: configured for PIO0
[ 4476.051591] ata3.00: qc timeout after 5000 msecs (cmd 0xa0)
[ 4476.051607] ata3.00: failed to clear UNIT ATTENTION (err_mask=0x5)
[ 4476.515583] ata3: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[ 4476.522296] ata3.00: dumping IDENTIFY data, class=3 may_fallback=1 
tried_spinup=0
[ 4476.522310] 00000000: 80a0 0000 0000 0000 0000 0000 0000 0000 
................
[ 4476.522314] 00000010: 0000 0000 2020 2020 2020 2020 2020 2020  .... 

[ 4476.522317] 00000020: 2020 2020 2020 2020 0000 0000 0000 3132 
  ......21
[ 4476.522320] 00000030: 2e41 2020 2020 494f 4d45 4741 2020 5a49  A. 
OIEMAG  IZ
[ 4476.522323] 00000040: 5020 3130 3020 2020 2020 2020 4154 4150   P01 0 
      TAPA
[ 4476.522326] 00000050: 4920 2020 2020 2020 2020 2020 2020 0000   I 
        ..
[ 4476.522328] 00000060: 0000 0e00 4002 0200 0000 0002 0000 0000 
.....@..........
[ 4476.522331] 00000070: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4476.522334] 00000080: 0001 0000 0000 01f4 00b4 0000 0000 0000 
................
[ 4476.522337] 00000090: 0000 0006 0009 0000 0202 0000 0000 0000 
................
[ 4476.522339] 000000a0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4476.522342] 000000b0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4476.522345] 000000c0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4476.522348] 000000d0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4476.522350] 000000e0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4476.522353] 000000f0: 0000 0000 0000 0000 0000 0000 0000 0101 
................
[ 4476.522356] 00000100: 2863 2920 436f 7079 7269 6768 7420 494f  c( 
)oCypirhg tOI
[ 4476.522359] 00000110: 4d45 4741 2031 3939 3720 0000 0000 0000  EMAG1 
99 7......
[ 4476.522362] 00000120: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4476.522364] 00000130: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4476.522367] 00000140: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4476.522370] 00000150: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4476.522372] 00000160: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4476.522375] 00000170: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4476.522378] 00000180: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4476.522381] 00000190: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4476.522383] 000001a0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4476.522386] 000001b0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4476.522389] 000001c0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4476.522392] 000001d0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4476.522394] 000001e0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4476.522397] 000001f0: 0000 0000 0000 0000 0000 0000 0116 1900 
................
[ 4476.522409] ata3.00: FORCE: xfer_mask set to pio0
[ 4476.529541] ata3.00: dumping IDENTIFY data, class=3 may_fallback=1 
tried_spinup=0
[ 4476.529549] 00000000: 80a0 0000 0000 0000 0000 0000 0000 0000 
................
[ 4476.529553] 00000010: 0000 0000 2020 2020 2020 2020 2020 2020  .... 

[ 4476.529571] 00000020: 2020 2020 2020 2020 0000 0000 0000 3132 
  ......21
[ 4476.529577] 00000030: 2e41 2020 2020 494f 4d45 4741 2020 5a49  A. 
OIEMAG  IZ
[ 4476.529583] 00000040: 5020 3130 3020 2020 2020 2020 4154 4150   P01 0 
      TAPA
[ 4476.529589] 00000050: 4920 2020 2020 2020 2020 2020 2020 0000   I 
        ..
[ 4476.529594] 00000060: 0000 0e00 4002 0200 0000 0002 0000 0000 
.....@..........
[ 4476.529600] 00000070: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4476.529606] 00000080: 0001 0000 0000 01f4 00b4 0000 0000 0000 
................
[ 4476.529612] 00000090: 0000 0006 0009 0000 0202 0000 0000 0000 
................
[ 4476.529617] 000000a0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4476.529623] 000000b0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4476.529628] 000000c0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4476.529633] 000000d0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4476.529639] 000000e0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4476.529644] 000000f0: 0000 0000 0000 0000 0000 0000 0000 0101 
................
[ 4476.529649] 00000100: 2863 2920 436f 7079 7269 6768 7420 494f  c( 
)oCypirhg tOI
[ 4476.529655] 00000110: 4d45 4741 2031 3939 3720 0000 0000 0000  EMAG1 
99 7......
[ 4476.529661] 00000120: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4476.529666] 00000130: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4476.529672] 00000140: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4476.529677] 00000150: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4476.529682] 00000160: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4476.529687] 00000170: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4476.529693] 00000180: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4476.529698] 00000190: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4476.529704] 000001a0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4476.529709] 000001b0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4476.529714] 000001c0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4476.529720] 000001d0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4476.529725] 000001e0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[ 4476.529731] 000001f0: 0000 0000 0000 0000 0000 0000 0116 1900 
................
[ 4476.529743] ata3.00: configured for PIO0
[ 4481.683441] ata3.00: qc timeout after 5000 msecs (cmd 0xa0)
[ 4481.683457] ata3.00: failed to clear UNIT ATTENTION (err_mask=0x5)
[ 4481.683461] ata3.00: disable device
[ 4482.147601] ata3: SATA link up 1.5 Gbps (SStatus 113 SControl 300)

-- 
Phil.
philpem@philpem.me.uk
https://www.philpem.me.uk/

Re: Zip 100 ATAPI not working, "qc timeout" and "failed to clear UNIT ATTENTION"

[Niklas Cassel]

Hello Philip,

On Wed, Jan 08, 2025 at 12:52:50PM +0000, Philip Pemberton wrote:
> I'm trying to connect an old Iomega Zip 100 ATAPI to a B550-chipset Ryzen
> system, to exchange files with an even older system. The Gigabyte B550 AORUS
> ELITE AX V2 rev1.3 motherboard doesn't have any PATA ports, so I'm using a
> SATA to PATA adapter.
> 
> Sadly it will not work in the B550 system (Kernel 6.8.0-51-generic x86_64,
> Linux Mint 21.3 based on Ubuntu 22.04). When I have the Zip drive connected,
> I get the following in dmesg and the sd device never appears:
> 
> ata3: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> ata3.00: ATAPI: IOMEGA  ZIP 100       ATAPI, 12.A, max PIO3, CDB intr,
> DMADIR
> ata3.00: applying bridge limits
> ata3.00: configured for PIO0
> ata3.00: qc timeout after 5000 msecs (cmd 0xa0)
> ata3.00: failed to clear UNIT ATTENTION (err_mask=0x5)
> 
> I've included a more complete dmesg at the bottom of this message.
> 
> I currently have the following in the kernel command line:
>   libata.atapi_dmadir=1
> libata.force=3.00:atapi_dmadir,dump_id,nodmalog,noncq,pio0
> 
> I started with only having the DMADIR option as suggested in this old patch
> from LKML:
>   https://lkml.org/lkml/2013/6/18/933
> 
> With "atapi_dmadir=1" and DMADIR forced, I have the same messages in the
> kernel log - except obviously none of the other "horkage" messages or the
> ATA IDENTIFY dump, and I think the "xfer mask" starts at a higher speed.
> 
> 
> The BIOS can see and access the Zip drive fine, as can Windows.
> 
> I've also tried the same setup (SATA bridge) in a Pentium 4 PCI+AGP machine
> I had sitting around. Admittedly this isn't much of a test as it was running
> a much older and 32bit OS (Knoppix 7.2, kernel 3.9.6) but the sd device
> appeared and the drive could be accessed fine.

Did you specify anything on the kernel command line when using kernel 3.9.6 ?

FWIW, commit e771451c0a83 ("libata: make ata_exec_internal_sg honor DMADIR")
was first included in v3.10.1, so even if you did specify it on the kernel
command line on kernel 3.9.6, it wouldn't have any effect on internal commands
(e.g. IDENTIFY).


Kind regards,
Niklas

Re: Zip 100 ATAPI not working, "qc timeout" and "failed to clear UNIT ATTENTION"

[Niklas Cassel]

On Wed, Jan 08, 2025 at 02:42:13PM +0100, Niklas Cassel wrote:
> Hello Philip,
> 
> On Wed, Jan 08, 2025 at 12:52:50PM +0000, Philip Pemberton wrote:
> > I'm trying to connect an old Iomega Zip 100 ATAPI to a B550-chipset Ryzen
> > system, to exchange files with an even older system. The Gigabyte B550 AORUS
> > ELITE AX V2 rev1.3 motherboard doesn't have any PATA ports, so I'm using a
> > SATA to PATA adapter.
> > 
> > Sadly it will not work in the B550 system (Kernel 6.8.0-51-generic x86_64,
> > Linux Mint 21.3 based on Ubuntu 22.04). When I have the Zip drive connected,
> > I get the following in dmesg and the sd device never appears:
> > 
> > ata3: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> > ata3.00: ATAPI: IOMEGA  ZIP 100       ATAPI, 12.A, max PIO3, CDB intr,
> > DMADIR
> > ata3.00: applying bridge limits
> > ata3.00: configured for PIO0
> > ata3.00: qc timeout after 5000 msecs (cmd 0xa0)
> > ata3.00: failed to clear UNIT ATTENTION (err_mask=0x5)
> > 
> > I've included a more complete dmesg at the bottom of this message.
> > 
> > I currently have the following in the kernel command line:
> >   libata.atapi_dmadir=1
> > libata.force=3.00:atapi_dmadir,dump_id,nodmalog,noncq,pio0
> > 
> > I started with only having the DMADIR option as suggested in this old patch
> > from LKML:
> >   https://lkml.org/lkml/2013/6/18/933
> > 
> > With "atapi_dmadir=1" and DMADIR forced, I have the same messages in the
> > kernel log - except obviously none of the other "horkage" messages or the
> > ATA IDENTIFY dump, and I think the "xfer mask" starts at a higher speed.
> > 
> > 
> > The BIOS can see and access the Zip drive fine, as can Windows.
> > 
> > I've also tried the same setup (SATA bridge) in a Pentium 4 PCI+AGP machine
> > I had sitting around. Admittedly this isn't much of a test as it was running
> > a much older and 32bit OS (Knoppix 7.2, kernel 3.9.6) but the sd device
> > appeared and the drive could be accessed fine.
> 
> Did you specify anything on the kernel command line when using kernel 3.9.6 ?
> 
> FWIW, commit e771451c0a83 ("libata: make ata_exec_internal_sg honor DMADIR")
> was first included in v3.10.1, so even if you did specify it on the kernel
> command line on kernel 3.9.6, it wouldn't have any effect on internal commands
> (e.g. IDENTIFY).

I take that back... the commit did exist in 3.9.6, but with a different SHA1:

commit 27a8de81bf1a476a3df6dd548c4925aa87689c92
Author: Vincent Pelletier <plr.vincent@gmail.com>
Date:   Sat May 18 18:44:04 2013 +0200

    libata: make ata_exec_internal_sg honor DMADIR
    
    commit e771451c0a831d96a7c14b0ca8a8ec671d98567b upstream.


Kind regards,
Niklas

Re: Zip 100 ATAPI not working, "qc timeout" and "failed to clear UNIT ATTENTION"

[Philip Pemberton]

On 08/01/2025 13:42, Niklas Cassel wrote:
 > Did you specify anything on the kernel command line when using kernel 
3.9.6 ?

No, I didn't have to - the drive worked fine without any extra command 
line entries over the Knoppix default.

The Knoppix default command line has "libata.force=noncq" - but nothing 
related to DMADIR or similar.

Thanks
-- 
Phil.
philpem@philpem.me.uk
https://www.philpem.me.uk/

Re: Zip 100 ATAPI not working, "qc timeout" and "failed to clear UNIT ATTENTION"

[Niklas Cassel]

On Wed, Jan 08, 2025 at 12:52:50PM +0000, Philip Pemberton wrote:
> I'm trying to connect an old Iomega Zip 100 ATAPI to a B550-chipset Ryzen
> system, to exchange files with an even older system. The Gigabyte B550 AORUS
> ELITE AX V2 rev1.3 motherboard doesn't have any PATA ports, so I'm using a
> SATA to PATA adapter.
> 
> Sadly it will not work in the B550 system (Kernel 6.8.0-51-generic x86_64,
> Linux Mint 21.3 based on Ubuntu 22.04). When I have the Zip drive connected,
> I get the following in dmesg and the sd device never appears:
> 
> ata3: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> ata3.00: ATAPI: IOMEGA  ZIP 100       ATAPI, 12.A, max PIO3, CDB intr,
> DMADIR
> ata3.00: applying bridge limits
> ata3.00: configured for PIO0
> ata3.00: qc timeout after 5000 msecs (cmd 0xa0)
> ata3.00: failed to clear UNIT ATTENTION (err_mask=0x5)

Since we see that the drive name is printed, the ATAPI IDENTIFY command
succeded (ATA_CMD_ID_ATAPI (0xA1)).

The command that timed out is ATA_CMD_PACKET 0xA0, so a regular ATAPI command.

The UNIT ATTENTION print is just from atapi_eh_clear_ua(), which seems to be
called by ata_eh_recover() unconditionally for ATAPI devices, because they
always need to clear UNIT ATTENTION after a reset:
https://github.com/torvalds/linux/blob/v6.8/drivers/ata/libata-eh.c#L3232-L3234

But the reset is of course only triggered because a command has timed out.


Kind regards,
Niklas

Re: Zip 100 ATAPI not working, "qc timeout" and "failed to clear UNIT ATTENTION"

[Hannes Reinecke]

On 1/8/25 15:05, Niklas Cassel wrote:
> On Wed, Jan 08, 2025 at 12:52:50PM +0000, Philip Pemberton wrote:
>> I'm trying to connect an old Iomega Zip 100 ATAPI to a B550-chipset Ryzen
>> system, to exchange files with an even older system. The Gigabyte B550 AORUS
>> ELITE AX V2 rev1.3 motherboard doesn't have any PATA ports, so I'm using a
>> SATA to PATA adapter.
>>
>> Sadly it will not work in the B550 system (Kernel 6.8.0-51-generic x86_64,
>> Linux Mint 21.3 based on Ubuntu 22.04). When I have the Zip drive connected,
>> I get the following in dmesg and the sd device never appears:
>>
>> ata3: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
>> ata3.00: ATAPI: IOMEGA  ZIP 100       ATAPI, 12.A, max PIO3, CDB intr,
>> DMADIR
>> ata3.00: applying bridge limits
>> ata3.00: configured for PIO0
>> ata3.00: qc timeout after 5000 msecs (cmd 0xa0)
>> ata3.00: failed to clear UNIT ATTENTION (err_mask=0x5)
> 
> Since we see that the drive name is printed, the ATAPI IDENTIFY command
> succeded (ATA_CMD_ID_ATAPI (0xA1)).
> 
> The command that timed out is ATA_CMD_PACKET 0xA0, so a regular ATAPI command.
> 
> The UNIT ATTENTION print is just from atapi_eh_clear_ua(), which seems to be
> called by ata_eh_recover() unconditionally for ATAPI devices, because they
> always need to clear UNIT ATTENTION after a reset:
> https://github.com/torvalds/linux/blob/v6.8/drivers/ata/libata-eh.c#L3232-L3234
> 
> But the reset is of course only triggered because a command has timed out.
> 
Which makes me wonder: does the SATA-to-PATA support ATAPI? It has been 
removed from recent ATA specifications, so there's a chance the bridge 
simply doesn't implement it ...

Cheers,

Hannes
-- 
Dr. Hannes Reinecke                  Kernel Storage Architect
hare@suse.de                                +49 911 74053 688
SUSE Software Solutions GmbH, Frankenstr. 146, 90461 Nürnberg
HRB 36809 (AG Nürnberg), GF: I. Totev, A. McDonald, W. Knoblich

Re: Zip 100 ATAPI not working, "qc timeout" and "failed to clear UNIT ATTENTION"

[Philip Pemberton]

On 09/01/2025 07:17, Hannes Reinecke wrote:
> Which makes me wonder: does the SATA-to-PATA support ATAPI? It has been 
> removed from recent ATA specifications, so there's a chance the bridge 
> simply doesn't implement it ...

It seems to -- if I use the SATA-to-PATA adapter to put the drive in the 
Knoppix PC, the Zip drive works fine.

-- 
Phil.
philpem@philpem.me.uk
https://www.philpem.me.uk/

Re: Zip 100 ATAPI not working, "qc timeout" and "failed to clear UNIT ATTENTION"

[Niklas Cassel]

On Thu, Jan 09, 2025 at 11:33:11AM +0000, Philip Pemberton wrote:
> On 09/01/2025 07:17, Hannes Reinecke wrote:
> > Which makes me wonder: does the SATA-to-PATA support ATAPI? It has been
> > removed from recent ATA specifications, so there's a chance the bridge
> > simply doesn't implement it ...
> 
> It seems to -- if I use the SATA-to-PATA adapter to put the drive in the
> Knoppix PC, the Zip drive works fine.

Which SATA-to-PATA adapter are you using?


Perhaps that computer (which was running a v3.x kernel) is using a different
SATA controller/driver, which has better ATAPI support?


Do you have the:
[ 4465.218535] ata3.00: ATAPI: IOMEGA  ZIP 100       ATAPI, 12.A, max 
PIO3, CDB intr, DMADIR
[ 4465.225787] ata3.00: configured for PIO0

prints from that other PC running v3.x kernel?


E.g. DMADIR can be automatically detected, if it is needed based on the
returned data in the IDENTIFY PACKET response, see:
https://www.mail-archive.com/linux-ide@vger.kernel.org/msg16469.html
https://www.spinics.net/lists/linux-ide/msg01514.html

The DMADIR print will only be there if we send an explicit DMA direction
with each command.

It would be interesting to see if it was there on your older kernel.

Also your device seems to only indicate support for PIO3, thus we see it
being configured for PIO. Thus, it seems that you are using PIO instead
of DMA. I think that DMADIR only matters when using a DMA mode and not PIO.

Forcing DMADIR=1 when your device only supports PIO, feels wrong to me,
but perhaps I am missing something. Also, why is your device only being
configured for PIO0 when it seems to support up to PIO3 speeds? Bug?


E.g. my print when using QEMU + ATAPI:
[    0.647370] ata2: SATA max UDMA/133 abar m4096@0xfebd2000 port 0xfebd2180 irq 90 lpm-pol 0
[    0.966896] ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[    0.971060] ata2.00: ATAPI: QEMU DVD-ROM, 2.5+, max UDMA/100
[    0.971818] ata2.00: applying bridge limits
[    0.972918] ata2.00: configured for UDMA/100
shows that the device supports up to UDMA/100, and later we also see that
we configure it for that speed.



Kind regards,
Niklas

Re: Zip 100 ATAPI not working, "qc timeout" and "failed to clear UNIT ATTENTION"

[Philip Pemberton]

On 09/01/2025 13:22, Niklas Cassel wrote:
> On Thu, Jan 09, 2025 at 11:33:11AM +0000, Philip Pemberton wrote:
>> On 09/01/2025 07:17, Hannes Reinecke wrote:
>>> Which makes me wonder: does the SATA-to-PATA support ATAPI? It has been
>>> removed from recent ATA specifications, so there's a chance the bridge
>>> simply doesn't implement it ...
>>
>> It seems to -- if I use the SATA-to-PATA adapter to put the drive in the
>> Knoppix PC, the Zip drive works fine.
> 
> Which SATA-to-PATA adapter are you using?

I've tried two, listed in the OP.

One is a Startech PATA2SATA3 which uses a Sunplus SPIF223A chip
The other is a cheap unbranded one from ebay. Even the converter chip is 
unbranded! It says "IDE/SATA DOF B77CSOF41" on the chip.


> Perhaps that computer (which was running a v3.x kernel) is using a different
> SATA controller/driver, which has better ATAPI support?

Could be.

I just tried a CD-ROM drive on the unbranded adapter, on the machine 
running Mint. It was detected fine:

[81482.308980] ata3: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
[81482.336950] ata3.00: FORCE: horkage modified (atapi_dmadir)
[81482.336955] ata3.00: FORCE: horkage modified (dump_id)
[81482.336958] ata3.00: FORCE: horkage modified (nodmalog)
[81482.336959] ata3.00: FORCE: horkage modified (noncq)
[81482.336969] ata3.00: ATAPI: TSSTcorpCD/DVDW TS-H552L, 0614, max 
UDMA/33, DMADIR
[81482.336973] ata3.00: applying bridge limits
[81482.336975] ata3.00: FORCE: xfer_mask set to pio0
[81482.379528] ata3.00: dumping IDENTIFY data, class=3 may_fallback=1 
tried_spinup=0
[81482.379536] 00000000: 85c0 0000 0000 0000 0000 0000 0000 0000 
................
[81482.379540] 00000010: 0000 0000 2020 2020 2020 2020 2020 2020  .... 

[81482.379543] 00000020: 2020 2020 2020 2020 0000 0000 0000 3036 
  ......60
[81482.379546] 00000030: 3134 2020 2020 5453 5354 636f 7270 4344  41 
STTSocprDC
[81482.379549] 00000040: 2f44 5644 5720 5453 2d48 3535 324c 2020  D/DV 
WSTH-55L2
[81482.379552] 00000050: 2020 2020 2020 2020 2020 2020 2020 0000 
        ..
[81482.379554] 00000060: 0000 0f00 0000 0200 0200 0006 0000 0000 
................
[81482.379557] 00000070: 0000 0000 0000 0000 0000 0000 0000 0407 
................
[81482.379560] 00000080: 0003 0078 0078 00e3 0078 0000 0000 0000 
..x.x...x.......
[81482.379563] 00000090: 0000 0000 0000 0000 0002 0000 0000 0000 
................
[81482.379566] 000000a0: 0000 0000 0000 4000 4000 0000 0000 4000 
.......@.@.....@
[81482.379568] 000000b0: 0007 0000 0000 0000 0000 0000 0000 0000 
................
[81482.379571] 000000c0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[81482.379574] 000000d0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[81482.379577] 000000e0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[81482.379579] 000000f0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[81482.379582] 00000100: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[81482.379585] 00000110: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[81482.379588] 00000120: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[81482.379591] 00000130: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[81482.379593] 00000140: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[81482.379596] 00000150: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[81482.379599] 00000160: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[81482.379602] 00000170: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[81482.379604] 00000180: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[81482.379607] 00000190: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[81482.379610] 000001a0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[81482.379613] 000001b0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[81482.379615] 000001c0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[81482.379618] 000001d0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[81482.379621] 000001e0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[81482.379624] 000001f0: 0000 0000 0000 0000 0000 0000 0000 0000 
................
[81482.379632] ata3.00: configured for PIO0
[81482.473195] scsi 2:0:0:0: CD-ROM            TSSTcorp CD/DVDW TS-H552L 
0614 PQ: 0 ANSI: 5
[81482.603033] sr 2:0:0:0: [sr1] scsi3-mmc drive: 8x/40x writer cd/rw 
xa/form2 cdda tray
[81482.644073] sr 2:0:0:0: Attached scsi CD-ROM sr1
[81482.644195] sr 2:0:0:0: Attached scsi generic sg12 type 5

The disc mounted and read fine too.

Given that it works with the TSST DVD drive - I think it's safe to say 
the incompatibility is related specifically to the Zip drive, not ATAPI 
in general.


> Do you have the:
> [ 4465.218535] ata3.00: ATAPI: IOMEGA  ZIP 100       ATAPI, 12.A, max
> PIO3, CDB intr, DMADIR
> [ 4465.225787] ata3.00: configured for PIO0
> 
> prints from that other PC running v3.x kernel?

It's not particularly interesting -- just the drive being detected and 
configured.

[    1.413561] ata1.00: FORCE: horkage modified (noncq)
[    1.413587] ata1.00: ATAPI: IOMEGA  ZIP 100       ATAPI, 12.A, max 
PIO3, CDB intr
[    1.413593] ata1.00: applying bridge limits
[    1.426990] ata1.00: configured for PIO3
[    1.433652] scsi 0:0:0:0: Direct-Access     IOMEGA   ZIP 100 
12.A PQ: 0 ANSI: 5
[    1.434333] sd 0:0:0:0: Attached scsi generic sg0 type 0
[    1.436371] scsi 1:0:0:0: CD-ROM            ATAPI    iHAS124   B 
AL0S PQ: 0 ANSI: 5
[    1.437890] sd 0:0:0:0: [sda] Attached SCSI removable disk


> E.g. DMADIR can be automatically detected, if it is needed based on the
> returned data in the IDENTIFY PACKET response, see:
> https://www.mail-archive.com/linux-ide@vger.kernel.org/msg16469.html
> https://www.spinics.net/lists/linux-ide/msg01514.html
> 
> The DMADIR print will only be there if we send an explicit DMA direction
> with each command.
> 
> It would be interesting to see if it was there on your older kernel.

I don't see any mention of DMADIR.


> Also your device seems to only indicate support for PIO3, thus we see it
> being configured for PIO. Thus, it seems that you are using PIO instead
> of DMA. I think that DMADIR only matters when using a DMA mode and not PIO.
> 
> Forcing DMADIR=1 when your device only supports PIO, feels wrong to me,
> but perhaps I am missing something. Also, why is your device only being
> configured for PIO0 when it seems to support up to PIO3 speeds? Bug?

No, I forced the mode to PIO0 (slowest mode) - see the kernel command 
line I included in my previous message. It included a libata.force 
command which set NONCQ, DMADIR and PIO0.

I wanted to rule out issues on the PATA side of things once I found out 
about the timing bug the drives have on VIA PATA controllers.

It's not like Zip drives are particularly fast anyway - usually about 
500kbytes/sec. PIO Mode 0 (3.3MB/s) is more than fast enough, but I 
guess going as far as PIO Mode 3 (11.1MB/s) reduces transfer latency. At 
only 500KB/s it needs all the help it can get...


> E.g. my print when using QEMU + ATAPI:
> [    0.647370] ata2: SATA max UDMA/133 abar m4096@0xfebd2000 port 0xfebd2180 irq 90 lpm-pol 0
> [    0.966896] ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> [    0.971060] ata2.00: ATAPI: QEMU DVD-ROM, 2.5+, max UDMA/100
> [    0.971818] ata2.00: applying bridge limits
> [    0.972918] ata2.00: configured for UDMA/100
> shows that the device supports up to UDMA/100, and later we also see that
> we configure it for that speed.

The TSST can do UDMA/33 according to its datasheet, so I could remove 
the libata.force line from my kernel command line and re-test if you 
wanted to know how the adapter handled UDMA.

Thanks for the details on command tracing - I'll try that in a moment 
and report back.

Thanks.
-- 
Phil.
philpem@philpem.me.uk
https://www.philpem.me.uk/

Re: Zip 100 ATAPI not working, "qc timeout" and "failed to clear UNIT ATTENTION"

[Philip Pemberton]

On 08/01/2025 14:05, Niklas Cassel wrote:
 > Since we see that the drive name is printed, the ATAPI IDENTIFY command
 > succeded (ATA_CMD_ID_ATAPI (0xA1)).
 >
 > The command that timed out is ATA_CMD_PACKET 0xA0, so a regular ATAPI 
command.

Aha - I'd tried to debug that, but thought it was a SCSI command code, 
not an ATA one.

Is there a way to find out what CDB or ATAPI packet was sent to the drive?
If necessary I can probably build a custom kernel and add some 
printk()'s but I'm hoping I don't need to!


 > The UNIT ATTENTION print is just from atapi_eh_clear_ua(), which 
seems to be
 > called by ata_eh_recover() unconditionally for ATAPI devices, because 
they
 > always need to clear UNIT ATTENTION after a reset:
 > 
https://github.com/torvalds/linux/blob/v6.8/drivers/ata/libata-eh.c#L3232-L3234
 >
 > But the reset is of course only triggered because a command has timed 
out.

I wouldn't be surprised if the failure to clear Unit Attention turned 
out to be a quirk in the Zip 100 ATAPI's ATA/ATAPI or SCSI 
implementation. They were known 'in the day' to have a few bugs [1] [2].

In any case the SATA bus reset (see larger log) sequence seems to get it 
talking again, though obviously it's not ideal.


FWIW, the drive I have is the ATAPI3 model variant, with 12.A firmware.
The pages I linked mention a "drive A:" mode - I tried that, but all it 
did was change part of the IDENTIFY response to read "FLOPPY".



[1]. 
<https://web.archive.org/web/20030207213746/http://iomega.com/software/betapatch.html>

[2]. 
<https://web.archive.org/web/20030212130255/http://pw2.netcom.com/~deepone/zipjaz/atapi.html>

Thanks
-- 
Phil.
philpem@philpem.me.uk
https://www.philpem.me.uk/

Re: Zip 100 ATAPI not working, "qc timeout" and "failed to clear UNIT ATTENTION"

[Niklas Cassel]

Hello Philip,

+linux-ide

On Wed, Jan 08, 2025 at 03:22:32PM +0000, Philip Pemberton wrote:
> On 08/01/2025 14:05, Niklas Cassel wrote:
> > Since we see that the drive name is printed, the ATAPI IDENTIFY command
> > succeded (ATA_CMD_ID_ATAPI (0xA1)).
> >
> > The command that timed out is ATA_CMD_PACKET 0xA0, so a regular ATAPI command.
>
> Aha - I'd tried to debug that, but thought it was a SCSI command code, not
> an ATA one.
>
> Is there a way to find out what CDB or ATAPI packet was sent to the drive?
> If necessary I can probably build a custom kernel and add some printk()'s
> but I'm hoping I don't need to!

If your kernel is built with trace events, you can do:

$ sudo mount -t tracefs nodev /sys/kernel/tracing

$ sudo sh -c "echo 1 > /sys/kernel/tracing/events/libata/ata_qc_issue/enable"

$ sudo cat /sys/kernel/tracing/trace
# tracer: nop
#
# entries-in-buffer/entries-written: 2/2   #P:32
#
#                                _-----=> irqs-off/BH-disabled
#                               / _----=> need-resched
#                              | / _---=> hardirq/softirq
#                              || / _--=> preempt-depth
#                              ||| / _-=> migrate-disable
#                              |||| /     delay
#           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
#              | |         |   |||||     |         |
    kworker/23:1-333     [023] d..1.   428.789473: ata_qc_issue: ata_port=2 ata_dev=0 tag=6 proto=ATAPI_PROT_PIO cmd=ATA_CMD_PACKET  tf=(a0/00:00:00:08:00/00:00:00:00:00/a0)
    kworker/11:1-321     [011] d..1.   430.837460: ata_qc_issue: ata_port=2 ata_dev=0 tag=23 proto=ATAPI_PROT_PIO cmd=ATA_CMD_PACKET  tf=(a0/00:00:00:08:00/00:00:00:00:00/a0)



For most regular ATA commands, the SCSI CDB that is received from the upper
layer (SCSI) is translated to an ATA command, and so the CDB is not written
to the device.

But for an ATA_CMD_PACKET ATAPI command, it just encapsulates the CDB as is,
within the ATA_CMD_PACKET... interesting design...

If you want to dump the CDB, you also need to do:
$ sudo sh -c "echo 1 > /sys/kernel/tracing/events/scsi/scsi_dispatch_cmd_start/enable"

     kworker/7:2-811     [007] .....   103.163426: scsi_dispatch_cmd_start: host_no=1 channel=0 id=0 lun=0 data_sgl=2 prot_sgl=0 prot_op=SCSI_PROT_NORMAL driver_tag=11 scheduler_tag=61 cmnd=(0x4a - raw=4a 01 00 00 10 00 00 00 08 00)
     kworker/7:2-811     [007] d..1.   103.163429: ata_qc_issue: ata_port=2 ata_dev=0 tag=11 proto=ATAPI_PROT_PIO cmd=ATA_CMD_PACKET  tf=(a0/00:00:00:08:00/00:00:00:00:00/a0)
    kworker/18:1-331     [018] .....   105.211404: scsi_dispatch_cmd_start: host_no=1 channel=0 id=0 lun=0 data_sgl=2 prot_sgl=0 prot_op=SCSI_PROT_NORMAL driver_tag=0 scheduler_tag=4 cmnd=(0x4a - raw=4a 01 00 00 10 00 00 00 08 00)
    kworker/18:1-331     [018] d..1.   105.211406: ata_qc_issue: ata_port=2 ata_dev=0 tag=0 proto=ATAPI_PROT_PIO cmd=ATA_CMD_PACKET  tf=(a0/00:00:00:08:00/00:00:00:00:00/a0)


Note that you could also enable the trace events using the kernel command line,
if you so prefer, by simply appending:
trace_event=libata:ata_qc_issue,scsi:scsi_dispatch_cmd_start


Note that for ATAPI, it also looks like your SATA driver needs special support.
See e.g. libahci.c which does a bunch of extra stuff if it is an ATAPI device,
e.g.:
https://github.com/torvalds/linux/blob/v6.13-rc6/drivers/ata/libahci.c#L1699-L1702
https://github.com/torvalds/linux/blob/v6.13-rc6/drivers/ata/libahci.c#L1638-L1643

Same for the libata-sff driver:
https://github.com/torvalds/linux/blob/v6.13-rc6/drivers/ata/libata-sff.c#L2672-L2684
https://github.com/torvalds/linux/blob/v6.13-rc6/drivers/ata/libata-sff.c#L295-L297
https://github.com/torvalds/linux/blob/v6.13-rc6/drivers/ata/libata-sff.c#L687-L715


Which SATA driver are you using?



> > The UNIT ATTENTION print is just from atapi_eh_clear_ua(), which seems to be
> > called by ata_eh_recover() unconditionally for ATAPI devices, because they
> > always need to clear UNIT ATTENTION after a reset:
> > https://github.com/torvalds/linux/blob/v6.8/drivers/ata/libata-eh.c#L3232-L3234
> >
> > But the reset is of course only triggered because a command has timed out.
>
> I wouldn't be surprised if the failure to clear Unit Attention turned out to
> be a quirk in the Zip 100 ATAPI's ATA/ATAPI or SCSI implementation. They
> were known 'in the day' to have a few bugs [1] [2].
>
> In any case the SATA bus reset (see larger log) sequence seems to get it
> talking again, though obviously it's not ideal.

There are the prints from the larger log sequence:


[ 4465.225787] ata3.00: configured for PIO0
[ 4470.419775] ata3.00: qc timeout after 5000 msecs (cmd 0xa0)
[ 4470.419794] ata3.00: failed to clear UNIT ATTENTION (err_mask=0x5)
[ 4470.883747] ata3: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[ 4470.890363] ata3.00: dumping IDENTIFY data, class=3 may_fallback=1
tried_spinup=0
(...)
[ 4470.890500] ata3.00: FORCE: xfer_mask set to pio0
[ 4470.897720] ata3.00: dumping IDENTIFY data, class=3 may_fallback=1
tried_spinup=0
(...)
[ 4470.897858] ata3.00: configured for PIO0
[ 4476.051591] ata3.00: qc timeout after 5000 msecs (cmd 0xa0)
[ 4476.051607] ata3.00: failed to clear UNIT ATTENTION (err_mask=0x5)
[ 4476.515583] ata3: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[ 4476.522296] ata3.00: dumping IDENTIFY data, class=3 may_fallback=1
tried_spinup=0
(...)
[ 4476.522409] ata3.00: FORCE: xfer_mask set to pio0
[ 4476.529541] ata3.00: dumping IDENTIFY data, class=3 may_fallback=1
tried_spinup=0
(...)
[ 4476.529743] ata3.00: configured for PIO0
[ 4481.683441] ata3.00: qc timeout after 5000 msecs (cmd 0xa0)
[ 4481.683457] ata3.00: failed to clear UNIT ATTENTION (err_mask=0x5)
[ 4481.683461] ata3.00: disable device
[ 4482.147601] ata3: SATA link up 1.5 Gbps (SStatus 113 SControl 300)


Are you saying that it does come up and work eventually?

When we see the "disable device" print, it is usually a sign that we have
given up, and thus remove the device.


>
>
> FWIW, the drive I have is the ATAPI3 model variant, with 12.A firmware.
> The pages I linked mention a "drive A:" mode - I tried that, but all it did
> was change part of the IDENTIFY response to read "FLOPPY".
>
>
>
> [1]. <https://web.archive.org/web/20030207213746/http://iomega.com/software/betapatch.html>
>
> [2]. <https://web.archive.org/web/20030212130255/http://pw2.netcom.com/~deepone/zipjaz/atapi.html>
>
> Thanks
> --
> Phil.
> philpem@philpem.me.uk
> https://www.philpem.me.uk/

Re: Zip 100 ATAPI not working, "qc timeout" and "failed to clear UNIT ATTENTION"

[Philip Pemberton]

On 09/01/2025 12:22, Niklas Cassel wrote:
> Hello Philip,
> 
> +linux-ide
> 
> On Wed, Jan 08, 2025 at 03:22:32PM +0000, Philip Pemberton wrote:
>> On 08/01/2025 14:05, Niklas Cassel wrote:
>>> Since we see that the drive name is printed, the ATAPI IDENTIFY command
>>> succeded (ATA_CMD_ID_ATAPI (0xA1)).
>>>
>>> The command that timed out is ATA_CMD_PACKET 0xA0, so a regular ATAPI command.
>>
>> Aha - I'd tried to debug that, but thought it was a SCSI command code, not
>> an ATA one.
>>
>> Is there a way to find out what CDB or ATAPI packet was sent to the drive?
>> If necessary I can probably build a custom kernel and add some printk()'s
>> but I'm hoping I don't need to!
> 
> If your kernel is built with trace events, you can do:
> 
> $ sudo mount -t tracefs nodev /sys/kernel/tracing

Seems like it is -- that was already mounted!

> $ sudo sh -c "echo 1 > /sys/kernel/tracing/events/libata/ata_qc_issue/enable"
> 
> $ sudo cat /sys/kernel/tracing/trace
> # tracer: nop
> #
> # entries-in-buffer/entries-written: 2/2   #P:32
> #
> #                                _-----=> irqs-off/BH-disabled
> #                               / _----=> need-resched
> #                              | / _---=> hardirq/softirq
> #                              || / _--=> preempt-depth
> #                              ||| / _-=> migrate-disable
> #                              |||| /     delay
> #           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
> #              | |         |   |||||     |         |
>      kworker/23:1-333     [023] d..1.   428.789473: ata_qc_issue: ata_port=2 ata_dev=0 tag=6 proto=ATAPI_PROT_PIO cmd=ATA_CMD_PACKET  tf=(a0/00:00:00:08:00/00:00:00:00:00/a0)
>      kworker/11:1-321     [011] d..1.   430.837460: ata_qc_issue: ata_port=2 ata_dev=0 tag=23 proto=ATAPI_PROT_PIO cmd=ATA_CMD_PACKET  tf=(a0/00:00:00:08:00/00:00:00:00:00/a0)

Here's the output I got. I've filtered out accesses to "ata_port=3" 
only, which is the Zip drive. (I had a lot of noise from "ata_port=4" 
which would be the DVD writer).

>        scsi_eh_2-219     [004] d..1. 86237.729018: ata_qc_issue: ata_port=3 ata_dev=0 tag=32 proto=ATA_PROT_PIO cmd=ATA_CMD_ID_ATAPI  tf=(a1/00:00:00:00:00/00:00:00:00:00/a0)
>        scsi_eh_2-219     [006] d..1. 86237.735641: ata_qc_issue: ata_port=3 ata_dev=0 tag=32 proto=ATA_PROT_NODATA cmd=ATA_CMD_SET_FEATURES  tf=(ef/03:08:00:00:00/00:00:00:00:00/a0)
>        scsi_eh_2-219     [006] d..1. 86237.735928: ata_qc_issue: ata_port=3 ata_dev=0 tag=32 proto=ATA_PROT_PIO cmd=ATA_CMD_ID_ATAPI  tf=(a1/00:00:00:00:00/00:00:00:00:00/a0)
>        scsi_eh_2-219     [006] d..1. 86237.742645: ata_qc_issue: ata_port=3 ata_dev=0 tag=32 proto=ATAPI_PROT_NODATA cmd=ATA_CMD_PACKET  tf=(a0/00:00:00:00:00/00:00:00:00:00/a0)
>        scsi_eh_2-219     [006] d..1. 86237.743196: ata_qc_issue: ata_port=3 ata_dev=0 tag=32 proto=ATAPI_PROT_DMA cmd=ATA_CMD_PACKET  tf=(a0/05:00:00:00:00/00:00:00:00:00/a0)
>        scsi_eh_2-219     [011] d..1. 86243.440867: ata_qc_issue: ata_port=3 ata_dev=0 tag=32 proto=ATA_PROT_PIO cmd=ATA_CMD_ID_ATAPI  tf=(a1/00:00:00:00:00/00:00:00:00:00/a0)
>        scsi_eh_2-219     [011] d..1. 86243.447703: ata_qc_issue: ata_port=3 ata_dev=0 tag=32 proto=ATA_PROT_NODATA cmd=ATA_CMD_SET_FEATURES  tf=(ef/03:08:00:00:00/00:00:00:00:00/a0)
>        scsi_eh_2-219     [011] d..1. 86243.448006: ata_qc_issue: ata_port=3 ata_dev=0 tag=32 proto=ATA_PROT_PIO cmd=ATA_CMD_ID_ATAPI  tf=(a1/00:00:00:00:00/00:00:00:00:00/a0)
>        scsi_eh_2-219     [011] d..1. 86243.454721: ata_qc_issue: ata_port=3 ata_dev=0 tag=32 proto=ATAPI_PROT_NODATA cmd=ATA_CMD_PACKET  tf=(a0/00:00:00:00:00/00:00:00:00:00/a0)
>        scsi_eh_2-219     [011] d..1. 86243.455272: ata_qc_issue: ata_port=3 ata_dev=0 tag=32 proto=ATAPI_PROT_DMA cmd=ATA_CMD_PACKET  tf=(a0/05:00:00:00:00/00:00:00:00:00/a0)
>        scsi_eh_2-219     [005] d..1. 86249.072704: ata_qc_issue: ata_port=3 ata_dev=0 tag=32 proto=ATA_PROT_PIO cmd=ATA_CMD_ID_ATAPI  tf=(a1/00:00:00:00:00/00:00:00:00:00/a0)
>        scsi_eh_2-219     [005] d..1. 86249.079384: ata_qc_issue: ata_port=3 ata_dev=0 tag=32 proto=ATA_PROT_NODATA cmd=ATA_CMD_SET_FEATURES  tf=(ef/03:08:00:00:00/00:00:00:00:00/a0)
>        scsi_eh_2-219     [005] d..1. 86249.079656: ata_qc_issue: ata_port=3 ata_dev=0 tag=32 proto=ATA_PROT_PIO cmd=ATA_CMD_ID_ATAPI  tf=(a1/00:00:00:00:00/00:00:00:00:00/a0)
>        scsi_eh_2-219     [005] d..1. 86249.086320: ata_qc_issue: ata_port=3 ata_dev=0 tag=32 proto=ATAPI_PROT_NODATA cmd=ATA_CMD_PACKET  tf=(a0/00:00:00:00:00/00:00:00:00:00/a0)
>        scsi_eh_2-219     [005] d..1. 86249.086879: ata_qc_issue: ata_port=3 ata_dev=0 tag=32 proto=ATAPI_PROT_DMA cmd=ATA_CMD_PACKET  tf=(a0/05:00:00:00:00/00:00:00:00:00/a0)

The ~5-second delay between tries is about what I was seeing on the SATA 
adapter's activity LED.


This is the sort of noise I was getting for the DVD drive:

>    kworker/u64:2-243835  [006] d..1. 86250.016698: ata_qc_issue: ata_port=4 ata_dev=0 tag=3 proto=ATAPI_PROT_PIO cmd=ATA_CMD_PACKET  tf=(a0/00:00:00:08:00/00:00:00:00:00/a0)
>    kworker/u64:1-244660  [009] d..1. 86252.064637: ata_qc_issue: ata_port=4 ata_dev=0 tag=16 proto=ATAPI_PROT_PIO cmd=ATA_CMD_PACKET  tf=(a0/00:00:00:08:00/00:00:00:00:00/a0)
>    kworker/u64:1-244660  [006] d..1. 86254.112578: ata_qc_issue: ata_port=4 ata_dev=0 tag=4 proto=ATAPI_PROT_PIO cmd=ATA_CMD_PACKET  tf=(a0/00:00:00:08:00/00:00:00:00:00/a0)
>    kworker/u64:1-244660  [004] d..1. 86256.160522: ata_qc_issue: ata_port=4 ata_dev=0 tag=31 proto=ATAPI_PROT_PIO cmd=ATA_CMD_PACKET  tf=(a0/00:00:00:08:00/00:00:00:00:00/a0)
>    kworker/u64:2-243835  [009] d..1. 86258.208459: ata_qc_issue: ata_port=4 ata_dev=0 tag=19 proto=ATAPI_PROT_PIO cmd=ATA_CMD_PACKET  tf=(a0/00:00:00:08:00/00:00:00:00:00/a0)
>    kworker/u64:8-242224  [008] d..1. 86260.256431: ata_qc_issue: ata_port=4 ata_dev=0 tag=23 proto=ATAPI_PROT_PIO cmd=ATA_CMD_PACKET  tf=(a0/00:00:00:08:00/00:00:00:00:00/a0)
>    kworker/u64:8-242224  [002] d..1. 86262.304358: ata_qc_issue: ata_port=4 ata_dev=0 tag=15 proto=ATAPI_PROT_PIO cmd=ATA_CMD_PACKET  tf=(a0/00:00:00:08:00/00:00:00:00:00/a0)
>    kworker/u64:8-242224  [003] d..1. 86264.352310: ata_qc_issue: ata_port=4 ata_dev=0 tag=15 proto=ATAPI_PROT_PIO cmd=ATA_CMD_PACKET  tf=(a0/00:00:00:08:00/00:00:00:00:00/a0)

I think it's probably just small sector reads or status polls to see if 
the disc has changed, and not relevant to the Zip drive. Just 
interesting to see it :)


> For most regular ATA commands, the SCSI CDB that is received from the upper
> layer (SCSI) is translated to an ATA command, and so the CDB is not written
> to the device.
> 
> But for an ATA_CMD_PACKET ATAPI command, it just encapsulates the CDB as is,
> within the ATA_CMD_PACKET... interesting design...
> 
> If you want to dump the CDB, you also need to do:
> $ sudo sh -c "echo 1 > /sys/kernel/tracing/events/scsi/scsi_dispatch_cmd_start/enable"
> 
>       kworker/7:2-811     [007] .....   103.163426: scsi_dispatch_cmd_start: host_no=1 channel=0 id=0 lun=0 data_sgl=2 prot_sgl=0 prot_op=SCSI_PROT_NORMAL driver_tag=11 scheduler_tag=61 cmnd=(0x4a - raw=4a 01 00 00 10 00 00 00 08 00)
>       kworker/7:2-811     [007] d..1.   103.163429: ata_qc_issue: ata_port=2 ata_dev=0 tag=11 proto=ATAPI_PROT_PIO cmd=ATA_CMD_PACKET  tf=(a0/00:00:00:08:00/00:00:00:00:00/a0)
>      kworker/18:1-331     [018] .....   105.211404: scsi_dispatch_cmd_start: host_no=1 channel=0 id=0 lun=0 data_sgl=2 prot_sgl=0 prot_op=SCSI_PROT_NORMAL driver_tag=0 scheduler_tag=4 cmnd=(0x4a - raw=4a 01 00 00 10 00 00 00 08 00)
>      kworker/18:1-331     [018] d..1.   105.211406: ata_qc_issue: ata_port=2 ata_dev=0 tag=0 proto=ATAPI_PROT_PIO cmd=ATA_CMD_PACKET  tf=(a0/00:00:00:08:00/00:00:00:00:00/a0)

I'm pretty sure there's some noise from the CD drive in here (TEST UNIT 
READY seems like something you'd do to poll for disc presence). I don't 
see any CDBs specific to the Zip drive though:

>        scsi_eh_2-219     [001] d..1. 86654.149985: ata_qc_issue: ata_port=3 ata_dev=0 tag=32 proto=ATA_PROT_PIO cmd=ATA_CMD_ID_ATAPI  tf=(a1/00:00:00:00:00/00:00:00:00:00/a0)
>        scsi_eh_2-219     [001] d..1. 86654.156717: ata_qc_issue: ata_port=3 ata_dev=0 tag=32 proto=ATA_PROT_NODATA cmd=ATA_CMD_SET_FEATURES  tf=(ef/03:08:00:00:00/00:00:00:00:00/a0)
>        scsi_eh_2-219     [001] d..1. 86654.157027: ata_qc_issue: ata_port=3 ata_dev=0 tag=32 proto=ATA_PROT_PIO cmd=ATA_CMD_ID_ATAPI  tf=(a1/00:00:00:00:00/00:00:00:00:00/a0)
>        scsi_eh_2-219     [001] d..1. 86654.163739: ata_qc_issue: ata_port=3 ata_dev=0 tag=32 proto=ATAPI_PROT_NODATA cmd=ATA_CMD_PACKET  tf=(a0/00:00:00:00:00/00:00:00:00:00/a0)
>        scsi_eh_2-219     [001] d..1. 86654.164286: ata_qc_issue: ata_port=3 ata_dev=0 tag=32 proto=ATAPI_PROT_DMA cmd=ATA_CMD_PACKET  tf=(a0/05:00:00:00:00/00:00:00:00:00/a0)
>    kworker/u64:8-242224  [011] ..... 86654.229960: scsi_dispatch_cmd_start: host_no=8 channel=0 id=0 lun=3 data_sgl=0 prot_sgl=0 prot_op=SCSI_PROT_NORMAL driver_tag=0 scheduler_tag=1 cmnd=(TEST_UNIT_READY - raw=00 00 00 00 00 00)
>    kworker/11:1H-191     [011] ..... 86654.232462: scsi_dispatch_cmd_start: host_no=8 channel=0 id=0 lun=0 data_sgl=0 prot_sgl=0 prot_op=SCSI_PROT_NORMAL driver_tag=0 scheduler_tag=1 cmnd=(TEST_UNIT_READY - raw=00 00 00 00 00 00)
>    kworker/10:1H-195     [010] ..... 86654.234515: scsi_dispatch_cmd_start: host_no=8 channel=0 id=0 lun=1 data_sgl=0 prot_sgl=0 prot_op=SCSI_PROT_NORMAL driver_tag=0 scheduler_tag=1 cmnd=(TEST_UNIT_READY - raw=00 00 00 00 00 00)
>    kworker/u64:2-243835  [003] ..... 86654.293953: scsi_dispatch_cmd_start: host_no=8 channel=0 id=0 lun=2 data_sgl=0 prot_sgl=0 prot_op=SCSI_PROT_NORMAL driver_tag=0 scheduler_tag=1 cmnd=(TEST_UNIT_READY - raw=00 00 00 00 00 00)
>    kworker/u64:2-243835  [006] ..... 86655.317932: scsi_dispatch_cmd_start: host_no=7 channel=0 id=0 lun=0 data_sgl=0 prot_sgl=0 prot_op=SCSI_PROT_NORMAL driver_tag=0 scheduler_tag=0 cmnd=(TEST_UNIT_READY - raw=00 00 00 00 00 00)
>    kworker/u64:1-244660  [000] ..... 86655.509932: scsi_dispatch_cmd_start: host_no=3 channel=0 id=0 lun=0 data_sgl=2 prot_sgl=0 prot_op=SCSI_PROT_NORMAL driver_tag=31 scheduler_tag=15 cmnd=(0x4a - raw=4a 01 00 00 10 00 00 00 08 00)
>    kworker/u64:1-244660  [000] d..1. 86655.509943: ata_qc_issue: ata_port=4 ata_dev=0 tag=31 proto=ATAPI_PROT_PIO cmd=ATA_CMD_PACKET  tf=(a0/00:00:00:08:00/00:00:00:00:00/a0)
>    kworker/u64:1-244660  [000] ..... 86656.277913: scsi_dispatch_cmd_start: host_no=8 channel=0 id=0 lun=0 data_sgl=0 prot_sgl=0 prot_op=SCSI_PROT_NORMAL driver_tag=0 scheduler_tag=0 cmnd=(TEST_UNIT_READY - raw=00 00 00 00 00 00)
>     kworker/0:1H-196     [000] ..... 86656.280741: scsi_dispatch_cmd_start: host_no=8 channel=0 id=0 lun=1 data_sgl=0 prot_sgl=0 prot_op=SCSI_PROT_NORMAL driver_tag=0 scheduler_tag=0 cmnd=(TEST_UNIT_READY - raw=00 00 00 00 00 00)
>    kworker/11:1H-191     [011] ..... 86656.282924: scsi_dispatch_cmd_start: host_no=8 channel=0 id=0 lun=3 data_sgl=0 prot_sgl=0 prot_op=SCSI_PROT_NORMAL driver_tag=0 scheduler_tag=0 cmnd=(TEST_UNIT_READY - raw=00 00 00 00 00 00)
>    kworker/u64:8-242224  [000] ..... 86656.341898: scsi_dispatch_cmd_start: host_no=8 channel=0 id=0 lun=2 data_sgl=0 prot_sgl=0 prot_op=SCSI_PROT_NORMAL driver_tag=0 scheduler_tag=0 cmnd=(TEST_UNIT_READY - raw=00 00 00 00 00 00)
>    kworker/u64:8-242224  [006] ..... 86657.365885: scsi_dispatch_cmd_start: host_no=7 channel=0 id=0 lun=0 data_sgl=0 prot_sgl=0 prot_op=SCSI_PROT_NORMAL driver_tag=0 scheduler_tag=1 cmnd=(TEST_UNIT_READY - raw=00 00 00 00 00 00)
>    kworker/u64:2-243835  [011] ..... 86657.558879: scsi_dispatch_cmd_start: host_no=3 channel=0 id=0 lun=0 data_sgl=2 prot_sgl=0 prot_op=SCSI_PROT_NORMAL driver_tag=9 scheduler_tag=43 cmnd=(0x4a - raw=4a 01 00 00 10 00 00 00 08 00)
>    kworker/u64:2-243835  [011] d..1. 86657.558889: ata_qc_issue: ata_port=4 ata_dev=0 tag=9 proto=ATAPI_PROT_PIO cmd=ATA_CMD_PACKET  tf=(a0/00:00:00:08:00/00:00:00:00:00/a0)
>    kworker/u64:2-243835  [000] ..... 86658.325849: scsi_dispatch_cmd_start: host_no=8 channel=0 id=0 lun=3 data_sgl=0 prot_sgl=0 prot_op=SCSI_PROT_NORMAL driver_tag=0 scheduler_tag=1 cmnd=(TEST_UNIT_READY - raw=00 00 00 00 00 00)
>     kworker/6:1H-192     [006] ..... 86658.328070: scsi_dispatch_cmd_start: host_no=8 channel=0 id=0 lun=0 data_sgl=0 prot_sgl=0 prot_op=SCSI_PROT_NORMAL driver_tag=0 scheduler_tag=1 cmnd=(TEST_UNIT_READY - raw=00 00 00 00 00 00)
>     kworker/7:1H-204     [007] ..... 86658.330167: scsi_dispatch_cmd_start: host_no=8 channel=0 id=0 lun=1 data_sgl=0 prot_sgl=0 prot_op=SCSI_PROT_NORMAL driver_tag=0 scheduler_tag=1 cmnd=(TEST_UNIT_READY - raw=00 00 00 00 00 00)
>    kworker/u64:8-242224  [007] ..... 86658.390842: scsi_dispatch_cmd_start: host_no=8 channel=0 id=0 lun=2 data_sgl=0 prot_sgl=0 prot_op=SCSI_PROT_NORMAL driver_tag=0 scheduler_tag=1 cmnd=(TEST_UNIT_READY - raw=00 00 00 00 00 00)
>    kworker/u64:8-242224  [010] ..... 86659.413818: scsi_dispatch_cmd_start: host_no=7 channel=0 id=0 lun=0 data_sgl=0 prot_sgl=0 prot_op=SCSI_PROT_NORMAL driver_tag=0 scheduler_tag=0 cmnd=(TEST_UNIT_READY - raw=00 00 00 00 00 00)
>    kworker/u64:2-243835  [000] ..... 86659.605846: scsi_dispatch_cmd_start: host_no=3 channel=0 id=0 lun=0 data_sgl=2 prot_sgl=0 prot_op=SCSI_PROT_NORMAL driver_tag=6 scheduler_tag=16 cmnd=(0x4a - raw=4a 01 00 00 10 00 00 00 08 00)
>    kworker/u64:2-243835  [000] d..1. 86659.605855: ata_qc_issue: ata_port=4 ata_dev=0 tag=6 proto=ATAPI_PROT_PIO cmd=ATA_CMD_PACKET  tf=(a0/00:00:00:08:00/00:00:00:00:00/a0)
>        scsi_eh_2-219     [001] d..1. 86659.685828: ata_qc_issue: ata_port=3 ata_dev=0 tag=32 proto=ATA_PROT_PIO cmd=ATA_CMD_ID_ATAPI  tf=(a1/00:00:00:00:00/00:00:00:00:00/a0)
>        scsi_eh_2-219     [001] d..1. 86659.692572: ata_qc_issue: ata_port=3 ata_dev=0 tag=32 proto=ATA_PROT_NODATA cmd=ATA_CMD_SET_FEATURES  tf=(ef/03:08:00:00:00/00:00:00:00:00/a0)
>        scsi_eh_2-219     [004] d..1. 86659.692866: ata_qc_issue: ata_port=3 ata_dev=0 tag=32 proto=ATA_PROT_PIO cmd=ATA_CMD_ID_ATAPI  tf=(a1/00:00:00:00:00/00:00:00:00:00/a0)
>        scsi_eh_2-219     [001] d..1. 86659.699575: ata_qc_issue: ata_port=3 ata_dev=0 tag=32 proto=ATAPI_PROT_NODATA cmd=ATA_CMD_PACKET  tf=(a0/00:00:00:00:00/00:00:00:00:00/a0)
>        scsi_eh_2-219     [001] d..1. 86659.700126: ata_qc_issue: ata_port=3 ata_dev=0 tag=32 proto=ATAPI_PROT_DMA cmd=ATA_CMD_PACKET  tf=(a0/05:00:00:00:00/00:00:00:00:00/a0)
>    kworker/u64:2-243835  [006] ..... 86660.373797: scsi_dispatch_cmd_start: host_no=8 channel=0 id=0 lun=3 data_sgl=0 prot_sgl=0 prot_op=SCSI_PROT_NORMAL driver_tag=0 scheduler_tag=0 cmnd=(TEST_UNIT_READY - raw=00 00 00 00 00 00)
>     kworker/6:1H-192     [006] ..... 86660.376058: scsi_dispatch_cmd_start: host_no=8 channel=0 id=0 lun=0 data_sgl=0 prot_sgl=0 prot_op=SCSI_PROT_NORMAL driver_tag=0 scheduler_tag=0 cmnd=(TEST_UNIT_READY - raw=00 00 00 00 00 00)
>    kworker/10:1H-195     [010] ..... 86660.378167: scsi_dispatch_cmd_start: host_no=8 channel=0 id=0 lun=1 data_sgl=0 prot_sgl=0 prot_op=SCSI_PROT_NORMAL driver_tag=0 scheduler_tag=0 cmnd=(TEST_UNIT_READY - raw=00 00 00 00 00 00)
>    kworker/u64:8-242224  [009] ..... 86660.437787: scsi_dispatch_cmd_start: host_no=8 channel=0 id=0 lun=2 data_sgl=0 prot_sgl=0 prot_op=SCSI_PROT_NORMAL driver_tag=0 scheduler_tag=0 cmnd=(TEST_UNIT_READY - raw=00 00 00 00 00 00)
>    kworker/u64:8-242224  [009] ..... 86661.461766: scsi_dispatch_cmd_start: host_no=7 channel=0 id=0 lun=0 data_sgl=0 prot_sgl=0 prot_op=SCSI_PROT_NORMAL driver_tag=0 scheduler_tag=1 cmnd=(TEST_UNIT_READY - raw=00 00 00 00 00 00)
>    kworker/u64:2-243835  [006] ..... 86661.653786: scsi_dispatch_cmd_start: host_no=3 channel=0 id=0 lun=0 data_sgl=2 prot_sgl=0 prot_op=SCSI_PROT_NORMAL driver_tag=6 scheduler_tag=14 cmnd=(0x4a - raw=4a 01 00 00 10 00 00 00 08 00)
>    kworker/u64:2-243835  [006] d..1. 86661.653795: ata_qc_issue: ata_port=4 ata_dev=0 tag=6 proto=ATAPI_PROT_PIO cmd=ATA_CMD_PACKET  tf=(a0/00:00:00:08:00/00:00:00:00:00/a0)

(Repeating myself here, ata4 / ata_port=4 is the DVD drive; ata_port=3 
is the Zip drive)

There's quite a lot on the ATA buses, so if it helps --
   ata1: Samsung 860 SSD
   ata2: WD 500GB mechanical hard drive
   ata3: Spare port / Zip drive
   ata4: DVD writer
   ata5: Not used
   ata6: Not used

There are a couple of SATA disks and a SAS tape drive on an LSI SAS card 
but they seem to go through the "scsi" and "mpt2sas" driver route.


> Note that for ATAPI, it also looks like your SATA driver needs special support.
> See e.g. libahci.c which does a bunch of extra stuff if it is an ATAPI device,
> e.g.:
> https://github.com/torvalds/linux/blob/v6.13-rc6/drivers/ata/libahci.c#L1699-L1702
> https://github.com/torvalds/linux/blob/v6.13-rc6/drivers/ata/libahci.c#L1638-L1643
> 
> Same for the libata-sff driver:
> https://github.com/torvalds/linux/blob/v6.13-rc6/drivers/ata/libata-sff.c#L2672-L2684
> https://github.com/torvalds/linux/blob/v6.13-rc6/drivers/ata/libata-sff.c#L295-L297
> https://github.com/torvalds/linux/blob/v6.13-rc6/drivers/ata/libata-sff.c#L687-L715
> 
> 
> Which SATA driver are you using?

It looks like it's "ahci" or "libahci".


> Are you saying that it does come up and work eventually?
> 
> When we see the "disable device" print, it is usually a sign that we have
> given up, and thus remove the device.

No, it tries to connect three times, then gives up and disables the device.

It won't try again unless the drive is hotplugged or the machine 
rebooted. I expect there's probably a route to reset the SATA port 
through sysfs too, but I haven't really looked closely at that.

Thanks.
-- 
Phil.
philpem@philpem.me.uk
https://www.philpem.me.uk/

Re: Zip 100 ATAPI not working, "qc timeout" and "failed to clear UNIT ATTENTION"

[Niklas Cassel]

Hello Philip,

On Thu, Jan 09, 2025 at 03:31:05PM +0000, Philip Pemberton wrote:
> (Repeating myself here, ata4 / ata_port=4 is the DVD drive; ata_port=3 is
> the Zip drive)
> 
> There's quite a lot on the ATA buses, so if it helps --
>   ata1: Samsung 860 SSD
>   ata2: WD 500GB mechanical hard drive
>   ata3: Spare port / Zip drive
>   ata4: DVD writer
>   ata5: Not used
>   ata6: Not used
> 
> There are a couple of SATA disks and a SAS tape drive on an LSI SAS card but
> they seem to go through the "scsi" and "mpt2sas" driver route.
> 
> 
> > Note that for ATAPI, it also looks like your SATA driver needs special support.
> > See e.g. libahci.c which does a bunch of extra stuff if it is an ATAPI device,
> > e.g.:
> > https://github.com/torvalds/linux/blob/v6.13-rc6/drivers/ata/libahci.c#L1699-L1702
> > https://github.com/torvalds/linux/blob/v6.13-rc6/drivers/ata/libahci.c#L1638-L1643
> > 
> > Same for the libata-sff driver:
> > https://github.com/torvalds/linux/blob/v6.13-rc6/drivers/ata/libata-sff.c#L2672-L2684
> > https://github.com/torvalds/linux/blob/v6.13-rc6/drivers/ata/libata-sff.c#L295-L297
> > https://github.com/torvalds/linux/blob/v6.13-rc6/drivers/ata/libata-sff.c#L687-L715
> > 
> > 
> > Which SATA driver are you using?
> 
> It looks like it's "ahci" or "libahci".
> 
> 
> > Are you saying that it does come up and work eventually?
> > 
> > When we see the "disable device" print, it is usually a sign that we have
> > given up, and thus remove the device.
> 
> No, it tries to connect three times, then gives up and disables the device.

Unfortunately, so far I do not think that we have enough information to
do much about this issue.

We know that the "SATA-to-PATA adatper + Zip drive" combo worked on some
other PC (that might have used another SATA HBA) with an ancient kernel.

I think my first recommendation would be to try to build an ancient kernel
on your current PC, and see if the same "SATA-to-PATA adatper + Zip drive"
combo then works. If it does work, then I think the best bet is to use
PCI passthrough and do an git bisection (which can be automated).

Or, do the opposite, see if the latest kernel with other PC still handles
the Zip drive properly, if it doesn't, then perhaps the best thing is to
to the bisection on this other PC.

You could look at this guide for inspiration:
https://github.com/floatious/qemu-bisect-doc


Kind regards,
Niklas

Re: Zip 100 ATAPI not working, "qc timeout" and "failed to clear UNIT ATTENTION"

[Philip Pemberton]

Hi Niklas,

On 17/01/2025 13:37, Niklas Cassel wrote:
> Unfortunately, so far I do not think that we have enough information to
> do much about this issue.
> 
> We know that the "SATA-to-PATA adatper + Zip drive" combo worked on some
> other PC (that might have used another SATA HBA) with an ancient kernel.
> 
> I think my first recommendation would be to try to build an ancient kernel
> on your current PC, and see if the same "SATA-to-PATA adatper + Zip drive"
> combo then works. If it does work, then I think the best bet is to use
> PCI passthrough and do an git bisection (which can be automated).
> 
> Or, do the opposite, see if the latest kernel with other PC still handles
> the Zip drive properly, if it doesn't, then perhaps the best thing is to
> to the bisection on this other PC.

I've just got the other PC up and running, running a network boot of 
Debian to make it easy to swap and change kernels and initrd's.

I've tested the following kernels and found them to work --

Debian Buster - 4.19.0-27-686-pae - no issues accessing the Zip drive.
Debian Buster - 5.10.0-0-686 - likewise.
Debian Bookworm - 6.1.0-30-686-pae

I checked and found (via "udevadm info -an /dev/sdX | grep DRIVER") that 
it was using the ata_piix driver.
By the same route (udevadm), the workstation is using the "ahci" driver.

I'm not sure what that really says, other than the PIIX driver isn't 
affected.

I'll dig out another machine which uses the "ahci" driver (and ideally 
the same chipset) and report back with my findings.

Thanks,
-- 
Phil.
philpem@philpem.me.uk
https://www.philpem.me.uk/

Re: Zip 100 ATAPI not working, "qc timeout" and "failed to clear UNIT ATTENTION"

[Philip Pemberton]

Hi Niklas,

I've reproduced the issue on an Intel based board (an Asus ROG Rampage 
Formula with a Q

I tested with the following Debian kernels --

vmlinuz-6.10.11+bpo-686-pae   (bookworm)
vmlinuz-6.1.0-30-686-pae      (bookworm)
vmlinuz-5.10.0-0.deb10.30-686 (buster)
vmlinuz-4.19.0-27-686-pae     (buster)

This is with no libata related options on the kernel command line:

[    0.062948] Kernel command line: 
BOOT_IMAGE=boot/vmlinuz-4.19.0-27-686-pae root=/dev/nfs 
nfsroot=10.0.0.32:/mnt/zfs/debian-nfs-boot,rw ip=dhcp 
initrd=boot/initrd.img-4.19.0-27-686-pae

Here is the output from the 4.19 kernel when it tries to initialise the 
Zip drive:

> [    2.549684] scsi host0: ahci
> [    2.550052] scsi host1: ahci
> [    2.550260] scsi host2: ahci
> [    2.550474] scsi host3: ahci
> [    2.550692] scsi host4: ahci
> [    2.550905] scsi host5: ahci
> [    2.551061] ata1: SATA max UDMA/133 abar m2048@0xf9ffe800 port 0xf9ffe900 irq 26
> [    2.551133] ata2: SATA max UDMA/133 abar m2048@0xf9ffe800 port 0xf9ffe980 irq 26
> [    2.551204] ata3: SATA max UDMA/133 abar m2048@0xf9ffe800 port 0xf9ffea00 irq 26
> [    2.551275] ata4: SATA max UDMA/133 abar m2048@0xf9ffe800 port 0xf9ffea80 irq 26
> [    2.551346] ata5: SATA max UDMA/133 abar m2048@0xf9ffe800 port 0xf9ffeb00 irq 26
> [    2.551417] ata6: SATA max UDMA/133 abar m2048@0xf9ffe800 port 0xf9ffeb80 irq 26
> [    2.863069] ata1: SATA link down (SStatus 0 SControl 300)
> [    3.041029] firewire_core 0000:05:03.0: created device fw0: GUID 001e8c0000b2df93, S400
> [    3.175068] ata2: SATA link down (SStatus 0 SControl 300)
> [    3.648939] ata3: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
> [    3.651027] ata3.00: ATA-8: WDC WD1001FALS-00E3A0, 05.01D05, max UDMA/133
> [    3.651084] ata3.00: 1953525168 sectors, multi 16: LBA48 NCQ (depth 32), AA
> [    3.653455] ata3.00: configured for UDMA/133
> [    3.653693] scsi 2:0:0:0: Direct-Access     ATA      WDC WD1001FALS-0 1D05 PQ: 0 ANSI: 5
> [    4.128939] ata4: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> [    4.135599] ata4.00: ATAPI: IOMEGA  ZIP 100       ATAPI, 12.A, max PIO3, CDB intr
> [    4.135671] ata4.00: applying bridge limits
> [    4.142464] ata4.00: configured for PIO3
> [    9.216983] ata4.00: qc timeout (cmd 0xa0)
> [    9.217040] ata4.00: failed to clear UNIT ATTENTION (err_mask=0x5)
> [    9.692938] ata4: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> [    9.706493] ata4.00: configured for PIO3
> [   14.848995] ata4.00: qc timeout (cmd 0xa0)
> [   14.849051] ata4.00: failed to clear UNIT ATTENTION (err_mask=0x5)
> [   14.849107] ata4.00: limiting speed to PIO2
> [   15.324938] ata4: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> [   15.338347] ata4.00: configured for PIO2
> [   20.480928] ata4.00: qc timeout (cmd 0xa0)
> [   20.480984] ata4.00: failed to clear UNIT ATTENTION (err_mask=0x5)
> [   20.481039] ata4.00: disabled
> [   20.956939] ata4: SATA link up 1.5 Gbps (SStatus 113 SControl 300)

The messages are the same (albeit with different timings) on every 
kernel up to and including 6.10.11+bpo-686-pae.

I can try and go back earlier if it would help.

If it helps any (see my previous message for more), the ata_piix driver 
on an Intel ICH5 Northbridge + 82801EB Southbridge (Aopen EZ65 board) 
seems to work fine on the exact same kernels (literally the same binaries).

32/64 bit seems not to be a contributing factor as the AMD B550 machine 
is fully 64-bit (userspace and kernel) and boots via UEFI.

Thanks,
Phil.


On 17/01/2025 13:37, Niklas Cassel wrote:
> Hello Philip,
> 
> On Thu, Jan 09, 2025 at 03:31:05PM +0000, Philip Pemberton wrote:
>> (Repeating myself here, ata4 / ata_port=4 is the DVD drive; ata_port=3 is
>> the Zip drive)
>>
>> There's quite a lot on the ATA buses, so if it helps --
>>    ata1: Samsung 860 SSD
>>    ata2: WD 500GB mechanical hard drive
>>    ata3: Spare port / Zip drive
>>    ata4: DVD writer
>>    ata5: Not used
>>    ata6: Not used
>>
>> There are a couple of SATA disks and a SAS tape drive on an LSI SAS card but
>> they seem to go through the "scsi" and "mpt2sas" driver route.
>>
>>
>>> Note that for ATAPI, it also looks like your SATA driver needs special support.
>>> See e.g. libahci.c which does a bunch of extra stuff if it is an ATAPI device,
>>> e.g.:
>>> https://github.com/torvalds/linux/blob/v6.13-rc6/drivers/ata/libahci.c#L1699-L1702
>>> https://github.com/torvalds/linux/blob/v6.13-rc6/drivers/ata/libahci.c#L1638-L1643
>>>
>>> Same for the libata-sff driver:
>>> https://github.com/torvalds/linux/blob/v6.13-rc6/drivers/ata/libata-sff.c#L2672-L2684
>>> https://github.com/torvalds/linux/blob/v6.13-rc6/drivers/ata/libata-sff.c#L295-L297
>>> https://github.com/torvalds/linux/blob/v6.13-rc6/drivers/ata/libata-sff.c#L687-L715
>>>
>>>
>>> Which SATA driver are you using?
>>
>> It looks like it's "ahci" or "libahci".
>>
>>
>>> Are you saying that it does come up and work eventually?
>>>
>>> When we see the "disable device" print, it is usually a sign that we have
>>> given up, and thus remove the device.
>>
>> No, it tries to connect three times, then gives up and disables the device.
> 
> Unfortunately, so far I do not think that we have enough information to
> do much about this issue.
> 
> We know that the "SATA-to-PATA adatper + Zip drive" combo worked on some
> other PC (that might have used another SATA HBA) with an ancient kernel.
> 
> I think my first recommendation would be to try to build an ancient kernel
> on your current PC, and see if the same "SATA-to-PATA adatper + Zip drive"
> combo then works. If it does work, then I think the best bet is to use
> PCI passthrough and do an git bisection (which can be automated).
> 
> Or, do the opposite, see if the latest kernel with other PC still handles
> the Zip drive properly, if it doesn't, then perhaps the best thing is to
> to the bisection on this other PC.
> 
> You could look at this guide for inspiration:
> https://github.com/floatious/qemu-bisect-doc
> 
> 
> Kind regards,
> Niklas
> 

-- 
Phil.
philpem@philpem.me.uk
https://www.philpem.me.uk/

Re: Zip 100 ATAPI not working, "qc timeout" and "failed to clear UNIT ATTENTION"

[Niklas Cassel]

Hello Philip,

On Thu, Jan 23, 2025 at 04:19:44PM +0000, Philip Pemberton wrote:
> Hi Niklas,
> 
> I've reproduced the issue on an Intel based board (an Asus ROG Rampage
> Formula with a Q
> 
> I tested with the following Debian kernels --
> 
> vmlinuz-6.10.11+bpo-686-pae   (bookworm)
> vmlinuz-6.1.0-30-686-pae      (bookworm)
> vmlinuz-5.10.0-0.deb10.30-686 (buster)
> vmlinuz-4.19.0-27-686-pae     (buster)
> 
> This is with no libata related options on the kernel command line:
> 
> [    0.062948] Kernel command line:
> BOOT_IMAGE=boot/vmlinuz-4.19.0-27-686-pae root=/dev/nfs
> nfsroot=10.0.0.32:/mnt/zfs/debian-nfs-boot,rw ip=dhcp
> initrd=boot/initrd.img-4.19.0-27-686-pae
> 
> Here is the output from the 4.19 kernel when it tries to initialise the Zip
> drive:
> 
> > [    2.549684] scsi host0: ahci
> > [    2.550052] scsi host1: ahci
> > [    2.550260] scsi host2: ahci
> > [    2.550474] scsi host3: ahci
> > [    2.550692] scsi host4: ahci
> > [    2.550905] scsi host5: ahci
> > [    2.551061] ata1: SATA max UDMA/133 abar m2048@0xf9ffe800 port 0xf9ffe900 irq 26
> > [    2.551133] ata2: SATA max UDMA/133 abar m2048@0xf9ffe800 port 0xf9ffe980 irq 26
> > [    2.551204] ata3: SATA max UDMA/133 abar m2048@0xf9ffe800 port 0xf9ffea00 irq 26
> > [    2.551275] ata4: SATA max UDMA/133 abar m2048@0xf9ffe800 port 0xf9ffea80 irq 26
> > [    2.551346] ata5: SATA max UDMA/133 abar m2048@0xf9ffe800 port 0xf9ffeb00 irq 26
> > [    2.551417] ata6: SATA max UDMA/133 abar m2048@0xf9ffe800 port 0xf9ffeb80 irq 26
> > [    2.863069] ata1: SATA link down (SStatus 0 SControl 300)
> > [    3.041029] firewire_core 0000:05:03.0: created device fw0: GUID 001e8c0000b2df93, S400
> > [    3.175068] ata2: SATA link down (SStatus 0 SControl 300)
> > [    3.648939] ata3: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
> > [    3.651027] ata3.00: ATA-8: WDC WD1001FALS-00E3A0, 05.01D05, max UDMA/133
> > [    3.651084] ata3.00: 1953525168 sectors, multi 16: LBA48 NCQ (depth 32), AA
> > [    3.653455] ata3.00: configured for UDMA/133
> > [    3.653693] scsi 2:0:0:0: Direct-Access     ATA      WDC WD1001FALS-0 1D05 PQ: 0 ANSI: 5
> > [    4.128939] ata4: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> > [    4.135599] ata4.00: ATAPI: IOMEGA  ZIP 100       ATAPI, 12.A, max PIO3, CDB intr
> > [    4.135671] ata4.00: applying bridge limits
> > [    4.142464] ata4.00: configured for PIO3
> > [    9.216983] ata4.00: qc timeout (cmd 0xa0)
> > [    9.217040] ata4.00: failed to clear UNIT ATTENTION (err_mask=0x5)
> > [    9.692938] ata4: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> > [    9.706493] ata4.00: configured for PIO3
> > [   14.848995] ata4.00: qc timeout (cmd 0xa0)
> > [   14.849051] ata4.00: failed to clear UNIT ATTENTION (err_mask=0x5)
> > [   14.849107] ata4.00: limiting speed to PIO2
> > [   15.324938] ata4: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> > [   15.338347] ata4.00: configured for PIO2
> > [   20.480928] ata4.00: qc timeout (cmd 0xa0)
> > [   20.480984] ata4.00: failed to clear UNIT ATTENTION (err_mask=0x5)
> > [   20.481039] ata4.00: disabled
> > [   20.956939] ata4: SATA link up 1.5 Gbps (SStatus 113 SControl 300)

I little bit weird that we see link up after it has been disabled.

I assume that the device is unusable at this point?


> 
> The messages are the same (albeit with different timings) on every kernel up
> to and including 6.10.11+bpo-686-pae.
> 
> I can try and go back earlier if it would help.
> 
> If it helps any (see my previous message for more), the ata_piix driver on
> an Intel ICH5 Northbridge + 82801EB Southbridge (Aopen EZ65 board) seems to
> work fine on the exact same kernels (literally the same binaries).
> 
> 32/64 bit seems not to be a contributing factor as the AMD B550 machine is
> fully 64-bit (userspace and kernel) and boots via UEFI.

It seems to me that you have found out that your "SATA to PATA adapter + Zip
drive" works fine on recent kernels (v6.10) with the ata_piix driver, but not
with the ahci driver on that same kernel version.

This does suggest to me that there is some bug in the ATAPI specific code in
the ahci driver.

This makes me a little bit surprised, since ahci is usually the most well
tested driver. I'm quite sure that people have CD/DVD ATAPI devices working
with the ahci drivers, so in order to get to the root of this issue, you would
probably need to debug the ahci driver.

I wonder which bug there could be in the ahci driver that allows it to work
with a lot of ATAPI devices, but not your "SATA to PATA adapter + Zip drive".

Did you try using the same mode as the ata_piix machine? e.g. PIO0/PIO3/DMA.

You didn't paste the dmesg from the ata_piix driver.
Did it have ", DMADIR" as part of the string that prints the device?
i.e.
"[    4.135599] ata4.00: ATAPI: IOMEGA  ZIP 100       ATAPI, 12.A, max PIO3, CDB intr"



Kind regards,
Niklas

Re: Zip 100 ATAPI not working, "qc timeout" and "failed to clear UNIT ATTENTION"

[Philip Pemberton]

Hi Niklas,

On 24/01/2025 10:03, Niklas Cassel wrote:
> Did you try using the same mode as the ata_piix machine? e.g. PIO0/PIO3/DMA.

Yes, I let the kernel autodetect the mode. PIIX didn't rell me what PIO 
mode it had selected.

> You didn't paste the dmesg from the ata_piix driver.
> Did it have ", DMADIR" as part of the string that prints the device?
> i.e.
> "[    4.135599] ata4.00: ATAPI: IOMEGA  ZIP 100       ATAPI, 12.A, max PIO3, CDB intr"

No, there was no mention of DMADIR on the PIIX or the AHCI system.


> I wonder which bug there could be in the ahci driver that allows it to work
> with a lot of ATAPI devices, but not your "SATA to PATA adapter + Zip drive".

I've built a kernel from source tonight (6.10 from the Debian source) 
and added some printk's to try and figure out what's going on.

Starting with the AHCI system...

When the function atapi_eh_clear_ua() [libata-eh.c:3294] is entered, the 
driver sends a SCSI "TEST UNIT READY" (scsicmd 0) CDB inside an ATAPI 
packet command (cmd 0xa0):

[    4.408044] ata4: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[    4.408107] ata4.00: direction 2 dmadir 0
[    4.414687] ata4.00: ATAPI: IOMEGA  ZIP 100       ATAPI, 12.A, max 
PIO3, CDB intr
[    4.414815] ata4.00: applying bridge limits
[    4.414870] ata4.00: direction 3 dmadir 0
[    4.415153] ata4.00: direction 2 dmadir 0
[    4.421662] ata4.00: configured for PIO3
[    4.421768] ata4.00: About to do TEST UNIT READY
[    4.421770] ata4.00: CDB[0] = 0x00
[    4.421824] ata4.00: CDB[1] = 0x00
[    4.421876] ata4.00: CDB[2] = 0x00
[    4.421929] ata4.00: CDB[3] = 0x00
[    4.421981] ata4.00: CDB[4] = 0x00
[    4.422033] ata4.00: CDB[5] = 0x00
[    4.422085] ata4.00: CDB[6] = 0x00
[    4.422138] ata4.00: CDB[7] = 0x00
[    4.422190] ata4.00: CDB[8] = 0x00
[    4.422242] ata4.00: CDB[9] = 0x00
[    4.422294] ata4.00: CDB[10] = 0x00
[    4.422347] ata4.00: CDB[11] = 0x00
[    4.422399] ata4.00: CDB[12] = 0x00
[    4.422452] ata4.00: CDB[13] = 0x00
[    4.422504] ata4.00: CDB[14] = 0x00
[    4.422556] ata4.00: CDB[15] = 0x00
[    4.422609] ata4.00: direction 3 dmadir 0
[    4.423185] ata4.00: TEST UNIT READY err_mask=1 sense_key=6

This fails with err_mask=1 (AC_ERR_DEV=1, "device reported error", 
defined in libata.h). Sense key 6 is UNIT ATTENTION, per 
<https://www.t10.org/lists/2sensekey.htm>.

The code then goes on to send a SCSI "REQUEST SENSE" CDB (scsicmd 0x03) 
in an attempt to clear the UNIT ATTENTION flag. It's this command which 
times out:

[    4.423239] ata4.00: CDB[0] = 0x03
[    4.423295] ata4.00: CDB[1] = 0x00
[    4.423347] ata4.00: CDB[2] = 0x00
[    4.423399] ata4.00: CDB[3] = 0x00
[    4.423452] ata4.00: CDB[4] = 0x60
[    4.423504] ata4.00: CDB[5] = 0x00
[    4.423556] ata4.00: CDB[6] = 0x00
[    4.423609] ata4.00: CDB[7] = 0x00
[    4.423661] ata4.00: CDB[8] = 0x00
[    4.423713] ata4.00: CDB[9] = 0x00
[    4.423765] ata4.00: CDB[10] = 0x00
[    4.423817] ata4.00: CDB[11] = 0x00
[    4.423870] ata4.00: CDB[12] = 0x00
[    4.423922] ata4.00: CDB[13] = 0x00
[    4.423974] ata4.00: CDB[14] = 0x00
[    4.424026] ata4.00: CDB[15] = 0x00
[    4.424079] ata4.00: direction 2 dmadir 0
[    9.556040] ata4.00: qc timeout after 5000 msecs (cmd 0xa0 cdb[0] 0x3)
[    9.556155] ata4.00: REQUEST SENSE err_mask=5 sense_key=6

It does this for PIO3 and PIO2.


Back onto the PIIX the drive initialises, then there seem to be a couple 
of non-ATAPI commands:

[    4.564157] ata4.00: ATAPI: IOMEGA  ZIP 100       ATAPI, 12.A, max 
PIO3, CDB intr
[    4.564223] ata4.00: applying bridge limits
[    4.564270] ata4.00: direction 3 dmadir 0
[    4.566480] ata4.00: direction 2 dmadir 0

TEST UNIT READY gives the same response:

[    4.588159] ata4.00: About to do TEST UNIT READY
[    4.588167] ata4.00: CDB[0] = 0x00
[    4.588214] ata4.00: CDB[1] = 0x00
[    4.588256] ata4.00: CDB[2] = 0x00
[    4.588297] ata4.00: CDB[3] = 0x00
[    4.588339] ata4.00: CDB[4] = 0x00
[    4.588380] ata4.00: CDB[5] = 0x00
[    4.588421] ata4.00: CDB[6] = 0x00
[    4.588462] ata4.00: CDB[7] = 0x00
[    4.588504] ata4.00: CDB[8] = 0x00
[    4.588545] ata4.00: CDB[9] = 0x00
[    4.588586] ata4.00: CDB[10] = 0x00
[    4.588627] ata4.00: CDB[11] = 0x00
[    4.588669] ata4.00: CDB[12] = 0x00
[    4.588710] ata4.00: CDB[13] = 0x00
[    4.588751] ata4.00: CDB[14] = 0x00
[    4.588792] ata4.00: CDB[15] = 0x00
[    4.588834] ata4.00: direction 3 dmadir 0
[    4.589445] ata4.00: TEST UNIT READY err_mask=1 sense_key=6

But REQUEST SENSE doesn't time out:

[    4.589490] ata4.00: CDB[0] = 0x03
[    4.589534] ata4.00: CDB[1] = 0x00
[    4.589575] ata4.00: CDB[2] = 0x00
[    4.589616] ata4.00: CDB[3] = 0x00
[    4.589657] ata4.00: CDB[4] = 0x60
[    4.589698] ata4.00: CDB[5] = 0x00
[    4.589740] ata4.00: CDB[6] = 0x00
[    4.589782] ata4.00: CDB[7] = 0x00
[    4.589823] ata4.00: CDB[8] = 0x00
[    4.589864] ata4.00: CDB[9] = 0x00
[    4.589905] ata4.00: CDB[10] = 0x00
[    4.589947] ata4.00: CDB[11] = 0x00
[    4.589988] ata4.00: CDB[12] = 0x00
[    4.590029] ata4.00: CDB[13] = 0x00
[    4.590070] ata4.00: CDB[14] = 0x00
[    4.590111] ata4.00: CDB[15] = 0x00
[    4.590152] ata4.00: direction 2 dmadir 0
[    4.591250] ata4.00: REQUEST SENSE err_mask=5 sense_key=6

Then it sends TEST UNIT READY again and gets sense_key 2, drive not ready:

[    4.591294] ata4.00: About to do TEST UNIT READY
[    4.591339] ata4.00: CDB[0] = 0x00
[    4.591382] ata4.00: CDB[1] = 0x00
[    4.591423] ata4.00: CDB[2] = 0x00
[    4.591466] ata4.00: CDB[3] = 0x00
[    4.591507] ata4.00: CDB[4] = 0x00
[    4.591549] ata4.00: CDB[5] = 0x00
[    4.591590] ata4.00: CDB[6] = 0x00
[    4.591631] ata4.00: CDB[7] = 0x00
[    4.591672] ata4.00: CDB[8] = 0x00
[    4.591713] ata4.00: CDB[9] = 0x00
[    4.591754] ata4.00: CDB[10] = 0x00
[    4.591796] ata4.00: CDB[11] = 0x00
[    4.591837] ata4.00: CDB[12] = 0x00
[    4.591879] ata4.00: CDB[13] = 0x00
[    4.591920] ata4.00: CDB[14] = 0x00
[    4.591962] ata4.00: CDB[15] = 0x00
[    4.592003] ata4.00: direction 3 dmadir 0
[    4.592679] ata4.00: TEST UNIT READY err_mask=1 sense_key=2

It's then picked up as a SCSI device:

[    4.597222] scsi 3:0:0:0: Direct-Access     IOMEGA   ZIP 100 
12.A PQ: 0 ANSI: 5


Thanks.
-- 
Phil.
philpem@philpem.me.uk
https://www.philpem.me.uk/

Re: Zip 100 ATAPI not working, "qc timeout" and "failed to clear UNIT ATTENTION"

[Niklas Cassel]

Hello Philip,

On Tue, Feb 18, 2025 at 03:05:49AM +0000, Philip Pemberton wrote:
> When the function atapi_eh_clear_ua() [libata-eh.c:3294] is entered, the
> driver sends a SCSI "TEST UNIT READY" (scsicmd 0) CDB inside an ATAPI packet
> command (cmd 0xa0):
> 
> [    4.408044] ata4: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> [    4.408107] ata4.00: direction 2 dmadir 0
> [    4.414687] ata4.00: ATAPI: IOMEGA  ZIP 100       ATAPI, 12.A, max PIO3,
> CDB intr
> [    4.414815] ata4.00: applying bridge limits
> [    4.414870] ata4.00: direction 3 dmadir 0
> [    4.415153] ata4.00: direction 2 dmadir 0
> [    4.421662] ata4.00: configured for PIO3
> [    4.421768] ata4.00: About to do TEST UNIT READY
> [    4.421770] ata4.00: CDB[0] = 0x00
> [    4.421824] ata4.00: CDB[1] = 0x00
> [    4.421876] ata4.00: CDB[2] = 0x00
> [    4.421929] ata4.00: CDB[3] = 0x00
> [    4.421981] ata4.00: CDB[4] = 0x00
> [    4.422033] ata4.00: CDB[5] = 0x00
> [    4.422085] ata4.00: CDB[6] = 0x00
> [    4.422138] ata4.00: CDB[7] = 0x00
> [    4.422190] ata4.00: CDB[8] = 0x00
> [    4.422242] ata4.00: CDB[9] = 0x00
> [    4.422294] ata4.00: CDB[10] = 0x00
> [    4.422347] ata4.00: CDB[11] = 0x00
> [    4.422399] ata4.00: CDB[12] = 0x00
> [    4.422452] ata4.00: CDB[13] = 0x00
> [    4.422504] ata4.00: CDB[14] = 0x00
> [    4.422556] ata4.00: CDB[15] = 0x00
> [    4.422609] ata4.00: direction 3 dmadir 0
> [    4.423185] ata4.00: TEST UNIT READY err_mask=1 sense_key=6
> 
> This fails with err_mask=1 (AC_ERR_DEV=1, "device reported error", defined
> in libata.h). Sense key 6 is UNIT ATTENTION, per
> <https://www.t10.org/lists/2sensekey.htm>.
> 
> The code then goes on to send a SCSI "REQUEST SENSE" CDB (scsicmd 0x03) in
> an attempt to clear the UNIT ATTENTION flag. It's this command which times
> out:
> 
> [    4.423239] ata4.00: CDB[0] = 0x03
> [    4.423295] ata4.00: CDB[1] = 0x00
> [    4.423347] ata4.00: CDB[2] = 0x00
> [    4.423399] ata4.00: CDB[3] = 0x00
> [    4.423452] ata4.00: CDB[4] = 0x60
> [    4.423504] ata4.00: CDB[5] = 0x00
> [    4.423556] ata4.00: CDB[6] = 0x00
> [    4.423609] ata4.00: CDB[7] = 0x00
> [    4.423661] ata4.00: CDB[8] = 0x00
> [    4.423713] ata4.00: CDB[9] = 0x00
> [    4.423765] ata4.00: CDB[10] = 0x00
> [    4.423817] ata4.00: CDB[11] = 0x00
> [    4.423870] ata4.00: CDB[12] = 0x00
> [    4.423922] ata4.00: CDB[13] = 0x00
> [    4.423974] ata4.00: CDB[14] = 0x00
> [    4.424026] ata4.00: CDB[15] = 0x00
> [    4.424079] ata4.00: direction 2 dmadir 0
> [    9.556040] ata4.00: qc timeout after 5000 msecs (cmd 0xa0 cdb[0] 0x3)
> [    9.556155] ata4.00: REQUEST SENSE err_mask=5 sense_key=6


If we look at code in atapi_eh_clear_ua(), it is a for loop that will run
for up to ATA_EH_UA_TRIES number of times.

For e.g. the case with your PIIX controller, it manages to clear Unit
Attention successfully on the second try.

The reason why it does not perform more than one try on your AHCI
controller is because atapi_eh_request_sense() returns AC_ERR_TIMEOUT,
which causes the code to return and not perform additional iterations/retries.

Looking at atapi_eh_request_sense(), I can see this code:
https://github.com/torvalds/linux/blob/v6.14-rc3/drivers/ata/libata-eh.c#L1545-L1553

	/* is it pointless to prefer PIO for "safety reasons"? */
	if (ap->flags & ATA_FLAG_PIO_DMA) {
		tf.protocol = ATAPI_PROT_DMA;
		tf.feature |= ATAPI_PKT_DMA;
	} else {
		tf.protocol = ATAPI_PROT_PIO;
		tf.lbam = SCSI_SENSE_BUFFERSIZE;
		tf.lbah = 0;
	}


Looking at ahci.c, we can see that all boards have .flags set to:
AHCI_FLAG_COMMON
which is defined as:

        AHCI_FLAG_COMMON                = ATA_FLAG_SATA | ATA_FLAG_PIO_DMA |
                                          ATA_FLAG_ACPI_SATA | ATA_FLAG_AN,


ATA_FLAG_PIO_DMA is defined as:
ATA_FLAG_PIO_DMA        = (1 << 7), /* PIO cmds via DMA */

Which, IIUC, seems to mean that atapi_eh_request_sense() will use DMA even
for a port configured to use PIO.


This flag does not appear to be set for any board in the PIIX driver.

Perhaps your could try with something like:

diff --git a/drivers/ata/libata-eh.c b/drivers/ata/libata-eh.c
index 3b303d4ae37a..bc2a317c97da 100644
--- a/drivers/ata/libata-eh.c
+++ b/drivers/ata/libata-eh.c
@@ -1543,7 +1543,7 @@ unsigned int atapi_eh_request_sense(struct ata_device *dev,
        tf.command = ATA_CMD_PACKET;
 
        /* is it pointless to prefer PIO for "safety reasons"? */
-       if (ap->flags & ATA_FLAG_PIO_DMA) {
+       if (0) {
                tf.protocol = ATAPI_PROT_DMA;
                tf.feature |= ATAPI_PKT_DMA;
        } else {

To see if NOT using DMA for PIO cmds makes any difference.


> 
> Back onto the PIIX the drive initialises, then there seem to be a couple of
> non-ATAPI commands:
> 
> [    4.564157] ata4.00: ATAPI: IOMEGA  ZIP 100       ATAPI, 12.A, max PIO3,
> CDB intr
> [    4.564223] ata4.00: applying bridge limits
> [    4.564270] ata4.00: direction 3 dmadir 0
> [    4.566480] ata4.00: direction 2 dmadir 0


Perhaps you would want to figure out what these commands are,
to know if the lack of these commands on AHCI could be related
to things not working on AHCI.



Kind regards,
Niklas

Re: Zip 100 ATAPI not working, "qc timeout" and "failed to clear UNIT ATTENTION"

[Niklas Cassel]

On Wed, Feb 19, 2025 at 04:48:56PM +0100, Niklas Cassel wrote:
> 
> Perhaps your could try with something like:
> 
> diff --git a/drivers/ata/libata-eh.c b/drivers/ata/libata-eh.c
> index 3b303d4ae37a..bc2a317c97da 100644
> --- a/drivers/ata/libata-eh.c
> +++ b/drivers/ata/libata-eh.c
> @@ -1543,7 +1543,7 @@ unsigned int atapi_eh_request_sense(struct ata_device *dev,
>         tf.command = ATA_CMD_PACKET;
>  
>         /* is it pointless to prefer PIO for "safety reasons"? */
> -       if (ap->flags & ATA_FLAG_PIO_DMA) {
> +       if (0) {
>                 tf.protocol = ATAPI_PROT_DMA;
>                 tf.feature |= ATAPI_PKT_DMA;
>         } else {
> 
> To see if NOT using DMA for PIO cmds makes any difference.

Or the big hammer:

diff --git a/drivers/ata/ahci.h b/drivers/ata/ahci.h
index 8e895ae45c86..920462101775 100644
--- a/drivers/ata/ahci.h
+++ b/drivers/ata/ahci.h
@@ -249,7 +249,7 @@ enum {
 
        /* ap->flags bits */
 
-       AHCI_FLAG_COMMON                = ATA_FLAG_SATA | ATA_FLAG_PIO_DMA |
+       AHCI_FLAG_COMMON                = ATA_FLAG_SATA |
                                          ATA_FLAG_ACPI_SATA | ATA_FLAG_AN,
 
        ICH_MAP                         = 0x90, /* ICH MAP register */




Just make sure to not use this on any system other than the machine that
you are debugging on.


Kind regards,
Niklas

Re: Zip 100 ATAPI not working, "qc timeout" and "failed to clear UNIT ATTENTION"

[Philip Pemberton]

Hi Niklas,

On 19/02/2025 16:02, Niklas Cassel wrote:
> On Wed, Feb 19, 2025 at 04:48:56PM +0100, Niklas Cassel wrote:
>>
>> Perhaps your could try with something like:
>>
(snip)
>> +       if (0) {
>>                  tf.protocol = ATAPI_PROT_DMA;
>>                  tf.feature |= ATAPI_PKT_DMA;

I tried the "little hammer". It works!

[    4.274698] ata4.00: ATAPI: IOMEGA  ZIP 100       ATAPI, 12.A, max 
PIO3, CDB intr
[    4.274825] ata4.00: applying bridge limits
[    4.274880] ata4.00: direction 3 dmadir 0
[    4.275166] ata4.00: direction 2 dmadir 0
[    4.281768] ata4.00: configured for PIO3
[    4.281874] ata4.00: About to do TEST UNIT READY
(snip cdb)
[    4.282715] ata4.00: direction 3 dmadir 0
[    4.283285] ata4.00: TEST UNIT READY err_mask=1 sense_key=6
(snip cdb)
[    4.284181] ata4.00: direction 2 dmadir 0
[    4.285265] ata4.00: REQUEST SENSE err_mask=0 sense_key=6
[    4.285319] ata4.00: About to do TEST UNIT READY
(snip cdb)
[    4.286214] ata4.00: direction 3 dmadir 0
[    4.286841] ata4.00: TEST UNIT READY err_mask=1 sense_key=2
[    4.291043] scsi 3:0:0:0: Direct-Access     IOMEGA   ZIP 100 
12.A PQ: 0 ANSI: 5
(snip cdb)
[    4.329969] ata4.00: direction 2 dmadir 0

And smartctl can talk to it:

root@localhost:~# smartctl -i /dev/sdb
smartctl 7.3 2022-02-28 r5338 [i686-linux-6.10.11] (local build)
Copyright (C) 2002-22, Bruce Allen, Christian Franke, www.smartmontools.org

=== START OF INFORMATION SECTION ===
Vendor:               IOMEGA
Product:              ZIP 100
Revision:             12.A
Compliance:           SPC-3
Device type:          disk
Local Time is:        Wed Feb 19 19:47:42 2025 UTC
SMART support is:     Unavailable - device lacks SMART capability.

I've been able to get a good read of a disk with ddrescue:

GNU ddrescue 1.27
Press Ctrl-C to interrupt
      ipos:  100597 kB, non-trimmed:        0 B,  current rate:    720 kB/s
      opos:  100597 kB, non-scraped:        0 B,  average rate:   1070 kB/s
non-tried:        0 B,  bad-sector:        0 B,    error rate:       0 B/s
   rescued:  100663 kB,   bad areas:        0,        run time:      1m 33s
pct rescued:  100.00%, read errors:        0,  remaining time:         n/a
                               time since last successful read:         n/a
Copying non-tried blocks... Pass 1 (forwards)
Finished

I'm pretty chuffed with the data rate, 1MB/sec is far more than the 
externals manage.

I guess the question now is, how to fix this properly?

Thanks,
-- 
Phil.
philpem@philpem.me.uk
https://www.philpem.me.uk/

Re: Zip 100 ATAPI not working, "qc timeout" and "failed to clear UNIT ATTENTION"

[Niklas Cassel]

Hello Philip,

On Wed, Feb 19, 2025 at 08:04:50PM +0000, Philip Pemberton wrote:
> 
> I've been able to get a good read of a disk with ddrescue:
> 
> GNU ddrescue 1.27
> Press Ctrl-C to interrupt
>      ipos:  100597 kB, non-trimmed:        0 B,  current rate:    720 kB/s
>      opos:  100597 kB, non-scraped:        0 B,  average rate:   1070 kB/s
> non-tried:        0 B,  bad-sector:        0 B,    error rate:       0 B/s
>   rescued:  100663 kB,   bad areas:        0,        run time:      1m 33s
> pct rescued:  100.00%, read errors:        0,  remaining time:         n/a
>                               time since last successful read:         n/a
> Copying non-tried blocks... Pass 1 (forwards)
> Finished
> 
> I'm pretty chuffed with the data rate, 1MB/sec is far more than the
> externals manage.
> 
> I guess the question now is, how to fix this properly?

Please try this patch:
https://lore.kernel.org/linux-ide/20250221015422.20687-2-cassel@kernel.org/T/#u

and see if it fixes your problem.

Please also make sure to check that you can still write and read back what
you wrote to the device (with the read data matching the written data).


Kind regards,
Niklas

Re: Zip 100 ATAPI not working, "qc timeout" and "failed to clear UNIT ATTENTION"

[Philip Pemberton]

On 21/02/2025 01:57, Niklas Cassel wrote:
> Please try this patch:
> https://lore.kernel.org/linux-ide/20250221015422.20687-2-cassel@kernel.org/T/#u
> 
> and see if it fixes your problem.
> 
> Please also make sure to check that you can still write and read back what
> you wrote to the device (with the read data matching the written data).

I can confirm the patch works!

I was slightly amused to see this bug appears to be 19 years old: 
https://github.com/torvalds/linux/blame/master/drivers/ata/libata-eh.c#L1546
It's understandable, in May 2006 the Zip drive was probably still around 
in places, but quite obsolete. The ATAPI internal versions were 
uncommon, most would have been external parallel, USB or SCSI.


I'm not sure if the Read Capacity command failing is a problem, it seems 
to succeed on the second attempt. My guess is the drive can't handle 
SCSI commands while it's doing a load or eject (probably updating the 
management data aka z-tracks).

[   79.936649] sd 3:0:0:0: [sdb] Read Capacity(16) failed: Result: 
hostbyte=DID_ERROR driverbyte=DRIVER_OK
[   79.936692] sd 3:0:0:0: [sdb] Sense not available.
[  162.381077] sdb: detected capacity change from 196608 to 0
[  164.969080] sd 3:0:0:0: [sdb] Spinning up disk...
[  166.004048] ..ready
[  167.262210] sd 3:0:0:0: [sdb] Read Capacity(16) failed: Result: 
hostbyte=DID_ERROR driverbyte=DRIVER_OK
[  167.262244] sd 3:0:0:0: [sdb] Sense not available.
[  167.305302] sd 3:0:0:0: [sdb] 196608 512-byte logical blocks: (101 
MB/96.0 MiB)
[  167.349309] sdb: detected capacity change from 0 to 196608
[  167.480724]  sdb: [mac] sdb1 sdb2 sdb3 sdb4 sdb5
[  192.527434] systemd-journald[260]: Failed to set ACL on 
/var/log/journal/44cff3865dce455fac8b3c3db744ba67/user-1000.journal, 
ignoring: Operation not supported
[  204.709301] sd 3:0:0:0: [sdb] Read Capacity(16) failed: Result: 
hostbyte=DID_ERROR driverbyte=DRIVER_OK
[  204.709334] sd 3:0:0:0: [sdb] Sense not available.


It seems to be able to read and write correctly -- I can read the 
contents of the disk, write random data, and read the random data back 
correctly.

Dump the original contents of the disk:
# ddrescue /dev/sdb zip_orig
GNU ddrescue 1.27
Press Ctrl-C to interrupt
      ipos:  100597 kB, non-trimmed:        0 B,  current rate:    589 kB/s
      opos:  100597 kB, non-scraped:        0 B,  average rate:    792 kB/s
non-tried:        0 B,  bad-sector:        0 B,    error rate:       0 B/s
   rescued:  100663 kB,   bad areas:        0,        run time:      2m  6s
pct rescued:  100.00%, read errors:        0,  remaining time:         n/a
                               time since last successful read:         n/a
Copying non-tried blocks... Pass 1 (forwards)
Finished

Create 100MB of randomness, write it to the disk:
# dd if=/dev/urandom of=ziptest bs=512 count=196608
196608+0 records in
196608+0 records out
100663296 bytes (101 MB, 96 MiB) copied, 2.74086 s, 36.7 MB/s
# dd if=ziptest of=/dev/sdb bs=512
196608+0 records in
196608+0 records out
100663296 bytes (101 MB, 96 MiB) copied, 226.022 s, 445 kB/s

Read it back:
# ddrescue /dev/sdb ziptest_read
GNU ddrescue 1.27
Press Ctrl-C to interrupt
      ipos:  100597 kB, non-trimmed:        0 B,  current rate:    196 kB/s
      opos:  100597 kB, non-scraped:        0 B,  average rate:   1059 kB/s
non-tried:        0 B,  bad-sector:        0 B,    error rate:       0 B/s
   rescued:  100663 kB,   bad areas:        0,        run time:      1m 34s
pct rescued:  100.00%, read errors:        0,  remaining time:         n/a
                               time since last successful read:         n/a
Copying non-tried blocks... Pass 1 (forwards)
Finished

Compare:
# md5sum ziptest*
f132f7ad38beef40d45ce9f96a6e9f92  ziptest
f132f7ad38beef40d45ce9f96a6e9f92  ziptest_read

Thanks.
-- 
Phil.
philpem@philpem.me.uk
https://www.philpem.me.uk/

Re: Zip 100 ATAPI not working, "qc timeout" and "failed to clear UNIT ATTENTION"

[Niklas Cassel]

On Fri, Feb 21, 2025 at 05:08:21PM +0000, Philip Pemberton wrote:
> On 21/02/2025 01:57, Niklas Cassel wrote:
> > Please try this patch:
> > https://lore.kernel.org/linux-ide/20250221015422.20687-2-cassel@kernel.org/T/#u
> > 
> > and see if it fixes your problem.
> > 
> > Please also make sure to check that you can still write and read back what
> > you wrote to the device (with the read data matching the written data).
> 
> I can confirm the patch works!

Thanks for testing, and thanks for actually taking the time to debug this!


> Dump the original contents of the disk:
> # ddrescue /dev/sdb zip_orig
> GNU ddrescue 1.27
> Press Ctrl-C to interrupt
>      ipos:  100597 kB, non-trimmed:        0 B,  current rate:    589 kB/s
>      opos:  100597 kB, non-scraped:        0 B,  average rate:    792 kB/s
> non-tried:        0 B,  bad-sector:        0 B,    error rate:       0 B/s
>   rescued:  100663 kB,   bad areas:        0,        run time:      2m  6s
> pct rescued:  100.00%, read errors:        0,  remaining time:         n/a
>                               time since last successful read:         n/a
> Copying non-tried blocks... Pass 1 (forwards)
> Finished
> 
> Create 100MB of randomness, write it to the disk:
> # dd if=/dev/urandom of=ziptest bs=512 count=196608
> 196608+0 records in
> 196608+0 records out
> 100663296 bytes (101 MB, 96 MiB) copied, 2.74086 s, 36.7 MB/s
> # dd if=ziptest of=/dev/sdb bs=512
> 196608+0 records in
> 196608+0 records out
> 100663296 bytes (101 MB, 96 MiB) copied, 226.022 s, 445 kB/s
> 
> Read it back:
> # ddrescue /dev/sdb ziptest_read
> GNU ddrescue 1.27
> Press Ctrl-C to interrupt
>      ipos:  100597 kB, non-trimmed:        0 B,  current rate:    196 kB/s
>      opos:  100597 kB, non-scraped:        0 B,  average rate:   1059 kB/s
> non-tried:        0 B,  bad-sector:        0 B,    error rate:       0 B/s
>   rescued:  100663 kB,   bad areas:        0,        run time:      1m 34s
> pct rescued:  100.00%, read errors:        0,  remaining time:         n/a
>                               time since last successful read:         n/a
> Copying non-tried blocks... Pass 1 (forwards)
> Finished
> 
> Compare:
> # md5sum ziptest*
> f132f7ad38beef40d45ce9f96a6e9f92  ziptest
> f132f7ad38beef40d45ce9f96a6e9f92  ziptest_read

Certainly good enough for me, I will add your Tested-by tag!

Considering that this has been broken for 19 years, a few more weeks
will be quick in comparison. I will queue it for 6.15 just to get some
extra testing.


Kind regards,
Niklas