INFO: task hung in __generic_file_write_iter

5 views
Skip to first unread message

syzbot

unread,
Dec 10, 2022, 5:14:42 PM12/10/22
to syzkaller...@googlegroups.com
Hello,

syzbot found the following issue on:

HEAD commit: 3f8a27f9e27b Linux 4.19.211
git tree: linux-4.19.y
console output: https://syzkaller.appspot.com/x/log.txt?x=12e948af880000
kernel config: https://syzkaller.appspot.com/x/.config?x=9b9277b418617afe
dashboard link: https://syzkaller.appspot.com/bug?extid=3beffef3d21bf9a3425f
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/98c0bdb4abb3/disk-3f8a27f9.raw.xz
vmlinux: https://storage.googleapis.com/syzbot-assets/ea228ff02669/vmlinux-3f8a27f9.xz

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

RDX: 0000000000000000 RSI: 0000000002007ffb RDI: 0000000000000005
RBP: 00007fd9bfacd1d0 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000001
R13: 00007ffec9bec15f R14: 00007fd9bfacd300 R15: 0000000000022000
INFO: task syz-executor.2:14848 blocked for more than 140 seconds.
Not tainted 4.19.211-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor.2 D26712 14848 8143 0x00000004
Call Trace:
context_switch kernel/sched/core.c:2828 [inline]
__schedule+0x887/0x2040 kernel/sched/core.c:3517
schedule+0x8d/0x1b0 kernel/sched/core.c:3561
io_schedule+0xb5/0x120 kernel/sched/core.c:5181
wait_on_page_bit_common mm/filemap.c:1123 [inline]
wait_on_page_bit+0x2c5/0x3f0 mm/filemap.c:1156
wait_on_page_writeback include/linux/pagemap.h:547 [inline]
__filemap_fdatawait_range+0x3ae/0x510 mm/filemap.c:535
filemap_fdatawait_range mm/filemap.c:560 [inline]
filemap_write_and_wait_range mm/filemap.c:683 [inline]
filemap_write_and_wait_range+0x6e/0xd0 mm/filemap.c:673
__generic_file_write_iter+0x4cf/0x610 mm/filemap.c:3281
f2fs_file_write_iter+0x3c4/0xbe0 fs/f2fs/file.c:3031
call_write_iter include/linux/fs.h:1821 [inline]
aio_write+0x37f/0x5c0 fs/aio.c:1574
__io_submit_one fs/aio.c:1858 [inline]
io_submit_one+0xecd/0x20c0 fs/aio.c:1909
__do_sys_io_submit fs/aio.c:1953 [inline]
__se_sys_io_submit+0x11b/0x4a0 fs/aio.c:1924
do_syscall_64+0xf9/0x620 arch/x86/entry/common.c:293
entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x7faefd48e0d9
Code: Bad RIP value.
RSP: 002b:00007faefb9df168 EFLAGS: 00000246 ORIG_RAX: 00000000000000d1
RAX: ffffffffffffffda RBX: 00007faefd5ae050 RCX: 00007faefd48e0d9
RDX: 0000000020000540 RSI: 0000000000000008 RDI: 00007faef759e000
RBP: 00007faefd4e9ae9 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000
R13: 00007ffedb42f27f R14: 00007faefb9df300 R15: 0000000000022000
INFO: task syz-executor.2:14958 blocked for more than 140 seconds.
Not tainted 4.19.211-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor.2 D27384 14958 8143 0x00000004
Call Trace:
context_switch kernel/sched/core.c:2828 [inline]
__schedule+0x887/0x2040 kernel/sched/core.c:3517
schedule+0x8d/0x1b0 kernel/sched/core.c:3561
__rwsem_down_write_failed_common kernel/locking/rwsem-xadd.c:589 [inline]
rwsem_down_write_failed+0x3aa/0x760 kernel/locking/rwsem-xadd.c:618
call_rwsem_down_write_failed+0x13/0x20 arch/x86/lib/rwsem.S:117
__down_write arch/x86/include/asm/rwsem.h:142 [inline]
down_write+0x4f/0x90 kernel/locking/rwsem.c:72
inode_lock include/linux/fs.h:748 [inline]
f2fs_file_write_iter+0x218/0xbe0 fs/f2fs/file.c:2996
call_write_iter include/linux/fs.h:1821 [inline]
do_iter_readv_writev+0x668/0x790 fs/read_write.c:681
do_iter_write+0x182/0x5d0 fs/read_write.c:960
vfs_iter_write+0x70/0xa0 fs/read_write.c:973
iter_file_splice_write+0x60d/0xbb0 fs/splice.c:750
do_splice_from fs/splice.c:852 [inline]
direct_splice_actor+0x115/0x160 fs/splice.c:1025
splice_direct_to_actor+0x33f/0x8d0 fs/splice.c:980
do_splice_direct+0x1a7/0x270 fs/splice.c:1068
do_sendfile+0x550/0xc30 fs/read_write.c:1447
__do_sys_sendfile64 fs/read_write.c:1508 [inline]
__se_sys_sendfile64+0x147/0x160 fs/read_write.c:1494
do_syscall_64+0xf9/0x620 arch/x86/entry/common.c:293
entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x7faefd48e0d9
Code: Bad RIP value.
RSP: 002b:00007faef759d168 EFLAGS: 00000246 ORIG_RAX: 0000000000000028
RAX: ffffffffffffffda RBX: 00007faefd5ae120 RCX: 00007faefd48e0d9
RDX: 0000000000000000 RSI: 0000000000000005 RDI: 0000000000000004
RBP: 00007faefd4e9ae9 R08: 0000000000000000 R09: 0000000000000000
R10: 0001000000201005 R11: 0000000000000246 R12: 0000000000000000
R13: 00007ffedb42f27f R14: 00007faef759d300 R15: 0000000000022000

