[v6.1] possible deadlock in bpf_trace_printk

[syzbot]

Hello,

syzbot found the following issue on:

HEAD commit: 2f3918bc53fb Linux 6.1.33
git tree: linux-6.1.y
console output: https://syzkaller.appspot.com/x/log.txt?x=10acc055280000
kernel config: https://syzkaller.appspot.com/x/.config?x=668ab7dd51e152ad
dashboard link: https://syzkaller.appspot.com/bug?extid=70a56384836c766b65bd
compiler: Debian clang version 15.0.7, GNU ld (GNU Binutils for Debian) 2.35.2

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

Downloadable assets:
disk image: https://storage.googleapis.com/syzbot-assets/2fe03f78a447/disk-2f3918bc.raw.xz
vmlinux: https://storage.googleapis.com/syzbot-assets/9e5a58c7d429/vmlinux-2f3918bc.xz
kernel image: https://storage.googleapis.com/syzbot-assets/30f32ed2ad75/bzImage-2f3918bc.xz

IMPORTANT: if you fix the issue, please add the following tag to the commit:
Reported-by: syzbot+70a563...@syzkaller.appspotmail.com

============================================
WARNING: possible recursive locking detected
6.1.33-syzkaller #0 Not tainted
--------------------------------------------
syz-executor.1/3575 is trying to acquire lock:
ffffffff8cf84fd8 (trace_printk_lock){-.-.}-{2:2}, at: ____bpf_trace_printk kernel/trace/bpf_trace.c:390 [inline]
ffffffff8cf84fd8 (trace_printk_lock){-.-.}-{2:2}, at: bpf_trace_printk+0x151/0x200 kernel/trace/bpf_trace.c:376

