INFO: rcu detected stall in io_uring_release

[syzbot]

Hello,

syzbot found the following crash on:

HEAD commit: 8f3d9f35 Linux 5.7-rc1
git tree: upstream
console output: https://syzkaller.appspot.com/x/log.txt?x=115720c3e00000
kernel config: https://syzkaller.appspot.com/x/.config?x=5d351a1019ed81a2
dashboard link: https://syzkaller.appspot.com/bug?extid=66243bb7126c410cefe6
compiler: gcc (GCC) 9.0.0 20181231 (experimental)

Unfortunately, I don't have any reproducer for this crash yet.

IMPORTANT: if you fix the bug, please add the following tag to the commit:
Reported-by: syzbot+66243b...@syzkaller.appspotmail.com

rcu: INFO: rcu_preempt self-detected stall on CPU
rcu: 0-....: (10500 ticks this GP) idle=57e/1/0x4000000000000002 softirq=44329/44329 fqs=5245
(t=10502 jiffies g=79401 q=2096)
NMI backtrace for cpu 0
CPU: 0 PID: 23184 Comm: syz-executor.5 Not tainted 5.7.0-rc1-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
<IRQ>
__dump_stack lib/dump_stack.c:77 [inline]
dump_stack+0x188/0x20d lib/dump_stack.c:118
nmi_cpu_backtrace.cold+0x70/0xb1 lib/nmi_backtrace.c:101
nmi_trigger_cpumask_backtrace+0x231/0x27e lib/nmi_backtrace.c:62
trigger_single_cpu_backtrace include/linux/nmi.h:164 [inline]
rcu_dump_cpu_stacks+0x19b/0x1e5 kernel/rcu/tree_stall.h:254
print_cpu_stall kernel/rcu/tree_stall.h:475 [inline]
check_cpu_stall kernel/rcu/tree_stall.h:549 [inline]
rcu_pending kernel/rcu/tree.c:3225 [inline]
rcu_sched_clock_irq.cold+0x55d/0xcfa kernel/rcu/tree.c:2296
update_process_times+0x25/0x60 kernel/time/timer.c:1727
tick_sched_handle+0x9b/0x180 kernel/time/tick-sched.c:176
tick_sched_timer+0x4e/0x140 kernel/time/tick-sched.c:1320
__run_hrtimer kernel/time/hrtimer.c:1520 [inline]
__hrtimer_run_queues+0x5ca/0xed0 kernel/time/hrtimer.c:1584
hrtimer_interrupt+0x312/0x770 kernel/time/hrtimer.c:1646
local_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1113 [inline]
smp_apic_timer_interrupt+0x15b/0x600 arch/x86/kernel/apic/apic.c:1138
apic_timer_interrupt+0xf/0x20 arch/x86/entry/entry_64.S:829
</IRQ>
RIP: 0010:io_ring_ctx_wait_and_kill+0x98/0x5a0 fs/io_uring.c:7301
Code: 01 00 00 4d 89 f4 48 b8 00 00 00 00 00 fc ff df 4c 89 ed 49 c1 ec 03 48 c1 ed 03 49 01 c4 48 01 c5 eb 1c e8 3a ea 9d ff f3 90 <41> 80 3c 24 00 0f 85 53 04 00 00 48 83 bb 10 01 00 00 00 74 21 e8
RSP: 0018:ffffc9000897fdf0 EFLAGS: 00000293 ORIG_RAX: ffffffffffffff13
RAX: ffff888024082080 RBX: ffff88808df8e000 RCX: 1ffff9200112ffab
RDX: 0000000000000000 RSI: ffffffff81d549c6 RDI: ffff88808df8e300
RBP: ffffed1011bf1c2c R08: 0000000000000001 R09: ffffed1011bf1c61
R10: ffff88808df8e307 R11: ffffed1011bf1c60 R12: ffffed1011bf1c22
R13: ffff88808df8e160 R14: ffff88808df8e110 R15: ffffffff81d54ed0
io_uring_release+0x3e/0x50 fs/io_uring.c:7324
__fput+0x33e/0x880 fs/file_table.c:280
task_work_run+0xf4/0x1b0 kernel/task_work.c:123
tracehook_notify_resume include/linux/tracehook.h:188 [inline]
exit_to_usermode_loop+0x2fa/0x360 arch/x86/entry/common.c:165
prepare_exit_to_usermode arch/x86/entry/common.c:196 [inline]
syscall_return_slowpath arch/x86/entry/common.c:279 [inline]
do_syscall_64+0x6b1/0x7d0 arch/x86/entry/common.c:305
entry_SYSCALL_64_after_hwframe+0x49/0xb3
RIP: 0033:0x416421
Code: 75 14 b8 03 00 00 00 0f 05 48 3d 01 f0 ff ff 0f 83 04 1b 00 00 c3 48 83 ec 08 e8 0a fc ff ff 48 89 04 24 b8 03 00 00 00 0f 05 <48> 8b 3c 24 48 89 c2 e8 53 fc ff ff 48 89 d0 48 83 c4 08 48 3d 01
RSP: 002b:00007ffc3c9f63d0 EFLAGS: 00000293 ORIG_RAX: 0000000000000003
RAX: 0000000000000000 RBX: 0000000000000004 RCX: 0000000000416421
RDX: 00000000000f4240 RSI: 0000000000000081 RDI: 0000000000000003
RBP: 0000000000000000 R08: 0000000000000000 R09: 01ffffffffffffff
R10: 0000000000770b20 R11: 0000000000000293 R12: 000000000076bfa0
R13: 0000000000770b30 R14: 0000000000000001 R15: 000000000076bfac


