BUG: soft lockup in __kmalloc_node() with KFENCE enabled

[Andrea Righi]

I can systematically reproduce the following soft lockup w/ the latest
5.15-rc4 kernel (and all the 5.14, 5.13 and 5.12 kernels that I've
tested so far).

I've found this issue by running systemd autopkgtest (I'm using the
latest systemd in Ubuntu - 248.3-1ubuntu7 - but it should happen with
any recent version of systemd).

I'm running this test inside a local KVM instance and apparently systemd
is starting up its own KVM instances to run its tests, so the context is
a nested KVM scenario (even if I don't think the nested KVM part really
matters).

Here's the oops:

[ 36.466565] watchdog: BUG: soft lockup - CPU#0 stuck for 26s! [udevadm:333]
[ 36.466565] Modules linked in: btrfs blake2b_generic zstd_compress raid10 raid456 async_raid6_recov async_memcpy async_pq async_xor async_tx xor raid6_pq libcrc32c raid1 raid0 multipath linear psmouse floppy
[ 36.466565] CPU: 0 PID: 333 Comm: udevadm Not tainted 5.15-rc4
[ 36.466565] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.14.0-2 04/01/2014
[ 36.466565] RIP: 0010:__kmalloc_node+0xcf/0x370
[ 36.466565] Code: 00 85 c0 74 20 49 8b 45 00 a8 03 0f 85 8e 02 00 00 65 48 ff 08 e8 01 7a e3 ff 45 31 ff e9 a3 00 00 00 45 31 ed 4d 85 f6 74 f0 <0f> 1f 44 00 00 48 c7 45 c8 00 00 00 00 4d 8b 06 65 4c 03 05 19 87
[ 36.466565] RSP: 0018:ffffb512802c3aa8 EFLAGS: 00000286
[ 36.466565] RAX: 0000000000000000 RBX: 0000000000000dc0 RCX: 0000000000000000
[ 36.466565] RDX: 0000000000000000 RSI: 0000000000000dc0 RDI: ffff998601042700
[ 36.466565] RBP: ffffb512802c3af0 R08: ffffeb90800b5c00 R09: 0000000000000000
[ 36.466565] R10: 0000000000000293 R11: ffff99861e02f448 R12: 0000000000000dc0
[ 36.466565] R13: 0000000000000000 R14: ffff998601042700 R15: ffffffff8b519c4d
[ 36.466565] FS: 00007f08d0674d00(0000) GS:ffff99861e000000(0000) knlGS:0000000000000000
[ 36.466565] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 36.466565] CR2: 00005622f86e3108 CR3: 00000000033c8000 CR4: 00000000000006f0
[ 36.466565] Call Trace:
[ 36.466565] memcg_alloc_page_obj_cgroups+0x3d/0x90
[ 36.466565] allocate_slab+0xc1/0x440
[ 36.466565] ? get_any_partial+0x85/0x190
[ 36.466565] new_slab+0x3a/0x60
[ 36.466565] ___slab_alloc+0x562/0x6b0
[ 36.466565] ? __alloc_file+0x28/0xe0
[ 36.466565] ? __alloc_file+0x28/0xe0
[ 36.466565] ? dput+0x84/0x180
[ 36.466565] ? step_into+0x312/0x380
[ 36.466565] kmem_cache_alloc+0x299/0x2d0
[ 36.466565] ? __alloc_file+0x28/0xe0
[ 36.466565] __alloc_file+0x28/0xe0
[ 36.466565] alloc_empty_file+0x45/0xc0
[ 36.466565] path_openat+0x47/0x2b0
[ 36.466565] do_filp_open+0xb2/0x150
[ 36.466565] ? putname+0x55/0x60
[ 36.466565] ? __check_object_size.part.0+0x128/0x150
[ 36.466565] ? __check_object_size+0x19/0x20
[ 36.466565] ? alloc_fd+0x53/0x170
[ 36.466565] do_sys_openat2+0x9b/0x160
[ 36.466565] __x64_sys_openat+0x55/0x90
[ 36.466565] do_syscall_64+0x5c/0xc0
[ 36.466565] ? exit_to_user_mode_prepare+0x37/0xb0
[ 36.466565] ? syscall_exit_to_user_mode+0x27/0x50
[ 36.466565] ? __x64_sys_newfstatat+0x1c/0x20
[ 36.466565] ? do_syscall_64+0x69/0xc0
[ 36.466565] ? do_syscall_64+0x69/0xc0
[ 36.466565] ? do_syscall_64+0x69/0xc0
[ 36.466565] entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 36.466565] RIP: 0033:0x7f08d0c0466b
[ 36.466565] Code: 25 00 00 41 00 3d 00 00 41 00 74 4b 64 8b 04 25 18 00 00 00 85 c0 75 67 44 89 e2 48 89 ee bf 9c ff ff ff b8 01 01 00 00 0f 05 <48> 3d 00 f0 ff ff 0f 87 91 00 00 00 48 8b 4c 24 28 64 48 2b 0c 25
[ 36.466565] RSP: 002b:00007ffe10be08f0 EFLAGS: 00000246 ORIG_RAX: 0000000000000101
[ 36.466565] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f08d0c0466b
[ 36.466565] RDX: 0000000000080000 RSI: 00007ffe10be0a70 RDI: 00000000ffffff9c
[ 36.466565] RBP: 00007ffe10be0a70 R08: fefefefefefefeff R09: fefefeff716e6c71
[ 36.466565] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000080000
[ 36.466565] R13: 00005622f86e2520 R14: 0000000000000003 R15: 00007ffe10be0990