but task is already holding lock:
ffffffff8cf84fd8 (trace_printk_lock){-.-.}-{2:2}, at: ____bpf_trace_printk kernel/trace/bpf_trace.c:390 [inline]
ffffffff8cf84fd8 (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

5 locks held by syz-executor.1/3575:
#0: ffff8880288b4308 (&xt[i].mutex){+.+.}-{3:3}, at: xt_find_table_lock+0x48/0x3a0 net/netfilter/x_tables.c:1242
#1: ffff8880288b42c0 (&lock->wait_lock){+.+.}-{2:2}, at: __mutex_lock_common+0x11bc/0x2520 kernel/locking/mutex.c:701
#2: ffffffff8cf272a0 (rcu_read_lock){....}-{1:2}, at: rcu_lock_acquire+0x5/0x30 include/linux/rcupdate.h:305
#3: ffffffff8cf84fd8 (trace_printk_lock){-.-.}-{2:2}, at: ____bpf_trace_printk kernel/trace/bpf_trace.c:390 [inline]
#3: ffffffff8cf84fd8 (trace_printk_lock){-.-.}-{2:2}, at: bpf_trace_printk+0x151/0x200 kernel/trace/bpf_trace.c:376
#4: ffffffff8cf272a0 (rcu_read_lock){....}-{1:2}, at: rcu_lock_acquire+0x5/0x30 include/linux/rcupdate.h:305

stack backtrace:
CPU: 0 PID: 3575 Comm: syz-executor.1 Not tainted 6.1.33-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 05/25/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:2991 [inline]
check_deadlock kernel/locking/lockdep.c:3034 [inline]
validate_chain+0x4726/0x58e0 kernel/locking/lockdep.c:3819
__lock_acquire+0x125b/0x1f80 kernel/locking/lockdep.c:5056
lock_acquire+0x1f8/0x5a0 kernel/locking/lockdep.c:5669
__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:975 [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:2258 [inline]
bpf_trace_run2+0x1d6/0x3e0 kernel/trace/bpf_trace.c:2297
__traceiter_contention_end+0x74/0xa0 include/trace/events/lock.h:122
trace_contention_end+0x14c/0x190 include/trace/events/lock.h:122
__pv_queued_spin_lock_slowpath+0x935/0xc50 kernel/locking/qspinlock.c:560
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:975 [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:2258 [inline]
bpf_trace_run2+0x1d6/0x3e0 kernel/trace/bpf_trace.c:2297
__traceiter_contention_end+0x74/0xa0 include/trace/events/lock.h:122
trace_contention_end+0x12f/0x170 include/trace/events/lock.h:122
__mutex_lock_common+0x13a1/0x2520 kernel/locking/mutex.c:722
__mutex_lock kernel/locking/mutex.c:747 [inline]
mutex_lock_nested+0x17/0x20 kernel/locking/mutex.c:799
xt_find_table_lock+0x48/0x3a0 net/netfilter/x_tables.c:1242
xt_request_find_table_lock+0x22/0xf0 net/netfilter/x_tables.c:1284
get_info net/ipv4/netfilter/ip_tables.c:965 [inline]
do_ipt_get_ctl+0x872/0x1890 net/ipv4/netfilter/ip_tables.c:1653
nf_getsockopt+0x28e/0x2b0 net/netfilter/nf_sockopt.c:116
ip_getsockopt+0x21a/0x2d0 net/ipv4/ip_sockglue.c:1824
tcp_getsockopt+0x15c/0x1c0 net/ipv4/tcp.c:4403
__sys_getsockopt+0x2b2/0x5d0 net/socket.c:2296
__do_sys_getsockopt net/socket.c:2311 [inline]
__se_sys_getsockopt net/socket.c:2308 [inline]
__x64_sys_getsockopt+0xb1/0xc0 net/socket.c:2308
do_syscall_x64 arch/x86/entry/common.c:50 [inline]
do_syscall_64+0x3d/0xb0 arch/x86/entry/common.c:80
entry_SYSCALL_64_after_hwframe+0x63/0xcd
RIP: 0033:0x7fd771c8d78a
Code: 48 c7 c1 b8 ff ff ff f7 d8 64 89 01 48 83 c8 ff c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 49 89 ca b8 37 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 c7 c1 b8 ff ff ff f7 d8 64 89 01 48
RSP: 002b:00007ffe02e50f48 EFLAGS: 00000246 ORIG_RAX: 0000000000000037
RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007fd771c8d78a
RDX: 0000000000000040 RSI: 0000000000000000 RDI: 0000000000000003
RBP: 00007ffe02e50f70 R08: 00007ffe02e50f6c R09: ffffffffff000000
R10: 00007ffe02e50f70 R11: 0000000000000246 R12: 0000000000000032
R13: 0000000000000003 R14: 00007ffe02e50f6c R15: 00007fd771d86d20
</TASK>


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

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

If the bug is already fixed, let syzbot know by replying with:
#syz fix: exact-commit-title

If you want to change bug's subsystems, reply with:
#syz set subsystems: new-subsystem
(See the list of subsystem names on the web dashboard)

If the bug is a duplicate of another bug, reply with:
#syz dup: exact-subject-of-another-report

If you want to undo deduplication, reply with:
#syz undup

[syzbot]

syzbot has found a reproducer for the following issue on:

HEAD commit: 2f3918bc53fb Linux 6.1.33
git tree: linux-6.1.y

console output: https://syzkaller.appspot.com/x/log.txt?x=170f5807280000

kernel config: https://syzkaller.appspot.com/x/.config?x=668ab7dd51e152ad
dashboard link: https://syzkaller.appspot.com/bug?extid=70a56384836c766b65bd
compiler: Debian clang version 15.0.7, GNU ld (GNU Binutils for Debian) 2.35.2

syz repro: https://syzkaller.appspot.com/x/repro.syz?x=1666ac53280000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=1701f9b3280000

Downloadable assets:
disk image: https://storage.googleapis.com/syzbot-assets/2fe03f78a447/disk-2f3918bc.raw.xz
vmlinux: https://storage.googleapis.com/syzbot-assets/9e5a58c7d429/vmlinux-2f3918bc.xz
kernel image: https://storage.googleapis.com/syzbot-assets/30f32ed2ad75/bzImage-2f3918bc.xz

IMPORTANT: if you fix the issue, please add the following tag to the commit:
Reported-by: syzbot+70a563...@syzkaller.appspotmail.com

============================================
WARNING: possible recursive locking detected
6.1.33-syzkaller #0 Not tainted
--------------------------------------------

syz-executor304/3555 is trying to acquire lock:
ffffffff8cf84fd8 (trace_printk_lock){....}-{2:2}, at: ____bpf_trace_printk kernel/trace/bpf_trace.c:390 [inline]
ffffffff8cf84fd8 (trace_printk_lock){....}-{2:2}, at: bpf_trace_printk+0x151/0x200 kernel/trace/bpf_trace.c:376

but task is already holding lock:

ffffffff8cf84fd8 (trace_printk_lock){....}-{2:2}, at: ____bpf_trace_printk kernel/trace/bpf_trace.c:390 [inline]
ffffffff8cf84fd8 (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

4 locks held by syz-executor304/3555:
#0: ffff88802259b1b8 (&tsk->futex_exit_mutex){+.+.}-{3:3}, at: futex_cleanup_begin kernel/futex/core.c:1066 [inline]
#0: ffff88802259b1b8 (&tsk->futex_exit_mutex){+.+.}-{3:3}, at: futex_exit_release+0x30/0x1e0 kernel/futex/core.c:1118
#1: ffffffff8cf272a0 (rcu_read_lock){....}-{1:2}, at: rcu_lock_acquire+0x5/0x30 include/linux/rcupdate.h:305
#2: ffffffff8cf84fd8 (trace_printk_lock){....}-{2:2}, at: ____bpf_trace_printk kernel/trace/bpf_trace.c:390 [inline]
#2: ffffffff8cf84fd8 (trace_printk_lock){....}-{2:2}, at: bpf_trace_printk+0x151/0x200 kernel/trace/bpf_trace.c:376
#3: ffffffff8cf272a0 (rcu_read_lock){....}-{1:2}, at: rcu_lock_acquire+0x5/0x30 include/linux/rcupdate.h:305

stack backtrace:
CPU: 0 PID: 3555 Comm: syz-executor304 Not tainted 6.1.33-syzkaller #0

__mutex_lock_common+0x41f/0x2520 kernel/locking/mutex.c:612

__mutex_lock kernel/locking/mutex.c:747 [inline]
mutex_lock_nested+0x17/0x20 kernel/locking/mutex.c:799

futex_cleanup_begin kernel/futex/core.c:1066 [inline]
futex_exit_release+0x30/0x1e0 kernel/futex/core.c:1118
exit_mm_release+0x16/0x30 kernel/fork.c:1497
exit_mm+0xa9/0x300 kernel/exit.c:535
do_exit+0x67e/0x2300 kernel/exit.c:856
do_group_exit+0x202/0x2b0 kernel/exit.c:1019
__do_sys_exit_group kernel/exit.c:1030 [inline]
__se_sys_exit_group kernel/exit.c:1028 [inline]
__x64_sys_exit_group+0x3b/0x40 kernel/exit.c:1028

do_syscall_x64 arch/x86/entry/common.c:50 [inline]
do_syscall_64+0x3d/0xb0 arch/x86/entry/common.c:80
entry_SYSCALL_64_after_hwframe+0x63/0xcd

RIP: 0033:0x7ff967a52c49
Code: 00 49 c7 c0 c0 ff ff ff be e7 00 00 00 ba 3c 00 00 00 eb 12 0f 1f 44 00 00 89 d0 0f 05 48 3d 00 f0 ff ff 77 1c f4 89 f0 0f 05 <48> 3d 00 f0 ff ff 76 e7 f7 d8 64 41 89 00 eb df 0f 1f 80 00 00 00
RSP: 002b:00007fff4aa3f9c8 EFLAGS: 00000246 ORIG_RAX: 00000000000000e7
RAX: ffffffffffffffda RBX: 00007ff967ac8330 RCX: 00007ff967a52c49
RDX: 000000000000003c RSI: 00000000000000e7 RDI: 0000000000000000
RBP: 0000000000000000 R08: ffffffffffffffc0 R09: 0000000000000001
R10: 0000000000000000 R11: 0000000000000246 R12: 00007ff967ac8330
R13: 0000000000000001 R14: 0000000000000000 R15: 0000000000000001
</TASK>


---
If you want syzbot to run the reproducer, reply with:
#syz test: git://repo/address.git branch-or-commit-hash
If you attach or paste a git patch, syzbot will apply it before testing.

[syzbot]

syzbot suspects this issue could be fixed by backporting the following commit:

commit e2bb9e01d589f7fa82573aedd2765ff9b277816a
git tree: upstream
Author: Jiri Olsa <jo...@kernel.org>
Date: Thu Dec 15 21:44:30 2022 +0000

bpf: Remove trace_printk_lock

bisection log: https://syzkaller.appspot.com/x/bisect.txt?x=10267d54680000

kernel config: https://syzkaller.appspot.com/x/.config?x=668ab7dd51e152ad
dashboard link: https://syzkaller.appspot.com/bug?extid=70a56384836c766b65bd

syz repro: https://syzkaller.appspot.com/x/repro.syz?x=1666ac53280000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=1701f9b3280000

Please keep in mind that other backports might be required as well.

For information about bisection process see: https://goo.gl/tpsmEJ#bisection