Showing all locks held in the system:
1 lock held by khungtaskd/1569:
#0: 000000003ae7cda5 (rcu_read_lock){....}, at: debug_show_all_locks+0x53/0x265 kernel/locking/lockdep.c:4441
1 lock held by in:imklog/7817:
#0: 000000004064821d (&f->f_pos_lock){+.+.}, at: __fdget_pos+0x26f/0x310 fs/file.c:767
1 lock held by syz-executor.2/14848:
#0: 000000006d638564 (&sb->s_type->i_mutex_key#31){+.+.}, at: inode_trylock include/linux/fs.h:768 [inline]
#0: 000000006d638564 (&sb->s_type->i_mutex_key#31){+.+.}, at: f2fs_file_write_iter+0x1b6/0xbe0 fs/f2fs/file.c:2993
2 locks held by syz-executor.2/14958:
#0: 00000000695f87b4 (sb_writers#24){.+.+}, at: file_start_write include/linux/fs.h:2779 [inline]
#0: 00000000695f87b4 (sb_writers#24){.+.+}, at: do_sendfile+0x97d/0xc30 fs/read_write.c:1446
#1: 000000006d638564 (&sb->s_type->i_mutex_key#31){+.+.}, at: inode_lock include/linux/fs.h:748 [inline]
#1: 000000006d638564 (&sb->s_type->i_mutex_key#31){+.+.}, at: f2fs_file_write_iter+0x218/0xbe0 fs/f2fs/file.c:2996
1 lock held by syz-executor.4/19622:
#0: 00000000b032fdf7 (&sb->s_type->i_mutex_key#31){+.+.}, at: inode_trylock include/linux/fs.h:768 [inline]
#0: 00000000b032fdf7 (&sb->s_type->i_mutex_key#31){+.+.}, at: f2fs_file_write_iter+0x1b6/0xbe0 fs/f2fs/file.c:2993
2 locks held by syz-executor.4/19623:
#0: 000000009ebe5a79 (sb_writers#24){.+.+}, at: file_start_write include/linux/fs.h:2779 [inline]
#0: 000000009ebe5a79 (sb_writers#24){.+.+}, at: do_sendfile+0x97d/0xc30 fs/read_write.c:1446
#1: 00000000b032fdf7 (&sb->s_type->i_mutex_key#31){+.+.}, at: inode_lock include/linux/fs.h:748 [inline]
#1: 00000000b032fdf7 (&sb->s_type->i_mutex_key#31){+.+.}, at: f2fs_file_write_iter+0x218/0xbe0 fs/f2fs/file.c:2996

=============================================