---
This bug 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 syzk...@googlegroups.com.

syzbot will keep track of this bug report. See:
https://goo.gl/tpsmEJ#status for how to communicate with syzbot.

[Hillf Danton]

Sat, 18 Apr 2020 11:59:13 -0700

Make io ring ctx's percpu_ref balanced.

--- a/fs/io_uring.c
+++ b/fs/io_uring.c
@@ -5904,6 +5904,7 @@ static int io_submit_sqes(struct io_ring
fail_req:
io_cqring_add_event(req, err);
io_double_put_req(req);
+ --submitted;
break;
}

[Hillf Danton]

Sat, 18 Apr 2020 11:59:13 -0700
>

Go another round of loop with EBUSY dropped if it's not good to
call kthread_park() somewhere near line 7301, see the RIP line above.

--- a/fs/io_uring.c
+++ b/fs/io_uring.c
@@ -5998,6 +5998,7 @@ static int io_sq_thread(void *data)
if (current->task_works)
task_work_run();
cond_resched();
+ ret = 0;
continue;
}

@@ -6014,6 +6015,7 @@ static int io_sq_thread(void *data)
if ((ctx->flags & IORING_SETUP_IOPOLL) &&
!list_empty_careful(&ctx->poll_list)) {
finish_wait(&ctx->sqo_wait, &wait);
+ ret = 0;
continue;
}

@@ -6031,6 +6033,7 @@ static int io_sq_thread(void *data)
if (current->task_works) {
task_work_run();
finish_wait(&ctx->sqo_wait, &wait);
+ ret = 0;
continue;
}
if (signal_pending(current))
@@ -6039,6 +6042,7 @@ static int io_sq_thread(void *data)
finish_wait(&ctx->sqo_wait, &wait);

ctx->rings->sq_flags &= ~IORING_SQ_NEED_WAKEUP;
+ ret = 0;
continue;
}
finish_wait(&ctx->sqo_wait, &wait);

[Jens Axboe]

Not sure this is right, need to look closer. But if we post a completion
event, the event has been consumed and should be accounted as such.

--
Jens Axboe

[Hillf Danton]

Sorry for my noise in terms of the stall reported.

> But if we post a completion
> event, the event has been consumed and should be accounted as such.

Because I mistook

while (ctx->sqo_thread && !wq_has_sleeper(&ctx->sqo_wait))

at the RIP line:7301 in the report with

wait_for_completion(&ctx->completions[0]);

at line:7316 in the upstream tree.

Sorry again.

Hillf

[Dan Carpenter]

