Red Hat Enterprise Linux 7 system crashes after errors regarding initializing IPMI devices

Solution Verified - Updated -

Environment

  • Red Hat Enterprise Linux 7
  • Observed but possibly not limited to physical systems with Baseboard Management Controllers (BMCs)

Issue

  • IPMI initialization fails shortly after booting
  • After the system boots fully with the IPMI device initialization failure, the system crashes

Resolution

  • Unfortunately, due to a noted fix for the issue requiring a large amount of change into relevant code paths, the fix is deemed too risky to backport into Red Hat Enterprise Linux 7 kernel.

Root Cause

  • A root cause is not fully known at the time of writing, however, it is strongly suspected the crash is due to memory corruption of the slab caches caused by the IPMI device would still be registered despite device registration failing. The inconsistent state can lead to an inconsistent state in the slab caches for that same CPU eventually causing a system crash.

Diagnostic Steps

  1. Ensure kdump is setup to create vmcores when a system crashes and ensure crash is setup to read the vmcore.

  2. Once the vmcore is loaded, check the kernel ring buffer (the log area of the kernel read by dmesg) via the log command for errors similar to the following:

    crash> log 
[...]
[   76.681179] ipmi_si dmi-ipmi-si.0: Couldn't get irq info: c0.
[   76.681183] ipmi_si dmi-ipmi-si.0: Maybe ok, but ipmi might run very slowly.
[   76.681827] ipmi_si dmi-ipmi-si.0: device id demangle failed: -22
[   76.681841] ipmi_si dmi-ipmi-si.0: Unable to get the device id: -5
[   76.685903] ipmi_si dmi-ipmi-si.0: Unable to register device: error -5
[...]

  3. The kernel ring buffer may also show list corruption warnings while trying to unregister an IPMI device:

    crash> log 
[...]
[   76.685913] WARNING: CPU: 1 PID: 1055 at lib/list_debug.c:56 __list_del_entry+0xc3/0xd0
[   76.685914] list_del corruption, ffff911ffdb64010->prev is LIST_POISON2 (dead000000000200)
[   76.685916] Modules linked in: bridge stp llc overlay(T) sch_ingress bonding [...]
[   76.685976] CPU: 1 PID: 1055 Comm: systemd-udevd Tainted: G               ------------ T 3.10.0-1160.49.1.el7.x86_64 #1
[   76.685978] Hardware name: Dell Inc. PowerEdge R630/02C2CP, BIOS 2.7.1 001/22/2018
[   76.685979] Call Trace:
[   76.685985]  [<ffffffffad783539>] dump_stack+0x19/0x1b
[   76.685989]  [<ffffffffad09b278>] __warn+0xd8/0x100
[   76.685992]  [<ffffffffad09b2ff>] warn_slowpath_fmt+0x5f/0x80
[   76.685995]  [<ffffffffad3a6803>] __list_del_entry+0xc3/0xd0
[   76.686001]  [<ffffffffc0538f9d>] ipmi_unregister_smi+0x5d/0x2ef [ipmi_msghandler]
[   76.686005]  [<ffffffffad4b77ec>] ? dev_err+0x6c/0x90
[   76.686011]  [<ffffffffc05b6776>] shutdown_one_si+0x36/0x220 [ipmi_si]
[   76.686017]  [<ffffffffc05bc045>] try_smi_init+0x8d5/0x1890 [ipmi_si]
[   76.686022]  [<ffffffffc04a9000>] ? 0xffffffffc04a8fff
[   76.686027]  [<ffffffffc04a908d>] init_ipmi_si+0x8d/0x16d [ipmi_si]
[   76.686031]  [<ffffffffad00210a>] do_one_initcall+0xba/0x240
[   76.686036]  [<ffffffffad11e92a>] load_module+0x271a/0x2bb0
[   76.686039]  [<ffffffffad3b4ef0>] ? ddebug_proc_write+0x100/0x100
[   76.686044]  [<ffffffffad11eeaf>] SyS_init_module+0xef/0x140
[   76.686047]  [<ffffffffad796226>] tracesys+0xa6/0xcc
[   76.686049] ---[ end trace 8bca0071d4438797 ]---
[...]
    • In the above backtrace, the kernel is attempting to load the ipmi_si module and in doing so tries to unregister an IPMI device (likely a BMC device) that initially failed to initialize in 2. In doing so, the kernel notes list corruption within IPMI.

  4. The kernel ring buffer may also show a kernel warning regarding procfs file state corruption:

    crash> log 
