syzbot


possible deadlock in bpf_trace_printk

Status: upstream: reported C repro on 2023/06/11 15:50
Bug presence: origin:lts-only
[Documentation on labels]
Reported-by: syzbot+70a56384836c766b65bd@syzkaller.appspotmail.com
First crash: 558d, last: 349d
Fix commit to backport (bisect log) :
tree: upstream
commit e2bb9e01d589f7fa82573aedd2765ff9b277816a
Author: Jiri Olsa <jolsa@kernel.org>
Date: Thu Dec 15 21:44:30 2022 +0000

  bpf: Remove trace_printk_lock

[report pending]
  
Fix bisection: the issue occurs on the latest tested release (bisect log)
Crash: possible deadlock in bpf_trace_printk (log)
Repro: C syz .config
  
Bug presence (2)
Date Name Commit Repro Result
2023/06/12 linux-6.1.y (ToT) 2f3918bc53fb C [report] INFO: rcu detected stall in corrupted
2023/06/12 upstream (ToT) 858fd168a95c C Didn't crash
Similar bugs (1)
Kernel Title Repro Cause bisect Fix bisect Count Last Reported Patched Status
upstream possible deadlock in bpf_trace_printk bpf trace C done done 68 670d 925d 22/28 fixed on 2023/03/23 17:59
Fix bisection attempts (3)
Created Duration User Patch Repo Result
2023/09/18 00:10 5h40m fix candidate upstream OK (1) job log
2023/09/10 16:39 1h38m bisect fix linux-6.1.y OK (0) job log log
2023/07/16 06:33 2h53m bisect fix linux-6.1.y OK (0) job log log

Sample crash report:
============================================
WARNING: possible recursive locking detected
6.1.71-syzkaller #0 Not tainted
--------------------------------------------
syz-executor316/3549 is trying to acquire lock:
ffffffff8d188238 (trace_printk_lock){....}-{2:2}, at: ____bpf_trace_printk kernel/trace/bpf_trace.c:390 [inline]
ffffffff8d188238 (trace_printk_lock){....}-{2:2}, at: bpf_trace_printk+0x151/0x200 kernel/trace/bpf_trace.c:376

but task is already holding lock:
ffffffff8d188238 (trace_printk_lock){....}-{2:2}, at: ____bpf_trace_printk kernel/trace/bpf_trace.c:390 [inline]
ffffffff8d188238 (trace_printk_lock){....}-{2:2}, at: bpf_trace_printk+0x151/0x200 kernel/trace/bpf_trace.c:376

other info that might help us debug this:
 Possible unsafe locking scenario:

       CPU0
       ----
  lock(trace_printk_lock);
  lock(trace_printk_lock);

 *** DEADLOCK ***

 May be due to missing lock nesting notation