It looks like this is pointing at asm_volatile_goto():

crash> gdb list *(__kmalloc_node+0xcf)
0xffffffff8b4f8e3f is in __kmalloc_node (/build/impish/arch/x86/include/asm/jump_label.h:27).
22
23 #ifdef CONFIG_STACK_VALIDATION
24
25 static __always_inline bool arch_static_branch(struct static_key *key, bool branch)
26 {
27 asm_volatile_goto("1:"
28 "jmp %l[l_yes] # objtool NOPs this \n\t"
29 JUMP_TABLE_ENTRY
30 : : "i" (key), "i" (2 | branch) : : l_yes);
31

And it seems that we're hitting an int3:

crash> bt 1
PID: 1 TASK: ffff998601248000 CPU: 3 COMMAND: "systemd"
[exception RIP: poke_int3_handler+89]
RIP: ffffffff8be6ac89 RSP: ffffb51280013b80 RFLAGS: 00000046
RAX: 000000008c0010a7 RBX: 0000000000000000 RCX: ffffb51280013ba8
RDX: 0000000000000000 RSI: ffffffff8c000a99 RDI: ffffb51280013ba8
RBP: ffffb51280013b98 R8: 0000000000000000 R9: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: ffffb51280013ba8
R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
CS: 0010 SS: 0018
#0 [ffffb51280013b80] exc_int3 at ffffffff8be69e80
#1 [ffffb51280013ba0] asm_exc_int3 at ffffffff8c000aa1
#2 [ffffb51280013c28] __kmalloc_node at ffffffff8b4f8e40
#3 [ffffb51280013c80] __kmalloc_node at ffffffff8b4f8e16
#4 [ffffb51280013cd8] kvmalloc_node at ffffffff8b4885c8
#5 [ffffb51280013d00] seq_read_iter at ffffffff8b56139c
#6 [ffffb51280013d60] seq_read at ffffffff8b561585
#7 [ffffb51280013de8] vfs_read at ffffffff8b531b0f
#8 [ffffb51280013e28] ksys_read at ffffffff8b5321d7
#9 [ffffb51280013e68] __x64_sys_read at ffffffff8b532269
#10 [ffffb51280013e78] do_syscall_64 at ffffffff8be6900c
#11 [ffffb51280013f50] entry_SYSCALL_64_after_hwframe at ffffffff8c00007c
RIP: 00007fc076f2e912 RSP: 00007ffde04ba888 RFLAGS: 00000246
RAX: ffffffffffffffda RBX: 000055e3b310bc30 RCX: 00007fc076f2e912
RDX: 0000000000000400 RSI: 000055e3b31415e0 RDI: 0000000000000029
RBP: 00007fc077031560 R8: 0000000000000029 R9: 0000000000000050
R10: 0000000000001000 R11: 0000000000000246 R12: 00007fc07679a6c0
R13: 0000000000000d68 R14: 00007fc077030960 R15: 0000000000000d68
ORIG_RAX: 0000000000000000 CS: 0033 SS: 002b

If I disable CONFIG_KFENCE the soft lockup doesn't happen and systemd
autotest completes just fine.

We've decided to disable KFENCE in the latest Ubuntu Impish kernel
(5.13) for now, because of this issue, but I'm still investigating
trying to better understand the problem.

Any hint / suggestion?

Thanks,
-Andrea

[Marco Elver]

On Sun, 10 Oct 2021 at 15:53, Andrea Righi <andrea...@canonical.com> wrote:
> I can systematically reproduce the following soft lockup w/ the latest
> 5.15-rc4 kernel (and all the 5.14, 5.13 and 5.12 kernels that I've
> tested so far).
>
> I've found this issue by running systemd autopkgtest (I'm using the
> latest systemd in Ubuntu - 248.3-1ubuntu7 - but it should happen with
> any recent version of systemd).
>
> I'm running this test inside a local KVM instance and apparently systemd
> is starting up its own KVM instances to run its tests, so the context is
> a nested KVM scenario (even if I don't think the nested KVM part really
> matters).
>
> Here's the oops:
>
> [ 36.466565] watchdog: BUG: soft lockup - CPU#0 stuck for 26s! [udevadm:333]
> [ 36.466565] Modules linked in: btrfs blake2b_generic zstd_compress raid10 raid456 async_raid6_recov async_memcpy async_pq async_xor async_tx xor raid6_pq libcrc32c raid1 raid0 multipath linear psmouse floppy
> [ 36.466565] CPU: 0 PID: 333 Comm: udevadm Not tainted 5.15-rc4
> [ 36.466565] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.14.0-2 04/01/2014

