Why mce panic @4.18 kernel pass @5.15 kernel

Question

When testing inject uncorrected error, it crashed in CentOS kernel 4.18 but pass in upstream kernel 5.15

This issue may relate to:

inject uncorrected error then system reboot

Why kernel panic when panic_on_warn==0

Summary the call trace:

[   242.337362] kernel BUG at arch/x86/kernel/cpu/mce/core.c:1364!

I checked this kernel (CentOS 8.5.2111 kernel), the line 1364 is:

1363 out_ist:
1364    nmi_exit();

P.S The code in the CentOS kernel looks quite different from the upstream kernel.

then trigger BUG_ON(!in_nmi()); ( in my understanding )

#define nmi_exit()                      \
    do {                            \
        lockdep_hardirq_exit();             \
        rcu_nmi_exit();                 \
        BUG_ON(!in_nmi());              \
        __preempt_count_sub(NMI_OFFSET + HARDIRQ_OFFSET);   \
        ftrace_nmi_exit();              \
        lockdep_on();                   \
        printk_nmi_exit();              \
        arch_nmi_exit();                \
    } while (0)

Here is the CentOS 4.18 kernel download:

https://vault.centos.org/8.5.2111/BaseOS/Source/SPackages/kernel-4.18.0-348.el8.src.rpm

overall log:

[root@localhost GreenTea]# ./einj_mem_uc -f 'single'

