possible deadlock in map_mft_record

5 views
Skip to first unread message

syzbot

unread,
Nov 14, 2022, 8:41:41 PM11/14/22
to syzkaller...@googlegroups.com
Hello,

syzbot found the following issue on:

HEAD commit: e911713e40ca Linux 4.14.299
git tree: linux-4.14.y
console output: https://syzkaller.appspot.com/x/log.txt?x=16e0158e880000
kernel config: https://syzkaller.appspot.com/x/.config?x=1d7ed9728cc57838
dashboard link: https://syzkaller.appspot.com/bug?extid=50dde734aa62ec2523d3
compiler: gcc version 10.2.1 20210110 (Debian 10.2.1-6)

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

Downloadable assets:
disk image: https://storage.googleapis.com/syzbot-assets/c8588259d654/disk-e911713e.raw.xz
vmlinux: https://storage.googleapis.com/syzbot-assets/700d08072e5e/vmlinux-e911713e.xz
kernel image: https://storage.googleapis.com/syzbot-assets/844ad5da2ed5/bzImage-e911713e.xz

IMPORTANT: if you fix the issue, please add the following tag to the commit:
Reported-by: syzbot+50dde7...@syzkaller.appspotmail.com

ntfs: volume version 3.1.
======================================================
WARNING: possible circular locking dependency detected
4.14.299-syzkaller #0 Not tainted
------------------------------------------------------
syz-executor.1/10592 is trying to acquire lock:
(&ni->mrec_lock){+.+.}, at: [<ffffffff8213d64b>] map_mft_record+0x2b/0xbe0 fs/ntfs/mft.c:166

but task is already holding lock:
(&rl->lock){++++}, at: [<ffffffff8211009d>] ntfs_attr_extend_allocation+0x1dd/0x2f80 fs/ntfs/attrib.c:1995

which lock already depends on the new lock.


the existing dependency chain (in reverse order) is:

-> #1 (&rl->lock){++++}:
down_read+0x36/0x80 kernel/locking/rwsem.c:24
ntfs_read_block fs/ntfs/aops.c:269 [inline]
ntfs_readpage+0x1396/0x1ad0 fs/ntfs/aops.c:456
do_read_cache_page+0x38e/0xc10 mm/filemap.c:2713
read_mapping_page include/linux/pagemap.h:398 [inline]
ntfs_map_page fs/ntfs/aops.h:89 [inline]
ntfs_sync_mft_mirror+0x1f4/0x1560 fs/ntfs/mft.c:490
write_mft_record_nolock+0xef0/0x1240 fs/ntfs/mft.c:811
write_mft_record fs/ntfs/mft.h:109 [inline]
__ntfs_write_inode+0x58d/0xcc0 fs/ntfs/inode.c:3077
ntfs_commit_inode fs/ntfs/inode.h:315 [inline]
ntfs_put_super+0xf3c/0x14d0 fs/ntfs/super.c:2274
generic_shutdown_super+0x144/0x370 fs/super.c:446
kill_block_super+0x95/0xe0 fs/super.c:1161
deactivate_locked_super+0x6c/0xd0 fs/super.c:319
deactivate_super+0x7f/0xa0 fs/super.c:350
cleanup_mnt+0x186/0x2c0 fs/namespace.c:1183
task_work_run+0x11f/0x190 kernel/task_work.c:113
tracehook_notify_resume include/linux/tracehook.h:191 [inline]
exit_to_usermode_loop+0x1ad/0x200 arch/x86/entry/common.c:164
prepare_exit_to_usermode arch/x86/entry/common.c:199 [inline]
syscall_return_slowpath arch/x86/entry/common.c:270 [inline]
do_syscall_64+0x4a3/0x640 arch/x86/entry/common.c:297
entry_SYSCALL_64_after_hwframe+0x5e/0xd3

-> #0 (&ni->mrec_lock){+.+.}:
lock_acquire+0x170/0x3f0 kernel/locking/lockdep.c:3998
__mutex_lock_common kernel/locking/mutex.c:756 [inline]
__mutex_lock+0xc4/0x1310 kernel/locking/mutex.c:893
map_mft_record+0x2b/0xbe0 fs/ntfs/mft.c:166
ntfs_attr_extend_allocation+0x1e5/0x2f80 fs/ntfs/attrib.c:1996
ntfs_prepare_file_for_write fs/ntfs/file.c:412 [inline]
ntfs_file_write_iter+0x61b/0x1f70 fs/ntfs/file.c:1949
call_write_iter include/linux/fs.h:1780 [inline]
new_sync_write fs/read_write.c:469 [inline]
__vfs_write+0x44c/0x630 fs/read_write.c:482
vfs_write+0x17f/0x4d0 fs/read_write.c:544
SYSC_write fs/read_write.c:590 [inline]
SyS_write+0xf2/0x210 fs/read_write.c:582
do_syscall_64+0x1d5/0x640 arch/x86/entry/common.c:292
entry_SYSCALL_64_after_hwframe+0x5e/0xd3

