Re: INFO: task hung in do_read_cache_page

From: Hao Sun
Date: Mon Sep 13 2021 - 21:48:51 EST


Hao Sun <sunhao.th@xxxxxxxxx> 于2021年9月13日周一 上午10:10写道:
>
> Hello,
>
> When using Healer to fuzz the latest Linux kernel, the following crash
> was triggered.
>
> HEAD commit: 4b93c544e90e-thunderbolt: test: split up test cases
> git tree: upstream
> console output:
> https://drive.google.com/file/d/1maGu7OQMMnheEq18g-XJRrSvPIRLyIae/view?usp=sharing
> kernel config: https://drive.google.com/file/d/1c0u2EeRDhRO-ZCxr9MP2VvAtJd6kfg-p/view?usp=sharing
> C reproducer: https://drive.google.com/file/d/1pf2nzNzl2hUxO6EJ1Vp4uqeAmr9tG4Pw/view?usp=sharing
> Syzlang reproducer:
> https://drive.google.com/file/d/1CZekMFes8O7FmLULOkxLnovMGWNFtI47/view?usp=sharing
> Similar report:
> https://groups.google.com/g/syzkaller-bugs/c/mt4E4qKbC5c/m/m-gbLPjIAgAJ
>
> If you fix this issue, please add the following tag to the commit:
> Reported-by: Hao Sun <sunhao.th@xxxxxxxxx>
>

Hi

This crash can still be triggered with the same C reproducer on the
latest kernel.

HEAD commit: 6880fa6c5660 Linux 5.15-rc1
git tree: upstream
kernel config: https://drive.google.com/file/d/1c0u2EeRDhRO-ZCxr9MP2VvAtJd6kfg-p/view?usp=sharing