NMI backtrace for cpu 1
CPU: 1 PID: 1569 Comm: khungtaskd Not tainted 4.19.211-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 10/26/2022
Call Trace:
__dump_stack lib/dump_stack.c:77 [inline]
dump_stack+0x1fc/0x2ef lib/dump_stack.c:118
nmi_cpu_backtrace.cold+0x63/0xa2 lib/nmi_backtrace.c:101
nmi_trigger_cpumask_backtrace+0x1a6/0x1f0 lib/nmi_backtrace.c:62
trigger_all_cpu_backtrace include/linux/nmi.h:146 [inline]
check_hung_uninterruptible_tasks kernel/hung_task.c:203 [inline]
watchdog+0x991/0xe60 kernel/hung_task.c:287
kthread+0x33f/0x460 kernel/kthread.c:259
ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:415
Sending NMI from CPU 1 to CPUs 0:
NMI backtrace for cpu 0
CPU: 0 PID: 4689 Comm: systemd-journal Not tainted 4.19.211-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 10/26/2022
RIP: 0010:get_current arch/x86/include/asm/current.h:15 [inline]
RIP: 0010:__sanitizer_cov_trace_pc+0x4/0x50 kernel/kcov.c:100
Code: e8 11 dd 35 00 e9 ab fe ff ff 4c 89 ef e8 04 dd 35 00 e9 23 fe ff ff 90 90 90 90 90 90 90 90 90 90 90 90 90 90 90 48 8b 34 24 <65> 48 8b 04 25 c0 df 01 00 65 8b 15 cc 59 9f 7e 81 e2 00 01 1f 00
RSP: 0018:ffff8880a0c5ff20 EFLAGS: 00000246
RAX: 0000000000000000 RBX: 0000000000000000 RCX: ffffffff810077d3
RDX: 0000000000000000 RSI: ffffffff810077e0 RDI: 0000000000000005
RBP: ffff8880a0c5ff58 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000005 R11: 0000000000000000 R12: 0000000000000102
R13: ffffffff89f18298 R14: 0000000000000000 R15: 0000000000000000
FS: 00007fd38f5108c0(0000) GS:ffff8880ba000000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007fd38c97f000 CR3: 00000000a10af000 CR4: 00000000003406f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000600
Call Trace:
arch_local_irq_disable arch/x86/include/asm/paravirt.h:794 [inline]
syscall_return_slowpath arch/x86/entry/common.c:270 [inline]
do_syscall_64+0x1c0/0x620 arch/x86/entry/common.c:296
entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x7fd38ea9f840
Code: 73 01 c3 48 8b 0d 68 77 20 00 f7 d8 64 89 01 48 83 c8 ff c3 66 0f 1f 44 00 00 83 3d 89 bb 20 00 00 75 10 b8 02 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 31 c3 48 83 ec 08 e8 1e f6 ff ff 48 89 04 24
RSP: 002b:00007ffe2e963828 EFLAGS: 00000246 ORIG_RAX: 0000000000000002
RAX: fffffffffffffffe RBX: 00007ffe2e963b30 RCX: 00007fd38ea9f840
RDX: 00000000000001a0 RSI: 0000000000080042 RDI: 0000564a29a21f20
RBP: 000000000000000d R08: 0000000000000000 R09: 00000000ffffffff
R10: 0000000000000069 R11: 0000000000000246 R12: 00000000ffffffff
R13: 0000564a29a14040 R14: 00007ffe2e963af0 R15: 0000564a29a1fb00


---
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,
Dec 10, 2022, 9:03:37 PM12/10/22
to syzkaller...@googlegroups.com
syzbot has found a reproducer for the following issue on:

HEAD commit: 3f8a27f9e27b Linux 4.19.211
git tree: linux-4.19.y
console output: https://syzkaller.appspot.com/x/log.txt?x=100eb967880000
kernel config: https://syzkaller.appspot.com/x/.config?x=9b9277b418617afe
dashboard link: https://syzkaller.appspot.com/bug?extid=3beffef3d21bf9a3425f
compiler: gcc version 10.2.1 20210110 (Debian 10.2.1-6)
syz repro: https://syzkaller.appspot.com/x/repro.syz?x=11ca950b880000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=12466eb7880000
mounted in repro: https://storage.googleapis.com/syzbot-assets/0e5778181dc8/mount_0.gz

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

