SCSI problem, card or taper?

[Palle Girgensohn]

Hi!

I have a problem with a SCSI taper, a DLT machine. I use amanda for 
dumping, and all she says is

  taper: tape daily104 kb 120864 fm 1 writing file: short write

Nothing ends up on the tape. Ran a cleaning tape twice in a short time, it 
didn't help. It has gotten worse over the last 10 days, and now it is not 
working at all... Nothing about the machine has changed recently.

It is a Quantum DLT4000 connected to a FreeBSD 4.10 machine with an Intel 
440GX (?) mobo. Old machine, dual P3 @ 450 MHz.

The SCSI card for the taper is an Adaptec 29XX

The taper is sa1 on card ahc2.

I cannot deduce if it is the card, the taper or something else that is 
causing this trouble. Help appreciated, esp in determinating which part I 
need to replace.

Regards,
Palle


dmesg.boot:

sahc0: <Adaptec aic7896/97 Ultra2 SCSI adapter> port 0x2000-0x20ff mem 
0xf4200000-0xf4200fff irq 2 at device 12.0 on pci0
aic7896/97: Ultra2 Wide Channel A, SCSI Id=7, 32/253 SCBs
ahc1: <Adaptec aic7896/97 Ultra2 SCSI adapter> port 0x2400-0x24ff mem 
0xf4201000-0xf4201fff irq 2 at device 12.1 on pci0
aic7896/97: Ultra2 Wide Channel B, SCSI Id=7, 32/253 SCBs
ahc2: <Adaptec 2902/04/10/15/20C/30C SCSI adapter> port 0x2800-0x28ff mem 
0xf4202000-0xf4202fff irq 5 at device 13.0 on pci0
ahc2: Host Adapter Bios disabled.  Using default SCSI device parameters
aic7850: Single Channel A, SCSI Id=7, 3/253 SCBs
...
a0 at ahc1 bus 0 target 0 lun 0
sa0: <ARCHIVE Python 04106-XXX 7270> Removable Sequential Access SCSI-2 
device
sa0: 7.812MB/s transfers (7.812MHz, offset 15)
sa1 at ahc2 bus 0 target 2 lun 0
sa1: <Quantum DLT4000 CC1E> Removable Sequential Access SCSI-2 device
sa1: 10.000MB/s transfers (10.000MHz, offset 15)
da1 at ahc0 bus 0 target 1 lun 0
da1: <QUANTUM ATLAS10K3_36_WLS 020W> Fixed Direct Access SCSI-3 device
da1: 80.000MB/s transfers (40.000MHz, offset 127, 16bit), Tagged Queueing 
Enabled
da1: 35074MB (71833096 512 byte sectors: 255H 63S/T 4471C)
... more daX's


Here's what I can see in /var/log/messages when the tape write fails:

Sep 22 18:10:09 banan /kernel: (sa1:ahc2:0:2:0): WRITE FILEMARKS. CDB: 10 0 
0 0 2 0
Sep 22 18:10:09 banan /kernel: (sa1:ahc2:0:2:0): NOT READY asc:4,3
Sep 22 18:10:09 banan /kernel: (sa1:ahc2:0:2:0): Logical unit not ready, 
manual intervention required
Sep 22 18:10:09 banan /kernel: (sa1:ahc2:0:2:0): failed to write 
terminating filemark(s)
Sep 22 18:11:09 banan /kernel: ahc2: Recovery Initiated
Sep 22 18:11:09 banan /kernel: >>>>>>>>>>>>>>>>>> Dump Card State Begins 
<<<<<<<<<<<<<<<<<
Sep 22 18:11:09 banan /kernel: ahc2: Dumping Card State while idle, at 
SEQADDR 0x8
Sep 22 18:11:09 banan /kernel: Card was paused
Sep 22 18:11:09 banan /kernel: ACCUM = 0xd4, SINDEX = 0x27, DINDEX = 0x23, 
ARG_2 = 0x0
Sep 22 18:11:09 banan /kernel: HCNT = 0x0 SCBPTR = 0x0
Sep 22 18:11:09 banan /kernel: SCSISIGI[0x0] ERROR[0x0] SCSIBUSL[0x0] 
LASTPHASE[0x1]:(P_BUSFREE)
Sep 22 18:11:09 banan /kernel: SCSISEQ[0x12]:(ENAUTOATNP|ENRSELI) 
SBLKCTL[0x0] SCSIRATE[0x0]
Sep 22 18:11:09 banan /kernel: SEQCTL[0x10]:(FASTMODE) 
SEQ_FLAGS[0xc0]:(NO_CDB_SENT|NOT_IDENTIFIED)
Sep 22 18:11:09 banan /kernel: SSTAT0[0x5]:(DMADONE|SDONE) 
SSTAT1[0xa]:(PHASECHG|BUSFREE)
Sep 22 18:11:09 banan /kernel: SSTAT2[0x0] SSTAT3[0x0] SIMODE0[0x0] 
SIMODE1[0xa4]:(ENSCSIPERR|ENSCSIRST|ENSELTIMO)
Sep 22 18:11:09 banan /kernel: SXFRCTL0[0x80]:(DFON) DFCNTRL[0x0] 
DFSTATUS[0x2d]:(FIFOEMP|DFTHRESH|HDONE|FIFOQWDEMP)
Sep 22 18:11:09 banan /kernel: STACK: 0xe3 0x161 0x1a2 0x3
Sep 22 18:11:09 banan /kernel: SCB count = 10
Sep 22 18:11:09 banan /kernel: Kernel NEXTQSCB = 7
Sep 22 18:11:09 banan /kernel: Card NEXTQSCB = 7
Sep 22 18:11:09 banan /kernel: QINFIFO entries:
Sep 22 18:11:09 banan /kernel: Waiting Queue entries:
Sep 22 18:11:09 banan /kernel: Disconnected Queue entries: 0:2
Sep 22 18:11:09 banan /kernel: QOUTFIFO entries:
Sep 22 18:11:09 banan /kernel: Sequencer Free SCB List: 1 2
Sep 22 18:11:09 banan /kernel: Sequencer SCB Info:
Sep 22 18:11:09 banan /kernel: 0 SCB_CONTROL[0x44]:(DISCONNECTED|DISCENB) 
SCB_SCSIID[0x27]
Sep 22 18:11:09 banan /kernel: SCB_LUN[0x0] SCB_TAG[0x2]
Sep 22 18:11:09 banan /kernel: 1 SCB_CONTROL[0x0] 
SCB_SCSIID[0xff]:(TWIN_CHNLB|OID|TWIN_TID)
Sep 22 18:11:09 banan /kernel: SCB_LUN[0xff]:(SCB_XFERLEN_ODD|LID) 
SCB_TAG[0xff]
Sep 22 18:11:09 banan /kernel: 2 SCB_CONTROL[0x0] 
SCB_SCSIID[0xff]:(TWIN_CHNLB|OID|TWIN_TID)
Sep 22 18:11:09 banan /kernel: SCB_LUN[0xff]:(SCB_XFERLEN_ODD|LID) 
SCB_TAG[0xff]
Sep 22 18:11:09 banan /kernel: Pending list:
Sep 22 18:11:09 banan /kernel: 2 SCB_CONTROL[0x40]:(DISCENB) 
SCB_SCSIID[0x27] SCB_LUN[0x0]
Sep 22 18:11:09 banan /kernel: Kernel Free SCB list: 3 4 5 6 8 9 1 0
Sep 22 18:11:09 banan /kernel: Untagged Q(2): 2
Sep 22 18:11:09 banan /kernel:
Sep 22 18:11:09 banan /kernel: <<<<<<<<<<<<<<<<< Dump Card State Ends 
>>>>>>>>>>>>>>>>>>
Sep 22 18:11:09 banan /kernel: (sa1:ahc2:0:2:0): SCB 0x2 - timed out
Sep 22 18:11:09 banan /kernel: (sa1:ahc2:0:2:0): Queuing a BDR SCB
Sep 22 18:11:09 banan /kernel: ahc2: Timedout SCBs already complete. 
Interrupts may not be functioning.
Sep 22 18:11:11 banan /kernel: ahc2: Recovery Initiated
Sep 22 18:11:11 banan /kernel: >>>>>>>>>>>>>>>>>> Dump Card State Begins 
<<<<<<<<<<<<<<<<<
Sep 22 18:11:11 banan /kernel: ahc2: Dumping Card State while idle, at 
SEQADDR 0x18
Sep 22 18:11:11 banan /kernel: Card was paused
Sep 22 18:11:11 banan /kernel: ACCUM = 0x2, SINDEX = 0x20, DINDEX = 0xc0, 
ARG_2 = 0x0
Sep 22 18:11:11 banan /kernel: HCNT = 0x0 SCBPTR = 0x0
Sep 22 18:11:11 banan /kernel: SCSISIGI[0x4]:(BSYI) ERROR[0x0] 
SCSIBUSL[0x0] LASTPHASE[0x1]:(P_BUSFREE)
Sep 22 18:11:11 banan /kernel: 
SCSISEQ[0x1a]:(ENAUTOATNP|ENAUTOATNO|ENRSELI) SBLKCTL[0x0]
Sep 22 18:11:11 banan /kernel: SCSIRATE[0x0] SEQCTL[0x10]:(FASTMODE) 
SEQ_FLAGS[0xc0]:(NO_CDB_SENT|NOT_IDENTIFIED)
Sep 22 18:11:11 banan /kernel: SSTAT0[0x5]:(DMADONE|SDONE) 
SSTAT1[0xa]:(PHASECHG|BUSFREE)
Sep 22 18:11:11 banan /kernel: SSTAT2[0x0] SSTAT3[0x0] SIMODE0[0x0] 
SIMODE1[0xa4]:(ENSCSIPERR|ENSCSIRST|ENSELTIMO)
Sep 22 18:11:11 banan /kernel: SXFRCTL0[0x80]:(DFON) 
DFCNTRL[0x4]:(DIRECTION) 
DFSTATUS[0x6d]:(FIFOEMP|DFTHRESH|HDONE|FIFOQWDEMP|DFCACHETH)
Sep 22 18:11:11 banan /kernel: STACK: 0xe3 0x161 0x1a2 0x17
Sep 22 18:11:11 banan /kernel: SCB count = 10
Sep 22 18:11:11 banan /kernel: Kernel NEXTQSCB = 7
Sep 22 18:11:11 banan /kernel: Card NEXTQSCB = 7
Sep 22 18:11:11 banan /kernel: QINFIFO entries:
Sep 22 18:11:11 banan /kernel: Waiting Queue entries: 0:2
Sep 22 18:11:11 banan /kernel: Disconnected Queue entries:
Sep 22 18:11:11 banan /kernel: QOUTFIFO entries:
Sep 22 18:11:11 banan /kernel: Sequencer Free SCB List: 1 2
Sep 22 18:11:11 banan /kernel: Sequencer SCB Info:
Sep 22 18:11:11 banan /kernel: 0 
SCB_CONTROL[0x54]:(DISCONNECTED|MK_MESSAGE|DISCENB) SCB_SCSIID[0x27]
Sep 22 18:11:11 banan /kernel: SCB_LUN[0x0] SCB_TAG[0x2]
Sep 22 18:11:11 banan /kernel: 1 SCB_CONTROL[0x0] 
SCB_SCSIID[0xff]:(TWIN_CHNLB|OID|TWIN_TID)
Sep 22 18:11:11 banan /kernel: SCB_LUN[0xff]:(SCB_XFERLEN_ODD|LID) 
SCB_TAG[0xff]
Sep 22 18:11:11 banan /kernel: 2 SCB_CONTROL[0x0] 
SCB_SCSIID[0xff]:(TWIN_CHNLB|OID|TWIN_TID)
Sep 22 18:11:11 banan /kernel: SCB_LUN[0xff]:(SCB_XFERLEN_ODD|LID) 
SCB_TAG[0xff]
Sep 22 18:11:11 banan /kernel: Pending list:
Sep 22 18:11:11 banan /kernel: 2 
SCB_CONTROL[0x54]:(DISCONNECTED|MK_MESSAGE|DISCENB) SCB_SCSIID[0x27]
Sep 22 18:11:11 banan /kernel: SCB_LUN[0x0]
Sep 22 18:11:11 banan /kernel: Kernel Free SCB list: 3 4 5 6 8 9 1 0
Sep 22 18:11:11 banan /kernel: Untagged Q(2): 2
Sep 22 18:11:11 banan /kernel:
Sep 22 18:11:11 banan /kernel: <<<<<<<<<<<<<<<<< Dump Card State Ends 
>>>>>>>>>>>>>>>>>>
Sep 22 18:11:11 banan /kernel: (sa1:ahc2:0:2:0): SCB 0x2 - timed out
Sep 22 18:11:11 banan /kernel: (sa1:ahc2:0:2:0): no longer in timeout, 
status = 34b
Sep 22 18:11:12 banan /kernel: ahc2: Issued Channel A Bus Reset. 1 SCBs 
aborted
Sep 22 18:11:12 banan /kernel: ahc2: Timedout SCBs already complete. 
Interrupts may not be functioning.
Sep 22 18:12:11 banan /kernel: ahc2: Recovery Initiated
Sep 22 18:12:11 banan /kernel: >>>>>>>>>>>>>>>>>> Dump Card State Begins 
<<<<<<<<<<<<<<<<<
Sep 22 18:12:11 banan /kernel: ahc2: Dumping Card State while idle, at 
SEQADDR 0x18
Sep 22 18:12:11 banan /kernel: Card was paused
Sep 22 18:12:11 banan /kernel: ACCUM = 0x7, SINDEX = 0x20, DINDEX = 0xc0, 
ARG_2 = 0x1
Sep 22 18:12:11 banan /kernel: HCNT = 0x0 SCBPTR = 0x0
Sep 22 18:12:11 banan /kernel: SCSISIGI[0x4]:(BSYI) ERROR[0x0] 
SCSIBUSL[0x0] LASTPHASE[0x1]:(P_BUSFREE)
Sep 22 18:12:11 banan /kernel: 
SCSISEQ[0x1a]:(ENAUTOATNP|ENAUTOATNO|ENRSELI) SBLKCTL[0x0]
Sep 22 18:12:11 banan /kernel: SCSIRATE[0x0] SEQCTL[0x10]:(FASTMODE) 
SEQ_FLAGS[0xc0]:(NO_CDB_SENT|NOT_IDENTIFIED)
Sep 22 18:12:11 banan /kernel: SSTAT0[0x5]:(DMADONE|SDONE) SSTAT1[0x0] 
SSTAT2[0x0]
Sep 22 18:12:11 banan /kernel: SSTAT3[0x0] SIMODE0[0x0] 
SIMODE1[0xa4]:(ENSCSIPERR|ENSCSIRST|ENSELTIMO)
Sep 22 18:12:11 banan /kernel: SXFRCTL0[0x80]:(DFON) 
DFCNTRL[0x4]:(DIRECTION) 
DFSTATUS[0x6d]:(FIFOEMP|DFTHRESH|HDONE|FIFOQWDEMP|DFCACHETH)
Sep 22 18:12:11 banan /kernel: STACK: 0xe3 0x161 0x1a2 0x17
Sep 22 18:12:11 banan /kernel: SCB count = 10
Sep 22 18:12:11 banan /kernel: Kernel NEXTQSCB = 2
Sep 22 18:12:11 banan /kernel: Card NEXTQSCB = 2
Sep 22 18:12:11 banan /kernel: QINFIFO entries:
Sep 22 18:12:11 banan /kernel: Waiting Queue entries: 0:7
Sep 22 18:12:11 banan /kernel: Disconnected Queue entries:
Sep 22 18:12:11 banan /kernel: QOUTFIFO entries:
Sep 22 18:12:11 banan /kernel: Sequencer Free SCB List: 1 2
Sep 22 18:12:11 banan /kernel: Sequencer SCB Info:
Sep 22 18:12:11 banan /kernel: 0 SCB_CONTROL[0x50]:(MK_MESSAGE|DISCENB) 
SCB_SCSIID[0x27]
Sep 22 18:12:11 banan /kernel: SCB_LUN[0x0] SCB_TAG[0x7]
Sep 22 18:12:11 banan /kernel: 1 SCB_CONTROL[0x0] 
SCB_SCSIID[0xff]:(TWIN_CHNLB|OID|TWIN_TID)
Sep 22 18:12:11 banan /kernel: SCB_LUN[0xff]:(SCB_XFERLEN_ODD|LID) 
SCB_TAG[0xff]
Sep 22 18:12:11 banan /kernel: 2 SCB_CONTROL[0x0] 
SCB_SCSIID[0xff]:(TWIN_CHNLB|OID|TWIN_TID)
Sep 22 18:12:11 banan /kernel: SCB_LUN[0xff]:(SCB_XFERLEN_ODD|LID) 
SCB_TAG[0xff]
Sep 22 18:12:11 banan /kernel: Pending list:
Sep 22 18:12:11 banan /kernel: 7 SCB_CONTROL[0x50]:(MK_MESSAGE|DISCENB) 
SCB_SCSIID[0x27]
Sep 22 18:12:11 banan /kernel: SCB_LUN[0x0]
Sep 22 18:12:11 banan /kernel: Kernel Free SCB list: 3 4 5 6 8 9 1 0
Sep 22 18:12:11 banan /kernel: Untagged Q(2): 7
Sep 22 18:12:11 banan /kernel:
Sep 22 18:12:11 banan /kernel: <<<<<<<<<<<<<<<<< Dump Card State Ends 
>>>>>>>>>>>>>>>>>>
Sep 22 18:12:11 banan /kernel: (sa1:ahc2:0:2:0): SCB 0x7 - timed out
Sep 22 18:12:12 banan /kernel: (sa1:ahc2:0:2:0): SCB 7: Immediate reset. 
Flags = 0x660
Sep 22 18:12:12 banan /kernel: (sa1:ahc2:0:2:0): no longer in timeout, 
status = 35b
Sep 22 18:12:12 banan /kernel: ahc2: Issued Channel A Bus Reset. 1 SCBs 
aborted
Sep 22 18:12:12 banan /kernel: ahc2: Timedout SCBs already complete. 
Interrupts may not be functioning.
Sep 22 18:12:12 banan /kernel: (sa1:ahc2:0:2:0): tape is now frozen- use an 
OFFLINE, REWIND or MTEOM command to clear this state.


