[3891] in linux-scsi channel archive
HP Travan 4000 - timeouts, seesawing (2.0.32 etc)
daemon@ATHENA.MIT.EDU (Ian Jackson)
Mon May 11 11:44:01 1998
From: Ian Jackson <ijackson@chiark.greenend.org.uk>
To: linux-scsi@vger.rutgers.edu
Date: Mon, 11 May 1998 16:32:30 +0100
I have two HP T4000s internal SCSI Travan 4 tape drives. One is in a
system I have at home, and the other is in a system I have at an ISP
under their hosting service.
I've had persistent problems which have been hard to debug. Almost
always a dump appears to successfully write the data to tape, but the
checksum/readback fails.
Notable symptoms and states the system would get into while reading
back include:
* Tape `see-saws' rather than streaming. stracing the process that's
reading the tape shows it blocked in read, with one small (512
byte) read completing for each seesaw and another being issued
immediately.
* On the ISP-hosted system, backups sometimes take an awfully long
time and have to be aborted. I think this is the same as the
previous symptom.
* SCSI `aborting command due to timeout', followed by a huge lot of
register and state dumps. Many `DANGER : command running, can not
abort'. Then `SCSI bus is being reset', and of course that's the
end of things because the drive starts to rewind the tape. This is
the currently-dominant failure mode. I attach a sample set of
messages.
* Medium error, add. sense indicates sequential positioning error.
I have been using two versions of a set of home-grown backup scripts.
In the first `old' version, dd would read data back from the tape and
the output would be piped straight into md5sum. In the `new' version
a variant of Lee McLoughlin's tape-buffering program was added to try
to ensure that the tape could continue to stream in batches even if
md5sum was slower than the tape read (which it shouldn't be).
Switching from the old to the new scripts has apparently solved the
problem on the home system, a K6/200 with 64Mb of RAM. It hasn't
solved it for the remote system, which is harder to debug. That
system is a Cx5x86/120, again with 64Mb. Both systems have ASUS
motherboards and NCR-clone SCSI controllers - in the former case a
DC390U and in the latter an ASUS SCSI paddle card.
I'm about ready to contact the drive manufacturer, or my supplier.
Does anyone have any helpful comments or suggestions ?
Please also find below a copy of the dump report (which shows the
error messages from the dump scripts) and a fragment of the relevant
script.
Thanks,
Ian.
May 11 00:47:00 chiark uptime: 12:47am up 11 days, 13:58h, 7 users, load average: 0.01, 0.08, 0.15
[ That last message is produced by a cron job. cron is turned off
during the backups to reduce load and to make the filesystems be
(more) inactive. The dump itself takes several hours, then during
the early part of the readback we see: ]
May 11 04:18:54 chiark kernel: scsi : aborting command due to timeout : pid 15260766, scsi0, channel 0, id 4, lun 0 Read (6) 01 00 00 40 00
May 11 04:18:54 chiark kernel: scsi0 : DANGER : command running, can not abort.
May 11 04:33:58 chiark kernel: scsi : aborting command due to timeout : pid 15260766, scsi0, channel 0, id 4, lun 0 Read (6) 01 00 00 40 00
May 11 04:33:58 chiark kernel: scsi0 : DANGER : command running, can not abort.
May 11 04:33:58 chiark kernel: SCSI host 0 abort (pid 15260766) timed out - resetting
May 11 04:33:58 chiark kernel: SCSI bus is being reset for host 0 channel 0.
May 11 04:33:58 chiark kernel: scsi0 : DCMD|DBC=0x50000000, DNAD=0x90c5c (virt 0x00090c5c)
May 11 04:33:58 chiark kernel: DSA=0x39021e8 (virt 0x039021e8)
May 11 04:33:58 chiark kernel: DSPS=0x90d6c, TEMP=0x909bc (virt 0x000909bc), DMODE=0x88
May 11 04:33:58 chiark kernel: SXFER=0x8, SCNTL3=0x13
May 11 04:33:58 chiark kernel: phase=MSGIN, 0 bytes in SCSI FIFO
May 11 04:33:58 chiark kernel: STEST0=0x6
May 11 04:33:58 chiark kernel: scsi0 : DSP 0x90c54 (virt 0x00090c54) ->
May 11 04:33:58 chiark kernel: 0x90c54 (virt 0x00090c54) : 0x50000000 0x00090d6c (virt 0x00090d6c)
May 11 04:33:58 chiark kernel: 0x90c5c (virt 0x00090c5c) : 0x60000200 0x00000000 (virt 0x00000000)
May 11 04:33:58 chiark kernel: 0x90c64 (virt 0x00090c64) : 0x78388800 0x00000000 (virt 0x00000000)
May 11 04:33:58 chiark kernel: 0x90c6c (virt 0x00090c6c) : 0x0f000001 0x000905d8 (virt 0x000905d8)
May 11 04:33:58 chiark kernel: 0x90c74 (virt 0x00090c74) : 0x78389800 0x00000000 (virt 0x00000000)
May 11 04:33:58 chiark kernel: 0x90c7c (virt 0x00090c7c) : 0xc0000004 0x000905d4 (virt 0x000905d4) 0x0000e834 (virt 0x0000e834)
May 11 04:33:58 chiark kernel: scsi0 : issue queue
May 11 04:33:58 chiark kernel: scsi0 : schedule dsa array :
May 11 04:33:58 chiark kernel: scsi0 : end schedule dsa array
May 11 04:33:58 chiark kernel: scsi0 : reconnect_dsa_head :
May 11 04:33:58 chiark kernel: scsi0 : dsa at phys 0x8e1e8 (virt 0x0008e1e8)
May 11 04:33:58 chiark kernel: + 64 : dsa_msgout length = 1, data = 0x8e02c (virt 0x0008e02c)
May 11 04:33:58 chiark kernel: Identify disconnect allowed lun 0
May 11 04:33:58 chiark kernel: + 60 : select_indirect = 0x3040000
May 11 04:33:58 chiark kernel: + 56 : dsa_cmnd = 0x94410 result = 0xffff, target = 4, lun = 0, cmd = Read (6) 01 00 00 40 00
May 11 04:33:58 chiark kernel: + 48 : dsa_next = 0x0
May 11 04:33:58 chiark kernel: scsi0 target 4 : sxfer_sanity = 0x0, scntl3_sanity = 0x3
May 11 04:33:58 chiark kernel: script : 0x78030300 0x0 0x78050000 0x0 0x90080000 0x0 0x0 0x0
May 11 04:33:58 chiark kernel: scsi0 : saved data pointer at offset 0
May 11 04:33:58 chiark kernel: scsi0 : can't determine active data pointer offset
May 11 04:33:58 chiark kernel: 0x90864 (virt 0x00090864) : 0x9e0b0000 0x00000000 (virt 0x00000000)
May 11 04:33:58 chiark kernel: 0x9086c (virt 0x0009086c) : 0x800b0000 0x0009088c (virt 0x0009088c)
May 11 04:33:58 chiark kernel: scsi0 : end reconnect_dsa_head
May 11 04:33:58 chiark kernel: The sti() implicit in a printk() prevents hangs
May 11 04:33:58 chiark kernel: scsi0 : target 4 rejected SDTR
May 11 04:33:58 chiark kernel: scsi0 : setting target 4 to asynchronous SCSI
May 11 04:33:58 chiark kernel: st0: Error with sense data: extra data not valid Current error st09:00: sense key Unit Attention
May 11 04:33:58 chiark kernel: Additional sense indicates Power on, reset, or bus device reset occurred
May 11 04:33:58 chiark kernel: st0: Error with sense data: extra data not valid Current error st09:00: sense key Not Ready
May 11 04:33:58 chiark kernel: Additional sense indicates Logical unit is in process of becoming ready
May 11 04:33:58 chiark kernel: scsi0 : target 0 accepting period 100ns offset 8 10.00MHz FAST SCSI-II
May 11 04:33:58 chiark kernel: scsi0 : setting target 0 to period 100ns offset 8 10.00MHz FAST SCSI-II
[ Now the backups have failed and the system comes back into full
service. ]
May 11 04:47:01 chiark uptime: 4:47am up 11 days, 17:58h, 6 users, load average: 0.11, 0.16, 0.47
Subject: Dump Report: FAILED during check
To: dump-reports@chiark.greenend.org.uk
From: root <root@chiark.greenend.org.uk>
X-Original-Date: Mon, 11 May 1998 04:34:01 +0100
Return-path: <newsmaster@chiark.greenend.org.uk>
X-Received: from root by chiark.greenend.org.uk with local (Exim 1.82 #3)
id 0yYjLl-0002V9-00 (Debian); Mon, 11 May 1998 04:34:01 +0100
Newsgroups: chiark.system
Path: ewrotcd!mail-to-news!not-for-mail
Date: Mon, 11 May 1998 04:32:02 GMT
Delivery-date: Mon, 11 May 1998 04:43:01 +0100
Message-ID: <E0yYjLl-0002V9-00@chiark.greenend.org.uk>
Lines: 150
Xref: ewrotcd chiark.system:5178
Configuration check ...
filesystem group pt0: c0 d0 a0 b0:
/u
filesystem group pt1: c1 d1 a1 b1:
/ /var /u2 /usr /var/spool/news/chiark
incremental group:
/ /var /u /u2 /usr /var/spool/news/chiark
mount points: <local>: sda1-/ hdc6-/tmp sda7-/var hdc5-/u2 sda8-/usr hdc1-/u hda1-/var/spool/news
filesystem expected not to be dumped: /var/spool/news
filesystem expected not to be dumped: /tmp
non-filesystem expected to be dumped: /var/spool/news/chiark
configuration ok
Mon May 11 00:50:10 1998
3+0 records in
3+0 records out
-rw-r--r-- root/root 3 May 10 00:50 1998 TAPEID
-rw-r--r-- root/root 3 May 11 00:51 1998 TAPEID
3+0 records in
3+0 records out
Doing dump of pt1 to tape c1 in drive /dev/st0 ...
Mon May 11 00:51:42 1998
md5sum
dump 0bfu 1 - /
tee p
writebuffer
dd ibs=1024 obs=512 of=/dev/nst0
DUMP: Date of this level 0 dump: Mon May 11 00:51:43 1998
DUMP: Date of last level 0 dump: the epoch
DUMP: Dumping /dev/sda1 (/) to standard output
DUMP: mapping (Pass I) [regular files]
DUMP: mapping (Pass II) [directories]
DUMP: estimated 13169 tape blocks.
DUMP: dumping (Pass III) [directories]
DUMP: dumping (Pass IV) [regular files]
DUMP: DUMP: 13557 tape blocks
DUMP: level 0 dump on Mon May 11 00:51:43 1998
DUMP: DUMP IS DONE
13557+0 records in
27114+0 records out
ok
Mon May 11 00:53:11 1998
md5sum
dump 0bfu 1 - /var
tee p
writebuffer
dd ibs=1024 obs=512 of=/dev/nst0
DUMP: Date of this level 0 dump: Mon May 11 00:53:11 1998
DUMP: Date of last level 0 dump: the epoch
DUMP: Dumping /dev/sda7 (/var) to standard output
DUMP: mapping (Pass I) [regular files]
DUMP: mapping (Pass II) [directories]
DUMP: estimated 217666 tape blocks.
DUMP: dumping (Pass III) [directories]
DUMP: dumping (Pass IV) [regular files]
DUMP: 22.87% done, finished in 0:16
DUMP: 46.01% done, finished in 0:11
DUMP: 66.25% done, finished in 0:07
DUMP: 88.94% done, finished in 0:02
DUMP: DUMP: 217963 tape blocks
DUMP: level 0 dump on Mon May 11 00:53:11 1998
DUMP: DUMP IS DONE
217963+0 records in
435926+0 records out
ok
Mon May 11 01:16:27 1998
md5sum
dump 0bfu 1 - /u2
tee p
writebuffer
dd ibs=1024 obs=512 of=/dev/nst0
DUMP: Date of this level 0 dump: Mon May 11 01:16:28 1998
DUMP: Date of last level 0 dump: the epoch
DUMP: Dumping /dev/hdc5 (/u2) to standard output
DUMP: mapping (Pass I) [regular files]
DUMP: mapping (Pass II) [directories]
DUMP: estimated 361414 tape blocks.
DUMP: dumping (Pass III) [directories]
DUMP: dumping (Pass IV) [regular files]
DUMP: 28.55% done, finished in 0:12
DUMP: 58.48% done, finished in 0:07
DUMP: 88.55% done, finished in 0:01
DUMP: DUMP: 361993 tape blocks
DUMP: level 0 dump on Mon May 11 01:16:28 1998
DUMP: DUMP IS DONE
361993+0 records in
723986+0 records out
ok
Mon May 11 01:33:58 1998
md5sum
dump 0bfu 1 - /usr
tee p
writebuffer
dd ibs=1024 obs=512 of=/dev/nst0
DUMP: Date of this level 0 dump: Mon May 11 01:34:00 1998
DUMP: Date of last level 0 dump: the epoch
DUMP: Dumping /dev/sda8 (/usr) to standard output
DUMP: mapping (Pass I) [regular files]
DUMP: mapping (Pass II) [directories]
DUMP: estimated 693124 tape blocks.
DUMP: dumping (Pass III) [directories]
DUMP: dumping (Pass IV) [regular files]
DUMP: 5.80% done, finished in 1:21
DUMP: 13.14% done, finished in 1:06
DUMP: 20.31% done, finished in 0:58
DUMP: 27.25% done, finished in 0:53
DUMP: 34.08% done, finished in 0:48
DUMP: 40.89% done, finished in 0:43
DUMP: 47.59% done, finished in 0:38
DUMP: 54.80% done, finished in 0:32
DUMP: 60.70% done, finished in 0:29
DUMP: 66.80% done, finished in 0:24
DUMP: 73.88% done, finished in 0:19
DUMP: 80.80% done, finished in 0:14
DUMP: 87.95% done, finished in 0:08
DUMP: 94.48% done, finished in 0:04
DUMP: DUMP: 694791 tape blocks
DUMP: level 0 dump on Mon May 11 01:34:00 1998
DUMP: DUMP IS DONE
694791+0 records in
1389582+0 records out
ok
Mon May 11 02:48:59 1998
md5sum
dump 0bfu 1 - /var/spool/news/chiark
tee p
writebuffer
dd ibs=1024 obs=512 of=/dev/nst0
DUMP: Date of this level 0 dump: Mon May 11 02:49:01 1998
DUMP: Date of last level 0 dump: the epoch
DUMP: Dumping /dev/hda1 (/var/spool/news) to standard output
DUMP: mapping (Pass I) [regular files]
DUMP: mapping (Pass II) [directories]
DUMP: estimated 280791 tape blocks.
DUMP: dumping (Pass III) [directories]
DUMP: dumping (Pass IV) [regular files]
DUMP: 24.86% done, finished in 0:15
DUMP: 50.10% done, finished in 0:09
DUMP: 71.03% done, finished in 0:06
DUMP: 94.62% done, finished in 0:01
DUMP: DUMP: 279750 tape blocks
DUMP: level 0 dump on Mon May 11 02:49:01 1998
DUMP: DUMP IS DONE
279750+0 records in
559500+0 records out
ok
Mon May 11 03:13:05 1998
checksum ok f087748e2a7d699ded5abe6fcad416d8 / dump
Mon May 11 03:13:41 1998
read: I/O error
MISMATCH /var dump bb64a3078666b2225f9bb3a01bd633eb 01ac241514c0463a0655133961ad5602
open S,"this-md5sums" or die $!;
for $tf (@fsys) {
printdate();
chomp($orgsum= <S>);
$orgsum =~ m/^[0-9a-fA-F]{32}$/i or die "orgsum \`$orgsum' ?";
chomp($csum= `readbuffer <$ntape | md5sum`);
$orgsum eq $csum or die "MISMATCH $tf $csum $orgsum\n";
print "checksum ok $csum\t$tf\n" or die $!;
print LOG "checksum ok $csum\t$tf\n" or die $!;
}
printdate();
system "mt -f $tape rewind"; $? and die $?;
-
To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
the body of a message to majordomo@vger.rutgers.edu