F2FS-fs (loop0): invalid crc value
F2FS-fs (loop0): Found nat_bits in checkpoint
F2FS-fs (loop0): f2fs_check_nid_range: out-of-range nid=2, run fsck to fix.
F2FS-fs (loop0): Mounted with checkpoint version = 48b305e4
INFO: task syz-executor466:8105 blocked for more than 140 seconds.
Not tainted 4.19.211-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor466 D26528 8105 8104 0x00000004
Call Trace:
context_switch kernel/sched/core.c:2828 [inline]
__schedule+0x887/0x2040 kernel/sched/core.c:3517
schedule+0x8d/0x1b0 kernel/sched/core.c:3561
io_schedule+0xb5/0x120 kernel/sched/core.c:5181
wait_on_page_bit_common mm/filemap.c:1123 [inline]
wait_on_page_bit+0x2c5/0x3f0 mm/filemap.c:1156
wait_on_page_writeback include/linux/pagemap.h:547 [inline]
__filemap_fdatawait_range+0x3ae/0x510 mm/filemap.c:535
filemap_fdatawait_range mm/filemap.c:560 [inline]
filemap_write_and_wait_range mm/filemap.c:683 [inline]
filemap_write_and_wait_range+0x6e/0xd0 mm/filemap.c:673
__generic_file_write_iter+0x4cf/0x610 mm/filemap.c:3281
f2fs_file_write_iter+0x3c4/0xbe0 fs/f2fs/file.c:3031
call_write_iter include/linux/fs.h:1821 [inline]
aio_write+0x37f/0x5c0 fs/aio.c:1574
__io_submit_one fs/aio.c:1858 [inline]
io_submit_one+0xecd/0x20c0 fs/aio.c:1909
__do_sys_io_submit fs/aio.c:1953 [inline]
__se_sys_io_submit+0x11b/0x4a0 fs/aio.c:1924
do_syscall_64+0xf9/0x620 arch/x86/entry/common.c:293
entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x7f4ec4b252e9
Code: Bad RIP value.
RSP: 002b:00007ffe82a3eb28 EFLAGS: 00000246 ORIG_RAX: 00000000000000d1
RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f4ec4b252e9
RDX: 0000000020000540 RSI: 0000000000000008 RDI: 00007f4ec06b7000
RBP: 0000000000000000 R08: 00007f4ec4ba3ec0 R09: 00007f4ec4ba3ec0
R10: 00007f4ec4ba3ec0 R11: 0000000000000246 R12: 00007ffe82a3eb50
R13: 0000000000000000 R14: 431bde82d7b634db R15: 0000000000000000

Showing all locks held in the system:
1 lock held by khungtaskd/1571:
#0: 000000000d094c00 (rcu_read_lock){....}, at: debug_show_all_locks+0x53/0x265 kernel/locking/lockdep.c:4441
1 lock held by syz-executor466/8105:
#0: 0000000037f00765 (&sb->s_type->i_mutex_key#17){+.+.}, at: inode_trylock include/linux/fs.h:768 [inline]
#0: 0000000037f00765 (&sb->s_type->i_mutex_key#17){+.+.}, at: f2fs_file_write_iter+0x1b6/0xbe0 fs/f2fs/file.c:2993

=============================================

NMI backtrace for cpu 0
CPU: 0 PID: 1571 Comm: khungtaskd Not tainted 4.19.211-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 10/26/2022
Call Trace:
__dump_stack lib/dump_stack.c:77 [inline]
dump_stack+0x1fc/0x2ef lib/dump_stack.c:118
nmi_cpu_backtrace.cold+0x63/0xa2 lib/nmi_backtrace.c:101
nmi_trigger_cpumask_backtrace+0x1a6/0x1f0 lib/nmi_backtrace.c:62
trigger_all_cpu_backtrace include/linux/nmi.h:146 [inline]
check_hung_uninterruptible_tasks kernel/hung_task.c:203 [inline]
watchdog+0x991/0xe60 kernel/hung_task.c:287
kthread+0x33f/0x460 kernel/kthread.c:259
ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:415
Sending NMI from CPU 0 to CPUs 1:
NMI backtrace for cpu 1
CPU: 1 PID: 10 Comm: rcu_preempt Not tainted 4.19.211-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 10/26/2022
RIP: 0010:__sanitizer_cov_trace_pc+0x0/0x50 kernel/kcov.c:97
Code: ff 48 89 df e8 11 dd 35 00 e9 ab fe ff ff 4c 89 ef e8 04 dd 35 00 e9 23 fe ff ff 90 90 90 90 90 90 90 90 90 90 90 90 90 90 90 <48> 8b 34 24 65 48 8b 04 25 c0 df 01 00 65 8b 15 cc 59 9f 7e 81 e2
RSP: 0018:ffff8880b5a67b98 EFLAGS: 00000003
RAX: 1ffff1101742456f RBX: 1ffff11016b4cf74 RCX: ffffffff8153155b
RDX: 0000000000000000 RSI: ffffffff8153161f RDI: ffff8880ba122b78
RBP: ffff8880ba122b40 R08: 0000000000000001 R09: 0000000008c00001
R10: 0000000000000004 R11: 0000000000000000 R12: ffff8880b5a67cc0
R13: dffffc0000000000 R14: ffff8880ba122b40 R15: 00000000ffffffff
FS: 0000000000000000(0000) GS:ffff8880ba100000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007f02068da000 CR3: 00000000a1364000 CR4: 00000000003406e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
try_to_del_timer_sync+0x9a/0x110 kernel/time/timer.c:1240
del_timer_sync+0x1a4/0x270 kernel/time/timer.c:1305
schedule_timeout+0x4d7/0xfe0 kernel/time/timer.c:1819
rcu_gp_kthread+0xdad/0x21c0 kernel/rcu/tree.c:2202
Reply all
Reply to author
Forward
0 new messages