nbd0: detected capacity change from 0 to 18
block nbd0: shutting down sockets
block nbd0: Possible stuck request ffff888018830000: control
(read@0,4096B). Runtime 30 seconds
block nbd0: Possible stuck request ffff888018830000: control
(read@0,4096B). Runtime 60 seconds
block nbd0: Possible stuck request ffff888018830000: control
(read@0,4096B). Runtime 90 seconds
block nbd0: Possible stuck request ffff888018830000: control
(read@0,4096B). Runtime 120 seconds
block nbd0: Possible stuck request ffff888018830000: control
(read@0,4096B). Runtime 150 seconds
INFO: task a.out:6658 blocked for more than 143 seconds.
Not tainted 5.15.0-rc1 #2
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:a.out state:D stack:27280 pid: 6658 ppid: 6657 flags:0x00004002
Call Trace:
__schedule+0xcd9/0x2530
? firmware_map_remove+0x1a0/0x1a0
schedule+0xd3/0x270
schedule_preempt_disabled+0xf/0x20
__mutex_lock+0xc96/0x1680
? blkdev_put+0x98/0x6f0
? mutex_lock_io_nested+0x1470/0x1470
? do_raw_spin_unlock+0x171/0x260
? blkdev_put+0x98/0x6f0
blkdev_put+0x98/0x6f0
blkdev_close+0x8d/0xb0
__fput+0x288/0x9f0
? blkdev_fsync+0xd0/0xd0
task_work_run+0xe0/0x1a0
do_exit+0xbbe/0x2dd0
? preempt_schedule_common+0x5e/0xc0
? mm_update_next_owner+0x7a0/0x7a0
? preempt_schedule_thunk+0x16/0x18
do_group_exit+0x125/0x340
__x64_sys_exit_group+0x3a/0x50
do_syscall_64+0x35/0xb0
entry_SYSCALL_64_after_hwframe+0x44/0xae
RIP: 0033:0x7fe9d6949618
RSP: 002b:00007ffffdd5e678 EFLAGS: 00000246 ORIG_RAX: 00000000000000e7
RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007fe9d6949618
RDX: 0000000000000000 RSI: 000000000000003c RDI: 0000000000000000
RBP: 00007fe9d6c268e0 R08: 00000000000000e7 R09: ffffffffffffff98
R10: 00007fe9d6e48260 R11: 0000000000000246 R12: 00007fe9d6c268e0
R13: 00007fe9d6c2bc20 R14: 0000000000000000 R15: 0000000000000000
INFO: task systemd-udevd:6665 blocked for more than 143 seconds.
Not tainted 5.15.0-rc1 #2
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:systemd-udevd state:D stack:26352 pid: 6665 ppid: 2993 flags:0x00004000
Call Trace:
__schedule+0xcd9/0x2530
? firmware_map_remove+0x1a0/0x1a0
? preempt_schedule_common+0x5e/0xc0
schedule+0xd3/0x270
io_schedule+0x17/0x70
wait_on_page_bit_common+0x57c/0xf10
? filemap_get_read_batch+0xe50/0xe50
? end_buffer_async_write+0x5d0/0x5d0
? __filemap_set_wb_err+0x240/0x240
? __sanitizer_cov_trace_pc+0x1a/0x40
? __page_cache_alloc+0x110/0x3d0
? enable_ptr_key_workfn+0x30/0x30
do_read_cache_page+0x911/0x1440
read_part_sector+0xfa/0x610
? adfspart_check_ADFS+0x830/0x830
adfspart_check_ICS+0x9d/0xc90
? pointer+0x810/0x810
? __alloc_pages+0x526/0x6e0
? __sanitizer_cov_trace_pc+0x1a/0x40
? __vmalloc_node_range+0x4aa/0x940
? adfspart_check_ADFS+0x830/0x830
? snprintf+0xbb/0xf0
? vsprintf+0x30/0x30
? __sanitizer_cov_trace_pc+0x1a/0x40
? adfspart_check_ADFS+0x830/0x830
bdev_disk_changed+0x778/0x1140
blkdev_get_whole+0x206/0x270
blkdev_get_by_dev+0x456/0x900
blkdev_open+0x154/0x2b0
do_dentry_open+0x4c8/0x11d0
? blkdev_close+0xb0/0xb0
path_openat+0x1c99/0x2710
? path_lookupat.isra.0+0x580/0x580
? lockdep_hardirqs_on_prepare+0x400/0x400
do_filp_open+0x1c1/0x290
? may_open_dev+0xf0/0xf0
? do_raw_spin_lock+0x120/0x2d0
? rwlock_bug.part.0+0x90/0x90
? __phys_addr_symbol+0x2c/0x70
? __sanitizer_cov_trace_pc+0x1a/0x40
? _find_next_bit+0x1e3/0x260
? _raw_spin_unlock+0x24/0x40
? alloc_fd+0x4bd/0x660
do_sys_openat2+0x61b/0x9a0
? rcu_read_lock_bh_held+0x14/0xb0
? file_open_root+0x430/0x430
? seccomp_notify_ioctl+0xdb0/0xdb0
do_sys_open+0xc3/0x140
? filp_open+0x70/0x70
? __sanitizer_cov_trace_pc+0x1a/0x40
? __secure_computing+0x104/0x360
do_syscall_64+0x35/0xb0
entry_SYSCALL_64_after_hwframe+0x44/0xae
RIP: 0033:0x7f8efe051840
RSP: 002b:00007ffef9fe31a8 EFLAGS: 00000246 ORIG_RAX: 0000000000000002
RAX: ffffffffffffffda RBX: 000055a1992dd370 RCX: 00007f8efe051840
RDX: 000055a197b1afe3 RSI: 00000000000a0800 RDI: 000055a1992d1260
RBP: 00007ffef9fe3320 R08: 000055a197b1a670 R09: 0000000000000010
R10: 00007f8efddcbd70 R11: 0000000000000246 R12: 00007ffef9fe3270
R13: 000055a1992d4c20 R14: 0000000000000003 R15: 000000000000000e

Showing all locks held in the system:
1 lock held by khungtaskd/29:
#0: ffffffff8b97e9a0 (rcu_read_lock){....}-{1:2}, at:
debug_show_all_locks+0x53/0x260
1 lock held by in:imklog/6245:
#0: ffff888107d06370 (&f->f_pos_lock){+.+.}-{3:3}, at: __fdget_pos+0xe9/0x100
1 lock held by a.out/6658:
#0: ffff8880187f2118 (&disk->open_mutex){+.+.}-{3:3}, at: blkdev_put+0x98/0x6f0
1 lock held by systemd-udevd/6665:
#0: ffff8880187f2118 (&disk->open_mutex){+.+.}-{3:3}, at:
blkdev_get_by_dev+0x3c1/0x900

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

