On 12/19/18 5:16 PM, Bart Van Assche wrote: > On Wed, 2018-12-19 at 16:27 -0700, Jens Axboe wrote: >> On 12/19/18 4:24 PM, Bart Van Assche wrote: >>> Hello, >>> >>> If I run the srp blktests in a loop then I see the below call stack appearing >>> sporadically. I have not yet had the time to analyze this but I'm reporting >>> this here in case someone else would already have had a look at this. >>> >>> Bart. >>> >>> ================================================================== >>> BUG: KASAN: use-after-free in bt_iter+0x86/0xf0 >>> Read of size 8 at addr ffff88803b335240 by task fio/21412 >>> >>> CPU: 0 PID: 21412 Comm: fio Tainted: G W 4.20.0-rc6-dbg+ #3 >>> Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014 >>> Call Trace: >>> dump_stack+0x86/0xca >>> print_address_description+0x71/0x239 >>> kasan_report.cold.5+0x242/0x301 >>> __asan_load8+0x54/0x90 >>> bt_iter+0x86/0xf0 >>> blk_mq_queue_tag_busy_iter+0x373/0x5e0 >>> blk_mq_in_flight+0x96/0xb0 >>> part_in_flight+0x40/0x140 >>> part_round_stats+0x18e/0x370 >>> blk_account_io_start+0x3d7/0x670 >>> blk_mq_bio_to_request+0x19c/0x3a0 >>> blk_mq_make_request+0x7a9/0xcb0 >>> generic_make_request+0x41d/0x960 >>> submit_bio+0x9b/0x250 >>> do_blockdev_direct_IO+0x435c/0x4c70 >>> __blockdev_direct_IO+0x79/0x88 >>> ext4_direct_IO+0x46c/0xc00 >>> generic_file_direct_write+0x119/0x210 >>> __generic_file_write_iter+0x11c/0x280 >>> ext4_file_write_iter+0x1b8/0x6f0 >>> aio_write+0x204/0x310 >>> io_submit_one+0x9d3/0xe80 >>> __x64_sys_io_submit+0x115/0x340 >>> do_syscall_64+0x71/0x210 >>> entry_SYSCALL_64_after_hwframe+0x49/0xbe >>> RIP: 0033:0x7f02cf043219 >> >> I've seen this one before as well, it's not a new thing. As far as I can >> tell, it's a false positive. There should be no possibility for a >> use-after-free iterating the static tags/requests. > > Are you sure this is a false positive? No I'm not, but the few times I have seen it, I haven't been able to make much sense of it. It goes back quite a bit. I have not yet encountered any false > positive KASAN complaints. According to the following gdb output this complaint > refers to reading rq->q: > > (gdb) list *(bt_iter+0x86) > 0xffffffff816b9346 is in bt_iter (block/blk-mq-tag.c:237). > 232 > 233 /* > 234 * We can hit rq == NULL here, because the tagging functions > 235 * test and set the bit before assigning ->rqs[]. > 236 */ > 237 if (rq && rq->q == hctx->queue) > 238 iter_data->fn(hctx, rq, iter_data->data, reserved); > 239 return true; > 240 } > 241 > > From the disassembly output: > > 232 > 233 /* > 234 * We can hit rq == NULL here, because the tagging functions > 235 * test and set the bit before assigning ->rqs[]. > 236 */ > 237 if (rq && rq->q == hctx->queue) > 0xffffffff816b9339 <+121>: test %r12,%r12 > 0xffffffff816b933c <+124>: je 0xffffffff816b935f <bt_iter+159> > 0xffffffff816b933e <+126>: mov %r12,%rdi > 0xffffffff816b9341 <+129>: callq 0xffffffff813bd3e0 <__asan_load8> > 0xffffffff816b9346 <+134>: lea 0x138(%r13),%rdi > 0xffffffff816b934d <+141>: mov (%r12),%r14 > 0xffffffff816b9351 <+145>: callq 0xffffffff813bd3e0 <__asan_load8> > 0xffffffff816b9356 <+150>: cmp 0x138(%r13),%r14 > 0xffffffff816b935d <+157>: je 0xffffffff816b936f <bt_iter+175> > > BTW, rq may but does not have to refer to tags->static_rqs[...]. It may also > refer to hctx->fq.flush_rq. But even those are persistent for the lifetime of the queue... But since kasan complains it belongs to a specific page, I'm guessing it's one of the regular requests since those are out of a chopped up page. Which means it makes even less sense. Is this happening while devices are being actively torn down? And are you using shared tags? That's the only way I could see this triggering. -- Jens Axboe