[...]

>
> If I disable CONFIG_KFENCE the soft lockup doesn't happen and systemd
> autotest completes just fine.
>
> We've decided to disable KFENCE in the latest Ubuntu Impish kernel
> (5.13) for now, because of this issue, but I'm still investigating
> trying to better understand the problem.
>
> Any hint / suggestion?

Can you confirm this is not a QEMU TCG instance? There's been a known
issue with it: https://bugs.launchpad.net/qemu/+bug/1920934

One thing that I've been wondering is, if we can make
CONFIG_KFENCE_STATIC_KEYS=n the default, because the static keys
approach is becoming more trouble than it's worth. It requires us to
re-benchmark the defaults. If you're thinking of turning KFENCE on by
default (i.e. CONFIG_KFENCE_SAMPLE_INTERVAL non-zero), you could make
this decision for Ubuntu with whatever sample interval you choose.
We've found that for large deployments 500ms or above is more than
adequate.

Thanks,
-- Marco

[Andrea Righi]

It looks like systemd is running qemu-system-x86 without any "accel"
options, so IIUC the instance shouldn't use TCG. Is this a correct
assumption or is there a better way to check?

>
> One thing that I've been wondering is, if we can make
> CONFIG_KFENCE_STATIC_KEYS=n the default, because the static keys
> approach is becoming more trouble than it's worth. It requires us to
> re-benchmark the defaults. If you're thinking of turning KFENCE on by
> default (i.e. CONFIG_KFENCE_SAMPLE_INTERVAL non-zero), you could make
> this decision for Ubuntu with whatever sample interval you choose.
> We've found that for large deployments 500ms or above is more than
> adequate.

Another thing that I forgot to mention is that with
CONFIG_KFENCE_STATIC_KEYS=n the soft lockup doesn't seem to happen.

Thanks,
-Andrea

[Marco Elver]

AFAIK, the default is TCG if nothing else is requested. What was the
command line?

> > One thing that I've been wondering is, if we can make
> > CONFIG_KFENCE_STATIC_KEYS=n the default, because the static keys
> > approach is becoming more trouble than it's worth. It requires us to
> > re-benchmark the defaults. If you're thinking of turning KFENCE on by
> > default (i.e. CONFIG_KFENCE_SAMPLE_INTERVAL non-zero), you could make
> > this decision for Ubuntu with whatever sample interval you choose.
> > We've found that for large deployments 500ms or above is more than
> > adequate.
>
> Another thing that I forgot to mention is that with
> CONFIG_KFENCE_STATIC_KEYS=n the soft lockup doesn't seem to happen.

Thanks for confirming.

Thanks,
-- Marco

[Andrea Righi]

This is the full command line of what systemd is running:

/bin/qemu-system-x86_64 -smp 4 -net none -m 512M -nographic -vga none -kernel /boot/vmlinuz-5.15-rc4 -drive format=raw,cache=unsafe,file=/var/tmp/systemd-test.sI1nrh/badid.img -initrd /boot/initrd.img-5.15-rc4 -append root=/dev/sda1 rw raid=noautodetect rd.luks=0 loglevel=2 init=/lib/systemd/systemd console=ttyS0 selinux=0 SYSTEMD_UNIT_PATH=/usr/lib/systemd/tests/testdata/testsuite-14.units:/usr/lib/systemd/tests/testdata/units: systemd.unit=testsuite.target systemd.wants=testsuite-14.service systemd.wants=end.service