NMI backtrace for cpu 0
CPU: 0 PID: 29 Comm: khungtaskd Not tainted 5.15.0-rc1 #2
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS
1.13.0-1ubuntu1.1 04/01/2014
Call Trace:
dump_stack_lvl+0xcd/0x134
nmi_cpu_backtrace.cold+0x47/0x144
? lapic_can_unplug_cpu+0x80/0x80
nmi_trigger_cpumask_backtrace+0x1e1/0x220
watchdog+0xcc8/0x1010
? reset_hung_task_detector+0x30/0x30
kthread+0x3e5/0x4d0
? set_kthread_struct+0x130/0x130
ret_from_fork+0x1f/0x30
Sending NMI from CPU 0 to CPUs 1:
NMI backtrace for cpu 1
CPU: 1 PID: 2986 Comm: systemd-journal Not tainted 5.15.0-rc1 #2
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS
1.13.0-1ubuntu1.1 04/01/2014
RIP: 0010:do_faccessat+0x2/0x850
Code: 84 00 00 00 25 e3 7f ff ff 0d 00 00 20 00 89 83 84 00 00 00 31
c0 5b c3 e8 2b 99 f5 ff eb df 66 0f 1f 84 00 00 00 00 00 41 57 <41> 56
41 55 41 54 55 89 cd 53 89 d3 48 83 c4 80 41 89 dc 48 8d 44
RSP: 0018:ffffc9000185ff30 EFLAGS: 00000246
RAX: dffffc0000000000 RBX: 0000000000000000 RCX: 0000000000000000
RDX: 0000000000000000 RSI: 00005560fae709a3 RDI: 00000000ffffff9c
RBP: ffffc9000185ff48 R08: ffffffff81c88ffd R09: 0000000000000000
R10: 0000000000000001 R11: ffffed1003425582 R12: ffffc9000185ff58
R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
FS: 00007f792748f8c0(0000) GS:ffff888135c00000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007f79247d3000 CR3: 0000000107cde000 CR4: 0000000000350ee0
Call Trace:
do_syscall_64+0x35/0xb0
entry_SYSCALL_64_after_hwframe+0x44/0xae
RIP: 0033:0x7f792674b9c7
Code: 83 c4 08 48 3d 01 f0 ff ff 73 01 c3 48 8b 0d c8 d4 2b 00 f7 d8
64 89 01 48 83 c8 ff c3 66 0f 1f 44 00 00 b8 15 00 00 00 0f 05 <48> 3d
01 f0 ff ff 73 01 c3 48 8b 0d a1 d4 2b 00 f7 d8 64 89 01 48
RSP: 002b:00007ffe4c6ab808 EFLAGS: 00000246 ORIG_RAX: 0000000000000015
RAX: ffffffffffffffda RBX: 00007ffe4c6ae720 RCX: 00007f792674b9c7
RDX: 00007f79271bca00 RSI: 0000000000000000 RDI: 00005560fae709a3
RBP: 00007ffe4c6ab840 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000069 R11: 0000000000000246 R12: 0000000000000000
R13: 0000000000000000 R14: 00007ffe4c6ae720 R15: 00007ffe4c6abd30
Kernel panic - not syncing: hung_task: blocked tasks
CPU: 0 PID: 29 Comm: khungtaskd Not tainted 5.15.0-rc1 #2
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS
1.13.0-1ubuntu1.1 04/01/2014
Call Trace:
dump_stack_lvl+0xcd/0x134
panic+0x2b0/0x6dd
? print_oops_end_marker.cold+0x15/0x15
? lapic_can_unplug_cpu+0x80/0x80
? preempt_schedule_thunk+0x16/0x18
? watchdog.cold+0x5/0x168
watchdog.cold+0x16/0x168
? reset_hung_task_detector+0x30/0x30
kthread+0x3e5/0x4d0
? set_kthread_struct+0x130/0x130
ret_from_fork+0x1f/0x30
Dumping ftrace buffer:
(ftrace buffer empty)
Kernel Offset: disabled
Rebooting in 1 seconds..