other info that might help us debug this:

Possible unsafe locking scenario:

CPU0 CPU1
---- ----
lock(&rl->lock);
lock(&ni->mrec_lock);
lock(&rl->lock);
lock(&ni->mrec_lock);

*** DEADLOCK ***

4 locks held by syz-executor.1/10592:
#0: (&f->f_pos_lock){+.+.}, at: [<ffffffff818d8b5b>] __fdget_pos+0x1fb/0x2b0 fs/file.c:819
#1: (sb_writers#16){.+.+}, at: [<ffffffff818726a8>] file_start_write include/linux/fs.h:2714 [inline]
#1: (sb_writers#16){.+.+}, at: [<ffffffff818726a8>] vfs_write+0x3d8/0x4d0 fs/read_write.c:543
#2: (&sb->s_type->i_mutex_key#23){+.+.}, at: [<ffffffff82126299>] inode_lock include/linux/fs.h:719 [inline]
#2: (&sb->s_type->i_mutex_key#23){+.+.}, at: [<ffffffff82126299>] ntfs_file_write_iter+0x79/0x1f70 fs/ntfs/file.c:1946
#3: (&rl->lock){++++}, at: [<ffffffff8211009d>] ntfs_attr_extend_allocation+0x1dd/0x2f80 fs/ntfs/attrib.c:1995

