2021-04-30 14:23:06

by Palash Oswal

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

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: [[email protected] [email protected] [email protected] [email protected]]
>
> 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: [email protected]
>
> 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
>
> Showing all locks held in the system:
> 3 locks held by kworker/u4:0/7:
> 3 locks held by kworker/1:0/19:
> 1 lock held by khungtaskd/1556:
> #0: ffffffe00592b5e8 (rcu_read_lock){....}-{1:2}, at: debug_show_all_locks+0x32/0x1fa kernel/locking/lockdep.c:6329
> 1 lock held by klogd/3947:
> 2 locks held by getty/4142:
> #0: ffffffe00f1aa098 (&tty->ldisc_sem){++++}-{0:0}, at: ldsem_down_read+0x3c/0x48 drivers/tty/tty_ldsem.c:340
> #1: ffffffd010b6f2e8 (&ldata->atomic_read_lock){+.+.}-{3:3}, at: n_tty_read+0x9ac/0xb08 drivers/tty/n_tty.c:2178
> 2 locks held by kworker/0:1/4375:
>
> =============================================
>
>
>
> ---
> 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 [email protected].
>
> syzbot will keep track of this issue. See:
> https://goo.gl/tpsmEJ#status for how to communicate with syzbot.

Attaching a C reproducer for this bug:

#define _GNU_SOURCE

#include <fcntl.h>
#include <signal.h>
#include <stdint.h>
#include <stdlib.h>
#include <string.h>
#include <sys/mman.h>
#include <sys/syscall.h>
#include <sys/wait.h>
#include <time.h>
#include <unistd.h>

static uint64_t current_time_ms(void)
{
struct timespec ts;
if (clock_gettime(CLOCK_MONOTONIC, &ts))
exit(1);
return (uint64_t)ts.tv_sec * 1000 + (uint64_t)ts.tv_nsec / 1000000;
}

#define SIZEOF_IO_URING_SQE 64
#define SIZEOF_IO_URING_CQE 16
#define SQ_TAIL_OFFSET 64
#define SQ_RING_MASK_OFFSET 256
#define SQ_RING_ENTRIES_OFFSET 264
#define CQ_RING_ENTRIES_OFFSET 268
#define CQ_CQES_OFFSET 320

struct io_sqring_offsets {
uint32_t head;
uint32_t tail;
uint32_t ring_mask;
uint32_t ring_entries;
uint32_t flags;
uint32_t dropped;
uint32_t array;
uint32_t resv1;
uint64_t resv2;
};

struct io_cqring_offsets {
uint32_t head;
uint32_t tail;
uint32_t ring_mask;
uint32_t ring_entries;
uint32_t overflow;
uint32_t cqes;
uint64_t resv[2];
};

struct io_uring_params {
uint32_t sq_entries;
uint32_t cq_entries;
uint32_t flags;
uint32_t sq_thread_cpu;
uint32_t sq_thread_idle;
uint32_t features;
uint32_t resv[4];
struct io_sqring_offsets sq_off;
struct io_cqring_offsets cq_off;
};

#define IORING_OFF_SQ_RING 0
#define IORING_OFF_SQES 0x10000000ULL

#define sys_io_uring_setup 425
static long syz_io_uring_setup(volatile long a0, volatile long a1,
volatile long a2, volatile long a3, volatile long a4, volatile long
a5)
{
uint32_t entries = (uint32_t)a0;
struct io_uring_params* setup_params = (struct io_uring_params*)a1;
void* vma1 = (void*)a2;
void* vma2 = (void*)a3;
void** ring_ptr_out = (void**)a4;
void** sqes_ptr_out = (void**)a5;
uint32_t fd_io_uring = syscall(sys_io_uring_setup, entries, setup_params);
uint32_t sq_ring_sz = setup_params->sq_off.array +
setup_params->sq_entries * sizeof(uint32_t);
uint32_t cq_ring_sz = setup_params->cq_off.cqes +
setup_params->cq_entries * SIZEOF_IO_URING_CQE;
uint32_t ring_sz = sq_ring_sz > cq_ring_sz ? sq_ring_sz : cq_ring_sz;
*ring_ptr_out = mmap(vma1, ring_sz, PROT_READ | PROT_WRITE,
MAP_SHARED | MAP_POPULATE | MAP_FIXED, fd_io_uring,
IORING_OFF_SQ_RING);
uint32_t sqes_sz = setup_params->sq_entries * SIZEOF_IO_URING_SQE;
*sqes_ptr_out = mmap(vma2, sqes_sz, PROT_READ | PROT_WRITE,
MAP_SHARED | MAP_POPULATE | MAP_FIXED, fd_io_uring, IORING_OFF_SQES);
return fd_io_uring;
}

static long syz_io_uring_submit(volatile long a0, volatile long a1,
volatile long a2, volatile long a3)
{
char* ring_ptr = (char*)a0;
char* sqes_ptr = (char*)a1;
char* sqe = (char*)a2;
uint32_t sqes_index = (uint32_t)a3;
uint32_t sq_ring_entries = *(uint32_t*)(ring_ptr + SQ_RING_ENTRIES_OFFSET);
uint32_t cq_ring_entries = *(uint32_t*)(ring_ptr + CQ_RING_ENTRIES_OFFSET);
uint32_t sq_array_off = (CQ_CQES_OFFSET + cq_ring_entries *
SIZEOF_IO_URING_CQE + 63) & ~63;
if (sq_ring_entries)
sqes_index %= sq_ring_entries;
char* sqe_dest = sqes_ptr + sqes_index * SIZEOF_IO_URING_SQE;
memcpy(sqe_dest, sqe, SIZEOF_IO_URING_SQE);
uint32_t sq_ring_mask = *(uint32_t*)(ring_ptr + SQ_RING_MASK_OFFSET);
uint32_t* sq_tail_ptr = (uint32_t*)(ring_ptr + SQ_TAIL_OFFSET);
uint32_t sq_tail = *sq_tail_ptr & sq_ring_mask;
uint32_t sq_tail_next = *sq_tail_ptr + 1;
uint32_t* sq_array = (uint32_t*)(ring_ptr + sq_array_off);
*(sq_array + sq_tail) = sqes_index;
__atomic_store_n(sq_tail_ptr, sq_tail_next, __ATOMIC_RELEASE);
return 0;
}

static void kill_and_wait(int pid, int* status)
{
kill(-pid, SIGKILL);
kill(pid, SIGKILL);
while (waitpid(-1, status, __WALL) != pid) {
}
}

#define WAIT_FLAGS __WALL

uint64_t r[3] = {0xffffffffffffffff, 0x0, 0x0};

