Segfault during reboot

[KennethWilke]

On a server using the v0.6.1 BMC version, we encountered a segfault when rebooting the BMC. I did happen to have a debug cable plugged into this server so I have this log of the occurrence:

After hitting this it seems the file system it tries to mount from /dev/mtdblock6 is corrupt and the BMC hit's the emergency maintenance shell. I can drop a debug cable in my own boxes to fix this, but need to make sure this doesn't occur on servers in a remote datacenter.

root@barreleye:~# reboot
[  OK  ] Stopped target Multi-User System.
         Stopping DBUS introspecting REST server....
         Stopping Phosphor Inverse ARP daemon...
         Stopping Kernel Logging Service...
[  OK  ] Stopped target Timers.
         Stopping Phosphor OpenBMC user management daemon...
         Stopping Network DBUS object...
         Stopping Phosphor OpenBMC DBus REST daemon...
         Stopping Phosphor OpenBMC event management daemon...
[  OK  ] Stopped target Network.
[  OK  ] Stopped Daily Cleanup of Temporary Directories.
[  OK  ] Stopped target System Time Synchronized.
         Stopping Settings DBUS Object...
[  OK  ] Stopped target Remote File Systems.
         Stopping Login Service...
         Stopping Phosphor OpenBMC BT to DBUS...
         Stopping System Logging Service...
[  OK  ] Removed slice system-getty.slice.
         Stopping Network Service...
         Stopping Phosphor OpenBMC IPMI daemon...
[  OK  ] Stopped target Login Prompts.
         Stopping Serial Getty on ttyS4...
[  OK  ] Stopped Settings DBUS Object.
[  OK  ] Stopped Kernel Logging Service.
[  OK  ] Stopped DBUS introspecting REST server..
[  OK  ] Stopped System Logging Service.
[  OK  ] Stopped Network DBUS object.
[  OK  ] Stopped Phosphor OpenBMC user management daemon.
[  OK  ] Stopped Phosphor Inverse ARP daemon.
[  OK  ] Stopped Login Service.
[  OK  ] Stopped Network Service.
[  OK  ] Stopped Phosphor OpenBMC event management daemon.
[  OK  ] Stopped Phosphor OpenBMC BT to DBUS.
[  OK  ] Stopped Serial Getty on ttyS4.
[  OK  ] Stopped Phosphor OpenBMC IPMI daemon.
[  OK  ] Stopped Phosphor OpenBMC DBus REST daemon.
         Stopping Phosphor OpenBMC DBus service management daemon...
[  OK  ] Stopped Clear one time boot overrides.
[  OK  ] Removed slice system-serial\x2dgetty.slice.
         Stopping D-Bus System Message Bus...
         Stopping Temp placeholder for skeleton function...
[  OK  ] Stopped Phosphor OpenBMC DBus service management daemon.
[  OK  ] Stopped Temp placeholder for skeleton function.
[  OK  ] Stopped D-Bus System Message Bus.
[  OK  ] Stopped target Basic System.
[  OK  ] Stopped target Slices.
[  OK  ] Removed slice User and Session Slice.
[  OK  ] Stopped target Sockets.
[  OK  ] Closed D-Bus System Message Bus Socket.
[  OK  ] Closed Syslog Socket.
[  OK  ] Closed dropbear.socket.
[  OK  ] Stopped target System Initialization.
         Stopping Update UTMP about System Boot/Shutdown...
[  OK  ] Stopped Apply Kernel Variables.
         Stopping Network Time Synchronization...
         Stopping Load/Save Random Seed...
[  OK  ] Stopped target Swap.
[  OK  ] Stopped target Paths.
[  OK  ] Stopped Dispatch Password Requests to Console Directory Watch.
[  OK  ] Stopped Forward Password Requests to Wall Directory Watch.
[  OK  ] Stopped Network Time Synchronization.
[  OK  ] Stopped Update UTMP about System Boot/Shutdown.
[  OK  ] Stopped Load/Save Random Seed.
[  OK  ] Stopped Create Volatile Files and Directories.
[  OK  ] Stopped target Local File Systems.
         Unmounting /var/volatile...
         Unmounting /run/initramfs/ro...
         Unmounting /run/initramfs/rw...
         Unmounting Temporary Directory...
