[syzbot] [fs?] INFO: task hung in synchronize_rcu (4)

13 views

Skip to first unread message

syzbot

unread,

May 3, 2023, 10:01:53 PM5/3/23

to amir...@gmail.com, dan...@iogearbox.net, ja...@suse.cz, ka...@fb.com, linux-...@vger.kernel.org, linux-...@vger.kernel.org, net...@vger.kernel.org, syzkall...@googlegroups.com

Hello,

syzbot found the following issue on:

HEAD commit: 6686317855c6 net: dsa: mv88e6xxx: add mv88e6321 rsvd2cpu
git tree: net
console output: https://syzkaller.appspot.com/x/log.txt?x=1457a594280000
kernel config: https://syzkaller.appspot.com/x/.config?x=7205cdba522fe4bc
dashboard link: https://syzkaller.appspot.com/bug?extid=222aa26d0a5dbc2e84fe
compiler: gcc (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2
syz repro: https://syzkaller.appspot.com/x/repro.syz?x=12ede410280000

Downloadable assets:
disk image: https://storage.googleapis.com/syzbot-assets/48685f457043/disk-66863178.raw.xz
vmlinux: https://storage.googleapis.com/syzbot-assets/7e1798ecf070/vmlinux-66863178.xz
kernel image: https://storage.googleapis.com/syzbot-assets/cc77fb901221/bzImage-66863178.xz

The issue was bisected to:

commit 3b5d4ddf8fe1f60082513f94bae586ac80188a03
Author: Martin KaFai Lau <ka...@fb.com>
Date: Wed Mar 9 09:04:50 2022 +0000

bpf: net: Remove TC_AT_INGRESS_OFFSET and SKB_MONO_DELIVERY_TIME_OFFSET macro

bisection log: https://syzkaller.appspot.com/x/bisect.txt?x=153459d7c80000
final oops: https://syzkaller.appspot.com/x/report.txt?x=173459d7c80000
console output: https://syzkaller.appspot.com/x/log.txt?x=133459d7c80000

IMPORTANT: if you fix the issue, please add the following tag to the commit:
Reported-by: syzbot+222aa2...@syzkaller.appspotmail.com
Fixes: 3b5d4ddf8fe1 ("bpf: net: Remove TC_AT_INGRESS_OFFSET and SKB_MONO_DELIVERY_TIME_OFFSET macro")

INFO: task kworker/u4:1:12 blocked for more than 145 seconds.
Not tainted 6.3.0-syzkaller-07940-g6686317855c6 #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:kworker/u4:1 state:D stack:26288 pid:12 ppid:2 flags:0x00004000
Workqueue: events_unbound fsnotify_connector_destroy_workfn
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5307 [inline]
__schedule+0xc91/0x5770 kernel/sched/core.c:6625
schedule+0xde/0x1a0 kernel/sched/core.c:6701
schedule_timeout+0x276/0x2b0 kernel/time/timer.c:2143
do_wait_for_common kernel/sched/completion.c:85 [inline]
__wait_for_common+0x1ce/0x5c0 kernel/sched/completion.c:106
__synchronize_srcu+0x1be/0x2c0 kernel/rcu/srcutree.c:1360
fsnotify_connector_destroy_workfn+0x4d/0xa0 fs/notify/mark.c:208
process_one_work+0x991/0x15c0 kernel/workqueue.c:2390
worker_thread+0x669/0x1090 kernel/workqueue.c:2537
kthread+0x344/0x440 kernel/kthread.c:379
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:308
</TASK>
INFO: task kworker/u4:4:5134 blocked for more than 146 seconds.
Not tainted 6.3.0-syzkaller-07940-g6686317855c6 #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:kworker/u4:4 state:D stack:26344 pid:5134 ppid:2 flags:0x00004000
Workqueue: events_unbound fsnotify_mark_destroy_workfn
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5307 [inline]
__schedule+0xc91/0x5770 kernel/sched/core.c:6625
schedule+0xde/0x1a0 kernel/sched/core.c:6701
schedule_timeout+0x276/0x2b0 kernel/time/timer.c:2143
do_wait_for_common kernel/sched/completion.c:85 [inline]
__wait_for_common+0x1ce/0x5c0 kernel/sched/completion.c:106
__synchronize_srcu+0x1be/0x2c0 kernel/rcu/srcutree.c:1360
fsnotify_mark_destroy_workfn+0x101/0x3c0 fs/notify/mark.c:898
process_one_work+0x991/0x15c0 kernel/workqueue.c:2390
worker_thread+0x669/0x1090 kernel/workqueue.c:2537
kthread+0x344/0x440 kernel/kthread.c:379
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:308
</TASK>

Showing all locks held in the system:
2 locks held by kworker/u4:1/12:
#0: ffff888012479138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: arch_atomic64_set arch/x86/include/asm/atomic64_64.h:34 [inline]
#0: ffff888012479138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: arch_atomic_long_set include/linux/atomic/atomic-long.h:41 [inline]
#0: ffff888012479138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: atomic_long_set include/linux/atomic/atomic-instrumented.h:1324 [inline]
#0: ffff888012479138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: set_work_data kernel/workqueue.c:639 [inline]
#0: ffff888012479138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: set_work_pool_and_clear_pending kernel/workqueue.c:666 [inline]
#0: ffff888012479138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: process_one_work+0x87a/0x15c0 kernel/workqueue.c:2361
#1: ffffc90000117da8 (connector_reaper_work){+.+.}-{0:0}, at: process_one_work+0x8ae/0x15c0 kernel/workqueue.c:2365
1 lock held by rcu_tasks_kthre/13:
#0: ffffffff8c7962f0 (rcu_tasks.tasks_gp_mutex){+.+.}-{3:3}, at: rcu_tasks_one_gp+0x31/0xd80 kernel/rcu/tasks.h:518
1 lock held by rcu_tasks_trace/14:
#0: ffffffff8c795ff0 (rcu_tasks_trace.tasks_gp_mutex){+.+.}-{3:3}, at: rcu_tasks_one_gp+0x31/0xd80 kernel/rcu/tasks.h:518
3 locks held by kworker/1:0/22:
1 lock held by khungtaskd/28:
#0: ffffffff8c796f00 (rcu_read_lock){....}-{1:2}, at: debug_show_all_locks+0x55/0x340 kernel/locking/lockdep.c:6545
1 lock held by khugepaged/34:
#0: ffffffff8c896708 (lock#3){+.+.}-{3:3}, at: __lru_add_drain_all+0x62/0x6a0 mm/swap.c:852
2 locks held by getty/4759:
#0: ffff88814c1e0098 (&tty->ldisc_sem){++++}-{0:0}, at: tty_ldisc_ref_wait+0x26/0x80 drivers/tty/tty_ldisc.c:244
#1: ffffc900015a02f0 (&ldata->atomic_read_lock){+.+.}-{3:3}, at: n_tty_read+0xef4/0x13e0 drivers/tty/n_tty.c:2177
4 locks held by syz-executor.2/5077:
#0: ffff8880b993c2d8 (&rq->__lock){-.-.}-{2:2}, at: raw_spin_rq_lock_nested+0x2f/0x120 kernel/sched/core.c:539
#1: ffff88802296aef0 (&mm->cid_lock#2){....}-{2:2}, at: mm_cid_get kernel/sched/sched.h:3280 [inline]
#1: ffff88802296aef0 (&mm->cid_lock#2){....}-{2:2}, at: switch_mm_cid kernel/sched/sched.h:3302 [inline]
#1: ffff88802296aef0 (&mm->cid_lock#2){....}-{2:2}, at: prepare_task_switch kernel/sched/core.c:5117 [inline]
#1: ffff88802296aef0 (&mm->cid_lock#2){....}-{2:2}, at: context_switch kernel/sched/core.c:5258 [inline]
#1: ffff88802296aef0 (&mm->cid_lock#2){....}-{2:2}, at: __schedule+0x2802/0x5770 kernel/sched/core.c:6625
#2: ffff8880b9929698 (&base->lock){-.-.}-{2:2}, at: lock_timer_base+0x5a/0x1f0 kernel/time/timer.c:999
#3: ffffffff91fb4ac8 (&obj_hash[i].lock){-.-.}-{2:2}, at: debug_object_activate+0x134/0x3f0 lib/debugobjects.c:690
1 lock held by syz-executor.5/5080:
2 locks held by kworker/u4:4/5134:
#0: ffff888012479138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: arch_atomic64_set arch/x86/include/asm/atomic64_64.h:34 [inline]
#0: ffff888012479138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: arch_atomic_long_set include/linux/atomic/atomic-long.h:41 [inline]
#0: ffff888012479138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: atomic_long_set include/linux/atomic/atomic-instrumented.h:1324 [inline]
#0: ffff888012479138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: set_work_data kernel/workqueue.c:639 [inline]
#0: ffff888012479138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: set_work_pool_and_clear_pending kernel/workqueue.c:666 [inline]
#0: ffff888012479138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: process_one_work+0x87a/0x15c0 kernel/workqueue.c:2361
#1: ffffc9000433fda8 ((reaper_work).work){+.+.}-{0:0}, at: process_one_work+0x8ae/0x15c0 kernel/workqueue.c:2365
2 locks held by dhcpcd/5583:
#0: ffff88802b7e0130 (sk_lock-AF_PACKET){+.+.}-{0:0}, at: lock_sock include/net/sock.h:1697 [inline]
#0: ffff88802b7e0130 (sk_lock-AF_PACKET){+.+.}-{0:0}, at: packet_do_bind+0x2f/0xe30 net/packet/af_packet.c:3204
#1: ffffffff8c7a2378 (rcu_state.exp_mutex){+.+.}-{3:3}, at: exp_funnel_lock kernel/rcu/tree_exp.h:293 [inline]
#1: ffffffff8c7a2378 (rcu_state.exp_mutex){+.+.}-{3:3}, at: synchronize_rcu_expedited+0x64a/0x770 kernel/rcu/tree_exp.h:992
2 locks held by dhcpcd/5586:
#0: ffff88806919e130 (sk_lock-AF_PACKET){+.+.}-{0:0}, at: lock_sock include/net/sock.h:1697 [inline]
#0: ffff88806919e130 (sk_lock-AF_PACKET){+.+.}-{0:0}, at: packet_do_bind+0x2f/0xe30 net/packet/af_packet.c:3204
#1: ffffffff8c7a2378 (rcu_state.exp_mutex){+.+.}-{3:3}, at: exp_funnel_lock kernel/rcu/tree_exp.h:325 [inline]
#1: ffffffff8c7a2378 (rcu_state.exp_mutex){+.+.}-{3:3}, at: synchronize_rcu_expedited+0x3e8/0x770 kernel/rcu/tree_exp.h:992
1 lock held by dhcpcd/5587:
#0: ffff88802cca0130 (sk_lock-AF_PACKET){+.+.}-{0:0}, at: lock_sock include/net/sock.h:1697 [inline]
#0: ffff88802cca0130 (sk_lock-AF_PACKET){+.+.}-{0:0}, at: packet_do_bind+0x2f/0xe30 net/packet/af_packet.c:3204
1 lock held by dhcpcd/5598:
#0: ffff88807be2c130 (sk_lock-AF_PACKET){+.+.}-{0:0}, at: lock_sock include/net/sock.h:1697 [inline]
#0: ffff88807be2c130 (sk_lock-AF_PACKET){+.+.}-{0:0}, at: packet_do_bind+0x2f/0xe30 net/packet/af_packet.c:3204
1 lock held by dhcpcd/5621:
#0: ffff88805f706130 (sk_lock-AF_PACKET){+.+.}-{0:0}, at: lock_sock include/net/sock.h:1697 [inline]
#0: ffff88805f706130 (sk_lock-AF_PACKET){+.+.}-{0:0}, at: packet_do_bind+0x2f/0xe30 net/packet/af_packet.c:3204
1 lock held by dhcpcd/5622:
#0: ffff88807e98e130 (sk_lock-AF_PACKET){+.+.}-{0:0}, at: lock_sock include/net/sock.h:1697 [inline]
#0: ffff88807e98e130 (sk_lock-AF_PACKET){+.+.}-{0:0}, at: packet_do_bind+0x2f/0xe30 net/packet/af_packet.c:3204
2 locks held by syz-executor.5/6144:

=============================================

NMI backtrace for cpu 0
CPU: 0 PID: 28 Comm: khungtaskd Not tainted 6.3.0-syzkaller-07940-g6686317855c6 #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 04/14/2023
Call Trace:
<TASK>
__dump_stack lib/dump_stack.c:88 [inline]
dump_stack_lvl+0xd9/0x150 lib/dump_stack.c:106
nmi_cpu_backtrace+0x29c/0x350 lib/nmi_backtrace.c:113
nmi_trigger_cpumask_backtrace+0x2a4/0x300 lib/nmi_backtrace.c:62
trigger_all_cpu_backtrace include/linux/nmi.h:148 [inline]
check_hung_uninterruptible_tasks kernel/hung_task.c:222 [inline]
watchdog+0xe16/0x1090 kernel/hung_task.c:379
kthread+0x344/0x440 kernel/kthread.c:379
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:308
</TASK>
Sending NMI from CPU 0 to CPUs 1:
NMI backtrace for cpu 1
CPU: 1 PID: 6146 Comm: syz-executor.1 Not tainted 6.3.0-syzkaller-07940-g6686317855c6 #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 04/14/2023
RIP: 0010:get_page_from_freelist+0x2f5/0x2e20 mm/page_alloc.c:4281
Code: e8 03 42 80 3c 28 00 0f 85 25 1d 00 00 48 8b 04 24 4d 03 67 20 48 8d 48 1c 48 89 c8 48 89 4c 24 38 48 c1 e8 03 42 0f b6 14 28 <48> 89 c8 83 e0 07 83 c0 03 38 d0 7c 08 84 d2 0f 85 c2 1c 00 00 48
RSP: 0018:ffffc9000392f408 EFLAGS: 00000a07
RAX: 1ffff92000725ec9 RBX: 0000000000000001 RCX: ffffc9000392f64c
RDX: 0000000000000000 RSI: ffffffffffffffff RDI: ffff88813fffae08
RBP: ffff88813fffc300 R08: 0000000000000000 R09: ffff88802581b0b7
R10: ffffed1004b03616 R11: 0000000000000000 R12: 0000000000000006
R13: dffffc0000000000 R14: 0000000000000000 R15: ffff88813fffae00
FS: 00007f7b6a98a700(0000) GS:ffff8880b9900000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007f5f54fa8000 CR3: 0000000191236000 CR4: 00000000003506e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
<TASK>
__alloc_pages+0x1cb/0x4a0 mm/page_alloc.c:5592
alloc_pages+0x1aa/0x270 mm/mempolicy.c:2277
__get_free_pages+0xc/0x40 mm/page_alloc.c:5642
kasan_populate_vmalloc_pte mm/kasan/shadow.c:323 [inline]
kasan_populate_vmalloc_pte+0x2e/0x180 mm/kasan/shadow.c:314
apply_to_pte_range mm/memory.c:2578 [inline]
apply_to_pmd_range mm/memory.c:2622 [inline]
apply_to_pud_range mm/memory.c:2658 [inline]
apply_to_p4d_range mm/memory.c:2694 [inline]
__apply_to_page_range+0x68c/0x1030 mm/memory.c:2728
alloc_vmap_area+0x500/0x1e00 mm/vmalloc.c:1642
__get_vm_area_node+0x145/0x3f0 mm/vmalloc.c:2499
__vmalloc_node_range+0x252/0x14a0 mm/vmalloc.c:3165
__bpf_map_area_alloc+0xe5/0x180 kernel/bpf/syscall.c:336
bloom_map_alloc+0x303/0x560 kernel/bpf/bloom_filter.c:137
find_and_alloc_map kernel/bpf/syscall.c:135 [inline]
map_create+0x508/0x1860 kernel/bpf/syscall.c:1161
__sys_bpf+0x127f/0x5420 kernel/bpf/syscall.c:5040
__do_sys_bpf kernel/bpf/syscall.c:5162 [inline]
__se_sys_bpf kernel/bpf/syscall.c:5160 [inline]
__x64_sys_bpf+0x79/0xc0 kernel/bpf/syscall.c:5160
do_syscall_x64 arch/x86/entry/common.c:50 [inline]
do_syscall_64+0x39/0xb0 arch/x86/entry/common.c:80
entry_SYSCALL_64_after_hwframe+0x63/0xcd
RIP: 0033:0x7f7b69c8c169
Code: 28 00 00 00 75 05 48 83 c4 28 c3 e8 f1 19 00 00 90 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 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:00007f7b6a98a168 EFLAGS: 00000246 ORIG_RAX: 0000000000000141
RAX: ffffffffffffffda RBX: 00007f7b69dabf80 RCX: 00007f7b69c8c169
RDX: 0000000000000048 RSI: 0000000020000180 RDI: 0000000000000000
RBP: 00007f7b69ce7ca1 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000
R13: 00007ffd1b79d6ff R14: 00007f7b6a98a300 R15: 0000000000022000
</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.
For information about bisection process see: https://goo.gl/tpsmEJ#bisection

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

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.

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

Hillf Danton

unread,

May 4, 2023, 2:16:27 AM5/4/23

to Peter Zijlstra, syzbot, Tetsuo Handa, Linus Torvalds, linux-...@vger.kernel.org, syzkall...@googlegroups.com

On 03 May 2023 19:01:51 -0700

What is hard to understand in this report is, how could acquire the
timer base lock with the mm cid lock held [1]?

static inline int mm_cid_get(struct mm_struct *mm)
{
int ret;

lockdep_assert_irqs_disabled();
raw_spin_lock(&mm->cid_lock);
ret = __mm_cid_get(mm);
raw_spin_unlock(&mm->cid_lock);
return ret;
}

[1] https://git.kernel.org/pub/scm/linux/kernel/git/netdev/net.git/tree/kernel/sched/sched.h?id=6686317855c6#n3280

Tetsuo Handa

unread,

May 4, 2023, 3:01:26 AM5/4/23

to Hillf Danton, Peter Zijlstra, Linus Torvalds, syzbot, linux-...@vger.kernel.org, syzkall...@googlegroups.com

On 2023/05/04 15:16, Hillf Danton wrote:
>> 4 locks held by syz-executor.2/5077:
>> #0: ffff8880b993c2d8 (&rq->__lock){-.-.}-{2:2}, at: raw_spin_rq_lock_nested+0x2f/0x120 kernel/sched/core.c:539
>> #1: ffff88802296aef0 (&mm->cid_lock#2){....}-{2:2}, at: mm_cid_get kernel/sched/sched.h:3280 [inline]
>> #1: ffff88802296aef0 (&mm->cid_lock#2){....}-{2:2}, at: switch_mm_cid kernel/sched/sched.h:3302 [inline]
>> #1: ffff88802296aef0 (&mm->cid_lock#2){....}-{2:2}, at: prepare_task_switch kernel/sched/core.c:5117 [inline]
>> #1: ffff88802296aef0 (&mm->cid_lock#2){....}-{2:2}, at: context_switch kernel/sched/core.c:5258 [inline]
>> #1: ffff88802296aef0 (&mm->cid_lock#2){....}-{2:2}, at: __schedule+0x2802/0x5770 kernel/sched/core.c:6625
>> #2: ffff8880b9929698 (&base->lock){-.-.}-{2:2}, at: lock_timer_base+0x5a/0x1f0 kernel/time/timer.c:999
>> #3: ffffffff91fb4ac8 (&obj_hash[i].lock){-.-.}-{2:2}, at: debug_object_activate+0x134/0x3f0 lib/debugobjects.c:690
>
> What is hard to understand in this report is, how could acquire the
> timer base lock with the mm cid lock held [1]?

Please be aware that lockdep_print_held_locks() is not an atomic action.
Since synchronous printk() is slow, it can sometimes happen that
task_is_running(p) becomes true after passing the

if (p != current && task_is_running(p))
return;

check. I think that this trace is an example where print_lock() by chance hit
hlock_class(p->held_locks + 2) != NULL. If sched_show_task() were also available,
we can know it via mismatch between sched_show_task() and lockdep_print_held_locks().

Linus, I think that "[PATCH v3 (repost)] locking/lockdep: add debug_show_all_lock_holders()"
helps here, but I can't wake up locking people. What can we do?

Peter Zijlstra

unread,

May 5, 2023, 4:36:01 AM5/5/23

to Tetsuo Handa, Hillf Danton, Linus Torvalds, syzbot, linux-...@vger.kernel.org, syzkall...@googlegroups.com

On Thu, May 04, 2023 at 04:01:23PM +0900, Tetsuo Handa wrote:
> On 2023/05/04 15:16, Hillf Danton wrote:
> >> 4 locks held by syz-executor.2/5077:
> >> #0: ffff8880b993c2d8 (&rq->__lock){-.-.}-{2:2}, at: raw_spin_rq_lock_nested+0x2f/0x120 kernel/sched/core.c:539
> >> #1: ffff88802296aef0 (&mm->cid_lock#2){....}-{2:2}, at: mm_cid_get kernel/sched/sched.h:3280 [inline]
> >> #1: ffff88802296aef0 (&mm->cid_lock#2){....}-{2:2}, at: switch_mm_cid kernel/sched/sched.h:3302 [inline]
> >> #1: ffff88802296aef0 (&mm->cid_lock#2){....}-{2:2}, at: prepare_task_switch kernel/sched/core.c:5117 [inline]
> >> #1: ffff88802296aef0 (&mm->cid_lock#2){....}-{2:2}, at: context_switch kernel/sched/core.c:5258 [inline]
> >> #1: ffff88802296aef0 (&mm->cid_lock#2){....}-{2:2}, at: __schedule+0x2802/0x5770 kernel/sched/core.c:6625
> >> #2: ffff8880b9929698 (&base->lock){-.-.}-{2:2}, at: lock_timer_base+0x5a/0x1f0 kernel/time/timer.c:999
> >> #3: ffffffff91fb4ac8 (&obj_hash[i].lock){-.-.}-{2:2}, at: debug_object_activate+0x134/0x3f0 lib/debugobjects.c:690
> >
> > What is hard to understand in this report is, how could acquire the
> > timer base lock with the mm cid lock held [1]?
>
> Please be aware that lockdep_print_held_locks() is not an atomic action.
> Since synchronous printk() is slow, it can sometimes happen that
> task_is_running(p) becomes true after passing the
>
> if (p != current && task_is_running(p))
> return;
>
> check. I think that this trace is an example where print_lock() by chance hit
> hlock_class(p->held_locks + 2) != NULL. If sched_show_task() were also available,
> we can know it via mismatch between sched_show_task() and lockdep_print_held_locks().
>
> Linus, I think that "[PATCH v3 (repost)] locking/lockdep: add debug_show_all_lock_holders()"
> helps here, but I can't wake up locking people. What can we do?

How is that not also racy ?

I think I've seen that patch, and it had a some 'blurb' Changelog that
leaves me wondering wtf the actual problem is and how it attempts to
solve it and I went on with looking at regressions because more
important than random weird patch.

Tetsuo Handa

unread,

May 5, 2023, 5:46:05 AM5/5/23

to Peter Zijlstra, Hillf Danton, Linus Torvalds, syzbot, linux-...@vger.kernel.org, syzkall...@googlegroups.com

On 2023/05/05 17:35, Peter Zijlstra wrote:
>> Linus, I think that "[PATCH v3 (repost)] locking/lockdep: add debug_show_all_lock_holders()"
>> helps here, but I can't wake up locking people. What can we do?
>
> How is that not also racy ?

Nobody can make this code racy.

>
> I think I've seen that patch, and it had a some 'blurb' Changelog that
> leaves me wondering wtf the actual problem is and how it attempts to
> solve it and I went on with looking at regressions because more
> important than random weird patch.

Please respond to
https://lkml.kernel.org/393a440f-5f82-432c...@I-love.SAKURA.ne.jp .

Tetsuo Handa

unread,

May 5, 2023, 5:49:44 AM5/5/23

to Peter Zijlstra, Hillf Danton, Linus Torvalds, syzbot, linux-...@vger.kernel.org, syzkall...@googlegroups.com

On 2023/05/05 18:46, Tetsuo Handa wrote:
> On 2023/05/05 17:35, Peter Zijlstra wrote:
>>> Linus, I think that "[PATCH v3 (repost)] locking/lockdep: add debug_show_all_lock_holders()"
>>> helps here, but I can't wake up locking people. What can we do?
>>
>> How is that not also racy ?
>
> Nobody can make this code racy.

Oops, nobody can make this code race-free.

Capturing vmcore is not an option.

>
>>
>> I think I've seen that patch, and it had a some 'blurb' Changelog that
>> leaves me wondering wtf the actual problem is and how it attempts to
>> solve it and I went on with looking at regressions because more
>> important than random weird patch.
>
> Please respond to
> https://lkml.kernel.org/393a440f-5f82-432c...@I-love.SAKURA.ne.jp .
>

I am waiting for your response.
But since you don't respond, I have to repeat re-posting.

syzbot

unread,

May 20, 2023, 6:14:01 PM5/20/23

to amir...@gmail.com, b...@vger.kernel.org, dan...@iogearbox.net, da...@davemloft.net, edum...@google.com, hda...@sina.com, ja...@suse.cz, ka...@fb.com, ku...@kernel.org, linux-...@vger.kernel.org, linux-...@vger.kernel.org, net...@vger.kernel.org, pab...@redhat.com, penguin...@i-love.sakura.ne.jp, pet...@infradead.org, syzkall...@googlegroups.com, torv...@linux-foundation.org, willemdebr...@gmail.com

syzbot has found a reproducer for the following issue on:

HEAD commit: dcbe4ea1985d Merge branch '1GbE' of git://git.kernel.org/p..
git tree: net-next
console output: https://syzkaller.appspot.com/x/log.txt?x=123ebd91280000
kernel config: https://syzkaller.appspot.com/x/.config?x=f20b05fe035db814

dashboard link: https://syzkaller.appspot.com/bug?extid=222aa26d0a5dbc2e84fe
compiler: gcc (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2

syz repro: https://syzkaller.appspot.com/x/repro.syz?x=1495596a280000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=1529326a280000

Downloadable assets:
disk image: https://storage.googleapis.com/syzbot-assets/41b9dda0e686/disk-dcbe4ea1.raw.xz
vmlinux: https://storage.googleapis.com/syzbot-assets/64d9bece8f89/vmlinux-dcbe4ea1.xz
kernel image: https://storage.googleapis.com/syzbot-assets/42429896dca0/bzImage-dcbe4ea1.xz

The issue was bisected to:

commit 3b5d4ddf8fe1f60082513f94bae586ac80188a03
Author: Martin KaFai Lau <ka...@fb.com>
Date: Wed Mar 9 09:04:50 2022 +0000

bpf: net: Remove TC_AT_INGRESS_OFFSET and SKB_MONO_DELIVERY_TIME_OFFSET macro

bisection log: https://syzkaller.appspot.com/x/bisect.txt?x=153459d7c80000
final oops: https://syzkaller.appspot.com/x/report.txt?x=173459d7c80000
console output: https://syzkaller.appspot.com/x/log.txt?x=133459d7c80000

IMPORTANT: if you fix the issue, please add the following tag to the commit:
Reported-by: syzbot+222aa2...@syzkaller.appspotmail.com
Fixes: 3b5d4ddf8fe1 ("bpf: net: Remove TC_AT_INGRESS_OFFSET and SKB_MONO_DELIVERY_TIME_OFFSET macro")

INFO: task dhcpcd:10860 blocked for more than 143 seconds.
Not tainted 6.4.0-rc2-syzkaller-00481-gdcbe4ea1985d #0

"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

task:dhcpcd state:D stack:29024 pid:10860 ppid:4670 flags:0x00000002
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5343 [inline]
__schedule+0xc9a/0x5880 kernel/sched/core.c:6669
schedule+0xde/0x1a0 kernel/sched/core.c:6745
exp_funnel_lock kernel/rcu/tree_exp.h:316 [inline]
synchronize_rcu_expedited+0x6f8/0x770 kernel/rcu/tree_exp.h:992
synchronize_rcu+0x2f1/0x3a0 kernel/rcu/tree.c:3499
synchronize_net+0x4e/0x60 net/core/dev.c:10791
__unregister_prot_hook+0x4b3/0x5c0 net/packet/af_packet.c:380
packet_do_bind+0x93f/0xe30 net/packet/af_packet.c:3235
packet_bind+0x15f/0x1c0 net/packet/af_packet.c:3319
__sys_bind+0x1ed/0x260 net/socket.c:1803
__do_sys_bind net/socket.c:1814 [inline]
__se_sys_bind net/socket.c:1812 [inline]
__x64_sys_bind+0x73/0xb0 net/socket.c:1812

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

RIP: 0033:0x7f522deb3677
RSP: 002b:00007ffec7fc94f8 EFLAGS: 00000217 ORIG_RAX: 0000000000000031
RAX: ffffffffffffffda RBX: 000055e71e865ca3 RCX: 00007f522deb3677
RDX: 0000000000000014 RSI: 00007ffec7fc9508 RDI: 0000000000000005
RBP: 0000000000000000 R08: 000055e7200048a0 R09: 0000000000000004
R10: 000000000000006d R11: 0000000000000217 R12: 000055e71ffff250
R13: 000055e720004788 R14: 00007ffec7fe9dec R15: 000055e720004754
</TASK>
INFO: task dhcpcd:10906 blocked for more than 145 seconds.
Not tainted 6.4.0-rc2-syzkaller-00481-gdcbe4ea1985d #0

"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

task:dhcpcd state:D stack:28864 pid:10906 ppid:4670 flags:0x00000002
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5343 [inline]
__schedule+0xc9a/0x5880 kernel/sched/core.c:6669
schedule+0xde/0x1a0 kernel/sched/core.c:6745
exp_funnel_lock kernel/rcu/tree_exp.h:316 [inline]
synchronize_rcu_expedited+0x6f8/0x770 kernel/rcu/tree_exp.h:992
synchronize_rcu+0x2f1/0x3a0 kernel/rcu/tree.c:3499
synchronize_net+0x4e/0x60 net/core/dev.c:10791
__unregister_prot_hook+0x4b3/0x5c0 net/packet/af_packet.c:380
packet_do_bind+0x93f/0xe30 net/packet/af_packet.c:3235
packet_bind+0x15f/0x1c0 net/packet/af_packet.c:3319
__sys_bind+0x1ed/0x260 net/socket.c:1803
__do_sys_bind net/socket.c:1814 [inline]
__se_sys_bind net/socket.c:1812 [inline]
__x64_sys_bind+0x73/0xb0 net/socket.c:1812

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

RIP: 0033:0x7f522deb3677
RSP: 002b:00007ffec7fc94f8 EFLAGS: 00000217 ORIG_RAX: 0000000000000031
RAX: ffffffffffffffda RBX: 000055e71e865ca3 RCX: 00007f522deb3677
RDX: 0000000000000014 RSI: 00007ffec7fc9508 RDI: 0000000000000005
RBP: 0000000000000000 R08: 000055e720004a20 R09: 0000000000000004
R10: 000000000000006d R11: 0000000000000217 R12: 000055e71ffff250
R13: 000055e720004908 R14: 00007ffec7fe9dec R15: 000055e7200048d4
</TASK>
INFO: task dhcpcd:11298 blocked for more than 147 seconds.
Not tainted 6.4.0-rc2-syzkaller-00481-gdcbe4ea1985d #0

"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

task:dhcpcd state:D stack:29008 pid:11298 ppid:4670 flags:0x00000002
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5343 [inline]
__schedule+0xc9a/0x5880 kernel/sched/core.c:6669
schedule+0xde/0x1a0 kernel/sched/core.c:6745
exp_funnel_lock kernel/rcu/tree_exp.h:316 [inline]
synchronize_rcu_expedited+0x6f8/0x770 kernel/rcu/tree_exp.h:992
synchronize_rcu+0x2f1/0x3a0 kernel/rcu/tree.c:3499
synchronize_net+0x4e/0x60 net/core/dev.c:10791
__unregister_prot_hook+0x4b3/0x5c0 net/packet/af_packet.c:380
packet_do_bind+0x93f/0xe30 net/packet/af_packet.c:3235
packet_bind+0x15f/0x1c0 net/packet/af_packet.c:3319
__sys_bind+0x1ed/0x260 net/socket.c:1803
__do_sys_bind net/socket.c:1814 [inline]
__se_sys_bind net/socket.c:1812 [inline]
__x64_sys_bind+0x73/0xb0 net/socket.c:1812

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

RIP: 0033:0x7f522deb3677
RSP: 002b:00007ffec7fc94f8 EFLAGS: 00000217
ORIG_RAX: 0000000000000031
RAX: ffffffffffffffda RBX: 000055e71e865ca3 RCX: 00007f522deb3677
RDX: 0000000000000014 RSI: 00007ffec7fc9508 RDI: 0000000000000005
RBP: 0000000000000000 R08: 000055e720004420 R09: 0000000000000004
R10: 000000000000006d R11: 0000000000000217 R12: 000055e71ffff250
R13: 000055e720004a88 R14: 00007ffec7fe9dec R15: 000055e720004a54
</TASK>
INFO: task dhcpcd:11328 blocked for more than 149 seconds.
Not tainted 6.4.0-rc2-syzkaller-00481-gdcbe4ea1985d #0

"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

task:dhcpcd state:D stack:28320 pid:11328 ppid:4670 flags:0x00000002
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5343 [inline]
__schedule+0xc9a/0x5880 kernel/sched/core.c:6669
schedule+0xde/0x1a0 kernel/sched/core.c:6745
exp_funnel_lock kernel/rcu/tree_exp.h:316 [inline]
synchronize_rcu_expedited+0x6f8/0x770 kernel/rcu/tree_exp.h:992
synchronize_rcu+0x2f1/0x3a0 kernel/rcu/tree.c:3499
synchronize_net+0x4e/0x60 net/core/dev.c:10791
__unregister_prot_hook+0x4b3/0x5c0 net/packet/af_packet.c:380
packet_do_bind+0x93f/0xe30 net/packet/af_packet.c:3235
packet_bind+0x15f/0x1c0 net/packet/af_packet.c:3319
__sys_bind+0x1ed/0x260 net/socket.c:1803
__do_sys_bind net/socket.c:1814 [inline]
__se_sys_bind net/socket.c:1812 [inline]
__x64_sys_bind+0x73/0xb0 net/socket.c:1812

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

RIP: 0033:0x7f522deb3677
RSP: 002b:00007ffec7fc94f8 EFLAGS: 00000217 ORIG_RAX: 0000000000000031
RAX: ffffffffffffffda RBX: 000055e71e865ca3 RCX: 00007f522deb3677
RDX: 0000000000000014 RSI: 00007ffec7fc9508 RDI: 0000000000000005
RBP: 0000000000000000 R08: 000055e720004420 R09: 0000000000000004
R10: 000000000000006d R11: 0000000000000217 R12: 000055e71ffff250
R13: 000055e720004c08 R14: 00007ffec7fe9dec R15: 000055e720004bd4

</TASK>

Showing all locks held in the system:

1 lock held by rcu_tasks_kthre/13:

#0: ffffffff8c798430 (rcu_tasks.tasks_gp_mutex){+.+.}-{3:3}, at: rcu_tasks_one_gp+0x31/0xd80 kernel/rcu/tasks.h:518

1 lock held by rcu_tasks_trace/14:

#0: ffffffff8c798130 (rcu_tasks_trace.tasks_gp_mutex){+.+.}-{3:3}, at: rcu_tasks_one_gp+0x31/0xd80 kernel/rcu/tasks.h:518

1 lock held by khungtaskd/28:

#0: ffffffff8c799040 (rcu_read_lock){....}-{1:2}, at: debug_show_all_locks+0x55/0x340 kernel/locking/lockdep.c:6545
1 lock held by kswapd0/84:
2 locks held by kswapd1/85:
3 locks held by kworker/0:2/760:
3 locks held by kworker/1:2/1126:
1 lock held by syslogd/4438:
2 locks held by klogd/4445:
1 lock held by dhcpcd/4669:
2 locks held by getty/4756:
#0: ffff8880286bf098 (&tty->ldisc_sem){++++}-{0:0}, at: tty_ldisc_ref_wait+0x26/0x80 drivers/tty/tty_ldisc.c:243
#1: ffffc900015902f0 (&ldata->atomic_read_lock){+.+.}-{3:3}, at: n_tty_read+0xef4/0x13e0 drivers/tty/n_tty.c:2176
2 locks held by sshd/5018:
2 locks held by syz-executor300/5025:
2 locks held by dhcpcd/10797:
#0: ffff8880734ebe10 (&sb->s_type->i_mutex_key#10){+.+.}-{3:3}, at: inode_lock include/linux/fs.h:775 [inline]
#0: ffff8880734ebe10 (&sb->s_type->i_mutex_key#10){+.+.}-{3:3}, at: __sock_release+0x86/0x290 net/socket.c:652
#1: ffffffff8c7a44b8 (rcu_state.exp_mutex){+.+.}-{3:3}, at: exp_funnel_lock kernel/rcu/tree_exp.h:325 [inline]
#1: ffffffff8c7a44b8 (rcu_state.exp_mutex){+.+.}-{3:3}, at: synchronize_rcu_expedited+0x3e8/0x770 kernel/rcu/tree_exp.h:992
2 locks held by dhcpcd/10818:
#0: ffff8880217f2130 (sk_lock-AF_PACKET){+.+.}-{0:0}, at: lock_sock include/net/sock.h:1697 [inline]
#0: ffff8880217f2130 (sk_lock-AF_PACKET){+.+.}-{0:0}, at: packet_do_bind+0x2f/0xe30 net/packet/af_packet.c:3202
#1: ffffffff8c7a44b8 (rcu_state.exp_mutex){+.+.}-{3:3}, at: exp_funnel_lock kernel/rcu/tree_exp.h:325 [inline]
#1: ffffffff8c7a44b8 (rcu_state.exp_mutex){+.+.}-{3:3}, at: synchronize_rcu_expedited+0x3e8/0x770 kernel/rcu/tree_exp.h:992
1 lock held by dhcpcd/10860:
#0: ffff88807b95c130 (sk_lock-AF_PACKET){+.+.}-{0:0}, at: lock_sock include/net/sock.h:1697 [inline]
#0: ffff88807b95c130 (sk_lock-AF_PACKET){+.+.}-{0:0}, at: packet_do_bind+0x2f/0xe30 net/packet/af_packet.c:3202
1 lock held by dhcpcd/10906:
#0: ffff888076080130 (sk_lock-AF_PACKET){+.+.}-{0:0}, at: lock_sock include/net/sock.h:1697 [inline]
#0: ffff888076080130 (sk_lock-AF_PACKET){+.+.}-{0:0}, at: packet_do_bind+0x2f/0xe30 net/packet/af_packet.c:3202
1 lock held by dhcpcd/11298:
#0: ffff888027a66130 (sk_lock-AF_PACKET){+.+.}-{0:0}, at: lock_sock include/net/sock.h:1697 [inline]
#0: ffff888027a66130 (sk_lock-AF_PACKET){+.+.}-{0:0}, at: packet_do_bind+0x2f/0xe30 net/packet/af_packet.c:3202

---

Martin KaFai Lau

unread,

May 20, 2023, 10:26:32 PM5/20/23

to syzbot, syzkall...@googlegroups.com, amir...@gmail.com, b...@vger.kernel.org, dan...@iogearbox.net, da...@davemloft.net, edum...@google.com, hda...@sina.com, ja...@suse.cz, ku...@kernel.org, linux-...@vger.kernel.org, linux-...@vger.kernel.org, net...@vger.kernel.org, pab...@redhat.com, penguin...@i-love.sakura.ne.jp, pet...@infradead.org, torv...@linux-foundation.org, willemdebr...@gmail.com

On 5/20/23 3:13 PM, syzbot wrote:
> syzbot has found a reproducer for the following issue on:
>
> HEAD commit: dcbe4ea1985d Merge branch '1GbE' of git://git.kernel.org/p..
> git tree: net-next
> console output: https://syzkaller.appspot.com/x/log.txt?x=123ebd91280000
> kernel config: https://syzkaller.appspot.com/x/.config?x=f20b05fe035db814
> dashboard link: https://syzkaller.appspot.com/bug?extid=222aa26d0a5dbc2e84fe
> compiler: gcc (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2
> syz repro: https://syzkaller.appspot.com/x/repro.syz?x=1495596a280000
> C reproducer: https://syzkaller.appspot.com/x/repro.c?x=1529326a280000
>
> Downloadable assets:
> disk image: https://storage.googleapis.com/syzbot-assets/41b9dda0e686/disk-dcbe4ea1.raw.xz
> vmlinux: https://storage.googleapis.com/syzbot-assets/64d9bece8f89/vmlinux-dcbe4ea1.xz
> kernel image: https://storage.googleapis.com/syzbot-assets/42429896dca0/bzImage-dcbe4ea1.xz
>
> The issue was bisected to:
>
> commit 3b5d4ddf8fe1f60082513f94bae586ac80188a03
> Author: Martin KaFai Lau <ka...@fb.com>
> Date: Wed Mar 9 09:04:50 2022 +0000
>
> bpf: net: Remove TC_AT_INGRESS_OFFSET and SKB_MONO_DELIVERY_TIME_OFFSET macro

I am afraid this bisect is incorrect. The commit removed a redundant macro and
is a no-op change.

Tetsuo Handa

unread,

May 21, 2023, 1:04:18 AM5/21/23

to Martin KaFai Lau, syzbot, syzkall...@googlegroups.com, amir...@gmail.com, b...@vger.kernel.org, dan...@iogearbox.net, da...@davemloft.net, edum...@google.com, hda...@sina.com, ja...@suse.cz, ku...@kernel.org, linux-...@vger.kernel.org, linux-...@vger.kernel.org, net...@vger.kernel.org, pab...@redhat.com, pet...@infradead.org, torv...@linux-foundation.org, willemdebr...@gmail.com

But the reproducer is heavily calling bpf() syscall.

void execute_call(int call)
{
switch (call) {
case 0:
NONFAILING(*(uint32_t*)0x200027c0 = 3);
NONFAILING(*(uint32_t*)0x200027c4 = 4);
NONFAILING(*(uint32_t*)0x200027c8 = 4);
NONFAILING(*(uint32_t*)0x200027cc = 0x10001);
NONFAILING(*(uint32_t*)0x200027d0 = 0);
NONFAILING(*(uint32_t*)0x200027d4 = -1);
NONFAILING(*(uint32_t*)0x200027d8 = 0);
NONFAILING(memset((void*)0x200027dc, 0, 16));
NONFAILING(*(uint32_t*)0x200027ec = 0);
NONFAILING(*(uint32_t*)0x200027f0 = -1);
NONFAILING(*(uint32_t*)0x200027f4 = 0);
NONFAILING(*(uint32_t*)0x200027f8 = 0);
NONFAILING(*(uint32_t*)0x200027fc = 0);
NONFAILING(*(uint64_t*)0x20002800 = 0);
syscall(__NR_bpf, 0ul, 0x200027c0ul, 0x48ul);
break;
}
}

Something caused infinite loop or too heavy stress to survive?
The first report was 7d31677bb7b1.
Rechecking or running the reproducer on commits shown by
"git log 7d31677bb7b1 net/bpf" might help.

syzbot

unread,

May 23, 2023, 9:13:40 AM5/23/23

to penguin...@i-love.sakura.ne.jp, penguin...@i-love.sakura.ne.jp, syzkall...@googlegroups.com

> #syz test: git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git master

Your commands are accepted, but please keep syzkall...@googlegroups.com mailing list in CC next time. It serves as a history of what happened with each bug report. Thank you.

>
> diff --git a/include/linux/debug_locks.h b/include/linux/debug_locks.h
> index dbb409d77d4f..0567d5ce5b4a 100644
> --- a/include/linux/debug_locks.h
> +++ b/include/linux/debug_locks.h
> @@ -50,6 +50,7 @@ extern int debug_locks_off(void);
> #ifdef CONFIG_LOCKDEP
> extern void debug_show_all_locks(void);
> extern void debug_show_held_locks(struct task_struct *task);
> +extern void debug_show_all_lock_holders(void);
> extern void debug_check_no_locks_freed(const void *from, unsigned long len);
> extern void debug_check_no_locks_held(void);
> #else
> @@ -61,6 +62,10 @@ static inline void debug_show_held_locks(struct task_struct *task)
> {
> }
>
> +static inline void debug_show_all_lock_holders(void)
> +{
> +}
> +
> static inline void
> debug_check_no_locks_freed(const void *from, unsigned long len)
> {
> diff --git a/kernel/hung_task.c b/kernel/hung_task.c
> index 9a24574988d2..3dfb6ed3e981 100644
> --- a/kernel/hung_task.c
> +++ b/kernel/hung_task.c
> @@ -215,7 +215,7 @@ static void check_hung_uninterruptible_tasks(unsigned long timeout)
> unlock:
> rcu_read_unlock();
> if (hung_task_show_lock)
> - debug_show_all_locks();
> + debug_show_all_lock_holders();
>
> if (hung_task_show_all_bt) {
> hung_task_show_all_bt = false;
> diff --git a/kernel/locking/lockdep.c b/kernel/locking/lockdep.c
> index dcd1d5bfc1e0..0d98ba19b214 100644
> --- a/kernel/locking/lockdep.c
> +++ b/kernel/locking/lockdep.c
> @@ -32,6 +32,7 @@
> #include <linux/sched/clock.h>
> #include <linux/sched/task.h>
> #include <linux/sched/mm.h>
> +#include <linux/sched/debug.h>
> #include <linux/delay.h>
> #include <linux/module.h>
> #include <linux/proc_fs.h>
> @@ -6562,6 +6563,33 @@ void debug_show_all_locks(void)
> pr_warn("=============================================\n\n");
> }
> EXPORT_SYMBOL_GPL(debug_show_all_locks);
> +
> +void debug_show_all_lock_holders(void)
> +{
> + struct task_struct *g, *p;
> +
> + if (unlikely(!debug_locks)) {
> + pr_warn("INFO: lockdep is turned off.\n");
> + return;
> + }
> + pr_warn("\nShowing all threads with locks held in the system:\n");
> +
> + rcu_read_lock();
> + for_each_process_thread(g, p) {
> + if (!p->lockdep_depth)
> + continue;
> + if (p == current && p->lockdep_depth == 1)
> + continue;
> + sched_show_task(p);
> + lockdep_print_held_locks(p);
> + touch_nmi_watchdog();
> + touch_all_softlockup_watchdogs();
> + }
> + rcu_read_unlock();
> +
> + pr_warn("\n");
> + pr_warn("=============================================\n\n");
> +}
> #endif
>
> /*
>

syzbot

unread,

May 23, 2023, 9:35:31 AM5/23/23

to penguin...@i-love.sakura.ne.jp, syzkall...@googlegroups.com

Hello,

syzbot tried to test the proposed patch but the build/boot failed:

failed to copy binary to VM: failed to run ["scp" "-P" "22" "-F" "/dev/null" "-o" "UserKnownHostsFile=/dev/null" "-o" "BatchMode=yes" "-o" "IdentitiesOnly=yes" "-o" "StrictHostKeyChecking=no" "-o" "ConnectTimeout=10" "-v" "/tmp/syz-executor710392664" "ro...@10.128.0.167:./syz-executor710392664"]: exit status 1
Executing: program /usr/bin/ssh host 10.128.0.167, user root, command scp -v -t ./syz-executor710392664
OpenSSH_8.4p1 Debian-5+deb11u1, OpenSSL 1.1.1n 15 Mar 2022
debug1: Reading configuration data /dev/null
debug1: Connecting to 10.128.0.167 [10.128.0.167] port 22.
debug1: fd 3 clearing O_NONBLOCK
debug1: Connection established.
debug1: identity file /root/.ssh/id_rsa type -1
debug1: identity file /root/.ssh/id_rsa-cert type -1
debug1: identity file /root/.ssh/id_dsa type -1
debug1: identity file /root/.ssh/id_dsa-cert type -1
debug1: identity file /root/.ssh/id_ecdsa type -1
debug1: identity file /root/.ssh/id_ecdsa-cert type -1
debug1: identity file /root/.ssh/id_ecdsa_sk type -1
debug1: identity file /root/.ssh/id_ecdsa_sk-cert type -1
debug1: identity file /root/.ssh/id_ed25519 type -1
debug1: identity file /root/.ssh/id_ed25519-cert type -1
debug1: identity file /root/.ssh/id_ed25519_sk type -1
debug1: identity file /root/.ssh/id_ed25519_sk-cert type -1
debug1: identity file /root/.ssh/id_xmss type -1
debug1: identity file /root/.ssh/id_xmss-cert type -1
debug1: Local version string SSH-2.0-OpenSSH_8.4p1 Debian-5+deb11u1
Connection timed out during banner exchange
Connection to 10.128.0.167 port 22 timed out
lost connection

syzkaller build log:
go env (err=<nil>)
GO111MODULE="auto"
GOARCH="amd64"
GOBIN=""
GOCACHE="/syzkaller/.cache/go-build"
GOENV="/syzkaller/.config/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/syzkaller/jobs-2/linux/gopath/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/syzkaller/jobs-2/linux/gopath"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
GOVCS=""
GOVERSION="go1.20.1"
GCCGO="gccgo"
GOAMD64="v1"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/syzkaller/jobs-2/linux/gopath/src/github.com/google/syzkaller/go.mod"
GOWORK=""
CGO_CFLAGS="-O2 -g"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-O2 -g"
CGO_FFLAGS="-O2 -g"
CGO_LDFLAGS="-O2 -g"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -Wl,--no-gc-sections -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build1254287027=/tmp/go-build -gno-record-gcc-switches"

git status (err=<nil>)
HEAD detached at 4bce1a3e7
nothing to commit, working tree clean

tput: No value for $TERM and no -T specified
tput: No value for $TERM and no -T specified
Makefile:32: run command via tools/syz-env for best compatibility, see:
Makefile:33: https://github.com/google/syzkaller/blob/master/docs/contributing.md#using-syz-env
go list -f '{{.Stale}}' ./sys/syz-sysgen | grep -q false || go install ./sys/syz-sysgen
make .descriptions
tput: No value for $TERM and no -T specified
tput: No value for $TERM and no -T specified
bin/syz-sysgen
touch .descriptions
GOOS=linux GOARCH=amd64 go build "-ldflags=-s -w -X github.com/google/syzkaller/prog.GitRevision=4bce1a3e705a8b62de8194bdb28f5eef89c8feec -X 'github.com/google/syzkaller/prog.gitRevisionDate=20230520-095734'" "-tags=syz_target syz_os_linux syz_arch_amd64 " -o ./bin/linux_amd64/syz-fuzzer github.com/google/syzkaller/syz-fuzzer
GOOS=linux GOARCH=amd64 go build "-ldflags=-s -w -X github.com/google/syzkaller/prog.GitRevision=4bce1a3e705a8b62de8194bdb28f5eef89c8feec -X 'github.com/google/syzkaller/prog.gitRevisionDate=20230520-095734'" "-tags=syz_target syz_os_linux syz_arch_amd64 " -o ./bin/linux_amd64/syz-execprog github.com/google/syzkaller/tools/syz-execprog
GOOS=linux GOARCH=amd64 go build "-ldflags=-s -w -X github.com/google/syzkaller/prog.GitRevision=4bce1a3e705a8b62de8194bdb28f5eef89c8feec -X 'github.com/google/syzkaller/prog.gitRevisionDate=20230520-095734'" "-tags=syz_target syz_os_linux syz_arch_amd64 " -o ./bin/linux_amd64/syz-stress github.com/google/syzkaller/tools/syz-stress
mkdir -p ./bin/linux_amd64
gcc -o ./bin/linux_amd64/syz-executor executor/executor.cc \
-m64 -O2 -pthread -Wall -Werror -Wparentheses -Wunused-const-variable -Wframe-larger-than=16384 -Wno-stringop-overflow -Wno-array-bounds -Wno-format-overflow -Wno-unused-but-set-variable -Wno-unused-command-line-argument -static-pie -fpermissive -w -DGOOS_linux=1 -DGOARCH_amd64=1 \
-DHOSTGOOS_linux=1 -DGIT_REVISION=\"4bce1a3e705a8b62de8194bdb28f5eef89c8feec\"

Tested on:

commit: ae8373a5 Merge tag 'x86_urgent_for_6.4-rc4' of git://g..
git tree: upstream
kernel config: https://syzkaller.appspot.com/x/.config?x=f389ffdf4e9ba3f0

dashboard link: https://syzkaller.appspot.com/bug?extid=222aa26d0a5dbc2e84fe
compiler: gcc (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2

patch: https://syzkaller.appspot.com/x/patch.diff?x=12365819280000

Tetsuo Handa

unread,

May 23, 2023, 10:02:14 PM5/23/23

to syzbot, syzkaller-bugs

#syz test: git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git master

syzbot

unread,

May 23, 2023, 10:39:21 PM5/23/23

to penguin...@i-love.sakura.ne.jp, syzkall...@googlegroups.com

Hello,

syzbot has tested the proposed patch but the reproducer is still triggering an issue:
INFO: task hung in synchronize_rcu

INFO: task kworker/u4:2:33 blocked for more than 143 seconds.
Not tainted 6.4.0-rc3-syzkaller-g27e462c8fad4-dirty #0

"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

task:kworker/u4:2 state:D stack:26360 pid:33 ppid:2 flags:0x00004000
Workqueue: events_unbound fsnotify_connector_destroy_workfn

Call Trace:
<TASK>
context_switch kernel/sched/core.c:5343 [inline]
__schedule+0xc9a/0x5880 kernel/sched/core.c:6669
schedule+0xde/0x1a0 kernel/sched/core.c:6745

schedule_timeout+0x276/0x2b0 kernel/time/timer.c:2143
do_wait_for_common kernel/sched/completion.c:85 [inline]
__wait_for_common+0x1ce/0x5c0 kernel/sched/completion.c:106
__synchronize_srcu+0x1be/0x2c0 kernel/rcu/srcutree.c:1360
fsnotify_connector_destroy_workfn+0x4d/0xa0 fs/notify/mark.c:208

process_one_work+0x99a/0x15e0 kernel/workqueue.c:2405
process_scheduled_works kernel/workqueue.c:2468 [inline]
worker_thread+0x881/0x10c0 kernel/workqueue.c:2554

kthread+0x344/0x440 kernel/kthread.c:379
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:308
</TASK>

INFO: task kworker/u4:4:75 blocked for more than 144 seconds.
Not tainted 6.4.0-rc3-syzkaller-g27e462c8fad4-dirty #0

"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

task:kworker/u4:4 state:D stack:26464 pid:75 ppid:2 flags:0x00004000
Workqueue: events_unbound fsnotify_mark_destroy_workfn

Call Trace:
<TASK>
context_switch kernel/sched/core.c:5343 [inline]
__schedule+0xc9a/0x5880 kernel/sched/core.c:6669
schedule+0xde/0x1a0 kernel/sched/core.c:6745

schedule_timeout+0x276/0x2b0 kernel/time/timer.c:2143
do_wait_for_common kernel/sched/completion.c:85 [inline]
__wait_for_common+0x1ce/0x5c0 kernel/sched/completion.c:106
__synchronize_srcu+0x1be/0x2c0 kernel/rcu/srcutree.c:1360
fsnotify_mark_destroy_workfn+0x101/0x3c0 fs/notify/mark.c:898

process_one_work+0x99a/0x15e0 kernel/workqueue.c:2405
process_scheduled_works kernel/workqueue.c:2468 [inline]
worker_thread+0x881/0x10c0 kernel/workqueue.c:2554

kthread+0x344/0x440 kernel/kthread.c:379
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:308
</TASK>

Showing all threads with locks held in the system:

task:rcu_tasks_kthre state:I stack:29024 pid:13 ppid:2 flags:0x00004000

Call Trace:
<TASK>
context_switch kernel/sched/core.c:5343 [inline]
__schedule+0xc9a/0x5880 kernel/sched/core.c:6669
schedule+0xde/0x1a0 kernel/sched/core.c:6745

rcu_tasks_one_gp+0x489/0xd80 kernel/rcu/tasks.h:525
rcu_tasks_kthread+0x84/0xb0 kernel/rcu/tasks.h:563

kthread+0x344/0x440 kernel/kthread.c:379
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:308
</TASK>

1 lock held by rcu_tasks_kthre/13:
#0:

ffffffff8c7984f0
(

rcu_tasks.tasks_gp_mutex){+.+.}-{3:3}, at: rcu_tasks_one_gp+0x31/0xd80 kernel/rcu/tasks.h:518

task:rcu_tasks_trace state:I stack:29128 pid:14 ppid:2 flags:0x00004000

Call Trace:
<TASK>
context_switch kernel/sched/core.c:5343 [inline]
__schedule+0xc9a/0x5880 kernel/sched/core.c:6669
schedule+0xde/0x1a0 kernel/sched/core.c:6745

rcu_tasks_one_gp+0x489/0xd80 kernel/rcu/tasks.h:525
rcu_tasks_kthread+0x84/0xb0 kernel/rcu/tasks.h:563

kthread+0x344/0x440 kernel/kthread.c:379
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:308
</TASK>

1 lock held by rcu_tasks_trace/14:

#0: ffffffff8c7981f0 (rcu_tasks_trace.tasks_gp_mutex){+.+.}-{3:3}, at: rcu_tasks_one_gp+0x31/0xd80 kernel/rcu/tasks.h:518
task:kworker/u4:2 state:D stack:26360 pid:33 ppid:2 flags:0x00004000
Workqueue: events_unbound fsnotify_connector_destroy_workfn

Call Trace:
<TASK>
context_switch kernel/sched/core.c:5343 [inline]
__schedule+0xc9a/0x5880 kernel/sched/core.c:6669
schedule+0xde/0x1a0 kernel/sched/core.c:6745

process_one_work+0x99a/0x15e0 kernel/workqueue.c:2405
process_scheduled_works kernel/workqueue.c:2468 [inline]
worker_thread+0x881/0x10c0 kernel/workqueue.c:2554

kthread+0x344/0x440 kernel/kthread.c:379
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:308
</TASK>

2 locks held by kworker/u4:2/33:

#0: ffff888012479138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: set_work_data kernel/workqueue.c:643 [inline]
#0: ffff888012479138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: set_work_pool_and_clear_pending kernel/workqueue.c:670 [inline]
#0: ffff888012479138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: process_one_work+0x883/0x15e0 kernel/workqueue.c:2376
#1: ffffc90000a9fdb0 (connector_reaper_work){+.+.}-{0:0}, at: process_one_work+0x8b7/0x15e0 kernel/workqueue.c:2380
task:khugepaged state:D stack:29048 pid:35 ppid:2 flags:0x00004000

Call Trace:
<TASK>
context_switch kernel/sched/core.c:5343 [inline]
__schedule+0xc9a/0x5880 kernel/sched/core.c:6669
schedule+0xde/0x1a0 kernel/sched/core.c:6745

schedule_timeout+0x276/0x2b0 kernel/time/timer.c:2143
do_wait_for_common kernel/sched/completion.c:85 [inline]
__wait_for_common+0x1ce/0x5c0 kernel/sched/completion.c:106

__flush_work+0x595/0xb60 kernel/workqueue.c:3189
__lru_add_drain_all+0x1bf/0x6a0 mm/swap.c:897
khugepaged_do_scan mm/khugepaged.c:2599 [inline]
khugepaged+0x105/0x1740 mm/khugepaged.c:2668

kthread+0x344/0x440 kernel/kthread.c:379
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:308
</TASK>

1 lock held by khugepaged/35:
#0: ffffffff8c89a5c8 (lock#3){+.+.}-{3:3}, at: __lru_add_drain_all+0x62/0x6a0 mm/swap.c:852
task:kworker/u4:4 state:D stack:26464 pid:75 ppid:2 flags:0x00004000
Workqueue: events_unbound fsnotify_mark_destroy_workfn

Call Trace:
<TASK>
context_switch kernel/sched/core.c:5343 [inline]
__schedule+0xc9a/0x5880 kernel/sched/core.c:6669
schedule+0xde/0x1a0 kernel/sched/core.c:6745

schedule_timeout+0x276/0x2b0 kernel/time/timer.c:2143
do_wait_for_common kernel/sched/completion.c:85 [inline]
__wait_for_common+0x1ce/0x5c0 kernel/sched/completion.c:106
__synchronize_srcu+0x1be/0x2c0 kernel/rcu/srcutree.c:1360
fsnotify_mark_destroy_workfn+0x101/0x3c0 fs/notify/mark.c:898

process_one_work+0x99a/0x15e0 kernel/workqueue.c:2405
process_scheduled_works kernel/workqueue.c:2468 [inline]
worker_thread+0x881/0x10c0 kernel/workqueue.c:2554

kthread+0x344/0x440 kernel/kthread.c:379
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:308
</TASK>

2 locks held by kworker/u4:4/75:

#0: ffff888012479138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: set_work_data kernel/workqueue.c:643 [inline]
#0: ffff888012479138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: set_work_pool_and_clear_pending kernel/workqueue.c:670 [inline]
#0: ffff888012479138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: process_one_work+0x883/0x15e0 kernel/workqueue.c:2376
#1: ffffc900015a7db0 ((reaper_work).work){+.+.}-{0:0}, at: process_one_work+0x8b7/0x15e0 kernel/workqueue.c:2380
task:getty state:S stack:23320 pid:4760 ppid:1 flags:0x00000002

Call Trace:
<TASK>
context_switch kernel/sched/core.c:5343 [inline]
__schedule+0xc9a/0x5880 kernel/sched/core.c:6669
schedule+0xde/0x1a0 kernel/sched/core.c:6745

schedule_timeout+0x276/0x2b0 kernel/time/timer.c:2143
wait_woken+0x197/0x200 kernel/sched/wait.c:463
n_tty_read+0x1055/0x13e0 drivers/tty/n_tty.c:2242
iterate_tty_read drivers/tty/tty_io.c:852 [inline]
tty_read+0x30e/0x610 drivers/tty/tty_io.c:927
call_read_iter include/linux/fs.h:1862 [inline]
new_sync_read fs/read_write.c:389 [inline]
vfs_read+0x4b1/0x8a0 fs/read_write.c:470
ksys_read+0x12b/0x250 fs/read_write.c:613

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

RIP: 0033:0x7f93674a5b6a
RSP: 002b:00007ffdec0af4a8 EFLAGS: 00000246 ORIG_RAX: 0000000000000000
RAX: ffffffffffffffda RBX: 00005588fb7d8910 RCX: 00007f93674a5b6a
RDX: 0000000000000001 RSI: 00007ffdec0af4c0 RDI: 0000000000000000
RBP: 00005588fb7d8970 R08: 0000000000000000 R09: 2758553aedef1ca6
R10: 0000000000000010 R11: 0000000000000246 R12: 00005588fb7d89ac
R13: 00007ffdec0af4c0 R14: 0000000000000000 R15: 00005588fb7d89ac
</TASK>
2 locks held by getty/4760:
#0: ffff88802c909098 (&tty->ldisc_sem){++++}-{0:0}, at: tty_ldisc_ref_wait+0x26/0x80 drivers/tty/tty_ldisc.c:243
#1: ffffc900015802f0 (&ldata->atomic_read_lock){+.+.}-{3:3}, at: n_tty_read+0xef4/0x13e0 drivers/tty/n_tty.c:2176
task:dhcpcd state:D stack:27528 pid:5180 ppid:4671 flags:0x00000002

packet_release+0xa7d/0xd10 net/packet/af_packet.c:3167
__sock_release+0xcd/0x290 net/socket.c:653
sock_close+0x1c/0x20 net/socket.c:1397
__fput+0x27c/0xa90 fs/file_table.c:321
task_work_run+0x16f/0x270 kernel/task_work.c:179
resume_user_mode_work include/linux/resume_user_mode.h:49 [inline]
exit_to_user_mode_loop kernel/entry/common.c:171 [inline]
exit_to_user_mode_prepare+0x210/0x240 kernel/entry/common.c:204
__syscall_exit_to_user_mode_work kernel/entry/common.c:286 [inline]
syscall_exit_to_user_mode+0x1d/0x50 kernel/entry/common.c:297
do_syscall_64+0x46/0xb0 arch/x86/entry/common.c:86
entry_SYSCALL_64_after_hwframe+0x63/0xcd
RIP: 0033:0x7fe2ecbec0a8
RSP: 002b:00007fff893f2f18 EFLAGS: 00000246 ORIG_RAX: 0000000000000003
RAX: 0000000000000000 RBX: 00007fff89403188 RCX: 00007fe2ecbec0a8
RDX: 0000000000000000 RSI: 0000000000000006 RDI: 0000000000000005
RBP: 000055edbdfe8e90 R08: 0000000000000012 R09: 0000000000000000
R10: 00007fff894033d0 R11: 0000000000000246 R12: 0000000000000000
R13: 000000000000143c R14: 000000000000123f R15: 0000000000000000
</TASK>
1 lock held by dhcpcd/5180:
#0: ffff888074b6e810 (&sb->s_type->i_mutex_key#10){+.+.}-{3:3}, at: inode_lock include/linux/fs.h:775 [inline]
#0: ffff888074b6e810 (&sb->s_type->i_mutex_key#10){+.+.}-{3:3}, at: __sock_release+0x86/0x290 net/socket.c:652
task:dhcpcd state:D stack:27624 pid:5203 ppid:4671 flags:0x00000002

packet_release+0xa7d/0xd10 net/packet/af_packet.c:3167
__sock_release+0xcd/0x290 net/socket.c:653
sock_close+0x1c/0x20 net/socket.c:1397
__fput+0x27c/0xa90 fs/file_table.c:321
task_work_run+0x16f/0x270 kernel/task_work.c:179
resume_user_mode_work include/linux/resume_user_mode.h:49 [inline]
exit_to_user_mode_loop kernel/entry/common.c:171 [inline]
exit_to_user_mode_prepare+0x210/0x240 kernel/entry/common.c:204
__syscall_exit_to_user_mode_work kernel/entry/common.c:286 [inline]
syscall_exit_to_user_mode+0x1d/0x50 kernel/entry/common.c:297
do_syscall_64+0x46/0xb0 arch/x86/entry/common.c:86
entry_SYSCALL_64_after_hwframe+0x63/0xcd
RIP: 0033:0x7fe2ecbec0a8
RSP: 002b:00007fff893f2f18 EFLAGS: 00000246 ORIG_RAX: 0000000000000003
RAX: 0000000000000000 RBX: 00007fff89403188 RCX: 00007fe2ecbec0a8
RDX: 0000000000000000 RSI: 0000000000000006 RDI: 0000000000000005
RBP: 000055edbdfe9550 R08: 0000000000000016 R09: 0000000000000000
R10: 00007fff894033d0 R11: 0000000000000246 R12: 0000000000000000
R13: 0000000000001453 R14: 000000000000123f R15: 0000000000000000
</TASK>
1 lock held by dhcpcd/5203:
#0: ffff888078695010 (&sb->s_type->i_mutex_key#10){+.+.}-{3:3}, at: inode_lock include/linux/fs.h:775 [inline]
#0: ffff888078695010 (&sb->s_type->i_mutex_key#10){+.+.}-{3:3}, at: __sock_release+0x86/0x290 net/socket.c:652
task:dhcpcd state:D stack:27624 pid:5209 ppid:4671 flags:0x00000002

Tested on:

commit: 27e462c8 Merge tag 'xtensa-20230523' of https://github..
git tree: upstream
console output: https://syzkaller.appspot.com/x/log.txt?x=158cd42e280000

kernel config: https://syzkaller.appspot.com/x/.config?x=f389ffdf4e9ba3f0
dashboard link: https://syzkaller.appspot.com/bug?extid=222aa26d0a5dbc2e84fe
compiler: gcc (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2

patch: https://syzkaller.appspot.com/x/patch.diff?x=1195f96a280000

Tetsuo Handa

unread,

May 25, 2023, 6:47:25 AM5/25/23

to syzbot, syzkaller-bugs

#syz test: git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git master

diff --git a/fs/notify/fsnotify.c b/fs/notify/fsnotify.c
index 7974e91ffe13..78f749b6887b 100644
--- a/fs/notify/fsnotify.c
+++ b/fs/notify/fsnotify.c
@@ -545,6 +545,7 @@ int fsnotify(__u32 mask, const void *data, int data_type, struct inode *dir,
return 0;

iter_info.srcu_idx = srcu_read_lock(&fsnotify_mark_srcu);
+ pr_info("pid=%d comm=%s lock idx=%d\n", current->pid, current->comm, iter_info.srcu_idx);

iter_info.marks[FSNOTIFY_ITER_TYPE_SB] =
fsnotify_first_mark(&sb->s_fsnotify_marks);
@@ -577,6 +578,7 @@ int fsnotify(__u32 mask, const void *data, int data_type, struct inode *dir,
}
ret = 0;
out:
+ pr_info("pid=%d comm=%s unlock idx=%d\n", current->pid, current->comm, iter_info.srcu_idx);
srcu_read_unlock(&fsnotify_mark_srcu, iter_info.srcu_idx);

return ret;
diff --git a/fs/notify/mark.c b/fs/notify/mark.c
index c74ef947447d..91ad7046522f 100644
--- a/fs/notify/mark.c
+++ b/fs/notify/mark.c
@@ -205,6 +205,7 @@ static void fsnotify_connector_destroy_workfn(struct work_struct *work)
connector_destroy_list = NULL;
spin_unlock(&destroy_lock);

+ pr_info("pid=%d comm=%s synchronize\n", current->pid, current->comm);
synchronize_srcu(&fsnotify_mark_srcu);
while (conn) {
free = conn;
@@ -409,11 +410,13 @@ bool fsnotify_prepare_user_wait(struct fsnotify_iter_info *iter_info)
* lists, we can drop SRCU lock, and safely resume the list iteration
* once userspace returns.
*/
+ pr_info("pid=%d comm=%s unlock idx=%d\n", current->pid, current->comm, iter_info->srcu_idx);
srcu_read_unlock(&fsnotify_mark_srcu, iter_info->srcu_idx);

return true;

fail:
+ pr_info("pid=%d comm=%s skip idx=%d\n", current->pid, current->comm, iter_info->srcu_idx);
for (type--; type >= 0; type--)
fsnotify_put_mark_wake(iter_info->marks[type]);
return false;
@@ -425,6 +428,7 @@ void fsnotify_finish_user_wait(struct fsnotify_iter_info *iter_info)
int type;

iter_info->srcu_idx = srcu_read_lock(&fsnotify_mark_srcu);
+ pr_info("pid=%d comm=%s lock idx=%d\n", current->pid, current->comm, iter_info->srcu_idx);
fsnotify_foreach_iter_type(type)
fsnotify_put_mark_wake(iter_info->marks[type]);
}
@@ -586,16 +590,19 @@ static struct fsnotify_mark_connector *fsnotify_grab_connector(
int idx;

idx = srcu_read_lock(&fsnotify_mark_srcu);
+ pr_info("pid=%d comm=%s lock idx=%d\n", current->pid, current->comm, idx);
conn = srcu_dereference(*connp, &fsnotify_mark_srcu);
if (!conn)
goto out;
spin_lock(&conn->lock);
if (conn->type == FSNOTIFY_OBJ_TYPE_DETACHED) {
spin_unlock(&conn->lock);
+ pr_info("pid=%d comm=%s unlock idx=%d\n", current->pid, current->comm, idx);
srcu_read_unlock(&fsnotify_mark_srcu, idx);
return NULL;
}
out:
+ pr_info("pid=%d comm=%s unlock idx=%d\n", current->pid, current->comm, idx);
srcu_read_unlock(&fsnotify_mark_srcu, idx);
return conn;
}
@@ -895,6 +902,7 @@ static void fsnotify_mark_destroy_workfn(struct work_struct *work)
list_replace_init(&destroy_list, &private_destroy_list);
spin_unlock(&destroy_lock);

+ pr_info("pid=%d comm=%s synchronize\n", current->pid, current->comm);
synchronize_srcu(&fsnotify_mark_srcu);

list_for_each_entry_safe(mark, next, &private_destroy_list, g_list) {

syzbot

unread,

May 25, 2023, 7:10:25 AM5/25/23

to penguin...@i-love.sakura.ne.jp, syzkall...@googlegroups.com

Hello,

syzbot has tested the proposed patch and the reproducer did not trigger any issue:

Reported-and-tested-by: syzbot+222aa2...@syzkaller.appspotmail.com

Tested on:

commit: 933174ae Merge tag 'spi-fix-v6.4-rc3' of git://git.ker..
git tree: upstream
console output: https://syzkaller.appspot.com/x/log.txt?x=1663e9b1280000

patch: https://syzkaller.appspot.com/x/patch.diff?x=1106feb1280000

Note: testing is done by a robot and is best-effort only.

Tetsuo Handa

unread,

May 25, 2023, 7:19:01 AM5/25/23

to syzbot, syzkaller-bugs

syzbot

unread,

May 25, 2023, 7:42:31 AM5/25/23

to penguin...@i-love.sakura.ne.jp, syzkall...@googlegroups.com

console output: https://syzkaller.appspot.com/x/log.txt?x=16ef4d39280000

patch: https://syzkaller.appspot.com/x/patch.diff?x=15c5246d280000

Tetsuo Handa

unread,

May 25, 2023, 8:07:59 AM5/25/23

to syzbot, syzkaller-bugs

Hmm, difficult to reproduce due to timing?

#syz test: git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git master

diff --git a/fs/notify/mark.c b/fs/notify/mark.c
index c74ef947447d..3bbeeb1f38f8 100644

--- a/fs/notify/mark.c
+++ b/fs/notify/mark.c
@@ -205,6 +205,7 @@ static void fsnotify_connector_destroy_workfn(struct work_struct *work)
connector_destroy_list = NULL;
spin_unlock(&destroy_lock);

+ pr_info("pid=%d comm=%s synchronize\n", current->pid, current->comm);
synchronize_srcu(&fsnotify_mark_srcu);
while (conn) {
free = conn;

@@ -414,6 +415,7 @@ bool fsnotify_prepare_user_wait(struct fsnotify_iter_info *iter_info)

return true;

fail:
+ pr_info("pid=%d comm=%s skip idx=%d\n", current->pid, current->comm, iter_info->srcu_idx);
for (type--; type >= 0; type--)
fsnotify_put_mark_wake(iter_info->marks[type]);
return false;

@@ -895,6 +897,7 @@ static void fsnotify_mark_destroy_workfn(struct work_struct *work)

syzbot

unread,

May 25, 2023, 8:27:25 AM5/25/23

to penguin...@i-love.sakura.ne.jp, syzkall...@googlegroups.com

Hello,

syzbot has tested the proposed patch but the reproducer is still triggering an issue:
INFO: task hung in synchronize_rcu

INFO: task kworker/u4:2:38 blocked for more than 143 seconds.
Not tainted 6.4.0-rc3-syzkaller-00032-g933174ae28ba-dirty #0

"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

task:kworker/u4:2 state:D stack:23832 pid:38 ppid:2 flags:0x00004000

Workqueue: events_unbound fsnotify_connector_destroy_workfn
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5343 [inline]
__schedule+0xc9a/0x5880 kernel/sched/core.c:6669
schedule+0xde/0x1a0 kernel/sched/core.c:6745
schedule_timeout+0x276/0x2b0 kernel/time/timer.c:2143
do_wait_for_common kernel/sched/completion.c:85 [inline]
__wait_for_common+0x1ce/0x5c0 kernel/sched/completion.c:106
__synchronize_srcu+0x1be/0x2c0 kernel/rcu/srcutree.c:1360

fsnotify_connector_destroy_workfn+0x97/0x100 fs/notify/mark.c:209

process_one_work+0x99a/0x15e0 kernel/workqueue.c:2405
process_scheduled_works kernel/workqueue.c:2468 [inline]
worker_thread+0x881/0x10c0 kernel/workqueue.c:2554
kthread+0x344/0x440 kernel/kthread.c:379
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:308
</TASK>

Showing all threads with locks held in the system:

task:kworker/u4:1 state:D stack:24640 pid:12 ppid:2 flags:0x00004000

Workqueue: events_unbound fsnotify_mark_destroy_workfn
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5343 [inline]
__schedule+0xc9a/0x5880 kernel/sched/core.c:6669
schedule+0xde/0x1a0 kernel/sched/core.c:6745
schedule_timeout+0x276/0x2b0 kernel/time/timer.c:2143
do_wait_for_common kernel/sched/completion.c:85 [inline]
__wait_for_common+0x1ce/0x5c0 kernel/sched/completion.c:106
__synchronize_srcu+0x1be/0x2c0 kernel/rcu/srcutree.c:1360

fsnotify_mark_destroy_workfn+0x14b/0x420 fs/notify/mark.c:901

2 locks held by kworker/u4:1/12:

#0: ffff888012479138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: arch_atomic64_set arch/x86/include/asm/atomic64_64.h:34 [inline]
#0: ffff888012479138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: arch_atomic_long_set include/linux/atomic/atomic-long.h:41 [inline]
#0: ffff888012479138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: atomic_long_set include/linux/atomic/atomic-instrumented.h:1324 [inline]
#0: ffff888012479138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: set_work_data kernel/workqueue.c:643 [inline]
#0: ffff888012479138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: set_work_pool_and_clear_pending kernel/workqueue.c:670 [inline]
#0: ffff888012479138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: process_one_work+0x883/0x15e0 kernel/workqueue.c:2376

#1: ffffc90000117db0 ((reaper_work).work){+.+.}-{0:0}, at: process_one_work+0x8b7/0x15e0 kernel/workqueue.c:2380

task:rcu_tasks_kthre state:I stack:29024 pid:13 ppid:2 flags:0x00004000
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5343 [inline]
__schedule+0xc9a/0x5880 kernel/sched/core.c:6669
schedule+0xde/0x1a0 kernel/sched/core.c:6745
rcu_tasks_one_gp+0x489/0xd80 kernel/rcu/tasks.h:525
rcu_tasks_kthread+0x84/0xb0 kernel/rcu/tasks.h:563
kthread+0x344/0x440 kernel/kthread.c:379
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:308
</TASK>
1 lock held by rcu_tasks_kthre/13:

#0: ffffffff8c7984f0 (rcu_tasks.tasks_gp_mutex){+.+.}-{3:3}, at: rcu_tasks_one_gp+0x31/0xd80 kernel/rcu/tasks.h:518

task:rcu_tasks_trace state:I stack:29128 pid:14 ppid:2 flags:0x00004000
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5343 [inline]
__schedule+0xc9a/0x5880 kernel/sched/core.c:6669
schedule+0xde/0x1a0 kernel/sched/core.c:6745
rcu_tasks_one_gp+0x489/0xd80 kernel/rcu/tasks.h:525
rcu_tasks_kthread+0x84/0xb0 kernel/rcu/tasks.h:563
kthread+0x344/0x440 kernel/kthread.c:379
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:308
</TASK>
1 lock held by rcu_tasks_trace/14:
#0: ffffffff8c7981f0 (rcu_tasks_trace.tasks_gp_mutex){+.+.}-{3:3}, at: rcu_tasks_one_gp+0x31/0xd80 kernel/rcu/tasks.h:518

task:khugepaged state:D stack:28376 pid:34 ppid:2 flags:0x00004000

Call Trace:
<TASK>
context_switch kernel/sched/core.c:5343 [inline]
__schedule+0xc9a/0x5880 kernel/sched/core.c:6669
schedule+0xde/0x1a0 kernel/sched/core.c:6745
schedule_timeout+0x276/0x2b0 kernel/time/timer.c:2143
do_wait_for_common kernel/sched/completion.c:85 [inline]
__wait_for_common+0x1ce/0x5c0 kernel/sched/completion.c:106
__flush_work+0x595/0xb60 kernel/workqueue.c:3189
__lru_add_drain_all+0x1bf/0x6a0 mm/swap.c:897
khugepaged_do_scan mm/khugepaged.c:2599 [inline]
khugepaged+0x105/0x1740 mm/khugepaged.c:2668
kthread+0x344/0x440 kernel/kthread.c:379
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:308
</TASK>

1 lock held by khugepaged/34:

#0: ffffffff8c89a5c8 (lock#3){+.+.}-{3:3}, at: __lru_add_drain_all+0x62/0x6a0 mm/swap.c:852

task:kworker/u4:2 state:D stack:23832 pid:38 ppid:2 flags:0x00004000

fsnotify_connector_destroy_workfn+0x97/0x100 fs/notify/mark.c:209

2 locks held by kworker/u4:2/38:

#1: ffffc90000af7db0 (connector_reaper_work){+.+.}-{0:0}, at: process_one_work+0x8b7/0x15e0 kernel/workqueue.c:2380
task:kworker/u4:3 state:R running task stack:23328 pid:46 ppid:2 flags:0x00004000
Workqueue: bat_events batadv_nc_worker

Call Trace:
<TASK>
context_switch kernel/sched/core.c:5343 [inline]
__schedule+0xc9a/0x5880 kernel/sched/core.c:6669
schedule+0xde/0x1a0 kernel/sched/core.c:6745

worker_thread+0x160/0x10c0 kernel/workqueue.c:2573

kthread+0x344/0x440 kernel/kthread.c:379
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:308
</TASK>

no locks held by kworker/u4:3/46.
task:kworker/u4:4 state:R running task stack:26144 pid:56 ppid:2 flags:0x00004000
Workqueue: 0x0 (wg-kex-wg2)

Call Trace:
<TASK>
context_switch kernel/sched/core.c:5343 [inline]
__schedule+0xc9a/0x5880 kernel/sched/core.c:6669
schedule+0xde/0x1a0 kernel/sched/core.c:6745

worker_thread+0x160/0x10c0 kernel/workqueue.c:2573

kthread+0x344/0x440 kernel/kthread.c:379
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:308
</TASK>

no locks held by kworker/u4:4/56.

task:getty state:S stack:23320 pid:4760 ppid:1 flags:0x00000002
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5343 [inline]
__schedule+0xc9a/0x5880 kernel/sched/core.c:6669
schedule+0xde/0x1a0 kernel/sched/core.c:6745
schedule_timeout+0x276/0x2b0 kernel/time/timer.c:2143
wait_woken+0x197/0x200 kernel/sched/wait.c:463
n_tty_read+0x1055/0x13e0 drivers/tty/n_tty.c:2242
iterate_tty_read drivers/tty/tty_io.c:852 [inline]
tty_read+0x30e/0x610 drivers/tty/tty_io.c:927
call_read_iter include/linux/fs.h:1862 [inline]
new_sync_read fs/read_write.c:389 [inline]
vfs_read+0x4b1/0x8a0 fs/read_write.c:470
ksys_read+0x12b/0x250 fs/read_write.c:613
do_syscall_x64 arch/x86/entry/common.c:50 [inline]
do_syscall_64+0x39/0xb0 arch/x86/entry/common.c:80
entry_SYSCALL_64_after_hwframe+0x63/0xcd

RIP: 0033:0x7fb684cb5b6a
RSP: 002b:00007ffd624422f8 EFLAGS: 00000246 ORIG_RAX: 0000000000000000
RAX: ffffffffffffffda RBX: 0000558b2098a910 RCX: 00007fb684cb5b6a
RDX: 0000000000000001 RSI: 00007ffd62442310 RDI: 0000000000000000
RBP: 0000558b2098a970 R08: 0000000000000000 R09: 43ac5665d88e4a10
R10: 0000000000000010 R11: 0000000000000246 R12: 0000558b2098a9ac
R13: 00007ffd62442310 R14: 0000000000000000 R15: 0000558b2098a9ac

</TASK>
2 locks held by getty/4760:

#0: ffff88802c2aa098 (&tty->ldisc_sem){++++}-{0:0}, at: tty_ldisc_ref_wait+0x26/0x80 drivers/tty/tty_ldisc.c:243
#1: ffffc900015b02f0 (&ldata->atomic_read_lock){+.+.}-{3:3}, at: n_tty_read+0xef4/0x13e0 drivers/tty/n_tty.c:2176
task:kworker/1:4 state:R running task stack:26712 pid:5018 ppid:2 flags:0x00004000
Workqueue: events prog_array_map_clear_deferred
Call Trace:
<TASK>
</TASK>
2 locks held by kworker/1:4/5018:
task:kworker/0:5 state:R running task stack:27192 pid:5019 ppid:2 flags:0x00004008
Workqueue: events prog_array_map_clear_deferred
Call Trace:
<TASK>
</TASK>
2 locks held by kworker/0:5/5019:
task:dhcpcd state:D stack:27528 pid:5164 ppid:4670 flags:0x00000002

Call Trace:
<TASK>
context_switch kernel/sched/core.c:5343 [inline]
__schedule+0xc9a/0x5880 kernel/sched/core.c:6669
schedule+0xde/0x1a0 kernel/sched/core.c:6745
exp_funnel_lock kernel/rcu/tree_exp.h:316 [inline]
synchronize_rcu_expedited+0x6f8/0x770 kernel/rcu/tree_exp.h:992
synchronize_rcu+0x2f1/0x3a0 kernel/rcu/tree.c:3499
synchronize_net+0x4e/0x60 net/core/dev.c:10791
packet_release+0xa7d/0xd10 net/packet/af_packet.c:3167
__sock_release+0xcd/0x290 net/socket.c:653
sock_close+0x1c/0x20 net/socket.c:1397
__fput+0x27c/0xa90 fs/file_table.c:321
task_work_run+0x16f/0x270 kernel/task_work.c:179
resume_user_mode_work include/linux/resume_user_mode.h:49 [inline]
exit_to_user_mode_loop kernel/entry/common.c:171 [inline]
exit_to_user_mode_prepare+0x210/0x240 kernel/entry/common.c:204
__syscall_exit_to_user_mode_work kernel/entry/common.c:286 [inline]
syscall_exit_to_user_mode+0x1d/0x50 kernel/entry/common.c:297
do_syscall_64+0x46/0xb0 arch/x86/entry/common.c:86
entry_SYSCALL_64_after_hwframe+0x63/0xcd

RIP: 0033:0x7f1720dfb0a8
RSP: 002b:00007ffe5b6f0ce8 EFLAGS: 00000246 ORIG_RAX: 0000000000000003
RAX: 0000000000000000 RBX: 00007ffe5b700f58 RCX: 00007f1720dfb0a8

RDX: 0000000000000000 RSI: 0000000000000006 RDI: 0000000000000005

RBP: 000055f1f019f090 R08: 0000000000000012 R09: 0000000000000000
R10: 00007ffe5b7011a0 R11: 0000000000000246 R12: 0000000000000000
R13: 000000000000142c R14: 000000000000123e R15: 0000000000000000
</TASK>
1 lock held by dhcpcd/5164:
#0: ffff888078242610 (&sb->s_type->i_mutex_key#10){+.+.}-{3:3}, at: inode_lock include/linux/fs.h:775 [inline]
#0: ffff888078242610 (&sb->s_type->i_mutex_key#10){+.+.}-{3:3}, at: __sock_release+0x86/0x290 net/socket.c:652
task:dhcpcd state:D stack:27624 pid:5204 ppid:4670 flags:0x00000002

Call Trace:
<TASK>
context_switch kernel/sched/core.c:5343 [inline]
__schedule+0xc9a/0x5880 kernel/sched/core.c:6669
schedule+0xde/0x1a0 kernel/sched/core.c:6745
exp_funnel_lock kernel/rcu/tree_exp.h:316 [inline]
synchronize_rcu_expedited+0x6f8/0x770 kernel/rcu/tree_exp.h:992
synchronize_rcu+0x2f1/0x3a0 kernel/rcu/tree.c:3499
synchronize_net+0x4e/0x60 net/core/dev.c:10791
packet_release+0xa7d/0xd10 net/packet/af_packet.c:3167
__sock_release+0xcd/0x290 net/socket.c:653
sock_close+0x1c/0x20 net/socket.c:1397
__fput+0x27c/0xa90 fs/file_table.c:321
task_work_run+0x16f/0x270 kernel/task_work.c:179
resume_user_mode_work include/linux/resume_user_mode.h:49 [inline]
exit_to_user_mode_loop kernel/entry/common.c:171 [inline]
exit_to_user_mode_prepare+0x210/0x240 kernel/entry/common.c:204
__syscall_exit_to_user_mode_work kernel/entry/common.c:286 [inline]
syscall_exit_to_user_mode+0x1d/0x50 kernel/entry/common.c:297
do_syscall_64+0x46/0xb0 arch/x86/entry/common.c:86
entry_SYSCALL_64_after_hwframe+0x63/0xcd

RIP: 0033:0x7f1720dfb0a8
RSP: 002b:00007ffe5b6f0ce8 EFLAGS: 00000246 ORIG_RAX: 0000000000000003
RAX: 0000000000000000 RBX: 00007ffe5b700f58 RCX: 00007f1720dfb0a8

RDX: 0000000000000000 RSI: 0000000000000006 RDI: 0000000000000005

RBP: 000055f1f019f8e0 R08: 0000000000000018 R09: 0000000000000000
R10: 00007ffe5b7011a0 R11: 0000000000000246 R12: 0000000000000000
R13: 0000000000001454 R14: 000000000000123e R15: 0000000000000000
</TASK>
1 lock held by dhcpcd/5204:
#0: ffff8880782d2010 (&sb->s_type->i_mutex_key#10){+.+.}-{3:3}, at: inode_lock include/linux/fs.h:775 [inline]
#0: ffff8880782d2010 (&sb->s_type->i_mutex_key#10){+.+.}-{3:3}, at: __sock_release+0x86/0x290 net/socket.c:652
task:dhcpcd state:D stack:27624 pid:5207 ppid:4670 flags:0x00000002

Call Trace:
<TASK>
context_switch kernel/sched/core.c:5343 [inline]
__schedule+0xc9a/0x5880 kernel/sched/core.c:6669
schedule+0xde/0x1a0 kernel/sched/core.c:6745
exp_funnel_lock kernel/rcu/tree_exp.h:316 [inline]
synchronize_rcu_expedited+0x6f8/0x770 kernel/rcu/tree_exp.h:992
synchronize_rcu+0x2f1/0x3a0 kernel/rcu/tree.c:3499
synchronize_net+0x4e/0x60 net/core/dev.c:10791
packet_release+0xa7d/0xd10 net/packet/af_packet.c:3167
__sock_release+0xcd/0x290 net/socket.c:653
sock_close+0x1c/0x20 net/socket.c:1397
__fput+0x27c/0xa90 fs/file_table.c:321
task_work_run+0x16f/0x270 kernel/task_work.c:179
resume_user_mode_work include/linux/resume_user_mode.h:49 [inline]
exit_to_user_mode_loop kernel/entry/common.c:171 [inline]
exit_to_user_mode_prepare+0x210/0x240 kernel/entry/common.c:204
__syscall_exit_to_user_mode_work kernel/entry/common.c:286 [inline]
syscall_exit_to_user_mode+0x1d/0x50 kernel/entry/common.c:297
do_syscall_64+0x46/0xb0 arch/x86/entry/common.c:86
entry_SYSCALL_64_after_hwframe+0x63/0xcd

RIP: 0033:0x7f1720dfb0a8
RSP: 002b:00007ffe5b6f0ce8 EFLAGS: 00000246 ORIG_RAX: 0000000000000003
RAX: 0000000000000000 RBX: 00007ffe5b700f58 RCX: 00007f1720dfb0a8

RDX: 0000000000000000 RSI: 0000000000000006 RDI: 0000000000000005

RBP: 000055f1f019f5e0 R08: 000000000000001a R09: 0000000000000000
R10: 00007ffe5b7011a0 R11: 0000000000000246 R12: 0000000000000000
R13: 0000000000001457 R14: 000000000000123e R15: 0000000000000000
</TASK>
1 lock held by dhcpcd/5207:
#0: ffff8880782d5c10 (&sb->s_type->i_mutex_key#10){+.+.}-{3:3}, at: inode_lock include/linux/fs.h:775 [inline]
#0: ffff8880782d5c10 (&sb->s_type->i_mutex_key#10){+.+.}-{3:3}, at: __sock_release+0x86/0x290 net/socket.c:652
task:dhcpcd state:D stack:27624 pid:5212 ppid:4670 flags:0x00004002

Call Trace:
<TASK>
context_switch kernel/sched/core.c:5343 [inline]
__schedule+0xc9a/0x5880 kernel/sched/core.c:6669
schedule+0xde/0x1a0 kernel/sched/core.c:6745

synchronize_rcu_expedited+0x5d4/0x770 kernel/rcu/tree_exp.h:1007

synchronize_rcu+0x2f1/0x3a0 kernel/rcu/tree.c:3499
synchronize_net+0x4e/0x60 net/core/dev.c:10791
packet_release+0xa7d/0xd10 net/packet/af_packet.c:3167
__sock_release+0xcd/0x290 net/socket.c:653
sock_close+0x1c/0x20 net/socket.c:1397
__fput+0x27c/0xa90 fs/file_table.c:321
task_work_run+0x16f/0x270 kernel/task_work.c:179
resume_user_mode_work include/linux/resume_user_mode.h:49 [inline]
exit_to_user_mode_loop kernel/entry/common.c:171 [inline]
exit_to_user_mode_prepare+0x210/0x240 kernel/entry/common.c:204
__syscall_exit_to_user_mode_work kernel/entry/common.c:286 [inline]
syscall_exit_to_user_mode+0x1d/0x50 kernel/entry/common.c:297
do_syscall_64+0x46/0xb0 arch/x86/entry/common.c:86
entry_SYSCALL_64_after_hwframe+0x63/0xcd

RIP: 0033:0x7f1720dfb0a8
RSP: 002b:00007ffe5b6f0ce8 EFLAGS: 00000246 ORIG_RAX: 0000000000000003
RAX: 0000000000000000 RBX: 00007ffe5b700f58 RCX: 00007f1720dfb0a8

RDX: 0000000000000000 RSI: 0000000000000006 RDI: 0000000000000005

RBP: 000055f1f019fee0 R08: 000000000000001c R09: 0000000000000000
R10: 00007ffe5b7011a0 R11: 0000000000000246 R12: 0000000000000000
R13: 000000000000145c R14: 000000000000123e R15: 0000000000000000
</TASK>
2 locks held by dhcpcd/5212:
#0: ffff88807820be10 (&sb->s_type->i_mutex_key#10){+.+.}-{3:3}, at: inode_lock include/linux/fs.h:775 [inline]
#0: ffff88807820be10 (&sb->s_type->i_mutex_key#10){+.+.}-{3:3}, at: __sock_release+0x86/0x290 net/socket.c:652
#1: ffffffff8c7a4578 (rcu_state.exp_mutex){+.+.}-{3:3}, at: exp_funnel_lock kernel/rcu/tree_exp.h:325 [inline]
#1: ffffffff8c7a4578 (rcu_state.exp_mutex){+.+.}-{3:3}, at: synchronize_rcu_expedited+0x3e8/0x770 kernel/rcu/tree_exp.h:992
task:syz-executor.4 state:D stack:23848 pid:5371 ppid:5360 flags:0x00004006

Call Trace:
<TASK>
context_switch kernel/sched/core.c:5343 [inline]
__schedule+0xc9a/0x5880 kernel/sched/core.c:6669
schedule+0xde/0x1a0 kernel/sched/core.c:6745

schedule_preempt_disabled+0x13/0x20 kernel/sched/core.c:6804
__mutex_lock_common kernel/locking/mutex.c:679 [inline]
__mutex_lock+0xa3b/0x1350 kernel/locking/mutex.c:747
exp_funnel_lock kernel/rcu/tree_exp.h:325 [inline]
synchronize_rcu_expedited+0x3e8/0x770 kernel/rcu/tree_exp.h:992
namespace_unlock+0x1af/0x410 fs/namespace.c:1499
drop_collected_mounts fs/namespace.c:1986 [inline]
put_mnt_ns fs/namespace.c:4448 [inline]
put_mnt_ns+0x10a/0x150 fs/namespace.c:4444
free_nsproxy+0x47/0x4d0 kernel/nsproxy.c:193
put_nsproxy include/linux/nsproxy.h:106 [inline]
switch_task_namespaces+0xb1/0xd0 kernel/nsproxy.c:251
do_exit+0xace/0x2960 kernel/exit.c:870
do_group_exit+0xd4/0x2a0 kernel/exit.c:1021
get_signal+0x2315/0x25b0 kernel/signal.c:2874
arch_do_signal_or_restart+0x79/0x5c0 arch/x86/kernel/signal.c:306
exit_to_user_mode_loop kernel/entry/common.c:168 [inline]
exit_to_user_mode_prepare+0x11f/0x240 kernel/entry/common.c:204

__syscall_exit_to_user_mode_work kernel/entry/common.c:286 [inline]
syscall_exit_to_user_mode+0x1d/0x50 kernel/entry/common.c:297
do_syscall_64+0x46/0xb0 arch/x86/entry/common.c:86
entry_SYSCALL_64_after_hwframe+0x63/0xcd

RIP: 0033:0x7f11d5cb0e91
RSP: 002b:00007ffcc0f9abf0 EFLAGS: 00000293 ORIG_RAX: 00000000000000e6
RAX: 0000000000000000 RBX: 0000000000000667 RCX: 00007f11d5cb0e91
RDX: 00007ffcc0f9ac30 RSI: 0000000000000000 RDI: 0000000000000000
RBP: 00007ffcc0f9acbc R08: 0000000000000000 R09: 00007ffcc0fc7080
R10: 0000000000000000 R11: 0000000000000293 R12: 0000000000000032
R13: 0000000000042567 R14: 0000000000000000 R15: 00007ffcc0f9ad20
</TASK>
1 lock held by syz-executor.4/5371:
#0: ffffffff8c7a4578 (rcu_state.exp_mutex){+.+.}-{3:3}, at: exp_funnel_lock kernel/rcu/tree_exp.h:325 [inline]
#0: ffffffff8c7a4578 (rcu_state.exp_mutex){+.+.}-{3:3}, at: synchronize_rcu_expedited+0x3e8/0x770 kernel/rcu/tree_exp.h:992
task:kworker/1:5 state:R running task stack:26336 pid:5435 ppid:2 flags:0x00004008
Workqueue: events prog_array_map_clear_deferred
Call Trace:
<TASK>
</TASK>
3 locks held by kworker/1:5/5435:
task:kworker/0:8 state:R running task stack:26184 pid:5617 ppid:2 flags:0x00004000
Workqueue: events prog_array_map_clear_deferred
Call Trace:
<TASK>
</TASK>
3 locks held by kworker/0:8/5617:
task:dhcpcd state:D stack:29024 pid:14672 ppid:4670 flags:0x00000002

__unregister_prot_hook+0x4b3/0x5c0 net/packet/af_packet.c:380
packet_do_bind+0x93f/0xe30 net/packet/af_packet.c:3235
packet_bind+0x15f/0x1c0 net/packet/af_packet.c:3319
__sys_bind+0x1ed/0x260 net/socket.c:1803
__do_sys_bind net/socket.c:1814 [inline]
__se_sys_bind net/socket.c:1812 [inline]
__x64_sys_bind+0x73/0xb0 net/socket.c:1812

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

RIP: 0033:0x7f1720e08677
RSP: 002b:00007ffe5b6e0a08 EFLAGS: 00000217 ORIG_RAX: 0000000000000031
RAX: ffffffffffffffda RBX: 000055f1eeec1ca3 RCX: 00007f1720e08677
RDX: 0000000000000014 RSI: 00007ffe5b6e0a18 RDI: 0000000000000005
RBP: 0000000000000000 R08: 000055f1f01a0590 R09: 0000000000200000
R10: 000000000000006d R11: 0000000000000217 R12: 000055f1f019c160
R13: 000055f1f019f0f8 R14: 00007ffe5b7012fc R15: 000055f1f019f0c4
</TASK>
1 lock held by dhcpcd/14672:
#0: ffff88802abd4130 (sk_lock-AF_PACKET){+.+.}-{0:0}, at: lock_sock include/net/sock.h:1697 [inline]
#0: ffff88802abd4130 (sk_lock-AF_PACKET){+.+.}-{0:0}, at: packet_do_bind+0x2f/0xe30 net/packet/af_packet.c:3202
task:dhcpcd state:D stack:29024 pid:14707 ppid:4670 flags:0x00000002

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

RIP: 0033:0x7f1720e08677
RSP: 002b:00007ffe5b6e0a08 EFLAGS: 00000217 ORIG_RAX: 0000000000000031
RAX: ffffffffffffffda RBX: 000055f1eeec1ca3 RCX: 00007f1720e08677
RDX: 0000000000000014 RSI: 00007ffe5b6e0a18 RDI: 0000000000000005
RBP: 0000000000000000 R08: 000055f1f01a0590 R09: 0000000000200000
R10: 000000000000006d R11: 0000000000000217 R12: 000055f1f019c160
R13: 000055f1f0199ce8 R14: 00007ffe5b7012fc R15: 000055f1f0199cb4
</TASK>
1 lock held by dhcpcd/14707:
#0: ffff8880b2a62130 (sk_lock-AF_PACKET){+.+.}-{0:0}, at: lock_sock include/net/sock.h:1697 [inline]
#0: ffff8880b2a62130 (sk_lock-AF_PACKET){+.+.}-{0:0}, at: packet_do_bind+0x2f/0xe30 net/packet/af_packet.c:3202
task:dhcpcd state:D stack:29024 pid:14709 ppid:4670 flags:0x00000002

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

RIP: 0033:0x7f1720e08677
RSP: 002b:00007ffe5b6e0a08 EFLAGS: 00000217 ORIG_RAX: 0000000000000031
RAX: ffffffffffffffda RBX: 000055f1eeec1ca3 RCX: 00007f1720e08677
RDX: 0000000000000014 RSI: 00007ffe5b6e0a18 RDI: 0000000000000005
RBP: 0000000000000000 R08: 000055f1f01a0590 R09: 0000000000200000
R10: 000000000000006d R11: 0000000000000217 R12: 000055f1f019c160
R13: 000055f1f0199e68 R14: 00007ffe5b7012fc R15: 000055f1f0199e34
</TASK>
1 lock held by dhcpcd/14709:
#0: ffff888024600130 (sk_lock-AF_PACKET){+.+.}-{0:0}, at: lock_sock include/net/sock.h:1697 [inline]
#0: ffff888024600130 (sk_lock-AF_PACKET){+.+.}-{0:0}, at: packet_do_bind+0x2f/0xe30 net/packet/af_packet.c:3202
task:dhcpcd state:D stack:29024 pid:14744 ppid:4670 flags:0x00000002

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

RIP: 0033:0x7f1720e08677
RSP: 002b:00007ffe5b6e0a08 EFLAGS: 00000217 ORIG_RAX: 0000000000000031
RAX: ffffffffffffffda RBX: 000055f1eeec1ca3 RCX: 00007f1720e08677
RDX: 0000000000000014 RSI: 00007ffe5b6e0a18 RDI: 0000000000000005
RBP: 0000000000000000 R08: 000055f1f01a0710 R09: 0000000000200000
R10: 000000000000006d R11: 0000000000000217 R12: 000055f1f019c160
R13: 000055f1f01a05f8 R14: 00007ffe5b7012fc R15: 000055f1f01a05c4
</TASK>
1 lock held by dhcpcd/14744:
#0: ffff88802b64e130 (sk_lock-AF_PACKET){+.+.}-{0:0}, at: lock_sock include/net/sock.h:1697 [inline]
#0: ffff88802b64e130 (sk_lock-AF_PACKET){+.+.}-{0:0}, at: packet_do_bind+0x2f/0xe30 net/packet/af_packet.c:3202
task:dhcpcd state:D stack:29024 pid:14766 ppid:4670 flags:0x00000002

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

Tested on:

commit: 933174ae Merge tag 'spi-fix-v6.4-rc3' of git://git.ker..
git tree: upstream

console output: https://syzkaller.appspot.com/x/log.txt?x=12026e4d280000

patch: https://syzkaller.appspot.com/x/patch.diff?x=100446b1280000

Reply all

Reply to author

Forward

0 new messages