void trigger_bug(void)
{
intptr_t res = 0;
*(uint32_t*)0x20000204 = 0;
*(uint32_t*)0x20000208 = 2;
*(uint32_t*)0x2000020c = 0;
*(uint32_t*)0x20000210 = 0;
*(uint32_t*)0x20000218 = -1;
memset((void*)0x2000021c, 0, 12);
res = -1;
res = syz_io_uring_setup(0x7987, 0x20000200, 0x20400000,
0x20ffd000, 0x200000c0, 0x200001c0);
if (res != -1) {
r[0] = res;
r[1] = *(uint64_t*)0x200000c0;
r[2] = *(uint64_t*)0x200001c0;
}
*(uint8_t*)0x20000180 = 0xb;
*(uint8_t*)0x20000181 = 1;
*(uint16_t*)0x20000182 = 0;
*(uint32_t*)0x20000184 = 0;
*(uint64_t*)0x20000188 = 4;
*(uint64_t*)0x20000190 = 0x20000140;
*(uint64_t*)0x20000140 = 0x77359400;
*(uint64_t*)0x20000148 = 0;
*(uint32_t*)0x20000198 = 1;
*(uint32_t*)0x2000019c = 0;
*(uint64_t*)0x200001a0 = 0;
*(uint16_t*)0x200001a8 = 0;
*(uint16_t*)0x200001aa = 0;
memset((void*)0x200001ac, 0, 20);
syz_io_uring_submit(r[1], r[2], 0x20000180, 1);
*(uint32_t*)0x20000544 = 0;
*(uint32_t*)0x20000548 = 0x36;
*(uint32_t*)0x2000054c = 0;
*(uint32_t*)0x20000550 = 0;
*(uint32_t*)0x20000558 = r[0];
memset((void*)0x2000055c, 0, 12);
syz_io_uring_setup(0x4bf1, 0x20000540, 0x20ffd000, 0x20ffc000, 0, 0);

}
int main(void)
{
syscall(__NR_mmap, 0x20000000ul, 0x1000000ul, 7ul, 0x32ul, -1, 0ul);
int pid = fork();
if (pid < 0)
exit(1);
if (pid == 0) {
trigger_bug();
exit(0);
}
int status = 0;
uint64_t start = current_time_ms();
for (;;) {
if (current_time_ms() - start < 1000) {
continue;
}
kill_and_wait(pid, &status);
break;
}
return 0;
}


2021-04-30 14:34:22

by Pavel Begunkov

[permalink] [raw]
Subject: Re: INFO: task hung in io_uring_cancel_sqpoll

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: [[email protected] [email protected] [email protected] [email protected]]
>>
>> 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


