Re: [Syzkaller & bisect] There is BUG: soft lockup after sendmsg syscall in v6.8-rc4
From: Pengfei Xu
Date: Wed Feb 21 2024 - 00:35:36 EST
Hi Jsason,
On 2024-02-21 at 11:07:44 +0800, Jason Xing wrote:
> On Wed, Feb 21, 2024 at 10:35 AM Pengfei Xu <pengfei.xu@xxxxxxxxx> wrote:
> >
> > Hi Kuniyuki Iwashima and kernel experts,
> >
> > Greeting!
> > There is BUG: soft lockup after sendmsg syscall in v6.8-rc4 in guest.
> >
> > All detailed info: https://github.com/xupengfe/syzkaller_logs/tree/main/240220_161242_softlockup
> > Syzkaller reproduced code: https://github.com/xupengfe/syzkaller_logs/blob/main/240220_161242_softlockup/repro.c
> > Syzkaller syscall reproduced steps: https://github.com/xupengfe/syzkaller_logs/blob/main/240220_161242_softlockup/repro.prog
> > Kconfig(need make olddefconfig): https://github.com/xupengfe/syzkaller_logs/blob/main/240220_161242_softlockup/kconfig_origin
> > Bisect info: https://github.com/xupengfe/syzkaller_logs/blob/main/240220_161242_softlockup/bisect_info.log
> > v6.8-rc4 issue dmesg: https://github.com/xupengfe/syzkaller_logs/blob/main/240220_161242_softlockup/841c35169323cd833294798e58b9bf63fa4fa1de_dmesg.log
> > bzImage_v6.8-rc4: https://github.com/xupengfe/syzkaller_logs/raw/main/240220_161242_softlockup/bzImage_v6.8-rc4.tar.gz
> >
> > Bisected and found first bad commit:
> > "
> > 1279f9d9dec2 af_unix: Call kfree_skb() for dead unix_(sk)->oob_skb in GC.
> > "
> >
> > After reverted above commit on top of v6.8-rc4 kernel, this issue was gone.
> >
> > Syzkaller repro.report: https://github.com/xupengfe/syzkaller_logs/blob/main/240220_161242_softlockup/repro.report
> > "
> > watchdog: BUG: soft lockup - CPU#0 stuck for 26s! [gdbus:349]
> > Modules linked in:
> > irq event stamp: 25162
> > hardirqs last enabled at (25161): [<ffffffff855dff2e>] irqentry_exit+0x3e/0xa0 kernel/entry/common.c:351
> > hardirqs last disabled at (25162): [<ffffffff855dded4>] sysvec_apic_timer_interrupt+0x14/0xc0 arch/x86/kernel/apic/apic.c:1076
> > softirqs last enabled at (25140): [<ffffffff8127fcc8>] invoke_softirq kernel/softirq.c:427 [inline]
> > softirqs last enabled at (25140): [<ffffffff8127fcc8>] __irq_exit_rcu+0xa8/0x110 kernel/softirq.c:632
> > softirqs last disabled at (25135): [<ffffffff8127fcc8>] invoke_softirq kernel/softirq.c:427 [inline]
> > softirqs last disabled at (25135): [<ffffffff8127fcc8>] __irq_exit_rcu+0xa8/0x110 kernel/softirq.c:632
> > CPU: 0 PID: 349 Comm: gdbus Not tainted 6.8.0-rc4-2024-02-12-intel-next-e92619743fcb+ #1
> > Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.16.0-0-gd239552ce722-prebuilt.qemu.org 04/01/2014
> > RIP: 0010:__sanitizer_cov_trace_pc+0x38/0x70 kernel/kcov.c:207
> > Code: 65 8b 05 73 89 a0 7e 48 89 e5 48 8b 75 08 a9 00 01 ff 00 74 0f f6 c4 01 74 35 8b 82 e4 1d 00 00 85 c0 74 2b 8b 82 c0 1d 00 00 <83> f8 02 75 20 48 8b 8a c8 1d 00 00 8b 92 c4 1d 00 00 48 8b 01 48
> > RSP: 0018:ffff88800b48f7b0 EFLAGS: 00000246
> > RAX: 0000000000000000 RBX: ffff888013018000 RCX: 1ffffffff12150bb
> > RDX: ffff888011ab8000 RSI: ffffffff8515e235 RDI: ffff888013018770
> > RBP: ffff88800b48f7b0 R08: 0000000000000001 R09: fffffbfff120f86e
> > R10: ffffffff8907c377 R11: 0000000000000001 R12: ffff888013018000
> > R13: dffffc0000000000 R14: ffff888013018630 R15: ffff88800b48f840
> > FS: 0000000000000000(0000) GS:ffff88806ca00000(0000) knlGS:0000000000000000
> > CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > CR2: 00007fffcc5fd648 CR3: 0000000006c82000 CR4: 0000000000750ef0
> > PKRU: 55555554
> > Call Trace:
> > <IRQ>
> > </IRQ>
> > <TASK>
> > unix_gc+0x465/0xfd0 net/unix/garbage.c:319
> > unix_release_sock+0xb8c/0xe80 net/unix/af_unix.c:683
> > unix_release+0x9c/0x100 net/unix/af_unix.c:1064
> > __sock_release+0xb6/0x280 net/socket.c:659
> > sock_close+0x27/0x40 net/socket.c:1421
> > __fput+0x284/0xb70 fs/file_table.c:376
> > ____fput+0x1f/0x30 fs/file_table.c:404
> > task_work_run+0x19d/0x2b0 kernel/task_work.c:180
> > exit_task_work include/linux/task_work.h:38 [inline]
> > do_exit+0xb51/0x28c0 kernel/exit.c:871
> > do_group_exit+0xe5/0x2c0 kernel/exit.c:1020
> > get_signal+0x2715/0x27d0 kernel/signal.c:2893
> > arch_do_signal_or_restart+0x8e/0x7e0 arch/x86/kernel/signal.c:311
> > exit_to_user_mode_loop kernel/entry/common.c:105 [inline]
> > exit_to_user_mode_prepare include/linux/entry-common.h:328 [inline]
> > __syscall_exit_to_user_mode_work kernel/entry/common.c:201 [inline]
> > syscall_exit_to_user_mode+0x129/0x190 kernel/entry/common.c:212
> > do_syscall_64+0x82/0x150 arch/x86/entry/common.c:89
> > entry_SYSCALL_64_after_hwframe+0x6e/0x76
> > RIP: 0033:0x7fe8f8b4296f
> > Code: Unable to access opcode bytes at 0x7fe8f8b42945.
> > RSP: 002b:00007fe8d7dff9c0 EFLAGS: 00000293 ORIG_RAX: 0000000000000007
> > RAX: fffffffffffffdfc RBX: 00007fe8f8f73071 RCX: 00007fe8f8b4296f
> > RDX: 00000000ffffffff RSI: 0000000000000002 RDI: 00007fe8a801f3f0
> > RBP: 00007fe8a801f3f0 R08: 0000000000000000 R09: 00007fe8d7dff850
> > R10: 00007ffec9196080 R11: 0000000000000293 R12: 0000000000000002
> > R13: 0000000000000002 R14: 00007fe8d7dffa30 R15: 00007fe8a801c4c0
> > </TASK>
> > "
>
> Hello, did you try this one:
>
> commit 25236c91b5ab4a26a56ba2e79b8060cf4e047839
> Author: Kuniyuki Iwashima <kuniyu@xxxxxxxxxx>
> Date: Fri Feb 9 14:04:53 2024 -0800
>
> af_unix: Fix task hung while purging oob_skb in GC.
>
> syzbot reported a task hung; at the same time, GC was looping infinitely
> in list_for_each_entry_safe() for OOB skb. [0]
>
> syzbot demonstrated that the list_for_each_entry_safe() was not actually
> safe in this case.
>
> A single skb could have references for multiple sockets. If we free such
> a skb in the list_for_each_entry_safe(), the current and next sockets could
> be unlinked in a single iteration.
>
> It should work, I think :)
Thanks for your information!
I tried the v6.8-rc5 kernel which contains the commit 25236c91b5ab4 and
the changed code in file net/unix/garbage.c was same.
The problem can still be reproduced in v6.8-rc5, seems there is still some
problem left.
"
[ 192.656972] watchdog: BUG: soft lockup - CPU#0 stuck for 22s! [GUsbEventThread:601]
[ 192.657524] Modules linked in:
[ 192.657714] irq event stamp: 23074
[ 192.657914] hardirqs last enabled at (23073): [<ffffffff85584fce>] irqentry_exit+0x3e/0xa0
[ 192.658446] hardirqs last disabled at (23074): [<ffffffff85582dc3>] sysvec_apic_timer_interrupt+0x13/0xd0
[ 192.659023] softirqs last enabled at (23058): [<ffffffff855cd1a0>] __do_softirq+0x4f0/0x791
[ 192.659542] softirqs last disabled at (23053): [<ffffffff8126ab41>] irq_exit_rcu+0xc1/0x110
[ 192.660058] CPU: 0 PID: 601 Comm: GUsbEventThread Not tainted 6.8.0-rc5-kvm #15
[ 192.660490] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.16.0-0-gd239552ce722-prebuilt.qemu.org 04/01/2014
[ 192.661163] RIP: 0010:__sanitizer_cov_trace_pc+0x0/0x70
[ 192.661485] Code: 48 8b 80 d8 1d 00 00 c3 cc cc cc cc 31 c0 5d c3 cc cc cc cc 66 0f 1f 44 00 00 90 90 90 90 90 90 90 90 90 90 90 90 90 90 90 90 8
[ 192.662586] RSP: 0018:ffff888007967798 EFLAGS: 00000246
[ 192.662909] RAX: ffff88800fe12500 RBX: ffffed1000f67eee RCX: ffffffff84b2f34f
[ 192.663337] RDX: 0000000000000000 RSI: ffffffff85103edf RDI: 0000000000000005
[ 192.663763] RBP: ffff888007967918 R08: ffff88800fe12500 R09: ffffed10035c57d5
[ 192.664187] R10: ffffed10035c57d4 R11: ffff88801ae2bea7 R12: ffff888007b3f630
[ 192.664611] R13: ffff888007b3f770 R14: dffffc0000000000 R15: 0000000000000000
[ 192.665061] FS: 0000000000000000(0000) GS:ffff88806cc00000(0000) knlGS:0000000000000000
[ 192.665549] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 192.665896] CR2: 00007f34b0ccd274 CR3: 0000000006a7e000 CR4: 0000000000750ef0
[ 192.666350] PKRU: 55555554
[ 192.666532] Call Trace:
[ 192.666690] <IRQ>
[ 192.666824] ? show_regs+0xa2/0xb0
[ 192.667056] ? watchdog_timer_fn+0x507/0x6a0
[ 192.667325] ? __pfx_watchdog_timer_fn+0x10/0x10
[ 192.667620] ? __hrtimer_run_queues+0x61a/0xba0
[ 192.667920] ? __pfx___hrtimer_run_queues+0x10/0x10
[ 192.668229] ? ktime_get_update_offsets_now+0x25b/0x340
[ 192.668553] ? hrtimer_interrupt+0x326/0x7b0
[ 192.668832] ? __sysvec_apic_timer_interrupt+0x101/0x390
[ 192.669163] ? sysvec_apic_timer_interrupt+0x9c/0xd0
[ 192.669466] </IRQ>
[ 192.669605] <TASK>
[ 192.669745] ? asm_sysvec_apic_timer_interrupt+0x1f/0x30
[ 192.670092] ? kfree_skb_reason+0x2af/0x2f0
[ 192.670360] ? unix_gc+0x98f/0x1120
[ 192.670591] ? __pfx___sanitizer_cov_trace_pc+0x10/0x10
[ 192.670926] ? unix_gc+0x9ae/0x1120
[ 192.671155] ? __pfx_unix_gc+0x10/0x10
[ 192.671402] ? mark_held_locks+0xb7/0x140
[ 192.671662] ? skb_dequeue+0x168/0x1e0
[ 192.671901] ? __this_cpu_preempt_check+0x20/0x30
[ 192.672213] ? fib_table_lookup+0xaf0/0x2590
[ 192.672482] ? skb_dequeue+0x168/0x1e0
[ 192.672723] unix_release_sock+0xb7a/0xfd0
[ 192.672988] ? __pfx_unix_release_sock+0x10/0x10
[ 192.673281] ? down_write+0x183/0x1e0
[ 192.673510] ? __pfx_down_write+0x10/0x10
[ 192.673766] unix_release+0x9c/0x100
[ 192.674009] __sock_release+0xba/0x280
[ 192.674250] ? __pfx_sock_close+0x10/0x10
[ 192.674499] sock_close+0x25/0x30
[ 192.674713] __fput+0x273/0xb70
[ 192.674933] ____fput+0x1e/0x30
[ 192.675140] task_work_run+0x1a4/0x2d0
[ 192.675380] ? __pfx_task_work_run+0x10/0x10
[ 192.675644] ? free_nsproxy+0x3c5/0x4f0
[ 192.675885] ? switch_task_namespaces+0xf7/0x130
[ 192.676174] do_exit+0xae1/0x3000
[ 192.676391] ? __this_cpu_preempt_check+0x20/0x30
[ 192.676675] ? lock_release+0x3f8/0x770
[ 192.676925] ? __this_cpu_preempt_check+0x20/0x30
[ 192.677221] ? get_signal+0xa87/0x2740
[ 192.677466] ? __pfx_do_exit+0x10/0x10
[ 192.677704] ? _raw_spin_unlock_irq+0x2b/0x60
[ 192.677983] ? get_signal+0xa87/0x2740
[ 192.678227] ? __this_cpu_preempt_check+0x20/0x30
[ 192.678528] do_group_exit+0xe0/0x2b0
[ 192.678764] get_signal+0x26f7/0x2740
[ 192.679004] ? poll_select_set_timeout+0xf5/0x160
[ 192.679298] ? __pfx_lock_release+0x10/0x10
[ 192.679564] ? __sanitizer_cov_trace_cmp8+0x1c/0x30
[ 192.679869] ? __pfx_get_signal+0x10/0x10
[ 192.680130] ? __sanitizer_cov_trace_const_cmp1+0x1e/0x30
[ 192.680462] ? kvm_clock_read+0x3f/0x60
[ 192.680707] arch_do_signal_or_restart+0x87/0x930
[ 192.681007] ? __pfx_arch_do_signal_or_restart+0x10/0x10
[ 192.681336] ? __this_cpu_preempt_check+0x20/0x30
[ 192.681636] ? lockdep_hardirqs_on+0x8a/0x110
[ 192.681917] syscall_exit_to_user_mode+0x178/0x260
[ 192.682222] do_syscall_64+0x83/0x150
[ 192.682459] entry_SYSCALL_64_after_hwframe+0x6e/0x76
[ 192.682764] RIP: 0033:0x7f34b134296f
[ 192.682990] Code: Unable to access opcode bytes at 0x7f34b1342945.
[ 192.683336] RSP: 002b:00007f34ae9ff9b0 EFLAGS: 00000293 ORIG_RAX: 0000000000000007
[ 192.683766] RAX: fffffffffffffdfc RBX: 0000564d3236d8a0 RCX: 00007f34b134296f
[ 192.684183] RDX: 00000000000007d0 RSI: 0000000000000002 RDI: 00007f349c000b60
[ 192.684601] RBP: 0000564d3236da48 R08: 0000000000000000 R09: 00000000000007d0
[ 192.685017] R10: 0000000000000000 R11: 0000000000000293 R12: 00000000000007d0
[ 192.685423] R13: 0000000000000002 R14: 00007f34b45a6340 R15: 00007f349c000b60
[ 192.685846] </TASK>
[ 192.685989] Kernel panic - not syncing: softlockup: hung tasks
[ 192.686326] CPU: 0 PID: 601 Comm: GUsbEventThread Tainted: G L 6.8.0-rc5-kvm #15
[ 192.686818] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.16.0-0-gd239552ce722-prebuilt.qemu.org 04/01/2014
[ 192.687464] Call Trace:
[ 192.687613] <IRQ>
[ 192.687741] dump_stack_lvl+0xa9/0x110
[ 192.687979] dump_stack+0x19/0x20
[ 192.688186] panic+0x6b9/0x720
[ 192.688374] ? __pfx_panic+0x10/0x10
[ 192.688604] ? watchdog_timer_fn+0x571/0x6a0
[ 192.688867] ? watchdog_timer_fn+0x564/0x6a0
[ 192.689144] watchdog_timer_fn+0x582/0x6a0
[ 192.689390] ? __pfx_watchdog_timer_fn+0x10/0x10
[ 192.689667] __hrtimer_run_queues+0x61a/0xba0
[ 192.689949] ? __pfx___hrtimer_run_queues+0x10/0x10
[ 192.690241] ? ktime_get_update_offsets_now+0x25b/0x340
[ 192.690567] hrtimer_interrupt+0x326/0x7b0
[ 192.690823] __sysvec_apic_timer_interrupt+0x101/0x390
[ 192.691131] sysvec_apic_timer_interrupt+0x9c/0xd0
[ 192.691415] </IRQ>
[ 192.691543] <TASK>
[ 192.691675] asm_sysvec_apic_timer_interrupt+0x1f/0x30
[ 192.691986] RIP: 0010:__sanitizer_cov_trace_pc+0x0/0x70
[ 192.692301] Code: 48 8b 80 d8 1d 00 00 c3 cc cc cc cc 31 c0 5d c3 cc cc cc cc 66 0f 1f 44 00 00 90 90 90 90 90 90 90 90 90 90 90 90 90 90 90 90 8
[ 192.693367] RSP: 0018:ffff888007967798 EFLAGS: 00000246
[ 192.693680] RAX: ffff88800fe12500 RBX: ffffed1000f67eee RCX: ffffffff84b2f34f
[ 192.694101] RDX: 0000000000000000 RSI: ffffffff85103edf RDI: 0000000000000005
[ 192.694505] RBP: ffff888007967918 R08: ffff88800fe12500 R09: ffffed10035c57d5
[ 192.694917] R10: ffffed10035c57d4 R11: ffff88801ae2bea7 R12: ffff888007b3f630
[ 192.695338] R13: ffff888007b3f770 R14: dffffc0000000000 R15: 0000000000000000
[ 192.695757] ? kfree_skb_reason+0x2af/0x2f0
[ 192.696020] ? unix_gc+0x98f/0x1120
[ 192.696237] ? unix_gc+0x9ae/0x1120
[ 192.696461] ? __pfx_unix_gc+0x10/0x10
[ 192.696701] ? mark_held_locks+0xb7/0x140
[ 192.696963] ? skb_dequeue+0x168/0x1e0
[ 192.697196] ? __this_cpu_preempt_check+0x20/0x30
[ 192.697493] ? fib_table_lookup+0xaf0/0x2590
[ 192.697757] ? skb_dequeue+0x168/0x1e0
[ 192.698000] unix_release_sock+0xb7a/0xfd0
[ 192.698264] ? __pfx_unix_release_sock+0x10/0x10
[ 192.698548] ? down_write+0x183/0x1e0
[ 192.698771] ? __pfx_down_write+0x10/0x10
[ 192.699026] unix_release+0x9c/0x100
[ 192.699254] __sock_release+0xba/0x280
[ 192.699490] ? __pfx_sock_close+0x10/0x10
[ 192.699742] sock_close+0x25/0x30
[ 192.699965] __fput+0x273/0xb70
[ 192.700170] ____fput+0x1e/0x30
[ 192.700365] task_work_run+0x1a4/0x2d0
[ 192.700603] ? __pfx_task_work_run+0x10/0x10
[ 192.700864] ? free_nsproxy+0x3c5/0x4f0
[ 192.701106] ? switch_task_namespaces+0xf7/0x130
[ 192.701387] do_exit+0xae1/0x3000
[ 192.701592] ? __this_cpu_preempt_check+0x20/0x30
[ 192.701879] ? lock_release+0x3f8/0x770
[ 192.702128] ? __this_cpu_preempt_check+0x20/0x30
[ 192.702420] ? get_signal+0xa87/0x2740
[ 192.702662] ? __pfx_do_exit+0x10/0x10
[ 192.702907] ? _raw_spin_unlock_irq+0x2b/0x60
[ 192.703185] ? get_signal+0xa87/0x2740
[ 192.703428] ? __this_cpu_preempt_check+0x20/0x30
[ 192.703723] do_group_exit+0xe0/0x2b0
[ 192.703966] get_signal+0x26f7/0x2740
[ 192.704203] ? poll_select_set_timeout+0xf5/0x160
[ 192.704490] ? __pfx_lock_release+0x10/0x10
[ 192.704763] ? __sanitizer_cov_trace_cmp8+0x1c/0x30
[ 192.705072] ? __pfx_get_signal+0x10/0x10
[ 192.705324] ? __sanitizer_cov_trace_const_cmp1+0x1e/0x30
[ 192.705649] ? kvm_clock_read+0x3f/0x60
[ 192.705900] arch_do_signal_or_restart+0x87/0x930
[ 192.706207] ? __pfx_arch_do_signal_or_restart+0x10/0x10
[ 192.706538] ? __this_cpu_preempt_check+0x20/0x30
[ 192.706833] ? lockdep_hardirqs_on+0x8a/0x110
[ 192.707120] syscall_exit_to_user_mode+0x178/0x260
[ 192.707418] do_syscall_64+0x83/0x150
[ 192.707652] entry_SYSCALL_64_after_hwframe+0x6e/0x76
[ 192.707978] RIP: 0033:0x7f34b134296f
[ 192.708199] Code: Unable to access opcode bytes at 0x7f34b1342945.
[ 192.708569] RSP: 002b:00007f34ae9ff9b0 EFLAGS: 00000293 ORIG_RAX: 0000000000000007
[ 192.709020] RAX: fffffffffffffdfc RBX: 0000564d3236d8a0 RCX: 00007f34b134296f
[ 192.709449] RDX: 00000000000007d0 RSI: 0000000000000002 RDI: 00007f349c000b60
[ 192.709873] RBP: 0000564d3236da48 R08: 0000000000000000 R09: 00000000000007d0
[ 192.710313] R10: 0000000000000000 R11: 0000000000000293 R12: 00000000000007d0
[ 192.710746] R13: 0000000000000002 R14: 00007f34b45a6340 R15: 00007f349c000b60
[ 192.711205] </TASK>
[ 192.711808] Kernel Offset: disabled
[ 192.712120] ---[ end Kernel panic - not syncing: softlockup: hung tasks ]---
"
Best Regards,
Thanks!
>
> Thanks,
> Jason
>
> >
> > Thanks!
> >
> > ---