Amanda-Users

Re: Tape mark error on LTO drive/tapes - SCSI problem ?

2003-03-04 20:25:38
Subject: Re: Tape mark error on LTO drive/tapes - SCSI problem ?
From: Murray Taylor <murraytaylor AT bytecraftsystems DOT com>
To: Joshua Baker-LePain <jlb17 AT duke DOT edu>
Date: Wed, 5 Mar 2003 10:45:03 +1100
NOTE 
cc'd to freebsd-hackers also
please check /var/log/messages extract at end

On Wed, 5 Mar 2003 10:15, Joshua Baker-LePain wrote:
> On Wed, 5 Mar 2003 at 9:19am, Murray Taylor wrote
>
> > *** A TAPE ERROR OCCURRED: [[writing filemark: Input/output error]].
> >
> > It seems to be related to a long pause in the cycles as the
> > last halfcut partition is dumped prior to taping
>
> What do you mean by "long pause in the cycles"?
I think that the small partitions dump and tape, then there is a longer time 
gap as the larger partition dumps before it runs the taper

>
> >   taper: tape Daily001 kb 6512800 fm 9 writing filemark: Input/output
> > error
>
> You're only getting about 6.5MB on a tape, before the OS throws an I/O
> error.  Do you have any messages in your system logs?  What OS are we
> talking here?  Have you tested the tape drive w/o amanda?

Operating system
# uname -a
FreeBSD svlto.dand02.au.bytecraft.au.com 4.7-STABLE FreeBSD 4.7-STABLE #0: Mon 
Oct 28 10:03:20 GMT 2002     root AT tapelto.dand02.au.bytecraft DOT 
int:/usr/obj/usr/src/sys/GENERIC  i386

I have run the tape drive with a series of tar dumps to try to bust it and it 
seems to happily chug along

This error does not happen every time I run Amanda .. we just did a full level 
0 on all machine last friday OK using amadmin daily force <hostname> for
each of the three machines.

The Amanda log from the failed dump

# more log.20030304.1
START driver date 20030304
DISK planner halfcut da0s2a
DISK planner halfcut da0s3f
DISK planner halfcut da0s2f
DISK planner wombat.bytecraft.au.com da0s2a
DISK planner wombat.bytecraft.au.com da0s3f
DISK planner wombat.bytecraft.au.com da0s2f
DISK planner spyder.bytecraft.au.com da0s2a
DISK planner spyder.bytecraft.au.com da0s4e
DISK planner spyder.bytecraft.au.com da0s3g
DISK planner spyder.bytecraft.au.com da0s2f
START planner date 20030304
START taper datestamp 20030304 label Daily001 tape 0
INFO planner Incremental of wombat.bytecraft.au.com:da0s3f bumped to level 2.
INFO planner Full dump of spyder.bytecraft.au.com:da0s4e promoted from 3 days 
ahead.
INFO planner Full dump of spyder.bytecraft.au.com:da0s3g promoted from 3 days 
ahead.
INFO planner Full dump of halfcut:da0s2f promoted from 3 days ahead.
INFO planner Full dump of halfcut:da0s2a promoted from 3 days ahead.
INFO planner Full dump of spyder.bytecraft.au.com:da0s2f promoted from 3 days 
ahead.
INFO planner Full dump of wombat.bytecraft.au.com:da0s2a promoted from 3 days 
ahead.
INFO planner Full dump of wombat.bytecraft.au.com:da0s2f promoted from 3 days 
ahead.
INFO planner Full dump of spyder.bytecraft.au.com:da0s2a promoted from 3 days 
ahead.
FINISH planner date 20030304
STATS driver startup time 5117.457
SUCCESS dumper spyder.bytecraft.au.com da0s3g 20030304 0 [sec 0.244 kb 170 kps 
696.3 orig-kb 820]
SUCCESS taper spyder.bytecraft.au.com da0s3g 20030304 0 [sec 2.148 kb 224 kps 
104.2 {wr: writers 7 rdwait 0.000 wrwait 0.016 filemark 2.130}
]
SUCCESS dumper halfcut da0s2a 20030304 0 [sec 15.259 kb 19910 kps 1304.8 
orig-kb 59380]
SUCCESS taper halfcut da0s2a 20030304 0 [sec 7.687 kb 19968 kps 2597.4 {wr: 
writers 624 rdwait 0.000 wrwait 4.196 filemark 3.325}]
SUCCESS dumper wombat.bytecraft.au.com da0s2a 20030304 0 [sec 44.356 kb 38718 
kps 872.9 orig-kb 79410]
SUCCESS taper wombat.bytecraft.au.com da0s2a 20030304 0 [sec 10.387 kb 38752 
kps 3730.8 {wr: writers 1211 rdwait 0.000 wrwait 6.378 filemark
 3.545}]