>>
>> IMPORTANT: if you fix the issue, please add the following tag to the commit:
>> Reported-by: [email protected]
>>
>> 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
>>
>> Showing all locks held in the system:
>> 3 locks held by kworker/u4:0/7:
>> 3 locks held by kworker/1:0/19:
>> 1 lock held by khungtaskd/1556:
>> #0: ffffffe00592b5e8 (rcu_read_lock){....}-{1:2}, at: debug_show_all_locks+0x32/0x1fa kernel/locking/lockdep.c:6329
>> 1 lock held by klogd/3947:
>> 2 locks held by getty/4142:
>> #0: ffffffe00f1aa098 (&tty->ldisc_sem){++++}-{0:0}, at: ldsem_down_read+0x3c/0x48 drivers/tty/tty_ldsem.c:340
>> #1: ffffffd010b6f2e8 (&ldata->atomic_read_lock){+.+.}-{3:3}, at: n_tty_read+0x9ac/0xb08 drivers/tty/n_tty.c:2178
>> 2 locks held by kworker/0:1/4375:
>>
>> =============================================
>>
>>
>>
>> ---
>> 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 [email protected].
>>
>> syzbot will keep track of this issue. See:
>> https://goo.gl/tpsmEJ#status for how to communicate with syzbot.
>
> Attaching a C reproducer for this bug:
>
> #define _GNU_SOURCE
>
> #include <fcntl.h>
> #include <signal.h>
> #include <stdint.h>
> #include <stdlib.h>
> #include <string.h>
> #include <sys/mman.h>
> #include <sys/syscall.h>
> #include <sys/wait.h>
> #include <time.h>
> #include <unistd.h>
>
> static uint64_t current_time_ms(void)
> {
> struct timespec ts;
> if (clock_gettime(CLOCK_MONOTONIC, &ts))
> exit(1);
> return (uint64_t)ts.tv_sec * 1000 + (uint64_t)ts.tv_nsec / 1000000;
> }
>
> #define SIZEOF_IO_URING_SQE 64
> #define SIZEOF_IO_URING_CQE 16
> #define SQ_TAIL_OFFSET 64
> #define SQ_RING_MASK_OFFSET 256
> #define SQ_RING_ENTRIES_OFFSET 264
> #define CQ_RING_ENTRIES_OFFSET 268
> #define CQ_CQES_OFFSET 320
>
> struct io_sqring_offsets {
> uint32_t head;
> uint32_t tail;
> uint32_t ring_mask;
> uint32_t ring_entries;
> uint32_t flags;
> uint32_t dropped;
> uint32_t array;
> uint32_t resv1;
> uint64_t resv2;
> };
>
> struct io_cqring_offsets {
> uint32_t head;
> uint32_t tail;
> uint32_t ring_mask;
> uint32_t ring_entries;
> uint32_t overflow;
> uint32_t cqes;
> uint64_t resv[2];
> };
>
> struct io_uring_params {
> uint32_t sq_entries;
> uint32_t cq_entries;
> uint32_t flags;
> uint32_t sq_thread_cpu;
> uint32_t sq_thread_idle;
> uint32_t features;
> uint32_t resv[4];
> struct io_sqring_offsets sq_off;
> struct io_cqring_offsets cq_off;
> };
>
> #define IORING_OFF_SQ_RING 0
> #define IORING_OFF_SQES 0x10000000ULL
>
> #define sys_io_uring_setup 425
> static long syz_io_uring_setup(volatile long a0, volatile long a1,
> volatile long a2, volatile long a3, volatile long a4, volatile long
> a5)
> {
> uint32_t entries = (uint32_t)a0;
> struct io_uring_params* setup_params = (struct io_uring_params*)a1;
> void* vma1 = (void*)a2;
> void* vma2 = (void*)a3;
> void** ring_ptr_out = (void**)a4;
> void** sqes_ptr_out = (void**)a5;
> uint32_t fd_io_uring = syscall(sys_io_uring_setup, entries, setup_params);
> uint32_t sq_ring_sz = setup_params->sq_off.array +
> setup_params->sq_entries * sizeof(uint32_t);
> uint32_t cq_ring_sz = setup_params->cq_off.cqes +
> setup_params->cq_entries * SIZEOF_IO_URING_CQE;
> uint32_t ring_sz = sq_ring_sz > cq_ring_sz ? sq_ring_sz : cq_ring_sz;
> *ring_ptr_out = mmap(vma1, ring_sz, PROT_READ | PROT_WRITE,
> MAP_SHARED | MAP_POPULATE | MAP_FIXED, fd_io_uring,
> IORING_OFF_SQ_RING);
> uint32_t sqes_sz = setup_params->sq_entries * SIZEOF_IO_URING_SQE;
> *sqes_ptr_out = mmap(vma2, sqes_sz, PROT_READ | PROT_WRITE,
> MAP_SHARED | MAP_POPULATE | MAP_FIXED, fd_io_uring, IORING_OFF_SQES);
> return fd_io_uring;
> }
>
> static long syz_io_uring_submit(volatile long a0, volatile long a1,
> volatile long a2, volatile long a3)
> {
> char* ring_ptr = (char*)a0;
> char* sqes_ptr = (char*)a1;
> char* sqe = (char*)a2;
> uint32_t sqes_index = (uint32_t)a3;
> uint32_t sq_ring_entries = *(uint32_t*)(ring_ptr + SQ_RING_ENTRIES_OFFSET);
> uint32_t cq_ring_entries = *(uint32_t*)(ring_ptr + CQ_RING_ENTRIES_OFFSET);
> uint32_t sq_array_off = (CQ_CQES_OFFSET + cq_ring_entries *
> SIZEOF_IO_URING_CQE + 63) & ~63;
> if (sq_ring_entries)
> sqes_index %= sq_ring_entries;
> char* sqe_dest = sqes_ptr + sqes_index * SIZEOF_IO_URING_SQE;
> memcpy(sqe_dest, sqe, SIZEOF_IO_URING_SQE);
> uint32_t sq_ring_mask = *(uint32_t*)(ring_ptr + SQ_RING_MASK_OFFSET);
> uint32_t* sq_tail_ptr = (uint32_t*)(ring_ptr + SQ_TAIL_OFFSET);
> uint32_t sq_tail = *sq_tail_ptr & sq_ring_mask;
> uint32_t sq_tail_next = *sq_tail_ptr + 1;
> uint32_t* sq_array = (uint32_t*)(ring_ptr + sq_array_off);
> *(sq_array + sq_tail) = sqes_index;
> __atomic_store_n(sq_tail_ptr, sq_tail_next, __ATOMIC_RELEASE);
> return 0;
> }
>
> static void kill_and_wait(int pid, int* status)
> {
> kill(-pid, SIGKILL);
> kill(pid, SIGKILL);
> while (waitpid(-1, status, __WALL) != pid) {
> }
> }
>
> #define WAIT_FLAGS __WALL
>
> uint64_t r[3] = {0xffffffffffffffff, 0x0, 0x0};
>
> void trigger_bug(void)
> {
> intptr_t res = 0;
> *(uint32_t*)0x20000204 = 0;
> *(uint32_t*)0x20000208 = 2;
> *(uint32_t*)0x2000020c = 0;
> *(uint32_t*)0x20000210 = 0;
> *(uint32_t*)0x20000218 = -1;
> memset((void*)0x2000021c, 0, 12);
> res = -1;
> res = syz_io_uring_setup(0x7987, 0x20000200, 0x20400000,
> 0x20ffd000, 0x200000c0, 0x200001c0);
> if (res != -1) {
> r[0] = res;
> r[1] = *(uint64_t*)0x200000c0;
> r[2] = *(uint64_t*)0x200001c0;
> }
> *(uint8_t*)0x20000180 = 0xb;
> *(uint8_t*)0x20000181 = 1;
> *(uint16_t*)0x20000182 = 0;
> *(uint32_t*)0x20000184 = 0;
> *(uint64_t*)0x20000188 = 4;
> *(uint64_t*)0x20000190 = 0x20000140;
> *(uint64_t*)0x20000140 = 0x77359400;
> *(uint64_t*)0x20000148 = 0;
> *(uint32_t*)0x20000198 = 1;
> *(uint32_t*)0x2000019c = 0;
> *(uint64_t*)0x200001a0 = 0;
> *(uint16_t*)0x200001a8 = 0;
> *(uint16_t*)0x200001aa = 0;
> memset((void*)0x200001ac, 0, 20);
> syz_io_uring_submit(r[1], r[2], 0x20000180, 1);
> *(uint32_t*)0x20000544 = 0;
> *(uint32_t*)0x20000548 = 0x36;
> *(uint32_t*)0x2000054c = 0;
> *(uint32_t*)0x20000550 = 0;
> *(uint32_t*)0x20000558 = r[0];
> memset((void*)0x2000055c, 0, 12);
> syz_io_uring_setup(0x4bf1, 0x20000540, 0x20ffd000, 0x20ffc000, 0, 0);
>
> }
> int main(void)
> {
> syscall(__NR_mmap, 0x20000000ul, 0x1000000ul, 7ul, 0x32ul, -1, 0ul);
> int pid = fork();
> if (pid < 0)
> exit(1);
> if (pid == 0) {
> trigger_bug();
> exit(0);
> }
> int status = 0;
> uint64_t start = current_time_ms();
> for (;;) {
> if (current_time_ms() - start < 1000) {
> continue;
> }
> kill_and_wait(pid, &status);
> break;
> }
> return 0;
> }
>

--
Pavel Begunkov

2021-04-30 15:05:59

by Palash Oswal

[permalink] [raw]
Subject: Re: INFO: task hung in io_uring_cancel_sqpoll

On Fri, Apr 30, 2021 at 8:03 PM Pavel Begunkov <[email protected]> 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: [[email protected] [email protected] [email protected] [email protected]]
> >>
> >> 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.


Palash

2021-04-30 15:09:21

by Pavel Begunkov

[permalink] [raw]
Subject: Re: INFO: task hung in io_uring_cancel_sqpoll

On 4/30/21 4:02 PM, Palash Oswal wrote:
> On Fri, Apr 30, 2021 at 8:03 PM Pavel Begunkov <[email protected]> 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: [[email protected] [email protected] [email protected] [email protected]]
>>>>
>>>> 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.

Ok, any chance you have syz repro as well? it's easier to read

>
> 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.

--
Pavel Begunkov

2021-04-30 15:14:10

by Palash Oswal

[permalink] [raw]
Subject: Re: INFO: task hung in io_uring_cancel_sqpoll

On Fri, Apr 30, 2021 at 8:37 PM Pavel Begunkov <[email protected]> wrote:
>
> On 4/30/21 4:02 PM, Palash Oswal wrote:
> > On Fri, Apr 30, 2021 at 8:03 PM Pavel Begunkov <[email protected]> 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: [[email protected] [email protected] [email protected] [email protected]]
> >>>>
> >>>> 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.
>
> Ok, any chance you have syz repro as well? it's easier to read
>
> >


