2022-01-09 14:24:44

by Sabri N. Ferreiro

[permalink] [raw]
Subject: INFO: task hung in fd_watchdog

Hi,

When using Syzkaller to fuzz the Linux kernel, it triggers the following crash.

HEAD commit: a7904a538933 Linux 5.16-rc6
git tree: upstream
console output: https://pastebin.com/raw/ufQZJNFy
kernel config: https://docs.google.com/document/d/1w94kqQ4ZSIE6BW-5WIhqp4_Zh7XTPH57L5OF2Xb6O6o/view
C reproducer: https://pastebin.com/raw/ByeE6LJ3
Syzlang reproducer: https://pastebin.com/raw/gi8ZtsQC

If you fix this issue, please add the following tag to the commit:
Reported-by: Yuheng Shen [email protected]

INFO: task kworker/u16:3:9594 blocked for more than 143 seconds.
Not tainted 5.16.0-rc8+ #10
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:kworker/u16:3 state:D stack:27224 pid: 9594 ppid: 2 flags:0x00004000
Workqueue: floppy floppy_work_workfn
Call Trace:
<TASK>
__schedule+0xcd9/0x2550
schedule+0xd2/0x260
schedule_timeout+0x5e5/0x890
wait_for_completion+0x17b/0x280
__flush_work+0x56c/0xb10
__cancel_work_timer+0x370/0x4b0
fd_watchdog.cold+0x3b/0x8f
setup_rw_floppy+0x6f1/0x9f0
floppy_ready+0x425/0x19b0
recal_interrupt+0xd9/0x610
process_one_work+0x9df/0x16a0
worker_thread+0x90/0xe20
kthread+0x405/0x4f0
ret_from_fork+0x1f/0x30
</TASK>
INFO: task syz-executor.0:21342 blocked for more than 143 seconds.
Not tainted 5.16.0-rc8+ #10
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:syz-executor.0 state:D stack:27920 pid:21342 ppid: 6935 flags:0x00000004
Call Trace:
<TASK>
__schedule+0xcd9/0x2550
schedule+0xd2/0x260
schedule_preempt_disabled+0xf/0x20
__mutex_lock+0xc48/0x1610
floppy_release+0x43/0x1c0
blkdev_put_whole+0xd2/0x110
blkdev_put+0x296/0x710
blkdev_close+0x6a/0x80
__fput+0x286/0x9f0
task_work_run+0xe0/0x1a0
exit_to_user_mode_prepare+0x28d/0x2a0
syscall_exit_to_user_mode+0x19/0x60
do_syscall_64+0x42/0xb0
entry_SYSCALL_64_after_hwframe+0x44/0xae
RIP: 0033:0x7f196095b14b
RSP: 002b:00007ffd4516c600 EFLAGS: 00000293 ORIG_RAX: 0000000000000003
RAX: 0000000000000000 RBX: 0000000000000005 RCX: 00007f196095b14b
RDX: 00007f1960acf5f8 RSI: 0000000000000001 RDI: 0000000000000004
RBP: 00007f1960acc96c R08: 0000000000000000 R09: 00007f1960acf600
R10: 00007ffd4516c730 R11: 0000000000000293 R12: 000000000005c797
R13: 00007ffd4516c740 R14: 00007f1960acaf6c R15: 000000000005c7c9
</TASK>
INFO: task syz-executor.7:21344 blocked for more than 143 seconds.
Not tainted 5.16.0-rc8+ #10
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:syz-executor.7 state:D stack:27920 pid:21344 ppid: 6934 flags:0x00000004
Call Trace:
<TASK>
__schedule+0xcd9/0x2550
schedule+0xd2/0x260
schedule_preempt_disabled+0xf/0x20
__mutex_lock+0xc48/0x1610
blkdev_put+0xa6/0x710
blkdev_close+0x6a/0x80
__fput+0x286/0x9f0
task_work_run+0xe0/0x1a0
exit_to_user_mode_prepare+0x28d/0x2a0
syscall_exit_to_user_mode+0x19/0x60
do_syscall_64+0x42/0xb0
entry_SYSCALL_64_after_hwframe+0x44/0xae
RIP: 0033:0x7f740523814b
RSP: 002b:00007ffcaa72e410 EFLAGS: 00000293 ORIG_RAX: 0000000000000003
RAX: 0000000000000000 RBX: 0000000000000004 RCX: 00007f740523814b
RDX: 0000001b2c820000 RSI: 0000000000000000 RDI: 0000000000000003
RBP: 00007f74053a9960 R08: 0000000000000000 R09: 00007ffcaa780090
R10: 000000000000edfc R11: 0000000000000293 R12: 000000000005ca89
R13: 00007ffcaa72e550 R14: 00007f74053a810c R15: 000000000005c7d7
</TASK>
INFO: task syz-executor.7:21347 blocked for more than 143 seconds.
Not tainted 5.16.0-rc8+ #10
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:syz-executor.7 state:D stack:28384 pid:21347 ppid: 6934 flags:0x00004004
Call Trace:
<TASK>
__schedule+0xcd9/0x2550
schedule+0xd2/0x260
__cancel_work_timer+0x44a/0x4b0
wait_til_done+0x340/0x370
fd_locked_ioctl+0x19ec/0x23d0
fd_ioctl+0x35/0x50
blkdev_ioctl+0x37a/0x800
__x64_sys_ioctl+0x193/0x200
do_syscall_64+0x35/0xb0
entry_SYSCALL_64_after_hwframe+0x44/0xae
RIP: 0033:0x7f740528889d
RSP: 002b:00007f7403bf9c28 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 00007f74053a7f60 RCX: 00007f740528889d
RDX: 0000000020000100 RSI: 0000000000000258 RDI: 0000000000000005
RBP: 00007f74052f500d R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000
R13: 00007ffcaa72e3af R14: 00007f74053a7f60 R15: 00007f7403bf9dc0
</TASK>
INFO: task syz-executor.2:21480 blocked for more than 143 seconds.
Not tainted 5.16.0-rc8+ #10
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:syz-executor.2 state:D stack:27920 pid:21480 ppid: 6932 flags:0x00000004
Call Trace:
<TASK>
__schedule+0xcd9/0x2550
schedule+0xd2/0x260
schedule_preempt_disabled+0xf/0x20
__mutex_lock+0xc48/0x1610
blkdev_get_by_dev+0x23b/0xa80
blkdev_open+0x154/0x2e0
do_dentry_open+0x4b9/0x1240
path_openat+0x1c3c/0x26c0
do_filp_open+0x1c1/0x290
do_sys_openat2+0x61b/0x9a0
do_sys_open+0xc3/0x140
do_syscall_64+0x35/0xb0
entry_SYSCALL_64_after_hwframe+0x44/0xae
RIP: 0033:0x7f3dcea8f434
RSP: 002b:00007f3dcd42f750 EFLAGS: 00000293 ORIG_RAX: 0000000000000101
RAX: ffffffffffffffda RBX: 6666666666666667 RCX: 00007f3dcea8f434
RDX: 0000000000000c00 RSI: 00007f3dcd42f7f0 RDI: 00000000ffffff9c
RBP: 00007f3dcd42f7f0 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000293 R12: 0000000000000c00
R13: 00007ffe9ca1c26f R14: 00007f3dcebff030 R15: 00007f3dcd42fdc0
</TASK>