SUCCESS dumper spyder.bytecraft.au.com da0s2a 20030304 0 [sec 57.663 kb 97841 
kps 1696.8 orig-kb 122080]
SUCCESS taper spyder.bytecraft.au.com da0s2a 20030304 0 [sec 18.013 kb 97888 
kps 5434.3 {wr: writers 3059 rdwait 0.000 wrwait 13.760 filemar
k 3.306}]
SUCCESS dumper spyder.bytecraft.au.com da0s4e 20030304 0 [sec 121.065 kb 174826 
kps 1444.1 orig-kb 216370]
SUCCESS dumper halfcut da0s2f 20030304 0 [sec 197.644 kb 188594 kps 954.2 
orig-kb 483220]
SUCCESS taper spyder.bytecraft.au.com da0s4e 20030304 0 [sec 28.180 kb 174880 
kps 6205.7 {wr: writers 5465 rdwait 0.000 wrwait 22.132 filema
rk 3.485}]
SUCCESS taper halfcut da0s2f 20030304 0 [sec 28.171 kb 188640 kps 6696.1 {wr: 
writers 5895 rdwait 0.380 wrwait 23.982 filemark 1.810}]
SUCCESS dumper spyder.bytecraft.au.com da0s2f 20030304 0 [sec 148.851 kb 159882 
kps 1074.1 orig-kb 637700]
SUCCESS taper spyder.bytecraft.au.com da0s2f 20030304 0 [sec 26.088 kb 159936 
kps 6130.4 {wr: writers 4998 rdwait 0.000 wrwait 21.400 filema
rk 3.532}]
SUCCESS dumper wombat.bytecraft.au.com da0s2f 20030304 0 [sec 331.741 kb 112827 
kps 340.1 orig-kb 299500]
SUCCESS taper wombat.bytecraft.au.com da0s2f 20030304 0 [sec 20.114 kb 112864 
kps 5611.1 {wr: writers 3527 rdwait 0.000 wrwait 15.914 filema
rk 3.515}]
SUCCESS dumper wombat.bytecraft.au.com da0s3f 20030304 2 [sec 3068.527 kb 
5719606 kps 1864.0 orig-kb 11429150]
SUCCESS taper wombat.bytecraft.au.com da0s3f 20030304 2 [sec 780.814 kb 5719648 
kps 7325.2 {wr: writers 178739 rdwait 0.066 wrwait 719.663 f
ilemark 16.574}]
SUCCESS dumper halfcut da0s3f 20030304 1 [sec 5929.900 kb 14640698 kps 2469.0 
orig-kb 23657680]
INFO taper tape Daily001 kb 6512800 fm 9 writing filemark: Input/output error
WARNING driver going into degraded mode because of tape error.
FAIL taper halfcut da0s3f 20030304 1 [out of tape]
ERROR taper no-tape [[writing filemark: Input/output error]]
FINISH driver date 20030304 time 15531.757

OUCH systems error log
/var/log/messages extract

