warning: checkpointing journal with EXT4_IOC_CHECKPOINT_FLAG_ZEROOUT can be slow
======================================================
WARNING: possible circular locking dependency detected
6.1.0-rc5-next-20221114 #1 Not tainted
------------------------------------------------------
syz-executor.6/53694 is trying to acquire lock:
ffff8880088f8400 (&sb->s_type->i_mutex_key#6){++++}-{3:3}, at: ext4_bmap+0x52/0x470
but task is already holding lock:
ffff88801011e3f8 (&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:
-> #1 (&journal->j_checkpoint_mutex){+.+.}-{3:3}:
mutex_lock_io_nested+0x14c/0x1330
__jbd2_log_wait_for_space+0x238/0x460
add_transaction_credits+0xa42/0xb80
start_this_handle+0x3ac/0x14c0
jbd2__journal_start+0x394/0x8d0
__ext4_journal_start_sb+0x395/0x470
ext4_unlink+0x4e8/0x8c0
vfs_unlink+0x35e/0x930
do_unlinkat+0x398/0x620
__x64_sys_unlink+0xca/0x110
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+0x9b0/0x4340
__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:
Possible unsafe locking scenario:
CPU0 CPU1
---- ----
lock(&journal->j_checkpoint_mutex);
lock(&sb->s_type->i_mutex_key#6);
lock(&journal->j_checkpoint_mutex);
lock(&sb->s_type->i_mutex_key#6);
*** DEADLOCK ***
2 locks held by syz-executor.6/53694:
#0: ffff88801011e170 (&journal->j_barrier){+.+.}-{3:3}, at: jbd2_journal_lock_updates+0x162/0x310
#1: ffff88801011e3f8 (&journal->j_checkpoint_mutex){+.+.}-{3:3}, at: jbd2_journal_flush+0x48f/0xc10
stack backtrace:
CPU: 0 PID: 53694 Comm: syz-executor.6 Not tainted 6.1.0-rc5-next-20221114 #1
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.12.0-1 04/01/2014
Call Trace:
<TASK>
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+0x9b0/0x4340
__x64_sys_ioctl+0x19e/0x210
do_syscall_64+0x3f/0x90
entry_SYSCALL_64_after_hwframe+0x72/0xdc
RIP: 0033:0x7fb8e07cfb19
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:00007fb8ddd45188 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 00007fb8e08e2f60 RCX: 00007fb8e07cfb19
RDX: 0000000020000000 RSI: 000000004004662b RDI: 0000000000000005
RBP: 00007fb8e0829f6d R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000
R13: 00007ffdba651d2f R14: 00007fb8ddd45300 R15: 0000000000022000
</TASK>
sr 1:0:0:0: [sr0] tag#0 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_OK cmd_age=0s
sr 1:0:0:0: [sr0] tag#0 Sense Key : Not Ready [current]
sr 1:0:0:0: [sr0] tag#0 Add. Sense: Medium not present
sr 1:0:0:0: [sr0] tag#0 CDB: Read(10) 28 00 00 00 00 00 00 00 40 00
sr 1:0:0:0: [sr0] tag#0 unaligned transfer
sr 1:0:0:0: [sr0] tag#0 unaligned transfer
sr 1:0:0:0: [sr0] tag#0 unaligned transfer
sr 1:0:0:0: [sr0] tag#0 unaligned transfer
sr 1:0:0:0: [sr0] tag#0 unaligned transfer
sr 1:0:0:0: [sr0] tag#0 unaligned transfer
sr 1:0:0:0: [sr0] tag#0 unaligned transfer
sr 1:0:0:0: [sr0] tag#0 unaligned transfer
sr 1:0:0:0: [sr0] tag#0 unaligned transfer
sr 1:0:0:0: [sr0] tag#0 unaligned transfer
sr 1:0:0:0: [sr0] tag#0 unaligned transfer
sr 1:0:0:0: [sr0] tag#0 unaligned transfer
sr 1:0:0:0: [sr0] tag#0 unaligned transfer
sr 1:0:0:0: [sr0] tag#0 unaligned transfer
sr 1:0:0:0: [sr0] tag#0 unaligned transfer
sr 1:0:0:0: [sr0] tag#0 unaligned transfer
sr 1:0:0:0: [sr0] tag#0 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_OK cmd_age=0s
sr 1:0:0:0: [sr0] tag#0 Sense Key : Not Ready [current]
sr 1:0:0:0: [sr0] tag#0 Add. Sense: Medium not present
sr 1:0:0:0: [sr0] tag#0 CDB: Read(10) 28 00 00 00 00 00 00 00 08 00
sr 1:0:0:0: [sr0] tag#0 unaligned transfer
sr 1:0:0:0: [sr0] tag#0 unaligned transfer
audit: type=1326 audit(1668423424.642:86): auid=0 uid=0 gid=0 ses=4 subj=system_u:system_r:kernel_t:s0 pid=53833 comm="syz-executor.3" exe="/syz-executor.3" sig=31 arch=c000003e syscall=202 compat=0 ip=0x7f1252ea4b19 code=0x0
audit: type=1326 audit(1668423425.472:87): auid=0 uid=0 gid=0 ses=4 subj=system_u:system_r:kernel_t:s0 pid=53833 comm="syz-executor.3" exe="/syz-executor.3" sig=31 arch=c000003e syscall=202 compat=0 ip=0x7f1252ea4b19 code=0x0
audit: type=1326 audit(1668423425.606:88): auid=0 uid=0 gid=0 ses=4 subj=system_u:system_r:kernel_t:s0 pid=53970 comm="syz-executor.3" exe="/syz-executor.3" sig=31 arch=c000003e syscall=202 compat=0 ip=0x7f1252ea4b19 code=0x0
Bluetooth: hci5: command 0x2021 tx timeout
audit: type=1326 audit(1668423426.544:89): auid=0 uid=0 gid=0 ses=4 subj=system_u:system_r:kernel_t:s0 pid=53999 comm="syz-executor.3" exe="/syz-executor.3" sig=31 arch=c000003e syscall=202 compat=0 ip=0x7f1252ea4b19 code=0x0
audit: type=1326 audit(1668423427.465:90): auid=0 uid=0 gid=0 ses=4 subj=system_u:system_r:kernel_t:s0 pid=54027 comm="syz-executor.3" exe="/syz-executor.3" sig=31 arch=c000003e syscall=202 compat=0 ip=0x7f1252ea4b19 code=0x0
Bluetooth: hci5: command 0x2021 tx timeout
9pnet_virtio: no channels available for device ./file0
9pnet_fd: Insufficient options for proto=fd
9pnet_virtio: no channels available for device ./file0
9pnet_fd: Insufficient options for proto=fd
9pnet_virtio: no channels available for device ./file0
9pnet_fd: Insufficient options for proto=fd
9pnet_virtio: no channels available for device ./file0
9pnet_fd: Insufficient options for proto=fd
Bluetooth: hci5: command 0x2021 tx timeout
device lo entered promiscuous mode
netlink: 104 bytes leftover after parsing attributes in process `syz-executor.7'.
audit: type=1326 audit(1668423430.803:91): auid=0 uid=0 gid=0 ses=4 subj=system_u:system_r:kernel_t:s0 pid=54503 comm="syz-executor.4" exe="/syz-executor.4" sig=31 arch=c000003e syscall=202 compat=0 ip=0x7fbea4a2db19 code=0x0
device lo left promiscuous mode
device lo entered promiscuous mode
netlink: 104 bytes leftover after parsing attributes in process `syz-executor.7'.
audit: type=1326 audit(1668423431.638:92): auid=0 uid=0 gid=0 ses=4 subj=system_u:system_r:kernel_t:s0 pid=54503 comm="syz-executor.4" exe="/syz-executor.4" sig=31 arch=c000003e syscall=202 compat=0 ip=0x7fbea4a2db19 code=0x0
netlink: 104 bytes leftover after parsing attributes in process `syz-executor.7'.
device lo left promiscuous mode
device lo entered promiscuous mode
device lo entered promiscuous mode
audit: type=1326 audit(1668423431.818:93): auid=0 uid=0 gid=0 ses=4 subj=system_u:system_r:kernel_t:s0 pid=54527 comm="syz-executor.4" exe="/syz-executor.4" sig=31 arch=c000003e syscall=202 compat=0 ip=0x7fbea4a2db19 code=0x0
device lo entered promiscuous mode
audit: type=1326 audit(1668423431.922:94): auid=0 uid=0 gid=0 ses=4 subj=system_u:system_r:kernel_t:s0 pid=54530 comm="syz-executor.1" exe="/syz-executor.1" sig=31 arch=c000003e syscall=202 compat=0 ip=0x7fd9bb6d4b19 code=0x0