[Hardy] ATA resets 3 times before correctly activating

[Stéphane Graber]

Binary package hint: linux-source-2.6.24

I'm running linux-2.6.24 on amd64 :
ii linux-image-2.6.24-2-generic 2.6.24-2.4 Linux kernel image for version 2.6.24 on x86

And experience serious problem at boot time, causing me not to be able to enter my HDD passphrase if I boot with usplash as ATA fails to activate before usplash's timeout.
Here is the error I got at boot time :
[ 23.536181] ACPI: PCI Interrupt 0000:02:06.1[B] -> GSI 19 (level, low) -> IRQ 19
[ 23.586461] ohci1394: fw-host0: OHCI-1394 1.1 (PCI): IRQ=[19] MMIO=[f4101000-f41017ff] Max Packet=[2048] IR/IT contexts=[4/8]
[ 23.586718] ahci 0000:00:1f.2: version 3.0
[ 23.586757] ACPI: PCI Interrupt 0000:00:1f.2[B] -> GSI 17 (level, low) -> IRQ 17
[ 23.587522] ahci 0000:00:1f.2: nr_ports (4) and implemented port map (0x1) don't match, using nr_ports
[ 23.587611] ahci 0000:00:1f.2: forcing PORTS_IMPL to 0xf
[ 23.639283] usb 1-1: configuration #1 chosen from 1 choice
[ 24.589227] ahci 0000:00:1f.2: AHCI 0001.0100 32 slots 4 ports 1.5 Gbps 0xf impl SATA mode
[ 24.589325] ahci 0000:00:1f.2: flags: 64bit ncq ilck stag pm led clo pmp pio slum part
[ 24.589418] PCI: Setting latency timer of device 0000:00:1f.2 to 64
[ 24.590257] scsi0 : ahci
[ 24.590523] scsi1 : ahci
[ 24.590729] scsi2 : ahci
[ 24.590927] scsi3 : ahci
[ 24.591047] ata1: SATA max UDMA/133 abar m1024@0xf4585000 port 0xf4585100 irq 509
[ 24.591132] ata2: SATA max UDMA/133 abar m1024@0xf4585000 port 0xf4585180 irq 509
[ 24.591215] ata3: SATA max UDMA/133 abar m1024@0xf4585000 port 0xf4585200 irq 509
[ 24.591298] ata4: SATA max UDMA/133 abar m1024@0xf4585000 port 0xf4585280 irq 509
[ 25.228089] ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[ 25.231277] ata1.00: ACPI cmd b1/c1:00:00:00:00:a0 failed (Emask=0x1 Stat=0x51 Err=0x04)
[ 25.232630] ata1: failed to recover some devices, retrying in 5 secs
[ 31.872471] ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[ 31.875642] ata1.00: ACPI cmd b1/c1:00:00:00:00:a0 failed (Emask=0x1 Stat=0x51 Err=0x04)
[ 31.876235] ata1.00: ACPI on devcfg failed the second time, disabling (errno=-5)
[ 31.876323] ata1.00: revalidation failed (errno=1)
[ 31.876394] ata1: failed to recover some devices, retrying in 5 secs
[ 38.516855] ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[ 38.519153] ata1.00: configured for UDMA/100
[ 38.836297] ata2: SATA link down (SStatus 0 SControl 0)
[ 39.155738] ata3: SATA link down (SStatus 0 SControl 0)
[ 39.475179] ata4: SATA link down (SStatus 0 SControl 0)
[ 39.475397] scsi 0:0:0:0: Direct-Access ATA HTS541010G9SA00 MBZO PQ: 0 ANSI: 5
[ 39.476194] ACPI: PCI Interrupt 0000:00:1d.7[A] -> GSI 20 (level, low) -> IRQ 20
[ 39.476838] PCI: Setting latency timer of device 0000:00:1d.7 to 64

As you can see, it takes at least 10s to reactivate and detects the drive.