fs/io_uring.c
5880 for (i = 0; i < nr; i++) {
5881 const struct io_uring_sqe *sqe;
5882 struct io_kiocb *req;
5883 int err;
5884
5885 sqe = io_get_sqe(ctx);
5886 if (unlikely(!sqe)) {
5887 io_consume_sqe(ctx);
5888 break;
5889 }
5890 req = io_alloc_req(ctx, statep);
5891 if (unlikely(!req)) {
5892 if (!submitted)
5893 submitted = -EAGAIN;
5894 break;
5895 }
5896
5897 err = io_init_req(ctx, req, sqe, statep, async);
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
On the success path io_init_req() takes some references like:

get_cred(req->work.creds);

That one is probably buggy and should be put if the call to:

return io_req_set_file(state, req, fd, sqe_flags);

fails... But io_req_set_file() takes some other references if it
succeeds like percpu_ref_get(req->fixed_file_refs); and it's not clear
that those are released if io_submit_sqe() fails.

5898 io_consume_sqe(ctx);
5899 /* will complete beyond this point, count as submitted */
5900 submitted++;
5901
5902 if (unlikely(err)) {
5903 fail_req:
5904 io_cqring_add_event(req, err);
5905 io_double_put_req(req);
5906 break;
5907 }
5908
5909 trace_io_uring_submit_sqe(ctx, req->opcode, req->user_data,
5910 true, async);
5911 err = io_submit_sqe(req, sqe, statep, &link);
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
here

5912 if (err)
5913 goto fail_req;
5914 }

regards,
dan carpenter

[Pavel Begunkov]

If a req have got into io_init_req(), than it'll be put at some point
with io_put_req(). io_req_work_drop_env() called from there will clean
up req->work.creds.

>
> That one is probably buggy and should be put if the call to:
>
> return io_req_set_file(state, req, fd, sqe_flags);
>
> fails... But io_req_set_file() takes some other references if it
> succeeds like percpu_ref_get(req->fixed_file_refs); and it's not clear
> that those are released if io_submit_sqe() fails.

The same should happen with req->fixed_file_refs, though I don't
remember in details.

>
> 5898 io_consume_sqe(ctx);
> 5899 /* will complete beyond this point, count as submitted */
> 5900 submitted++;

Regarding, "--submitted" patch -- we take 1 ctx->refs per request, which
is put in io_put_req(). So after a request passes the line above (5900),
it's ref will be eventually dropped in io_put_req() and friends.

And it's a bit more peculiar because io_submit_sqes() batch-takes N refs
first, and then puts unused back at the end.

> 5901
> 5902 if (unlikely(err)) {
> 5903 fail_req:
> 5904 io_cqring_add_event(req, err);
> 5905 io_double_put_req(req);
> 5906 break;
> 5907 }
> 5908
> 5909 trace_io_uring_submit_sqe(ctx, req->opcode, req->user_data,
> 5910 true, async);
> 5911 err = io_submit_sqe(req, sqe, statep, &link);
> ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
> here
>
> 5912 if (err)
> 5913 goto fail_req;
> 5914 }
>
> regards,
> dan carpenter
>

--
Pavel Begunkov

[syzbot]

syzbot has found a reproducer for the following crash on:

HEAD commit: ac935d22 Add linux-next specific files for 20200415
git tree: linux-next
console output: https://syzkaller.appspot.com/x/log.txt?x=13a38f0a100000
kernel config: https://syzkaller.appspot.com/x/.config?x=bc498783097e9019

dashboard link: https://syzkaller.appspot.com/bug?extid=66243bb7126c410cefe6
compiler: gcc (GCC) 9.0.0 20181231 (experimental)

syz repro: https://syzkaller.appspot.com/x/repro.syz?x=179b3b32100000

IMPORTANT: if you fix the bug, please add the following tag to the commit:
Reported-by: syzbot+66243b...@syzkaller.appspotmail.com

rcu: INFO: rcu_preempt self-detected stall on CPU

rcu: 0-....: (10533 ticks this GP) idle=aea/1/0x4000000000000002 softirq=10553/10555 fqs=5249
(t=10501 jiffies g=12777 q=556)

NMI backtrace for cpu 0

CPU: 0 PID: 8729 Comm: syz-executor.3 Not tainted 5.7.0-rc1-next-20200415-syzkaller #0

Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
<IRQ>
__dump_stack lib/dump_stack.c:77 [inline]
dump_stack+0x188/0x20d lib/dump_stack.c:118
nmi_cpu_backtrace.cold+0x70/0xb1 lib/nmi_backtrace.c:101
nmi_trigger_cpumask_backtrace+0x231/0x27e lib/nmi_backtrace.c:62

