syzbot


possible deadlock in ext4_file_write_iter

Status: auto-closed as invalid on 2020/09/14 06:49
Reported-by: syzbot+0456fbb3a6f333f981df@syzkaller.appspotmail.com
First crash: 821d, last: 768d
similar bugs (4):
Kernel Title Repro Cause bisect Fix bisect Count Last Reported Patched Status
linux-4.14 possible deadlock in ext4_file_write_iter (2) syz inconclusive 8 48d 608d 0/1 upstream: reported syz repro on 2020/10/24 08:36
linux-4.19 possible deadlock in ext4_file_write_iter (2) 1 330d 330d 0/1 auto-closed as invalid on 2021/11/26 16:39
linux-4.19 possible deadlock in ext4_file_write_iter (3) syz error 7 56d 182d 0/1 upstream: reported syz repro on 2021/12/24 22:56
linux-4.19 possible deadlock in ext4_file_write_iter 1 751d 751d 0/1 auto-closed as invalid on 2020/10/01 00:41

Sample crash report:
======================================================
WARNING: possible circular locking dependency detected
4.14.180-syzkaller #0 Not tainted
------------------------------------------------------
syz-executor.3/20859 is trying to acquire lock:
 ("dio/%s"sb->s_id){+.+.}, at: [<ffffffff813ae99a>] flush_workqueue+0xda/0x13f0 kernel/workqueue.c:2621