7 locks held by syz-executor316/3549:
 #0: ffffffff8d1c4b10 (dup_mmap_sem){.+.+}-{0:0}, at: dup_mmap kernel/fork.c:592 [inline]
 #0: ffffffff8d1c4b10 (dup_mmap_sem){.+.+}-{0:0}, at: dup_mm kernel/fork.c:1540 [inline]
 #0: ffffffff8d1c4b10 (dup_mmap_sem){.+.+}-{0:0}, at: copy_mm+0x3cb/0x1990 kernel/fork.c:1589
 #1: ffff888012469f58 (&mm->mmap_lock){++++}-{3:3}, at: mmap_write_lock_killable include/linux/mmap_lock.h:87 [inline]
 #1: ffff888012469f58 (&mm->mmap_lock){++++}-{3:3}, at: dup_mmap kernel/fork.c:593 [inline]
 #1: ffff888012469f58 (&mm->mmap_lock){++++}-{3:3}, at: dup_mm kernel/fork.c:1540 [inline]
 #1: ffff888012469f58 (&mm->mmap_lock){++++}-{3:3}, at: copy_mm+0x3e5/0x1990 kernel/fork.c:1589
 #2: ffff88807bc535d8 (&mm->mmap_lock/1){+.+.}-{3:3}, at: mmap_write_lock_nested include/linux/mmap_lock.h:78 [inline]
 #2: ffff88807bc535d8 (&mm->mmap_lock/1){+.+.}-{3:3}, at: dup_mmap kernel/fork.c:602 [inline]
 #2: ffff88807bc535d8 (&mm->mmap_lock/1){+.+.}-{3:3}, at: dup_mm kernel/fork.c:1540 [inline]
 #2: ffff88807bc535d8 (&mm->mmap_lock/1){+.+.}-{3:3}, at: copy_mm+0x4ca/0x1990 kernel/fork.c:1589
 #3: ffff88801246a368 (&mm->context.lock){+.+.}-{3:3}, at: ldt_dup_context+0x3b/0x2e0 arch/x86/kernel/ldt.c:457
 #4: ffffffff8d12a320 (rcu_read_lock){....}-{1:2}, at: rcu_lock_acquire include/linux/rcupdate.h:306 [inline]
 #4: ffffffff8d12a320 (rcu_read_lock){....}-{1:2}, at: rcu_read_lock include/linux/rcupdate.h:747 [inline]
 #4: ffffffff8d12a320 (rcu_read_lock){....}-{1:2}, at: __bpf_trace_run kernel/trace/bpf_trace.c:2274 [inline]
 #4: ffffffff8d12a320 (rcu_read_lock){....}-{1:2}, at: bpf_trace_run2+0x110/0x410 kernel/trace/bpf_trace.c:2314
 #5: ffffffff8d188238 (trace_printk_lock){....}-{2:2}, at: ____bpf_trace_printk kernel/trace/bpf_trace.c:390 [inline]
 #5: ffffffff8d188238 (trace_printk_lock){....}-{2:2}, at: bpf_trace_printk+0x151/0x200 kernel/trace/bpf_trace.c:376
 #6: ffffffff8d12a320 (rcu_read_lock){....}-{1:2}, at: rcu_lock_acquire include/linux/rcupdate.h:306 [inline]
 #6: ffffffff8d12a320 (rcu_read_lock){....}-{1:2}, at: rcu_read_lock include/linux/rcupdate.h:747 [inline]
 #6: ffffffff8d12a320 (rcu_read_lock){....}-{1:2}, at: __bpf_trace_run kernel/trace/bpf_trace.c:2274 [inline]
 #6: ffffffff8d12a320 (rcu_read_lock){....}-{1:2}, at: bpf_trace_run2+0x110/0x410 kernel/trace/bpf_trace.c:2314

