On Apr 20, 2022 / 17:34, Ming Lei wrote:
> On Wed, Apr 20, 2022 at 01:59:11PM +0900, Shin'ichiro Kawasaki wrote:
> > The test case block/002 checks that device removal during blktrace run
> > does not leak debugfs directory. The Linux kernel commit 0a9a25ca7843
> > ("block: let blkcg_gq grab request queue's refcnt") triggered failure of
> > the test case. The commit delayed queue release and debugfs directory
> > removal then the test case checks directory existence too early. To
> > avoid this false-positive failure, delay the directory existence check.
> >
> > Signed-off-by: Shin'ichiro Kawasaki <shinichiro.kawasaki@xxxxxxx>
> > ---
> > tests/block/002 | 1 +
> > 1 file changed, 1 insertion(+)
> >
> > diff --git a/tests/block/002 b/tests/block/002
> > index 9b183e7..8061c91 100755
> > --- a/tests/block/002
> > +++ b/tests/block/002
> > @@ -29,6 +29,7 @@ test() {
> > echo "debugfs directory deleted with blktrace active"
> > fi
> > { kill $!; wait; } >/dev/null 2>/dev/null
> > + sleep 0.5
> > if [[ -d /sys/kernel/debug/block/${SCSI_DEBUG_DEVICES[0]} ]]; then
> > echo "debugfs directory leaked"
> > fi
>
> Hello,
>
> Jens has merged Yu Kuai's fix[1], so I think it won't be triggered now.
>
>
> [1] https://git.kernel.org/pub/scm/linux/kernel/git/axboe/linux-block.git/commit/?h=block-5.18&id=a87c29e1a85e64b28445bb1e80505230bf2e3b4b
Hi Ming, I applied the patch above on top of v5.18-rc3 and ran block/002.
Unfortunately, it failed with a new symptom with KASAN use-after-free [2]. I
ran block/002 with linux-block/block-5.18 branch tip with git hash a87c29e1a85e
and got the same KASAN uaf. Reverting the patch from the linux-block/block-5.18
branch, the KASAN uaf disappears (Still block/002 fails). Regarding block/002,
it looks the patch made the failure symptom worse.
[2]
[ 466.424358] run blktests block/002 at 2022-04-20 19:44:02
[ 466.508847] scsi_debug:sdebug_driver_probe: scsi_debug: trim poll_queues to 0. poll_q/nr_hw = (0/1)
[ 466.518617] scsi host7: scsi_debug: version 0191 [20210520]
dev_size_mb=8, opts=0x0, submit_queues=1, statistics=0
[ 466.535080] scsi 7:0:0:0: Direct-Access Linux scsi_debug 0191 PQ: 0 ANSI: 7
[ 466.548701] sd 7:0:0:0: Power-on or device reset occurred
[ 466.549819] sd 7:0:0:0: Attached scsi generic sg9 type 0
[ 466.557985] sd 7:0:0:0: [sdi] 16384 512-byte logical blocks: (8.39 MB/8.00 MiB)
[ 466.570116] sd 7:0:0:0: [sdi] Write Protect is off
[ 466.575644] sd 7:0:0:0: [sdi] Mode Sense: 73 00 10 08
[ 466.577821] sd 7:0:0:0: [sdi] Write cache: enabled, read cache: enabled, supports DPO and FUA
[ 466.590343] sd 7:0:0:0: [sdi] Optimal transfer size 524288 bytes
[ 466.645516] sd 7:0:0:0: [sdi] Attached SCSI disk
[ 467.438285] sd 7:0:0:0: [sdi] Synchronizing SCSI cache
[ 467.458790] ==================================================================
[ 467.466714] BUG: KASAN: use-after-free in __lock_acquire+0x396b/0x5030
[ 467.473951] Read of size 8 at addr ffff888104e05248 by task check/1549
[ 467.483373] CPU: 1 PID: 1549 Comm: check Not tainted 5.18.0-rc3+ #24
[ 467.490426] Hardware name: Supermicro X10SLL-F/X10SLL-F, BIOS 3.0 04/24/2015
[ 467.498164] Call Trace:
[ 467.501313] <TASK>
[ 467.504120] dump_stack_lvl+0x56/0x6f
[ 467.508488] print_report.cold+0x5e/0x5db
[ 467.513205] ? __lock_acquire+0x396b/0x5030
[ 467.518092] kasan_report+0xbf/0xf0
[ 467.522288] ? lockdep_lock+0x30/0x1a0
[ 467.526738] ? __lock_acquire+0x396b/0x5030
[ 467.531630] __lock_acquire+0x396b/0x5030
[ 467.536346] ? lockdep_unlock+0xf2/0x240
[ 467.540970] ? __lock_acquire+0x23db/0x5030
[ 467.545861] ? lockdep_hardirqs_on_prepare+0x410/0x410
[ 467.551705] lock_acquire+0x19a/0x4b0
[ 467.556068] ? lockref_get+0x9/0x40
[ 467.560264] ? lock_release+0x6c0/0x6c0
[ 467.564806] ? lock_is_held_type+0xe2/0x140
[ 467.569693] ? find_held_lock+0x2c/0x110
[ 467.574316] ? lock_release+0x3a7/0x6c0
[ 467.578856] _raw_spin_lock+0x2f/0x40
[ 467.583222] ? lockref_get+0x9/0x40
[ 467.587414] lockref_get+0x9/0x40
[ 467.591439] simple_recursive_removal+0x36/0x7e0
[ 467.596758] ? debugfs_remove+0x60/0x60
[ 467.601300] ? do_raw_spin_unlock+0x55/0x1f0
[ 467.606278] debugfs_remove+0x40/0x60
[ 467.610643] blk_mq_debugfs_unregister_queue_rqos+0x34/0x70
[ 467.616919] rq_qos_exit+0x1b/0xf0
[ 467.621028] ? sysfs_file_ops+0x170/0x170
[ 467.625740] blk_cleanup_queue+0xfd/0x1f0
[ 467.630449] __scsi_remove_device+0xdd/0x2b0
[ 467.635422] sdev_store_delete+0x83/0x120
[ 467.640137] kernfs_fop_write_iter+0x353/0x520
[ 467.645287] new_sync_write+0x2d9/0x500
[ 467.649827] ? new_sync_read+0x500/0x500
[ 467.654455] ? perf_msr_probe+0x1f0/0x280
[ 467.659170] ? lock_release+0x6c0/0x6c0
[ 467.663709] ? inode_security+0x54/0xf0
[ 467.668253] ? lock_is_held_type+0xe2/0x140
[ 467.673144] vfs_write+0x61c/0x910
[ 467.677250] ksys_write+0xe3/0x1a0
[ 467.681355] ? __ia32_sys_read+0xa0/0xa0
[ 467.685982] ? syscall_enter_from_user_mode+0x21/0x70
[ 467.691740] do_syscall_64+0x3b/0x90
[ 467.696018] entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 467.701772] RIP: 0033:0x7f2d0b701817
[ 467.706046] Code: 0f 00 f7 d8 64 89 02 48 c7 c0 ff ff ff ff eb b7 0f 1f 00 f3 0f 1e fa 64 8b 04 25 18 00 00 00 85 c0 75 10 b8 01 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 51 c3 48 83 ec 28 48 89 54 24 18 48 89 74 24
[ 467.725492] RSP: 002b:00007ffd37a645e8 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
[ 467.733762] RAX: ffffffffffffffda RBX: 0000000000000002 RCX: 00007f2d0b701817
[ 467.741596] RDX: 0000000000000002 RSI: 000055a23ecf4630 RDI: 0000000000000001
[ 467.749431] RBP: 000055a23ecf4630 R08: 0000000000000000 R09: 00007f2d0b7b64e0
[ 467.757267] R10: 00007f2d0b7b63e0 R11: 0000000000000246 R12: 0000000000000002
[ 467.765101] R13: 00007f2d0b7fb5a0 R14: 0000000000000002 R15: 00007f2d0b7fb7a0
[ 467.772945] </TASK>
[ 467.778033] Allocated by task 111:
[ 467.782141] kasan_save_stack+0x1e/0x40
[ 467.786681] __kasan_slab_alloc+0x90/0xc0
[ 467.791395] kmem_cache_alloc_lru+0x258/0x720
[ 467.796457] __d_alloc+0x31/0x960
[ 467.800477] d_alloc+0x44/0x200
[ 467.804326] d_alloc_parallel+0xca/0x1490
[ 467.809041] __lookup_slow+0x17f/0x3d0
[ 467.813495] lookup_one_len+0x10b/0x130
[ 467.818038] start_creating.part.0+0xf0/0x220
[ 467.823098] debugfs_create_dir+0x2f/0x460
[ 467.827901] blk_mq_debugfs_register_rqos+0x1fe/0x330
[ 467.833655] wbt_init+0x35e/0x630
[ 467.837676] blk_register_queue+0x26c/0x430
[ 467.842565] device_add_disk+0x639/0xd90
[ 467.847192] sd_probe+0x93f/0xf50
[ 467.851212] really_probe+0x3d7/0xa10
[ 467.855581] __driver_probe_device+0x2ab/0x460
[ 467.860721] driver_probe_device+0x49/0x120
[ 467.865610] __device_attach_driver+0x191/0x240
[ 467.870845] bus_for_each_drv+0x119/0x180
[ 467.875560] __device_attach_async_helper+0x172/0x210
[ 467.881314] async_run_entry_fn+0x95/0x500
[ 467.886115] process_one_work+0x7cf/0x12d0
[ 467.890915] worker_thread+0x5ac/0xec0
[ 467.895369] kthread+0x2a7/0x350
[ 467.899305] ret_from_fork+0x22/0x30
[ 467.905779] Freed by task 1588:
[ 467.909620] kasan_save_stack+0x1e/0x40
[ 467.914159] kasan_set_track+0x21/0x30
[ 467.918614] kasan_set_free_info+0x20/0x30
[ 467.923416] ____kasan_slab_free+0x167/0x1a0
[ 467.928391] slab_free_freelist_hook+0xd6/0x1b0
[ 467.933618] kmem_cache_free+0x138/0x640
[ 467.938246] rcu_do_batch+0x35f/0xd30
[ 467.942613] rcu_core+0x6de/0xbd0
[ 467.946636] __do_softirq+0x28a/0x8fd
[ 467.953194] Last potentially related work creation:
[ 467.958768] kasan_save_stack+0x1e/0x40
[ 467.963309] __kasan_record_aux_stack+0xb1/0xc0
[ 467.968544] call_rcu+0xb3/0xec0
[ 467.972478] __dentry_kill+0x3f2/0x560
[ 467.976934] dput+0x43a/0xa10
[ 467.980609] simple_recursive_removal+0x133/0x7e0
[ 467.986017] debugfs_remove+0x40/0x60
[ 467.990386] blk_unregister_queue+0x1e2/0x280
[ 467.995446] del_gendisk+0x2f0/0x7f0
[ 467.999728] sd_remove+0x85/0xf0
[ 468.003661] device_release_driver_internal+0x3c3/0x5a0
[ 468.009580] bus_remove_device+0x2a3/0x560
[ 468.014382] device_del+0x499/0xb60
[ 468.018575] __scsi_remove_device+0x21e/0x2b0
[ 468.023638] sdev_store_delete+0x83/0x120
[ 468.028353] kernfs_fop_write_iter+0x353/0x520
[ 468.033502] new_sync_write+0x2d9/0x500
[ 468.038033] vfs_write+0x61c/0x910
[ 468.042132] ksys_write+0xe3/0x1a0
[ 468.046242] do_syscall_64+0x3b/0x90
[ 468.050523] entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 468.058469] Second to last potentially related work creation:
[ 468.064912] kasan_save_stack+0x1e/0x40
[ 468.069442] __kasan_record_aux_stack+0xb1/0xc0
[ 468.074669] call_rcu+0xb3/0xec0
[ 468.078602] __dentry_kill+0x3f2/0x560
[ 468.083057] dput+0x43a/0xa10
[ 468.086732] step_into+0xbc2/0x1d50
[ 468.090917] path_openat+0x3bf/0x24b0
[ 468.095288] do_filp_open+0x197/0x3c0
[ 468.099655] do_sys_openat2+0xef/0x3c0
[ 468.104109] __x64_sys_openat+0x109/0x1a0
[ 468.108825] do_syscall_64+0x3b/0x90
[ 468.113105] entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 468.121054] The buggy address belongs to the object at ffff888104e051a0
which belongs to the cache dentry of size 312
[ 468.134522] The buggy address is located 168 bytes inside of
312-byte region [ffff888104e051a0, ffff888104e052d8)
[ 468.149836] The buggy address belongs to the physical page:
[ 468.156102] page:00000000fe687ef7 refcount:1 mapcount:0 mapping:0000000000000000 index:0x0 pfn:0x104e04
[ 468.166191] head:00000000fe687ef7 order:1 compound_mapcount:0 compound_pincount:0
[ 468.174361] memcg:ffff888130bd2801
[ 468.178461] flags: 0x17ffffc0010200(slab|head|node=0|zone=2|lastcpupid=0x1fffff)
[ 468.186549] raw: 0017ffffc0010200 ffffea0004a5fd80 dead000000000002 ffff88810025cdc0
[ 468.194990] raw: 0000000000000000 0000000000150015 00000001ffffffff ffff888130bd2801
[ 468.203430] page dumped because: kasan: bad access detected
[ 468.211891] Memory state around the buggy address:
[ 468.217375] ffff888104e05100: 00 00 00 00 00 00 00 00 00 00 00 00 fc fc fc fc
[ 468.225298] ffff888104e05180: fc fc fc fc fa fb fb fb fb fb fb fb fb fb fb fb
[ 468.233221] >ffff888104e05200: fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb
[ 468.241138] ^
[ 468.247406] ffff888104e05280: fb fb fb fb fb fb fb fb fb fb fb fc fc fc fc fc
[ 468.255328] ffff888104e05300: fc fc fc 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 468.263247] ==================================================================
[ 468.271160] Disabling lock debugging due to kernel taint
[ 469.094627] BUG: kernel NULL pointer dereference, address: 00000000000000e0
[ 469.102295] #PF: supervisor write access in kernel mode
[ 469.108221] #PF: error_code(0x0002) - not-present page
[ 469.114064] PGD 0 P4D 0
[ 469.117304] Oops: 0002 [#1] PREEMPT SMP KASAN PTI
[ 469.122704] CPU: 2 PID: 1549 Comm: check Tainted: G B 5.18.0-rc3+ #24
[ 469.131138] Hardware name: Supermicro X10SLL-F/X10SLL-F, BIOS 3.0 04/24/2015
[ 469.138884] RIP: 0010:down_write+0xb1/0x130
[ 469.143773] Code: 00 00 00 48 c7 44 24 28 00 00 00 00 e8 98 de 50 fe be 08 00 00 00 48 8d 7c 24 28 e8 89 de 50 fe ba 01 00 00 00 48 8b 44 24 28 <f0> 48 0f b1 55 00 0f 94 c0 5a 84 c0 74 4b 4c 8d 6d 08 be 08 00 00
[ 469.163210] RSP: 0000:ffff8881963bfb50 EFLAGS: 00010246
[ 469.169139] RAX: 0000000000000000 RBX: 1ffff11032c77f6b RCX: ffffffff9b4379c7
[ 469.176975] RDX: 0000000000000001 RSI: 0000000000000008 RDI: ffff8881963bfb78
[ 469.184809] RBP: 00000000000000e0 R08: 0000000000000001 R09: ffff8881963bfb7f
[ 469.192643] R10: ffffed1032c77f6f R11: 0000000000000001 R12: dffffc0000000000
[ 469.200470] R13: 0000000000000000 R14: 0000000000000002 R15: 00000000000000e0
[ 469.208298] FS: 00007f2d0b884740(0000) GS:ffff8886ed900000(0000) knlGS:0000000000000000
[ 469.217084] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 469.223523] CR2: 00000000000000e0 CR3: 000000012ca86004 CR4: 00000000001706e0
[ 469.231358] Call Trace:
[ 469.234505] <TASK>
[ 469.237312] ? simple_recursive_removal+0x173/0x7e0
[ 469.242897] ? down_write_killable_nested+0x150/0x150
[ 469.248649] ? do_raw_spin_unlock+0x1a8/0x1f0
[ 469.253714] simple_recursive_removal+0x173/0x7e0
[ 469.259120] ? debugfs_remove+0x60/0x60
[ 469.263662] ? do_raw_spin_unlock+0x55/0x1f0
[ 469.268638] debugfs_remove+0x40/0x60
[ 469.273005] blk_mq_debugfs_unregister_queue_rqos+0x34/0x70
[ 469.279280] rq_qos_exit+0x1b/0xf0
[ 469.283388] ? sysfs_file_ops+0x170/0x170
[ 469.288099] blk_cleanup_queue+0xfd/0x1f0
[ 469.292817] __scsi_remove_device+0xdd/0x2b0
[ 469.297791] sdev_store_delete+0x83/0x120
[ 469.302506] kernfs_fop_write_iter+0x353/0x520
[ 469.307646] new_sync_write+0x2d9/0x500
[ 469.312187] ? new_sync_read+0x500/0x500
[ 469.316815] ? perf_msr_probe+0x1f0/0x280
[ 469.321529] ? lock_release+0x6c0/0x6c0
[ 469.326070] ? inode_security+0x54/0xf0
[ 469.330614] ? lock_is_held_type+0xe2/0x140
[ 469.335503] vfs_write+0x61c/0x910
[ 469.339611] ksys_write+0xe3/0x1a0
[ 469.343715] ? __ia32_sys_read+0xa0/0xa0
[ 469.348345] ? syscall_enter_from_user_mode+0x21/0x70
[ 469.354091] do_syscall_64+0x3b/0x90
[ 469.358370] entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 469.364126] RIP: 0033:0x7f2d0b701817
[ 469.368405] Code: 0f 00 f7 d8 64 89 02 48 c7 c0 ff ff ff ff eb b7 0f 1f 00 f3 0f 1e fa 64 8b 04 25 18 00 00 00 85 c0 75 10 b8 01 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 51 c3 48 83 ec 28 48 89 54 24 18 48 89 74 24
[ 469.387853] RSP: 002b:00007ffd37a645e8 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
[ 469.396113] RAX: ffffffffffffffda RBX: 0000000000000002 RCX: 00007f2d0b701817
[ 469.403949] RDX: 0000000000000002 RSI: 000055a23ecf4630 RDI: 0000000000000001
[ 469.411784] RBP: 000055a23ecf4630 R08: 0000000000000000 R09: 00007f2d0b7b64e0
[ 469.419618] R10: 00007f2d0b7b63e0 R11: 0000000000000246 R12: 0000000000000002
[ 469.427451] R13: 00007f2d0b7fb5a0 R14: 0000000000000002 R15: 00007f2d0b7fb7a0
[ 469.435299] </TASK>
[ 469.438191] Modules linked in: scsi_debug xt_CHECKSUM xt_MASQUERADE xt_conntrack ipt_REJECT nf_nat_tftp nf_conntrack_tftp bridge stp llc nft_objref nf_conntrack_netbios_ns nf_conntrack_broadcast nft_fib_inet nft_fib_ipv4 nft_fib_ipv6 nft_fib nft_reject_inet nf_reject_ipv4 nf_reject_ipv6 nft_reject nft_ct nft_chain_nat nf_tables ebtable_nat ebtable_broute ip6table_nat ip6table_mangle ip6table_raw ip6table_security iptable_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 iptable_mangle iptable_raw iptable_security rfkill target_core_user target_core_mod ip_set nfnetlink ebtable_filter ebtables ip6table_filter ip6_tables iptable_filter qrtr sunrpc intel_rapl_msr intel_rapl_common x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel iTCO_wdt intel_pmc_bxt at24 iTCO_vendor_support kvm irqbypass rapl intel_cstate joydev intel_uncore pcspkr intel_pch_thermal i2c_i801 i2c_smbus ses enclosure lpc_ich ie31200_edac video zram ip_tables crct10dif_pclmul crc32_pclmul
[ 469.438399] crc32c_intel ghash_clmulni_intel ast drm_vram_helper drm_kms_helper drm_ttm_helper ttm igb drm dca mpt3sas i2c_algo_bit e1000e raid_class scsi_transport_sas fuse
[ 469.540513] CR2: 00000000000000e0
[ 469.544603] ---[ end trace 0000000000000000 ]---
[ 469.662129] RIP: 0010:down_write+0xb1/0x130
[ 469.667027] Code: 00 00 00 48 c7 44 24 28 00 00 00 00 e8 98 de 50 fe be 08 00 00 00 48 8d 7c 24 28 e8 89 de 50 fe ba 01 00 00 00 48 8b 44 24 28 <f0> 48 0f b1 55 00 0f 94 c0 5a 84 c0 74 4b 4c 8d 6d 08 be 08 00 00
[ 469.686477] RSP: 0000:ffff8881963bfb50 EFLAGS: 00010246
[ 469.692414] RAX: 0000000000000000 RBX: 1ffff11032c77f6b RCX: ffffffff9b4379c7
[ 469.700266] RDX: 0000000000000001 RSI: 0000000000000008 RDI: ffff8881963bfb78
[ 469.708113] RBP: 00000000000000e0 R08: 0000000000000001 R09: ffff8881963bfb7f
[ 469.715959] R10: ffffed1032c77f6f R11: 0000000000000001 R12: dffffc0000000000
[ 469.723809] R13: 0000000000000000 R14: 0000000000000002 R15: 00000000000000e0
[ 469.731669] FS: 00007f2d0b884740(0000) GS:ffff8886ed900000(0000) knlGS:0000000000000000
[ 469.740476] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 469.746931] CR2: 00000000000000e0 CR3: 000000012ca86004 CR4: 00000000001706e0
--
Best Regards,
Shin'ichiro Kawasaki