[...]
[   76.697919] WARNING: CPU: 1 PID: 1055 at fs/proc/generic.c:620 remove_proc_entry+0x18d/0x1a0
[   76.697920] name ''
[   76.697921] Modules linked in: bridge stp llc overlay(T) sch_ingress bonding [...]
[   76.697962] CPU: 1 PID: 1055 Comm: systemd-udevd Tainted: G        W      ------------ T 3.10.0-1160.49.1.el7.x86_64 #1
[   76.697963] Hardware name: Dell Inc. PowerEdge R630/02C2CP, BIOS 2.7.1 001/22/2018
[   76.697964] Call Trace:
[   76.697968]  [<ffffffffad783539>] dump_stack+0x19/0x1b
[   76.697971]  [<ffffffffad09b278>] __warn+0xd8/0x100
[   76.697974]  [<ffffffffad09b2ff>] warn_slowpath_fmt+0x5f/0x80
[   76.697976]  [<ffffffffad2ce3dd>] remove_proc_entry+0x18d/0x1a0
[   76.697981]  [<ffffffffc0532f45>] remove_proc_entries+0x85/0x90 [ipmi_msghandler]
[   76.697986]  [<ffffffffc05391a3>] ipmi_unregister_smi+0x263/0x2ef [ipmi_msghandler]
[   76.697991]  [<ffffffffc05b6776>] shutdown_one_si+0x36/0x220 [ipmi_si]
[   76.697997]  [<ffffffffc05bc045>] try_smi_init+0x8d5/0x1890 [ipmi_si]
[   76.698001]  [<ffffffffc04a9000>] ? 0xffffffffc04a8fff
[   76.698007]  [<ffffffffc04a908d>] init_ipmi_si+0x8d/0x16d [ipmi_si]
[   76.698009]  [<ffffffffad00210a>] do_one_initcall+0xba/0x240
[   76.698013]  [<ffffffffad11e92a>] load_module+0x271a/0x2bb0
[   76.698015]  [<ffffffffad3b4ef0>] ? ddebug_proc_write+0x100/0x100
[   76.698020]  [<ffffffffad11eeaf>] SyS_init_module+0xef/0x140
[   76.698023]  [<ffffffffad796226>] tracesys+0xa6/0xcc
[   76.698025] ---[ end trace 8bca0071d4438798 ]---
[...]
    • In the above, the kernel warns a procfs file (IE a file in /proc) is in an inconsistent state where the name is blank. This warning is near the list corruption in 3. where the the IPMI modules are attempting to clean up the failed IPMI device from 2.

  5. The kernel ring buffer may show a crash ultimately in attempting to allocate from the slab cache on the same CPU as the errors were observed in 3. and 4. above;

    crash> log 
