Re: INFO: task hung in io_uring_cancel_sqpoll

[Palash Oswal]

On Mon, May 3, 2021 at 3:42 AM Pavel Begunkov <asml.silence@xxxxxxxxx> wrote:
>
> On 4/30/21 3:21 PM, Palash Oswal wrote:
> > On Thursday, March 18, 2021 at 9:40:21 PM UTC+5:30 syzbot wrote:
> >>
> >> Hello,
> >>
> >> syzbot found the following issue on:
> >>
> >> HEAD commit: 0d7588ab riscv: process: Fix no prototype for arch_dup_tas..
> >> git tree: git://git.kernel.org/pub/scm/linux/kernel/git/riscv/linux.git fixes
> >> console output: https://syzkaller.appspot.com/x/log.txt?x=12dde5aed00000
> >> kernel config: https://syzkaller.appspot.com/x/.config?x=81c0b708b31626cc
> >> dashboard link: https://syzkaller.appspot.com/bug?extid=11bf59db879676f59e52
> >> userspace arch: riscv64
> >> CC: [asml.s...@xxxxxxxxx ax...@xxxxxxxxx io-u...@xxxxxxxxxxxxxxx linux-...@xxxxxxxxxxxxxxx]
> >>
> >> Unfortunately, I don't have any reproducer for this issue yet.
> >>
> >> IMPORTANT: if you fix the issue, please add the following tag to the commit:
> >> Reported-by: syzbot+11bf59...@xxxxxxxxxxxxxxxxxxxxxxxxx
> >>
> >> INFO: task iou-sqp-4867:4871 blocked for more than 430 seconds.
> >> Not tainted 5.12.0-rc2-syzkaller-00467-g0d7588ab9ef9 #0
> >> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> >> task:iou-sqp-4867 state:D stack: 0 pid: 4871 ppid: 4259 flags:0x00000004
> >> Call Trace:
> >> [<ffffffe003bc3252>] context_switch kernel/sched/core.c:4324 [inline]
> >> [<ffffffe003bc3252>] __schedule+0x478/0xdec kernel/sched/core.c:5075
> >> [<ffffffe003bc3c2a>] schedule+0x64/0x166 kernel/sched/core.c:5154
> >> [<ffffffe0004b80ee>] io_uring_cancel_sqpoll+0x1de/0x294 fs/io_uring.c:8858
> >> [<ffffffe0004c19cc>] io_sq_thread+0x548/0xe58 fs/io_uring.c:6750
> >> [<ffffffe000005570>] ret_from_exception+0x0/0x14
>
> The test might be very useful. Would you send a patch to
> liburing? Or mind the repro being taken as a test?
>
>

Pavel,

I'm working on a PR for liburing with this test. Do you know how I can
address this behavior?

root@syzkaller:~/liburing/test# ./runtests.sh sqpoll-cancel-hang
Running test sqp[   15.310997] Running test sqpoll-cancel-hang:
oll-cancel-hang:
[   15.333348] sqpoll-cancel-h[305]: segfault at 0 ip 000055ad00e265e3 sp]
[   15.334940] Code: 89 d8 8d 34 90 8b 45 04 ba 03 00 00 00 c1 e0 04 03 46
All tests passed

root@syzkaller:~/liburing/test# ./sqpoll-cancel-hang
[   13.572639] sqpoll-cancel-h[298]: segfault at 0 ip 00005634c4a455e3 sp]
[   13.576506] Code: 89 d8 8d 34 90 8b 45 04 ba 03 00 00 00 c1 e0 04 03 46
[   23.350459] random: crng init done
[   23.352837] random: 7 urandom warning(s) missed due to ratelimiting
[  243.090865] INFO: task iou-sqp-298:299 blocked for more than 120 secon.
[  243.095187]       Not tainted 5.12.0 #142
[  243.099800] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disable.
[  243.105928] task:iou-sqp-298     state:D stack:    0 pid:  299 ppid:  4
[  243.111044] Call Trace:
[  243.112855]  __schedule+0xb1d/0x1130
[  243.115549]  ? __sched_text_start+0x8/0x8
[  243.118328]  ? io_wq_worker_sleeping+0x145/0x500
[  243.121790]  schedule+0x131/0x1c0
[  243.123698]  io_uring_cancel_sqpoll+0x288/0x350
[  243.125977]  ? io_sq_thread_unpark+0xd0/0xd0
[  243.128966]  ? mutex_lock+0xbb/0x130
[  243.132572]  ? init_wait_entry+0xe0/0xe0
[  243.135429]  ? wait_for_completion_killable_timeout+0x20/0x20
[  243.138303]  io_sq_thread+0x174c/0x18c0
[  243.140162]  ? io_rsrc_put_work+0x380/0x380
[  243.141613]  ? init_wait_entry+0xe0/0xe0
[  243.143686]  ? _raw_spin_lock_irq+0xa5/0x180
[  243.145619]  ? _raw_spin_lock_irqsave+0x190/0x190
[  243.147671]  ? calculate_sigpending+0x6b/0xa0
[  243.149036]  ? io_rsrc_put_work+0x380/0x380
[  243.150694]  ret_from_fork+0x22/0x30

Palash