Syzkaller reproducer:
# {Threaded:false Collide:false Repeat:true RepeatTimes:0 Procs:1
Slowdown:1 Sandbox: Fault:false FaultCall:-1 FaultNth:0 Leak:false
NetInjection:false NetDevices:false NetReset:false Cgroups:false
BinfmtMisc:false CloseFDs:false KCSAN:false DevlinkPCI:false USB:false
VhciInjection:false Wifi:false IEEE802154:false Sysctl:false
UseTmpDir:false HandleSegv:false Repro:false Trace:false}
r0 = syz_io_uring_setup(0x7987, &(0x7f0000000200)={0x0, 0x0, 0x2},
&(0x7f0000400000/0xc00000)=nil, &(0x7f0000ffd000/0x3000)=nil,
&(0x7f00000000c0)=<r1=>0x0, &(0x7f00000001c0)=<r2=>0x0)
syz_io_uring_submit(r1, r2, &(0x7f0000000180)=@IORING_OP_TIMEOUT={0xb,
0x1, 0x0, 0x0, 0x4, &(0x7f0000000140)={0x77359400}}, 0x1)
syz_io_uring_setup(0x4bf1, &(0x7f0000000540)={0x0, 0x0, 0x36, 0x0,
0x0, 0x0, r0}, &(0x7f0000ffd000/0x2000)=nil,
&(0x7f0000ffc000/0x1000)=nil, 0x0, 0x0)

2021-04-30 18:35:44

by syzbot

[permalink] [raw]
Subject: Re: INFO: task hung in io_uring_cancel_sqpoll

> On 4/30/21 4:02 PM, Palash Oswal wrote:
>> On Fri, Apr 30, 2021 at 8:03 PM Pavel Begunkov <[email protected]> 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: [[email protected] [email protected] [email protected] [email protected]]
>>>>>
>>>>> 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?
>
> #syz test: git://git.kernel.dk/linux-block io_uring-5.13

This crash does not have a reproducer. I cannot test it.

>
> --
> Pavel Begunkov

2021-04-30 18:35:56

by Pavel Begunkov

[permalink] [raw]
Subject: Re: INFO: task hung in io_uring_cancel_sqpoll

On 4/30/21 4:02 PM, Palash Oswal wrote:
> On Fri, Apr 30, 2021 at 8:03 PM Pavel Begunkov <[email protected]> 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: [[email protected] [email protected] [email protected] [email protected]]
>>>>
>>>> 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?

#syz test: git://git.kernel.dk/linux-block io_uring-5.13

--
Pavel Begunkov

2021-04-30 21:05:57

by Pavel Begunkov

[permalink] [raw]
Subject: Re: INFO: task hung in io_uring_cancel_sqpoll

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 <[email protected]> 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: [[email protected] [email protected] [email protected] [email protected]]
>>>>>
>>>>> 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

>
> #syz test: git://git.kernel.dk/linux-block io_uring-5.13
>

--
Pavel Begunkov

2021-05-01 04:54:28

by Palash Oswal

[permalink] [raw]
Subject: Re: INFO: task hung in io_uring_cancel_sqpoll

On Sat, May 1, 2021 at 2:35 AM Pavel Begunkov <[email protected]> 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 <[email protected]> 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: [[email protected] [email protected] [email protected] [email protected]]
> >>>>>
> >>>>> 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

2021-05-01 07:40:17

by Pavel Begunkov

[permalink] [raw]
Subject: Re: INFO: task hung in io_uring_cancel_sqpoll

On 5/1/21 5:51 AM, Palash Oswal wrote:
> On Sat, May 1, 2021 at 2:35 AM Pavel Begunkov <[email protected]> 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 <[email protected]> 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: [[email protected] [email protected] [email protected] [email protected]]
>>>>>>>
>>>>>>> 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

Great, thanks. I'll take a look later

>
> 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
>

--
Pavel Begunkov

2021-05-02 10:41:21

by Pavel Begunkov

[permalink] [raw]
Subject: Re: INFO: task hung in io_uring_cancel_sqpoll

On 4/30/21 4:02 PM, Palash Oswal wrote:
> On Fri, Apr 30, 2021 at 8:03 PM Pavel Begunkov <[email protected]> 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: [[email protected] [email protected] [email protected] [email protected]]
>>>>
>>>> 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.

Tried 5.12,

[ 245.467397] INFO: task iou-sqp-2018:2019 blocked for more than 122 seconds.
[ 245.467424] Call Trace:
[ 245.467432] __schedule+0x365/0x960
[ 245.467444] schedule+0x68/0xe0
[ 245.467450] io_uring_cancel_sqpoll+0xdb/0x110
[ 245.467461] ? wait_woken+0x80/0x80
[ 245.467472] io_sq_thread+0x1c6/0x6c0
[ 245.467482] ? wait_woken+0x80/0x80
[ 245.467491] ? finish_task_switch.isra.0+0xca/0x2e0
[ 245.467497] ? io_wq_submit_work+0x140/0x140
[ 245.467506] ret_from_fork+0x22/0x30
[ 245.467520] INFO: task iou-sqp-2052:2053 blocked for more than 122 seconds.
[ 245.467536] Call Trace:
[ 245.467539] __schedule+0x365/0x960
[ 245.467545] schedule+0x68/0xe0
[ 245.467550] io_uring_cancel_sqpoll+0xdb/0x110
[ 245.467559] ? wait_woken+0x80/0x80
[ 245.467568] io_sq_thread+0x1c6/0x6c0
[ 245.467577] ? wait_woken+0x80/0x80
[ 245.467586] ? finish_task_switch.isra.0+0xca/0x2e0
[ 245.467591] ? io_wq_submit_work+0x140/0x140

>
> I tested against the HEAD b1ef997bec4d5cf251bfb5e47f7b04afa49bcdfe

However, there is a bunch patches fixing sqpoll cancellations in
5.13, all are waiting for backporting. and for-next doesn't trigger
the issue for me.

Are you absolutely sure b1ef997bec4d5cf251bfb5e47f7b04afa49bcdfe
does hit it?

> 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.

--
Pavel Begunkov

2021-05-02 15:03:15

by Palash Oswal

[permalink] [raw]
Subject: Re: INFO: task hung in io_uring_cancel_sqpoll

On Sun, May 2, 2021 at 4:04 PM Pavel Begunkov <[email protected]> wrote:

> > I tested against the HEAD b1ef997bec4d5cf251bfb5e47f7b04afa49bcdfe
>
> However, there is a bunch patches fixing sqpoll cancellations in
> 5.13, all are waiting for backporting. and for-next doesn't trigger
> the issue for me.
>
> Are you absolutely sure b1ef997bec4d5cf251bfb5e47f7b04afa49bcdfe
> does hit it?
>
> > 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.

Hi Pavel and Hillf,

I believe there's a little misunderstanding, apologies. The reproducer
does not trigger the bug on the for-next tree which has patches for
5.13. The reproducer process exits correctly. Likely one of those
commits that will be back-ported to 5.12 will address this issue.
When I wrote `the reproducer fails`, I meant to indicate that the bug
is not triggered on for-next. I will word it better next time!

Palash

2021-05-02 15:58:15

by Pavel Begunkov

[permalink] [raw]
Subject: Re: INFO: task hung in io_uring_cancel_sqpoll