[...]
[  199.383476] BUG: unable to handle kernel paging request at ffffffffffffffff
[  199.391293] IP: [<ffffffffad22b28b>] __kmalloc_node_track_caller+0x17b/0x290
[  199.399200] PGD 78b4c14067 PUD 78b4c16067 PMD 0 
[  199.404401] Oops: 0000 [#1] SMP 
[  199.408033] Modules linked in: cdc_ether usbnet mii joydev udp_diag  [...]
[  199.522065] CPU: 1 PID: 13168 Comm: ss Kdump: loaded Tainted: G        W      ------------ T 3.10.0-1160.49.1.el7.x86_64 #1
[  199.534524] Hardware name: Dell Inc. PowerEdge R630/02C2CP, BIOS 2.7.1 001/22/2018
[  199.542998] task: ffff90dffb55b180 ti: ffff90dfecee4000 task.ti: ffff90dfecee4000
[  199.551373] RIP: 0010:[<ffffffffad22b28b>]  [<ffffffffad22b28b>] __kmalloc_node_track_caller+0x17b/0x290
[  199.561999] RSP: 0018:ffff90dfecee7a48  EFLAGS: 00010246
[  199.567944] RAX: 0000000000000000 RBX: ffff90dfcb559b00 RCX: 0000000000003029
[  199.575930] RDX: 0000000000003028 RSI: 0000000000000000 RDI: 000000000001f1c0
[  199.583916] RBP: ffff90dfecee7a90 R08: ffff911ffee1f1c0 R09: ffff90a1ffc03200
[  199.591902] R10: ffff90a1ffc03200 R11: ffff90dfcb559b00 R12: 00000000000102d0
[  199.599888] R13: 0000000000001c80 R14: ffffffffffffffff R15: 00000000ffffffff
[  199.607874] FS:  00007fd61565e840(0000) GS:ffff911ffee00000(0000) knlGS:0000000000000000
[  199.616930] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  199.623361] CR2: ffffffffffffffff CR3: 00000078a246e000 CR4: 00000000003607e0
[  199.631348] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  199.639334] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[  199.647319] Call Trace:
[  199.650059]  [<ffffffffad6401ad>] ? __alloc_skb+0x8d/0x2d0
[  199.656202]  [<ffffffffad63f111>] __kmalloc_reserve.isra.32+0x31/0x90
[  199.663412]  [<ffffffffad6401ad>] __alloc_skb+0x8d/0x2d0
[  199.669358]  [<ffffffffad227022>] ? kmem_cache_free+0x1e2/0x200
[  199.675984]  [<ffffffffad6911d7>] netlink_dump+0xa7/0x2b0
[  199.682018]  [<ffffffffad691645>] netlink_recvmsg+0x265/0x490
[  199.688451]  [<ffffffffad6364f5>] sock_recvmsg+0xc5/0x100
[  199.694496]  [<ffffffffad1c8f04>] ? __alloc_pages_nodemask+0x184/0xbe0
[  199.701803]  [<ffffffffad637673>] ___sys_recvmsg+0x133/0x2d0
[  199.708137]  [<ffffffffad1ce0be>] ? lru_cache_add+0xe/0x10
[  199.714277]  [<ffffffffad201948>] ? page_add_new_anon_rmap+0xb8/0x170
[  199.721488]  [<ffffffffad1f677d>] ? handle_mm_fault+0xbfd/0xfb0
[  199.728113]  [<ffffffffad638b91>] __sys_recvmsg+0x51/0x90
[  199.734157]  [<ffffffffad638be2>] SyS_recvmsg+0x12/0x20
[  199.740946]  [<ffffffffad796226>] tracesys+0xa6/0xcc
[  199.747427] Code: cf 44 89 e6 4c 89 4d c8 e8 e3 19 01 00 4c 8b 4d c8 49 89 c2 e9 fb fe ff ff 0f 1f 80 00 00 00 00 49 63 42 20 48 8d 4a 01 49 8b 3a <49> 8b 1c 06 4c 89 f0 65 48 0f c7 0f 0f 94 c0 84 c0 0f 84 d2 fe 
[  199.771158] RIP  [<ffffffffad22b28b>] __kmalloc_node_track_caller+0x17b/0x290
[  199.780113]  RSP <ffff90dfecee7a48>
[  199.784958] CR2: ffffffffffffffff
[...]
    • Note The kernel panic occurred on CPU 1 (CPU: 1 PID: 13168 Comm: ss Kdump: loaded Tainted: G) and the warnings in 3. and 4. occurred on CPU 1 as well (where the logs show CPU: 1 PID: 1055 Comm: systemd-udevd Tainted: G for both). Slab caches exist on a per-CPU basis, so it is extremely likely the IPMI corruption noted in 3. and 4. impacted and corrupted the slab caches for CPU 1 leading to the crash in 5.

This solution is part of Red Hat’s fast-track publication program, providing a huge library of solutions that Red Hat engineers have created while supporting our customers. To give you the knowledge you need the instant it becomes available, these articles may be presented in a raw and unedited form.

Comments