After that, it correctly asks for my passphrase and boots normally, then if I look at the kernel log I see that happening after some time :
[ 9032.736303] ata5.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
[ 9032.736325] ata5.00: cmd a0/00:00:00:08:00/00:00:00:00:00/a0 tag 0 pio 8 in
[ 9032.736326] cdb 25 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 9032.736328] res 40/00:03:00:00:00/00:00:00:00:00/a0 Emask 0x4 (timeout)
[ 9032.736330] ata5.00: status: { DRDY }
[ 9037.743501] ata5: port is slow to respond, please be patient (Status 0xd0)
[ 9042.758755] ata5: device not ready (errno=-16), forcing hardreset
[ 9042.758771] ata5: soft resetting link
[ 9043.287232] ata5.00: configured for MWDMA2
[ 9043.287251] ata5: EH complete
[10046.180592] ata5.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
[10046.180610] ata5.00: cmd a0/00:00:00:0c:00/00:00:00:00:00/a0 tag 0 pio 12 in
[10046.180612] cdb 43 00 00 00 00 00 00 00 0c 40 00 00 00 00 00 00
[10046.180614] res 40/00:03:00:00:00/00:00:00:00:00/a0 Emask 0x4 (timeout)
[10046.180619] ata5.00: status: { DRDY }
[10051.188688] ata5: port is slow to respond, please be patient (Status 0xd0)
[10056.178970] ata5: device not ready (errno=-16), forcing hardreset
[10056.178981] ata5: soft resetting link
[10056.711471] ata5.00: configured for MWDMA2
[10056.711487] ata5: EH complete
[15097.752928] ata5.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
[15097.752940] ata5.00: cmd a0/00:00:00:00:00/00:00:00:00:00/a0 tag 0
[15097.752941] cdb 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[15097.752942] res 40/00:03:00:00:00/00:00:00:00:00/a0 Emask 0x4 (timeout)
[15097.752945] ata5.00: status: { DRDY }
[15102.792956] ata5: port is slow to respond, please be patient (Status 0xd0)
[15107.787232] ata5: device not ready (errno=-16), forcing hardreset
[15107.787242] ata5: soft resetting link
[15108.326743] ata5.00: configured for MWDMA2
[15108.326762] ata5: EH complete

Looks like something is going wrong with either the ACPI or my S-ATA adapter.

Detailed lspci:
stgraber@castiana:~$ lspci -nn
00:00.0 Host bridge [0600]: Intel Corporation Mobile 945GM/PM/GMS, 943/940GML and 945GT Express Memory Controller Hub [8086:27a0] (rev 03)
00:02.0 VGA compatible controller [0300]: Intel Corporation Mobile 945GM/GMS, 943/940GML Express Integrated Graphics Controller [8086:27a2] (rev 03)
00:02.1 Display controller [0380]: Intel Corporation Mobile 945GM/GMS/GME, 943/940GML Express Integrated Graphics Controller [8086:27a6] (rev 03)
00:1b.0 Audio device [0403]: Intel Corporation 82801G (ICH7 Family) High Definition Audio Controller [8086:27d8] (rev 01)
00:1c.0 PCI bridge [0604]: Intel Corporation 82801G (ICH7 Family) PCI Express Port 1 [8086:27d0] (rev 01)
00:1c.1 PCI bridge [0604]: Intel Corporation 82801G (ICH7 Family) PCI Express Port 2 [8086:27d2] (rev 01)
00:1d.0 USB Controller [0c03]: Intel Corporation 82801G (ICH7 Family) USB UHCI Controller #1 [8086:27c8] (rev 01)
00:1d.1 USB Controller [0c03]: Intel Corporation 82801G (ICH7 Family) USB UHCI Controller #2 [8086:27c9] (rev 01)
00:1d.2 USB Controller [0c03]: Intel Corporation 82801G (ICH7 Family) USB UHCI Controller #3 [8086:27ca] (rev 01)
00:1d.3 USB Controller [0c03]: Intel Corporation 82801G (ICH7 Family) USB UHCI Controller #4 [8086:27cb] (rev 01)
00:1d.7 USB Controller [0c03]: Intel Corporation 82801G (ICH7 Family) USB2 EHCI Controller [8086:27cc] (rev 01)
00:1e.0 PCI bridge [0604]: Intel Corporation 82801 Mobile PCI Bridge [8086:2448] (rev e1)
00:1f.0 ISA bridge [0601]: Intel Corporation 82801GBM (ICH7-M) LPC Interface Bridge [8086:27b9] (rev 01)
00:1f.1 IDE interface [0101]: Intel Corporation 82801G (ICH7 Family) IDE Controller [8086:27df] (rev 01)
00:1f.2 SATA controller [0106]: Intel Corporation 82801GBM/GHM (ICH7 Family) SATA AHCI Controller [8086:27c5] (rev 01)
02:06.0 CardBus bridge [0607]: Texas Instruments PCIxx12 Cardbus Controller [104c:8039]
02:06.1 FireWire (IEEE 1394) [0c00]: Texas Instruments PCIxx12 OHCI Compliant IEEE 1394 Host Controller [104c:803a]
02:0e.0 Ethernet controller [0200]: Broadcom Corporation BCM4401-B0 100Base-TX [14e4:170c] (rev 02)
10:00.0 Network controller [0280]: Intel Corporation PRO/Wireless 3945ABG Network Connection [8086:4222] (rev 02)

I already had the ata errors after boot time on 2.6.22 but never had issues when kernel's detecting devices.
This bug would make someone not knowing how to turn off usplash not able to boot its system if it's encrypted and requires the user to enter a passphrase.
Please ask if you need more information.

[Stéphane Graber (stgraber)]

