Here's an oops. Mount a target with iscsi. Start a process that
holds open the bsg device, in the debugger perhaps. Then use
iscsiadm to logout. Let the bsg process try to submit another
command. Its queue is no longer usable, as blk_get_request() finds
a NULL q->elevator->ops.
BUG: unable to handle kernel NULL pointer dereference at 0000000000000070
IP: [<ffffffff802e6adb>] elv_may_queue+0xb/0x20
PGD 3e8e1067 PUD 3e4ce067 PMD 0
Oops: 0000 [1] SMP
CPU 1
Modules linked in: crc32c libcrc32c rdma_ucm rdma_cm iw_cm ib_addr ib_ipoib ib_ucm ib_cm ib_sa ib_umad ib_uverbs ib_mthca iscsi_tcp libiscsi scsi_transport_iscsi ext3 jbd ib_mad ib_core i2c_nforce2 i2c_core sg sd_mod sata_nv tg3 nfs lockd sunrpc
Pid: 3000, comm: sgio Not tainted 2.6.25-rc4-bidi-pw #29
RIP: 0010:[<ffffffff802e6adb>] [<ffffffff802e6adb>] elv_may_queue+0xb/0x20
RSP: 0018:ffff81007d15fd28 EFLAGS: 00010046
RAX: 0000000000000000 RBX: ffff81007d54d468 RCX: 0000000000000010
RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffff81007d54d468
RBP: ffff81007d15fd28 R08: 0000000000000001 R09: ffff81007d093e88
R10: 0000000000000000 R11: 0000000000000000 R12: ffff81007d54d468
R13: ffff81007d54d488 R14: 0000000000000000 R15: 0000000000000000
FS: 00002b05a4a17b00(0000) GS:ffff81007f600840(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: 0000000000000070 CR3: 000000003e497000 CR4: 00000000000006e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff4ff0 DR7: 0000000000000400
Process sgio (pid: 3000, threadinfo ffff81007d15e000, task ffff81007f712830)
Stack: ffff81007d15fd98 ffffffff802ea129 ffff810040005358 ffff810040005350
00000010000612d0 0000000000000000 ffff81007cda6a68 ffff81007d9de020
0000000000000086 0000000000000000 ffff81007d54d468 0000000000000000
Call Trace:
[<ffffffff802ea129>] get_request+0x39/0x330
[<ffffffff802ea44f>] get_request_wait+0x2f/0x1c0
[<ffffffff80286b27>] ? cache_grow+0x1b7/0x260
[<ffffffff802ea7d8>] blk_get_request+0x38/0x80
[<ffffffff802f171c>] bsg_map_hdr+0x9c/0x340
[<ffffffff802f1aac>] bsg_write+0xec/0x2e0
[<ffffffff8028d4a7>] vfs_write+0xc7/0x150
[<ffffffff8028db10>] sys_write+0x50/0x90
[<ffffffff8020b58b>] system_call_after_swapgs+0x7b/0x80
Code: 55 48 8b 47 18 48 89 e5 48 8b 00 48 8b 40 68 48 85 c0 74 05 48 89 f7 ff d0 c9 c3 0f 1f 44 00 00 48 8b 47 18 55 48 89 e5 48 8b 00 <48> 8b 50 70 31 c0 48 85 d2 74 02 ff d2 c9 c3 66 0f 1f 44 00 00
RIP [<ffffffff802e6adb>] elv_may_queue+0xb/0x20
RSP <ffff81007d15fd28>
CR2: 0000000000000070
---[ end trace a020f2a7368afcb4 ]---
I think this used not to happen; not sure. But I changed two things
lately. 2.6.25-rc1 to -rc4 and fedora 8 iscsi-initiator-utils (865) to
fedora devel (868). Bidi and varlen patches always too.
I'll follow with some more variations on this theme. Looks like bsg
needs to protect more carefully against the device going away. Any
ideas how best to do this? What was the approach in sg?
-- Pete
Here's an interesting hang. Mount a target with iscsi, again one that
may be slow in responding. Send it a command via bsg. Kill the target
or unplug the network before the response returns. At this point the
kernel notices and iscsid goes about trying to reconnect.
Hit ctrl-c to try to kill the bsg-using application. Being the last
user of the device, it hangs during file close waiting for the
outstanding command to complete (even in error), sleeping with bsg_mutex
held.
sgio D ffff81007c567bc8 0 2916 2846
ffff81007c567b98 0000000000000046 ffff81007c567b78 ffff810040e16cc8
ffff81007f721080 ffff81007f71f830 ffff81007f721298 ffffffff80263514
ffff81007c567b98 0000000000000282 ffff81007c567c28 ffffffff80267238
Call Trace:
[<ffffffff80263514>] ? __pagevec_free+0x24/0x30
[<ffffffff80267238>] ? release_pages+0x198/0x1e0
[<ffffffff80404ce8>] io_schedule+0x28/0x40
[<ffffffff802f1520>] bsg_release+0x1c0/0x1e0
[<ffffffff80244ad0>] ? autoremove_wake_function+0x0/0x40
[<ffffffff8028ded3>] __fput+0xb3/0x1a0
[<ffffffff8028e1d6>] fput+0x16/0x20
[<ffffffff8028afab>] filp_close+0x4b/0x80
[<ffffffff80232171>] put_files_struct+0xc1/0xd0
[<ffffffff802321c5>] __exit_files+0x45/0x50
[<ffffffff80233592>] do_exit+0x1a2/0x7a0
[<ffffffff80233bc7>] do_group_exit+0x37/0xa0
[<ffffffff8023ccf8>] get_signal_to_deliver+0x268/0x330
[<ffffffff8020b614>] ? sysret_signal+0x1c/0x27
[<ffffffff8020a814>] do_notify_resume+0xd4/0x950
[<ffffffff80244ba0>] ? finish_wait+0x60/0x80
[<ffffffff802f112a>] ? bsg_get_done_cmd+0x11a/0x140
[<ffffffff802f1f8a>] ? bsg_read+0xda/0x180
[<ffffffff8028d5f4>] ? vfs_read+0xc4/0x150
[<ffffffff8020b614>] ? sysret_signal+0x1c/0x27
[<ffffffff8020b8a7>] ptregscall_common+0x67/0xb0
Meanwhile, in another shell, use iscsiadm to logout from the target. As
scsi removes the device, it tells bsg to unregister the queue that is
going away, and to do that, it needs the bsg_mutex. You have to be
fairly quick about it to get into this situation.
iscsi_scan_4 D ffffffff804ff688 0 2873 2
ffff81007c421cd0 0000000000000046 000001a800000002 fffffffffffffffc
ffff81007c1690c0 ffff81007e4c8830 ffff81007c1692d8 0000000000015d6d
0000015400000002 fffffffffffffffc 0000000000015e4c 0000016400000002
Call Trace:
[<ffffffff804052ff>] __mutex_lock_slowpath+0x7f/0xd0
[<ffffffff804050be>] mutex_lock+0xe/0x10
[<ffffffff802f1d81>] bsg_unregister_queue+0x31/0xa0
[<ffffffff8036b300>] __scsi_remove_device+0x40/0xa0
[<ffffffff8036b38b>] scsi_remove_device+0x2b/0x40
[<ffffffff8036b43c>] __scsi_remove_target+0x9c/0xe0
[<ffffffff8036b4e0>] ? __remove_child+0x0/0x30
[<ffffffff8036b4fe>] __remove_child+0x1e/0x30
[<ffffffff80355f93>] device_for_each_child+0x33/0x60
[<ffffffff802fafea>] ? kobject_get+0x1a/0x30
[<ffffffff8036b4ce>] scsi_remove_target+0x4e/0x60
[<ffffffff880f1d15>] :scsi_transport_iscsi:__iscsi_unbind_session+0x85/0xa0
[<ffffffff880f1c90>] ? :scsi_transport_iscsi:__iscsi_unbind_session+0x0/0xa0
[<ffffffff80240c64>] run_workqueue+0x84/0x110
[<ffffffff80241713>] worker_thread+0x93/0xd0
[<ffffffff80244ad0>] ? autoremove_wake_function+0x0/0x40
[<ffffffff80241680>] ? worker_thread+0x0/0xd0
[<ffffffff8024466d>] kthread+0x4d/0x80
[<ffffffff8020c3b8>] child_rip+0xa/0x12
[<ffffffff80244620>] ? kthread+0x0/0x80
[<ffffffff8020c3ae>] ? child_rip+0x0/0x12
Same setup as the bug 1/3.
-- Pete
Here's a different oops that may happen when the target goes away
unexpectedly. Mount a slow target with iscsi. Start a process that
uses bsg to issue an oustanding command, kill off the target before it
can respond (or unplug the network), but do not ctrl-C the bsg process.
In another shell, use iscsiadm to logout. This provokes a kref
complaint and a bug. The bug looks like the bsg app has seen completion
in error of its hung command, issues andother command, and ends up with
a NULL sdev later in the SCSI processing.
WARNING: at lib/kref.c:43 kref_get+0x2d/0x30()
Modules linked in: crc32c libcrc32c rdma_ucm rdma_cm iw_cm ib_addr ib_ipoib ib_ucm ib_cm ib_sa ib_umad ib_uverbs ib_mthca iscsi_tcp libiscsi scsi_transport_iscsi ext3 jbd ib_mad sg ib_core sd_mod i2c_nforce2 i2c_core sata_nv tg3 nfs lockd sunrpc
Pid: 3045, comm: sgio Not tainted 2.6.25-rc4-bidi-pw #29
Call Trace:
[<ffffffff8022f82f>] warn_on_slowpath+0x5f/0x80
[<ffffffff802ea243>] ? get_request+0x153/0x330
[<ffffffff80247d26>] ? hrtimer_start+0xd6/0x150
[<ffffffff80239b96>] ? lock_timer_base+0x36/0x70
[<ffffffff802fc07d>] kref_get+0x2d/0x30
[<ffffffff802fafea>] kobject_get+0x1a/0x30
[<ffffffff803559f7>] get_device+0x17/0x20
[<ffffffff80367357>] scsi_request_fn+0x37/0x3b0
[<ffffffff802e9d94>] __generic_unplug_device+0x24/0x30
[<ffffffff802ece63>] blk_execute_rq_nowait+0x63/0x90
[<ffffffff802f1b48>] bsg_write+0x188/0x2e0
[<ffffffff8028d4a7>] vfs_write+0xc7/0x150
[<ffffffff8028db10>] sys_write+0x50/0x90
[<ffffffff8020b58b>] system_call_after_swapgs+0x7b/0x80
---[ end trace dbc99ed69e02749c ]---
BUG: unable to handle kernel NULL pointer dereference at 0000000000000420
IP: [<ffffffff8036513c>] scsi_prep_state_check+0xc/0xb0
PGD 3d111067 PUD 3e9b3067 PMD 0
Oops: 0000 [1] SMP
CPU 0
Modules linked in: crc32c libcrc32c rdma_ucm rdma_cm iw_cm ib_addr ib_ipoib ib_ucm ib_cm ib_sa ib_umad ib_uverbs ib_mthca iscsi_tcp libiscsi scsi_transport_iscsi ext3 jbd ib_mad sg ib_core sd_mod i2c_nforce2 i2c_core sata_nv tg3 nfs lockd sunrpc
Pid: 3045, comm: sgio Not tainted 2.6.25-rc4-bidi-pw #29
RIP: 0010:[<ffffffff8036513c>] [<ffffffff8036513c>] scsi_prep_state_check+0xc/0xb0
RSP: 0018:ffff81007f5dfd68 EFLAGS: 00010092
RAX: ffffffff80366150 RBX: 0000000000000000 RCX: 0000000000000001
RDX: 0000000000000001 RSI: ffff81003fdcd3e0 RDI: 0000000000000000
RBP: ffff81007f5dfd78 R08: 0000000000000000 R09: 00000000ffffffff
R10: 0000000000000000 R11: 0000000000000020 R12: 0000000000000000
R13: ffff81007e4ed800 R14: ffff81007c8b94e8 R15: 0000000000000001
FS: 00007f34d7ad96f0(0000) GS:ffffffff80515000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: 0000000000000420 CR3: 000000003d0e0000 CR4: 00000000000006e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Process sgio (pid: 3045, threadinfo ffff81007f5de000, task ffff81007e4977b0)
Stack: 0000000100000000 ffff81003fdcd3e0 ffff81007f5dfda8 ffffffff80365fd8
ffff81007f5dfdb8 ffff81003fdcd3e0 ffff81007c8b94e8 ffff81007e4ed800
ffff81007f5dfdc8 ffffffff80366195 ffff81007c8b94e8 ffff81003fdcd3e0
Call Trace:
[<ffffffff80365fd8>] scsi_setup_blk_pc_cmnd+0x18/0x190
[<ffffffff80366195>] scsi_prep_fn+0x45/0x50
[<ffffffff802e7809>] elv_next_request+0xc9/0x280
[<ffffffff802fafea>] ? kobject_get+0x1a/0x30
[<ffffffff80367529>] scsi_request_fn+0x209/0x3b0
[<ffffffff802e9d94>] __generic_unplug_device+0x24/0x30
[<ffffffff802ece63>] blk_execute_rq_nowait+0x63/0x90
[<ffffffff802f1b48>] bsg_write+0x188/0x2e0
[<ffffffff8028d4a7>] vfs_write+0xc7/0x150
[<ffffffff8028db10>] sys_write+0x50/0x90
[<ffffffff8020b58b>] system_call_after_swapgs+0x7b/0x80
Code: 0a 00 4c 89 f7 48 89 45 d0 e8 a1 a4 ff ff eb ab 66 66 66 66 66 66 2e 0f 1f 84 00 00 00 00 00 55 48 89 e5 53 48 89 fb 48 83 ec 08 <8b> 87 20 04 00 00 83 f8 02 75 09 31 c0 48 83 c4 08 5b c9 c3 83
RIP [<ffffffff8036513c>] scsi_prep_state_check+0xc/0xb0
RSP <ffff81007f5dfd68>
CR2: 0000000000000420
---[ end trace dbc99ed69e02749c ]---
Same setup as the bug 1/3.
-- Pete