Showing all locks held in the system:
1 lock held by khungtaskd/59:
#0: ffffffff8bb80ee0 (rcu_read_lock){....}-{1:2}, at:
debug_show_all_locks+0x53/0x260
1 lock held by in:imklog/6782:
#0: ffff88801c992670 (&f->f_pos_lock){+.+.}-{3:3}, at: __fdget_pos+0xe9/0x100
2 locks held by kworker/u16:3/9594:
#0: ffff88810505b138 ((wq_completion)floppy){+.+.}-{0:0}, at:
process_one_work+0x8c3/0x16a0
#1: ffffc900180b7dc8 (floppy_work){+.+.}-{0:0}, at:
process_one_work+0x8f7/0x16a0
2 locks held by syz-executor.0/21342:
#0: ffff88801a762918 (&disk->open_mutex){+.+.}-{3:3}, at: blkdev_put+0xa6/0x710
#1: ffffffff8c6a4c88 (floppy_mutex){+.+.}-{3:3}, at: floppy_release+0x43/0x1c0
1 lock held by syz-executor.7/21344:
#0: ffff88801a762918 (&disk->open_mutex){+.+.}-{3:3}, at: blkdev_put+0xa6/0x710
1 lock held by syz-executor.7/21347:
#0: ffffffff8c6a4c88 (floppy_mutex){+.+.}-{3:3}, at: fd_ioctl+0x25/0x50
1 lock held by syz-executor.2/21480:
#0: ffff88801a762918 (&disk->open_mutex){+.+.}-{3:3}, at:
blkdev_get_by_dev+0x23b/0xa80

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