$ grep irq /var/run/dmesg.boot
IOAPIC #0 intpin 2 -> irq 0
IOAPIC #0 intpin 19 -> irq 2
IOAPIC #0 intpin 17 -> irq 5
IOAPIC #0 intpin 21 -> irq 9
fxp0: <Intel 82558 Pro/100 Ethernet> port 0x2c40-0x2c5f mem 
0xf4000000-0xf40fffff,0xf4205000-0xf4205fff irq 2 at device 9.0 on pci0
ahc0: <Adaptec aic7896/97 Ultra2 SCSI adapter> port 0x2000-0x20ff mem 
0xf4200000-0xf4200fff irq 2 at device 12.0 on pci0
ahc1: <Adaptec aic7896/97 Ultra2 SCSI adapter> port 0x2400-0x24ff mem 
0xf4201000-0xf4201fff irq 2 at device 12.1 on pci0
ahc2: <Adaptec 2902/04/10/15/20C/30C SCSI adapter> port 0x2800-0x28ff mem 
0xf4202000-0xf4202fff irq 5 at device 13.0 on pci0
fxp1: <Intel 82559 Pro/100 Ethernet> port 0x2c00-0x2c3f mem 
0xf4100000-0xf41fffff,0xf4203000-0xf4203fff irq 9 at device 14.0 on pci0
ata0: at 0x1f0 irq 14 on atapci0
ata1: at 0x170 irq 15 on atapci0
pci0: <Intel 82371AB/EB (PIIX4) USB controller> at 18.2 irq 9
fdc0: <NEC 72065B or clone> at port 0x3f0-0x3f5,0x3f7 irq 6 drq 2 on isa0
atkbd0: <AT Keyboard> irq 1 on atkbdc0
sio0 at port 0x3f8-0x3ff irq 4 flags 0x10 on isa0
sio1 at port 0x2f8-0x2ff irq 3 on isa0
ppc0: <Parallel port> at port 0x378-0x37f irq 7 on isa0