On 5/2/21 4:01 PM, Palash Oswal wrote:
> On Sun, May 2, 2021 at 4:04 PM Pavel Begunkov <[email protected]> wrote:
>
>>> I tested against the HEAD b1ef997bec4d5cf251bfb5e47f7b04afa49bcdfe
>>
>> However, there is a bunch patches fixing sqpoll cancellations in
>> 5.13, all are waiting for backporting. and for-next doesn't trigger
>> the issue for me.
>>
>> Are you absolutely sure b1ef997bec4d5cf251bfb5e47f7b04afa49bcdfe
>> does hit it?
>>
>>> 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.
>
> Hi Pavel and Hillf,
>
> I believe there's a little misunderstanding, apologies. The reproducer
> does not trigger the bug on the for-next tree which has patches for
> 5.13. The reproducer process exits correctly. Likely one of those
> commits that will be back-ported to 5.12 will address this issue.
> When I wrote `the reproducer fails`, I meant to indicate that the bug
> is not triggered on for-next. I will word it better next time!

I see, great it's clarified

--
Pavel Begunkov

2021-05-02 22:13:44

by Pavel Begunkov

[permalink] [raw]
Subject: Re: INFO: task hung in io_uring_cancel_sqpoll

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: [[email protected] [email protected] [email protected] [email protected]]
>>
>> 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: [email protected]
>>
>> 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?


>>
>> Showing all locks held in the system:
>> 3 locks held by kworker/u4:0/7:
>> 3 locks held by kworker/1:0/19:
>> 1 lock held by khungtaskd/1556:
>> #0: ffffffe00592b5e8 (rcu_read_lock){....}-{1:2}, at: debug_show_all_locks+0x32/0x1fa kernel/locking/lockdep.c:6329
>> 1 lock held by klogd/3947:
>> 2 locks held by getty/4142:
>> #0: ffffffe00f1aa098 (&tty->ldisc_sem){++++}-{0:0}, at: ldsem_down_read+0x3c/0x48 drivers/tty/tty_ldsem.c:340
>> #1: ffffffd010b6f2e8 (&ldata->atomic_read_lock){+.+.}-{3:3}, at: n_tty_read+0x9ac/0xb08 drivers/tty/n_tty.c:2178
>> 2 locks held by kworker/0:1/4375:
>>
>> =============================================
>>
>>
>>
>> ---
>> 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 [email protected].
>>
>> syzbot will keep track of this issue. See:
>> https://goo.gl/tpsmEJ#status for how to communicate with syzbot.
>
> Attaching a C reproducer for this bug:
>
> #define _GNU_SOURCE
>
> #include <fcntl.h>
> #include <signal.h>
> #include <stdint.h>
> #include <stdlib.h>
> #include <string.h>
> #include <sys/mman.h>
> #include <sys/syscall.h>
> #include <sys/wait.h>
> #include <time.h>
> #include <unistd.h>
>
> static uint64_t current_time_ms(void)
> {
> struct timespec ts;
> if (clock_gettime(CLOCK_MONOTONIC, &ts))
> exit(1);
> return (uint64_t)ts.tv_sec * 1000 + (uint64_t)ts.tv_nsec / 1000000;
> }
>
> #define SIZEOF_IO_URING_SQE 64
> #define SIZEOF_IO_URING_CQE 16
> #define SQ_TAIL_OFFSET 64
> #define SQ_RING_MASK_OFFSET 256
> #define SQ_RING_ENTRIES_OFFSET 264
> #define CQ_RING_ENTRIES_OFFSET 268
> #define CQ_CQES_OFFSET 320
>
> struct io_sqring_offsets {
> uint32_t head;
> uint32_t tail;
> uint32_t ring_mask;
> uint32_t ring_entries;
> uint32_t flags;
> uint32_t dropped;
> uint32_t array;
> uint32_t resv1;
> uint64_t resv2;
> };
>
> struct io_cqring_offsets {
> uint32_t head;
> uint32_t tail;
> uint32_t ring_mask;
> uint32_t ring_entries;
> uint32_t overflow;
> uint32_t cqes;
> uint64_t resv[2];
> };
>
> struct io_uring_params {
> uint32_t sq_entries;
> uint32_t cq_entries;
> uint32_t flags;
> uint32_t sq_thread_cpu;
> uint32_t sq_thread_idle;
> uint32_t features;
> uint32_t resv[4];
> struct io_sqring_offsets sq_off;
> struct io_cqring_offsets cq_off;
> };
>
> #define IORING_OFF_SQ_RING 0
> #define IORING_OFF_SQES 0x10000000ULL
>
> #define sys_io_uring_setup 425
> static long syz_io_uring_setup(volatile long a0, volatile long a1,
> volatile long a2, volatile long a3, volatile long a4, volatile long
> a5)
> {
> uint32_t entries = (uint32_t)a0;
> struct io_uring_params* setup_params = (struct io_uring_params*)a1;
> void* vma1 = (void*)a2;
> void* vma2 = (void*)a3;
> void** ring_ptr_out = (void**)a4;
> void** sqes_ptr_out = (void**)a5;
> uint32_t fd_io_uring = syscall(sys_io_uring_setup, entries, setup_params);
> uint32_t sq_ring_sz = setup_params->sq_off.array +
> setup_params->sq_entries * sizeof(uint32_t);
> uint32_t cq_ring_sz = setup_params->cq_off.cqes +
> setup_params->cq_entries * SIZEOF_IO_URING_CQE;
> uint32_t ring_sz = sq_ring_sz > cq_ring_sz ? sq_ring_sz : cq_ring_sz;
> *ring_ptr_out = mmap(vma1, ring_sz, PROT_READ | PROT_WRITE,
> MAP_SHARED | MAP_POPULATE | MAP_FIXED, fd_io_uring,
> IORING_OFF_SQ_RING);
> uint32_t sqes_sz = setup_params->sq_entries * SIZEOF_IO_URING_SQE;
> *sqes_ptr_out = mmap(vma2, sqes_sz, PROT_READ | PROT_WRITE,
> MAP_SHARED | MAP_POPULATE | MAP_FIXED, fd_io_uring, IORING_OFF_SQES);
> return fd_io_uring;
> }
>
> static long syz_io_uring_submit(volatile long a0, volatile long a1,
> volatile long a2, volatile long a3)
> {
> char* ring_ptr = (char*)a0;
> char* sqes_ptr = (char*)a1;
> char* sqe = (char*)a2;
> uint32_t sqes_index = (uint32_t)a3;
> uint32_t sq_ring_entries = *(uint32_t*)(ring_ptr + SQ_RING_ENTRIES_OFFSET);
> uint32_t cq_ring_entries = *(uint32_t*)(ring_ptr + CQ_RING_ENTRIES_OFFSET);
> uint32_t sq_array_off = (CQ_CQES_OFFSET + cq_ring_entries *
> SIZEOF_IO_URING_CQE + 63) & ~63;
> if (sq_ring_entries)
> sqes_index %= sq_ring_entries;
> char* sqe_dest = sqes_ptr + sqes_index * SIZEOF_IO_URING_SQE;
> memcpy(sqe_dest, sqe, SIZEOF_IO_URING_SQE);
> uint32_t sq_ring_mask = *(uint32_t*)(ring_ptr + SQ_RING_MASK_OFFSET);
> uint32_t* sq_tail_ptr = (uint32_t*)(ring_ptr + SQ_TAIL_OFFSET);
> uint32_t sq_tail = *sq_tail_ptr & sq_ring_mask;
> uint32_t sq_tail_next = *sq_tail_ptr + 1;
> uint32_t* sq_array = (uint32_t*)(ring_ptr + sq_array_off);
> *(sq_array + sq_tail) = sqes_index;
> __atomic_store_n(sq_tail_ptr, sq_tail_next, __ATOMIC_RELEASE);
> return 0;
> }
>
> static void kill_and_wait(int pid, int* status)
> {
> kill(-pid, SIGKILL);
> kill(pid, SIGKILL);
> while (waitpid(-1, status, __WALL) != pid) {
> }
> }
>
> #define WAIT_FLAGS __WALL
>
> uint64_t r[3] = {0xffffffffffffffff, 0x0, 0x0};
>
> void trigger_bug(void)
> {
> intptr_t res = 0;
> *(uint32_t*)0x20000204 = 0;
> *(uint32_t*)0x20000208 = 2;
> *(uint32_t*)0x2000020c = 0;
> *(uint32_t*)0x20000210 = 0;
> *(uint32_t*)0x20000218 = -1;
> memset((void*)0x2000021c, 0, 12);
> res = -1;
> res = syz_io_uring_setup(0x7987, 0x20000200, 0x20400000,
> 0x20ffd000, 0x200000c0, 0x200001c0);
> if (res != -1) {
> r[0] = res;
> r[1] = *(uint64_t*)0x200000c0;
> r[2] = *(uint64_t*)0x200001c0;
> }
> *(uint8_t*)0x20000180 = 0xb;
> *(uint8_t*)0x20000181 = 1;
> *(uint16_t*)0x20000182 = 0;
> *(uint32_t*)0x20000184 = 0;
> *(uint64_t*)0x20000188 = 4;
> *(uint64_t*)0x20000190 = 0x20000140;
> *(uint64_t*)0x20000140 = 0x77359400;
> *(uint64_t*)0x20000148 = 0;
> *(uint32_t*)0x20000198 = 1;
> *(uint32_t*)0x2000019c = 0;
> *(uint64_t*)0x200001a0 = 0;
> *(uint16_t*)0x200001a8 = 0;
> *(uint16_t*)0x200001aa = 0;
> memset((void*)0x200001ac, 0, 20);
> syz_io_uring_submit(r[1], r[2], 0x20000180, 1);
> *(uint32_t*)0x20000544 = 0;
> *(uint32_t*)0x20000548 = 0x36;
> *(uint32_t*)0x2000054c = 0;
> *(uint32_t*)0x20000550 = 0;
> *(uint32_t*)0x20000558 = r[0];
> memset((void*)0x2000055c, 0, 12);
> syz_io_uring_setup(0x4bf1, 0x20000540, 0x20ffd000, 0x20ffc000, 0, 0);
>
> }
> int main(void)
> {
> syscall(__NR_mmap, 0x20000000ul, 0x1000000ul, 7ul, 0x32ul, -1, 0ul);
> int pid = fork();
> if (pid < 0)
> exit(1);
> if (pid == 0) {
> trigger_bug();
> exit(0);
> }
> int status = 0;
> uint64_t start = current_time_ms();
> for (;;) {
> if (current_time_ms() - start < 1000) {
> continue;
> }
> kill_and_wait(pid, &status);
> break;
> }
> return 0;
> }
>

