Re: BUG: KASAN: use-after-free in bt_for_each+0x1ea/0x29f

2018-04-05 Thread Bart Van Assche
On Wed, 2018-04-04 at 19:26 -0600, Jens Axboe wrote:
> Leaving the whole trace here, but I'm having a hard time making sense of it.
> It complains about a user-after-free in the inflight iteration, which is only
> working on the queue, request, and on-stack mi data. None of these would be
> freed. The below trace on allocation and free indicates a bio, but that isn't
> used in the inflight path at all. Is it possible that kasan gets confused 
> here?
> Not sure what to make of it so far.

Hello Jens,

In the many block layer tests I ran with KASAN enabled I have never seen
anything like this nor have I seen anything that made me wonder about the
reliability of KASAN. Maybe some code outside the block layer core corrupted
a request queue data structure and triggered this weird report?

Bart.





Re: BUG: KASAN: use-after-free in bt_for_each+0x1ea/0x29f

2018-04-04 Thread Jens Axboe
On 4/4/18 5:28 PM, Ming Lei wrote:
> Hi,
> 
> The following warning is observed once when running dbench on NVMe with
> the linus tree(top commit is 642e7fd23353).
> 
> [ 1446.882043] 
> ==
> [ 1446.886884] BUG: KASAN: use-after-free in bt_for_each+0x1ea/0x29f
> [ 1446.888045] Read of size 8 at addr 880055a60a00 by task dbench/13443
> [ 1446.889660]
> [ 1446.889892] CPU: 1 PID: 13443 Comm: dbench Not tainted 
> 4.16.0_642e7fd23353_master+ #1
> [ 1446.891007] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 
> 1.10.2-2.fc27 04/01/2014
> [ 1446.892290] Call Trace:
> [ 1446.892641]  
> [ 1446.892937]  dump_stack+0xf0/0x191
> [ 1446.893600]  ? dma_direct_map_page+0x6f/0x6f
> [ 1446.894425]  ? show_regs_print_info+0xa/0xa
> [ 1446.895247]  ? ext4_writepages+0x196d/0x1e6d
> [ 1446.896063]  ? do_writepages+0x57/0xa3
> [ 1446.896810]  print_address_description+0x6e/0x23b
> [ 1446.897882]  ? bt_for_each+0x1ea/0x29f
> [ 1446.898693]  kasan_report+0x247/0x285
> [ 1446.899484]  bt_for_each+0x1ea/0x29f
> [ 1446.900233]  ? blk_mq_tagset_busy_iter+0xa3/0xa3
> [ 1446.901190]  ? generic_file_buffered_read+0x14b1/0x14b1
> [ 1446.903097]  ? blk_mq_hctx_mark_pending.isra.0+0x5c/0x5c
> [ 1446.904418]  ? bio_free+0x64/0xaa
> [ 1446.905113]  ? debug_lockdep_rcu_enabled+0x26/0x52
> [ 1446.906332]  ? bio_put+0x7a/0x10e
> [ 1446.906811]  ? debug_lockdep_rcu_enabled+0x26/0x52
> [ 1446.907527]  ? blk_mq_hctx_mark_pending.isra.0+0x5c/0x5c
> [ 1446.908334]  blk_mq_queue_tag_busy_iter+0xd0/0xde
> [ 1446.909023]  blk_mq_in_flight+0xb4/0xdb
> [ 1446.909619]  ? blk_mq_exit_hctx+0x190/0x190
> [ 1446.910281]  ? ext4_end_bio+0x25d/0x2a1
> [ 1446.911713]  part_in_flight+0xc0/0x2ac
> [ 1446.912470]  ? ext4_put_io_end_defer+0x277/0x277
> [ 1446.913465]  ? part_dec_in_flight+0x8f/0x8f
> [ 1446.914375]  ? __lock_acquire+0x38/0x8e5
> [ 1446.915182]  ? bio_endio+0x3d9/0x41c
> [ 1446.915936]  ? __rcu_read_unlock+0x134/0x180
> [ 1446.916796]  ? lock_acquire+0x2ba/0x32d
> [ 1446.917570]  ? blk_account_io_done+0xea/0x572
> [ 1446.918424]  part_round_stats+0x167/0x1a3
> [ 1446.919188]  ? part_round_stats_single.isra.1+0xc7/0xc7
> [ 1446.920187]  blk_account_io_done+0x34d/0x572
> [ 1446.921056]  ? blk_update_bidi_request+0x8f/0x8f
> [ 1446.921923]  ? blk_mq_run_hw_queue+0x13d/0x187
> [ 1446.922803]  blk_mq_end_request+0x3f/0xbf
> [ 1446.923631]  nvme_complete_rq+0x305/0x348 [nvme_core]
> [ 1446.924612]  ? nvme_delete_ctrl_sync+0x5c/0x5c [nvme_core]
> [ 1446.925696]  ? nvme_pci_complete_rq+0x1f6/0x20c [nvme]
> [ 1446.926673]  ? kfree+0x21c/0x2ab
> [ 1446.927317]  ? nvme_pci_complete_rq+0x1f6/0x20c [nvme]
> [ 1446.928239]  __blk_mq_complete_request+0x391/0x3ee
> [ 1446.928938]  ? blk_mq_free_request+0x479/0x479
> [ 1446.929588]  ? rcu_read_lock_bh_held+0x3a/0x3a
> [ 1446.930321]  ? enqueue_hrtimer+0x252/0x29a
> [ 1446.930938]  ? do_raw_spin_lock+0xd8/0xd8
> [ 1446.931532]  ? debug_lockdep_rcu_enabled+0x26/0x52
> [ 1446.932425]  blk_mq_complete_request+0x10e/0x159
> [ 1446.933341]  ? hctx_lock+0xe8/0xe8
> [ 1446.933985]  ? lock_contended+0x680/0x680
> [ 1446.934707]  ? lock_downgrade+0x338/0x338
> [ 1446.935463]  nvme_process_cq+0x26a/0x34d [nvme]
> [ 1446.936297]  ? nvme_init_hctx+0xa6/0xa6 [nvme]
> [ 1446.937150]  nvme_irq+0x23/0x51 [nvme]
> [ 1446.937864]  ? nvme_process_cq+0x34d/0x34d [nvme]
> [ 1446.938713]  __handle_irq_event_percpu+0x29d/0x568
> [ 1446.939516]  ? __irq_wake_thread+0x99/0x99
> [ 1446.940241]  ? rcu_user_enter+0x72/0x72
> [ 1446.940978]  ? do_timer+0x25/0x25
> [ 1446.941650]  ? do_raw_spin_unlock+0x146/0x179
> [ 1446.942514]  ? __lock_acquire+0x38/0x8e5
> [ 1446.943305]  ? debug_lockdep_rcu_enabled+0x26/0x52
> [ 1446.944242]  ? lock_acquire+0x32d/0x32d
> [ 1446.944995]  ? lock_contended+0x680/0x680
> [ 1446.945718]  handle_irq_event_percpu+0x7c/0xf7
> [ 1446.946438]  ? __handle_irq_event_percpu+0x568/0x568
> [ 1446.947124]  ? rcu_user_exit+0xa/0xa
> [ 1446.947781]  handle_irq_event+0x53/0x83
> [ 1446.948553]  handle_edge_irq+0x1f2/0x279
> [ 1446.949397]  handle_irq+0x1d8/0x1e9
> [ 1446.950094]  do_IRQ+0x90/0x12d
> [ 1446.950750]  common_interrupt+0xf/0xf
> [ 1446.951507]  
> [ 1446.951953] RIP: 0010:__blk_mq_get_tag+0x201/0x22d
> [ 1446.952894] RSP: 0018:880055b467a0 EFLAGS: 0246 ORIG_RAX: 
> ffdc
> [ 1446.954295] RAX:  RBX: 88005952f648 RCX: 
> 
> [ 1446.955641] RDX: 0259 RSI:  RDI: 
> ed000ab68d06
> [ 1446.956972] RBP: ed000ab68cf6 R08: 0007 R09: 
> 
> [ 1446.958356] R10: ed000a0ec0f2 R11: ed000a0ec0f1 R12: 
> 88007f113978
> [ 1446.959737] R13: 880055b46ce8 R14: dc00 R15: 
> 880058bf60c0
> [ 1446.961184]  ? modules_open+0x5e/0x5e
> [ 1446.961922]  ? blk_mq_unique_tag+0xc5/0xc5
> [ 1446.962748]  ? lock_acquire+0x32d/0x32d
> [ 1446.963534]  ? __rcu_read_unlock+0x134/0x180
> [ 1446.964393]  ?