[  OK  ] Unmounted /var/volatile.
[  OK  ] Unmounted /run/initramfs/ro.
[  OK  ] Unmounted /run/initramfs/rw.
[  OK  ] Unmounted Temporary Directory.
[  OK  ] Reached target Unmount All Filesystems.
[  OK  ] Stopped target Local File Systems (Pre).
[  OK  ] Stopped Create Static Device Nodes in /dev.
[  OK  ] Stopped Remount Root and Kernel File Systems.
[  OK  ] Reached target Shutdown.
systemd-shutdown[1]: Sending SIGTERM to remaining processes...
systemd-journald[531]: Received SIGTERM from PID 1 (systemd-shutdow).
BUG: Bad page map in process systemd-journal  pte:4d69a100 pmd:4dddd831
addr:7f600000 vm_flags:00000875 anon_vma:  (null) mapping:cf4e5974 index:3e
file:systemd-journald fault:filemap_fault mmap:generic_file_readonly_mmap readpage:squashfs_readpage
CPU: 0 PID: 531 Comm: systemd-journal Not tainted 4.3.6-openbmc-20160222-1 #1
Hardware name: ASpeed SoC
[<c000f28c>] (unwind_backtrace) from [<c000cf0c>] (show_stack+0x10/0x14)
[<c000cf0c>] (show_stack) from [<c00787c8>] (print_bad_pte+0x158/0x190)
[<c00787c8>] (print_bad_pte) from [<c0079cec>] (unmap_single_vma+0x4ec/0x500)
[<c0079cec>] (unmap_single_vma) from [<c007a438>] (unmap_vmas+0x44/0x54)
[<c007a438>] (unmap_vmas) from [<c007e97c>] (exit_mmap+0xc8/0x1dc)
[<c007e97c>] (exit_mmap) from [<c0014770>] (mmput+0x38/0xb8)
[<c0014770>] (mmput) from [<c0017380>] (do_exit+0x2f0/0x7b0)
[<c0017380>] (do_exit) from [<c0018654>] (do_group_exit+0x4c/0xb8)
[<c0018654>] (do_group_exit) from [<c00186d0>] (__wake_up_parent+0x0/0x18)
Disabling lock debugging due to kernel taint
BUG: Bad rss-counter state mm:cdcf71a0 idx:0 val:1
BUG: Bad rss-counter state mm:cdcf71a0 idx:2 val:-1
systemd-shutdown[1]: Sending SIGKILL to remaining processes...
systemd-shutdown[1]: Hardware watchdog 'aspeed_wdt', version 0
systemd-shutdown[1]: Unmounting file systems.
systemd-shutdown[1]: All filesystems unmounted.
systemd-shutdown[1]: Deactivating swaps.
systemd-shutdown[1]: All swaps deactivated.
systemd-shutdown[1]: Detaching loop devices.
systemd-shutdown[1]: All loop devices detached.
systemd-shutdown[1]: Detaching DM devices.
systemd-shutdown[1]: All DM devices detached.
systemd-shutdown[1]: Successfully changed into root pivot.
systemd-shutdown[1]: Returning to initrd...
shutdown: reboot --log-level 6 --log-target kmsg --log-color
+ sort -r
+ awk /oldroot|mnt/ { print $2 }
+ umount /oldroot/sys/kernel/debug
+ umount /oldroot/sys/kernel/config
+ umount /oldroot/sys/fs/cgroup/systemd
+ umount /oldroot/sys/fs/cgroup
+ umount /oldroot/sys
+ umount /oldroot/proc
+ umount /oldroot/dev/shm
+ umount /oldroot/dev/pts
+ umount /oldroot/dev
+ umount /oldroot
------------[ cut here ]------------
Kernel BUG at c005ec1c [verbose debug info unavailable]
Internal error: Oops - BUG: 0 [#1] ARM
Modules linked in:
CPU: 0 PID: 1124 Comm: umount Tainted: G    B           4.3.6-openbmc-20160222-1 #1
Hardware name: ASpeed SoC
task: cf9684a0 ti: cfabc000 task.ti: cfabc000
PC is at __delete_from_page_cache+0x204/0x2a8
LR is at __delete_from_page_cache+0x11c/0x2a8
pc : [<c005ec1c>]    lr : [<c005eb34>]    psr: 60000093
sp : cfabddf0  ip : c0529740  fp : 00000004
r10: 0000003e  r9 : cf4e5978  r8 : 00000003
r7 : 00000000  r6 : 00000000  r5 : cf4e5974  r4 : cffa6340
r3 : 00000000  r2 : 000002bc  r1 : c053e674  r0 : 00002e2e
Flags: nZCv  IRQs off  FIQs on  Mode SVC_32  ISA ARM  Segment none
Control: 0005317f  Table: 4fa7c000  DAC: 00000051
Process umount (pid: 1124, stack limit = 0xcfabc190)
Stack: (0xcfabddf0 to 0xcfabe000)
dde0:                                     00000000 0000000c cf4de8c0 cf4de9d0
de00: cfabdea8 cffa6340 00000000 00000013 cf4e5974 0000003e 00000000 00000006
de20: cffa6340 c005ecfc cffa6340 cf4e5974 0000003e c0069430 00001000 00000000
de40: 00000000 cffa6c60 00000000 00000000 ffffffff 00000000 cf4e5974 c00695d4
de60: cfabde68 00000000 00000038 00000039 0000003a 0000003b 0000003c 0000003d
de80: 0000003e 0000003f 00000040 00000041 00000042 00000043 00000036 00000037
dea0: 0000000c 00000000 cffa6460 cffa6320 cffa6300 cffa5220 cffa6c40 cffa6c60
dec0: cffa6340 cffa6280 cffa6520 cff9a1a0 cff9a1c0 cff9a1e0 cffa64c0 cffa6480
dee0: c000a424 ffffffff ffffffff cfabc000 ce484800 c000a424 cfabc000 00000000
df00: be869ebc c0069998 ffffffff ffffffff 00000000 cf4e58b8 c037f1a0 c00a1060
df20: cfabc000 cfabdf38 cf7a8778 c00a1128 ce4849fc c00a1d64 cf4e57dc cf7a87fc
df40: 00000000 ce484800 c037f1a0 c053296c 00000034 c008e5d0 00000000 cf4039e0
df60: 00000081 c008e830 ce484800 c0510548 c053296c c008e930 ffff0001 ce4279e0
df80: ce4277bc c00a42d4 cf9684a0 c002a97c c000a424 cfabc000 cfabdfb0 c000cba8
dfa0: 000bc1a0 000bc290 000bc1c0 c000a2d0 00000000 00000000 00000000 000bc1a0
dfc0: 000bc1a0 000bc290 000bc1c0 00000034 00000000 000bc2c0 00000000 be869ebc
dfe0: 000aa3a8 be869cc4 0004ebc4 4a7b407c 60000010 000bc1c0 00000000 00000000
[<c005ec1c>] (__delete_from_page_cache) from [<c005ecfc>] (delete_from_page_cache+0x3c/0x5c)
[<c005ecfc>] (delete_from_page_cache) from [<c0069430>] (truncate_inode_page+0x98/0xa4)
[<c0069430>] (truncate_inode_page) from [<c00695d4>] (truncate_inode_pages_range+0x168/0x518)
[<c00695d4>] (truncate_inode_pages_range) from [<c0069998>] (truncate_inode_pages+0x14/0x1c)
[<c0069998>] (truncate_inode_pages) from [<c00a1060>] (evict+0x90/0x128)
[<c00a1060>] (evict) from [<c00a1128>] (dispose_list+0x30/0x3c)
[<c00a1128>] (dispose_list) from [<c00a1d64>] (evict_inodes+0xb4/0xbc)
[<c00a1d64>] (evict_inodes) from [<c008e5d0>] (generic_shutdown_super+0x40/0xc0)
[<c008e5d0>] (generic_shutdown_super) from [<c008e830>] (kill_block_super+0x18/0x68)
[<c008e830>] (kill_block_super) from [<c008e930>] (deactivate_locked_super+0x44/0x74)
[<c008e930>] (deactivate_locked_super) from [<c00a42d4>] (cleanup_mnt+0x4c/0x70)
[<c00a42d4>] (cleanup_mnt) from [<c002a97c>] (task_work_run+0x6c/0x80)
[<c002a97c>] (task_work_run) from [<c000cba8>] (do_work_pending+0xa4/0xc0)
[<c000cba8>] (do_work_pending) from [<c000a2d0>] (slow_work_pending+0xc/0x20)
Code: e121f002 e594300c e3530000 ba000000 (e7f001f2)
---[ end trace b045e78c59981ae5 ]---
Segmentation fault
+ umount /mnt
+ set +x
Remaining mounts:
tmpfs / tmpfs rw,nosuid,nodev,mode=755 0 0
dev /dev devtmpfs rw,relatime,size=126368k,nr_inodes=31592,mode=755 0 0
proc /proc proc rw,relatime 0 0
sys /sys sysfs rw,relatime 0 0
tmpfs /run tmpfs rw,nosuid,nodev,mode=755 0 0

[shenki]

@mdmillerii is this related to the corruption caused by i2c?

[mdmillerii]

Its hard to say definitively but I hope so.

The first error detected was a bad page while tearing down systemd-journal:

BUG: Bad page map in process systemd-journal pte:4d69a100 pmd:4dddd831
addr:7f600000 vm_flags:00000875 anon_vma: (null) mapping:cf4e5974 index:3e
file:systemd-journald fault:filemap_fault mmap:generic_file_readonly_mmap readpage:squashfs_readpage
CPU: 0 PID: 531 Comm: systemd-journal Not tainted 4.3.6-openbmc-20160222-1 #1

The vma say sits a file map page from squashfs in a read-only mmap.

The PTE is only PTE_USER not PRESENT, YOUNG, DIRTY, RDONLY, XN, or SHARED.

The next prints about rss counters say we had 1 file page present and -1 swap pages present, because we didn't classify that as a pte.

The BUG at shutdown says we still have a rmap entry for a PTE.

The address is nicely aligned, so all this goes along with the first byte of a page being zeroed, which may be the 32k i2c rom being read.

Looks like @jk-ozlabs has a patch coming soon.

[mdmillerii]

This is the same issue as #190, just a different file. It's still likely corruption of the page table.

[williamspatrick]

Is this resolved?

[mdmillerii]

This should be fixed by the i2c fix in openbmc-20160606-1 merged in the main branch via #313.
I believe that tag should have alternative patches to support occ with 12-core parts and the scu changes. The JFFS2 patches are in the kernel v4.4.y stream.
Alternatives to the fixes to u-boot in 0.6.1 were merged in #304.