--
Pavel Begunkov

2021-05-03 04:43:09

by Palash Oswal

[permalink] [raw]
Subject: Re: INFO: task hung in io_uring_cancel_sqpoll

On Mon, May 3, 2021 at 3:42 AM Pavel Begunkov <[email protected]> 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: [[email protected] [email protected] [email protected] [email protected]]
> >>
> >> 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: [email protected]
> >>
> >> 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

2021-05-03 12:47:20

by Pavel Begunkov

[permalink] [raw]
Subject: Re: INFO: task hung in io_uring_cancel_sqpoll

On 5/3/21 5:41 AM, Palash Oswal wrote:
> On Mon, May 3, 2021 at 3:42 AM Pavel Begunkov <[email protected]> wrote:
>> 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

Perfect, thanks

> address this behavior?

As the hang is sqpoll cancellations, it's most probably
fixed in 5.13 + again awaits to be taken for stable.

Don't know about segfaults, but it was so for long, and
syz reproducers are ofthen faults for me, and exit with 0
in the end. So, I wouldn't worry about it.

> 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
>

--
Pavel Begunkov

2021-05-14 01:03:31

by Pavel Begunkov

[permalink] [raw]
Subject: Re: INFO: task hung in io_uring_cancel_sqpoll

On 5/13/21 10:28 PM, Pavel Begunkov wrote:
> On 5/10/21 5:47 AM, Palash Oswal wrote:
>> On Mon, May 3, 2021 at 4:15 PM Pavel Begunkov <[email protected]>
>> wrote:
>>
>>> On 5/3/21 5:41 AM, Palash Oswal wrote:
>>>> On Mon, May 3, 2021 at 3:42 AM Pavel Begunkov <[email protected]>
>>> wrote:
>>>>> 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
>>>
>>> Perfect, thanks
>>>
>>>> address this behavior?
>>>
>>> As the hang is sqpoll cancellations, it's most probably
>>> fixed in 5.13 + again awaits to be taken for stable.
>>>
>>> Don't know about segfaults, but it was so for long, and
>>> syz reproducers are ofthen faults for me, and exit with 0
>>> in the end. So, I wouldn't worry about it.
>>>
>>>
>> Hey Pavel,
>> The bug actually fails to reproduce on 5.12 when the fork() call is made by
>> the runtests.sh script. This causes the program to end correctly, and the
>> hang does not occur. I verified this on 5.12 where the bug isn't patched.
>> Just running the `sqpoll-cancel-hang` triggers the bug; whereas running it
>> after being forked from runtests.sh does not trigger the bug.
>
> I see. fyi, it's always good to wait for 5 minutes, because some useful
> logs are not generated immediately but do timeout based hang detection.
>
> I'd think that may be due CLONE_IO and how to whom it binds workers,
> but can you try first:
>
> 1) timeout -s INT -k $TIMEOUT $TIMEOUT ./sqpoll-cancel-hang

edit:

timeout -s INT -k 60 60 ./sqpoll-cancel-hang

And privileged, root/sudo