stack backtrace:
CPU: 1 PID: 3549 Comm: syz-executor316 Not tainted 6.1.71-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 11/17/2023
Call Trace:
 <TASK>
 __dump_stack lib/dump_stack.c:88 [inline]
 dump_stack_lvl+0x1e3/0x2cb lib/dump_stack.c:106
 print_deadlock_bug kernel/locking/lockdep.c:2983 [inline]
 check_deadlock kernel/locking/lockdep.c:3026 [inline]
 validate_chain+0x4711/0x5950 kernel/locking/lockdep.c:3812
 __lock_acquire+0x125b/0x1f80 kernel/locking/lockdep.c:5049
 lock_acquire+0x1f8/0x5a0 kernel/locking/lockdep.c:5662
 __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
 _raw_spin_lock_irqsave+0xd1/0x120 kernel/locking/spinlock.c:162
 ____bpf_trace_printk kernel/trace/bpf_trace.c:390 [inline]
 bpf_trace_printk+0x151/0x200 kernel/trace/bpf_trace.c:376
 bpf_prog_0605f9f479290f07+0x2f/0x33
 bpf_dispatcher_nop_func include/linux/bpf.h:970 [inline]
 __bpf_prog_run include/linux/filter.h:600 [inline]
 bpf_prog_run include/linux/filter.h:607 [inline]
 __bpf_trace_run kernel/trace/bpf_trace.c:2275 [inline]
 bpf_trace_run2+0x1fd/0x410 kernel/trace/bpf_trace.c:2314
 __traceiter_contention_begin+0x74/0xa0 include/trace/events/lock.h:95
 trace_contention_begin+0x14f/0x1a0 include/trace/events/lock.h:95
 __pv_queued_spin_lock_slowpath+0x111/0xc50 kernel/locking/qspinlock.c:405
 pv_queued_spin_lock_slowpath arch/x86/include/asm/paravirt.h:591 [inline]
 queued_spin_lock_slowpath+0x42/0x50 arch/x86/include/asm/qspinlock.h:51
 queued_spin_lock include/asm-generic/qspinlock.h:114 [inline]
 do_raw_spin_lock+0x269/0x370 kernel/locking/spinlock_debug.c:115
 __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:111 [inline]
 _raw_spin_lock_irqsave+0xdd/0x120 kernel/locking/spinlock.c:162
 ____bpf_trace_printk kernel/trace/bpf_trace.c:390 [inline]
 bpf_trace_printk+0x151/0x200 kernel/trace/bpf_trace.c:376
 bpf_prog_0605f9f479290f07+0x2f/0x33
 bpf_dispatcher_nop_func include/linux/bpf.h:970 [inline]
 __bpf_prog_run include/linux/filter.h:600 [inline]
 bpf_prog_run include/linux/filter.h:607 [inline]
 __bpf_trace_run kernel/trace/bpf_trace.c:2275 [inline]
 bpf_trace_run2+0x1fd/0x410 kernel/trace/bpf_trace.c:2314
 __traceiter_contention_begin+0x74/0xa0 include/trace/events/lock.h:95
 trace_contention_begin+0x12f/0x170 include/trace/events/lock.h:95
 __mutex_lock_common kernel/locking/mutex.c:605 [inline]
 __mutex_lock+0x143/0xd80 kernel/locking/mutex.c:747
 ldt_dup_context+0x3b/0x2e0 arch/x86/kernel/ldt.c:457
 arch_dup_mmap arch/x86/include/asm/mmu_context.h:171 [inline]
 dup_mmap kernel/fork.c:705 [inline]
 dup_mm kernel/fork.c:1540 [inline]
 copy_mm+0x10ba/0x1990 kernel/fork.c:1589
 copy_process+0x19d5/0x4060 kernel/fork.c:2267
 kernel_clone+0x222/0x920 kernel/fork.c:2682
 __do_sys_clone kernel/fork.c:2823 [inline]
 __se_sys_clone kernel/fork.c:2807 [inline]
 __x64_sys_clone+0x231/0x280 kernel/fork.c:2807
 do_syscall_x64 arch/x86/entry/common.c:51 [inline]
 do_syscall_64+0x3d/0xb0 arch/x86/entry/common.c:81
 entry_SYSCALL_64_after_hwframe+0x63/0xcd
RIP: 0033:0x7f4ade0f9d33
Code: 1f 84 00 00 00 00 00 64 48 8b 04 25 10 00 00 00 45 31 c0 31 d2 31 f6 bf 11 00 20 01 4c 8d 90 d0 02 00 00 b8 38 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 35 89 c2 85 c0 75 2c 64 48 8b 04 25 10 00 00
RSP: 002b:00007ffd70640498 EFLAGS: 00000246 ORIG_RAX: 0000000000000038
RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f4ade0f9d33
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000001200011
RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000010
R10: 0000555556553650 R11: 0000000000000246 R12: 0000000000000001
R13: 00007ffd706405ac R14: 00007ffd706405c0 R15: 00007ffd706405b0
 </TASK>

Crashes (3):
Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Assets (help?) Manager Title
2024/01/07 00:55 linux-6.1.y 38fb82ecd144 d0304e9c .config console log report syz C [disk image] [vmlinux] [kernel image] ci2-linux-6-1-kasan-perf possible deadlock in bpf_trace_printk
2023/06/12 08:27 linux-6.1.y 2f3918bc53fb 49519f06 .config console log report syz C [disk image] [vmlinux] [kernel image] ci2-linux-6-1-kasan-perf possible deadlock in bpf_trace_printk
2023/06/11 15:48 linux-6.1.y 2f3918bc53fb 49519f06 .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-6-1-kasan-perf possible deadlock in bpf_trace_printk
* Struck through repros no longer work on HEAD.