possible deadlock in generic_file_write_iter

11 views
Skip to first unread message

syzbot

unread,
Mar 22, 2020, 12:19:21 AM3/22/20
to syzkaller...@googlegroups.com
Hello,

syzbot found the following crash on:

HEAD commit: 01364dad Linux 4.14.174
git tree: linux-4.14.y
console output: https://syzkaller.appspot.com/x/log.txt?x=11b8e223e00000
kernel config: https://syzkaller.appspot.com/x/.config?x=664dd71881ab2b2d
dashboard link: https://syzkaller.appspot.com/bug?extid=09f6e253ac5990621a05
compiler: gcc (GCC) 9.0.0 20181231 (experimental)

Unfortunately, I don't have any reproducer for this crash yet.

IMPORTANT: if you fix the bug, please add the following tag to the commit:
Reported-by: syzbot+09f6e2...@syzkaller.appspotmail.com

======================================================
WARNING: possible circular locking dependency detected
4.14.174-syzkaller #0 Not tainted
9pnet: Insufficient options for proto=fd
------------------------------------------------------
syz-executor.5/17155 is trying to acquire lock:
("dio/%s"sb->s_id){+.+.}, at: [<ffffffff813ae9ba>] flush_workqueue+0xda/0x13f0 kernel/workqueue.c:2621