0: single   vaddr = xxxxxxxx paddr = xxxxx[   242.248140] core: Uncorrected hardware memory error in user-access at xxxxxxxx
[   242.248410] {1}[Hardware Error]: Hardware error from APEI Generic Hardware Error Source: 0
[   242.257296] BUG: scheduling while atomic: einj_mem_uc/9237/0x00110000
a400
[   242.258700] Memory failure: xxxx: Killing einj_mem_uc:9237 due to hardware memory corruption
[   242.267021] {1}[Hardware Error]: event severity: recoverable
[   242.267022] {1}[Hardware Error]:  Error 0, type: recoverable
[   242.267023] {1}[Hardware Error]:  fru_text: Card01, ChnG, DIMM0
[   242.267023] {1}[Hardware Error]:   section_type: memory error
[   242.267024] {1}[Hardware Error]:   error_status: 0x0000000000000400
[   242.267024] {1}[Hardware Error]:   physical_address: 0x00000004805da400
[   242.267026] {1}[Hardware Error]:   node: 0 card: 6 module: 0 rank: 0 bank: 16 device: 0 row: 8835 column: 16 
[   242.267026] {1}[Hardware Error]:   error_type: 4, single-symbol chipkill ECC
[   242.267027] {1}[Hardware Error]:   DIMM location: _Node0_Channel6_Dimm0 CPU0_G0 
[   242.267053] Memory failure: xxxxx: already hardware poisoned
[   242.274392] Memory failure: xxxxx: recovery action for dirty LRU page: Recovered
[   242.285519] EDAC skx MC3: HANDLING MCE MEMORY ERROR
[   242.318662] ------------[ cut here ]------------
[   242.326171] EDAC skx MC3: CPU 0: Machine Check Event: 0x0 Bank 255: 0xb40000000000009f
[   242.337362] kernel BUG at arch/x86/kernel/cpu/mce/core.c:1364!
[   242.337366] invalid opcode: 0000 [#1] SMP NOPTI
[   242.337367] CPU: 139 PID: 9237 Comm: einj_mem_uc Kdump: loaded Tainted: G   M    W        --------- -  - 4.18.0-348.el8.x86_64 #1
[   242.337368] Hardware name: Foo Inc. Foo  BIOS 4C012 01/21/2022
[   242.345383] EDAC skx MC3: TSC 0x0 
[   242.345383] EDAC skx MC3: ADDR 0x4805da400 
[   242.353765] RIP: 0010:do_machine_check+0xb10/0xc70
[   242.353766] Code: 42 bf f4 01 00 00 e8 df 92 92 00 8b 05 b9 cb e2 01 41 39 c7 7e 2d 4c 89 ee 4c 89 e7 e8 09 ec ff ff 85 c0 74 dc e9 17 fe ff ff <0f> 0b 0f 0b 8b 35 1a 6c 7e 01 e9 05 fb ff ff c7 05 87 cb e2 01 01
[   242.353766] RSP: 0018:ff2f652d53383e58 EFLAGS: 00010046
[   242.353767] RAX: 0000000080000000 RBX: 00000000004805da RCX: 3ffffffffffffffe
[   242.353768] RDX: ff121aa3ffbeaf40 RSI: 0000000000000001 RDI: ff121a69005db000
[   242.360497] EDAC skx MC3: MISC 0x0 
[   242.360498] EDAC skx MC3: PROCESSOR 0:0x806f6 TIME 1529665988 SOCKET 0 APIC 0x0
[   242.369175] RBP: ff121a65a70f3c80 R08: ff121a6480000010 R09: 0000000000000000
[   242.369176] R10: 0000000000000002 R11: 0000000000000003 R12: 0000000000000000
[   242.369176] R13: 0000000000000000 R14: ff121aa3ffb95ce0 R15: 0000000000000014
[   242.369177] FS:  00007fe1bde23640(0000) GS:ff121aa3ffbc0000(0000) knlGS:0000000000000000
[   242.369177] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   242.369177] CR2: 00007f50808270cc CR3: 00000001d0118001 CR4: 0000000000771ee0
[   242.369178] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[   242.369178] DR3: 0000000000000000 DR6: 00000000fffe07f0 DR7: 0000000000000400
[   242.369179] PKRU: 55555554
[   242.369179] Call Trace:
[   242.369182]  ? machine_check+0x25/0x40
[   242.374751] EDAC MC3: 1 UE memory read error on CPU_SrcID#0_MC#3_Chan#0_DIMM#0 (channel:0 slot:0 page:0x4805da offset:0x400 grain:32 -  err_code:0x0000:0x009f  SystemAddress:0x4805da400 ProcessorSocketId:0x0 MemoryControllerId:0x3 ChannelAddress:0x800bb400 ChannelId:0x0 RankAddress:0x2002ed00 PhysicalRankId:0x0 DimmSlotId:0x0 DimmRankId:0x0 Row:0x2283 Column:0x10 Bank:0x0 BankGroup:0x4 ChipSelect:0x0)
[   242.380013]  machine_check+0x2f/0x40
[   242.380015] RIP: 0033:0x403f5b
[   242.380015] Code: 89 05 cd 37 20 00 8b 05 c7 37 20 00 c3 53 48 8b 1d 92 37 20 00 e8 2b d5 ff ff 48 8d 84 1b 76 14 40 00 48 f7 db 48 21 d8 5b c3 <0f> be 07 c3 0f be 07 0f be 57 01 01 d0 c3 48 8b 47 ff c3 c6 07 61
[   242.380016] RSP: 002b:00007ffcfb9e6098 EFLAGS: 00010206
[   242.380016] RAX: 0000000000607280 RBX: 0000000000607280 RCX: 0000000001b7b010
[   242.380017] RDX: 0000000000000000 RSI: 0000000000000001 RDI: 00007fe1bde21400
[   242.380017] RBP: 00007fe1bde21400 R08: 0000000001b7b04a R09: 0000000000000000
[   242.380017] R10: 0000000000000000 R11: 0000000000000206 R12: 0000000000000001
[   242.380018] R13: 00007ffcfb9e6410 R14: 0000000000000000 R15: 0000000000000000
[   242.380018] Modules linked in: einj xt_CHECKSUM ipt_MASQUERADE xt_conntrack ipt_REJECT nft_compat nf_nat_tftp nft_objref nf_conntrack_tftp nft_counter tun bridge stp llc nft_fib_inet nft_fib_ipv4 nft_fib_ipv6 nft_fib nft_reject_inet nf_reject_ipv4 nf_reject_ipv6 nft_reject nft_ct nf_tables_set nft_chain_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 ip_set nf_tables nfnetlink sunrpc vfat fat sd_mod sg intel_rapl_msr intel_rapl_common i10nm_edac nfit libnvdimm x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel iTCO_wdt intel_pmt_telemetry intel_pmt_crashlog iTCO_vendor_support intel_pmt_class kvm irqbypass crct10dif_pclmul crc32_pclmul ghash_clmulni_intel pcspkr rapl intel_th_gth ipmi_ssif uas intel_th_pci isst_if_mbox_pci isst_if_mmio idxd usb_storage joydev intel_pmt intel_th i2c_i801 isst_if_common i2c_ismt wmi acpi_ipmi ipmi_si ipmi_devintf ipmi_msghandler acpi_pad acpi_power_meter xfs libcrc32c ast i2c_algo_bit drm_vram_helper drm_kms_helper syscopyarea sysfillrect
[   242.380033]  sysimgblt fb_sys_fops drm_ttm_helper ttm crc32c_intel nvme ahci drm nvme_core libahci libata t10_pi pinctrl_emmitsburg dm_mirror dm_region_hash dm_log dm_mod fuse
[    0.000000] Linux version 4.18.0-348.el8.x86_64 (mockbuild@x86-vm-09.build.eng.bos.redhat.com) (gcc version 8.5.0 20210514 (Red Hat 8.5.0-3) (GCC)) #1 SMP Mon Oct 4 12:17:22 EDT 2021