but task is already holding lock:
 (&sb->s_type->i_mutex_key#9){++++}, at: [<ffffffff81bbd325>] inode_trylock include/linux/fs.h:739 [inline]
 (&sb->s_type->i_mutex_key#9){++++}, at: [<ffffffff81bbd325>] ext4_file_write_iter+0x1d5/0xdc0 fs/ext4/file.c:236

which lock already depends on the new lock.


the existing dependency chain (in reverse order) is:

-> #2 (&sb->s_type->i_mutex_key#9){++++}:
       down_write+0x34/0x90 kernel/locking/rwsem.c:54
       inode_lock include/linux/fs.h:719 [inline]
       __generic_file_fsync+0x9e/0x190 fs/libfs.c:987
       ext4_sync_file+0x757/0x12c0 fs/ext4/fsync.c:120
       vfs_fsync_range+0x103/0x250 fs/sync.c:196
       generic_write_sync include/linux/fs.h:2678 [inline]
       dio_complete+0x37d/0x840 fs/direct-io.c:330
       process_one_work+0x813/0x1540 kernel/workqueue.c:2116
       worker_thread+0x5d1/0x1070 kernel/workqueue.c:2250
       kthread+0x30d/0x420 kernel/kthread.c:232
       ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:404

-> #1 ((&dio->complete_work)){+.+.}:
       process_one_work+0x7b5/0x1540 kernel/workqueue.c:2092
       worker_thread+0x5d1/0x1070 kernel/workqueue.c:2250
       kthread+0x30d/0x420 kernel/kthread.c:232
base_sock_release(ffff888082b85a40) sk=ffff8880a4445280
       ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:404

-> #0 ("dio/%s"sb->s_id){+.+.}:
       lock_acquire+0x170/0x3f0 kernel/locking/lockdep.c:3998
       flush_workqueue+0x109/0x13f0 kernel/workqueue.c:2624
       drain_workqueue+0x177/0x3e0 kernel/workqueue.c:2789
       destroy_workqueue+0x71/0x660 kernel/workqueue.c:4102
       sb_init_dio_done_wq+0x61/0x80 fs/direct-io.c:635
       do_blockdev_direct_IO+0x3842/0x9120 fs/direct-io.c:1286
       ext4_direct_IO_write fs/ext4/inode.c:3716 [inline]
       ext4_direct_IO+0x7cf/0x1980 fs/ext4/inode.c:3852
       generic_file_direct_write+0x1df/0x420 mm/filemap.c:2950
       __generic_file_write_iter+0x2a5/0x590 mm/filemap.c:3129
       ext4_file_write_iter+0x281/0xdc0 fs/ext4/file.c:270
       call_write_iter include/linux/fs.h:1778 [inline]
       aio_write+0x2c7/0x4f0 fs/aio.c:1553
       io_submit_one fs/aio.c:1641 [inline]
       do_io_submit+0x996/0x13f0 fs/aio.c:1709
       do_syscall_64+0x1d5/0x640 arch/x86/entry/common.c:292
       entry_SYSCALL_64_after_hwframe+0x42/0xb7

other info that might help us debug this:

Chain exists of:
  "dio/%s"sb->s_id --> (&dio->complete_work) --> &sb->s_type->i_mutex_key#9

 Possible unsafe locking scenario:

       CPU0                    CPU1
       ----                    ----
  lock(&sb->s_type->i_mutex_key#9);
                               lock((&dio->complete_work));
                               lock(&sb->s_type->i_mutex_key#9);
  lock("dio/%s"sb->s_id);

 *** DEADLOCK ***

2 locks held by syz-executor.3/20859:
 #0:  (sb_writers#3){.+.+}, at: [<ffffffff819c4c56>] file_start_write include/linux/fs.h:2708 [inline]
 #0:  (sb_writers#3){.+.+}, at: [<ffffffff819c4c56>] aio_write+0x426/0x4f0 fs/aio.c:1552
 #1:  (&sb->s_type->i_mutex_key#9){++++}, at: [<ffffffff81bbd325>] inode_trylock include/linux/fs.h:739 [inline]
 #1:  (&sb->s_type->i_mutex_key#9){++++}, at: [<ffffffff81bbd325>] ext4_file_write_iter+0x1d5/0xdc0 fs/ext4/file.c:236

stack backtrace:
CPU: 0 PID: 20859 Comm: syz-executor.3 Not tainted 4.14.180-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
 __dump_stack lib/dump_stack.c:17 [inline]
 dump_stack+0x13e/0x194 lib/dump_stack.c:58
 print_circular_bug.isra.0.cold+0x1c4/0x282 kernel/locking/lockdep.c:1258
 check_prev_add kernel/locking/lockdep.c:1905 [inline]
 check_prevs_add kernel/locking/lockdep.c:2022 [inline]
 validate_chain kernel/locking/lockdep.c:2464 [inline]
 __lock_acquire+0x2cb3/0x4620 kernel/locking/lockdep.c:3491
 lock_acquire+0x170/0x3f0 kernel/locking/lockdep.c:3998
 flush_workqueue+0x109/0x13f0 kernel/workqueue.c:2624
 drain_workqueue+0x177/0x3e0 kernel/workqueue.c:2789
 destroy_workqueue+0x71/0x660 kernel/workqueue.c:4102
 sb_init_dio_done_wq+0x61/0x80 fs/direct-io.c:635
 do_blockdev_direct_IO+0x3842/0x9120 fs/direct-io.c:1286
 ext4_direct_IO_write fs/ext4/inode.c:3716 [inline]
 ext4_direct_IO+0x7cf/0x1980 fs/ext4/inode.c:3852
 generic_file_direct_write+0x1df/0x420 mm/filemap.c:2950
 __generic_file_write_iter+0x2a5/0x590 mm/filemap.c:3129
 ext4_file_write_iter+0x281/0xdc0 fs/ext4/file.c:270
 call_write_iter include/linux/fs.h:1778 [inline]
 aio_write+0x2c7/0x4f0 fs/aio.c:1553
 io_submit_one fs/aio.c:1641 [inline]
 do_io_submit+0x996/0x13f0 fs/aio.c:1709
 do_syscall_64+0x1d5/0x640 arch/x86/entry/common.c:292
 entry_SYSCALL_64_after_hwframe+0x42/0xb7
RIP: 0033:0x45ca29
RSP: 002b:00007fd479b12c78 EFLAGS: 00000246 ORIG_RAX: 00000000000000d1
RAX: ffffffffffffffda RBX: 00000000004e0d00 RCX: 000000000045ca29
RDX: 0000000020000540 RSI: 0000000000000006 RDI: 00007fd479b14000
RBP: 000000000078bfa0 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00000000ffffffff
R13: 00000000000001fb R14: 00000000004c4446 R15: 00007fd479b136d4
base_sock_release(ffff88808e41b5c0) sk=ffff88808f241640
kauditd_printk_skb: 27488 callbacks suppressed
audit: type=1326 audit(1589698114.190:1306832): auid=0 uid=0 gid=0 ses=4 subj=system_u:system_r:kernel_t:s0 pid=20809 comm="syz-executor.1" exe="/root/syz-executor.1" sig=0 arch=c000003e syscall=202 compat=0 ip=0x45ca29 code=0x50000
audit: type=1326 audit(1589698114.190:1306833): auid=0 uid=0 gid=0 ses=4 subj=system_u:system_r:kernel_t:s0 pid=20809 comm="syz-executor.1" exe="/root/syz-executor.1" sig=0 arch=c000003e syscall=202 compat=0 ip=0x45ca29 code=0x50000
audit: type=1326 audit(1589698114.190:1306834): auid=0 uid=0 gid=0 ses=4 subj=system_u:system_r:kernel_t:s0 pid=20809 comm="syz-executor.1" exe="/root/syz-executor.1" sig=0 arch=c000003e syscall=202 compat=0 ip=0x45ca29 code=0x50000
audit: type=1326 audit(1589698114.190:1306835): auid=0 uid=0 gid=0 ses=4 subj=system_u:system_r:kernel_t:s0 pid=20809 comm="syz-executor.1" exe="/root/syz-executor.1" sig=0 arch=c000003e syscall=202 compat=0 ip=0x45ca29 code=0x50000
audit: type=1326 audit(1589698114.190:1306836): auid=0 uid=0 gid=0 ses=4 subj=system_u:system_r:kernel_t:s0 pid=20809 comm="syz-executor.1" exe="/root/syz-executor.1" sig=0 arch=c000003e syscall=202 compat=0 ip=0x45ca29 code=0x50000
audit: type=1326 audit(1589698114.190:1306837): auid=0 uid=0 gid=0 ses=4 subj=system_u:system_r:kernel_t:s0 pid=20809 comm="syz-executor.1" exe="/root/syz-executor.1" sig=0 arch=c000003e syscall=202 compat=0 ip=0x45ca29 code=0x50000
audit: type=1326 audit(1589698114.190:1306838): auid=0 uid=0 gid=0 ses=4 subj=system_u:system_r:kernel_t:s0 pid=20809 comm="syz-executor.1" exe="/root/syz-executor.1" sig=0 arch=c000003e syscall=202 compat=0 ip=0x45ca29 code=0x50000
audit: type=1326 audit(1589698114.190:1306839): auid=0 uid=0 gid=0 ses=4 subj=system_u:system_r:kernel_t:s0 pid=20809 comm="syz-executor.1" exe="/root/syz-executor.1" sig=0 arch=c000003e syscall=202 compat=0 ip=0x45ca29 code=0x50000
audit: type=1326 audit(1589698114.190:1306840): auid=0 uid=0 gid=0 ses=4 subj=system_u:system_r:kernel_t:s0 pid=20809 comm="syz-executor.1" exe="/root/syz-executor.1" sig=0 arch=c000003e syscall=202 compat=0 ip=0x45ca29 code=0x50000
audit: type=1326 audit(1589698114.190:1306841): auid=0 uid=0 gid=0 ses=4 subj=system_u:system_r:kernel_t:s0 pid=20809 comm="syz-executor.1" exe="/root/syz-executor.1" sig=0 arch=c000003e syscall=202 compat=0 ip=0x45ca29 code=0x50000
base_sock_release(ffff888089954640) sk=ffff88804d64e240
base_sock_release(ffff888024d1e000) sk=ffff888037cb21c0
base_sock_release(ffff888013d2fb00) sk=ffff8880319ae340
base_sock_release(ffff8880139110c0) sk=ffff88803d5f6a00
base_sock_release(ffff8880965924c0) sk=ffff88804397a340
base_sock_release(ffff888083b6ea00) sk=ffff88803836c600
base_sock_release(ffff888083a14540) sk=ffff888040a98cc0
base_sock_release(ffff88804d955a80) sk=ffff888052ce95c0
base_sock_release(ffff888083a16640) sk=ffff888029075600
base_sock_release(ffff888089bcd600) sk=ffff888090938a40
base_sock_release(ffff888083abb5c0) sk=ffff88803f600a80
base_sock_release(ffff8880839720c0) sk=ffff88803fee6600
base_sock_release(ffff88808e755a40) sk=ffff888051748d00
base_sock_release(ffff888083b89500) sk=ffff888034f02280
kauditd_printk_skb: 30726 callbacks suppressed
audit: type=1326 audit(1589698119.201:1337569): auid=0 uid=0 gid=0 ses=4 subj=system_u:system_r:kernel_t:s0 pid=21004 comm="syz-executor.2" exe="/root/syz-executor.2" sig=0 arch=c000003e syscall=228 compat=0 ip=0x45f86a code=0x50000
audit: type=1326 audit(1589698119.201:1337570): auid=0 uid=0 gid=0 ses=4 subj=system_u:system_r:kernel_t:s0 pid=21004 comm="syz-executor.2" exe="/root/syz-executor.2" sig=0 arch=c000003e syscall=202 compat=0 ip=0x45ca29 code=0x50000
audit: type=1326 audit(1589698119.201:1337571): auid=0 uid=0 gid=0 ses=4 subj=system_u:system_r:kernel_t:s0 pid=21004 comm="syz-executor.2" exe="/root/syz-executor.2" sig=0 arch=c000003e syscall=228 compat=0 ip=0x45f86a code=0x50000
audit: type=1326 audit(1589698119.201:1337572): auid=0 uid=0 gid=0 ses=4 subj=system_u:system_r:kernel_t:s0 pid=21004 comm="syz-executor.2" exe="/root/syz-executor.2" sig=0 arch=c000003e syscall=202 compat=0 ip=0x45ca29 code=0x50000
audit: type=1326 audit(1589698119.201:1337567): auid=0 uid=0 gid=0 ses=4 subj=system_u:system_r:kernel_t:s0 pid=21004 comm="syz-executor.2" exe="/root/syz-executor.2" sig=0 arch=c000003e syscall=202 compat=0 ip=0x45ca29 code=0x50000
audit: type=1326 audit(1589698119.201:1337573): auid=0 uid=0 gid=0 ses=4 subj=system_u:system_r:kernel_t:s0 pid=21004 comm="syz-executor.2" exe="/root/syz-executor.2" sig=0 arch=c000003e syscall=202 compat=0 ip=0x45ca29 code=0x50000
audit: type=1326 audit(1589698119.201:1337574): auid=0 uid=0 gid=0 ses=4 subj=system_u:system_r:kernel_t:s0 pid=21004 comm="syz-executor.2" exe="/root/syz-executor.2" sig=0 arch=c000003e syscall=202 compat=0 ip=0x45ca29 code=0x50000
audit: type=1326 audit(1589698119.201:1337575): auid=0 uid=0 gid=0 ses=4 subj=system_u:system_r:kernel_t:s0 pid=21004 comm="syz-executor.2" exe="/root/syz-executor.2" sig=0 arch=c000003e syscall=202 compat=0 ip=0x45ca29 code=0x50000
audit: type=1326 audit(1589698119.201:1337576): auid=0 uid=0 gid=0 ses=4 subj=system_u:system_r:kernel_t:s0 pid=21004 comm="syz-executor.2" exe="/root/syz-executor.2" sig=0 arch=c000003e syscall=202 compat=0 ip=0x45ca29 code=0x50000
audit: type=1326 audit(1589698119.201:1337577): auid=0 uid=0 gid=0 ses=4 subj=system_u:system_r:kernel_t:s0 pid=21004 comm="syz-executor.2" exe="/root/syz-executor.2" sig=0 arch=c000003e syscall=202 compat=0 ip=0x45ca29 code=0x50000

Crashes (3):
Manager Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Title
ci2-linux-4-14 2020/05/17 06:48 linux-4.14.y ab9dfda23248 37bccd4e .config log report
ci2-linux-4-14 2020/03/27 15:56 linux-4.14.y 01364dad1d45 831e9a81 .config log report
ci2-linux-4-14 2020/03/25 12:12 linux-4.14.y 01364dad1d45 41f049cc .config log report