[ 3893.423052] run fstests btrfs/159 at 2022-04-02 21:56:21
[ 3893.641782] BTRFS info (device dm-0): flagging fs with big metadata feature
[ 3893.642126] BTRFS info (device dm-0): using free space tree
[ 3893.642428] BTRFS info (device dm-0): has skinny extents
[ 3893.882481] BTRFS: device fsid ade0a402-eeb8-4380-a566-fc5770d7fe91 devid 1 transid 6 /dev/mapper/vg0-lv9 scanned by mkfs.btrfs (488891)
[ 3893.965528] BTRFS info (device dm-11): flagging fs with big metadata feature
[ 3893.965777] BTRFS info (device dm-11): turning on async discard
[ 3893.965977] BTRFS info (device dm-11): disk space caching is enabled
[ 3893.966208] BTRFS info (device dm-11): has skinny extents
[ 3893.968387] BTRFS info (device dm-11): checking UUID tree
[ 3898.275225] BTRFS info: devid 1 device path /dev/mapper/flakey-test changed to /dev/dm-11 scanned by systemd-udevd (490603)
[ 3898.276152] BTRFS info: devid 1 device path /dev/dm-11 changed to /dev/mapper/flakey-test scanned by systemd-udevd (490603)
[ 3898.392148] BTRFS info (device dm-11): flagging fs with big metadata feature
[ 3898.392390] BTRFS info (device dm-11): turning on async discard
[ 3898.392587] BTRFS info (device dm-11): disk space caching is enabled
[ 3898.392795] BTRFS info (device dm-11): has skinny extents
[ 3898.395031] BTRFS info (device dm-11): start tree-log replay
[ 3899.875127] BUG: sleeping function called from invalid context at block/blk-sysfs.c:766
[ 3899.875416] in_atomic(): 1, irqs_disabled(): 0, non_block: 0, pid: 490603, name: systemd-udevd
[ 3899.875706] preempt_count: 101, expected: 0
[ 3899.875868] RCU nest depth: 0, expected: 0
[ 3899.876031] INFO: lockdep is turned off.
[ 3899.876210] Preemption disabled at:
[ 3899.876211] [] percpu_counter_add_batch+0x1b/0xb0
[ 3899.876575] CPU: 0 PID: 490603 Comm: systemd-udevd Tainted: G        W         5.17.0+ #640
[ 3899.876862] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.13.0-2.fc32 04/01/2014
[ 3899.877152] Call Trace:
[ 3899.877285]  
[ 3899.877406]  dump_stack_lvl+0x56/0x6f
[ 3899.877561]  __might_resched.cold+0xff/0x13a
[ 3899.877732]  blk_release_queue+0x24/0x120
[ 3899.877895]  kobject_put+0x7c/0x1d0
[ 3899.878047]  ? rcu_do_batch+0x1ac/0x570
[ 3899.878205]  blkg_free.part.0+0x41/0x60
[ 3899.878357]  rcu_do_batch+0x1e1/0x570
[ 3899.878526]  ? rcu_do_batch+0x1ac/0x570
[ 3899.878682]  rcu_core+0x2cb/0x460
[ 3899.878826]  __do_softirq+0x178/0x517
[ 3899.878980]  __irq_exit_rcu+0xe3/0x160
[ 3899.879132]  irq_exit_rcu+0xa/0x20
[ 3899.879275]  sysvec_apic_timer_interrupt+0xa2/0xd0
[ 3899.879458]  
[ 3899.879584]  
[ 3899.879711]  asm_sysvec_apic_timer_interrupt+0x12/0x20
[ 3899.879886] RIP: 0010:rcu_read_lock_sched_held+0x7/0x60
[ 3899.880064] Code: 00 66 90 0f 1f 44 00 00 9c 58 0f 1f 40 00 48 c1 e8 09 48 83 f0 01 83 e0 01 c3 66 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 41 54 <41> bc 01 00 00 00 e8 4e db c4 00 85 c0 75 06 44 89 e0 41 5c c3 e8
[ 3899.880638] RSP: 0018:ffffb18fc2e2bc50 EFLAGS: 00000283
[ 3899.880889] RAX: 0000000000000000 RBX: ffff9e5a3730c258 RCX: 0000000000000000
[ 3899.881097] RDX: 0000000000000000 RSI: ffffffffb73c8f5d RDI: ffffffffb8c8c120
[ 3899.881443] RBP: ffffffffb8c8c120 R08: 0000000000000001 R09: 0000000000000000
[ 3899.881688] R10: ffff9e59d389f308 R11: ffff9e59d6131320 R12: ffff9e59d6af5258
[ 3899.881924] R13: 0000000000000cc0 R14: ffffffffb73c8f5d R15: 0000000000000cc0
[ 3899.882148]  ? fs_reclaim_acquire+0x4d/0xd0
[ 3899.882308]  ? fs_reclaim_acquire+0x4d/0xd0
[ 3899.882488]  lock_release+0x1ed/0x2c0
[ 3899.882646]  ? anon_vma_fork+0xa5/0x180
[ 3899.882799]  kmem_cache_alloc+0x30/0x3f0
[ 3899.882958]  anon_vma_fork+0xa5/0x180
[ 3899.883112]  dup_mm+0x461/0x610
[ 3899.883256]  copy_process+0x134f/0x1e90
[ 3899.883410]  kernel_clone+0x8b/0x3c0
[ 3899.883561]  ? rcu_read_lock_sched_held+0x12/0x60
[ 3899.883733]  ? rcu_read_lock_sched_held+0x12/0x60
[ 3899.883900]  ? lock_acquire+0x176/0x2d0
[ 3899.884055]  ? __seccomp_filter+0x38b/0x5d0
[ 3899.884219]  __do_sys_clone+0x52/0x60
[ 3899.884370]  do_syscall_64+0x38/0x90
[ 3899.884520]  entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 3899.884706] RIP: 0033:0x7f31a71030df
[ 3899.884860] Code: ed 0f 85 f4 00 00 00 64 4c 8b 0c 25 10 00 00 00 45 31 c0 4d 8d 91 d0 02 00 00 31 d2 31 f6 bf 11 00 20 01 b8 38 00 00 00 0f 05 <48> 3d 00 f0 ff ff 0f 87 8d 00 00 00 41 89 c5 85 c0 0f 85 9a 00 00
[ 3899.885355] RSP: 002b:00007ffd27b249b0 EFLAGS: 00000246 ORIG_RAX: 0000000000000038
[ 3899.885623] RAX: ffffffffffffffda RBX: 0000000000000045 RCX: 00007f31a71030df
[ 3899.885829] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000001200011
[ 3899.886034] RBP: 0000000000000000 R08: 0000000000000000 R09: 00007f31a6269380
[ 3899.886237] R10: 00007f31a6269650 R11: 0000000000000246 R12: 0000000000000000
[ 3899.886440] R13: 00007ffd27b24a80 R14: 0000000000000040 R15: 00007ffd27b24a00
[ 3899.886650]  
[ 3900.005244] BTRFS: device fsid 5af8d5a0-34ce-4eda-b13e-75f16867a4c7 devid 1 transid 6 /dev/mapper/vg0-lv9 scanned by mkfs.btrfs (490645)
[ 3900.076120] BTRFS info (device dm-11): flagging fs with big metadata feature
[ 3900.076351] BTRFS info (device dm-11): turning on async discard
[ 3900.076531] BTRFS info (device dm-11): disk space caching is enabled
[ 3900.076722] BTRFS info (device dm-11): has skinny extents
[ 3900.078862] BTRFS info (device dm-11): checking UUID tree
[ 3904.285452] BTRFS info: devid 1 device path /dev/mapper/flakey-test changed to /dev/dm-11 scanned by systemd-udevd (492357)
[ 3904.286481] BTRFS info: devid 1 device path /dev/dm-11 changed to /dev/mapper/flakey-test scanned by systemd-udevd (492357)
[ 3904.398733] BTRFS info (device dm-11): flagging fs with big metadata feature
[ 3904.398979] BTRFS info (device dm-11): turning on async discard
[ 3904.407543] BTRFS info (device dm-11): disk space caching is enabled
[ 3904.407761] BTRFS info (device dm-11): has skinny extents
[ 3904.409711] BTRFS info (device dm-11): start tree-log replay
[ 3905.588088] BUG: sleeping function called from invalid context at block/blk-sysfs.c:766
[ 3905.588422] in_atomic(): 1, irqs_disabled(): 0, non_block: 0, pid: 14, name: ksoftirqd/0
[ 3905.588741] preempt_count: 100, expected: 0
[ 3905.588899] RCU nest depth: 0, expected: 0
[ 3905.589077] INFO: lockdep is turned off.
[ 3905.589256] Preemption disabled at:
[ 3905.589258] [] __do_softirq+0x5e/0x517
[ 3905.589617] CPU: 0 PID: 14 Comm: ksoftirqd/0 Tainted: G        W         5.17.0+ #640
[ 3905.589901] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.13.0-2.fc32 04/01/2014
[ 3905.590174] Call Trace:
[ 3905.590325]  
[ 3905.590468]  dump_stack_lvl+0x56/0x6f
[ 3905.590658]  __might_resched.cold+0xff/0x13a
[ 3905.590833]  blk_release_queue+0x24/0x120
[ 3905.590991]  kobject_put+0x7c/0x1d0
[ 3905.591137]  ? rcu_do_batch+0x1ac/0x570
[ 3905.591292]  blkg_free.part.0+0x41/0x60
[ 3905.591446]  rcu_do_batch+0x1e1/0x570
[ 3905.591599]  ? rcu_do_batch+0x1ac/0x570
[ 3905.591762]  rcu_core+0x2cb/0x460
[ 3905.591911]  __do_softirq+0x178/0x517
[ 3905.592063]  ? smpboot_thread_fn+0x2c/0x270
[ 3905.592224]  run_ksoftirqd+0x43/0x70
[ 3905.592374]  smpboot_thread_fn+0x1c1/0x270
[ 3905.592531]  ? sort_range+0x20/0x20
[ 3905.592687]  kthread+0xf0/0x120
[ 3905.592829]  ? kthread_complete_and_exit+0x20/0x20
[ 3905.593000]  ret_from_fork+0x1f/0x30
[ 3905.593151]