Mar  5 03:03:01 svlto ntpdate[56332]: step time server 203.39.118.3 offset 
0.593492 sec
Mar  5 03:48:35 svlto /kernel: (sa0:ahc0:0:3:0): SCB 0x6 - timed out
Mar  5 03:48:52 svlto /kernel: ahc0: Dumping Card State while idle, at SEQADDR 
0x8
Mar  5 03:48:52 svlto /kernel: ACCUM = 0x0, SINDEX = 0x14, DINDEX = 0xe4, ARG_2 
= 0x0
Mar  5 03:48:52 svlto /kernel: HCNT = 0x0 SCBPTR = 0x11
Mar  5 03:48:52 svlto /kernel: SCSISEQ = 0x12, SBLKCTL = 0xa
Mar  5 03:48:52 svlto /kernel: DFCNTRL = 0x0, DFSTATUS = 0x89
Mar  5 03:48:52 svlto /kernel: LASTPHASE = 0x1, SCSISIGI = 0x0, SXFRCTL0 = 0x80
Mar  5 03:48:52 svlto /kernel: SSTAT0 = 0x0, SSTAT1 = 0x8
Mar  5 03:48:52 svlto /kernel: SCSIPHASE = 0x0
Mar  5 03:48:52 svlto /kernel: STACK == 0x3, 0x108, 0x160, 0x34
Mar  5 03:48:52 svlto /kernel: SCB count = 70
Mar  5 03:48:52 svlto /kernel: Kernel NEXTQSCB = 58
Mar  5 03:48:52 svlto /kernel: Card NEXTQSCB = 58
Mar  5 03:48:52 svlto /kernel: QINFIFO entries: 
Mar  5 03:48:52 svlto /kernel: Waiting Queue entries: 
Mar  5 03:48:52 svlto /kernel: Disconnected Queue entries: 9:6 
Mar  5 03:48:53 svlto /kernel: QOUTFIFO entries: 
Mar  5 03:48:53 svlto /kernel: Sequencer Free SCB List: 17 14 0 3 23 22 4 28 1 
7 24 12 25 16 5 11 18 29 26 19 20 21 27 13 10 31 8 6 2 15 30 
Mar  5 03:48:53 svlto /kernel: Sequencer SCB Info: 0(c 0x60, s 0x7, l 0, t 
0xff) 1(c 0x60, s 0x7, l 0, t 0xff) 2(c 0x60, s 0x7, l 0, t 0xff)
 3(c 0x60, s 0x7, l 0, t 0xff) 4(c 0x60, s 0x7, l 0, t 0xff) 5(c 0x60, s 0x7, l 
0, t 0xff) 6(c 0x60, s 0x7, l 0, t 0xff) 7(c 0x60, s 0x7, l 
0, t 0xff) 8(c 0x60, s 0x7, l 0, t 0xff) 9(c 0x44, s 0x37, l 0, t 0x6) 10(c 
0x60, s 0x7, l 0, t 0xff) 11(c 0x60, s 0x7, l 0, t 0xff) 12(c 0x
60, s 0x7, l 0, t 0xff) 13(c 0x60, s 0x7, l 0, t 0xff) 14(c 0x60, s 0x7, l 0, t 
0xff) 15(c 0x60, s 0x7, l 0, t 0xff) 16(c 0x60, s 0x7, l 0, 
t 0xff) 17(c 0x62, s 0x7, l 0, t 0xff) 18(c 0x60, s 0x7, l 0, t 0xff) 19(c 
0x60, s 0x7, l 0, t 0xff) 20(c 0x60, s 0x7, l 0, t 0xff) 21(c 0x6
0, s 0x7, l 0, t 0xff) 22(c 0x60, s 0x7, l 0, t 0xff) 23(c 0x60, s 0x7, l 0, t 
0xff) 24(c 0x60, s 0x7, l 0, t 0xff) 25(c 0x60, s 0x7, l 0, t
 0xff) 26(c 0x60, s 0x7, l 0, t 0xff) 27(c 0x60, s 0x7, l 0, t 0xff) 28(c 0x60, 
s 0x7, l 0, t 0xff) 29(c 0x60, s 0x7, l 0, t 0xff) 30(c 0x60
, s 0x7, l 0, t 0xff) 31(c 0x60, s 0x7, l 0, t 0xff) 
Mar  5 03:48:53 svlto /kernel: Pending list: 6(c 0x40, s 0x37, l 0)
Mar  5 03:48:53 svlto /kernel: Kernel Free SCB list: 20 59 55 11 10 52 26 67 12 
33 68 13 7 28 8 29 50 18 49 24 23 38 9 44 42 65 21 43 22 46 
37 4 0 27 66 34 36 1 45 47 15 32 39 51 35 53 3 40 41 19 57 17 16 56 14 30 25 54 
69 63 48 5 31 2 64 62 61 60 
Mar  5 03:48:53 svlto /kernel: Untagged Q(3): 6 
Mar  5 03:48:53 svlto /kernel: (sa0:ahc0:0:3:0): Queuing a BDR SCB
Mar  5 03:48:53 svlto /kernel: (sa0:ahc0:0:3:0): Bus Device Reset Message Sent
Mar  5 03:48:53 svlto /kernel: (sa0:ahc0:0:3:0): SCB 0x6 - timed out
Mar  5 03:48:53 svlto /kernel: ahc0: Dumping Card State in Command phase, at 
SEQADDR 0x168
Mar  5 03:48:53 svlto /kernel: ACCUM = 0x80, SINDEX = 0xa0, DINDEX = 0xe4, 
ARG_2 = 0x1
Mar  5 03:48:53 svlto /kernel: HCNT = 0x0 SCBPTR = 0x9
Mar  5 03:48:53 svlto /kernel: SCSISEQ = 0x12, SBLKCTL = 0xa
Mar  5 03:48:53 svlto /kernel: DFCNTRL = 0x4, DFSTATUS = 0x89
Mar  5 03:48:53 svlto /kernel: LASTPHASE = 0x80, SCSISIGI = 0x84, SXFRCTL0 = 
0x88
Mar  5 03:48:53 svlto /kernel: SSTAT0 = 0x7, SSTAT1 = 0x0
Mar  5 03:48:53 svlto /kernel: SCSIPHASE = 0x0
Mar  5 03:48:53 svlto /kernel: STACK == 0x175, 0x160, 0x34, 0x34
Mar  5 03:48:53 svlto /kernel: SCB count = 70
Mar  5 03:48:53 svlto /kernel: Kernel NEXTQSCB = 58
Mar  5 03:48:53 svlto /kernel: Card NEXTQSCB = 58
Mar  5 03:48:53 svlto /kernel: QINFIFO entries: 
Mar  5 03:48:53 svlto /kernel: Waiting Queue entries: 
Mar  5 03:48:53 svlto /kernel: Disconnected Queue entries: 
Mar  5 03:48:53 svlto /kernel: QOUTFIFO entries: 
Mar  5 03:48:53 svlto /kernel: Sequencer Free SCB List: 17 14 0 3 23 22 4 28 1 
7 24 12 25 16 5 11 18 29 26 19 20 21 27 13 10 31 8 6 2 15 30 
Mar  5 03:48:53 svlto /kernel: Sequencer SCB Info: 0(c 0x60, s 0x7, l 0, t 
0xff) 1(c 0x60, s 0x7, l 0, t 0xff) 2(c 0x60, s 0x7, l 0, t 0xff)
 3(c 0x60, s 0x7, l 0, t 0xff) 4(c 0x60, s 0x7, l 0, t 0xff) 5(c 0x60, s 0x7, l 
0, t 0xff) 6(c 0x60, s 0x7, l 0, t 0xff) 7(c 0x60, s 0x7, l 
0, t 0xff) 8(c 0x60, s 0x7, l 0, t 0xff) 9(c 0x44, s 0x37, l 0, t 0x6) 10(c 
0x60, s 0x7, l 0, t 0xff) 11(c 0x60, s 0x7, l 0, t 0xff) 12(c 0x
60, s 0x7, l 0, t 0xff) 13(c 0x60, s 0x7, l 0, t 0xff) 14(c 0x60, s 0x7, l 0, t 
0xff) 15(c 0x60, s 0x7, l 0, t 0xff) 16(c 0x60, s 0x7, l 0, 
t 0xff) 17(c 0x62, s 0x7, l 0, t 0xff) 18(c 0x60, s 0x7, l 0, t 0xff) 19(c 
0x60, s 0x7, l 0, t 0xff) 20(c 0x60, s 0x7, l 0, t 0xff) 21(c 0x6
0, s 0x7, l 0, t 0xff) 22(c 0x60, s 0x7, l 0, t 0xff) 23(c 0x60, s 0x7, l 0, t 
0xff) 24(c 0x60, s 0x7, l 0, t 0xff) 25(c 0x60, s 0x7, l 0, t
 0xff) 26(c 0x60, s 0x7, l 0, t 0xff) 27(c 0x60, s 0x7, l 0, t 0xff) 28(c 0x60, 
s 0x7, l 0, t 0xff) 29(c 0x60, s 0x7, l 0, t 0xff) 30(c 0x60
, s 0x7, l 0, t 0xff) 31(c 0x60, s 0x7, l 0, t 0xff) 
Mar  5 03:48:53 svlto /kernel: Pending list: 6(c 0x44, s 0x37, l 0)
Mar  5 03:48:53 svlto /kernel: Kernel Free SCB list: 20 59 55 11 10 52 26 67 12 
33 68 13 7 28 8 29 50 18 49 24 23 38 9 44 42 65 21 43 22 46 
37 4 0 27 66 34 36 1 45 47 15 32 39 51 35 53 3 40 41 19 57 17 16 56 14 30 25 54 
69 63 48 5 31 2 64 62 61 60 
Mar  5 03:48:54 svlto /kernel: Untagged Q(3): 6 
Mar  5 03:48:54 svlto /kernel: (sa0:ahc0:0:3:0): no longer in timeout, status = 
34b
Mar  5 03:48:54 svlto /kernel: ahc0: Issued Channel A Bus Reset. 1 SCBs aborted
Mar  5 03:48:54 svlto /kernel: (sa0:ahc0:0:3:0): failed to write terminating 
filemark(s)
Mar  5 03:48:54 svlto /kernel: (sa0:ahc0:0:3:0): tape is now frozen- use an 
OFFLINE, REWIND or MTEOM command to clear this state.



-- 
Murray Taylor
Special Projects Engineer
---------------------------------
Bytecraft Systems & Entertainment
Phone: 61 3 8710 2555
Fax: 61 3 8710 2599
Direct: 61 3 9238 4275
Mobile: 61 0417 319 256
Email: murraytaylor AT bytecraftsystems DOT com
or visit us on the web
http://www.bytecraftsystems.com
http://www.bytecraftentertainment.com

************************************************************************
This Email has been scanned for Viruses by MailMarshal.
************************************************************************

<Prev in Thread] Current Thread [Next in Thread>