NMI backtrace for cpu 4
CPU: 4 PID: 59 Comm: khungtaskd Not tainted 5.16.0-rc8+ #10
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS
1.13.0-1ubuntu1.1 04/01/2014
Call Trace:
<TASK>
dump_stack_lvl+0xcd/0x134
nmi_cpu_backtrace.cold+0x47/0x144
nmi_trigger_cpumask_backtrace+0x1a1/0x1e0
watchdog+0xcc8/0x1010
kthread+0x405/0x4f0
ret_from_fork+0x1f/0x30
</TASK>
Sending NMI from CPU 4 to CPUs 0-3,5-7:
NMI backtrace for cpu 2 skipped: idling at default_idle+0xb/0x10
NMI backtrace for cpu 0 skipped: idling at default_idle+0xb/0x10
NMI backtrace for cpu 5 skipped: idling at default_idle+0xb/0x10
NMI backtrace for cpu 3
CPU: 3 PID: 7496 Comm: kworker/u16:2 Not tainted 5.16.0-rc8+ #10
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS
1.13.0-1ubuntu1.1 04/01/2014
Workqueue: bat_events batadv_nc_worker
RIP: 0010:__this_cpu_preempt_check+0xd/0x20
Code: 00 00 48 c7 c6 e0 1f 05 8a 48 c7 c7 20 20 05 8a e9 78 fe ff ff
0f 1f 84 00 00 00 00 00 55 48 89 fd 0f 1f 44 00 00 48 89 ee 5d <48> c7
c7 60 20 05 8a e9 57 fe ff ff cc cc cc cc cc cc cc 0f 1f 44
RSP: 0018:ffffc900095efbe8 EFLAGS: 00000086
RAX: 0000000000000001 RBX: 1ffff920012bdf80 RCX: 0000000000000001
RDX: 1ffff11020dab873 RSI: ffffffff89ac11c0 RDI: ffffffff89ac11c0
RBP: 0000000000000000 R08: 1ffff11020dab87d R09: fffffbfff1fee329
R10: ffffffff8ff71947 R11: fffffbfff1fee328 R12: 0000000000000002
R13: ffffffff8bb80ee0 R14: 0000000000000000 R15: 0000000000000000
FS: 0000000000000000(0000) GS:ffff888135c80000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 000000c000235090 CR3: 0000000019740000 CR4: 0000000000350ee0
Call Trace:
<TASK>
lock_acquire+0x1bb/0x520
batadv_nc_worker+0x114/0x770
process_one_work+0x9df/0x16a0
worker_thread+0x90/0xe20
kthread+0x405/0x4f0
ret_from_fork+0x1f/0x30
</TASK>
NMI backtrace for cpu 7 skipped: idling at default_idle+0xb/0x10
NMI backtrace for cpu 1 skipped: idling at default_idle+0xb/0x10
NMI backtrace for cpu 6 skipped: idling at default_idle+0xb/0x10
----------------
Code disassembly (best guess):
0: 00 00 add %al,(%rax)
2: 48 c7 c6 e0 1f 05 8a mov $0xffffffff8a051fe0,%rsi
9: 48 c7 c7 20 20 05 8a mov $0xffffffff8a052020,%rdi
10: e9 78 fe ff ff jmpq 0xfffffe8d
15: 0f 1f 84 00 00 00 00 nopl 0x0(%rax,%rax,1)
1c: 00
1d: 55 push %rbp
1e: 48 89 fd mov %rdi,%rbp
21: 0f 1f 44 00 00 nopl 0x0(%rax,%rax,1)
26: 48 89 ee mov %rbp,%rsi
29: 5d pop %rbp
* 2a: 48 c7 c7 60 20 05 8a mov $0xffffffff8a052060,%rdi <--
trapping instruction
31: e9 57 fe ff ff jmpq 0xfffffe8d
36: cc int3
37: cc int3
38: cc int3
39: cc int3
3a: cc int3
3b: cc int3
3c: cc int3
3d: 0f .byte 0xf
3e: 1f (bad)
3f: 44 rex.R