but task is already holding lock:
(&sb->s_type->i_mutex_key#21){++++}, at: [<ffffffff816dee19>] inode_lock include/linux/fs.h:718 [inline]
(&sb->s_type->i_mutex_key#21){++++}, at: [<ffffffff816dee19>] generic_file_write_iter+0x99/0x650 mm/filemap.c:3197

which lock already depends on the new lock.


the existing dependency chain (in reverse order) is:

-> #2 (&sb->s_type->i_mutex_key#21){++++}:
down_write+0x34/0x90 kernel/locking/rwsem.c:54
inode_lock include/linux/fs.h:718 [inline]
__generic_file_fsync+0x9e/0x190 fs/libfs.c:985
fat_file_fsync+0x73/0x1f0 fs/fat/file.c:165
vfs_fsync_range+0x103/0x250 fs/sync.c:196
generic_write_sync include/linux/fs.h:2677 [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
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:3994
flush_workqueue+0x109/0x13f0 kernel/workqueue.c:2624
drain_workqueue+0x177/0x3e0 kernel/workqueue.c:2789
destroy_workqueue+0x71/0x660 kernel/workqueue.c:4102
__alloc_workqueue_key+0xb94/0xec0 kernel/workqueue.c:4079
sb_init_dio_done_wq+0x34/0x80 fs/direct-io.c:624
do_blockdev_direct_IO+0x3842/0x9120 fs/direct-io.c:1286
blockdev_direct_IO include/linux/fs.h:2987 [inline]
fat_direct_IO+0x19b/0x2b0 fs/fat/inode.c:275
generic_file_direct_write+0x1df/0x420 mm/filemap.c:2950
__generic_file_write_iter+0x2a5/0x590 mm/filemap.c:3129
generic_file_write_iter+0x2fa/0x650 mm/filemap.c:3200
call_write_iter include/linux/fs.h:1777 [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#21

Possible unsafe locking scenario:

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

*** DEADLOCK ***

2 locks held by syz-executor.5/17155:
#0: (sb_writers#13){.+.+}, at: [<ffffffff819c46b6>] file_start_write include/linux/fs.h:2707 [inline]
#0: (sb_writers#13){.+.+}, at: [<ffffffff819c46b6>] aio_write+0x426/0x4f0 fs/aio.c:1552
#1: (&sb->s_type->i_mutex_key#21){++++}, at: [<ffffffff816dee19>] inode_lock include/linux/fs.h:718 [inline]
#1: (&sb->s_type->i_mutex_key#21){++++}, at: [<ffffffff816dee19>] generic_file_write_iter+0x99/0x650 mm/filemap.c:3197

stack backtrace:
CPU: 1 PID: 17155 Comm: syz-executor.5 Not tainted 4.14.174-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:1901 [inline]
check_prevs_add kernel/locking/lockdep.c:2018 [inline]
validate_chain kernel/locking/lockdep.c:2460 [inline]
__lock_acquire+0x2cb3/0x4620 kernel/locking/lockdep.c:3487
lock_acquire+0x170/0x3f0 kernel/locking/lockdep.c:3994
flush_workqueue+0x109/0x13f0 kernel/workqueue.c:2624
drain_workqueue+0x177/0x3e0 kernel/workqueue.c:2789
audit: type=1400 audit(1584850707.523:82): avc: denied { audit_read } for pid=17193 comm="syz-executor.1" capability=37 scontext=unconfined_u:system_r:insmod_t:s0-s0:c0.c1023 tcontext=unconfined_u:system_r:insmod_t:s0-s0:c0.c1023 tclass=capability2 permissive=1
destroy_workqueue+0x71/0x660 kernel/workqueue.c:4102
__alloc_workqueue_key+0xb94/0xec0 kernel/workqueue.c:4079
sb_init_dio_done_wq+0x34/0x80 fs/direct-io.c:624
do_blockdev_direct_IO+0x3842/0x9120 fs/direct-io.c:1286
blockdev_direct_IO include/linux/fs.h:2987 [inline]
fat_direct_IO+0x19b/0x2b0 fs/fat/inode.c:275
generic_file_direct_write+0x1df/0x420 mm/filemap.c:2950
__generic_file_write_iter+0x2a5/0x590 mm/filemap.c:3129
generic_file_write_iter+0x2fa/0x650 mm/filemap.c:3200
call_write_iter include/linux/fs.h:1777 [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:0x45c849
RSP: 002b:00007f19aa775c78 EFLAGS: 00000246 ORIG_RAX: 00000000000000d1
RAX: ffffffffffffffda RBX: 00007f19aa7766d4 RCX: 000000000045c849
RDX: 0000000020000540 RSI: 0000000000000006 RDI: 00007f19aa753000
RBP: 000000000076bf00 R08: 0000000000000000 R09: 0000000000000000
9pnet: Insufficient options for proto=fd
R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000006
R13: 00000000000001f9 R14: 00000000004c422b R15: 0000000000000009
netlink: 72 bytes leftover after parsing attributes in process `syz-executor.3'.
netlink: 72 bytes leftover after parsing attributes in process `syz-executor.3'.
FAT-fs (loop4): bogus number of reserved sectors
FAT-fs (loop4): Can't find a valid FAT filesystem
FAT-fs (loop5): error, fat_free_clusters: deleting FAT entry beyond EOF
FAT-fs (loop5): Filesystem has been set read-only
FAT-fs (loop4): bogus number of reserved sectors
FAT-fs (loop4): Can't find a valid FAT filesystem
audit: type=1804 audit(1584850708.313:83): pid=17248 uid=0 auid=4294967295 ses=4294967295 subj=unconfined_u:system_r:insmod_t:s0-s0:c0.c1023 op="invalid_pcr" cause="ToMToU" comm="syz-executor.4" name="/root/syzkaller-testdir388636811/syzkaller.glI5Hz/57/bus" dev="sda1" ino=16929 res=1
FAT-fs (loop5): error, fat_free_clusters: deleting FAT entry beyond EOF
FAT-fs (loop5): Filesystem has been set read-only
audit: type=1400 audit(1584850708.903:84): avc: denied { create } for pid=17307 comm="syz-executor.1" scontext=unconfined_u:system_r:insmod_t:s0-s0:c0.c1023 tcontext=unconfined_u:system_r:insmod_t:s0-s0:c0.c1023 tclass=netlink_scsitransport_socket permissive=1
audit: type=1400 audit(1584850708.903:85): avc: denied { bind } for pid=17307 comm="syz-executor.1" scontext=unconfined_u:system_r:insmod_t:s0-s0:c0.c1023 tcontext=unconfined_u:system_r:insmod_t:s0-s0:c0.c1023 tclass=netlink_scsitransport_socket permissive=1
audit: type=1400 audit(1584850708.903:86): avc: denied { write } for pid=17307 comm="syz-executor.1" path="socket:[63271]" dev="sockfs" ino=63271 scontext=unconfined_u:system_r:insmod_t:s0-s0:c0.c1023 tcontext=unconfined_u:system_r:insmod_t:s0-s0:c0.c1023 tclass=netlink_scsitransport_socket permissive=1
9pnet: Insufficient options for proto=fd
FAT-fs (loop5): error, fat_free_clusters: deleting FAT entry beyond EOF
FAT-fs (loop5): Filesystem has been set read-only
FAT-fs (loop5): error, fat_free_clusters: deleting FAT entry beyond EOF
FAT-fs (loop5): Filesystem has been set read-only
9pnet: Insufficient options for proto=fd
9pnet: Insufficient options for proto=fd
9pnet: Insufficient options for proto=fd
9pnet: Insufficient options for proto=fd
FAT-fs (loop5): error, fat_free_clusters: deleting FAT entry beyond EOF
FAT-fs (loop5): Filesystem has been set read-only
9pnet: Insufficient options for proto=fd
9pnet: Insufficient options for proto=fd
9pnet: Insufficient options for proto=fd
FAT-fs (loop5): error, fat_free_clusters: deleting FAT entry beyond EOF
FAT-fs (loop5): Filesystem has been set read-only
9pnet: Insufficient options for proto=fd
FAT-fs (loop4): invalid media value (0xaa)
FAT-fs (loop4): Can't find a valid FAT filesystem
FAT-fs (loop4): invalid media value (0xaa)
FAT-fs (loop4): Can't find a valid FAT filesystem
9pnet: Insufficient options for proto=fd
FAT-fs (loop5): error, fat_free_clusters: deleting FAT entry beyond EOF
FAT-fs (loop5): Filesystem has been set read-only
9pnet: Insufficient options for proto=fd
9pnet: Insufficient options for proto=fd
9pnet: Insufficient options for proto=fd
FAT-fs (loop4): bogus number of reserved sectors
FAT-fs (loop4): Can't find a valid FAT filesystem
FAT-fs (loop4): bogus number of reserved sectors
FAT-fs (loop4): Can't find a valid FAT filesystem
9pnet: Insufficient options for proto=fd
9pnet: Insufficient options for proto=fd
9pnet: Insufficient options for proto=fd
FAT-fs (loop5): error, fat_free_clusters: deleting FAT entry beyond EOF
FAT-fs (loop5): Filesystem has been set read-only
9pnet: Insufficient options for proto=fd
FAT-fs (loop4): bogus number of reserved sectors
9pnet: Insufficient options for proto=fd
FAT-fs (loop4): Can't find a valid FAT filesystem
FAT-fs (loop4): bogus number of reserved sectors
FAT-fs (loop4): Can't find a valid FAT filesystem
FAT-fs (loop4): invalid media value (0xc0)
FAT-fs (loop4): Can't find a valid FAT filesystem
9pnet: Insufficient options for proto=fd
FAT-fs (loop4): invalid media value (0xc0)
FAT-fs (loop4): Can't find a valid FAT filesystem
FAT-fs (loop5): error, fat_free_clusters: deleting FAT entry beyond EOF
FAT-fs (loop5): Filesystem has been set read-only
FAT-fs (loop5): error, fat_free_clusters: deleting FAT entry beyond EOF
FAT-fs (loop5): Filesystem has been set read-only
9pnet: Insufficient options for proto=fd
FAT-fs (loop5): bogus number of reserved sectors
FAT-fs (loop5): Can't find a valid FAT filesystem
FAT-fs (loop5): bogus number of reserved sectors
FAT-fs (loop5): Can't find a valid FAT filesystem
SELinux: unrecognized netlink message: protocol=4 nlmsg_type=32 sclass=netlink_tcpdiag_socket pig=17991 comm=syz-executor.1
9pnet: Insufficient options for proto=fd
9pnet: Insufficient options for proto=fd
9pnet: Insufficient options for proto=fd
FAT-fs (loop5): bogus number of FAT structure
FAT-fs (loop5): Can't find a valid FAT filesystem
FAT-fs (loop5): bogus number of FAT structure
FAT-fs (loop5): Can't find a valid FAT filesystem


---
This bug is generated by a bot. It may contain errors.
See https://goo.gl/tpsmEJ for more information about syzbot.
syzbot engineers can be reached at syzk...@googlegroups.com.

syzbot will keep track of this bug report. See:
https://goo.gl/tpsmEJ#status for how to communicate with syzbot.

syzbot

unread,
Oct 1, 2020, 7:22:10 PM10/1/20
to syzkaller...@googlegroups.com
Auto-closing this bug as obsolete.
Crashes did not happen for a while, no reproducer and no activity.
Reply all
Reply to author
Forward
0 new messages