>
> 2) remove timeout from <liburing>/tests/Makefile and run
> "./runtests.sh sqpoll-cancel-hang" again looking for faults?
>
> diff --git a/test/runtests.sh b/test/runtests.sh
> index e8f4ae5..2b51dca 100755
> --- a/test/runtests.sh
> +++ b/test/runtests.sh
> @@ -91,7 +91,8 @@ run_test()
> fi
>
> # Run the test
> - timeout -s INT -k $TIMEOUT $TIMEOUT ./$test_name $dev
> + # timeout -s INT -k $TIMEOUT $TIMEOUT ./$test_name $dev
> + ./$test_name $dev
> local status=$?
>
> # Check test status
>
>
>>
>> The segfaults are benign, but notice the "All tests passed" in the previous
>> mail. It should not have passed, as the run was on 5.12. Therefore I wanted
>> to ask your input on how to address this odd behaviour, where the
>> involvement of runtests.sh actually mitigated the bug.
>>
>>
>>
>>>> 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
>>>>
>>>
>>> --
>>> Pavel Begunkov
>>>
>>
>

--
Pavel Begunkov

2021-05-14 07:51:23

by Pavel Begunkov

[permalink] [raw]
Subject: Re: INFO: task hung in io_uring_cancel_sqpoll

On 5/10/21 5:47 AM, Palash Oswal wrote:
> On Mon, May 3, 2021 at 4:15 PM Pavel Begunkov <[email protected]>
> wrote:
>
>> On 5/3/21 5:41 AM, Palash Oswal wrote:
>>> On Mon, May 3, 2021 at 3:42 AM Pavel Begunkov <[email protected]>
>> wrote:
>>>> 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
>>
>> Perfect, thanks
>>
>>> address this behavior?
>>
>> As the hang is sqpoll cancellations, it's most probably
>> fixed in 5.13 + again awaits to be taken for stable.
>>
>> Don't know about segfaults, but it was so for long, and
>> syz reproducers are ofthen faults for me, and exit with 0
>> in the end. So, I wouldn't worry about it.
>>
>>
> Hey Pavel,
> The bug actually fails to reproduce on 5.12 when the fork() call is made by
> the runtests.sh script. This causes the program to end correctly, and the
> hang does not occur. I verified this on 5.12 where the bug isn't patched.
> Just running the `sqpoll-cancel-hang` triggers the bug; whereas running it
> after being forked from runtests.sh does not trigger the bug.

I see. fyi, it's always good to wait for 5 minutes, because some useful
logs are not generated immediately but do timeout based hang detection.

I'd think that may be due CLONE_IO and how to whom it binds workers,
but can you try first:

1) timeout -s INT -k $TIMEOUT $TIMEOUT ./sqpoll-cancel-hang

2) remove timeout from <liburing>/tests/Makefile and run
"./runtests.sh sqpoll-cancel-hang" again looking for faults?

diff --git a/test/runtests.sh b/test/runtests.sh
index e8f4ae5..2b51dca 100755
--- a/test/runtests.sh
+++ b/test/runtests.sh
@@ -91,7 +91,8 @@ run_test()
fi

# Run the test
- timeout -s INT -k $TIMEOUT $TIMEOUT ./$test_name $dev
+ # timeout -s INT -k $TIMEOUT $TIMEOUT ./$test_name $dev
+ ./$test_name $dev
local status=$?

# Check test status


>
> The segfaults are benign, but notice the "All tests passed" in the previous
> mail. It should not have passed, as the run was on 5.12. Therefore I wanted
> to ask your input on how to address this odd behaviour, where the
> involvement of runtests.sh actually mitigated the bug.
>
>
>
>>> 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
>>>
>>
>> --
>> Pavel Begunkov
>>
>

--
Pavel Begunkov

2021-05-15 17:46:32

by Palash Oswal

[permalink] [raw]
Subject: Re: INFO: task hung in io_uring_cancel_sqpoll

On Fri, May 14, 2021 at 3:01 AM Pavel Begunkov <[email protected]> wrote:
>
> On 5/13/21 10:28 PM, Pavel Begunkov wrote:
> > On 5/10/21 5:47 AM, Palash Oswal wrote:
> >> On Mon, May 3, 2021 at 4:15 PM Pavel Begunkov <[email protected]>
> >> wrote:
> >>
> >>> On 5/3/21 5:41 AM, Palash Oswal wrote:
> >>>> On Mon, May 3, 2021 at 3:42 AM Pavel Begunkov <[email protected]>
> >>> wrote:
> >>>>> 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
> >>>
> >>> Perfect, thanks
> >>>
> >>>> address this behavior?
> >>>
> >>> As the hang is sqpoll cancellations, it's most probably
> >>> fixed in 5.13 + again awaits to be taken for stable.
> >>>
> >>> Don't know about segfaults, but it was so for long, and
> >>> syz reproducers are ofthen faults for me, and exit with 0
> >>> in the end. So, I wouldn't worry about it.
> >>>
> >>>
> >> Hey Pavel,
> >> The bug actually fails to reproduce on 5.12 when the fork() call is made by
> >> the runtests.sh script. This causes the program to end correctly, and the
> >> hang does not occur. I verified this on 5.12 where the bug isn't patched.
> >> Just running the `sqpoll-cancel-hang` triggers the bug; whereas running it
> >> after being forked from runtests.sh does not trigger the bug.
> >
> > I see. fyi, it's always good to wait for 5 minutes, because some useful
> > logs are not generated immediately but do timeout based hang detection.
> >
> > I'd think that may be due CLONE_IO and how to whom it binds workers,
> > but can you try first:
> >
> > 1) timeout -s INT -k $TIMEOUT $TIMEOUT ./sqpoll-cancel-hang
>
> edit:
>
> timeout -s INT -k 60 60 ./sqpoll-cancel-hang
>
> And privileged, root/sudo
>
> >
> > 2) remove timeout from <liburing>/tests/Makefile and run
> > "./runtests.sh sqpoll-cancel-hang" again looking for faults?
> >
> > diff --git a/test/runtests.sh b/test/runtests.sh
> > index e8f4ae5..2b51dca 100755
> > --- a/test/runtests.sh
> > +++ b/test/runtests.sh
> > @@ -91,7 +91,8 @@ run_test()
> > fi
> >
> > # Run the test
> > - timeout -s INT -k $TIMEOUT $TIMEOUT ./$test_name $dev
> > + # timeout -s INT -k $TIMEOUT $TIMEOUT ./$test_name $dev
> > + ./$test_name $dev
> > local status=$?
> >
> > # Check test status

