Re: INFO: task hung in io_uring_cancel_sqpoll

[Palash Oswal]

On Sat, May 1, 2021 at 2:35 AM Pavel Begunkov <asml.silence@xxxxxxxxx> wrote:
>
> On 4/30/21 7:34 PM, Pavel Begunkov wrote:
> > On 4/30/21 4:02 PM, Palash Oswal wrote:
> >> On Fri, Apr 30, 2021 at 8:03 PM 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.
> >>>
> >>> There was so many fixes in 5.12 after this revision, including sqpoll
> >>> cancellation related... Can you try something more up-to-date? Like
> >>> released 5.12 or for-next
> >>>
> >>
> >> The reproducer works for 5.12.
> >>
> >> I tested against the HEAD b1ef997bec4d5cf251bfb5e47f7b04afa49bcdfe
> >> commit on for-next tree
> >> https://git.kernel.org/pub/scm/linux/kernel/git/axboe/linux-block.git/?h=for-next
> >> and the reproducer fails.
> >
> > Can't reproduce. Does it hang as in the original's report dmesg?
> > Can you paste logs?
>
> and `uname -r` if you could


root@syzkaller:~# echo 30 > /proc/sys/kernel/hung_task_timeout_secs
root@syzkaller:~# uname -a
Linux syzkaller 5.12.0 #112 SMP Sat May 1 10:13:41 IST 2021 x86_64 GNU/Linux
root@syzkaller:~# ./repro
[   70.412424] repro[365]: segfault at 0 ip 0000556d88201005 sp
00007ffc7ddf2cd0 error 6 in repro[556d8]
[   70.417215] Code: cc 8b 75 c0 48 8b 45 e8 41 b9 00 00 00 00 41 89
d0 b9 11 80 00 00 ba 03 00 00 00 48
[  121.593305] INFO: task iou-sqp-365:366 blocked for more than 30 seconds.
[  121.594448]       Not tainted 5.12.0 #112
[  121.595072] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[  121.596250] task:iou-sqp-365     state:D stack:    0 pid:  366
ppid:   364 flags:0x00004004
[  121.597514] Call Trace:
[  121.598019]  __schedule+0xb1d/0x1130
[  121.598774]  ? __sched_text_start+0x8/0x8
[  121.599580]  ? io_wq_worker_sleeping+0x145/0x500
[  121.600442]  schedule+0x131/0x1c0
[  121.600902]  io_uring_cancel_sqpoll+0x288/0x350
[  121.601571]  ? io_sq_thread_unpark+0xd0/0xd0
[  121.602410]  ? mutex_lock+0xbb/0x130
[  121.603027]  ? init_wait_entry+0xe0/0xe0
[  121.603573]  ? wait_for_completion_killable_timeout+0x20/0x20
[  121.604454]  io_sq_thread+0x174c/0x18c0
[  121.605014]  ? io_rsrc_put_work+0x380/0x380
[  121.605652]  ? init_wait_entry+0xe0/0xe0
[  121.606428]  ? _raw_spin_lock_irq+0xa5/0x180
[  121.607262]  ? _raw_spin_lock_irqsave+0x190/0x190
[  121.608005]  ? calculate_sigpending+0x6b/0xa0
[  121.608636]  ? io_rsrc_put_work+0x380/0x380
[  121.609301]  ret_from_fork+0x22/0x30


root@syzkaller:~# ps
  PID TTY          TIME CMD
  294 ttyS0    00:00:00 login
  357 ttyS0    00:00:00 bash
  365 ttyS0    00:00:00 repro
  370 ttyS0    00:00:00 ps
root@syzkaller:~# kill -9 365
root@syzkaller:~# [  305.888970] INFO: task iou-sqp-365:366 blocked
for more than 215 seconds.
[  305.893275]       Not tainted 5.12.0 #112
[  305.895507] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[  305.899685] task:iou-sqp-365     state:D stack:    0 pid:  366
ppid:     1 flags:0x00004004
[  305.904071] Call Trace:
[  305.905616]  __schedule+0xb1d/0x1130
[  305.907660]  ? __sched_text_start+0x8/0x8
[  305.910314]  ? io_wq_worker_sleeping+0x145/0x500
[  305.913328]  schedule+0x131/0x1c0
[  305.914562]  io_uring_cancel_sqpoll+0x288/0x350
[  305.916513]  ? io_sq_thread_unpark+0xd0/0xd0
[  305.918346]  ? mutex_lock+0xbb/0x130
[  305.919616]  ? init_wait_entry+0xe0/0xe0
[  305.920896]  ? wait_for_completion_killable_timeout+0x20/0x20
[  305.922805]  io_sq_thread+0x174c/0x18c0
[  305.923876]  ? io_rsrc_put_work+0x380/0x380
[  305.924748]  ? init_wait_entry+0xe0/0xe0
[  305.925523]  ? _raw_spin_lock_irq+0xa5/0x180
[  305.926353]  ? _raw_spin_lock_irqsave+0x190/0x190
[  305.927436]  ? calculate_sigpending+0x6b/0xa0
[  305.928266]  ? io_rsrc_put_work+0x380/0x380
[  305.929104]  ret_from_fork+0x22/0x30

The trace from my syzkaller instance:

Syzkaller hit 'INFO: task hung in io_uring_cancel_sqpoll' bug.

syz-executor198[307]: segfault at 0 ip 00000000004020f3 sp
00007ffd21853620 error 6 in syz-executor198379463[401000+96000]
Code: 89 d8 8d 34 90 8b 45 04 ba 03 00 00 00 c1 e0 04 03 45 64 39 c6
48 0f 42 f0 45 31 c9 e8 96 8a 04 00 8b 75 00 41 89 d8 4c 89 ef <49> 89
06 41 b9 00 00 00 10 b9 11 80 00 00 ba 03 00 00 00 c1 e6 06
INFO: task iou-sqp-307:308 blocked for more than 120 seconds.
      Not tainted 5.12.0 #2
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:iou-sqp-307     state:D stack:    0 pid:  308 ppid:   306 flags:0x00004004
Call Trace:
 context_switch kernel/sched/core.c:4322 [inline]
 __schedule+0x75f/0xa10 kernel/sched/core.c:5073
 schedule+0xb7/0x110 kernel/sched/core.c:5152
 io_uring_cancel_sqpoll+0x1c6/0x290 fs/io_uring.c:9018
 io_sq_thread+0xf8c/0x1080 fs/io_uring.c:6836
 ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:294