INFO: rcu detected stall in open

4 views
Skip to first unread message

syzbot

unread,
Jan 9, 2020, 6:57:10 AM1/9/20
to syzkaller...@googlegroups.com
Hello,

syzbot found the following crash on:

HEAD commit: b0cdffaa Linux 4.14.163
git tree: linux-4.14.y
console output: https://syzkaller.appspot.com/x/log.txt?x=1250569ee00000
kernel config: https://syzkaller.appspot.com/x/.config?x=b207c4ed8f8f80b4
dashboard link: https://syzkaller.appspot.com/bug?extid=02c65795dd5f9de10b3e
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+02c657...@syzkaller.appspotmail.com

INFO: rcu_sched detected stalls on CPUs/tasks:
1-...: (1 GPs behind) idle=e5a/140000000000002/0 softirq=11952/11969 fqs=3
(detected by 0, t=10502 jiffies, g=1248, c=1247, q=6)
Sending NMI from CPU 0 to CPUs 1:
INFO: NMI handler (nmi_cpu_backtrace_handler) took too long to run: 1.109
msecs
NMI backtrace for cpu 1
CPU: 1 PID: 7689 Comm: syz-executor.4 Not tainted 4.14.163-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS
Google 01/01/2011
task: ffff888051a92340 task.stack: ffff888051a98000
RIP: 0010:native_apic_msr_eoi_write+0xb/0x10 arch/x86/include/asm/apic.h:199
RSP: 0018:ffff8880aed07920 EFLAGS: 00000046
RAX: 0000000000000000 RBX: ffffffff87c191a0 RCX: 000000000000080b
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 00000000000000b0
RBP: ffff8880aed07940 R08: 0000004279a70e03 R09: ffff88821fff7048
R10: ffff88821fff7050 R11: 0000000000000001 R12: 0000000000000000
R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
FS: 00007fd2e8b43700(0000) GS:ffff8880aed00000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000001b2d630000 CR3: 000000009bcce000 CR4: 00000000001406e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
<IRQ>
irq_work_interrupt+0x96/0xa0 arch/x86/entry/entry_64.S:823
RIP: 0010:arch_local_irq_restore arch/x86/include/asm/paravirt.h:779
[inline]
RIP: 0010:lock_acquire+0x1ea/0x430 kernel/locking/lockdep.c:3997
RSP: 0018:ffff8880aed07a00 EFLAGS: 00000286 ORIG_RAX: ffffffffffffff09
RAX: 1ffffffff0fe2d29 RBX: ffff888051a92340 RCX: 00000000a134655d
RDX: dffffc0000000000 RSI: ffff888051a92c60 RDI: 0000000000000286
RBP: ffff8880aed07a48 R08: 0000000000000000 R09: ffff888051a92c80
R10: ffff888051a92c60 R11: ffff888051a92340 R12: ffffffff87f886a0
R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000002
rcu_lock_acquire include/linux/rcupdate.h:242 [inline]
rcu_read_lock include/linux/rcupdate.h:629 [inline]
nf_hook.constprop.0+0xb7/0x2c0 include/linux/netfilter.h:197
NF_HOOK include/linux/netfilter.h:248 [inline]
ndisc_send_skb+0x83b/0x11e0 net/ipv6/ndisc.c:483
ndisc_send_rs+0x12b/0x670 net/ipv6/ndisc.c:677
addrconf_rs_timer+0x289/0x5a0 net/ipv6/addrconf.c:3757
call_timer_fn+0x161/0x670 kernel/time/timer.c:1279
expire_timers kernel/time/timer.c:1318 [inline]
__run_timers kernel/time/timer.c:1636 [inline]
__run_timers kernel/time/timer.c:1604 [inline]
run_timer_softirq+0x5b7/0x1520 kernel/time/timer.c:1649
__do_softirq+0x244/0x9a0 kernel/softirq.c:288
invoke_softirq kernel/softirq.c:368 [inline]
irq_exit+0x160/0x1b0 kernel/softirq.c:409
exiting_irq arch/x86/include/asm/apic.h:648 [inline]
smp_apic_timer_interrupt+0x146/0x5e0 arch/x86/kernel/apic/apic.c:1102
apic_timer_interrupt+0x96/0xa0 arch/x86/entry/entry_64.S:792
</IRQ>
RIP: 0010:preempt_count_add+0x2f/0x1a0 kernel/sched/core.c:3099
RSP: 0018:ffff888051a9f4d8 EFLAGS: 00000206 ORIG_RAX: ffffffffffffff10
RAX: 0000000000000003 RBX: ffffffff89a98c80 RCX: ffffc90007e24000
RDX: 0000000000000004 RSI: ffffffff819bf586 RDI: 0000000000000001
RBP: ffff888051a9f4e8 R08: ffff888051a92340 R09: 0000000000000002
R10: 0000000000000000 R11: ffff888051a92340 R12: 0000000000000001
R13: 000000000000000f R14: ffffea0001fe4880 R15: ffff8882199f8318
__raw_spin_lock include/linux/spinlock_api_smp.h:141 [inline]
_raw_spin_lock+0x13/0x40 kernel/locking/spinlock.c:152
spin_lock include/linux/spinlock.h:317 [inline]
__find_get_block_slow fs/buffer.c:218 [inline]
__find_get_block fs/buffer.c:1357 [inline]
__find_get_block+0x479/0xbf0 fs/buffer.c:1351
__getblk_gfp+0x38/0x7c0 fs/buffer.c:1379
sb_getblk include/linux/buffer_head.h:325 [inline]
ext4_getblk+0x14f/0x450 fs/ext4/inode.c:987
ext4_bread+0x6e/0x1a0 fs/ext4/inode.c:1030
__ext4_read_dirblock+0x34/0x820 fs/ext4/namei.c:110
ext4_add_entry+0x5b9/0xa20 fs/ext4/namei.c:2103
ext4_add_nondir+0x28/0x80 fs/ext4/namei.c:2444
ext4_create+0x26e/0x4f0 fs/ext4/namei.c:2486
lookup_open+0x11a6/0x1860 fs/namei.c:3240
do_last fs/namei.c:3331 [inline]
path_openat+0xfca/0x3f70 fs/namei.c:3566
do_filp_open+0x18e/0x250 fs/namei.c:3600
do_sys_open+0x2c5/0x430 fs/open.c:1084
SYSC_open fs/open.c:1102 [inline]
SyS_open+0x2d/0x40 fs/open.c:1097
do_syscall_64+0x1e8/0x640 arch/x86/entry/common.c:292
entry_SYSCALL_64_after_hwframe+0x42/0xb7
RIP: 0033:0x45af49
RSP: 002b:00007fd2e8b42c78 EFLAGS: 00000246 ORIG_RAX: 0000000000000002
RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 000000000045af49
RDX: 0000000000000000 RSI: 0000000000141042 RDI: 0000000020002000
RBP: 000000000075bf20 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00007fd2e8b436d4
R13: 000000000050039f R14: 00000000004e0a68 R15: 00000000ffffffff
Code: 5f 00 eb a6 b8 da ff ff ff eb c7 0f 1f 44 00 00 55 be 01 00 00 00 48
89 e5 e8 22 d3 24 00 5d c3 31 c0 b9 0b 08 00 00 89 c2 0f 30 <c3> 0f 1f 40
00 c3 0f 1f 44 00 00 66 2e 0f 1f 84 00 00 00 00 00
rcu_sched kthread starved for 10447 jiffies! g1248 c1247 f0x0
RCU_GP_WAIT_FQS(3) ->state=0x0 ->cpu=0
rcu_sched R running task 29824 9 2 0x80000000
Call Trace:
context_switch kernel/sched/core.c:2808 [inline]
__schedule+0x7b8/0x1cd0 kernel/sched/core.c:3384
schedule+0x92/0x1c0 kernel/sched/core.c:3428
schedule_timeout+0x43e/0xe10 kernel/time/timer.c:1746
rcu_gp_kthread+0xbf4/0x1ec0 kernel/rcu/tree.c:2255
kthread+0x319/0x430 kernel/kthread.c:232
ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:404
INFO: rcu_preempt detected stalls on CPUs/tasks:
1-...: (1 GPs behind) idle=e5a/140000000000001/0 softirq=11955/11969 fqs=2
(detected by 0, t=10530 jiffies, g=1836, c=1835, q=313)
Sending NMI from CPU 0 to CPUs 1:
NMI backtrace for cpu 1
CPU: 1 PID: 7689 Comm: syz-executor.4 Not tainted 4.14.163-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS
Google 01/01/2011
task: ffff888051a92340 task.stack: ffff888051a98000
RIP: 0010:irq_work_run_list+0xe6/0x190 kernel/irq_work.c:156
RSP: 0018:ffff8880aed074a8 EFLAGS: 00000002
RAX: 0000000000000003 RBX: ffff888051aca4f0 RCX: 0000000000000000
RDX: 0000000000010100 RSI: ffffffff87049100 RDI: ffff8880aed278c8
RBP: ffff8880aed074d8 R08: 00000042a3455913 R09: ffff88821fff7048
R10: ffff88821fff7050 R11: 0000000000000001 R12: ffff888051aca4f8
R13: 0000000000000002 R14: dffffc0000000000 R15: 0000000000000003
FS: 00007fd2e8b43700(0000) GS:ffff8880aed00000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000001b2d630000 CR3: 000000009bcce000 CR4: 00000000001406e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
<IRQ>
irq_work_run+0x52/0xb0 kernel/irq_work.c:171
smp_irq_work_interrupt+0xa8/0x4e0 arch/x86/kernel/irq_work.c:21
irq_work_interrupt+0x96/0xa0 arch/x86/entry/entry_64.S:823
RIP: 0010:decode_frame_pointer arch/x86/kernel/unwind_frame.c:183 [inline]
RIP: 0010:update_stack_state+0xb1/0x590 arch/x86/kernel/unwind_frame.c:221
RSP: 0018:ffff8880aed075e0 EFLAGS: 00000286 ORIG_RAX: ffffffffffffff09
RAX: ffff8880aed07808 RBX: ffff8880aed07788 RCX: 1ffff11015da0ef8
RDX: 1ffff11015da0eef RSI: ffff8880aed07808 RDI: ffff8880aed077c0
RBP: ffff8880aed07688 R08: 000000000001ede0 R09: ffff8880aed077e0
R10: ffff8880aed077b0 R11: ffff8880aed077c0 R12: 1ffff11015da0ed8
R13: ffff8880aed07788 R14: 1ffff11015da0ec4 R15: ffff8880aed07808
unwind_next_frame.part.0+0x188/0x8b0 arch/x86/kernel/unwind_frame.c:333
unwind_next_frame arch/x86/include/asm/unwind.h:46 [inline]
__unwind_start+0x1f6/0x3d0 arch/x86/kernel/unwind_frame.c:433
unwind_start arch/x86/include/asm/unwind.h:60 [inline]
__save_stack_trace+0x4a/0xd0 arch/x86/kernel/stacktrace.c:43
save_stack_trace+0x16/0x20 arch/x86/kernel/stacktrace.c:59
save_stack+0x45/0xd0 mm/kasan/kasan.c:447
set_track mm/kasan/kasan.c:459 [inline]
kasan_kmalloc mm/kasan/kasan.c:551 [inline]
kasan_kmalloc+0xce/0xf0 mm/kasan/kasan.c:529
kasan_slab_alloc+0xf/0x20 mm/kasan/kasan.c:489
slab_post_alloc_hook mm/slab.h:442 [inline]
slab_alloc_node mm/slab.c:3333 [inline]
kmem_cache_alloc_node_trace+0x13c/0x770 mm/slab.c:3659
__do_kmalloc_node mm/slab.c:3681 [inline]
__kmalloc_node_track_caller+0x3d/0x80 mm/slab.c:3696
__kmalloc_reserve.isra.0+0x40/0xe0 net/core/skbuff.c:137
__alloc_skb+0xcf/0x500 net/core/skbuff.c:205
alloc_skb include/linux/skbuff.h:980 [inline]
ndisc_alloc_skb+0x13c/0x340 net/ipv6/ndisc.c:402
ndisc_send_rs+0x303/0x670 net/ipv6/ndisc.c:661
addrconf_rs_timer+0x289/0x5a0 net/ipv6/addrconf.c:3757
call_timer_fn+0x161/0x670 kernel/time/timer.c:1279
expire_timers kernel/time/timer.c:1318 [inline]
__run_timers kernel/time/timer.c:1636 [inline]
__run_timers kernel/time/timer.c:1604 [inline]
run_timer_softirq+0x5b7/0x1520 kernel/time/timer.c:1649
__do_softirq+0x244/0x9a0 kernel/softirq.c:288
invoke_softirq kernel/softirq.c:368 [inline]
irq_exit+0x160/0x1b0 kernel/softirq.c:409
exiting_irq arch/x86/include/asm/apic.h:648 [inline]
smp_apic_timer_interrupt+0x146/0x5e0 arch/x86/kernel/apic/apic.c:1102
apic_timer_interrupt+0x96/0xa0 arch/x86/entry/entry_64.S:792
</IRQ>
RIP: 0010:preempt_count_add+0x2f/0x1a0 kernel/sched/core.c:3099
RSP: 0018:ffff888051a9f4d8 EFLAGS: 00000206 ORIG_RAX: ffffffffffffff10
RAX: 0000000000000003 RBX: ffffffff89a98c80 RCX: ffffc90007e24000
RDX: 0000000000000004 RSI: ffffffff819bf586 RDI: 0000000000000001
RBP: ffff888051a9f4e8 R08: ffff888051a92340 R09: 0000000000000002
R10: 0000000000000000 R11: ffff888051a92340 R12: 0000000000000001
R13: 000000000000000f R14: ffffea0001fe4880 R15: ffff8882199f8318
__raw_spin_lock include/linux/spinlock_api_smp.h:141 [inline]
_raw_spin_lock+0x13/0x40 kernel/locking/spinlock.c:152
spin_lock include/linux/spinlock.h:317 [inline]
__find_get_block_slow fs/buffer.c:218 [inline]
__find_get_block fs/buffer.c:1357 [inline]
__find_get_block+0x479/0xbf0 fs/buffer.c:1351
__getblk_gfp+0x38/0x7c0 fs/buffer.c:1379
sb_getblk include/linux/buffer_head.h:325 [inline]
ext4_getblk+0x14f/0x450 fs/ext4/inode.c:987
ext4_bread+0x6e/0x1a0 fs/ext4/inode.c:1030
__ext4_read_dirblock+0x34/0x820 fs/ext4/namei.c:110
ext4_add_entry+0x5b9/0xa20 fs/ext4/namei.c:2103
ext4_add_nondir+0x28/0x80 fs/ext4/namei.c:2444
ext4_create+0x26e/0x4f0 fs/ext4/namei.c:2486
lookup_open+0x11a6/0x1860 fs/namei.c:3240
do_last fs/namei.c:3331 [inline]
path_openat+0xfca/0x3f70 fs/namei.c:3566
do_filp_open+0x18e/0x250 fs/namei.c:3600
do_sys_open+0x2c5/0x430 fs/open.c:1084
SYSC_open fs/open.c:1102 [inline]
SyS_open+0x2d/0x40 fs/open.c:1097
do_syscall_64+0x1e8/0x640 arch/x86/entry/common.c:292
entry_SYSCALL_64_after_hwframe+0x42/0xb7
RIP: 0033:0x45af49
RSP: 002b:00007fd2e8b42c78 EFLAGS: 00000246 ORIG_RAX: 0000000000000002
RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 000000000045af49
RDX: 0000000000000000 RSI: 0000000000141042 RDI: 0000000020002000
RBP: 000000000075bf20 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00007fd2e8b436d4
R13: 000000000050039f R14: 00000000004e0a68 R15: 00000000ffffffff
Code: 00 0f 85 a1 00 00 00 48 89 d8 49 8b 0c 24 48 c1 e8 03 42 80 3c 30 00
75 7a 4d 8b 7c 24 f8 4d 89 fd 49 83 e5 fe 4c 89 e8 48 87 03 <49> 8d 7c 24
08 48 89 f8 48 c1 e8 03 42 80 3c 30 00 75 46 48 89
rcu_preempt kthread starved for 10516 jiffies! g1836 c1835 f0x0
RCU_GP_WAIT_FQS(3) ->state=0x0 ->cpu=0
rcu_preempt R running task 29776 8 2 0x80000000
Call Trace:
context_switch kernel/sched/core.c:2808 [inline]
__schedule+0x7b8/0x1cd0 kernel/sched/core.c:3384
schedule+0x92/0x1c0 kernel/sched/core.c:3428
schedule_timeout+0x43e/0xe10 kernel/time/timer.c:1746
rcu_gp_kthread+0xbf4/0x1ec0 kernel/rcu/tree.c:2255
kthread+0x319/0x430 kernel/kthread.c:232
ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:404


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

syzbot

unread,
May 8, 2020, 7:57:09 AM5/8/20
to syzkaller...@googlegroups.com
Auto-closing this bug as obsolete.
Crashes did not happen for a while, no reproducer and no activity.
Reply all
Reply to author
Forward
0 new messages