root@syzkaller:~/liburing/test# timeout -s INT -k 60 60 ./sqpoll-cancel-hang
[ 19.381358] sqpoll-cancel-h[300]: segfault at 0 ip 0000556f7fa325e3
sp 00007ffee497d980 error 6 in s]
[ 19.387323] 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 c6
root@syzkaller:~/liburing/test# [ 243.511620] INFO: task
iou-sqp-300:301 blocked for more than 120 sec.
[ 243.514146] Not tainted 5.12.0 #142
[ 243.515301] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 243.517629] task:iou-sqp-300 state:D stack: 0 pid: 301
ppid: 1 flags:0x00004004
[ 243.520155] Call Trace:
[ 243.520956] __schedule+0xb1d/0x1130
[ 243.522102] ? __sched_text_start+0x8/0x8
[ 243.523195] ? io_wq_worker_sleeping+0x145/0x500
[ 243.524588] schedule+0x131/0x1c0
[ 243.525892] io_uring_cancel_sqpoll+0x288/0x350
[ 243.527610] ? io_sq_thread_unpark+0xd0/0xd0
[ 243.529084] ? mutex_lock+0xbb/0x130
[ 243.530327] ? init_wait_entry+0xe0/0xe0
[ 243.532805] ? wait_for_completion_killable_timeout+0x20/0x20
[ 243.535411] io_sq_thread+0x174c/0x18c0
[ 243.536520] ? io_rsrc_put_work+0x380/0x380
[ 243.537904] ? init_wait_entry+0xe0/0xe0
[ 243.538935] ? _raw_spin_lock_irq+0xa5/0x180
[ 243.540203] ? _raw_spin_lock_irqsave+0x190/0x190
[ 243.542398] ? calculate_sigpending+0x6b/0xa0
[ 243.543868] ? io_rsrc_put_work+0x380/0x380
[ 243.545377] ret_from_fork+0x22/0x30
^C
root@syzkaller:~/liburing/test# ps
PID TTY TIME CMD
269 ttyS0 00:00:00 login
294 ttyS0 00:00:00 bash
300 ttyS0 00:00:00 sqpoll-cancel-h
305 ttyS0 00:00:00 ps


After reboot, and the runtests.sh diff applied ( to remove timeout )
root@syzkaller:~/liburing/test# ./runtests.sh sqpoll-cancel-hang
Running test sqp[ 45.332140] Running test sqpoll-cancel-hang:
oll-cancel-hang:
[ 45.352524] sqpoll-cancel-h[314]: segfault at 0 ip 000056025bd085e3
sp 00007fffb08e20b0 error 6 in s]
[ 45.356601] 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 c6
[ 243.019384] INFO: task iou-sqp-314:315 blocked for more than 120 seconds.
[ 243.021483] Not tainted 5.12.0 #142
[ 243.022633] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 243.024651] task:iou-sqp-314 state:D stack: 0 pid: 315
ppid: 313 flags:0x00004004
[ 243.026822] Call Trace:
[ 243.027478] __schedule+0xb1d/0x1130
[ 243.028382] ? __sched_text_start+0x8/0x8
[ 243.029536] ? io_wq_worker_sleeping+0x145/0x500
[ 243.030932] schedule+0x131/0x1c0
[ 243.031920] io_uring_cancel_sqpoll+0x288/0x350
[ 243.033393] ? io_sq_thread_unpark+0xd0/0xd0
[ 243.034713] ? mutex_lock+0xbb/0x130
[ 243.035775] ? init_wait_entry+0xe0/0xe0
[ 243.037036] ? wait_for_completion_killable_timeout+0x20/0x20
[ 243.039492] io_sq_thread+0x174c/0x18c0
[ 243.040894] ? io_rsrc_put_work+0x380/0x380
[ 243.042463] ? init_wait_entry+0xe0/0xe0
[ 243.043990] ? _raw_spin_lock_irq+0xa5/0x180
[ 243.045581] ? _raw_spin_lock_irqsave+0x190/0x190
[ 243.047545] ? calculate_sigpending+0x6b/0xa0
[ 243.049262] ? io_rsrc_put_work+0x380/0x380
[ 243.050861] ret_from_fork+0x22/0x30
^C
root@syzkaller:~/liburing/test# ps
PID TTY TIME CMD
285 ttyS0 00:00:00 login
300 ttyS0 00:00:00 bash
314 ttyS0 00:00:00 sqpoll-cancel-h
318 ttyS0 00:00:00 ps


runtests.sh without any changes
root@syzkaller:~/liburing/test# ./runtests.sh sqpoll-cancel-hang
[ 49.634886] Running test sqpoll-cancel-hang:
Running test sqpoll-cancel-hang:
[ 49.658365] sqpoll-cancel-h[302]: segfault at 0 ip 000055a76e99c5e3
sp 00007ffdc255d1a0 error 6 in s]
[ 49.661703] 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 c6
Test sqpoll-cancel-hang timed out (may not be a failure)
All tests passed
root@syzkaller:~/liburing/test# ps
PID TTY TIME CMD
269 ttyS0 00:00:00 login
287 ttyS0 00:00:00 bash
302 ttyS0 00:00:00 sqpoll-cancel-h
309 ttyS0 00:00:00 ps
root@syzkaller:~/liburing/test# [ 243.324831] INFO: task
iou-sqp-302:303 blocked for more than 120 sec.
[ 243.328320] Not tainted 5.12.0 #142
[ 243.330361] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 243.333930] task:iou-sqp-302 state:D stack: 0 pid: 303
ppid: 1 flags:0x00004004
[ 243.337758] Call Trace:
[ 243.338926] __schedule+0xb1d/0x1130
[ 243.340801] ? __sched_text_start+0x8/0x8
[ 243.342690] ? io_wq_worker_sleeping+0x145/0x500
[ 243.344903] schedule+0x131/0x1c0
[ 243.346626] io_uring_cancel_sqpoll+0x288/0x350
[ 243.348762] ? io_sq_thread_unpark+0xd0/0xd0
[ 243.351036] ? mutex_lock+0xbb/0x130
[ 243.352737] ? init_wait_entry+0xe0/0xe0
[ 243.354673] ? wait_for_completion_killable_timeout+0x20/0x20
[ 243.356989] io_sq_thread+0x174c/0x18c0
[ 243.358559] ? io_rsrc_put_work+0x380/0x380
[ 243.359981] ? init_wait_entry+0xe0/0xe0
[ 243.361185] ? _raw_spin_lock_irq+0x110/0x180
[ 243.362958] ? _raw_spin_lock_irqsave+0x190/0x190
[ 243.364260] ? calculate_sigpending+0x6b/0xa0
[ 243.365763] ? io_rsrc_put_work+0x380/0x380
[ 243.367041] ret_from_fork+0x22/0x30




> >
> >
> >>
> >> The segfaults are benign, but notice the "All tests passed" in the previous
> >> mail. It should not have passed, as the run was on 5.12. Therefore I wanted
> >> to ask your input on how to address this odd behaviour, where the
> >> involvement of runtests.sh actually mitigated the bug.
> >>
> >>
> >>
> >>>> 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
> >>>>
> >>>
> >>> --
> >>> Pavel Begunkov
> >>>
> >>
> >
>
> --
> Pavel Begunkov

2021-06-12 15:54:25

by syzbot

[permalink] [raw]
Subject: Re: INFO: task hung in io_uring_cancel_sqpoll

Auto-closing this bug as obsolete.
Crashes did not happen for a while, no reproducer and no activity.