After updating to 2.6.24-3, the detection slow down at boot time disappeared (I can now boot with usplash :)).
Though I still have regular ATA messages in dmesg, like this one:

[ 272.016411] ata5.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
[ 272.016423] ata5.00: cmd a0/00:00:00:00:00/00:00:00:00:00/a0 tag 0
[ 272.016425] cdb 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 272.016426] res 40/00:03:00:00:00/00:00:00:00:00/a0 Emask 0x4 (timeo
ut)
[ 272.016430] ata5.00: status: { DRDY }
[ 277.013160] ata5: port is slow to respond, please be patient (Status 0xd0)
[ 282.046882] ata5: device not ready (errno=-16), forcing hardreset
[ 282.046889] ata5: soft resetting link
[ 282.594613] ata5.00: configured for MWDMA2
[ 282.594631] ata5: EH complete

[kiev1 (sys-sys-admin)]

use IDE hard drive
this kernel bug
dublicate -> https://bugs.launchpad.net/ubuntu/+source/linux/+bug/217920

[Leann Ogasawara (leannogasawara)]

The Ubuntu Kernel Team is planning to move to the 2.6.27 kernel for the upcoming Intrepid Ibex 8.10 release. As a result, the kernel team would appreciate it if you could please test this newer 2.6.27 Ubuntu kernel. There are one of two ways you should be able to test:

1) If you are comfortable installing packages on your own, the linux-image-2.6.27-* package is currently available for you to install and test.

--or--

2) The upcoming Alpha5 for Intrepid Ibex 8.10 will contain this newer 2.6.27 Ubuntu kernel. Alpha5 is set to be released Thursday Sept 4. Please watch http://www.ubuntu.com/testing for Alpha5 to be announced. You should then be able to test via a LiveCD.

Please let us know immediately if this newer 2.6.27 kernel resolves the bug reported here or if the issue remains. More importantly, please open a new bug report for each new bug/regression introduced by the 2.6.27 kernel and tag the bug report with 'linux-2.6.27'. Also, please specifically note if the issue does or does not appear in the 2.6.26 kernel. Thanks again, we really appreicate your help and feedback.

[Stéphane Graber (stgraber)]

I haven't been able to reproduce the issue with Intrepid, marking fix released.

[manysounds (manysounds)]

Hello, doing an install of Ibex today and receiving nearly the same exact behavior.
(sorry, bit of a linux noob here and no way to copy the console input that I am aware of)
starting cupsd---
---start loop here---
 ata5.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
ata5.00: cmd a0/00:00:00:00:00/00:00:00:00:00/a0 tag 0
 cdb 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
res 40/00:03:00:00:00/00:00:00:00:00/a0 Emask 0x4 (timeout)
ata5.00: status: { DRDY }
ata5: port is slow to respond, please be patient (Status 0xd0)
ata5: device not ready (errno=-16), forcing hardreset
ata5: soft resetting link
 ata5.00: configured for MWDMA2
ata5: EH complete
-loop-
---Repeats a few times then tries to run a bunch of same stuff, gets stuck after cupsd and repeats the whole thing again, then goes black, monitor on and hangs.

I tried 2 fresh downloads of both 386 and x64 burned on 2 different machines as well as booting from USB unetbootin style.

Gateway DX 4720-03
Dual Pentium
came with vista 64 (meh)
4 gig ram

my 6th hack sense ( and I mean hack, like I don't rreally know what 'm doing) 6th sense tells me it's somethi9ng having to do with IRQ assignments or something because there's some other bug in the output about being unable to move the device? or something. Stupid southbridge?

Additionally, I get a BSOD trying to install WinXPsp2 on the same machine.
YES, I tried using a non serial ata drive. That's when I discovered that an old version of XP will boot up just fine on this box -you just can't install it.
-Flingpoo at MS and Gateway and MSI? who makes the mobo and NVidia for the chipset too and oh yeah Intel.

Anyway, same errors.

[Hein Zelle (zelle)]

I have this issue with a

[ 27.129377] ata2: PATA max UDMA/100 cmd 0x170 ctl 0x376 bmdma 0x18b8 irq 15
[ 27.337912] ata2.00: ATAPI: TSSTcorpCD/DVDW SN-S082D, SS03, max UDMA/33

which gives (using hardy, kernel 2.6.24-21-generic) regular error messages like this (no noticeable lockups):

