INFO: rcu detected stall in bpf

6 views
Skip to first unread message

syzbot

unread,
Mar 4, 2020, 11:30:10 AM3/4/20
to syzkaller...@googlegroups.com
Hello,

syzbot found the following crash on:

HEAD commit: 78d697fc Linux 4.14.172
git tree: linux-4.14.y
console output: https://syzkaller.appspot.com/x/log.txt?x=17df0819e00000
kernel config: https://syzkaller.appspot.com/x/.config?x=31ad682bcda9b93f
dashboard link: https://syzkaller.appspot.com/bug?extid=273d031c9aa5bce41346
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+273d03...@syzkaller.appspotmail.com

INFO: rcu_sched detected stalls on CPUs/tasks:
0-...: (10501 ticks this GP) idle=6de/140000000000002/0 softirq=18461/18461 fqs=3
(detected by 1, t=10503 jiffies, g=1854, c=1853, q=7)
Sending NMI from CPU 1 to CPUs 0:
INFO: NMI handler (nmi_cpu_backtrace_handler) took too long to run: 1.502 msecs
NMI backtrace for cpu 0
CPU: 0 PID: 8687 Comm: syz-executor.3 Not tainted 4.14.172-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
task: ffff888052684140 task.stack: ffff888053280000
RIP: 0010:debug_lockdep_rcu_enabled.part.0+0x42/0x50 kernel/rcu/update.c:299
RSP: 0018:ffff8880aea075a0 EFLAGS: 00000002
RAX: 0000000000000000 RBX: ffff888052684140 RCX: 1ffffffff1027974
RDX: 0000000000000001 RSI: 0000000000000000 RDI: ffff8880526849bc
RBP: ffffffff87d843e0 R08: 0000000000000000 R09: 0000000000000000
R10: ffff888052684a60 R11: ffff888052684140 R12: 0000000000000000
R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000002
FS: 00007f4f09090700(0000) GS:ffff8880aea00000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000000000625208 CR3: 000000008a034000 CR4: 00000000001426f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
<IRQ>
trace_lock_acquire include/trace/events/lock.h:13 [inline]
lock_acquire+0x307/0x3f0 kernel/locking/lockdep.c:3993
rcu_lock_acquire include/linux/rcupdate.h:242 [inline]
rcu_read_lock include/linux/rcupdate.h:629 [inline]
kill_fasync fs/fcntl.c:1010 [inline]
kill_fasync+0x6c/0x3c0 fs/fcntl.c:1004
perf_event_wakeup+0x20c/0x350 kernel/events/core.c:5569
perf_pending_event+0xa5/0xd0 kernel/events/core.c:5593
irq_work_run_list+0xf0/0x160 kernel/irq_work.c:156
irq_work_run+0x4e/0xb0 kernel/irq_work.c:171
smp_irq_work_interrupt+0xa3/0x4e0 arch/x86/kernel/irq_work.c:21
irq_work_interrupt+0x8f/0xa0 arch/x86/entry/entry_64.S:823
RIP: 0010:orc_ip arch/x86/kernel/unwind_orc.c:27 [inline]
RIP: 0010:__orc_find+0x6f/0xf0 arch/x86/kernel/unwind_orc.c:49
RSP: 0018:ffff8880aea077a8 EFLAGS: 00000a03 ORIG_RAX: ffffffffffffff09
RAX: 1ffffffff11416ce RBX: ffffffff88a0b674 RCX: ffffffff8163e1e8
RDX: 0000000000000000 RSI: ffffffff88eee14e RDI: ffffffff88a0b674
RBP: ffffffff88a0b674 R08: ffffffff88eee154 R09: ffff888053287c20
R10: ffff8880aea078d5 R11: 0000000000058071 R12: ffffffff88a0b674
R13: ffffffff88a0b674 R14: ffffffff88a0b674 R15: dffffc0000000000
orc_find arch/x86/kernel/unwind_orc.c:121 [inline]
unwind_next_frame+0x5de/0x17a0 arch/x86/kernel/unwind_orc.c:348
__save_stack_trace+0x6b/0xd0 arch/x86/kernel/stacktrace.c:44
save_stack+0x32/0xa0 mm/kasan/kasan.c:447
set_track mm/kasan/kasan.c:459 [inline]
kasan_kmalloc mm/kasan/kasan.c:551 [inline]
kasan_kmalloc+0xbf/0xe0 mm/kasan/kasan.c:529
slab_post_alloc_hook mm/slab.h:442 [inline]
slab_alloc mm/slab.c:3390 [inline]
kmem_cache_alloc+0x114/0x770 mm/slab.c:3550
skb_clone+0x11c/0x310 net/core/skbuff.c:1282
frame_get_tagged_skb net/hsr/hsr_forward.c:195 [inline]
hsr_forward_do net/hsr/hsr_forward.c:283 [inline]
hsr_forward_skb+0xf18/0x18ed net/hsr/hsr_forward.c:373
send_hsr_supervision_frame+0x8ec/0xf40 net/hsr/hsr_device.c:321
hsr_announce+0xf0/0x330 net/hsr/hsr_device.c:350
call_timer_fn+0x14a/0x650 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+0x52a/0x1390 kernel/time/timer.c:1649
__do_softirq+0x254/0x9bf kernel/softirq.c:288
invoke_softirq kernel/softirq.c:368 [inline]
irq_exit+0x15b/0x1a0 kernel/softirq.c:409
exiting_irq arch/x86/include/asm/apic.h:648 [inline]
smp_apic_timer_interrupt+0x141/0x5e0 arch/x86/kernel/apic/apic.c:1102
apic_timer_interrupt+0x8f/0xa0 arch/x86/entry/entry_64.S:792
</IRQ>
RIP: 0010:arch_local_irq_restore arch/x86/include/asm/paravirt.h:779 [inline]
RIP: 0010:__free_pages_ok+0x588/0xdf0 mm/page_alloc.c:1263
RSP: 0018:ffff888053287320 EFLAGS: 00000286 ORIG_RAX: ffffffffffffff10
RAX: 1ffffffff0fa2ce1 RBX: 0000000000000001 RCX: 1ffff1100a4d093c
RDX: dffffc0000000000 RSI: ffff8880526849e8 RDI: 0000000000000286
RBP: ffffea0001490400 R08: 0000000000000001 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000286
R13: 0000000000000003 R14: 0000000000052410 R15: 0000000000000000
free_thread_stack kernel/fork.c:262 [inline]
release_task_stack kernel/fork.c:347 [inline]
put_task_stack+0x9d/0x1c0 kernel/fork.c:358
finish_task_switch+0x46b/0x620 kernel/sched/core.c:2692
context_switch kernel/sched/core.c:2811 [inline]
__schedule+0x7c0/0x1ca0 kernel/sched/core.c:3384
preempt_schedule_irq+0xb0/0x140 kernel/sched/core.c:3611
retint_kernel+0x1b/0x2d
RIP: 0010:__read_once_size include/linux/compiler.h:183 [inline]
RIP: 0010:raw_read_seqcount_latch include/linux/seqlock.h:281 [inline]
RIP: 0010:latch_tree_find include/linux/rbtree_latch.h:206 [inline]
RIP: 0010:bpf_prog_kallsyms_find kernel/bpf/core.c:422 [inline]
RIP: 0010:bpf_prog_kallsyms_find+0x74/0x260 kernel/bpf/core.c:415
RSP: 0018:ffff888053287560 EFLAGS: 00000212 ORIG_RAX: ffffffffffffff10
RAX: 0000000000000008 RBX: 000000000045c479 RCX: ffffc90009a32000
RDX: 000000000003a326 RSI: ffffffff8162db0e RDI: 000000000045c479
RBP: 000000000045c479 R08: 0000000000000000 R09: 0000000000020012
R10: ffff8880526849e8 R11: ffff888052684140 R12: dffffc0000000000
R13: 0000000000000000 R14: 000000000045c479 R15: ffff8880a3fde3df
is_bpf_text_address+0x5e/0x120 kernel/bpf/core.c:457
kernel_text_address+0x6e/0xe0 kernel/extable.c:150
__kernel_text_address+0x9/0x30 kernel/extable.c:105
unwind_get_return_address arch/x86/kernel/unwind_orc.c:255 [inline]
unwind_get_return_address+0x5a/0xa0 arch/x86/kernel/unwind_orc.c:250
__save_stack_trace+0x7b/0xd0 arch/x86/kernel/stacktrace.c:45
save_stack+0x32/0xa0 mm/kasan/kasan.c:447
set_track mm/kasan/kasan.c:459 [inline]
kasan_kmalloc mm/kasan/kasan.c:551 [inline]
kasan_kmalloc+0xbf/0xe0 mm/kasan/kasan.c:529
kmem_cache_alloc_trace+0x14d/0x7b0 mm/slab.c:3618
kmalloc include/linux/slab.h:488 [inline]
kzalloc include/linux/slab.h:661 [inline]
push_stack+0x73/0x280 kernel/bpf/verifier.c:552
check_cond_jmp_op kernel/bpf/verifier.c:3294 [inline]
do_check+0x436c/0x9350 kernel/bpf/verifier.c:4360
bpf_check+0xb1d/0x18a0 kernel/bpf/verifier.c:5047
bpf_prog_load+0x5e9/0xe00 kernel/bpf/syscall.c:1057
SYSC_bpf kernel/bpf/syscall.c:1509 [inline]
SyS_bpf+0x456/0x2d12 kernel/bpf/syscall.c:1475
do_syscall_64+0x1d5/0x640 arch/x86/entry/common.c:292
entry_SYSCALL_64_after_hwframe+0x42/0xb7
RIP: 0033:0x45c479
RSP: 002b:00007f4f0908fc78 EFLAGS: 00000246 ORIG_RAX: 0000000000000141
RAX: ffffffffffffffda RBX: 00007f4f090906d4 RCX: 000000000045c479
RDX: 0000000000000048 RSI: 0000000020000200 RDI: 0000000000000005
RBP: 000000000076bf20 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00000000ffffffff
R13: 0000000000000068 R14: 00000000004c2c9c R15: 000000000076bf2c
Code: 7c 08 00 00 48 89 fa 48 c1 ea 03 0f b6 14 02 48 89 f8 83 e0 07 83 c0 03 38 d0 7c 04 84 d2 75 0f 8b 93 7c 08 00 00 31 c0 5b 85 d2 <0f> 94 c0 c3 e8 65 a4 38 00 eb ea 0f 1f 00 48 c7 c0 04 23 92 88
rcu_sched kthread starved for 10459 jiffies! g1854 c1853 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x0 ->cpu=1
INFO: rcu_preempt detected stalls on CPUs/tasks:
rcu_sched R running task
29984 9 2 0x80000000
Tasks blocked on level-0 rcu_node (CPUs 0-1):
Call Trace:
P8687
P7686

