Bug 188667 - Assertion failed! qc != NULL,drivers/scsi/libata-core.c,ata_pio_poll,line=2897
Assertion failed! qc != NULL,drivers/scsi/libata-core.c,ata_pio_poll,line=2897
Status: CLOSED INSUFFICIENT_DATA
Product: Fedora
Classification: Fedora
Component: kernel (Show other bugs)
5
i386 Linux
medium Severity medium
: ---
: ---
Assigned To: Kernel Maintainer List
Brian Brock
MassClosed
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2006-04-11 21:16 EDT by Mitch Skinner
Modified: 2008-01-19 23:40 EST (History)
2 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2008-01-19 23:40:56 EST
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)

  None (edit)
Description Mitch Skinner 2006-04-11 21:16:34 EDT
Description of problem:
I have a drive that's starting to go, but I was still hoping to get some data
off of it.  I don't blame the kernel for the drive failure, but the handling of
it could be better.  FC5 is installed on a new drive, and I was trying to dd
from a partition on the old one to the new one.  In /var/log/messages, I got a
lot of repeats of these messages:
Apr 11 09:34:40 enzian kernel: sd 0:0:1:0: SCSI error: return code = 0x8000002
Apr 11 09:34:40 enzian kernel: sdb: Current: sense key: Aborted Command
Apr 11 09:34:40 enzian kernel:     Additional sense: Scsi parity error
Apr 11 09:34:40 enzian kernel: end_request: I/O error, dev sdb, sector 159488
Apr 11 09:34:40 enzian kernel: Buffer I/O error on device sdb1, logical block 159425
Apr 11 09:34:40 enzian kernel: ATA: abnormal status 0xD0 on port 0xFE07
Apr 11 09:34:40 enzian last message repeated 2 times
Apr 11 09:34:40 enzian kernel: ata1: command 0x25 timeout, stat 0xd0 host_stat 0x61
Apr 11 09:34:40 enzian kernel: ata1: status=0xd0 { Busy }


I was unable to kill the dd.  After a while, I got this in /var/log/messages:


Apr 11 09:41:25 enzian kernel: ATA: abnormal status 0xD0 on port 0xFE07
Apr 11 09:41:26 enzian last message repeated 3 times
Apr 11 09:41:26 enzian kernel: ata1: command 0xb0 timeout, stat 0xd0 host_stat 0x0
Apr 11 09:41:26 enzian kernel: ata1: status=0xd0 { Busy }
Apr 11 09:41:26 enzian kernel: ATA: abnormal status 0xD0 on port 0xFE07
Apr 11 09:41:26 enzian kernel: Assertion failed! qc !=
NULL,drivers/scsi/libata-core.c,ata_pio_poll,line=2897
Apr 11 09:41:26 enzian kernel: Assertion failed! qc !=
NULL,drivers/scsi/libata-core.c,ata_pio_block,line=3333
Apr 11 09:41:26 enzian kernel: Unable to handle kernel NULL pointer dereference
at virtual address 00000014
Apr 11 09:41:26 enzian kernel:  printing eip:
Apr 11 09:41:26 enzian kernel: f886b421
Apr 11 09:41:26 enzian kernel: *pde = 36ec9001
Apr 11 09:41:27 enzian kernel: Oops: 0000 [#1]
Apr 11 09:41:27 enzian kernel: SMP
Apr 11 09:41:27 enzian kernel: last sysfs file:
/class/net/sit0/statistics/collisions
Apr 11 09:41:27 enzian kernel: Modules linked in: radeon drm ppdev autofs4 hidp
rfcomm l2cap bluetooth sunrpc ip_conntrack_netbios_ns ipt_REJECT xt_state
ip_conntrack nfnetlink xt_tcpudp iptable_filter ip_tables x_tables video button
battery ac ipv6 lp parport_pc parport floppy nvram ehci_hcd uhci_hcd sg e100
snd_intel8x0 snd_ac97_codec snd_ac97_bus snd_seq_dummy mii snd_seq_oss
snd_seq_midi_event snd_seq snd_seq_device snd_pcm_oss snd_mixer_oss snd_pcm
snd_timer snd soundcore snd_page_alloc i2c_i801 i2c_core dm_snapshot dm_zero
dm_mirror dm_mod ext3 jbd ata_piix libata sd_mod scsi_mod
Apr 11 09:41:27 enzian kernel: CPU:    0
Apr 11 09:41:27 enzian kernel: EIP:    0060:[<f886b421>]    Not tainted VLI
Apr 11 09:41:27 enzian kernel: EFLAGS: 00010246   (2.6.16-1.2080_FC5smp #1)
Apr 11 09:41:27 enzian kernel: EIP is at ata_pio_task+0xed/0x677 [libata]
Apr 11 09:41:27 enzian kernel: eax: 00000053   ebx: 00000050   ecx: f7f7cf08  
edx: 00000050
Apr 11 09:41:28 enzian kernel: esi: f7de7310   edi: 00000000   ebp: 00000000  
esp: f7f7cf18
Apr 11 09:41:28 enzian kernel: ds: 007b   es: 007b   ss: 0068
Apr 11 09:41:28 enzian kernel: Process ata/0 (pid: 333, threadinfo=f7f7c000
task=f7ca86d0)
Apr 11 09:41:28 enzian kernel: Stack: <0>f7ca87f8 c0354300 f7de7310 c2412160
2fdd3e00 003d25ca 00000000 00000000
Apr 11 09:41:28 enzian kernel:        00200082 00000282 f7de78cc f7de78d0
c26279c0 00000282 c01313a0 f886b334
Apr 11 09:41:28 enzian kernel:        f7de7310 c26279d8 c26279c0 c26279e0
c0131b8d c0131c73 00000000 00000000
Apr 11 09:41:28 enzian kernel: Call Trace:
Apr 11 09:41:28 enzian kernel:  [<c01313a0>] run_workqueue+0x7f/0xba    
[<f886b334>] ata_pio_task+0x0/0x677 [libata]
Apr 11 09:41:29 enzian kernel:  [<c0131b8d>] worker_thread+0x0/0x117    
[<c0131c73>] worker_thread+0xe6/0x117
Apr 11 09:41:29 enzian kernel:  [<c011da81>] default_wake_function+0x0/0xc    
[<c01344a5>] kthread+0x9d/0xc9
Apr 11 09:41:29 enzian kernel:  [<c0134408>] kthread+0x0/0xc9     [<c0102005>]
kernel_thread_helper+0x5/0xb
Apr 11 09:41:29 enzian kernel: Code: f8 e8 d5 89 8b c7 83 c4 14 0f b6 d3 f6 c2
21 74 1a 83 8d 94 00 00 00 02 8b 44 24 08 c7 80 ec 05 00 00 07 00 00 00 e9 1e ff
ff ff <8a> 45 14 83 e8 05 3c 02 0f 87 ba 01 00 00 80 e2 08 75 09 8b 54
Apr 11 09:41:29 enzian kernel: Continuing in 120 seconds. ^MContinuing in 119
seconds. ^MContinuing in 118 seconds. ^MContinuing in 117 seconds. ^MContinuing
[snip]
Apr 11 09:41:30 enzian kernel: tinuing in 10 seconds. ^MContinuing in 9 seconds.
^MContinuing in 8 seconds. ^MContinuing in 7 seconds. ^MContinuing in 6 seconds.
^MContinuing in 5 seconds. ^MContinuing in 4 seconds. ^MContinuing in 3 seconds.
^MContinuing in 2 seconds. ^MContinuing in 1 seconds.
Apr 11 09:41:30 enzian kernel:  <3>BUG: soft lockup detected on CPU#0!
Apr 11 09:41:30 enzian kernel:
Apr 11 09:41:30 enzian kernel: Pid: 333, comm:                ata/0
Apr 11 09:41:30 enzian kernel: EIP: 0060:[<c0127fd7>] CPU: 0
Apr 11 09:41:30 enzian kernel: EIP is at __do_softirq+0x4f/0xc2
Apr 11 09:41:31 enzian kernel:  EFLAGS: 00000286    Not tainted 
(2.6.16-1.2080_FC5smp #1)
Apr 11 09:41:31 enzian kernel: EAX: 02018f60 EBX: 00000022 ECX: c03f8380 EDX:
c03f8380
Apr 11 09:41:31 enzian kernel: ESI: c03bdb00 EDI: 0000000a EBP: 00000000 DS:
007b ES: 007b
Apr 11 09:41:31 enzian kernel: CR0: 8005003b CR2: 00000014 CR3: 36f393c0 CR4:
000006f0
Apr 11 09:41:31 enzian kernel:  [<c0105eef>] do_softirq+0x46/0x4e    
=======================
Apr 11 09:41:31 enzian kernel:  [<c01047dc>] apic_timer_interrupt+0x1c/0x24
Apr 11 09:41:31 enzian kernel:  [<c02f216c>] _spin_unlock_irqrestore+0xa/0xc
 [<c0105208>] die+0x1a3/0x207
Apr 11 09:41:31 enzian kernel:  [<c02f3258>] do_page_fault+0x3b1/0x5e2    
[<f886b421>] ata_pio_task+0xed/0x677 [libata]
Apr 11 09:41:31 enzian kernel:  [<c02f2ea7>] do_page_fault+0x0/0x5e2    
[<c01048a7>] error_code+0x4f/0x54
Apr 11 09:41:31 enzian kernel:  [<f886b421>] ata_pio_task+0xed/0x677 [libata]
  [<c01313a0>] run_workqueue+0x7f/0xba
Apr 11 09:41:32 enzian kernel:  [<f886b334>] ata_pio_task+0x0/0x677 [libata]
 [<c0131b8d>] worker_thread+0x0/0x117
Apr 11 09:41:32 enzian kernel:  [<c0131c73>] worker_thread+0xe6/0x117    
[<c011da81>] default_wake_function+0x0/0xc
Apr 11 09:41:32 enzian kernel:  [<c01344a5>] kthread+0x9d/0xc9     [<c0134408>]
kthread+0x0/0xc9


Version-Release number of selected component (if applicable):
2.6.16-1.2080_FC5smp #1 SMP Tue Mar 28 03:55:15 EST 2006 i686 i686 i386
Comment 1 Mitch Skinner 2006-04-11 21:18:41 EDT
If it helps, I'm happy to provide any more information or do tests.
Comment 2 Martin Ebourne 2006-06-05 18:16:05 EDT
I've got a kernel oops and although it's a different way of triggering the
problem, it is exactly the same assertion that has failed so posting here
because it is probably related. Original poster was i386, I'm x86_64 so I've
change arch -> all.

Steps to reproduce:
1. hdparm -S 120 /dev/sdc
2. Wait for the disk to spin down
3. hddtemp /dev/sdc

Results:
Jun  5 22:37:24 hordein kernel: ata3: command 0xb0 timeout, stat 0xd0 host_stat 0x0
Jun  5 22:37:24 hordein kernel: ata3: status=0xd0 { Busy }
Jun  5 22:37:24 hordein kernel: ATA: abnormal status 0xD0 on port 0x9F7
Jun  5 22:37:24 hordein last message repeated 3 times
Jun  5 22:37:27 hordein kernel: ata3: command 0xb0 timeout, stat 0xd0 host_stat 0x0
Jun  5 22:37:27 hordein kernel: ata3: status=0xd0 { Busy }
Jun  5 22:37:27 hordein kernel: Assertion failed! qc !=
NULL,drivers/scsi/libata-core.c,ata_pio_poll,line=2897
Jun  5 22:37:28 hordein last message repeated 60 times
Jun  5 22:37:28 hordein kernel: Assertion failed! qc !=
NULL,drivers/scsi/libata-core.c,ata_pio_block,line=3333
Jun  5 22:37:28 hordein kernel: Unable to handle kernel NULL pointer dereference
at 0000000000000028 RIP: 
Jun  5 22:37:28 hordein kernel: <ffffffff880407ca>{:libata:ata_pio_task+231}
Jun  5 22:37:28 hordein kernel: PGD 433c0067 PUD 2016a067 PMD 0 
Jun  5 22:37:28 hordein kernel: Oops: 0000 [1] SMP 
Jun  5 22:37:28 hordein kernel: last sysfs file:
/devices/platform/i2c-9191/9191-0290/cpu0_vid
Jun  5 22:37:28 hordein kernel: CPU 0 
Jun  5 22:37:28 hordein kernel: Modules linked in: aes dm_crypt loop nfsd lockd
nfs_acl autofs4 it87 hwmon_vid hwmon i2c_isa hidp rfcomm l2cap bluetooth sunrpc
ipt_LOG xt_state ip_conntrack nfnetlink xt_tcpudp xt_limit iptable_filter
ip_tables x_tables xfs exportfs video button battery ac lp parport_pc parport
nvram ohci1394 ieee1394 ohci_hcd ehci_hcd sg dvb_bt8xx dst_ca dst bt878 nxt6000
mt352 dvb_pll sp887x cx24110 or51211 lgdt330x tuner bttv video_buf budget_ci
tda1004x budget_core saa7146 matroxfb_base matroxfb_DAC1064 matroxfb_accel
matroxfb_Ti3026 matroxfb_g450 g450_pll matroxfb_misc matrox_w1 wire
compat_ioctl32 i2c_algo_bit v4l2_common btcx_risc ir_common ttpci_eeprom stv0299
dvb_core stv0297 prism54 tveeprom videodev snd_intel8x0 snd_ac97_codec
snd_ac97_bus snd_seq_dummy snd_seq_oss snd_seq_midi_event snd_seq snd_seq_device
snd_pcm_oss snd_mixer_oss snd_pcm snd_timer snd soundcore snd_page_alloc
i2c_nforce2 i2c_core forcedeth dm_snapshot dm_zero dm_mirror dm_mod ext3 jbd
sata_nv libata sd_mod scsi_mod
Jun  5 22:37:28 hordein kernel: Pid: 386, comm: ata/0 Not tainted
2.6.16-1.2122_FC5 #1
Jun  5 22:37:28 hordein kernel: RIP: 0010:[<ffffffff880407ca>]
<ffffffff880407ca>{:libata:ata_pio_task+231}
Jun  5 22:37:28 hordein kernel: RSP: 0018:ffff81005f34ddb8  EFLAGS: 00010246
Jun  5 22:37:28 hordein kernel: RAX: 0000000000000053 RBX: 0000000000000050 RCX:
0000000000000720
Jun  5 22:37:28 hordein kernel: RDX: 0000000000000050 RSI: 0000000000000246 RDI:
ffffffff803c0a30
Jun  5 22:37:28 hordein kernel: RBP: 0000000000000000 R08: 00000000000000a0 R09:
ffffffff803c09e0
Jun  5 22:37:28 hordein kernel: R10: 0000000000000004 R11: 0000000000000000 R12:
0000000000000000
Jun  5 22:37:28 hordein kernel: R13: 0000000000000296 R14: ffff81005f339518 R15:
ffff81005f339518
Jun  5 22:37:28 hordein kernel: FS:  00002aaaac88e000(0000)
GS:ffffffff8050c000(0000) knlGS:00000000080df830
Jun  5 22:37:28 hordein kernel: CS:  0010 DS: 0018 ES: 0018 CR0: 000000008005003b
Jun  5 22:37:28 hordein kernel: CR2: 0000000000000028 CR3: 00000000131bb000 CR4:
00000000000006e0
Jun  5 22:37:28 hordein kernel: Process ata/0 (pid: 386, threadinfo
ffff81005f34c000, task ffff810037d4e100)
Jun  5 22:37:28 hordein kernel: Stack: 00000000000043d0 0000000000000003
ffff81005f34de08 ffffffff8012be00 
Jun  5 22:37:28 hordein kernel:        ffffffff803b83c0 ffff81005f339bc8
ffff81005f339bd0 ffff81005f39cdc0 
Jun  5 22:37:28 hordein kernel:        0000000000000296 ffff81005f339518 
Jun  5 22:37:28 hordein kernel: Call Trace: <ffffffff8012be00>{__wake_up+56}
<ffffffff880406e3>{:libata:ata_pio_task+0}
Jun  5 22:37:28 hordein kernel:        <ffffffff801423a9>{run_workqueue+159}
<ffffffff80142a42>{worker_thread+0}
Jun  5 22:37:28 hordein kernel:       
<ffffffff80145a6f>{keventd_create_kthread+0} <ffffffff80142b4b>{worker_thread+265}
Jun  5 22:37:28 hordein kernel:       
<ffffffff8012ad28>{default_wake_function+0}
<ffffffff80145a6f>{keventd_create_kthread+0}
Jun  5 22:37:28 hordein kernel:       
<ffffffff80145a6f>{keventd_create_kthread+0} <ffffffff80145d82>{kthread+254}
Jun  5 22:37:28 hordein kernel:        <ffffffff8010b8b2>{child_rip+8}
<ffffffff80145a6f>{keventd_create_kthread+0}
Jun  5 22:37:28 hordein kernel:        <ffffffff80339aee>{thread_return+0}
<ffffffff80145c84>{kthread+0}
Jun  5 22:37:28 hordein kernel:        <ffffffff8010b8aa>{child_rip+0}
Jun  5 22:37:28 hordein kernel: 
Jun  5 22:37:28 hordein kernel: Code: 8a 45 28 83 e8 05 3c 02 0f 87 f7 01 00 00
80 e2 08 75 10 41 
Jun  5 22:37:28 hordein kernel: RIP <ffffffff880407ca>{:libata:ata_pio_task+231}
RSP <ffff81005f34ddb8>
Jun  5 22:37:28 hordein kernel: CR2: 0000000000000028
Jun  5 22:37:37 hordein kernel:  <3>ata3: command 0xec timeout, stat 0x58
host_stat 0x0
Jun  5 22:37:37 hordein kernel: ATA: abnormal status 0x58 on port 0x9F7
Jun  5 22:37:37 hordein last message repeated 2 times
Jun  5 22:37:40 hordein kernel: ata3: command 0xec timeout, stat 0x58 host_stat 0x0
Jun  5 22:37:40 hordein kernel: ATA: abnormal status 0x58 on port 0x9F7
Jun  5 22:37:40 hordein last message repeated 3 times
Jun  5 22:37:43 hordein kernel: ata3: command 0xb0 timeout, stat 0x58 host_stat 0x0
Jun  5 22:37:43 hordein kernel: ATA: abnormal status 0x58 on port 0x9F7
Jun  5 22:37:43 hordein last message repeated 3 times
Jun  5 22:37:46 hordein kernel: ata3: command 0xb0 timeout, stat 0x58 host_stat 0x0

Expected results:
Kernel not to crash.

Additional info:
Works fine on the disk if spinning, and seems ok on IDE. Just fails on SATA
while spun down. Google turns up a couple of other people with the same
assertion from using hddtemp on a spun down sata, but they were tainted so were
roundly ignored, alas.

The machine is seriously not well now, keeps hanging for ages and putting this out:
Jun  5 22:57:48 hordein kernel: ata2: command 0xec timeout, stat 0x58 host_stat 0x0
Jun  5 22:57:48 hordein kernel: ATA: abnormal status 0x58 on port 0x967
Seriously needs rebooting.

kernel-2.6.16-1.2122_FC5
Seagate 400GB SATA drive, Model: ST3400832AS Rev: 3.03

Great so it lets me change the hardware field on the page, then tells me off
afterwards. Sigh.
Comment 3 Dave Jones 2006-10-16 15:14:41 EDT
A new kernel update has been released (Version: 2.6.18-1.2200.fc5)
based upon a new upstream kernel release.

Please retest against this new kernel, as a large number of patches
go into each upstream release, possibly including changes that
may address this problem.

This bug has been placed in NEEDINFO state.
Due to the large volume of inactive bugs in bugzilla, if this bug is
still in this state in two weeks time, it will be closed.

Should this bug still be relevant after this period, the reporter
can reopen the bug at any time. Any other users on the Cc: list
of this bug can request that the bug be reopened by adding a
comment to the bug.

In the last few updates, some users upgrading from FC4->FC5
have reported that installing a kernel update has left their
systems unbootable. If you have been affected by this problem
please check you only have one version of device-mapper & lvm2
installed.  See bug 207474 for further details.

If this bug is a problem preventing you from installing the
release this version is filed against, please see bug 169613.

If this bug has been fixed, but you are now experiencing a different
problem, please file a separate bug for the new problem.

Thank you.
Comment 4 Jon Stanley 2008-01-19 23:40:56 EST
(this is a mass-close to kernel bugs in NEEDINFO state)

As indicated previously there has been no update on the progress of this bug
therefore I am closing it as INSUFFICIENT_DATA. Please re-open if the issue
still occurs for you and I will try to assist in its resolution. Thank you for
taking the time to report the initial bug.

If you believe that this bug was closed in error, please feel free to reopen
this bug.

Note You need to log in before you can comment on or make changes to this bug.