Oct 16 07:47:41 giotto kernel: [81641.657883] cdb 43 00 00 00 00 00 00 00 0c 40 00 00 00 00 00 00
Oct 16 07:47:41 giotto kernel: [81641.657885] res 40/00:03:00:00:00/00:00:00:00:00/a0 Emask 0x4 (timeout)
Oct 16 07:47:46 giotto kernel: [81646.691699] ata2: port is slow to respond, please be patient (Status 0xd0)
Oct 16 07:47:51 giotto kernel: [81651.670626] ata2: device not ready (errno=-16), forcing hardreset
Oct 16 07:47:51 giotto kernel: [81651.670635] ata2: soft resetting link
Oct 16 07:47:51 giotto kernel: [81652.194503] ata2.00: configured for UDMA/25
Oct 16 07:47:51 giotto kernel: [81652.194525] ata2: EH complete

I have just tried the 2.6.27 kernel from intrepid, and got exactly the same messages after a few minutes.
The new kernel does not appear to help, for my system.

[GoofY (goofy-dse)]

I've got the same issues both on Hardy & Ibex.
Both reproducible on 2 machines with setup's like this:

1st
2x pata 160GB (raidsetup)
2x sata 1TB (raidsetup)

2nd
2x pata (160GB + 80GB )
1x sata 250GB

Eventually it got so bad on the 1st compu (= server) that I even DOWNGRADED to Gutsy (no problems since, running under heavy load for 3 days now (mainly for testing))

Both systems run into problems under average to heavy load with SATA drives attached, if no SATA is attached (so only PATA, i've got no probs). Also if only SATA is attached!

IMHO this is a serious bug introduced in Ubuntu version 8.04 & up (eg 8.10)

This happens continually every +/-10 sec

excerpt logging
-------------------
[ 4850.988125] ata3.01: status: { DRDY ERR }
[ 4850.988173] ata3: soft resetting link
[ 4851.380541] ata3.01: configured for PIO0
[ 4851.380583] ata3: EH complete
[ 4880.992051] ata3.01: qc timeout (cmd 0xa0)
[ 4880.992078] ata3.01: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
[ 4880.992096] ata3.01: cmd a0/00:00:00:00:00/00:00:00:00:00/b0 tag 0
[ 4880.992099] cdb 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 4880.992101] res 51/20:03:00:00:00/00:00:00:00:00/b0 Emask 0x5 (timeout)
[ 4880.992109] ata3.01: status: { DRDY ERR }
[ 4880.992141] ata3: soft resetting link
[ 4881.384525] ata3.01: configured for PIO0
[ 4881.384585] ata3: EH complete
[ 4897.996075] ata3.01: qc timeout (cmd 0xa0)
[ 4897.996102] ata3.01: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
[ 4897.996120] ata3.01: cmd a0/00:00:00:00:00/00:00:00:00:00/b0 tag 0
[ 4897.996123] cdb 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 4897.996126] res 51/20:03:00:00:00/00:00:00:00:00/b0 Emask 0x5 (timeout)
[ 4897.996134] ata3.01: status: { DRDY ERR }
[ 4897.996176] ata3: soft resetting link
[ 4898.388522] ata3.01: configured for PIO0
[ 4898.388578] ata3: EH complete
[ 4937.568066] ata3.01: qc timeout (cmd 0xa0)
[ 4937.568100] ata3.01: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
[ 4937.568118] ata3.01: cmd a0/00:00:00:00:00/00:00:00:00:00/b0 tag 0
[ 4937.568121] cdb 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 4937.568123] res 51/20:03:00:00:00/00:00:00:00:00/b0 Emask 0x5 (timeout)
[ 4937.568131] ata3.01: status: { DRDY ERR }
[ 4937.568189] ata3: soft resetting link
[ 4937.952536] ata3.01: configured for PIO0
[ 4937.952598] ata3: EH complete
[ 5027.812089] ata3.01: qc timeout (cmd 0xa0)
[ 5027.812168] ata3.01: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
[ 5027.812188] ata3.01: cmd a0/00:00:00:00:00/00:00:00:00:00/b0 tag 0
[ 5027.812191] cdb 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 5027.812193] res 51/20:03:00:00:00/00:00:00:00:00/b0 Emask 0x5 (timeout)
[ 5027.812208] ata3.01: status: { DRDY ERR }
[ 5027.812239] ata3: soft resetting link
[ 5028.200559] ata3.01: configured for PIO0
[ 5028.200606] ata3: EH complete
---------------

[kiev1 (sys-sys-admin)]

try using debian

[GoofY (goofy)]

Fix does not work for me, SATA keeps being resetting.

[Leann Ogasawara (leannogasawara)]

It would be best if those of you still experiencing issues would open a new report as you likely have a slightly different bug than what Stephane reported. He's commented this is no longer an issue with Intrepid. I'm setting the status back to "Fix Released".

[Launchpad Janitor (janitor)]

Per a decision made by the Ubuntu Kernel Team, bugs will longer be assigned to the ubuntu-kernel-team in Launchpad as part of the bug triage process. The ubuntu-kernel-team is being unassigned from this bug report. Refer to https://wiki.ubuntu.com/KernelTeamBugPolicies for more information. Thanks.