Re: [BUG] 2.6.39.1 crash in scsi_dispatch_cmd()

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



cc'ing Jens (full quote of the original bug report at the end).

I patched the SLUB debugging code so that it includes full call traces
instead of just the address of the caller of kfree/kmalloc. So here is
yet another incarnation of what I think is the same use-after-free bug:

What we can see here: while scsi_dispatch_cmd() operates on a scsi_cmnd
it gets freed via blk_done_softirq().
In this specific case scsi_send_log() crashes while trying to dereference
the SLAB/SLUB poison value.

[  952.532025] Unable to handle kernel pointer dereference at virtual kernel address 6b6b6b6b6b6b6000
[  952.532031] Oops: 0038 [#1] PREEMPT SMP DEBUG_PAGEALLOC
[  952.532038] Modules linked in: dm_round_robin dm_multipath scsi_dh sunrpc qeth_l3 binfmt_misc dm_mod ipv6 qeth ccwgroup [last unloaded: scsi_wait_scan]
[  952.532055] CPU: 0 Not tainted 2.6.39.1-50.0slubdbg.20110616-s390xdefault #1
[  952.532058] Process flush-252:1 (pid: 3993, task: 00000000b837a558, ksp: 000000009f1934f0)
[  952.532062] Krnl PSW : 0704100180000000 0000000000426dfc (scsi_print_command+0x44/0xf8)
[  952.532071]            R:0 T:1 IO:1 EX:1 Key:0 M:1 W:0 P:0 AS:0 CC:1 PM:0 EA:3
[  952.532075] Krnl GPRS: 0000000000000799 6b6b6b6b6b6b6b6b 000000008ac7c800 0000000000000001
[  952.532078]            00000000005a1c8e 00000000005b95b0 00000000af005ba8 00000000afc9f57f
[  952.532082]            000000008ac7c800 00000000afc9efa8 000000008ac7c800 000000008ac7c800
[  952.532085]            0000000000000004 00000000005f1bb0 000000009f1938a0 000000009f193870
[  952.532097] Krnl Code: 0000000000426dea: f0b80004ebbf        srp	4(12,%r0),3007(%r14),8
[  952.532102]            0000000000426df0: f0a0000407f4        srp	4(11,%r0),2036,0
[  952.532106]            0000000000426df6: e31020800004        lg	%r1,128(%r2)
[  952.532111]           >0000000000426dfc: e31010b00004        lg	%r1,176(%r1)
[  952.532115]            0000000000426e02: b9020011            ltgr	%r1,%r1
[  952.532118]            0000000000426e06: a7840032            brc	8,426e6a
[  952.532122]            0000000000426e0a: e33020000004        lg	%r3,0(%r2)
[  952.532127]            0000000000426e10: c04000165e8b        larl	%r4,6f2b26
[  952.532131] Call Trace:
[  952.532133] ([<000000008ac7c800>] 0x8ac7c800)
[  952.532136]  [<0000000000424f0c>] scsi_log_send+0xf0/0x130
[  952.532140]  [<0000000000425230>] scsi_dispatch_cmd+0xc8/0x29c
[  952.532144]  [<000000000042cf78>] scsi_request_fn+0x3b8/0x480
[  952.532149]  [<00000000003a78be>] blk_insert_cloned_request+0x72/0xcc
[  952.532154]  [<000003c0023f3466>] dm_dispatch_request+0x5a/0x94 [dm_mod]
[  952.532166]  [<000003c0023f5b0c>] dm_request_fn+0x1e4/0x208 [dm_mod]
[  952.532174]  [<00000000003aa512>] queue_unplugged.clone.27+0x3e/0x6c
[  952.532178]  [<00000000003ab284>] blk_flush_plug_list+0x1fc/0x290
[  952.532182]  [<00000000003ab342>] blk_finish_plug+0x2a/0x58
[  952.532185]  [<00000000001e9410>] generic_writepages+0x6c/0x94
[  952.532192]  [<000000000026abe0>] writeback_single_inode+0xf8/0x268
[  952.532198]  [<000000000026b13a>] writeback_sb_inodes+0xd2/0x18c
[  952.532202]  [<000000000026bcc0>] writeback_inodes_wb+0x80/0x168
[  952.532206]  [<000000000026c04e>] wb_writeback+0x2a6/0x320
[  952.532210]  [<000000000026c2f4>] wb_do_writeback+0x22c/0x270
[  952.532213]  [<000000000026c3ec>] bdi_writeback_thread+0xb4/0x1c0
[  952.532217]  [<0000000000169b3e>] kthread+0xa6/0xb0
[  952.532223]  [<00000000005a73ea>] kernel_thread_starter+0x6/0xc
[  952.532228]  [<00000000005a73e4>] kernel_thread_starter+0x0/0xc
[  952.532231] INFO: lockdep is turned off.
[  952.532233] Last Breaking-Event-Address:
[  952.532235]  [<0000000000426de4>] scsi_print_command+0x2c/0xf8

Debug call traces from the freed object:

free (on cpu 1):
000000000011bd5e save_stack_trace
00000000002290b4 process_slab
0000000000229514 free_debug_processing
00000000002298a8 __slab_free
0000000000229c30 kmem_cache_free
000000000042d400 scsi_next_command
000000000042d628 scsi_io_completion
00000000003b0238 blk_done_softirq
000000000014c110 __do_softirq
000000000010e2ce do_softirq
000000000014c570 irq_exit
00000000004689b8 do_IRQ
00000000005a7e70 io_return

alloc ([flush-252:1]):
000000000011bd82 save_stack_trace
00000000002290b4 process_slab
00000000002292e4 alloc_debug_processing
000000000022a574 new_slab
000000000022a926 kmem_cache_alloc
000000000042475e scsi_pool_alloc_command
000000000042490a scsi_host_alloc_command
000000000042499e __scsi_get_command
0000000000424a8e scsi_get_command
000000000042bda6 scsi_setup_fs_cmnd
0000000000440662 sd_prep_fn
00000000003aa97e blk_peek_request
000000000042cc28 scsi_request_fn
00000000003a78be blk_insert_cloned_request
000003c0023f3466 dm_dispatch_request
000003c0023f5b0c dm_request_fn
00000000003aa512 blk_end_request_cur
00000000003ab284 blk_flush_plug_list
00000000003ab342 blk_finish_plug
00000000001e9410 generic_writepages
000000000026abe0 writeback_single_inode
000000000026b13a writeback_sb_inodes
000000000026bcc0 writeback_inodes_wb
000000000026c04e wb_writeback
000000000026c2f4 wb_do_writeback
000000000026c3ec bdi_writeback_thread
0000000000169b3e kthread
00000000005a73ea kernel_thread_starter

On Wed, Jun 15, 2011 at 01:20:16PM +0200, Heiko Carstens wrote:
> Hi James,
> 
> while running some error recovery tests we encountered the following bug:
> 
> [23710.196446] Unable to handle kernel pointer dereference at virtual kernel address 6b6b6b6b6b6b6000
> [23710.196453] Oops: 0038 [#1] PREEMPT SMP DEBUG_PAGEALLOC
> [23710.196460] Modules linked in: dm_round_robin sunrpc qeth_l3 binfmt_misc dm_multipath scsi_dh dm_mod ipv6 vmur qeth ccwgroup [last unloaded: scsi_wait_scan]
> [23710.196477] CPU: 0 Not tainted 2.6.39.1-49.x.20110609-s390xdefault #1
> [23710.196480] Process kworker/u:5 (pid: 18534, task: 000000002f4d2368, ksp: 000000002f48f268)
> [23710.196483] Krnl PSW : 0704000180000000 000000000042407c (scsi_dispatch_cmd+0xd4/0x29c)
> [23710.196492]            R:0 T:1 IO:1 EX:1 Key:0 M:1 W:0 P:0 AS:0 CC:0 PM:0 EA:3
> [23710.196496] Krnl GPRS: 0280000000000000 6b6b6b6b6b6b6b6b 0000000000000060 0000000000006b6b
> [23710.196499]            00000000005a0ab2 000000002f4d2af0 00000000390d8090 000000002f611ac7
> [23710.196502]            000000003a764600 000000002f6114f0 000000003a764600 0000000000000000
> [23710.196505]            000000003a78e1b0 00000000005f0638 0000000000424070 000000002f48f530
> [23710.196516] Krnl Code: 000000000042406a: c0e5fffffdf9        brasl   %r14,423c5c
> [23710.196520]            0000000000424070: e310a0000004        lg      %r1,0(%r10)
> [23710.196525]            0000000000424076: e330a04a0091        llgh    %r3,74(%r10)
> [23710.196529]           >000000000042407c: e31010000004        lg      %r1,0(%r1)
> [23710.196533]            0000000000424082: e34012480091        llgh    %r4,584(%r1)
> [23710.196537]            0000000000424088: 1534                clr     %r3,%r4
> [23710.196541]            000000000042408a: a7240033            brc     2,4240f0
> [23710.196546]            000000000042408e: d503d008c2c0        clc     8(4,%r13),704(%r12)
> [23710.196549] Call Trace:
> [23710.196551] ([<0000000000424070>] scsi_dispatch_cmd+0xc8/0x29c)
> [23710.196555]  [<000000000042bdb8>] scsi_request_fn+0x3b8/0x480
> [23710.196560]  [<00000000003adfb6>] blk_execute_rq_nowait+0x76/0xd0
> [23710.196565]  [<00000000003ae0a6>] blk_execute_rq+0x96/0xe8
> [23710.196569]  [<000000000042af84>] scsi_execute+0x124/0x22c
> [23710.196573]  [<000000000042b1cc>] scsi_execute_req+0x140/0x148
> [23710.196577]  [<0000000000422f0c>] scsi_vpd_inquiry+0x80/0xac
> [23710.196580]  [<0000000000422f80>] scsi_get_vpd_page+0x48/0x108
> [23710.196584]  [<000000000043e240>] sd_revalidate_disk+0x984/0x1a6c
> [23710.196590]  [<00000000002b898e>] rescan_partitions+0xc6/0x594
> [23710.196596]  [<000000000027b1ca>] __blkdev_get+0x2f6/0x43c
> [23710.196602]  [<000000000027b358>] blkdev_get+0x48/0x38c
> [23710.196606]  [<00000000003b463e>] register_disk+0x182/0x19c
> [23710.196610]  [<00000000003b4758>] add_disk+0x100/0x2ac
> [23710.196614]  [<00000000004402bc>] sd_probe_async+0x118/0x1c8
> [23710.196618]  [<0000000000173168>] async_run_entry_fn+0x98/0x188
> [23710.196624]  [<000000000015ec5e>] process_one_work+0x1f6/0x4ec
> [23710.196630]  [<0000000000162a48>] worker_thread+0x17c/0x370
> [23710.196633]  [<0000000000168b7e>] kthread+0xa6/0xb0
> [23710.196637]  [<00000000005a61fa>] kernel_thread_starter+0x6/0xc
> [23710.196643]  [<00000000005a61f4>] kernel_thread_starter+0x0/0xc
> [23710.196646] INFO: lockdep is turned off.
> [23710.196648] Last Breaking-Event-Address:
> [23710.196650]  [<00000000005a0abc>] printk+0x5c/0x60
> 
> Testcase is multipath setup (dm) where I/O happens to these SCSI devices and
> while doing so randomly the channel paths to adapters get switched on and off.
> Each time a channel path to a adapter gets switched off this results into a
> call to fc_remote_port_delete() for each connected port of an adapter.
> 
> A short analysis for the call trace above: we use SLUB and have all debugging
> options turned on. The system crashed within scsi_dispatch_cmd() when it tried
> to derefence cmd->device in order to get the host pointer within this short
> code snippet:
> 
>         /*
>          * Before we queue this command, check if the command
>          * length exceeds what the host adapter can handle.
>          */
>         if (cmd->cmd_len > cmd->device->host->max_cmd_len) {
>                 SCSI_LOG_MLQUEUE(3,
> 
> The struct scsi_cmnd contains 0x6b which means it got freed and we have a
> use after free bug here. The interesting thing is that the code got so far
> into this function without crashing. Since there are several other places
> where derefencing happened before in the function (without crashing) this
> means that this piece of memory got freed while this function got executed
> (well, preemption is turned on, so maybe it got freed while being preempted).
> 
> SLUB caller tracking is turned on, which reveals that this piece of memory
> got freed by __scsi_put_command().
> 
> As far as I can tell, in this case the device driver cannot be blamed since
> the request in question didn't even reach the driver before it got freed and
> the system crashed.
> But of course I could be entirely wrong :)
> 
> Would you happen to have any ideas what could cause this bug?
> 
> FWIW, this is 2.6.39.1 which in addition contains
> e73e079bf128d68284efedeba1fbbc18d78610f9 "[SCSI] Fix oops caused by queue
> refcounting failure"
> 
> Thanks,
> Heiko
--
To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html


[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]
[Index of Archives]     [SCSI Target Devel]     [Linux SCSI Target Infrastructure]     [Kernel Newbies]     [IDE]     [Security]     [Git]     [Netfilter]     [Bugtraq]     [Yosemite News]     [MIPS Linux]     [ARM Linux]     [Linux Security]     [Linux RAID]     [Linux ATA RAID]     [Linux IIO]     [Samba]     [Device Mapper]
  Powered by Linux