warning: checkpointing journal with EXT4_IOC_CHECKPOINT_FLAG_ZEROOUT can be slow ====================================================== WARNING: possible circular locking dependency detected 6.1.0-rc4-next-20221110 #1 Not tainted ------------------------------------------------------ syz-executor.6/11631 is trying to acquire lock: ffff88800b130400 (&sb->s_type->i_mutex_key#6){++++}-{3:3}, at: ext4_bmap+0x52/0x470 but task is already holding lock: ffff88800960a3f8 (&journal->j_checkpoint_mutex){+.+.}-{3:3}, at: jbd2_journal_flush+0x48f/0xc10 which lock already depends on the new lock. the existing dependency chain (in reverse order) is: -> #3 (&journal->j_checkpoint_mutex){+.+.}-{3:3}: mutex_lock_io_nested+0x14c/0x1330 jbd2_journal_flush+0x19e/0xc10 __ext4_ioctl+0x9c1/0x4140 __x64_sys_ioctl+0x19e/0x210 do_syscall_64+0x3f/0x90 entry_SYSCALL_64_after_hwframe+0x72/0xdc -> #2 (&journal->j_barrier){+.+.}-{3:3}: __mutex_lock+0x136/0x14e0 jbd2_journal_lock_updates+0x162/0x310 ext4_change_inode_journal_flag+0x183/0x540 ext4_fileattr_set+0x142b/0x18c0 vfs_fileattr_set+0x780/0xb90 do_vfs_ioctl+0xfa6/0x15d0 __x64_sys_ioctl+0x110/0x210 do_syscall_64+0x3f/0x90 entry_SYSCALL_64_after_hwframe+0x72/0xdc -> #1 (&sbi->s_writepages_rwsem){++++}-{0:0}: percpu_down_write+0x51/0x350 ext4_ind_migrate+0x23b/0x830 ext4_fileattr_set+0x1452/0x18c0 vfs_fileattr_set+0x780/0xb90 do_vfs_ioctl+0xfa6/0x15d0 __x64_sys_ioctl+0x110/0x210 do_syscall_64+0x3f/0x90 entry_SYSCALL_64_after_hwframe+0x72/0xdc -> #0 (&sb->s_type->i_mutex_key#6){++++}-{3:3}: __lock_acquire+0x2a02/0x5e70 lock_acquire+0x1a6/0x530 down_read+0x9c/0x450 ext4_bmap+0x52/0x470 bmap+0xb0/0x130 jbd2_journal_bmap+0xac/0x190 jbd2_journal_flush+0x857/0xc10 __ext4_ioctl+0x9c1/0x4140 __x64_sys_ioctl+0x19e/0x210 do_syscall_64+0x3f/0x90 entry_SYSCALL_64_after_hwframe+0x72/0xdc other info that might help us debug this: Chain exists of: &sb->s_type->i_mutex_key#6 --> &journal->j_barrier --> &journal->j_checkpoint_mutex Possible unsafe locking scenario: CPU0 CPU1 ---- ---- lock(&journal->j_checkpoint_mutex); lock(&journal->j_barrier); lock(&journal->j_checkpoint_mutex); lock(&sb->s_type->i_mutex_key#6); *** DEADLOCK *** 2 locks held by syz-executor.6/11631: #0: ffff88800960a170 (&journal->j_barrier){+.+.}-{3:3}, at: jbd2_journal_lock_updates+0x162/0x310 #1: ffff88800960a3f8 (&journal->j_checkpoint_mutex){+.+.}-{3:3}, at: jbd2_journal_flush+0x48f/0xc10 stack backtrace: CPU: 1 PID: 11631 Comm: syz-executor.6 Not tainted 6.1.0-rc4-next-20221110 #1 Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.12.0-1 04/01/2014 Call Trace: dump_stack_lvl+0x8f/0xb7 check_noncircular+0x263/0x2e0 __lock_acquire+0x2a02/0x5e70 lock_acquire+0x1a6/0x530 down_read+0x9c/0x450 ext4_bmap+0x52/0x470 bmap+0xb0/0x130 jbd2_journal_bmap+0xac/0x190 jbd2_journal_flush+0x857/0xc10 __ext4_ioctl+0x9c1/0x4140 __x64_sys_ioctl+0x19e/0x210 do_syscall_64+0x3f/0x90 entry_SYSCALL_64_after_hwframe+0x72/0xdc RIP: 0033:0x7f5cd5d9db19 Code: ff ff c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 40 00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 c7 c1 bc ff ff ff f7 d8 64 89 01 48 RSP: 002b:00007f5cd3313188 EFLAGS: 00000246 ORIG_RAX: 0000000000000010 RAX: ffffffffffffffda RBX: 00007f5cd5eb0f60 RCX: 00007f5cd5d9db19 RDX: 0000000020000380 RSI: 000000004004662b RDI: 0000000000000003 RBP: 00007f5cd5df7f6d R08: 0000000000000000 R09: 0000000000000000 R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000 R13: 00007ffea6a6ecff R14: 00007f5cd3313300 R15: 0000000000022000 warning: checkpointing journal with EXT4_IOC_CHECKPOINT_FLAG_ZEROOUT can be slow netlink: 52 bytes leftover after parsing attributes in process `syz-executor.6'. netlink: 52 bytes leftover after parsing attributes in process `syz-executor.6'. netlink: 52 bytes leftover after parsing attributes in process `syz-executor.6'. SELinux: security_context_str_to_sid (system_u) failed with errno=-22 SELinux: security_context_str_to_sid (system_u) failed with errno=-22 SELinux: security_context_str_to_sid (system_u) failed with errno=-22 netlink: 52 bytes leftover after parsing attributes in process `syz-executor.6'. SELinux: security_context_str_to_sid (system_u) failed with errno=-22 SELinux: security_context_str_to_sid (system_u) failed with errno=-22 netlink: 52 bytes leftover after parsing attributes in process `syz-executor.6'. cgroup: fork rejected by pids controller in /syz5 audit: type=1400 audit(1668080143.093:24): avc: denied { map } for pid=11896 comm="syz-executor.1" path="pipe:[32537]" dev="pipefs" ino=32537 scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:system_r:kernel_t:s0 tclass=fifo_file permissive=1 perf: interrupt took too long (5188 > 5186), lowering kernel.perf_event_max_sample_rate to 38000 perf: interrupt took too long (10380 > 10316), lowering kernel.perf_event_max_sample_rate to 19000 UDC core: USB Raw Gadget: couldn't find an available UDC or it's busy misc raw-gadget: fail, usb_gadget_register_driver returned -16 UDC core: USB Raw Gadget: couldn't find an available UDC or it's busy misc raw-gadget: fail, usb_gadget_register_driver returned -16 loop0: detected capacity change from 0 to 264192 perf: interrupt took too long (13005 > 12975), lowering kernel.perf_event_max_sample_rate to 15000 perf: interrupt took too long (16281 > 16256), lowering kernel.perf_event_max_sample_rate to 12000 Bluetooth: hci1: Ignoring connect complete event for invalid link type loop0: detected capacity change from 0 to 264192 Bluetooth: hci1: Ignoring connect complete event for invalid link type perf: interrupt took too long (20356 > 20351), lowering kernel.perf_event_max_sample_rate to 9000 UDC core: USB Raw Gadget: couldn't find an available UDC or it's busy misc raw-gadget: fail, usb_gadget_register_driver returned -16 loop0: detected capacity change from 0 to 264192 UDC core: USB Raw Gadget: couldn't find an available UDC or it's busy misc raw-gadget: fail, usb_gadget_register_driver returned -16 UDC core: USB Raw Gadget: couldn't find an available UDC or it's busy misc raw-gadget: fail, usb_gadget_register_driver returned -16 loop0: detected capacity change from 0 to 264192 perf: interrupt took too long (25668 > 25445), lowering kernel.perf_event_max_sample_rate to 7000 loop0: detected capacity change from 0 to 264192