oops during scsi scanning disk setup

oops during scsi scanning disk setup

[Chris Webb]

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.

Re: oops during scsi scanning disk setup

[Matthew Wilcox]

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."

Re: oops during scsi scanning disk setup

[Yinghai Lu]

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

Re: oops during scsi scanning disk setup

[James Bottomley]

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

Re: oops during scsi scanning disk setup

[Arjan van de Ven]

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?

Re: oops during scsi scanning disk setup

[Chris Webb]

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.

Re: oops during scsi scanning disk setup

[Chris Webb]

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.

Re: oops during scsi scanning disk setup

[Chris Webb]

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,

Re: oops during scsi scanning disk setup

[James Bottomley]

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

Re: oops during scsi scanning disk setup

[Chris Webb]

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.

Re: oops during scsi scanning disk setup

[James Bottomley]

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;

Re: oops during scsi scanning disk setup

[Chris Webb]

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.

Re: oops during scsi scanning disk setup

[James Bottomley]

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

Re: oops during scsi scanning disk setup

[Chris Webb]

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.

Re: oops during scsi scanning disk setup

[James Bottomley]

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

Re: oops during scsi scanning disk setup

[Chris Webb]

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.

Re: oops during scsi scanning disk setup

[Chris Webb]

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.