* oops during scsi scanning disk setup
@ 2009-08-20 18:05 Chris Webb
2009-08-20 20:01 ` Matthew Wilcox
2009-08-20 22:26 ` James Bottomley
0 siblings, 2 replies; 17+ messages in thread
From: Chris Webb @ 2009-08-20 18:05 UTC (permalink / raw)
To: linux-scsi
Hi. I originally sent this report to the open-iscsi list, but Mike Christie
recommended I repost it here as he doesn't think iscsi is the problem.
Originally, I saw an oops very similar to this one following an iscsi login
in Linux 2.6.30.4 x86-64 with async scsi bus scanning turned on. I've now
seen it again a couple of times with CONFIG_SCSI_SCAN_ASYNC turned off. The
machine locks up hard shortly after the oops.
There's a copy of the kernel .config at
http://cdw.me.uk/tmp/linux-2.6.30.4-config.text
and boot dmesg at
http://cdw.me.uk/tmp/linux-2.6.30.4-dmesg.text
if these are useful.
Mike Christie <michaelc@cs.wisc.edu> writes:
> I was thinking you might be hitting a problem in the async code the
> scsi_scan.c/sd.c code use like here:
>
> http://git.kernel.org/?p=linux/kernel/git/torvalds/linux-2.6.git;a=history;f=kernel/async.c;h=27235f5de198997180d4a293adc932d48c6101c7;hb=HEAD
Sorry to follow up again, but I've now seen the same oops with async scsi
scan turned off at compile time in the kernel:
p0# uname -a
Linux f7ea8425-d45b-490f-a738-d181d0df6963.host.elastichosts.com 2.6.30.4-elastic-lon-p #2 SMP PREEMPT Thu Aug 20 14:30:50 BST 2009 x86_64 Intel(R) Xeon(R) CPU E5420 @ 2.50GHz GenuineIntel GNU/Linux
p0# zgrep SCAN_ASYNC /proc/config.gz
# CONFIG_SCSI_SCAN_ASYNC is not set
p0# cat /var/log/kern/2009-08-20
[...]
15:27:10.485 kernel: scsi9 : iSCSI Initiator over TCP/IP
15:27:11.493 kernel: scsi 9:0:0:0: RAID IET Controller 0001 PQ: 0 ANSI: 5
15:27:11.493 kernel: scsi 9:0:0:0: Attached scsi generic sg6 type 12
15:27:11.495 kernel: scsi 9:0:0:1: Direct-Access IET VIRTUAL-DISK 0001 PQ: 0 ANSI: 5
15:27:11.495 kernel: sd 9:0:0:1: Attached scsi generic sg7 type 0
15:27:11.495 kernel: sd 9:0:0:1: [sdg] 4194304 512-byte hardware sectors: (2.14 GB/2.00 GiB)
15:27:11.495 kernel: sd 9:0:0:1: [sdg] Write Protect is off
15:27:11.495 kernel: sd 9:0:0:1: [sdg] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
15:27:13.012 kernel: sdg:<6>scsi 9:0:0:1: [sdg] Unhandled error code
15:27:13.012 kernel: scsi 9:0:0:1: [sdg] Result: hostbyte=0x07 driverbyte=0x00
15:27:13.012 kernel: end_request: I/O error, dev sdg, sector 0
15:27:13.012 kernel: Buffer I/O error on device sdg, logical block 0
15:27:13.012 kernel: ldm_validate_partition_table(): Disk read failed.
15:27:13.012 kernel: unable to read partition table
15:27:13.014 kernel: BUG: unable to handle kernel NULL pointer dereference at 0000000000000010
15:27:13.014 kernel: IP: [<ffffffff803f0d77>] disk_part_iter_next+0x74/0xfd
15:27:13.014 kernel: PGD 82ad0b067 PUD 82cd7e067 PMD 0
15:27:13.014 kernel: Oops: 0000 [#1] PREEMPT SMP
15:27:13.014 kernel: last sysfs file: /sys/devices/platform/host9/session4/iscsi_session/session4/ifacename
15:27:13.014 kernel: CPU 5
15:27:13.014 kernel: Modules linked in:
15:27:13.014 kernel: Pid: 13999, comm: async/0 Not tainted 2.6.30.4-elastic-lon-p #2 X7DBN
15:27:13.014 kernel: RIP: 0010:[<ffffffff803f0d77>] [<ffffffff803f0d77>] disk_part_iter_next+0x74/0xfd
15:27:13.014 kernel: RSP: 0018:ffff88066afa3dd0 EFLAGS: 00010246
15:27:13.014 kernel: RAX: ffff88082b58a000 RBX: ffff88066afa3e00 RCX: 0000000000000000
15:27:13.014 kernel: RDX: 0000000000000000 RSI: ffff88082b58a000 RDI: 0000000000000000
15:27:13.014 kernel: RBP: ffff88066afa3df0 R08: ffff88066afa2000 R09: ffff8806a204f000
15:27:13.014 kernel: R10: 000000fb12c7d274 R11: ffff8806c2bf0628 R12: ffff88066afa3e00
15:27:13.014 kernel: R13: ffff88082c829a00 R14: 0000000000000000 R15: ffff8806bc50c920
15:27:13.014 kernel: FS: 0000000000000000(0000) GS:ffff88002818a000(0000) knlGS:0000000000000000
15:27:13.014 kernel: CS: 0010 DS: 0018 ES: 0018 CR0: 000000008005003b
15:27:13.014 kernel: CR2: 0000000000000010 CR3: 000000082ade3000 CR4: 00000000000426e0
15:27:13.014 kernel: DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
15:27:13.014 kernel: DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
15:27:13.014 kernel: Process async/0 (pid: 13999, threadinfo ffff88066afa2000, task ffff8806c2bf05e0)
15:27:13.014 kernel: Stack:
15:27:13.014 kernel: 0000000000000000 ffff88066afa3e00 ffff88066afa3e00 ffff88082c829a00
15:27:13.014 kernel: ffff88066afa3e40 ffffffff80306feb ffff88082b58a000 0000000000000000
15:27:13.014 kernel: 0000000000000001 ffff8806bc50c920 ffff88066afa3e40 ffff88082b58a000
15:27:13.014 kernel: Call Trace:
15:27:13.014 kernel: [<ffffffff80306feb>] register_disk+0x122/0x13a
15:27:13.014 kernel: [<ffffffff803f0b0f>] add_disk+0xaa/0x106
15:27:13.014 kernel: [<ffffffff80493609>] sd_probe_async+0x198/0x25b
15:27:13.014 kernel: [<ffffffff80270482>] async_thread+0x10c/0x20d
15:27:13.014 kernel: [<ffffffff802545ff>] ? default_wake_function+0x0/0xf
15:27:13.014 kernel: [<ffffffff80270376>] ? async_thread+0x0/0x20d
15:27:13.014 kernel: [<ffffffff8026ad89>] kthread+0x55/0x80
15:27:13.014 kernel: [<ffffffff8022be6a>] child_rip+0xa/0x20
15:27:13.014 kernel: [<ffffffff8026ad34>] ? kthread+0x0/0x80
15:27:13.014 kernel: [<ffffffff8022be60>] ? child_rip+0x0/0x20
15:27:13.014 kernel: Code: c8 ff 80 e1 0c b9 00 00 00 00 0f 44 c1 41 83 cd ff 48 8d 7a 20 48 be ff ff ff ff 08 00 00 00 48 b9 00 00 00 00 08 00 00 00 eb 50 <8b> 42 10 41 bd 01 00 00 00 eb db 4c 63 c2 4e 8d 04 c7 4d 8b 20
15:27:13.015 kernel: RIP [<ffffffff803f0d77>] disk_part_iter_next+0x74/0xfd
15:27:13.015 kernel: RSP <ffff88066afa3dd0>
15:27:13.015 kernel: CR2: 0000000000000010
15:27:13.015 kernel: ---[ end trace 6104b56ef5590e25 ]---
15:27:13.015 kernel: note: async/0[13999] exited with preempt_count 1
15:27:13.064 kernel: device-mapper: ioctl: device doesn't appear to be in the dev hash table.
15:27:13.115 kernel: device-mapper: ioctl: device doesn't appear to be in the dev hash table.
15:34:52.618 kernel: device tap1 entered promiscuous mode
15:34:52.621 kernel: br0: port 8(tap1) entering forwarding state
15:39:12.560 kernel: scsi10 : iSCSI Initiator over TCP/IP
15:39:13.568 kernel: scsi 10:0:0:0: RAID IET Controller 0001 PQ: 0 ANSI: 5
15:39:13.568 kernel: scsi 10:0:0:0: Attached scsi generic sg6 type 12
15:39:13.569 kernel: scsi 10:0:0:1: Direct-Access IET VIRTUAL-DISK 0001 PQ: 0 ANSI: 5
15:39:13.572 kernel: general protection fault: 0000 [#2] PREEMPT SMP
15:39:13.572 kernel: last sysfs file: /sys/devices/platform/host10/scsi_host/host10/scan
15:39:13.572 kernel: CPU 5
15:39:13.572 kernel: Modules linked in:
15:39:13.572 kernel: Pid: 16876, comm: iscsid Tainted: G D 2.6.30.4-elastic-lon-p #2 X7DBN
15:39:13.572 kernel: RIP: 0010:[<ffffffff8024b6ce>] [<ffffffff8024b6ce>] __wake_up_common+0x46/0x7f
15:39:13.572 kernel: RSP: 0018:ffff8802580bd848 EFLAGS: 00010006
15:39:13.572 kernel: RAX: ffff88066afa3ed0 RBX: 0000000000000001 RCX: 0000000000000000
15:39:13.572 kernel: RDX: 0000000000000000 RSI: 0000000000000003 RDI: ffff88066afa3ed0
15:39:13.572 kernel: RBP: ffff8802580bd888 R08: 0000000000000000 R09: ffff88082b9c4d88
15:39:13.572 kernel: R10: 0000000000000abc R11: 00000000000002af R12: 0000000000000003
15:39:13.572 kernel: R13: ea164bc9f170a707 R14: 000000003f771c34 R15: 0000000000000000
15:39:13.572 kernel: FS: 00007f99209626f0(0000) GS:ffff88002818a000(0000) knlGS:0000000000000000
15:39:13.572 kernel: CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
15:39:13.572 kernel: CR2: 0000000002aced78 CR3: 00000005c6a7d000 CR4: 00000000000426e0
15:39:13.572 kernel: DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
15:39:13.572 kernel: DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
15:39:13.572 kernel: Process iscsid (pid: 16876, threadinfo ffff8802580bc000, task ffff8806c2bf1780)
15:39:13.572 kernel: Stack:
15:39:13.572 kernel: 0000000000000000 ffffffff80835c38 ffff8802580bd888 ffffffff80835c30
15:39:13.572 kernel: 0000000000000282 ffff88082b5d7000 0000000000000011 ffffffff80835c80
15:39:13.572 kernel: ffff8802580bd8c8 ffffffff8024c06c 00000000000080d0 0000000000000000
15:39:13.572 kernel: Call Trace:
15:39:13.572 kernel: [<ffffffff8024c06c>] __wake_up+0x34/0x48
15:39:13.572 kernel: [<ffffffff80493471>] ? sd_probe_async+0x0/0x25b
15:39:13.572 kernel: [<ffffffff802708cb>] __async_schedule+0x17e/0x190
15:39:13.572 kernel: [<ffffffff802708f8>] async_schedule+0x10/0x14
15:39:13.572 kernel: [<ffffffff80493d4a>] sd_probe+0x1bd/0x213
15:39:13.572 kernel: [<ffffffff80473a1e>] driver_probe_device+0x9a/0x11f
15:39:13.572 kernel: [<ffffffff80473b54>] __device_attach+0x35/0x3a
15:39:13.572 kernel: [<ffffffff80473b1f>] ? __device_attach+0x0/0x3a
15:39:13.572 kernel: [<ffffffff80472fd4>] bus_for_each_drv+0x51/0x88
15:39:13.572 kernel: [<ffffffff80473be1>] device_attach+0x5e/0x75
15:39:13.572 kernel: [<ffffffff80472e3c>] bus_attach_device+0x26/0x58
15:39:13.572 kernel: [<ffffffff80471a5d>] device_add+0x3ff/0x562
15:39:13.572 kernel: [<ffffffff80485104>] scsi_sysfs_add_sdev+0xb5/0x252
15:39:13.572 kernel: [<ffffffff80482f72>] scsi_probe_and_add_lun+0x910/0xa32
15:39:13.572 kernel: [<ffffffff8048363c>] __scsi_scan_target+0x3a5/0x542
15:39:13.572 kernel: [<ffffffff8029e08d>] ? zone_statistics+0x60/0x65
15:39:13.572 kernel: [<ffffffff80293369>] ? get_page_from_freelist+0x4ad/0x67a
15:39:13.572 kernel: [<ffffffff80483dce>] scsi_scan_target+0x97/0xae
15:39:13.572 kernel: [<ffffffff80487c3b>] iscsi_user_scan_session+0xcd/0xe4
15:39:13.572 kernel: [<ffffffff80487b6e>] ? iscsi_user_scan_session+0x0/0xe4
15:39:13.572 kernel: [<ffffffff80470f95>] device_for_each_child+0x35/0x6c
15:39:13.572 kernel: [<ffffffff80487b53>] iscsi_user_scan+0x28/0x2a
15:39:13.572 kernel: [<ffffffff8048471c>] store_scan+0x9b/0xc6
15:39:13.573 kernel: [<ffffffff80470765>] dev_attr_store+0x1b/0x1d
15:39:13.573 kernel: [<ffffffff8030b61d>] sysfs_write_file+0xf2/0x12e
15:39:13.573 kernel: [<ffffffff802c1711>] vfs_write+0xad/0x129
15:39:13.573 kernel: [<ffffffff802c1846>] sys_write+0x45/0x6c
15:39:13.573 kernel: [<ffffffff8022aeeb>] system_call_fastpath+0x16/0x1b
15:39:13.573 kernel: Code: 47 08 48 83 c7 08 48 83 e8 18 4c 8b 68 18 48 89 7d c8 49 83 ed 18 eb 33 44 8b 30 4c 89 c1 4c 89 45 c0 44 89 fa 44 89 e6 48 89 c7 <ff> 50 10 4c 8b 45 c0 85 c0 74 0a 41 80 e6 01 74 04 ff cb 74 15
15:39:13.573 kernel: RIP [<ffffffff8024b6ce>] __wake_up_common+0x46/0x7f
15:39:13.573 kernel: RSP <ffff8802580bd848>
15:39:13.573 kernel: ---[ end trace 6104b56ef5590e26 ]---
15:39:13.573 kernel: note: iscsid[16876] exited with preempt_count 1
15:39:13.573 kernel: BUG: scheduling while atomic: iscsid/16876/0x10000002
15:39:13.573 kernel: Modules linked in:
15:39:13.573 kernel: Pid: 16876, comm: iscsid Tainted: G D 2.6.30.4-elastic-lon-p #2
15:39:13.573 kernel: Call Trace:
15:39:13.573 kernel: [<ffffffff80250e32>] __schedule_bug+0x57/0x5c
15:39:13.573 kernel: [<ffffffff806645b9>] __schedule+0xc1/0x814
15:39:13.573 kernel: [<ffffffff803ff025>] ? number+0x12f/0x225
15:39:13.573 kernel: [<ffffffff8026ef79>] ? __atomic_notifier_call_chain+0x20/0x4e
15:39:13.573 kernel: [<ffffffff80664dec>] schedule+0x18/0x3b
15:39:13.573 kernel: [<ffffffff80250f33>] __cond_resched+0x1c/0x45
15:39:13.573 kernel: [<ffffffff80664ec2>] _cond_resched+0x30/0x3b
15:39:13.573 kernel: [<ffffffff802a17b2>] unmap_vmas+0x6cd/0x886
15:39:13.573 kernel: [<ffffffff802a5db3>] exit_mmap+0xd4/0x184
15:39:13.573 kernel: [<ffffffff80255c6b>] mmput+0x2b/0xb4
15:39:13.573 kernel: [<ffffffff80259524>] exit_mm+0xff/0x10a
15:39:13.574 kernel: [<ffffffff8025ae2c>] do_exit+0x17a/0x695
15:39:13.574 kernel: [<ffffffff8022ea59>] oops_end+0x89/0x8e
15:39:13.574 kernel: [<ffffffff8022ec1c>] die+0x55/0x5e
15:39:13.574 kernel: [<ffffffff8022ccaa>] do_general_protection+0x123/0x12b
15:39:13.574 kernel: [<ffffffff806670cf>] general_protection+0x1f/0x30
15:39:13.574 kernel: [<ffffffff8024b6ce>] ? __wake_up_common+0x46/0x7f
15:39:13.574 kernel: [<ffffffff8024c06c>] __wake_up+0x34/0x48
15:39:13.574 kernel: [<ffffffff80493471>] ? sd_probe_async+0x0/0x25b
15:39:13.574 kernel: [<ffffffff802708cb>] __async_schedule+0x17e/0x190
15:39:13.574 kernel: [<ffffffff802708f8>] async_schedule+0x10/0x14
15:39:13.574 kernel: [<ffffffff80493d4a>] sd_probe+0x1bd/0x213
15:39:13.574 kernel: [<ffffffff80473a1e>] driver_probe_device+0x9a/0x11f
15:39:13.575 kernel: [<ffffffff80473b54>] __device_attach+0x35/0x3a
15:39:13.575 kernel: [<ffffffff80473b1f>] ? __device_attach+0x0/0x3a
15:39:13.575 kernel: [<ffffffff80472fd4>] bus_for_each_drv+0x51/0x88
15:39:13.575 kernel: [<ffffffff80473be1>] device_attach+0x5e/0x75
15:39:13.575 kernel: [<ffffffff80472e3c>] bus_attach_device+0x26/0x58
15:39:13.575 kernel: [<ffffffff80471a5d>] device_add+0x3ff/0x562
15:39:13.575 kernel: [<ffffffff80485104>] scsi_sysfs_add_sdev+0xb5/0x252
15:39:13.575 kernel: [<ffffffff80482f72>] scsi_probe_and_add_lun+0x910/0xa32
15:39:13.575 kernel: [<ffffffff8048363c>] __scsi_scan_target+0x3a5/0x542
15:39:13.575 kernel: [<ffffffff8029e08d>] ? zone_statistics+0x60/0x65
15:39:13.575 kernel: [<ffffffff80293369>] ? get_page_from_freelist+0x4ad/0x67a
15:39:13.575 kernel: [<ffffffff80483dce>] scsi_scan_target+0x97/0xae
15:39:13.575 kernel: [<ffffffff80487c3b>] iscsi_user_scan_session+0xcd/0xe4
15:39:13.575 kernel: [<ffffffff80487b6e>] ? iscsi_user_scan_session+0x0/0xe4
15:39:13.575 kernel: [<ffffffff80470f95>] device_for_each_child+0x35/0x6c
15:39:13.575 kernel: [<ffffffff80487b53>] iscsi_user_scan+0x28/0x2a
15:39:13.575 kernel: [<ffffffff8048471c>] store_scan+0x9b/0xc6
15:39:13.575 kernel: [<ffffffff80470765>] dev_attr_store+0x1b/0x1d
15:39:13.575 kernel: [<ffffffff8030b61d>] sysfs_write_file+0xf2/0x12e
15:39:13.575 kernel: [<ffffffff802c1711>] vfs_write+0xad/0x129
15:39:13.575 kernel: [<ffffffff802c1846>] sys_write+0x45/0x6c
15:39:13.575 kernel: [<ffffffff8022aeeb>] system_call_fastpath+0x16/0x1b
15:39:13.643 kernel: device-mapper: ioctl: device doesn't appear to be in the dev hash table.
[...]
iscsid crashed following this, and the machine locked up hard (no longer
even responding to ping) shortly afterwards.
I'm not quite clear how I can be in sd_probe_async when asynchronous bus
scanning is compiled out completely, but perhaps I'm misunderstanding how
this function is used.
The common factor between this incident and the last couple of crashes we've
seen is that the iSCSI target was under a bit of load in each case (RAID
resyncing here) and logins were therefore a bit slower than they'd normally
be. This might be evidence for some sort of race?
Best wishes,
Chris.
^ permalink raw reply [flat|nested] 17+ messages in thread* Re: oops during scsi scanning disk setup 2009-08-20 18:05 oops during scsi scanning disk setup Chris Webb @ 2009-08-20 20:01 ` Matthew Wilcox 2009-08-20 20:10 ` Yinghai Lu 2009-08-20 22:26 ` James Bottomley 1 sibling, 1 reply; 17+ messages in thread From: Matthew Wilcox @ 2009-08-20 20:01 UTC (permalink / raw) To: Chris Webb; +Cc: linux-scsi, Arjan van de Ven On Thu, Aug 20, 2009 at 07:05:49PM +0100, Chris Webb wrote: > in Linux 2.6.30.4 x86-64 with async scsi bus scanning turned on. I've now > seen it again a couple of times with CONFIG_SCSI_SCAN_ASYNC turned off. The > machine locks up hard shortly after the oops. ^^^ that option > I'm not quite clear how I can be in sd_probe_async when asynchronous bus > scanning is compiled out completely, but perhaps I'm misunderstanding how > this function is used. ^^^ has nothing to do with sd_probe_async. I wrote the code covered by the former, and it's really annoying me that people keep reporting it as buggy, when it's actually the code in kernel/async.c that's buggy. -- Matthew Wilcox Intel Open Source Technology Centre "Bill, look, we understand that you're interested in selling us this operating system, but compare it to ours. We can't possibly take such a retrograde step." ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: oops during scsi scanning disk setup 2009-08-20 20:01 ` Matthew Wilcox @ 2009-08-20 20:10 ` Yinghai Lu 2009-08-21 4:26 ` Arjan van de Ven 0 siblings, 1 reply; 17+ messages in thread From: Yinghai Lu @ 2009-08-20 20:10 UTC (permalink / raw) To: Matthew Wilcox, Jeff Garzik, Ingo Molnar Cc: Chris Webb, linux-scsi, Arjan van de Ven On Thu, Aug 20, 2009 at 1:01 PM, Matthew Wilcox<matthew@wil.cx> wrote: > On Thu, Aug 20, 2009 at 07:05:49PM +0100, Chris Webb wrote: >> in Linux 2.6.30.4 x86-64 with async scsi bus scanning turned on. I've now >> seen it again a couple of times with CONFIG_SCSI_SCAN_ASYNC turned off. The >> machine locks up hard shortly after the oops. > > ^^^ that option > >> I'm not quite clear how I can be in sd_probe_async when asynchronous bus >> scanning is compiled out completely, but perhaps I'm misunderstanding how >> this function is used. > > ^^^ has nothing to do with sd_probe_async. > > I wrote the code covered by the former, and it's really annoying me > that people keep reporting it as buggy, when it's actually the code in > kernel/async.c that's buggy. anyway to disable that? should have something like fastboot=off or nofastboot YH ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: oops during scsi scanning disk setup 2009-08-20 20:10 ` Yinghai Lu @ 2009-08-21 4:26 ` Arjan van de Ven 0 siblings, 0 replies; 17+ messages in thread From: Arjan van de Ven @ 2009-08-21 4:26 UTC (permalink / raw) To: Yinghai Lu Cc: Matthew Wilcox, Jeff Garzik, Ingo Molnar, Chris Webb, linux-scsi On Thu, 20 Aug 2009 13:10:51 -0700 Yinghai Lu <yhlu.kernel@gmail.com> wrote: > On Thu, Aug 20, 2009 at 1:01 PM, Matthew Wilcox<matthew@wil.cx> wrote: > > On Thu, Aug 20, 2009 at 07:05:49PM +0100, Chris Webb wrote: > >> in Linux 2.6.30.4 x86-64 with async scsi bus scanning turned on. > >> I've now seen it again a couple of times with > >> CONFIG_SCSI_SCAN_ASYNC turned off. The machine locks up hard > >> shortly after the oops. > > > > ^^^ that option > > > >> I'm not quite clear how I can be in sd_probe_async when > >> asynchronous bus scanning is compiled out completely, but perhaps > >> I'm misunderstanding how this function is used. > > > > ^^^ has nothing to do with sd_probe_async. > > > > I wrote the code covered by the former, and it's really annoying me > > that people keep reporting it as buggy, when it's actually the code > > in kernel/async.c that's buggy. > > anyway to disable that? should have something like fastboot=off or > nofastboot async is not (just) about boot, and it's really not optional. what exactly are you seeing? ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: oops during scsi scanning disk setup 2009-08-20 18:05 oops during scsi scanning disk setup Chris Webb 2009-08-20 20:01 ` Matthew Wilcox @ 2009-08-20 22:26 ` James Bottomley 2009-08-21 8:16 ` Chris Webb 1 sibling, 1 reply; 17+ messages in thread From: James Bottomley @ 2009-08-20 22:26 UTC (permalink / raw) To: Chris Webb; +Cc: linux-scsi On Thu, 2009-08-20 at 19:05 +0100, Chris Webb wrote: > 15:27:13.014 kernel: IP: [<ffffffff803f0d77>] disk_part_iter_next+0x74/0xfd Have to confess, no idea how this happened. Especially since the system must have gone through the disk iterator once before successfully. Can you use addr2line or gdb to get where this occurred? Thanks, James ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: oops during scsi scanning disk setup 2009-08-20 22:26 ` James Bottomley @ 2009-08-21 8:16 ` Chris Webb 2009-08-21 8:33 ` Chris Webb 0 siblings, 1 reply; 17+ messages in thread From: Chris Webb @ 2009-08-21 8:16 UTC (permalink / raw) To: James Bottomley; +Cc: linux-scsi James Bottomley <James.Bottomley@suse.de> writes: > On Thu, 2009-08-20 at 19:05 +0100, Chris Webb wrote: > > 15:27:13.014 kernel: IP: [<ffffffff803f0d77>] disk_part_iter_next+0x74/0xfd > > Have to confess, no idea how this happened. Especially since the system > must have gone through the disk iterator once before successfully. > > Can you use addr2line or gdb to get where this occurred? Hi James. I'm having a bit of trouble getting this to work, although I can disassemble the function fine. # addr2line -e vmlinux 0xffffffff803f0d77 ??:0 # gdb vmlinux GNU gdb 6.8 Copyright (C) 2008 Free Software Foundation, Inc. License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html> This is free software: you are free to change and redistribute it. There is NO WARRANTY, to the extent permitted by law. Type "show copying" and "show warranty" for details. This GDB was configured as "x86_64-arachsys-linux-gnu"... (no debugging symbols found) (gdb) info line *0xffffffff803f0d77 No line number information available for address 0xffffffff803f0d77 <disk_part_iter_next+116> (gdb) disas disk_part_iter_next Dump of assembler code for function disk_part_iter_next: 0xffffffff803f0d03 <disk_part_iter_next+0>: push %rbp 0xffffffff803f0d04 <disk_part_iter_next+1>: mov %rsp,%rbp 0xffffffff803f0d07 <disk_part_iter_next+4>: push %r13 0xffffffff803f0d09 <disk_part_iter_next+6>: push %r12 0xffffffff803f0d0b <disk_part_iter_next+8>: push %rbx 0xffffffff803f0d0c <disk_part_iter_next+9>: mov %rdi,%rbx 0xffffffff803f0d0f <disk_part_iter_next+12>: sub $0x8,%rsp 0xffffffff803f0d13 <disk_part_iter_next+16>: mov 0x8(%rdi),%rdi 0xffffffff803f0d17 <disk_part_iter_next+20>: test %rdi,%rdi 0xffffffff803f0d1a <disk_part_iter_next+23>: je 0xffffffff803f0d25 <disk_part_iter_next+34> 0xffffffff803f0d1c <disk_part_iter_next+25>: add $0x10,%rdi 0xffffffff803f0d20 <disk_part_iter_next+29>: callq 0xffffffff8047088a <put_device> 0xffffffff803f0d25 <disk_part_iter_next+34>: movq $0x0,0x8(%rbx) 0xffffffff803f0d2d <disk_part_iter_next+42>: mov %gs:0xb4e8,%rax 0xffffffff803f0d36 <disk_part_iter_next+51>: incl -0x1fbc(%rax) 0xffffffff803f0d3c <disk_part_iter_next+57>: mov (%rbx),%rax 0xffffffff803f0d3f <disk_part_iter_next+60>: mov 0x14(%rbx),%ecx 0xffffffff803f0d42 <disk_part_iter_next+63>: mov 0x30(%rax),%rdx 0xffffffff803f0d46 <disk_part_iter_next+67>: test $0x1,%cl 0xffffffff803f0d49 <disk_part_iter_next+70>: je 0xffffffff803f0d77 <disk_part_iter_next+116> 0xffffffff803f0d4b <disk_part_iter_next+72>: or $0xffffffffffffffff,%eax 0xffffffff803f0d4e <disk_part_iter_next+75>: and $0xc,%cl 0xffffffff803f0d51 <disk_part_iter_next+78>: mov $0x0,%ecx 0xffffffff803f0d56 <disk_part_iter_next+83>: cmove %ecx,%eax 0xffffffff803f0d59 <disk_part_iter_next+86>: or $0xffffffffffffffff,%r13d 0xffffffff803f0d5d <disk_part_iter_next+90>: lea 0x20(%rdx),%rdi 0xffffffff803f0d61 <disk_part_iter_next+94>: mov $0x8ffffffff,%rsi 0xffffffff803f0d6b <disk_part_iter_next+104>: mov $0x800000000,%rcx 0xffffffff803f0d75 <disk_part_iter_next+114>: jmp 0xffffffff803f0dc7 <disk_part_iter_next+196> 0xffffffff803f0d77 <disk_part_iter_next+116>: mov 0x10(%rdx),%eax 0xffffffff803f0d7a <disk_part_iter_next+119>: mov $0x1,%r13d 0xffffffff803f0d80 <disk_part_iter_next+125>: jmp 0xffffffff803f0d5d <disk_part_iter_next+90> 0xffffffff803f0d82 <disk_part_iter_next+127>: movslq %edx,%r8 0xffffffff803f0d85 <disk_part_iter_next+130>: lea (%rdi,%r8,8),%r8 0xffffffff803f0d89 <disk_part_iter_next+134>: mov (%r8),%r12 0xffffffff803f0d8c <disk_part_iter_next+137>: test %r12,%r12 0xffffffff803f0d8f <disk_part_iter_next+140>: je 0xffffffff803f0dbf <disk_part_iter_next+188> [...] I'm sure I've seen addr2line and gdb info line work fine like this in the past, but there definitely doesn't seem to be debugging info present in my vmlinux now. Am I doing something stupid, or is there something special I need to do to get debugging symbols turned on? (And if I do this and recompile in a copy of the tree, will I still get a valid mapping from the address disk_part_iter_next+116 to a line number for you?) Best wishes, Chris. ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: oops during scsi scanning disk setup 2009-08-21 8:16 ` Chris Webb @ 2009-08-21 8:33 ` Chris Webb 2009-08-21 9:23 ` Chris Webb 0 siblings, 1 reply; 17+ messages in thread From: Chris Webb @ 2009-08-21 8:33 UTC (permalink / raw) To: James Bottomley; +Cc: linux-scsi Chris Webb <chris@arachsys.com> writes: > Hi James. I'm having a bit of trouble getting this to work, although I can > disassemble the function fine. [...] > 0xffffffff803f0d77 <disk_part_iter_next+116>: mov 0x10(%rdx),%eax [...] Reading through the disassembled code and comparing by hand against disk_part_iter_next(), I think that might be line 144 of block/genhd.c, where the ptbl->len dereference happens. Best wishes, Chris. ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: oops during scsi scanning disk setup 2009-08-21 8:33 ` Chris Webb @ 2009-08-21 9:23 ` Chris Webb 2009-08-21 14:00 ` James Bottomley 0 siblings, 1 reply; 17+ messages in thread From: Chris Webb @ 2009-08-21 9:23 UTC (permalink / raw) To: James Bottomley; +Cc: linux-scsi Chris Webb <chris@arachsys.com> writes: > Reading through the disassembled code and comparing by hand against > disk_part_iter_next(), I think that might be line 144 of block/genhd.c, > where the ptbl->len dereference happens. Sorry to follow up a third time, but I can now confirm this. I slipped -g into CFLAGS in the kernel Makefile and rebuilt genhd.o and then the entire vmlinux. # objdump -S genhd.o [...] 0000000000000da3 <disk_part_iter_next>: * * CONTEXT: * Don't care. */ struct hd_struct *disk_part_iter_next(struct disk_part_iter *piter) { da3: 55 push %rbp da4: 48 89 e5 mov %rsp,%rbp da7: 41 55 push %r13 da9: 41 54 push %r12 dab: 53 push %rbx dac: 48 89 fb mov %rdi,%rbx daf: 48 83 ec 08 sub $0x8,%rsp struct disk_part_tbl *ptbl; int inc, end; /* put the last partition */ disk_put_part(piter->part); db3: 48 8b 7f 08 mov 0x8(%rdi),%rdi [...] e01: 48 be ff ff ff ff 08 mov $0x8ffffffff,%rsi e08: 00 00 00 e0b: 48 b9 00 00 00 00 08 mov $0x800000000,%rcx e12: 00 00 00 e15: eb 50 jmp e67 <disk_part_iter_next+0xc4> end = -1; else end = 0; } else { inc = 1; end = ptbl->len; e17: 8b 42 10 mov 0x10(%rdx),%eax e1a: 41 bd 01 00 00 00 mov $0x1,%r13d e20: eb db jmp dfd <disk_part_iter_next+0x5a> [...] # addr2line -e vmlinux 0xffffffff803f0d77 /tmp/linux-2.6.30.4-p.tmp/block/genhd.c:144 Cheers, Chris, ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: oops during scsi scanning disk setup 2009-08-21 9:23 ` Chris Webb @ 2009-08-21 14:00 ` James Bottomley 2009-08-21 14:51 ` Chris Webb 0 siblings, 1 reply; 17+ messages in thread From: James Bottomley @ 2009-08-21 14:00 UTC (permalink / raw) To: Chris Webb; +Cc: linux-scsi On Fri, 2009-08-21 at 10:23 +0100, Chris Webb wrote: > Chris Webb <chris@arachsys.com> writes: > > > Reading through the disassembled code and comparing by hand against > > disk_part_iter_next(), I think that might be line 144 of block/genhd.c, > > where the ptbl->len dereference happens. > > Sorry to follow up a third time, but I can now confirm this. I slipped -g into > CFLAGS in the kernel Makefile and rebuilt genhd.o and then the entire vmlinux. I suppose it makes sense: That was the only dereference at offset 16 I could find in the code. The thing which doesn't quite make sense is that disk_part_iter_init() also dereferences the same pointer successfully ... I suppose this could be a race with another thread to null out the gendisk part_tbl ... I'll have to think about it some more. Thanks for the detective work, James ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: oops during scsi scanning disk setup 2009-08-21 14:00 ` James Bottomley @ 2009-08-21 14:51 ` Chris Webb 2009-08-21 15:47 ` James Bottomley 0 siblings, 1 reply; 17+ messages in thread From: Chris Webb @ 2009-08-21 14:51 UTC (permalink / raw) To: James Bottomley; +Cc: linux-scsi James Bottomley <James.Bottomley@suse.de> writes: > On Fri, 2009-08-21 at 10:23 +0100, Chris Webb wrote: > > > Sorry to follow up a third time, but I can now confirm this. I slipped -g into > > CFLAGS in the kernel Makefile and rebuilt genhd.o and then the entire vmlinux. > > I suppose it makes sense: That was the only dereference at offset 16 I > could find in the code. The thing which doesn't quite make sense is > that disk_part_iter_init() also dereferences the same pointer > successfully ... I suppose this could be a race with another thread to > null out the gendisk part_tbl ... I'll have to think about it some more. Thanks! If it helps, I've only ever seen it following an iscsi login to a target machine which is heavy loaded (e.g. RAID resync in this case), presumably meaning that everything (including disk reads) happens a bit slowly. Perhaps this increases the window for a race in some way? I've spent some time over the past week trying to reproduce it in a VM with magic sysrq enabled so I could find out a bit more, but it subbornly refuses to happen except on machines in a busy production cluster. Here are some more crashes we've seen which look extremely similar, but don't all directly involve disk_part_iter_next: 20:15:29.272 kernel: scsi2 : iSCSI Initiator over TCP/IP 20:15:30.278 kernel: scsi 2:0:0:0: RAID IET Controller 0001 PQ: 0 ANSI: 5 20:15:30.279 kernel: scsi 2:0:0:0: Attached scsi generic sg4 type 12 20:15:30.280 kernel: scsi 2:0:0:1: Direct-Access IET VIRTUAL-DISK 0001 PQ: 0 ANSI: 5 20:15:30.281 kernel: sd 2:0:0:1: Attached scsi generic sg5 type 0 20:15:30.281 kernel: sd 2:0:0:1: [sde] 1957888 512-byte hardware sectors: (1.00 GB/956 MiB) 20:15:30.281 kernel: sd 2:0:0:1: [sde] Write Protect is off 20:15:30.281 kernel: sd 2:0:0:1: [sde] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA 20:15:30.334 kernel: sde:<4>device-mapper: ioctl: device doesn't appear to be in the dev hash table. 20:15:30.842 kernel: scsi 2:0:0:1: [sde] Unhandled error code 20:15:30.842 kernel: scsi 2:0:0:1: [sde] Result: hostbyte=0x07 driverbyte=0x00 20:15:30.842 kernel: end_request: I/O error, dev sde, sector 0 20:15:30.842 kernel: Buffer I/O error on device sde, logical block 0 20:15:30.842 kernel: ldm_validate_partition_table(): Disk read failed. 20:15:30.842 kernel: unable to read partition table 20:15:30.844 kernel: BUG: unable to handle kernel NULL pointer dereference at 0000000000000010 20:15:30.844 kernel: IP: [<ffffffff803f0cf7>] disk_part_iter_next+0x74/0xfd 20:15:30.844 kernel: PGD 82cdff067 PUD 82cd52067 PMD 0 20:15:30.844 kernel: Oops: 0000 [#1] PREEMPT SMP 20:15:30.844 kernel: last sysfs file: /sys/devices/platform/host2/session1/iscsi_session/session1/ifacename 20:15:30.844 kernel: CPU 2 20:15:30.844 kernel: Modules linked in: 20:15:30.844 kernel: Pid: 1546, comm: async/0 Not tainted 2.6.30.3-elastic-lon-p #2 X7DBN 20:15:30.844 kernel: RIP: 0010:[<ffffffff803f0cf7>] [<ffffffff803f0cf7>] disk_part_iter_next+0x74/0xfd 20:15:30.844 kernel: RSP: 0018:ffff8808285e1dd0 EFLAGS: 00010246 20:15:30.844 kernel: RAX: ffff88082b664800 RBX: ffff8808285e1e00 RCX: 0000000000000000 20:15:30.844 kernel: RDX: 0000000000000000 RSI: ffff88082b664800 RDI: 0000000000000000 20:15:30.844 kernel: RBP: ffff8808285e1df0 R08: ffff8808285e0000 R09: ffff8808285c3000 20:15:30.844 kernel: R10: 0000000021cd6417 R11: ffff88082cd2bd80 R12: ffff8808285e1e00 20:15:30.844 kernel: R13: ffff88082c970340 R14: 0000000000000000 R15: ffff88082ae10120 20:15:30.844 kernel: FS: 0000000000000000(0000) GS:ffff88002813c000(0000) knlGS:0000000000000000 20:15:30.844 kernel: CS: 0010 DS: 0018 ES: 0018 CR0: 000000008005003b 20:15:30.844 kernel: CR2: 0000000000000010 CR3: 000000082cd77000 CR4: 00000000000426e0 20:15:30.844 kernel: DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 20:15:30.844 kernel: DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400 20:15:30.844 kernel: Process async/0 (pid: 1546, threadinfo ffff8808285e0000, task ffff88082af58bc0) 20:15:30.844 kernel: Stack: 20:15:30.844 kernel: 0000000000000000 ffff8808285e1e00 ffff8808285e1e00 ffff88082c970340 20:15:30.844 kernel: ffff8808285e1e40 ffffffff80306f5f ffff88082b664800 0000000000000000 20:15:30.844 kernel: 0000000000000001 ffff88082ae10120 ffff8808285e1e40 ffff88082b664800 20:15:30.844 kernel: Call Trace: 20:15:30.844 kernel: [<ffffffff80306f5f>] register_disk+0x122/0x13a 20:15:30.844 kernel: [<ffffffff803f0a8f>] add_disk+0xaa/0x106 20:15:30.844 kernel: [<ffffffff80493581>] sd_probe_async+0x198/0x25b 20:15:30.844 kernel: [<ffffffff8027046e>] async_thread+0x10c/0x20d 20:15:30.844 kernel: [<ffffffff802545ec>] ? default_wake_function+0x0/0xf 20:15:30.844 kernel: [<ffffffff80270362>] ? async_thread+0x0/0x20d 20:15:30.844 kernel: [<ffffffff8026ad75>] kthread+0x55/0x80 20:15:30.844 kernel: [<ffffffff8022be6a>] child_rip+0xa/0x20 20:15:30.844 kernel: [<ffffffff8026ad20>] ? kthread+0x0/0x80 20:15:30.844 kernel: [<ffffffff8022be60>] ? child_rip+0x0/0x20 20:15:30.844 kernel: Code: c8 ff 80 e1 0c b9 00 00 00 00 0f 44 c1 41 83 cd ff 48 8d 7a 20 48 be ff ff ff ff 08 00 00 00 48 b9 00 00 00 00 08 00 00 00 eb 50 <8b> 42 10 41 bd 01 00 00 00 eb db 4c 63 c2 4e 8d 04 c7 4d 8b 20 20:15:30.844 kernel: RIP [<ffffffff803f0cf7>] disk_part_iter_next+0x74/0xfd 20:15:30.844 kernel: RSP <ffff8808285e1dd0> 20:15:30.844 kernel: CR2: 0000000000000010 20:15:30.844 kernel: ---[ end trace 0c87b5734489633f ]--- 20:15:30.844 kernel: note: async/0[1546] exited with preempt_count 1 [...] 20:16:32.450 kernel: scsi3 : iSCSI Initiator over TCP/IP 20:16:33.456 kernel: scsi 3:0:0:0: RAID IET Controller 0001 PQ: 0 ANSI: 5 20:16:33.456 kernel: scsi 3:0:0:0: Attached scsi generic sg4 type 12 20:16:33.457 kernel: scsi 3:0:0:1: Direct-Access IET VIRTUAL-DISK 0001 PQ: 0 ANSI: 5 20:16:33.465 kernel: ------------[ cut here ]------------ 20:16:33.465 kernel: kernel BUG at kernel/exit.c:1014! 20:16:33.465 kernel: invalid opcode: 0000 [#2] PREEMPT SMP 20:16:33.465 kernel: last sysfs file: /sys/devices/platform/host3/scsi_host/host3/scan 20:16:33.465 kernel: CPU 0 20:16:33.465 kernel: Modules linked in: 20:16:33.465 kernel: Pid: 1733, comm: iscsid Tainted: G D 2.6.30.3-elastic-lon-p #2 X7DBN 20:16:33.465 kernel: RIP: 0010:[<ffffffff8025b324>] [<ffffffff8025b324>] do_exit+0x686/0x695 20:16:33.465 kernel: RSP: 0018:ffff88082cd79840 EFLAGS: 00010006 20:16:33.465 kernel: RAX: ffff8808285e1ed0 RBX: 0000000000000001 RCX: 0000000000000000 20:16:33.465 kernel: RDX: 0000000000000000 RSI: 0000000000000003 RDI: ffff8808285e1ed0 20:16:33.465 kernel: RBP: ffff88082cd79888 R08: 0000000000000000 R09: ffff88082b9ab208 20:16:33.465 kernel: R10: 00000000000002bc R11: 00000000000000af R12: 0000000000000003 20:16:33.465 kernel: R13: ffff88082ae71340 R14: 0000000080664c7c R15: 0000000000000000 20:16:33.465 kernel: FS: 00007fe7c45ff6f0(0000) GS:ffff880028108000(0000) knlGS:0000000000000000 20:16:33.465 kernel: CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 20:16:33.465 kernel: CR2: 0000000000f893c8 CR3: 0000000828441000 CR4: 00000000000426e0 20:16:33.465 kernel: DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 20:16:33.465 kernel: DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400 20:16:33.465 kernel: Process iscsid (pid: 1733, threadinfo ffff88082cd78000, task ffff88082b551d60) 20:16:33.465 kernel: Stack: 20:16:33.465 kernel: ffffffff8024b6f1 0000000000000000 ffffffff80835c38 ffff88082cd79888 20:16:33.465 kernel: ffffffff80835c30 0000000000000282 ffff88082b66f600 0000000000000008 20:16:33.465 kernel: ffffffff80835c80 ffff88082cd798c8 ffffffff8024c08c 00000000000080d0 20:16:33.465 kernel: Call Trace: 20:16:33.465 kernel: [<ffffffff8024b6f1>] ? __wake_up_common+0x49/0x7f 20:16:33.465 kernel: [<ffffffff8024c08c>] __wake_up+0x34/0x48 20:16:33.465 kernel: [<ffffffff804933e9>] ? sd_probe_async+0x0/0x25b 20:16:33.465 kernel: [<ffffffff802708b7>] __async_schedule+0x17e/0x190 20:16:33.465 kernel: [<ffffffff802708e4>] async_schedule+0x10/0x14 20:16:33.465 kernel: [<ffffffff80493cc2>] sd_probe+0x1bd/0x213 20:16:33.465 kernel: [<ffffffff8047399e>] driver_probe_device+0x9a/0x11f 20:16:33.465 kernel: [<ffffffff80473ad4>] __device_attach+0x35/0x3a 20:16:33.465 kernel: [<ffffffff80473a9f>] ? __device_attach+0x0/0x3a 20:16:33.465 kernel: [<ffffffff80472f54>] bus_for_each_drv+0x51/0x88 20:16:33.465 kernel: [<ffffffff80473b61>] device_attach+0x5e/0x75 20:16:33.465 kernel: [<ffffffff80472dbc>] bus_attach_device+0x26/0x58 20:16:33.465 kernel: [<ffffffff804719dd>] device_add+0x3ff/0x562 20:16:33.465 kernel: [<ffffffff8048507c>] scsi_sysfs_add_sdev+0xb5/0x252 20:16:33.465 kernel: [<ffffffff80482eea>] scsi_probe_and_add_lun+0x910/0xa32 20:16:33.465 kernel: [<ffffffff804835b4>] __scsi_scan_target+0x3a5/0x542 20:16:33.465 kernel: [<ffffffff8029e029>] ? zone_statistics+0x60/0x65 20:16:33.465 kernel: [<ffffffff80483d46>] scsi_scan_target+0x97/0xae 20:16:33.465 kernel: [<ffffffff80487bb3>] iscsi_user_scan_session+0xcd/0xe4 20:16:33.465 kernel: [<ffffffff80487ae6>] ? iscsi_user_scan_session+0x0/0xe4 20:16:33.465 kernel: [<ffffffff80470f15>] device_for_each_child+0x35/0x6c 20:16:33.465 kernel: [<ffffffff80487acb>] iscsi_user_scan+0x28/0x2a 20:16:33.465 kernel: [<ffffffff80484694>] store_scan+0x9b/0xc6 20:16:33.465 kernel: [<ffffffff804706e5>] dev_attr_store+0x1b/0x1d 20:16:33.465 kernel: [<ffffffff8030b585>] sysfs_write_file+0xf2/0x12e 20:16:33.465 kernel: [<ffffffff802c169d>] vfs_write+0xad/0x129 20:16:33.465 kernel: [<ffffffff802c17d2>] sys_write+0x45/0x6c 20:16:33.465 kernel: [<ffffffff8022aeeb>] system_call_fastpath+0x16/0x1b 20:16:33.465 kernel: Code: 8b bb 98 05 00 00 48 85 ff 74 05 e8 04 c4 06 00 65 48 8b 04 25 e8 b4 00 00 ff 80 44 e0 ff ff 48 c7 03 40 00 00 00 e8 40 99 40 00 <0f> 0b eb fe 41 bc fe ff ff ff e9 17 ff ff ff 55 48 89 e5 41 55 20:16:33.465 kernel: RIP [<ffffffff8025b324>] do_exit+0x686/0x695 20:16:33.465 kernel: RSP <ffff88082cd79840> 20:16:33.465 kernel: ---[ end trace 0c87b57344896340 ]--- 20:16:33.465 kernel: note: iscsid[1733] exited with preempt_count 1 [following a hard lockup and reboot from previous crash] 20:21:03.288 kernel: scsi2 : iSCSI Initiator over TCP/IP 20:21:04.295 kernel: scsi 2:0:0:0: RAID IET Controller 0001 PQ: 0 ANSI: 5 20:21:04.295 kernel: scsi 2:0:0:0: Attached scsi generic sg4 type 12 20:21:04.296 kernel: scsi 2:0:0:1: Direct-Access IET VIRTUAL-DISK 0001 PQ: 0 ANSI: 5 20:21:04.296 kernel: sd 2:0:0:1: Attached scsi generic sg5 type 0 20:21:04.297 kernel: sd 2:0:0:1: [sde] 1957888 512-byte hardware sectors: (1.00 GB/956 MiB) 20:21:04.297 kernel: sd 2:0:0:1: [sde] Write Protect is off 20:21:04.298 kernel: sd 2:0:0:1: [sde] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA 20:21:04.359 kernel: sde:<4>device-mapper: ioctl: device doesn't appear to be in the dev hash table. 20:21:04.868 kernel: scsi 2:0:0:1: [sde] Unhandled error code 20:21:04.868 kernel: scsi 2:0:0:1: [sde] Result: hostbyte=0x07 driverbyte=0x00 20:21:04.868 kernel: end_request: I/O error, dev sde, sector 0 20:21:04.868 kernel: Buffer I/O error on device sde, logical block 0 20:21:04.868 kernel: ldm_validate_partition_table(): Disk read failed. 20:21:04.868 kernel: unable to read partition table 20:21:04.875 kernel: BUG: unable to handle kernel NULL pointer dereference at 0000000000000010 20:21:04.875 kernel: IP: [<ffffffff803f0cf7>] disk_part_iter_next+0x74/0xfd 20:21:04.875 kernel: PGD 82a4c6067 PUD 82a4c2067 PMD 0 20:21:04.875 kernel: Oops: 0000 [#1] PREEMPT SMP 20:21:04.875 kernel: last sysfs file: /sys/devices/platform/host2/session1/iscsi_session/session1/ifacename 20:21:04.875 kernel: CPU 1 20:21:04.875 kernel: Modules linked in: 20:21:04.875 kernel: Pid: 1388, comm: async/0 Not tainted 2.6.30.3-elastic-lon-p #2 X7DBN 20:21:04.875 kernel: RIP: 0010:[<ffffffff803f0cf7>] [<ffffffff803f0cf7>] disk_part_iter_next+0x74/0xfd 20:21:04.875 kernel: RSP: 0018:ffff880827951dd0 EFLAGS: 00010246 20:21:04.875 kernel: RAX: ffff88082b495400 RBX: ffff880827951e00 RCX: 0000000000000000 20:21:04.875 kernel: RDX: 0000000000000000 RSI: ffff88082b495400 RDI: 0000000000000000 20:21:04.875 kernel: RBP: ffff880827951df0 R08: ffff880827950000 R09: ffff88082b9aa000 20:21:04.875 kernel: R10: ffff88082ccbd018 R11: 0000000000000000 R12: ffff880827951e00 20:21:04.875 kernel: R13: ffff88082c971380 R14: 0000000000000000 R15: ffff88082add6520 20:21:04.875 kernel: FS: 0000000000000000(0000) GS:ffff880028122000(0000) knlGS:0000000000000000 20:21:04.875 kernel: CS: 0010 DS: 0018 ES: 0018 CR0: 000000008005003b 20:21:04.875 kernel: CR2: 0000000000000010 CR3: 000000082a48c000 CR4: 00000000000426e0 20:21:04.875 kernel: DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 20:21:04.875 kernel: DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400 20:21:04.875 kernel: Process async/0 (pid: 1388, threadinfo ffff880827950000, task ffff88082aed2f00) 20:21:04.875 kernel: Stack: 20:21:04.875 kernel: 0000000000000000 ffff880827951e00 ffff880827951e00 ffff88082c971380 20:21:04.875 kernel: ffff880827951e40 ffffffff80306f5f ffff88082b495400 0000000000000000 20:21:04.875 kernel: 0000000000000001 ffff88082add6520 ffff880827951e40 ffff88082b495400 20:21:04.875 kernel: Call Trace: 20:21:04.875 kernel: [<ffffffff80306f5f>] register_disk+0x122/0x13a 20:21:04.875 kernel: [<ffffffff803f0a8f>] add_disk+0xaa/0x106 20:21:04.875 kernel: [<ffffffff80493581>] sd_probe_async+0x198/0x25b 20:21:04.875 kernel: [<ffffffff8027046e>] async_thread+0x10c/0x20d 20:21:04.875 kernel: [<ffffffff802545ec>] ? default_wake_function+0x0/0xf 20:21:04.875 kernel: [<ffffffff80270362>] ? async_thread+0x0/0x20d 20:21:04.875 kernel: [<ffffffff8026ad75>] kthread+0x55/0x80 20:21:04.875 kernel: [<ffffffff8022be6a>] child_rip+0xa/0x20 20:21:04.875 kernel: [<ffffffff8026ad20>] ? kthread+0x0/0x80 20:21:04.875 kernel: [<ffffffff8022be60>] ? child_rip+0x0/0x20 20:21:04.875 kernel: Code: c8 ff 80 e1 0c b9 00 00 00 00 0f 44 c1 41 83 cd ff 48 8d 7a 20 48 be ff ff ff ff 08 00 00 00 48 b9 00 00 00 00 08 00 00 00 eb 50 <8b> 42 10 41 bd 01 00 00 00 eb db 4c 63 c2 4e 8d 04 c7 4d 8b 20 20:21:04.875 kernel: RIP [<ffffffff803f0cf7>] disk_part_iter_next+0x74/0xfd 20:21:04.875 kernel: RSP <ffff880827951dd0> 20:21:04.875 kernel: CR2: 0000000000000010 20:21:04.875 kernel: ---[ end trace d0aff0b325825503 ]--- 20:21:04.875 kernel: note: async/0[1388] exited with preempt_count 1 [a few days later] 10:05:03.019 kernel: scsi23 : iSCSI Initiator over TCP/IP 10:05:04.015 kernel: scsi 23:0:0:0: RAID IET Controller 0001 PQ: 0 ANSI: 5 10:05:04.015 kernel: scsi 23:0:0:0: Attached scsi generic sg14 type 12 10:05:04.017 kernel: scsi 23:0:0:1: Direct-Access IET VIRTUAL-DISK 0001 PQ: 0 ANSI: 5 10:05:04.017 kernel: sd 23:0:0:1: Attached scsi generic sg15 type 0 10:05:04.018 kernel: sd 23:0:0:1: [sdk] 27262976 512-byte hardware sectors: (13.9 GB/13.0 GiB) 10:05:04.018 kernel: sd 23:0:0:1: [sdk] Write Protect is off 10:05:04.019 kernel: sd 23:0:0:1: [sdk] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA 10:05:04.248 kernel: sdk: unknown partition table 10:05:04.248 kernel: BUG: unable to handle kernel NULL pointer dereference at 0000000000000010 10:05:04.248 kernel: IP: [<ffffffff803f0d77>] disk_part_iter_next+0x74/0xfd 10:05:04.248 kernel: PGD 82ad47067 PUD 82b591067 PMD 0 10:05:04.248 kernel: Oops: 0000 [#1] PREEMPT SMP 10:05:04.248 kernel: last sysfs file: /sys/devices/platform/host14/session9/iscsi_session/session9/ifacename 10:05:04.248 kernel: CPU 6 10:05:04.248 kernel: Modules linked in: 10:05:04.248 kernel: Pid: 29251, comm: async/0 Not tainted 2.6.30.4-elastic-lon-p #1 X7DBN 10:05:04.248 kernel: RIP: 0010:[<ffffffff803f0d77>] [<ffffffff803f0d77>] disk_part_iter_next+0x74/0xfd 10:05:04.248 kernel: RSP: 0018:ffff8802645b9dd0 EFLAGS: 00010246 10:05:04.248 kernel: RAX: ffff880548d43c00 RBX: ffff8802645b9e00 RCX: 0000000000000000 10:05:04.248 kernel: RDX: 0000000000000000 RSI: ffff880548d43c00 RDI: 0000000000000000 10:05:04.248 kernel: RBP: ffff8802645b9df0 R08: 0000000000000000 R09: ffff88082cdaf000 10:05:04.248 kernel: R10: ffff8802645b9ce0 R11: ffff880825d06fe8 R12: ffff8802645b9e00 10:05:04.248 kernel: R13: ffff88082c91f1c0 R14: 0000000000000000 R15: ffff880548d45920 10:05:04.248 kernel: FS: 0000000000000000(0000) GS:ffff8800281a4000(0000) knlGS:0000000000000000 10:05:04.248 kernel: CS: 0010 DS: 0018 ES: 0018 CR0: 000000008005003b 10:05:04.248 kernel: CR2: 0000000000000010 CR3: 000000082ad48000 CR4: 00000000000426e0 10:05:04.248 kernel: DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 10:05:04.248 kernel: DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400 10:05:04.248 kernel: Process async/0 (pid: 29251, threadinfo ffff8802645b8000, task ffff88082af363e0) 10:05:04.248 kernel: Stack: 10:05:04.248 kernel: 0000000000000000 ffff8802645b9e00 ffff8802645b9e00 ffff88082c91f1c0 10:05:04.248 kernel: ffff8802645b9e40 ffffffff80306feb ffff880548d43c00 0000000000000000 10:05:04.248 kernel: 0000000000000001 ffff880548d45920 ffff8802645b9e40 ffff880548d43c00 10:05:04.248 kernel: Call Trace: 10:05:04.248 kernel: [<ffffffff80306feb>] register_disk+0x122/0x13a 10:05:04.248 kernel: [<ffffffff803f0b0f>] add_disk+0xaa/0x106 10:05:04.248 kernel: [<ffffffff80493609>] sd_probe_async+0x198/0x25b 10:05:04.248 kernel: [<ffffffff802de5a3>] ? free_fs_struct+0x2d/0x31 10:05:04.248 kernel: [<ffffffff80270482>] async_thread+0x10c/0x20d 10:05:04.249 kernel: [<ffffffff802545ff>] ? default_wake_function+0x0/0xf 10:05:04.249 kernel: [<ffffffff80270376>] ? async_thread+0x0/0x20d 10:05:04.249 kernel: [<ffffffff8026ad89>] kthread+0x55/0x80 10:05:04.249 kernel: [<ffffffff8022be6a>] child_rip+0xa/0x20 10:05:04.249 kernel: [<ffffffff8026ad34>] ? kthread+0x0/0x80 10:05:04.249 kernel: [<ffffffff8022be60>] ? child_rip+0x0/0x20 10:05:04.249 kernel: Code: c8 ff 80 e1 0c b9 00 00 00 00 0f 44 c1 41 83 cd ff 48 8d 7a 20 48 be ff ff ff ff 08 00 00 00 48 b9 00 00 00 00 08 00 00 00 eb 50 <8b> 42 10 41 bd 01 00 00 00 eb db 4c 63 c2 4e 8d 04 c7 4d 8b 20 10:05:04.249 kernel: RIP [<ffffffff803f0d77>] disk_part_iter_next+0x74/0xfd 10:05:04.249 kernel: RSP <ffff8802645b9dd0> 10:05:04.249 kernel: CR2: 0000000000000010 10:05:04.249 kernel: ---[ end trace c2e45cd8c17e96d1 ]--- 10:05:04.249 kernel: note: async/0[29251] exited with preempt_count 1 [...] 10:05:42.880 kernel: scsi24 : iSCSI Initiator over TCP/IP 10:05:43.888 kernel: scsi 24:0:0:0: RAID IET Controller 0001 PQ: 0 ANSI: 5 10:05:43.888 kernel: scsi 24:0:0:0: Attached scsi generic sg14 type 12 10:05:43.888 kernel: scsi 24:0:0:1: Direct-Access IET VIRTUAL-DISK 0001 PQ: 0 ANSI: 5 10:05:43.897 kernel: ------------[ cut here ]------------ 10:05:43.899 kernel: kernel BUG at kernel/exit.c:1014! 10:05:43.899 kernel: invalid opcode: 0000 [#2] PREEMPT SMP 10:05:43.899 kernel: last sysfs file: /sys/devices/platform/host24/scsi_host/host24/scan 10:05:43.899 kernel: CPU 7 10:05:43.899 kernel: Modules linked in: 10:05:43.899 kernel: Pid: 29567, comm: iscsid Tainted: G D 2.6.30.4-elastic-lon-p #1 X7DBN 10:05:43.899 kernel: RIP: 0010:[<ffffffff8025b338>] [<ffffffff8025b338>] do_exit+0x686/0x695 10:05:43.899 kernel: RSP: 0018:ffff8801da10f840 EFLAGS: 00010006 10:05:43.899 kernel: RAX: ffff8802645b9ed0 RBX: 0000000000000001 RCX: 0000000000000000 10:05:43.899 kernel: RDX: 0000000000000000 RSI: 0000000000000003 RDI: ffff8802645b9ed0 10:05:43.899 kernel: RBP: ffff8801da10f888 R08: 0000000000000000 R09: ffff88082cd3f108 10:05:43.899 kernel: R10: 000000000000046c R11: 000000000000011b R12: 0000000000000003 10:05:43.899 kernel: R13: ffff8806d24a9920 R14: 0000000080664dec R15: 0000000000000000 10:05:43.899 kernel: FS: 00007f3b0eefa6f0(0000) GS:ffff8800281be000(0000) knlGS:0000000000000000 10:05:43.899 kernel: CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b 10:05:43.899 kernel: CR2: fffff88004d30000 CR3: 0000000275c0e000 CR4: 00000000000426e0 10:05:43.899 kernel: DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 10:05:43.899 kernel: DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400 10:05:43.899 kernel: Process iscsid (pid: 29567, threadinfo ffff8801da10e000, task ffff8802811fd820) 10:05:43.899 kernel: Stack: 10:05:43.899 kernel: ffffffff8024b6d1 0000000000000000 ffffffff80835c38 ffff8801da10f888 10:05:43.899 kernel: ffffffff80835c30 0000000000000282 ffff88020696c200 000000000000001f 10:05:43.899 kernel: ffffffff80835c80 ffff8801da10f8c8 ffffffff8024c06c 00000000000080d0 10:05:43.899 kernel: Call Trace: 10:05:43.899 kernel: [<ffffffff8024b6d1>] ? __wake_up_common+0x49/0x7f 10:05:43.899 kernel: [<ffffffff8024c06c>] __wake_up+0x34/0x48 10:05:43.899 kernel: [<ffffffff80493471>] ? sd_probe_async+0x0/0x25b 10:05:43.899 kernel: [<ffffffff802708cb>] __async_schedule+0x17e/0x190 10:05:43.899 kernel: [<ffffffff802708f8>] async_schedule+0x10/0x14 10:05:43.899 kernel: [<ffffffff80493d4a>] sd_probe+0x1bd/0x213 10:05:43.899 kernel: [<ffffffff80473a1e>] driver_probe_device+0x9a/0x11f 10:05:43.899 kernel: [<ffffffff80473b54>] __device_attach+0x35/0x3a 10:05:43.899 kernel: [<ffffffff80473b1f>] ? __device_attach+0x0/0x3a 10:05:43.899 kernel: [<ffffffff80472fd4>] bus_for_each_drv+0x51/0x88 10:05:43.899 kernel: [<ffffffff80473be1>] device_attach+0x5e/0x75 10:05:43.899 kernel: [<ffffffff80472e3c>] bus_attach_device+0x26/0x58 10:05:43.899 kernel: [<ffffffff80471a5d>] device_add+0x3ff/0x562 10:05:43.899 kernel: [<ffffffff80485104>] scsi_sysfs_add_sdev+0xb5/0x252 10:05:43.899 kernel: [<ffffffff80482f72>] scsi_probe_and_add_lun+0x910/0xa32 10:05:43.899 kernel: [<ffffffff8048363c>] __scsi_scan_target+0x3a5/0x542 10:05:43.899 kernel: [<ffffffff8029e08d>] ? zone_statistics+0x60/0x65 10:05:43.899 kernel: [<ffffffff80293369>] ? get_page_from_freelist+0x4ad/0x67a 10:05:43.899 kernel: [<ffffffff80483dce>] scsi_scan_target+0x97/0xae 10:05:43.899 kernel: [<ffffffff80487c3b>] iscsi_user_scan_session+0xcd/0xe4 10:05:43.899 kernel: [<ffffffff80487b6e>] ? iscsi_user_scan_session+0x0/0xe4 10:05:43.899 kernel: [<ffffffff80470f95>] device_for_each_child+0x35/0x6c 10:05:43.899 kernel: [<ffffffff80487b53>] iscsi_user_scan+0x28/0x2a 10:05:43.899 kernel: [<ffffffff8048471c>] store_scan+0x9b/0xc6 10:05:43.899 kernel: [<ffffffff80470765>] dev_attr_store+0x1b/0x1d 10:05:43.899 kernel: [<ffffffff8030b61d>] sysfs_write_file+0xf2/0x12e 10:05:43.899 kernel: [<ffffffff802c1711>] vfs_write+0xad/0x129 10:05:43.899 kernel: [<ffffffff802c1846>] sys_write+0x45/0x6c 10:05:43.899 kernel: [<ffffffff8022aeeb>] system_call_fastpath+0x16/0x1b 10:05:43.899 kernel: Code: 8b bb 98 05 00 00 48 85 ff 74 05 e8 64 c4 06 00 65 48 8b 04 25 e8 b4 00 00 ff 80 44 e0 ff ff 48 c7 03 40 00 00 00 e8 9c 9a 40 00 <0f> 0b eb fe 41 bc fe ff ff ff e9 17 ff ff ff 55 48 89 e5 41 55 10:05:43.899 kernel: RIP [<ffffffff8025b338>] do_exit+0x686/0x695 10:05:43.899 kernel: RSP <ffff8801da10f840> 10:05:43.899 kernel: ---[ end trace c2e45cd8c17e96d2 ]--- 10:05:43.899 kernel: note: iscsid[29567] exited with preempt_count 1 10:05:43.899 kernel: BUG: scheduling while atomic: iscsid/29567/0x10000002 10:05:43.899 kernel: Modules linked in: 10:05:43.899 kernel: Pid: 29567, comm: iscsid Tainted: G D 2.6.30.4-elastic-lon-p #1 10:05:43.899 kernel: Call Trace: 10:05:43.899 kernel: [<ffffffff80250e32>] __schedule_bug+0x57/0x5c 10:05:43.899 kernel: [<ffffffff806645b9>] __schedule+0xc1/0x814 10:05:43.899 kernel: [<ffffffff803ff025>] ? number+0x12f/0x225 10:05:43.899 kernel: [<ffffffff80292cb0>] ? __pagevec_free+0x29/0x3c 10:05:43.899 kernel: [<ffffffff80664dec>] schedule+0x18/0x3b 10:05:43.899 kernel: [<ffffffff80250f33>] __cond_resched+0x1c/0x45 10:05:43.899 kernel: [<ffffffff80664ec2>] _cond_resched+0x30/0x3b 10:05:43.899 kernel: [<ffffffff802a17b2>] unmap_vmas+0x6cd/0x886 10:05:43.899 kernel: [<ffffffff802a5db3>] exit_mmap+0xd4/0x184 10:05:43.899 kernel: [<ffffffff80255c6b>] mmput+0x2b/0xb4 10:05:43.899 kernel: [<ffffffff80259524>] exit_mm+0xff/0x10a 10:05:43.899 kernel: [<ffffffff8025ae2c>] do_exit+0x17a/0x695 10:05:43.899 kernel: [<ffffffff80419d84>] ? vgacon_set_cursor_size+0xfd/0x109 10:05:43.899 kernel: [<ffffffff8022ea59>] oops_end+0x89/0x8e 10:05:43.899 kernel: [<ffffffff8022ec1c>] die+0x55/0x5e 10:05:43.899 kernel: [<ffffffff8022c6a0>] do_trap+0x115/0x124 10:05:43.899 kernel: [<ffffffff8022ca20>] do_invalid_op+0x91/0x9a 10:05:43.899 kernel: [<ffffffff8025b338>] ? do_exit+0x686/0x695 10:05:43.899 kernel: [<ffffffff8024ecfd>] ? dequeue_task_fair+0x68/0x71 10:05:43.899 kernel: [<ffffffff80250e89>] ? finish_task_switch+0x52/0xe0 10:05:43.899 kernel: [<ffffffff8022bc05>] invalid_op+0x15/0x20 10:05:43.899 kernel: [<ffffffff8025b338>] ? do_exit+0x686/0x695 10:05:43.899 kernel: [<ffffffff8024b6d1>] ? __wake_up_common+0x49/0x7f 10:05:43.899 kernel: [<ffffffff8024c06c>] __wake_up+0x34/0x48 10:05:43.899 kernel: [<ffffffff80493471>] ? sd_probe_async+0x0/0x25b 10:05:43.899 kernel: [<ffffffff802708cb>] __async_schedule+0x17e/0x190 10:05:43.899 kernel: [<ffffffff802708f8>] async_schedule+0x10/0x14 10:05:43.899 kernel: [<ffffffff80493d4a>] sd_probe+0x1bd/0x213 10:05:43.899 kernel: [<ffffffff80473a1e>] driver_probe_device+0x9a/0x11f 10:05:43.899 kernel: [<ffffffff80473b54>] __device_attach+0x35/0x3a 10:05:43.899 kernel: [<ffffffff80473b1f>] ? __device_attach+0x0/0x3a 10:05:43.899 kernel: [<ffffffff80472fd4>] bus_for_each_drv+0x51/0x88 10:05:43.899 kernel: [<ffffffff80473be1>] device_attach+0x5e/0x75 10:05:43.899 kernel: [<ffffffff80472e3c>] bus_attach_device+0x26/0x58 10:05:43.899 kernel: [<ffffffff80471a5d>] device_add+0x3ff/0x562 10:05:43.899 kernel: [<ffffffff80485104>] scsi_sysfs_add_sdev+0xb5/0x252 10:05:43.900 kernel: [<ffffffff80482f72>] scsi_probe_and_add_lun+0x910/0xa32 10:05:43.900 kernel: [<ffffffff8048363c>] __scsi_scan_target+0x3a5/0x542 10:05:43.900 kernel: [<ffffffff8029e08d>] ? zone_statistics+0x60/0x65 10:05:43.900 kernel: [<ffffffff80293369>] ? get_page_from_freelist+0x4ad/0x67a 10:05:43.900 kernel: [<ffffffff80483dce>] scsi_scan_target+0x97/0xae 10:05:43.900 kernel: [<ffffffff80487c3b>] iscsi_user_scan_session+0xcd/0xe4 10:05:43.900 kernel: [<ffffffff80487b6e>] ? iscsi_user_scan_session+0x0/0xe4 10:05:43.900 kernel: [<ffffffff80470f95>] device_for_each_child+0x35/0x6c 10:05:43.900 kernel: [<ffffffff80487b53>] iscsi_user_scan+0x28/0x2a 10:05:43.900 kernel: [<ffffffff8048471c>] store_scan+0x9b/0xc6 10:05:43.900 kernel: [<ffffffff80470765>] dev_attr_store+0x1b/0x1d 10:05:43.901 kernel: [<ffffffff8030b61d>] sysfs_write_file+0xf2/0x12e 10:05:43.901 kernel: [<ffffffff802c1711>] vfs_write+0xad/0x129 10:05:43.901 kernel: [<ffffffff802c1846>] sys_write+0x45/0x6c 10:05:43.901 kernel: [<ffffffff8022aeeb>] system_call_fastpath+0x16/0x1b 10:05:43.950 kernel: device-mapper: ioctl: device doesn't appear to be in the dev hash table. [another hard lockup after a short time] register_disk+0x122 is line 183 of include/linux/genhd.h. Ironically, although these disks contain partitions, we're only using the whole device to export to kvm virtual machines, so it'd be sufficient to fix our problem if we were able to turn off partition detection altogether on them. Is that possible for just iSCSI disks without turning off partitioning on all disks? (Normal partitioned SATA drives are also in use on these boxes, so I can't just compile out all the partition support from the kernel.) Cheers, Chris. ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: oops during scsi scanning disk setup 2009-08-21 14:51 ` Chris Webb @ 2009-08-21 15:47 ` James Bottomley 2009-08-21 22:59 ` Chris Webb 2009-08-22 11:55 ` Chris Webb 0 siblings, 2 replies; 17+ messages in thread From: James Bottomley @ 2009-08-21 15:47 UTC (permalink / raw) To: Chris Webb; +Cc: linux-scsi On Fri, 2009-08-21 at 15:51 +0100, Chris Webb wrote: > James Bottomley <James.Bottomley@suse.de> writes: > > > On Fri, 2009-08-21 at 10:23 +0100, Chris Webb wrote: > > > > > Sorry to follow up a third time, but I can now confirm this. I slipped -g into > > > CFLAGS in the kernel Makefile and rebuilt genhd.o and then the entire vmlinux. > > > > I suppose it makes sense: That was the only dereference at offset 16 I > > could find in the code. The thing which doesn't quite make sense is > > that disk_part_iter_init() also dereferences the same pointer > > successfully ... I suppose this could be a race with another thread to > > null out the gendisk part_tbl ... I'll have to think about it some more. > > Thanks! If it helps, I've only ever seen it following an iscsi login to a > target machine which is heavy loaded (e.g. RAID resync in this case), > presumably meaning that everything (including disk reads) happens a bit > slowly. Perhaps this increases the window for a race in some way? > > I've spent some time over the past week trying to reproduce it in a VM with > magic sysrq enabled so I could find out a bit more, but it subbornly refuses > to happen except on machines in a busy production cluster. Actually, for that particular pointer to be NULL'd, I think the race must be between add_disk and del_gendisk, implying that your iSCSI cluster somehow shut down the link while it was busy. I think that's an artifact of the fact that we don't get a reference to the disk in these operations, and the race window is much longer now we do sd async scanning. Can you try this as a partial fix? (It should prevent the oops, but you'll still lose the disk). James --- diff --git a/drivers/scsi/sd.c b/drivers/scsi/sd.c index b7b9fec..a89c421 100644 --- a/drivers/scsi/sd.c +++ b/drivers/scsi/sd.c @@ -2021,6 +2021,7 @@ static void sd_probe_async(void *data, async_cookie_t cookie) sd_printk(KERN_NOTICE, sdkp, "Attached SCSI %sdisk\n", sdp->removable ? "removable " : ""); + put_device(&sdkp->dev); } /** @@ -2106,6 +2107,7 @@ static int sd_probe(struct device *dev) get_device(&sdp->sdev_gendev); + get_device(&sdkp->dev); /* prevent release before async_schedule */ async_schedule(sd_probe_async, sdkp); return 0; ^ permalink raw reply related [flat|nested] 17+ messages in thread
* Re: oops during scsi scanning disk setup 2009-08-21 15:47 ` James Bottomley @ 2009-08-21 22:59 ` Chris Webb 2009-08-21 23:39 ` James Bottomley 2009-08-22 11:55 ` Chris Webb 1 sibling, 1 reply; 17+ messages in thread From: Chris Webb @ 2009-08-21 22:59 UTC (permalink / raw) To: James Bottomley; +Cc: linux-scsi James Bottomley <James.Bottomley@suse.de> writes: > Can you try this as a partial fix? (It should prevent the oops, but > you'll still lose the disk). Hi James. Many thanks for this. Do you think it's worth adding a printk() to flag up when this happens so we can detect when this case happens and confirm the issue given how rare the crashes are, or is this difficult to arrange? Cheers, Chris. ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: oops during scsi scanning disk setup 2009-08-21 22:59 ` Chris Webb @ 2009-08-21 23:39 ` James Bottomley 0 siblings, 0 replies; 17+ messages in thread From: James Bottomley @ 2009-08-21 23:39 UTC (permalink / raw) To: Chris Webb; +Cc: linux-scsi On Fri, 2009-08-21 at 23:59 +0100, Chris Webb wrote: > James Bottomley <James.Bottomley@suse.de> writes: > > > Can you try this as a partial fix? (It should prevent the oops, but > > you'll still lose the disk). > > Hi James. Many thanks for this. Do you think it's worth adding a printk() to > flag up when this happens so we can detect when this case happens and > confirm the issue given how rare the crashes are, or is this difficult to > arrange? Well, it's only a theory, so we need confirmation that it actually fixes the problem. As for a printk, there's no real way to do that. What I did was make sure we take a reference to the scsi disk. Holding that reference should prevent us from losing the partition table ... but the issue itself is legitimate (add racing with remove), and there's not really a good way of detecting it. James ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: oops during scsi scanning disk setup 2009-08-21 15:47 ` James Bottomley 2009-08-21 22:59 ` Chris Webb @ 2009-08-22 11:55 ` Chris Webb 2009-08-22 14:56 ` James Bottomley 1 sibling, 1 reply; 17+ messages in thread From: Chris Webb @ 2009-08-22 11:55 UTC (permalink / raw) To: James Bottomley; +Cc: linux-scsi James Bottomley <James.Bottomley@suse.de> writes: > Can you try this as a partial fix? (It should prevent the oops, but > you'll still lose the disk). Hi James. Thanks for patch. I've applied this, although the context is quite a bit different in the released 2.6.30.x from your patch against head. (E.g. in sd_probe, there's no get_device(&sdp->sdev_gendev) at all before the async_schedule(). Instead that happens in sd_probe_async.) I'm now seeing a warning backtrace for every scsi attach in the machine, including the main system hard drives, so I think something's not quite right. For instance, in my test virtual machine: scsi0 : ata_piix scsi1 : ata_piix ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc000 irq 14 ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc008 irq 15 Intel(R) PRO/1000 Network Driver - version 7.3.21-k3-NAPI Copyright (c) 1999-2006 Intel Corporation. ata1.01: NODEV after polling detection ata1.00: ATA-7: QEMU HARDDISK, 0.10.6, max UDMA/100 ata1.00: 20971520 sectors, multi 16: LBA48 ata1.00: configured for MWDMA2 scsi 0:0:0:0: Direct-Access ATA QEMU HARDDISK 0.10 PQ: 0 ANSI: 5 ------------[ cut here ]------------ WARNING: at lib/kref.c:43 kref_get+0x23/0x2d() Hardware name: Modules linked in: Pid: 578, comm: async/0 Not tainted 2.6.30.4-elastic-lon-p #3 Call Trace: [<ffffffff80419d84>] ? vgacon_set_cursor_size+0xfd/0x109 [<ffffffff80257fa5>] warn_slowpath_common+0x77/0x8f [<ffffffff80257fcc>] warn_slowpath_null+0xf/0x11 [<ffffffff803fbfb6>] kref_get+0x23/0x2d [<ffffffff803fb167>] kobject_get+0x1a/0x22 [<ffffffff804708c1>] get_device+0x14/0x1a [<ffffffff80493d56>] sd_probe+0x1b7/0x21d [<ffffffff80473a1e>] driver_probe_device+0x9a/0x11f [<ffffffff80473b54>] __device_attach+0x35/0x3a [<ffffffff80473b1f>] ? __device_attach+0x0/0x3a [<ffffffff80472fd4>] bus_for_each_drv+0x51/0x88 [<ffffffff80473be1>] device_attach+0x5e/0x75 [<ffffffff80472e3c>] bus_attach_device+0x26/0x58 [<ffffffff80471a5d>] device_add+0x3ff/0x562 [<ffffffff80485104>] scsi_sysfs_add_sdev+0xb5/0x252 [<ffffffff80482f72>] scsi_probe_and_add_lun+0x910/0xa32 [<ffffffff80483e98>] __scsi_add_device+0xb3/0xdf [<ffffffff804a104d>] ata_scsi_scan_host+0x74/0x16e [<ffffffff8026b1c3>] ? autoremove_wake_function+0x0/0x34 [<ffffffff8049f3b8>] async_port_probe+0xab/0xb3 [<ffffffff80270482>] async_thread+0x10c/0x20d [<ffffffff802545ff>] ? default_wake_function+0x0/0xf [<ffffffff80270376>] ? async_thread+0x0/0x20d [<ffffffff8026ad89>] kthread+0x55/0x80 [<ffffffff8022be6a>] child_rip+0xa/0x20 [<ffffffff8026ad34>] ? kthread+0x0/0x80 [<ffffffff8022be60>] ? child_rip+0x0/0x20 ---[ end trace cce8275f5d03fa65 ]--- sd 0:0:0:0: Attached scsi generic sg0 type 0 sd 0:0:0:0: [sda] 20971520 512-byte hardware sectors: (10.7 GB/10.0 GiB) sd 0:0:0:0: [sda] Write Protect is off sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00 sd 0:0:0:0: [sda] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA sda: sda1 sda2 sd 0:0:0:0: [sda] Attached SCSI disk [...] scsi2 : iSCSI Initiator over TCP/IP scsi 2:0:0:0: RAID IET Controller 0001 PQ: 0 ANSI: 5 scsi 2:0:0:0: Attached scsi generic sg1 type 12 scsi 2:0:0:1: Direct-Access IET VIRTUAL-DISK 0001 PQ: 0 ANSI: 5 ------------[ cut here ]------------ WARNING: at lib/kref.c:43 kref_get+0x23/0x2d() Hardware name: Modules linked in: Pid: 1156, comm: iscsid Tainted: G W 2.6.30.4-elastic-lon-p #3 Call Trace: [<ffffffff80419d84>] ? vgacon_set_cursor_size+0xfd/0x109 [<ffffffff80257fa5>] warn_slowpath_common+0x77/0x8f [<ffffffff80257fcc>] warn_slowpath_null+0xf/0x11 [<ffffffff803fbfb6>] kref_get+0x23/0x2d [<ffffffff803fb167>] kobject_get+0x1a/0x22 [<ffffffff804708c1>] get_device+0x14/0x1a [<ffffffff80493d56>] sd_probe+0x1b7/0x21d [<ffffffff80473a1e>] driver_probe_device+0x9a/0x11f [<ffffffff80473b54>] __device_attach+0x35/0x3a [<ffffffff80473b1f>] ? __device_attach+0x0/0x3a [<ffffffff80472fd4>] bus_for_each_drv+0x51/0x88 [<ffffffff80473be1>] device_attach+0x5e/0x75 [<ffffffff80472e3c>] bus_attach_device+0x26/0x58 [<ffffffff80471a5d>] device_add+0x3ff/0x562 [<ffffffff80485104>] scsi_sysfs_add_sdev+0xb5/0x252 [<ffffffff80482f72>] scsi_probe_and_add_lun+0x910/0xa32 [<ffffffff8048363c>] __scsi_scan_target+0x3a5/0x542 [<ffffffff8029e08d>] ? zone_statistics+0x60/0x65 [<ffffffff80293369>] ? get_page_from_freelist+0x4ad/0x67a [<ffffffff80483dce>] scsi_scan_target+0x97/0xae [<ffffffff80487c3b>] iscsi_user_scan_session+0xcd/0xe4 [<ffffffff80487b6e>] ? iscsi_user_scan_session+0x0/0xe4 [<ffffffff80470f95>] device_for_each_child+0x35/0x6c [<ffffffff80487b53>] iscsi_user_scan+0x28/0x2a [<ffffffff8048471c>] store_scan+0x9b/0xc6 [<ffffffff80470765>] dev_attr_store+0x1b/0x1d [<ffffffff8030b61d>] sysfs_write_file+0xf2/0x12e [<ffffffff802c1711>] vfs_write+0xad/0x129 [<ffffffff802c1846>] sys_write+0x45/0x6c [<ffffffff8022aeeb>] system_call_fastpath+0x16/0x1b ---[ end trace cce8275f5d03fa67 ]--- sd 2:0:0:1: Attached scsi generic sg2 type 0 sd 2:0:0:1: [sdb] 10485760 512-byte hardware sectors: (5.36 GB/5.00 GiB) sd 2:0:0:1: [sdb] Write Protect is off sd 2:0:0:1: [sdb] Mode Sense: 79 00 00 08 sd 2:0:0:1: [sdb] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA sdb: unknown partition table sd 2:0:0:1: [sdb] Attached SCSI disk [...] etc. > As for a printk, there's no real way to do that. What I did was make sure > we take a reference to the scsi disk. Holding that reference should > prevent us from losing the partition table ... but the issue itself is > legitimate (add racing with remove), and there's not really a good way of > detecting it. I was thinking of a debug hack like if (atomic_read(&sdkp->dev.kobj.kref.refcount) < 2) printk("James' patch has just protected us from a crash: send him a beer\n"); just before put_device(&sdkp->dev); in sd_probe_async(). I know the refcount could still drop between the atomic_read and put_device, but we wouldn't have crashed in that case anyway and at least if we do see the message over the next few days in our kernel logs, I could definitely confirm your theory. Otherwise, given it's such a rare crash, I might not know whether or not we've just been lucky for a couple of weeks! Best wishes, Chris. ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: oops during scsi scanning disk setup 2009-08-22 11:55 ` Chris Webb @ 2009-08-22 14:56 ` James Bottomley 2009-08-22 15:50 ` Chris Webb 0 siblings, 1 reply; 17+ messages in thread From: James Bottomley @ 2009-08-22 14:56 UTC (permalink / raw) To: Chris Webb; +Cc: linux-scsi On Sat, 2009-08-22 at 12:55 +0100, Chris Webb wrote: > James Bottomley <James.Bottomley@suse.de> writes: > > > Can you try this as a partial fix? (It should prevent the oops, but > > you'll still lose the disk). > > Hi James. Thanks for patch. I've applied this, although the context is quite > a bit different in the released 2.6.30.x from your patch against head. (E.g. > in sd_probe, there's no get_device(&sdp->sdev_gendev) at all before the > async_schedule(). Instead that happens in sd_probe_async.) > > I'm now seeing a warning backtrace for every scsi attach in the machine, > including the main system hard drives, so I think something's not quite > right. For instance, in my test virtual machine: Oh, I'm afraid that won't work (as you found out). For your kernel, you'll need this patch: http://git.kernel.org/?p=linux/kernel/git/torvalds/linux-2.6.git;a=commitdiff_plain;h=601e7638254c118fca135af9b1a9f35061420f62 Before you apply it. Actually, if that works, I'll have the above backported as well. James ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: oops during scsi scanning disk setup 2009-08-22 14:56 ` James Bottomley @ 2009-08-22 15:50 ` Chris Webb 2009-09-05 16:45 ` Chris Webb 0 siblings, 1 reply; 17+ messages in thread From: Chris Webb @ 2009-08-22 15:50 UTC (permalink / raw) To: James Bottomley; +Cc: linux-scsi James Bottomley <James.Bottomley@suse.de> writes: > Actually, if that works, I'll have the above backported as well. Hi James. That's much better; thanks! I certainly can't provoke any problems with it in a VM, although I couldn't really reproduce the problem with the original kernel in a test environment either. I'll push it to our clusters and see how things go over the next week or so. Cheers, Chris. ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: oops during scsi scanning disk setup 2009-08-22 15:50 ` Chris Webb @ 2009-09-05 16:45 ` Chris Webb 0 siblings, 0 replies; 17+ messages in thread From: Chris Webb @ 2009-09-05 16:45 UTC (permalink / raw) To: James Bottomley; +Cc: linux-scsi Chris Webb <chris@arachsys.com> writes: > James Bottomley <James.Bottomley@suse.de> writes: > > > Actually, if that works, I'll have the above backported as well. > > Hi James. That's much better; thanks! I certainly can't provoke any problems > with it in a VM, although I couldn't really reproduce the problem with the > original kernel in a test environment either. I'll push it to our clusters > and see how things go over the next week or so. We've been running with this for a couple of weeks now, and I haven't seen the crash repeat itself. That said, I applied this on top to see if I could detect the race: diff --git a/drivers/scsi/sd.c b/drivers/scsi/sd.c --- a/drivers/scsi/sd.c +++ b/drivers/scsi/sd.c @@ -1936,6 +1936,8 @@ sd_printk(KERN_NOTICE, sdkp, "Attached SCSI %sdisk\n", sdp->removable ? "removable " : ""); + if (atomic_read(&sdkp->dev.kobj.kref.refcount) < 2) + sd_printk(KERN_WARNING, sdkp, "Attempted to release device before sd_probe_async complete\n"); put_device(&sdkp->dev); } and it hasn't triggered at all, so I wonder whether we've just not hit the bug again. Best wishes, Chris. ^ permalink raw reply [flat|nested] 17+ messages in thread
end of thread, other threads:[~2009-09-05 16:50 UTC | newest] Thread overview: 17+ messages (download: mbox.gz follow: Atom feed -- links below jump to the message on this page -- 2009-08-20 18:05 oops during scsi scanning disk setup Chris Webb 2009-08-20 20:01 ` Matthew Wilcox 2009-08-20 20:10 ` Yinghai Lu 2009-08-21 4:26 ` Arjan van de Ven 2009-08-20 22:26 ` James Bottomley 2009-08-21 8:16 ` Chris Webb 2009-08-21 8:33 ` Chris Webb 2009-08-21 9:23 ` Chris Webb 2009-08-21 14:00 ` James Bottomley 2009-08-21 14:51 ` Chris Webb 2009-08-21 15:47 ` James Bottomley 2009-08-21 22:59 ` Chris Webb 2009-08-21 23:39 ` James Bottomley 2009-08-22 11:55 ` Chris Webb 2009-08-22 14:56 ` James Bottomley 2009-08-22 15:50 ` Chris Webb 2009-09-05 16:45 ` Chris Webb
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).