From owner-freebsd-stable Sun Jun 15 12:45:33 1997 Return-Path: Received: (from root@localhost) by hub.freebsd.org (8.8.5/8.8.5) id MAA22731 for stable-outgoing; Sun, 15 Jun 1997 12:45:33 -0700 (PDT) Received: from fani.fidata.fi (fani.fidata.fi [193.64.102.6]) by hub.freebsd.org (8.8.5/8.8.5) with ESMTP id MAA22709 for ; Sun, 15 Jun 1997 12:45:28 -0700 (PDT) Received: from zeta.fidata.fi (zeta.fidata.fi [193.64.103.213]) by fani.fidata.fi (8.8.5/8.8.5) with ESMTP id WAA21742 for ; Sun, 15 Jun 1997 22:45:26 +0300 (EET DST) Received: (from tomppa@localhost) by zeta.fidata.fi (8.8.5/8.8.5) id WAA17262; Sun, 15 Jun 1997 22:45:25 +0300 (EET DST) Date: Sun, 15 Jun 1997 22:45:25 +0300 (EET DST) Message-Id: <199706151945.WAA17262@zeta.fidata.fi> From: Tomi Vainio MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Transfer-Encoding: 7bit To: freebsd-stable@freebsd.org Subject: ahc driver problem X-Mailer: VM 6.32 under 19.15 XEmacs Lucid Reply-To: tomppa@fidata.fi Sender: owner-stable@freebsd.org X-Loop: FreeBSD.org Precedence: bulk Once again I was making weekly world on my 2.2-stable machine. This time system couldn't anymore recover on this timedout state. Normally I see one or two SCB timedout messages on syslog. Tomppa Jun 15 22:09:54 tick /kernel: sd0(ahc0:0:0): SCB 0x3 - timed out in dataout phase, SCSISIGI == 0x4 Jun 15 22:09:54 tick /kernel: SEQADDR = 0x127 SCSISEQ = 0x12 SSTAT0 = 0x0 SSTAT1 = 0x2 Jun 15 22:11:01 tick /kernel: Ordered Tag queued Jun 15 22:17:05 tick /kernel: SCSISIGI == 0x4 Jun 15 22:17:06 tick /kernel: SEQADDR = 0x128 SCSISEQ = 0x12 SSTAT0 = 0x0 SSTAT1 = 0x2 Jun 15 22:17:06 tick /kernel: Ordered Tag queued Jun 15 22:17:06 tick /kernel: sd0(ahc0:0:0): SCB 0x6 timedout while recovery in progress Jun 15 22:17:06 tick /kernel: sd0(ahc0:0:0): SCB 0x3 timedout while recovery in progress Jun 15 22:17:06 tick /kernel: sd0(ahc0:0:0): SCB 0x2 timedout while recovery in progress Jun 15 22:17:06 tick /kernel: sd0(ahc0:0:0): SCB 0x7 - timed out in dataout phase, SCSISIGI == 0x4 Jun 15 22:17:06 tick /kernel: SEQADDR = 0x127 SCSISEQ = 0x12 SSTAT0 = 0x0 SSTAT1 = 0x2 Jun 15 22:17:06 tick /kernel: sd0(ahc0:0:0): abort message in message buffer Jun 15 22:17:06 tick /kernel: sd0(ahc0:0:0): SCB 0x3 - timed out in dataout phase, SCSISIGI == 0x14 Jun 15 22:17:06 tick /kernel: SEQADDR = 0x127 SCSISEQ = 0x12 SSTAT0 = 0x0 SSTAT1 = 0x2 Jun 15 22:17:06 tick /kernel: ahc0: Issued Channel A Bus Reset. 4 SCBs aborted Jun 15 22:17:06 tick /kernel: Clearing bus reset Jun 15 22:17:06 tick /kernel: Clearing 'in-reset' flag Jun 15 22:17:06 tick /kernel: sd0(ahc0:0:0): no longer in timeout Jun 15 22:17:06 tick /kernel: sd0(ahc0:0:0): no longer in timeout Jun 15 22:17:06 tick /kernel: sd0(ahc0:0:0): UNIT ATTENTION asc:29,0 Jun 15 22:17:06 tick /kernel: sd0(ahc0:0:0): Power on, reset, or bus device reset occurred field replaceable unit: 1 Jun 15 22:17:07 tick /kernel: , retries:1 Jun 15 22:17:07 tick /kernel: sd0(ahc0:0:0): SCB 0x7 - timed out in dataout phase, SCSISIGI == 0x4 Jun 15 22:17:07 tick /kernel: SEQADDR = 0x128 SCSISEQ = 0x12 SSTAT0 = 0x0 SSTAT1 = 0x2 Jun 15 22:17:07 tick /kernel: Ordered Tag queued Jun 15 22:17:07 tick /kernel: sd0(ahc0:0:0): SCB 0x6 timedout while recovery in progress Jun 15 22:17:07 tick /kernel: sd0(ahc0:0:0): SCB 0x3 timedout while recovery in progress Jun 15 22:17:07 tick /kernel: sd0(ahc0:0:0): SCB 0x2 timedout while recovery in progress Jun 15 22:17:07 tick /kernel: sd0(ahc0:0:0): SCB 0x7 - timed out in dataout phase, SCSISIGI == 0x4 Jun 15 22:17:07 tick /kernel: SEQADDR = 0x127 SCSISEQ = 0x12 SSTAT0 = 0x0 SSTAT1 = 0x2 Jun 15 22:17:07 tick /kernel: sd0(ahc0:0:0): abort message in message buffer Jun 15 22:17:07 tick /kernel: sd0(ahc0:0:0): SCB 0x3 - timed out in dataout phase, SCSISIGI == 0x14 Jun 15 22:17:07 tick /kernel: SEQADDR = 0x127 SCSISEQ = 0x12 SSTAT0 = 0x0 SSTAT1 = 0x2 Jun 15 22:17:07 tick /kernel: ahc0: Issued Channel A Bus Reset. 4 SCBs aborted Jun 15 22:17:07 tick /kernel: Clearing bus reset Jun 15 22:17:07 tick /kernel: Clearing 'in-reset' flag Jun 15 22:17:08 tick /kernel: sd0(ahc0:0:0): no longer in timeout Jun 15 22:17:08 tick /kernel: sd0(ahc0:0:0): no longer in timeout Jun 15 22:17:08 tick /kernel: sd0(ahc0:0:0): UNIT ATTENTION asc:29,0 Jun 15 22:17:08 tick /kernel: sd0(ahc0:0:0): Power on, reset, or bus device reset occurred field replaceable unit: 1 Jun 15 22:17:08 tick /kernel: , retries:4 Jun 15 22:17:08 tick /kernel: sd0(ahc0:0:0): SCB 0x7 - timed out in dataout phase, SCSISIGI == 0x4 Jun 15 22:17:08 tick /kernel: SEQADDR = 0x128 SCSISEQ = 0x12 SSTAT0 = 0x0 SSTAT1 = 0x2 Jun 15 22:17:08 tick /kernel: Ordered Tag queued Jun 15 22:17:08 tick /kernel: sd0(ahc0:0:0): SCB 0x6 timedout while recovery in progress Jun 15 22:17:08 tick /kernel: sd0(ahc0:0:0): SCB 0x3 timedout while recovery in progress Jun 15 22:17:08 tick /kernel: sd0(ahc0:0:0): SCB 0x2 timedout while recovery in progress Jun 15 22:17:08 tick /kernel: sd0(ahc0:0:0): SCB 0x7 - timed out in dataout phase, SCSISIGI == 0x4 Jun 15 22:17:08 tick /kernel: SEQADDR = 0x127 SCSISEQ = 0x12 SSTAT0 = 0x0 SSTAT1 = 0x2 Jun 15 22:17:08 tick /kernel: sd0(ahc0:0:0): abort message in message buffer Jun 15 22:17:08 tick /kernel: sd0(ahc0:0:0): SCB 0x3 - timed out in dataout phase, SCSISIGI == 0x14 Jun 15 22:17:08 tick /kernel: SEQADDR = 0x127 SCSISEQ = 0x12 SSTAT0 = 0x0 SSTAT1 = 0x2 Jun 15 22:17:09 tick /kernel: ahc0: Issued Channel A Bus Reset. 4 SCBs aborted Jun 15 22:17:09 tick /kernel: Clearing bus reset Jun 15 22:17:09 tick /kernel: Clearing 'in-reset' flag Jun 15 22:17:09 tick /kernel: sd0(ahc0:0:0): no longer in timeout Jun 15 22:17:09 tick /kernel: sd0(ahc0:0:0): no longer in timeout Jun 15 22:17:09 tick /kernel: sd0(ahc0:0:0): UNIT ATTENTION asc:29,0 Jun 15 22:17:09 tick /kernel: sd0(ahc0:0:0): Power on, reset, or bus device reset occurred field replaceable unit: 1 Jun 15 22:17:09 tick /kernel: , retries:2 Jun 15 22:17:09 tick /kernel: sd0(ahc0:0:0): SCB 0x7 - timed out in dataout phase, SCSISIGI == 0x4 Jun 15 22:17:09 tick /kernel: SEQADDR = 0x128 SCSISEQ = 0x12 SSTAT0 = 0x0 SSTAT1 = 0x2 Jun 15 22:17:09 tick /kernel: Ordered Tag queued Jun 15 22:17:09 tick /kernel: sd0(ahc0:0:0): SCB 0x6 timedout while recovery in progress Jun 15 22:17:09 tick /kernel: sd0(ahc0:0:0): SCB 0x3 timedout while recovery in progress Jun 15 22:17:09 tick /kernel: sd0(ahc0:0:0): SCB 0x2 timedout while recovery in progress Jun 15 22:17:09 tick /kernel: sd0(ahc0:0:0): SCB 0x7 - timed out in dataout phase, SCSISIGI == 0x4 Jun 15 22:17:10 tick /kernel: SEQADDR = 0x127 SCSISEQ = 0x12 SSTAT0 = 0x0 SSTAT1 = 0x2 Jun 15 22:17:10 tick /kernel: sd0(ahc0:0:0): abort message in message buffer Jun 15 22:17:10 tick /kernel: sd0(ahc0:0:0): SCB 0x3 - timed out in dataout phase, SCSISIGI == 0x14 Jun 15 22:17:10 tick /kernel: SEQADDR = 0x127 SCSISEQ = 0x12 SSTAT0 = 0x0 SSTAT1 = 0x2 Jun 15 22:17:10 tick /kernel: ahc0: Issued Channel A Bus Reset. 4 SCBs aborted Jun 15 22:17:10 tick /kernel: Clearing bus reset Jun 15 22:17:10 tick /kernel: Clearing 'in-reset' flag Jun 15 22:17:10 tick /kernel: sd0(ahc0:0:0): no longer in timeout Jun 15 22:17:10 tick /kernel: sd0(ahc0:0:0): no longer in timeout Jun 15 22:17:10 tick /kernel: sd0(ahc0:0:0): UNIT ATTENTION asc:29,0 Jun 15 22:17:10 tick /kernel: sd0(ahc0:0:0): Power on, reset, or bus device reset occurred field replaceable unit: 1 Jun 15 22:17:10 tick /kernel: , FAILURE Jun 15 22:17:10 tick /kernel: sd0(ahc0:0:0): SCB 0x3 - timed out in dataout phase, SCSISIGI == 0x4 Jun 15 22:17:10 tick /kernel: SEQADDR = 0x128 SCSISEQ = 0x12 SSTAT0 = 0x0 SSTAT1 = 0x2 Jun 15 22:17:10 tick /kernel: Ordered Tag queued Jun 15 22:17:10 tick /kernel: sd0(ahc0:0:0): SCB 0x6 timedout while recovery in progress Jun 15 22:17:11 tick /kernel: sd0(ahc0:0:0): SCB 0x2 timedout while recovery in progress Jun 15 22:17:11 tick /kernel: sd0(ahc0:0:0): SCB 0x7 timedout while recovery in progress Jun 15 22:17:11 tick /kernel: sd0(ahc0:0:0): SCB 0x3 - timed out in dataout phase, SCSISIGI == 0x4 Jun 15 22:17:11 tick /kernel: SEQADDR = 0x128 SCSISEQ = 0x12 SSTAT0 = 0x0 SSTAT1 = 0x2 Jun 15 22:17:11 tick /kernel: sd0(ahc0:0:0): abort message in message buffer Jun 15 22:17:11 tick /kernel: sd0(ahc0:0:0): SCB 0x3 - timed out in dataout phase, SCSISIGI == 0x14 Jun 15 22:17:11 tick /kernel: SEQADDR = 0x127 SCSISEQ = 0x12 SSTAT0 = 0x0 SSTAT1 = 0x2 Jun 15 22:17:11 tick /kernel: ahc0: Issued Channel A Bus Reset. 4 SCBs aborted Jun 15 22:17:11 tick /kernel: Clearing bus reset Jun 15 22:17:11 tick /kernel: Clearing 'in-reset' flag Jun 15 22:17:11 tick /kernel: sd0(ahc0:0:0): no longer in timeout Jun 15 22:17:11 tick /kernel: sd0(ahc0:0:0): UNIT ATTENTION asc:29,0 Jun 15 22:17:11 tick /kernel: sd0(ahc0:0:0): Power on, reset, or bus device reset occurred field replaceable unit: 1 Jun 15 22:17:11 tick /kernel: , retries:3 Jun 15 22:17:11 tick /kernel: sd0(ahc0:0:0): SCB 0x7 - timed out in dataout phase, SCSISIGI == 0x4 Jun 15 22:17:12 tick /kernel: SEQADDR = 0x127 SCSISEQ = 0x12 SSTAT0 = 0x0 SSTAT1 = 0x2 Jun 15 22:17:12 tick /kernel: Ordered Tag queued Jun 15 22:17:12 tick /kernel: sd0(ahc0:0:0): SCB 0x6 timedout while recovery in progress Jun 15 22:17:12 tick /kernel: sd0(ahc0:0:0): SCB 0x3 timedout while recovery in progress Jun 15 22:17:12 tick /kernel: sd0(ahc0:0:0): SCB 0x2 timedout while recovery in progress Jun 15 22:17:12 tick /kernel: swap_pager: indefinite wait buffer: device: 132097, blkno: 9928x14 Jun 15 22:17:12 tick /kernel: SEQADDR = Copyright (c) 1992-1997 FreeBSD Inc. Jun 15 22:17:12 tick /kernel: Copyright (c) 1982, 1986, 1989, 1991, 1993 Jun 15 22:17:12 tick /kernel: The Regents of the University of California. All rights reserved. Jun 15 22:17:12 tick /kernel: Jun 15 22:17:12 tick /kernel: FreeBSD 2.2-STABLE #0: Fri Jun 6 19:28:26 EET DST 1997 Jun 15 22:17:12 tick /kernel: tomppa@tick:/f/local/sup/2.2/sys/compile/TICK Jun 15 22:17:12 tick /kernel: CPU: Pentium Pro (232.52-MHz 686-class CPU) Jun 15 22:17:12 tick /kernel: Origin = "GenuineIntel" Id = 0x619 Stepping=9 Jun 15 22:17:13 tick /kernel: Features=0xf9ff,MTRR,PGE,MCA,CMOV> Jun 15 22:17:13 tick /kernel: real memory = 67108864 (65536K bytes) Jun 15 22:17:13 tick /kernel: avail memory = 63688704 (62196K bytes) Jun 15 22:17:13 tick /kernel: Probing for devices on PCI bus 0: Jun 15 22:17:13 tick /kernel: chip0 rev 2 on pci0:0 Jun 15 22:17:13 tick /kernel: chip1 rev 1 on pci0:1:0 Jun 15 22:17:13 tick /kernel: chip2 rev 0 on pci0:1:1 Jun 15 22:17:13 tick /kernel: de0 rev 35 int a irq 15 on pci0:9 Jun 15 22:17:13 tick /kernel: de0: 21040 [10Mb/s] pass 2.3 Jun 15 22:17:13 tick /kernel: de0: address 00:40:c7:94:07:97 Jun 15 22:17:13 tick /kernel: de0: enabling BNC/AUI port Jun 15 22:17:13 tick /kernel: vga0 rev 1 int a irq 12 on pci0:11 Jun 15 22:17:13 tick /kernel: ahc0 rev 0 int a irq 11 on pci0:12 Jun 15 22:17:13 tick /kernel: ahc0: aic7880 Wide Channel, SCSI Id=7, 16/255 SCBs Jun 15 22:17:13 tick /kernel: ahc0 waiting for scsi devices to settle Jun 15 22:17:13 tick /kernel: ahc0: target 0 Tagged Queuing Device Jun 15 22:17:13 tick /kernel: (ahc0:0:0): "SEAGATE ST32155N 0532" type 0 fixed SCSI 2 Jun 15 22:17:13 tick /kernel: sd0(ahc0:0:0): Direct-Access 2049MB (4197405 512 byte sectors) Jun 15 22:17:14 tick /kernel: sd0(ahc0:0:0): with 4177 cyls, 8 heads, and an average 125 sectors/track Jun 15 22:17:14 tick /kernel: ahc0: target 1 Tagged Queuing Device Jun 15 22:17:14 tick /kernel: (ahc0:1:0): "CONNER CP30540 545MB3.5 B0BD" type 0 fixed SCSI 2 Jun 15 22:17:14 tick /kernel: sd1(ahc0:1:0): Direct-Access 520MB (1065912 512 byte sectors) Jun 15 22:17:14 tick /kernel: sd1(ahc0:1:0): with 2242 cyls, 6 heads, and an average 79 sectors/track Jun 15 22:17:14 tick /kernel: ahc0: target 3 Tagged Queuing Device Jun 15 22:17:14 tick /kernel: (ahc0:3:0): "SEAGATE ST5660N 0518" type 0 fixed SCSI 2 Jun 15 22:17:14 tick /kernel: sd2(ahc0:3:0): Direct-Access 520MB (1065664 512 byte sectors) Jun 15 22:17:14 tick /kernel: sd2(ahc0:3:0): with 3002 cyls, 4 heads, and an average 88 sectors/track Jun 15 22:17:14 tick /kernel: (ahc0:6:0): "PLEXTOR CD-ROM PX-12TS 1.02" type 5 removable SCSI 2 Jun 15 22:17:14 tick /kernel: cd0(ahc0:6:0): CD-ROM cd present [220090 x 2048 byte records] Jun 15 22:17:14 tick /kernel: probe0(ahc0:9:0): scsi_cmd Jun 15 22:17:14 tick /kernel: probe0(ahc0:9:0): scsi_done Jun 15 22:17:14 tick /kernel: (ahc0:9:0): command: 0,0,0,0,0,0-[0 bytes] Jun 15 22:17:14 tick /kernel: probe0(ahc0:9:0): scsi_cmd Jun 15 22:17:14 tick /kernel: probe0(ahc0:9:0): scsi_done Jun 15 22:17:14 tick /kernel: (ahc0:9:0): command: 40,0,0,3,0,0,0,0,0,0-[0 bytes] Jun 15 22:17:14 tick /kernel: probe0(ahc0:9:0): scsi_cmd Jun 15 22:17:15 tick /kernel: probe0(ahc0:9:0): scsi_done Jun 15 22:17:15 tick /kernel: (ahc0:9:0): command: 12,0,0,0,2c,0-[44 bytes] Jun 15 22:17:15 tick /kernel: ------------------------------ Jun 15 22:17:15 tick /kernel: 000: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 Jun 15 22:17:15 tick /kernel: 016: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 Jun 15 22:17:15 tick /kernel: 032: 00 00 00 00 00 00 00 00 00 00 00 00 Jun 15 22:17:15 tick /kernel: ------------------------------ Jun 15 22:17:15 tick /kernel: Probing for devices on the ISA bus: Jun 15 22:17:15 tick /kernel: sc0 at 0x60-0x6f irq 1 on motherboard Jun 15 22:17:15 tick /kernel: sc0: VGA color <4 virtual consoles, flags=0x0> Jun 15 22:17:15 tick /kernel: lpt0: disabled, not probed. Jun 15 22:17:15 tick /kernel: sio0 at 0x3f8-0x3ff irq 4 on isa Jun 15 22:17:15 tick /kernel: sio0: type 16550A Jun 15 22:17:15 tick /kernel: sio1 at 0x2f8-0x2ff irq 3 on isa Jun 15 22:17:15 tick /kernel: sio1: type 16550A Jun 15 22:17:15 tick /kernel: wdc0 at 0x1f0-0x1f7 irq 14 flags 0x80ff80ff on isa Jun 15 22:17:15 tick /kernel: wdc0: unit 0 (wd0): , 32-bit, multi-block-8 Jun 15 22:17:15 tick /kernel: wd0: 516MB (1057392 sectors), 1049 cyls, 16 heads, 63 S/T, 512 B/S Jun 15 22:17:16 tick /kernel: fdc0 at 0x3f0-0x3f7 irq 6 drq 2 on isa Jun 15 22:17:16 tick /kernel: fdc0: NEC 72065B Jun 15 22:17:16 tick /kernel: fd0: 1.44MB 3.5in Jun 15 22:17:16 tick /kernel: pas0 at 0x388 irq 10 drq 5 on isa Jun 15 22:17:16 tick /kernel: pas0: Jun 15 22:17:16 tick /kernel: opl0 at 0x388 on isa Jun 15 22:17:16 tick /kernel: opl0: Jun 15 22:17:16 tick /kernel: sb0 at 0x220 irq 7 drq 1 on isa Jun 15 22:17:16 tick /kernel: sb0: Jun 15 22:17:16 tick /kernel: apm0 on isa Jun 15 22:17:16 tick /kernel: apm: found APM BIOS version 1.1 Jun 15 22:17:16 tick /kernel: npx0 on motherboard Jun 15 22:17:16 tick /kernel: npx0: INT 16 interface Jun 15 22:17:16 tick /kernel: WARNING: / was not properly dismounted. -- Tomi Vainio, Fimeko-Data Oy Phone: +358 (0)9 4582421 Mail: tomppa@iki.fi tomppa@fidata.fi Telefax: +358 (0)9 4582425