And this is running inside a KVM instance (so a nested KVM scenario).

-Andrea

[Dmitry Vyukov]

Hi Andrea,

I think you need to pass -enable-kvm to make it "nested KVM scenario",
otherwise it's TCG emulation.

You seem to use the default 20s stall timeout. FWIW syzbot uses 160
secs timeout for TCG emulation to avoid false positive warnings:
https://github.com/google/syzkaller/blob/838e7e2cd9228583ca33c49a39aea4d863d3e36d/dashboard/config/linux/upstream-arm64-kasan.config#L509
There are a number of other timeouts raised as well, some as high as
420 seconds.

[Andrea Righi]

So, IIUC I shouldn't hit the QEMU TCG issue mentioned by Marco, right?

>
> You seem to use the default 20s stall timeout. FWIW syzbot uses 160
> secs timeout for TCG emulation to avoid false positive warnings:
> https://github.com/google/syzkaller/blob/838e7e2cd9228583ca33c49a39aea4d863d3e36d/dashboard/config/linux/upstream-arm64-kasan.config#L509
> There are a number of other timeouts raised as well, some as high as
> 420 seconds.

I see, I'll try with these settings and see if I can still hit the soft
lockup messages.

Thanks,
-Andrea

[Andrea Righi]

On Mon, Oct 11, 2021 at 11:23:32AM +0200, Andrea Righi wrote:
...

> > You seem to use the default 20s stall timeout. FWIW syzbot uses 160
> > secs timeout for TCG emulation to avoid false positive warnings:
> > https://github.com/google/syzkaller/blob/838e7e2cd9228583ca33c49a39aea4d863d3e36d/dashboard/config/linux/upstream-arm64-kasan.config#L509
> > There are a number of other timeouts raised as well, some as high as
> > 420 seconds.
>
> I see, I'll try with these settings and see if I can still hit the soft
> lockup messages.

Still getting soft lockup messages even with the new timeout settings:

[ 462.663766] watchdog: BUG: soft lockup - CPU#2 stuck for 430s! [systemd-udevd:168]
[ 462.755758] watchdog: BUG: soft lockup - CPU#3 stuck for 430s! [systemd-udevd:171]
[ 924.663765] watchdog: BUG: soft lockup - CPU#2 stuck for 861s! [systemd-udevd:168]
[ 924.755767] watchdog: BUG: soft lockup - CPU#3 stuck for 861s! [systemd-udevd:171]

-Andrea

[Marco Elver]

The lockups are expected if you're hitting the TCG bug I linked. Try
to pass '-enable-kvm' to the inner qemu instance (my bad if you
already have), assuming that's somehow easy to do.

Thanks,
-- Marco

[Andrea Righi]

If I add '-enable-kvm' I can triggering other random panics (almost
immediately), like this one for example:

[21383.189976] BUG: kernel NULL pointer dereference, address: 0000000000000098
[21383.190633] #PF: supervisor read access in kernel mode
[21383.191072] #PF: error_code(0x0000) - not-present page
[21383.191529] PGD 0 P4D 0
[21383.191771] Oops: 0000 [#1] SMP NOPTI
[21383.192113] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.15-rc4
[21383.192757] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.14.0-2 04/01/2014
[21383.193414] RIP: 0010:wb_timer_fn+0x44/0x3c0
[21383.193855] Code: 41 8b 9c 24 98 00 00 00 41 8b 94 24 b8 00 00 00 41 8b 84 24 d8 00 00 00 4d 8b 74 24 28 01 d3 01 c3 49 8b 44 24 60 48 8b 40 78 <4c> 8b b8 98 00 00 00 4d 85 f6 0f 84 c4 00 00 00 49 83 7c 24 30 00
[21383.195366] RSP: 0018:ffffbcd140003e68 EFLAGS: 00010246
[21383.195842] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000004
[21383.196425] RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffff9a3521f4fd80
[21383.197010] RBP: ffffbcd140003e90 R08: 0000000000000000 R09: 0000000000000000
[21383.197594] R10: 0000000000000004 R11: 000000000000000f R12: ffff9a34c75c4900
[21383.198178] R13: ffff9a34c3906de0 R14: 0000000000000000 R15: ffff9a353dc18c00
[21383.198763] FS: 0000000000000000(0000) GS:ffff9a353dc00000(0000) knlGS:0000000000000000
[21383.199558] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[21383.200212] CR2: 0000000000000098 CR3: 0000000005f54000 CR4: 00000000000006f0
[21383.200930] Call Trace:
[21383.201210] <IRQ>
[21383.201461] ? blk_stat_free_callback_rcu+0x30/0x30
[21383.202692] blk_stat_timer_fn+0x138/0x140
[21383.203180] call_timer_fn+0x2b/0x100
[21383.203666] __run_timers.part.0+0x1d1/0x240
[21383.204227] ? kvm_clock_get_cycles+0x11/0x20
[21383.204815] ? ktime_get+0x3e/0xa0
[21383.205309] ? native_apic_msr_write+0x2c/0x30
[21383.205914] ? lapic_next_event+0x20/0x30
[21383.206412] ? clockevents_program_event+0x94/0xf0
[21383.206873] run_timer_softirq+0x2a/0x50
[21383.207260] __do_softirq+0xcb/0x26f
[21383.207647] irq_exit_rcu+0x8c/0xb0
[21383.208010] sysvec_apic_timer_interrupt+0x7c/0x90
[21383.208464] </IRQ>
[21383.208713] asm_sysvec_apic_timer_interrupt+0x12/0x20

I think that systemd autotest used to use -enable-kvm, but then they
removed it, because it was introducing too many problems in the nested
KVM context. I'm not sure about the nature of those problems though, I
can investigate a bit and see if I can understand what they were
exactly.

-Andrea

[Dmitry Vyukov]

This looks like just a plain bug in wb_timer_fn, not something related
to virtualization.
Do you have this fix?
https://syzkaller.appspot.com/bug?extid=aa0801b6b32dca9dda82

[Andrea Righi]

Yes, it looks like I have this:

d152c682f03c block: add an explicit ->disk backpointer to the request_queue

-Andrea

[Dmitry Vyukov]

Then there is another bug in wb_timer_fn I guess...

Don't know if this is the same or something else:
https://lore.kernel.org/lkml/CAHbLzkrdGva2dzO36r62LKv_...@mail.gmail.com/

There also were some data races in this function:
https://groups.google.com/g/syzkaller-upstream-moderation/search?q=wb_timer_fn

[Marco Elver]

On Mon, 11 Oct 2021 at 16:42, Andrea Righi <andrea...@canonical.com> wrote:
> On Mon, Oct 11, 2021 at 12:03:52PM +0200, Marco Elver wrote:
> > On Mon, 11 Oct 2021 at 11:53, Andrea Righi <andrea...@canonical.com> wrote:
> > > On Mon, Oct 11, 2021 at 11:23:32AM +0200, Andrea Righi wrote:
> > > ...
> > > > > You seem to use the default 20s stall timeout. FWIW syzbot uses 160
> > > > > secs timeout for TCG emulation to avoid false positive warnings:
> > > > > https://github.com/google/syzkaller/blob/838e7e2cd9228583ca33c49a39aea4d863d3e36d/dashboard/config/linux/upstream-arm64-kasan.config#L509
> > > > > There are a number of other timeouts raised as well, some as high as
> > > > > 420 seconds.
> > > >
> > > > I see, I'll try with these settings and see if I can still hit the soft
> > > > lockup messages.
> > >
> > > Still getting soft lockup messages even with the new timeout settings:
> > >
> > > [ 462.663766] watchdog: BUG: soft lockup - CPU#2 stuck for 430s! [systemd-udevd:168]
> > > [ 462.755758] watchdog: BUG: soft lockup - CPU#3 stuck for 430s! [systemd-udevd:171]
> > > [ 924.663765] watchdog: BUG: soft lockup - CPU#2 stuck for 861s! [systemd-udevd:168]
> > > [ 924.755767] watchdog: BUG: soft lockup - CPU#3 stuck for 861s! [systemd-udevd:171]
> >
> > The lockups are expected if you're hitting the TCG bug I linked. Try
> > to pass '-enable-kvm' to the inner qemu instance (my bad if you
> > already have), assuming that's somehow easy to do.
>
> If I add '-enable-kvm' I can triggering other random panics (almost
> immediately), like this one for example:

Just FYI: https://lkml.kernel.org/r/20211019102524....@google.com

But you can already flip that switch in your config
(CONFIG_KFENCE_STATIC_KEYS=n), which we recommend as a default now.

As a side-effect it'd also make your QEMU TCG tests pass.

[Andrea Righi]

Cool! Thanks for the update!

And about the other panic that I was getting it seems to be fixed by
this one:
https://lore.kernel.org/lkml/YW6N2qXpBU3oc50q@arighi-desktop/T/#u

-Andrea