It seems (?) nmi_exit(); caused this panic, but why opcode is 0000?

What is the root cause of this log kernel BUG at arch/x86/kernel/cpu/mce/core.c:1364! and why kernel reboot during call trace.

20220908 Update:

#define nmi_enter()                     \
    do {                            \
        arch_nmi_enter();               \
        printk_nmi_enter();             \
        lockdep_off();                  \
        ftrace_nmi_enter();             \
        BUG_ON(in_nmi() == NMI_MASK);           \
        __preempt_count_add(NMI_OFFSET + HARDIRQ_OFFSET);   \
        rcu_nmi_enter();                \
        lockdep_hardirq_enter();            \
    } while (0)

#define nmi_exit()                      \
    do {                            \
        lockdep_hardirq_exit();             \
        rcu_nmi_exit();                 \
        BUG_ON(!in_nmi());              \
        __preempt_count_sub(NMI_OFFSET + HARDIRQ_OFFSET);   \
        ftrace_nmi_exit();              \
        lockdep_on();                   \
        printk_nmi_exit();              \
        arch_nmi_exit();                \
    } while (0)

In my understanding, if second entry of do_machine_check() happened, it should not cause BUG_ON(!in_nmi()) triggered.

ex:

__preempt_count_add(NMI_OFFSET + HARDIRQ_OFFSET);
__preempt_count_add(NMI_OFFSET + HARDIRQ_OFFSET);
BUG_ON(!in_nmi());

__preempt_count_add is not an OR operation.

static inline void __preempt_count_add(int val)
{
    u32 pc = READ_ONCE(current_thread_info()->preempt.count);
    pc += val;
    WRITE_ONCE(current_thread_info()->preempt.count, pc);
}

Others:

Please note, there is no this line in the PASS ( upstream kernel 5.15 ) log.

[   242.257296] BUG: scheduling while atomic: einj_mem_uc/9237/0x00110000

Answer 1

Based on a couple facts listed below, my working theory is a uncorrected hardware memory error (UHME) occurred resulting in a NMI. During processing the NMI, a page fault happens. There may an order of operations issue with the increasing the preempt count or a bug allowing a page fault inside the nmi_handler.

• CentOS 4.18.0.348 is very different code from mainline Linux 4.18.0 code base. Many features from 5.x releases have been backported into 4.18.0.x for CentOS. This code has only RedHat review, so there may be a higher chance of a bug.

My studied opinion is this diagram demonstrates the flow of the event.

1. Userland einj_mem_uc.
2. Start nmi_enter(), in_nmi() is false until preempt_count_add() sets to true.
3. Inside the nmi handler begins working the NMI interrupt.
4. A page fault happens, we jump to page fault handler.
5. The page fault handler leaves in_nmi() true and exits with iret.
6. The Intel iret flaw force clears the in_nmi() value to false.
7. Returning to the hmi handler, the in_nmi() is false inside the handler.
8. The nmi handler returns with nmi_exit, triggering the BUG_ON(!in_nmi()) check.
9. This results in panic then halt or reboot.

I have a hunch that mainline 4.18.1 would also work like the 5.15 kernel.

Initially I had done the source code work for this other question.

Answer 2

As I has suspected when commenting & answering your very first related question you are typically facing a double fault. I add here : and possibly a triple. (under the 4.18)

Regarding the 4.18 only (since this kernel option is only available up to 5.7) I suggest you check your kernel .config file for the setting of CONFIG_DOUBLEFAULT that should enable the doublefault exception handler.
(Please do take note of the comment : Disabling this option... might cause you much additional grey hair. ;-) ) If it is not set then the kernel will be just incapable to handle that situation and will silently reboot.
If you get it actually set then your 4.18 is actually facing a triple fault. (I think that is unlikely since I would have expected at least the begenning of a second trace dump) => I suspect CONFIG_DOUBLEFAULT not set in your 4.18 config.

---

Why doesn't it happen under 5.15 :

From 5.8, if, previous way of handling doublefaults is kept for x32 arches, x86_64 arches benefit from a feature (which is not available on i386) : The Interrupt Stack Table. Which gives the ability to automatically switch to a new stack for designated events such as double fault or NMI.
Since the initial memory failure concerns the stack (scheduling in atomic context) a doublefault occurs when tracedumping and the triple when retracedumping.
Whereas from 5.8 on x86_64, the possibility to switch to some new stack (free of memory error) helps handling the doublefault gracefully.

Answer 3

Think it is not related to the kernel, but simply a HW memory error whereby you hit that memory address with the newer kernel and not (yet) with the old one. Have you performed a mem test?

Answer 4

It seems BUG_ON(true) will trigger a kernel BUG which is invalid opcode 0000

If yes in this case, then

BUG_ON(!in_nmi());

trigger this dump.