stack backtrace:
CPU: 1 PID: 10592 Comm: syz-executor.1 Not tainted 4.14.299-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 10/26/2022
Call Trace:
__dump_stack lib/dump_stack.c:17 [inline]
dump_stack+0x1b2/0x281 lib/dump_stack.c:58
print_circular_bug.constprop.0.cold+0x2d7/0x41e 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+0x2e0e/0x3f20 kernel/locking/lockdep.c:3491
lock_acquire+0x170/0x3f0 kernel/locking/lockdep.c:3998
__mutex_lock_common kernel/locking/mutex.c:756 [inline]
__mutex_lock+0xc4/0x1310 kernel/locking/mutex.c:893
map_mft_record+0x2b/0xbe0 fs/ntfs/mft.c:166
ntfs_attr_extend_allocation+0x1e5/0x2f80 fs/ntfs/attrib.c:1996
ntfs_prepare_file_for_write fs/ntfs/file.c:412 [inline]
ntfs_file_write_iter+0x61b/0x1f70 fs/ntfs/file.c:1949
call_write_iter include/linux/fs.h:1780 [inline]
new_sync_write fs/read_write.c:469 [inline]
__vfs_write+0x44c/0x630 fs/read_write.c:482
vfs_write+0x17f/0x4d0 fs/read_write.c:544
SYSC_write fs/read_write.c:590 [inline]
SyS_write+0xf2/0x210 fs/read_write.c:582
do_syscall_64+0x1d5/0x640 arch/x86/entry/common.c:292
entry_SYSCALL_64_after_hwframe+0x5e/0xd3
EXT4-fs (loop5): mounted filesystem without journal. Opts: errors=remount-ro,nombcache,usrquota,
netlink: 12 bytes leftover after parsing attributes in process `syz-executor.5'.
ntfs: volume version 3.1.
netlink: 12 bytes leftover after parsing attributes in process `syz-executor.5'.
netlink: 12 bytes leftover after parsing attributes in process `syz-executor.5'.
ntfs: volume version 3.1.
BTRFS: device fsid f90cac8b-044b-4fa8-8bee-4b8d3da88dc2 devid 1 transid 7 /dev/loop3
BTRFS info (device loop3): disk space caching is enabled
netlink: 12 bytes leftover after parsing attributes in process `syz-executor.5'.
ntfs: volume version 3.1.
BTRFS info (device loop3): has skinny extents
BTRFS info (device loop3): disk space caching is enabled
BTRFS info (device loop3): has skinny extents
BTRFS info (device loop3): disk space caching is enabled
BTRFS info (device loop3): has skinny extents
BTRFS info (device loop0): disk space caching is enabled
BTRFS info (device loop0): has skinny extents
NILFS (loop0): corrupt root inode
NILFS (loop0): segctord starting. Construction interval = 5 seconds, CP frequency < 30 seconds
audit: type=1804 audit(1668476464.391:6): pid=11144 uid=0 auid=4294967295 ses=4294967295 op="invalid_pcr" cause="open_writers" comm="syz-executor.1" name="/root/syzkaller-testdir2995794484/syzkaller.AelnhG/48/file1/bus" dev="loop1" ino=4 res=1
audit: type=1804 audit(1668476464.481:7): pid=11149 uid=0 auid=4294967295 ses=4294967295 op="invalid_pcr" cause="ToMToU" comm="syz-executor.1" name="/root/syzkaller-testdir2995794484/syzkaller.AelnhG/48/file1/bus" dev="loop1" ino=4 res=1
IPVS: ftp: loaded support on port[0] = 21
netlink: 12 bytes leftover after parsing attributes in process `syz-executor.3'.
NILFS (loop0): corrupt root inode
NILFS (loop0): segctord starting. Construction interval = 5 seconds, CP frequency < 30 seconds
audit: type=1804 audit(1668476465.111:8): pid=11195 uid=0 auid=4294967295 ses=4294967295 op="invalid_pcr" cause="open_writers" comm="syz-executor.1" name="/root/syzkaller-testdir2995794484/syzkaller.AelnhG/49/file1/bus" dev="loop1" ino=6 res=1
attempt to access beyond end of device
loop1: rw=2049, want=230, limit=87
attempt to access beyond end of device
loop1: rw=1, want=192, limit=87
NILFS (loop0): corrupt root inode
NILFS (loop0): segctord starting. Construction interval = 5 seconds, CP frequency < 30 seconds
audit: type=1804 audit(1668476465.631:9): pid=11239 uid=0 auid=4294967295 ses=4294967295 op="invalid_pcr" cause="open_writers" comm="syz-executor.1" name="/root/syzkaller-testdir2995794484/syzkaller.AelnhG/50/file1/bus" dev="loop1" ino=9 res=1
attempt to access beyond end of device
loop1: rw=2049, want=230, limit=87
attempt to access beyond end of device
loop1: rw=1, want=192, limit=87
NILFS (loop0): corrupt root inode
NILFS (loop0): segctord starting. Construction interval = 5 seconds, CP frequency < 30 seconds
audit: type=1804 audit(1668476465.991:10): pid=11257 uid=0 auid=4294967295 ses=4294967295 op="invalid_pcr" cause="open_writers" comm="syz-executor.1" name="/root/syzkaller-testdir2995794484/syzkaller.AelnhG/51/file1/bus" dev="loop1" ino=11 res=1
attempt to access beyond end of device
loop1: rw=2049, want=230, limit=87
attempt to access beyond end of device
loop1: rw=1, want=192, limit=87
audit: type=1804 audit(1668476467.691:11): pid=11327 uid=0 auid=4294967295 ses=4294967295 op="invalid_pcr" cause="open_writers" comm="syz-executor.2" name="/root/syzkaller-testdir1022598549/syzkaller.9m6fIc/57/file1/bus" dev="loop2" ino=13 res=1
attempt to access beyond end of device
loop2: rw=2049, want=230, limit=87
attempt to access beyond end of device
loop2: rw=1, want=192, limit=87
audit: type=1804 audit(1668476467.811:12): pid=11345 uid=0 auid=4294967295 ses=4294967295 op="invalid_pcr" cause="open_writers" comm="syz-executor.2" name="/root/syzkaller-testdir1022598549/syzkaller.9m6fIc/58/file1/bus" dev="loop2" ino=15 res=1
attempt to access beyond end of device
loop2: rw=2049, want=230, limit=87
attempt to access beyond end of device
loop2: rw=1, want=192, limit=87
audit: type=1804 audit(1668476467.951:13): pid=11353 uid=0 auid=4294967295 ses=4294967295 op="invalid_pcr" cause="open_writers" comm="syz-executor.2" name="/root/syzkaller-testdir1022598549/syzkaller.9m6fIc/59/file1/bus" dev="loop2" ino=17 res=1
attempt to access beyond end of device
loop2: rw=2049, want=230, limit=87
attempt to access beyond end of device
loop2: rw=1, want=192, limit=87
audit: type=1804 audit(1668476468.061:14): pid=11361 uid=0 auid=4294967295 ses=4294967295 op="invalid_pcr" cause="open_writers" comm="syz-executor.2" name="/root/syzkaller-testdir1022598549/syzkaller.9m6fIc/60/file1/bus" dev="loop2" ino=19 res=1
attempt to access beyond end of device
loop2: rw=2049, want=230, limit=87
attempt to access beyond end of device
loop2: rw=1, want=192, limit=87
audit: type=1804 audit(1668476468.211:15): pid=11378 uid=0 auid=4294967295 ses=4294967295 op="invalid_pcr" cause="open_writers" comm="syz-executor.2" name="/root/syzkaller-testdir1022598549/syzkaller.9m6fIc/61/file1/bus" dev="loop2" ino=21 res=1
attempt to access beyond end of device
loop2: rw=2049, want=230, limit=87
attempt to access beyond end of device
loop2: rw=1, want=192, limit=87
attempt to access beyond end of device
loop2: rw=2049, want=230, limit=87
attempt to access beyond end of device
loop2: rw=1, want=192, limit=87
attempt to access beyond end of device
loop2: rw=2049, want=230, limit=87
attempt to access beyond end of device
loop2: rw=1, want=192, limit=87
attempt to access beyond end of device
loop5: rw=2049, want=230, limit=87
attempt to access beyond end of device
loop2: rw=2049, want=230, limit=87
attempt to access beyond end of device
loop5: rw=1, want=192, limit=87
attempt to access beyond end of device
loop2: rw=1, want=192, limit=87
attempt to access beyond end of device
loop5: rw=2049, want=230, limit=87
attempt to access beyond end of device
loop2: rw=2049, want=230, limit=87
attempt to access beyond end of device
attempt to access beyond end of device
loop2: rw=1, want=192, limit=87
loop5: rw=1, want=192, limit=87


---
This report 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 issue. See:
https://goo.gl/tpsmEJ#status for how to communicate with syzbot.

syzbot

unread,
Jan 7, 2023, 10:27:34 PM1/7/23
to syzkaller...@googlegroups.com
syzbot has found a reproducer for the following issue on:

HEAD commit: c4215ee4771b Linux 4.14.302
git tree: linux-4.14.y
console output: https://syzkaller.appspot.com/x/log.txt?x=165c6e6a480000
kernel config: https://syzkaller.appspot.com/x/.config?x=4a9988fe055c9527
dashboard link: https://syzkaller.appspot.com/bug?extid=50dde734aa62ec2523d3
compiler: gcc version 10.2.1 20210110 (Debian 10.2.1-6)
syz repro: https://syzkaller.appspot.com/x/repro.syz?x=12beb756480000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=137f3c6e480000

Downloadable assets:
disk image: https://storage.googleapis.com/syzbot-assets/c93ba055d204/disk-c4215ee4.raw.xz
vmlinux: https://storage.googleapis.com/syzbot-assets/bfbc929a33c1/vmlinux-c4215ee4.xz
kernel image: https://storage.googleapis.com/syzbot-assets/444658051770/bzImage-c4215ee4.xz
mounted in repro: https://storage.googleapis.com/syzbot-assets/26a0a4d92744/mount_0.gz

IMPORTANT: if you fix the issue, please add the following tag to the commit:
Reported-by: syzbot+50dde7...@syzkaller.appspotmail.com

IPVS: ftp: loaded support on port[0] = 21
ntfs: volume version 3.1.
======================================================
WARNING: possible circular locking dependency detected
4.14.302-syzkaller #0 Not tainted
------------------------------------------------------
syz-executor207/7976 is trying to acquire lock:
(&lcnbmp_mrec_lock_key){+.+.}, at: [<ffffffff8213da7b>] map_mft_record+0x2b/0xbe0 fs/ntfs/mft.c:166

but task is already holding lock:
(&vol->lcnbmp_lock){+.+.}, at: [<ffffffff8215a4e1>] ntfs_put_super+0x311/0x14d0 fs/ntfs/super.c:2296

which lock already depends on the new lock.


the existing dependency chain (in reverse order) is:

-> #1 (&vol->lcnbmp_lock){+.+.}:
down_write+0x34/0x90 kernel/locking/rwsem.c:54
__ntfs_cluster_free+0xff/0xa80 fs/ntfs/lcnalloc.c:876
ntfs_cluster_free fs/ntfs/lcnalloc.h:110 [inline]
ntfs_truncate+0x10b7/0x22d0 fs/ntfs/inode.c:2727
ntfs_truncate_vfs fs/ntfs/inode.c:2895 [inline]
ntfs_setattr+0x148/0x580 fs/ntfs/inode.c:2945
notify_change+0x56b/0xd10 fs/attr.c:315
do_truncate+0xff/0x1a0 fs/open.c:63
handle_truncate fs/namei.c:3010 [inline]
do_last fs/namei.c:3437 [inline]
path_openat+0x1dcc/0x2970 fs/namei.c:3571
do_file_open_root+0x224/0x490 fs/namei.c:3633
file_open_root+0x1e7/0x2a0 fs/open.c:1042
do_handle_open+0x2a2/0x570 fs/fhandle.c:233
do_syscall_64+0x1d5/0x640 arch/x86/entry/common.c:292
entry_SYSCALL_64_after_hwframe+0x5e/0xd3

-> #0 (&lcnbmp_mrec_lock_key){+.+.}:
lock_acquire+0x170/0x3f0 kernel/locking/lockdep.c:3998
__mutex_lock_common kernel/locking/mutex.c:756 [inline]
__mutex_lock+0xc4/0x1310 kernel/locking/mutex.c:893
map_mft_record+0x2b/0xbe0 fs/ntfs/mft.c:166
__ntfs_write_inode+0x97/0xcc0 fs/ntfs/inode.c:3012
ntfs_commit_inode fs/ntfs/inode.h:315 [inline]
ntfs_put_super+0xf81/0x14d0 fs/ntfs/super.c:2297
generic_shutdown_super+0x144/0x370 fs/super.c:446
kill_block_super+0x95/0xe0 fs/super.c:1161
deactivate_locked_super+0x6c/0xd0 fs/super.c:319
deactivate_super+0x7f/0xa0 fs/super.c:350
cleanup_mnt+0x186/0x2c0 fs/namespace.c:1183
task_work_run+0x11f/0x190 kernel/task_work.c:113
exit_task_work include/linux/task_work.h:22 [inline]
do_exit+0xa44/0x2850 kernel/exit.c:868
do_group_exit+0x100/0x2e0 kernel/exit.c:965
SYSC_exit_group kernel/exit.c:976 [inline]
SyS_exit_group+0x19/0x20 kernel/exit.c:974
do_syscall_64+0x1d5/0x640 arch/x86/entry/common.c:292
entry_SYSCALL_64_after_hwframe+0x5e/0xd3

other info that might help us debug this:

Possible unsafe locking scenario:

CPU0 CPU1
---- ----
lock(&vol->lcnbmp_lock);
lock(&lcnbmp_mrec_lock_key);
lock(&vol->lcnbmp_lock);
lock(&lcnbmp_mrec_lock_key);

*** DEADLOCK ***

2 locks held by syz-executor207/7976:
#0: (&type->s_umount_key#47){+.+.}, at: [<ffffffff818785b7>] deactivate_super+0x77/0xa0 fs/super.c:349
#1: (&vol->lcnbmp_lock){+.+.}, at: [<ffffffff8215a4e1>] ntfs_put_super+0x311/0x14d0 fs/ntfs/super.c:2296

stack backtrace:
CPU: 1 PID: 7976 Comm: syz-executor207 Not tainted 4.14.302-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 10/26/2022
Call Trace:
__dump_stack lib/dump_stack.c:17 [inline]
dump_stack+0x1b2/0x281 lib/dump_stack.c:58
print_circular_bug.constprop.0.cold+0x2d7/0x41e 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+0x2e0e/0x3f20 kernel/locking/lockdep.c:3491
lock_acquire+0x170/0x3f0 kernel/locking/lockdep.c:3998
__mutex_lock_common kernel/locking/mutex.c:756 [inline]
__mutex_lock+0xc4/0x1310 kernel/locking/mutex.c:893
map_mft_record+0x2b/0xbe0 fs/ntfs/mft.c:166
__ntfs_write_inode+0x97/0xcc0 fs/ntfs/inode.c:3012
ntfs_commit_inode fs/ntfs/inode.h:315 [inline]
ntfs_put_super+0xf81/0x14d0 fs/ntfs/super.c:2297
generic_shutdown_super+0x144/0x370 fs/super.c:446
kill_block_super+0x95/0xe0 fs/super.c:1161
deactivate_locked_super+0x6c/0xd0 fs/super.c:319
deactivate_super+0x7f/0xa0 fs/super.c:350
cleanup_mnt+0x186/0x2c0 fs/namespace.c:1183
task_work_run+0x11f/0x190 kernel/task_work.c:113
exit_task_work include/linux/task_work.h:22 [inline]
do_exit+0xa44/0x2850 kernel/exit.c:868
do_group_exit+0x100/0x2e0 kernel/exit.c:965
SYSC_exit_group kernel/exit.c:976 [inline]
SyS_exit_group+0x19/0x20 kernel/exit.c:974
do_syscall_64+0x1d5/0x640 arch/x86/entry/common.c:292
entry_SYSCALL_64_after_hwframe+0x5e/0xd3
RIP: 0033:0x7fa10da72a49
RSP: 002b:00007ffd05b00f48 EFLAGS: 00000246 ORIG_RAX: 00000000000000e7
RAX: ffffffffffffffda RBX: 00007

Reply all
Reply to author
Forward
0 new messages