(detected by 0, t=10502 jiffies, g=2633, c=2632, q=451)
schedule+0x8d/0x1b0 kernel/sched/core.c:3428
syz-executor.3 R
schedule_timeout+0x43c/0xe40 kernel/time/timer.c:1746
running task 27376 8687 7441 0x80000004
Call Trace:
preempt_schedule_irq+0xb0/0x140 kernel/sched/core.c:3611
rcu_gp_kthread+0xb8e/0x1ce0 kernel/rcu/tree.c:2255
retint_kernel+0x1b/0x2d
RIP: 0010:__read_once_size include/linux/compiler.h:183 [inline]
RIP: 0010:raw_read_seqcount_latch include/linux/seqlock.h:281 [inline]
RIP: 0010:latch_tree_find include/linux/rbtree_latch.h:206 [inline]
RIP: 0010:bpf_prog_kallsyms_find kernel/bpf/core.c:422 [inline]
RIP: 0010:bpf_prog_kallsyms_find+0x74/0x260 kernel/bpf/core.c:415
RSP: 0018:ffff888053287560 EFLAGS: 00000212 ORIG_RAX: ffffffffffffff10
kthread+0x30d/0x420 kernel/kthread.c:232
RAX: 0000000000000008 RBX: 000000000045c479 RCX: ffffc90009a32000
RDX: 000000000003a326 RSI: ffffffff8162db0e RDI: 000000000045c479
RBP: 000000000045c479 R08: 0000000000000000 R09: 0000000000020012
ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:404
R10: ffff8880526849e8 R11: ffff888052684140 R12: dffffc0000000000
R13: 0000000000000000 R14: 000000000045c479 R15: ffff8880a3fde3df
is_bpf_text_address+0x5e/0x120 kernel/bpf/core.c:457
kernel_text_address+0x6e/0xe0 kernel/extable.c:150
__kernel_text_address+0x9/0x30 kernel/extable.c:105
unwind_get_return_address arch/x86/kernel/unwind_orc.c:255 [inline]
unwind_get_return_address+0x5a/0xa0 arch/x86/kernel/unwind_orc.c:250
__save_stack_trace+0x7b/0xd0 arch/x86/kernel/stacktrace.c:45
save_stack+0x32/0xa0 mm/kasan/kasan.c:447
set_track mm/kasan/kasan.c:459 [inline]
kasan_kmalloc mm/kasan/kasan.c:551 [inline]
kasan_kmalloc+0xbf/0xe0 mm/kasan/kasan.c:529
kmem_cache_alloc_trace+0x14d/0x7b0 mm/slab.c:3618
kmalloc include/linux/slab.h:488 [inline]
kzalloc include/linux/slab.h:661 [inline]
push_stack+0x73/0x280 kernel/bpf/verifier.c:552
check_cond_jmp_op kernel/bpf/verifier.c:3294 [inline]
do_check+0x436c/0x9350 kernel/bpf/verifier.c:4360
bpf_check+0xb1d/0x18a0 kernel/bpf/verifier.c:5047
bpf_prog_load+0x5e9/0xe00 kernel/bpf/syscall.c:1057
SYSC_bpf kernel/bpf/syscall.c:1509 [inline]
SyS_bpf+0x456/0x2d12 kernel/bpf/syscall.c:1475
do_syscall_64+0x1d5/0x640 arch/x86/entry/common.c:292
entry_SYSCALL_64_after_hwframe+0x42/0xb7
RIP: 0033:0x45c479
RSP: 002b:00007f4f0908fc78 EFLAGS: 00000246 ORIG_RAX: 0000000000000141
RAX: ffffffffffffffda RBX: 00007f4f090906d4 RCX: 000000000045c479
RDX: 0000000000000048 RSI: 0000000020000200 RDI: 0000000000000005
RBP: 000000000076bf20 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00000000ffffffff
R13: 0000000000000068 R14: 00000000004c2c9c R15: 000000000076bf2c
kworker/u4:6 R running task 27056 7686 2 0x80000000
Workqueue: bat_events batadv_nc_worker
Call Trace:
preempt_schedule_irq+0xb0/0x140 kernel/sched/core.c:3611
retint_kernel+0x1b/0x2d
RIP: 0010:arch_local_irq_restore arch/x86/include/asm/paravirt.h:779 [inline]
RIP: 0010:lock_acquire+0x1ec/0x3f0 kernel/locking/lockdep.c:3997
RSP: 0018:ffff88805156fcb8 EFLAGS: 00000286 ORIG_RAX: ffffffffffffff10
RAX: 1ffffffff0fa2ce1 RBX: ffff88808023c340 RCX: 000000002286b4b8
RDX: dffffc0000000000 RSI: ffff88808023cc10 RDI: 0000000000000286
RBP: ffffffff87d843e0 R08: 0000000000000000 R09: 0000000000020012
R10: ffff88808023cc10 R11: ffff88808023c340 R12: 0000000000000000
R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000002
rcu_lock_acquire include/linux/rcupdate.h:242 [inline]
rcu_read_lock include/linux/rcupdate.h:629 [inline]
batadv_nc_purge_orig_hash net/batman-adv/network-coding.c:416 [inline]
batadv_nc_worker+0x103/0x6d0 net/batman-adv/network-coding.c:726
process_one_work+0x813/0x1540 kernel/workqueue.c:2114
worker_thread+0x5d1/0x1070 kernel/workqueue.c:2248
kthread+0x30d/0x420 kernel/kthread.c:232
ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:404
syz-executor.3 R running task 27376 8687 7441 0x80000004
Call Trace:
preempt_schedule_irq+0xb0/0x140 kernel/sched/core.c:3611
retint_kernel+0x1b/0x2d
RIP: 0010:__read_once_size include/linux/compiler.h:183 [inline]
RIP: 0010:raw_read_seqcount_latch include/linux/seqlock.h:281 [inline]
RIP: 0010:latch_tree_find include/linux/rbtree_latch.h:206 [inline]
RIP: 0010:bpf_prog_kallsyms_find kernel/bpf/core.c:422 [inline]
RIP: 0010:bpf_prog_kallsyms_find+0x74/0x260 kernel/bpf/core.c:415
RSP: 0018:ffff888053287560 EFLAGS: 00000212 ORIG_RAX: ffffffffffffff10
RAX: 0000000000000008 RBX: 000000000045c479 RCX: ffffc90009a32000
RDX: 000000000003a326 RSI: ffffffff8162db0e RDI: 000000000045c479
RBP: 000000000045c479 R08: 0000000000000000 R09: 0000000000020012
R10: ffff8880526849e8 R11: ffff888052684140 R12: dffffc0000000000
R13: 0000000000000000 R14: 000000000045c479 R15: ffff8880a3fde3df
is_bpf_text_address+0x5e/0x120 kernel/bpf/core.c:457
kernel_text_address+0x6e/0xe0 kernel/extable.c:150
__kernel_text_address+0x9/0x30 kernel/extable.c:105
unwind_get_return_address arch/x86/kernel/unwind_orc.c:255 [inline]
unwind_get_return_address+0x5a/0xa0 arch/x86/kernel/unwind_orc.c:250
__save_stack_trace+0x7b/0xd0 arch/x86/kernel/stacktrace.c:45
save_stack+0x32/0xa0 mm/kasan/kasan.c:447
set_track mm/kasan/kasan.c:459 [inline]
kasan_kmalloc mm/kasan/kasan.c:551 [inline]
kasan_kmalloc+0xbf/0xe0 mm/kasan/kasan.c:529
kmem_cache_alloc_trace+0x14d/0x7b0 mm/slab.c:3618
kmalloc include/linux/slab.h:488 [inline]
kzalloc include/linux/slab.h:661 [inline]
push_stack+0x73/0x280 kernel/bpf/verifier.c:552
check_cond_jmp_op kernel/bpf/verifier.c:3294 [inline]
do_check+0x436c/0x9350 kernel/bpf/verifier.c:4360
bpf_check+0xb1d/0x18a0 kernel/bpf/verifier.c:5047
bpf_prog_load+0x5e9/0xe00 kernel/bpf/syscall.c:1057
SYSC_bpf kernel/bpf/syscall.c:1509 [inline]
SyS_bpf+0x456/0x2d12 kernel/bpf/syscall.c:1475
do_syscall_64+0x1d5/0x640 arch/x86/entry/common.c:292
entry_SYSCALL_64_after_hwframe+0x42/0xb7
RIP: 0033:0x45c479
RSP: 002b:00007f4f0908fc78 EFLAGS: 00000246 ORIG_RAX: 0000000000000141
RAX: ffffffffffffffda RBX: 00007f4f090906d4 RCX: 000000000045c479
RDX: 0000000000000048 RSI: 0000000020000200 RDI: 0000000000000005
RBP: 000000000076bf20 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00000000ffffffff
R13: 0000000000000068 R14: 00000000004c2c9c R15: 000000000076bf2c
kworker/u4:6 R running task 27056 7686 2 0x80000000
Workqueue: bat_events batadv_nc_worker
Call Trace:
preempt_schedule_irq+0xb0/0x140 kernel/sched/core.c:3611
retint_kernel+0x1b/0x2d
RIP: 0010:arch_local_irq_restore arch/x86/include/asm/paravirt.h:779 [inline]
RIP: 0010:lock_acquire+0x1ec/0x3f0 kernel/locking/lockdep.c:3997
RSP: 0018:ffff88805156fcb8 EFLAGS: 00000286 ORIG_RAX: ffffffffffffff10
RAX: 1ffffffff0fa2ce1 RBX: ffff88808023c340 RCX: 000000002286b4b8
RDX: dffffc0000000000 RSI: ffff88808023cc10 RDI: 0000000000000286
RBP: ffffffff87d843e0 R08: 0000000000000000 R09: 0000000000020012
R10: ffff88808023cc10 R11: ffff88808023c340 R12: 0000000000000000
R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000002
rcu_lock_acquire include/linux/rcupdate.h:242 [inline]
rcu_read_lock include/linux/rcupdate.h:629 [inline]
batadv_nc_purge_orig_hash net/batman-adv/network-coding.c:416 [inline]
batadv_nc_worker+0x103/0x6d0 net/batman-adv/network-coding.c:726
process_one_work+0x813/0x1540 kernel/workqueue.c:2114
worker_thread+0x5d1/0x1070 kernel/workqueue.c:2248
kthread+0x30d/0x420 kernel/kthread.c:232
ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:404
md: md_import_device returned -22


---
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,
Sep 5, 2020, 7:39:10 AM9/5/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