trigger_single_cpu_backtrace include/linux/nmi.h:165 [inline]

rcu_dump_cpu_stacks+0x19b/0x1e5 kernel/rcu/tree_stall.h:254
print_cpu_stall kernel/rcu/tree_stall.h:475 [inline]
check_cpu_stall kernel/rcu/tree_stall.h:549 [inline]
rcu_pending kernel/rcu/tree.c:3225 [inline]

rcu_sched_clock_irq.cold+0x55d/0xd00 kernel/rcu/tree.c:2296

update_process_times+0x25/0x60 kernel/time/timer.c:1727
tick_sched_handle+0x9b/0x180 kernel/time/tick-sched.c:176
tick_sched_timer+0x4e/0x140 kernel/time/tick-sched.c:1320
__run_hrtimer kernel/time/hrtimer.c:1520 [inline]
__hrtimer_run_queues+0x5ca/0xed0 kernel/time/hrtimer.c:1584
hrtimer_interrupt+0x312/0x770 kernel/time/hrtimer.c:1646
local_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1113 [inline]
smp_apic_timer_interrupt+0x15b/0x600 arch/x86/kernel/apic/apic.c:1138
apic_timer_interrupt+0xf/0x20 arch/x86/entry/entry_64.S:829
</IRQ>
RIP: 0010:io_ring_ctx_wait_and_kill+0x98/0x5a0 fs/io_uring.c:7301

Code: 01 00 00 4d 89 f4 48 b8 00 00 00 00 00 fc ff df 4c 89 ed 49 c1 ec 03 48 c1 ed 03 49 01 c4 48 01 c5 eb 1c e8 ba 65 9d ff f3 90 <41> 80 3c 24 00 0f 85 53 04 00 00 48 83 bb 10 01 00 00 00 74 21 e8
RSP: 0018:ffffc900054d7a50 EFLAGS: 00000293 ORIG_RAX: ffffffffffffff13
RAX: ffff888097c14400 RBX: ffff8880963a0000 RCX: 1ffff92000a9af37
RDX: 0000000000000000 RSI: ffffffff81d5ced6 RDI: ffff8880963a0300
RBP: ffffed1012c7402c R08: 0000000000000001 R09: ffffed1012c74061
R10: ffff8880963a0307 R11: ffffed1012c74060 R12: ffffed1012c74022
R13: ffff8880963a0160 R14: ffff8880963a0110 R15: ffffffff81d5d3e0

io_uring_release+0x3e/0x50 fs/io_uring.c:7324
__fput+0x33e/0x880 fs/file_table.c:280
task_work_run+0xf4/0x1b0 kernel/task_work.c:123

exit_task_work include/linux/task_work.h:22 [inline]
do_exit+0xb53/0x2e10 kernel/exit.c:795
do_group_exit+0x125/0x340 kernel/exit.c:893
get_signal+0x47b/0x24e0 kernel/signal.c:2735
do_signal+0x81/0x2240 arch/x86/kernel/signal.c:784
exit_to_usermode_loop+0x26c/0x360 arch/x86/entry/common.c:161

prepare_exit_to_usermode arch/x86/entry/common.c:196 [inline]
syscall_return_slowpath arch/x86/entry/common.c:279 [inline]
do_syscall_64+0x6b1/0x7d0 arch/x86/entry/common.c:305
entry_SYSCALL_64_after_hwframe+0x49/0xb3

RIP: 0033:0x45c829
Code: Bad RIP value.
RSP: 002b:00007fdd2a37fc78 EFLAGS: 00000246 ORIG_RAX: 00000000000001a9
RAX: 0000000000000003 RBX: 00000000004e0ce0 RCX: 000000000045c829
RDX: 0000000000000000 RSI: 0000000020000580 RDI: 00000000000000f1
RBP: 000000000078bf00 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00000000ffffffff
R13: 0000000000000204 R14: 00000000004c425f R15: 00007fdd2a3806d4

[Jens Axboe]

#syz fix: io_uring: use cond_resched() in io_ring_ctx_wait_and_kill()


--
Jens Axboe