Crashlog with pstore¶
- Table of contents
- Crashlog with pstore
The Linux kernel supports the automatic storage of stack traces for crashes in a special memory area. This can be in a non-volatile memory area (like the efivars) or a reserved memory area in the system ram. In older OpenWrt releases, this was for example implemented via the /sys/kernel/debug/crashlog file which was created after a system rebooted after a kernel panic. Newer OpenWrt releases (with kernel 5.4 or newer) don't use the old (OpenWrt-only) implementation and the user has to manually enable the generic kernel implementation. This is is most cases PSTORE_RAM (previously called ramoops).
Enable PSTORE_RAM for ath79 board¶
Enabling kernel feature¶
The kernel feature has to be enabled via make kernel_menuconfig. The option for it is called CONFIG_PSTORE_RAM and requires the pstore subystem (CONFIG_PSTORE) to be enabled.
diff --git a/target/linux/ath79/config-5.4 b/target/linux/ath79/config-5.4
index e37b728554..7e5ee88817 100644
--- a/target/linux/ath79/config-5.4
+++ b/target/linux/ath79/config-5.4
@@ -210,7 +159,23 @@ CONFIG_PHYLIB=y
# CONFIG_PHY_AR7200_USB is not set
# CONFIG_PHY_ATH79_USB is not set
CONFIG_PINCTRL=y
+CONFIG_PSTORE=y
+# CONFIG_PSTORE_842_COMPRESS is not set
+CONFIG_PSTORE_COMPRESS=y
+CONFIG_PSTORE_COMPRESS_DEFAULT="deflate"
+# CONFIG_PSTORE_CONSOLE is not set
+CONFIG_PSTORE_DEFLATE_COMPRESS=y
+CONFIG_PSTORE_DEFLATE_COMPRESS_DEFAULT=y
+# CONFIG_PSTORE_LZ4HC_COMPRESS is not set
+# CONFIG_PSTORE_LZ4_COMPRESS is not set
+# CONFIG_PSTORE_LZO_COMPRESS is not set
+# CONFIG_PSTORE_PMSG is not set
+CONFIG_PSTORE_RAM=y
+# CONFIG_PSTORE_ZSTD_COMPRESS is not set
CONFIG_RATIONAL=y
+CONFIG_REED_SOLOMON=y
+CONFIG_REED_SOLOMON_DEC8=y
+CONFIG_REED_SOLOMON_ENC8=y
CONFIG_REGMAP=y
CONFIG_REGMAP_MMIO=y
CONFIG_REGULATOR=y
Reserving memory for the board¶
The PSTORE_RAM is using a small RAM area for a crashlog ring-buffer. It is recommended to use a 64KB area in the system RAM area in the address space of the SoC which neither the bootloader nor Linux need for booting the system. The "System RAM" region of the system can be found using cat /proc/iomem. A good place must not conflict with any other entry in iomem - but there can still be conflicts with the bootloader which are not listed here. Board specific information like the data from uboot's bdinfo, the map files (generated using the u-boot build) and the boot scripts must be checked here.
The old crashlog implementation used a couple of kilobytes at the 63MB address (or the highest memory address - 1MB when the board has less than 64MB of RAM) for the storage. This would be the 0x03f00000 address (because the system RAM starts at 0x0 for ath79) which we can add manually to the devicetree file of the board:
--- a/target/linux/ath79/dts/xxx_xxx.dts
+++ b/target/linux/ath79/dts/xxx_xxx.dts
@@ -6,4 +18 @@
#include <dt-bindings/input/input.h>
/ {
+ reserved-memory {
+ #address-cells = <1>;
+ #size-cells = <1>;
+ ranges;
+
+ /* 64 KiB reserved for ramoops/pstore */
+ ramoops@03f00000 {
+ compatible = "ramoops";
+ reg = <0x03f00000 0x10000>;
+ record-size = <0x1000>;
+ console-size = <0x1000>;
+ };
+ };
+
chosen {
Other options how to specify the ramoops region are defined in the official documentation
The system will initialize the area on bootup:
root@OpenWrt:/# dmesg|grep -e ramoops -e pstore
[ 0.134694] pstore: Registered ramoops as persistent store backend
[ 0.141271] ramoops: using 0x10000@0x3f00000, ecc: 0
[ 1.253190] pstore: Using crash dump compression: deflate
Accessing the pstore¶
OpenWrt 21.02 (or newer) will automatically handle the mounting of the pstore filesystem. For other systems, it is necessary to manually mount the pstore using
root@OpenWrt:/# /bin/mount -o noatime -t pstore pstore /sys/fs/pstore
After a kernel panic, one or more files called dmesg-ramoops-* can be found in the directory /sys/fs/pstore/.
root@OpenWrt:/# ls -ltr /sys/fs/pstore/
-r--r--r-- 1 root root 9001 Oct 19 12:45 dmesg-ramoops-1
-r--r--r-- 1 root root 9024 Oct 19 12:45 dmesg-ramoops-0
It should be easy to extract the relevant stacktrace from such a file. It could for example look like this:
<1>[ 95.770888] CPU 0 Unable to handle kernel paging request at virtual address 00000000, epc == 8699f200, ra == 8699f1f4 <4>[ 95.781691] Oops[#1]: <4>[ 95.783999] CPU: 0 PID: 2323 Comm: batctl Not tainted 5.4.152 #0 <4>[ 95.790082] $ 0 : 00000000 00000001 00000017 00000000 <4>[ 95.795379] $ 4 : 86f5d61c 86d7dc08 86d7dc08 869b3218 <4>[ 95.800677] $ 8 : 00000034 805464c8 86d7dc6c 00000002 <4>[ 95.805975] $12 : fffffffd 00000402 80691574 00000040 <4>[ 95.811273] $16 : 86d7dc08 86e85460 86f5d600 8689f3c0 <4>[ 95.816569] $20 : 00000000 86d7dc6c 00000000 8068fed8 <4>[ 95.821867] $24 : 00000000 86d7dde4 <4>[ 95.827164] $28 : 86d7c000 86d7dbc8 868cea00 8699f1f4 <4>[ 95.832463] Hi : 00000000 <4>[ 95.835375] Lo : 00000003 <4>[ 95.838627] epc : 8699f200 batadv_netlink_set_mesh+0x40/0x320 [batman_adv] <4>[ 95.846091] ra : 8699f1f4 batadv_netlink_set_mesh+0x34/0x320 [batman_adv] <4>[ 95.853231] Status: 1100fc03 KERNEL EXL IE <4>[ 95.857474] Cause : 0080000c (ExcCode 03) <4>[ 95.861529] BadVA : 00000000 <4>[ 95.864443] PrId : 00019750 (MIPS 74Kc) <4>[ 95.868411] Modules linked in: ath9k ath9k_common pppoe ppp_async iptable_nat batman_adv ath9k_hw ath10k_pci ath10k_core ath xt_state xt_nat xt_conntrack xt_REDIRECT xt_MASQUERADE xt_FLOWOFFLOAD pppox ppp_generic nf_nat nf_flow_table_hw nf_flow_table nf_conntrack mac80211 ipt_REJECT cfg80211 xt_time xt_tcpudp xt_multiport xt_mark xt_mac xt_limit xt_comment xt_TCPMSS xt_LOG slhc nf_reject_ipv4 nf_log_ipv4 nf_defrag_ipv6 nf_defrag_ipv4 libcrc32c iptable_mangle iptable_filter ip_tables crc_ccitt compat nf_log_ipv6 nf_log_common ip6table_mangle ip6table_filter ip6_tables ip6t_REJECT x_tables nf_reject_ipv6 sha256_generic libsha256 seqiv jitterentropy_rng drbg hmac ghash_generic gf128mul gcm ctr cmac ccm fsl_mph_dr_of ehci_platform ehci_fsl ehci_hcd gpio_button_hotplug usbcore nls_base usb_common crc16 aead crypto_null cryptomgr crc32c_generic crypto_hash <4>[ 95.944865] Process batctl (pid: 2323, threadinfo=92bd6437, task=bec29b92, tls=77e34dcc) <4>[ 95.953057] Stack : 86f5d600 869b31c8 869b4b64 86f5d600 869b31c8 869b4b64 86f5d600 8042ab40 <4>[ 95.961532] 80691570 86d7dc54 00000000 00000002 00000000 86d7dc6c 868cea00 00000913 <4>[ 95.970005] 616ebdec 00000913 86f5d600 86f5d610 86f5d614 868cea00 8068fed8 86e85460 <4>[ 95.978480] 00000000 86d7dc6c 86f5d600 8689f3c0 fffffffc 8042a96c 80670000 00000000 <4>[ 95.986955] 00000000 00000000 8042962c 80429e2c 8689f3c0 00000006 00000006 8042b2dc <4>[ 95.995429] ... <4>[ 95.997905] Call Trace: <4>[ 96.000709] [<8699f200>] batadv_netlink_set_mesh+0x40/0x320 [batman_adv] <4>[ 96.007823] [<8042ab40>] genl_rcv_msg+0x1d4/0x4b0 <4>[ 96.012595] [<80429e2c>] netlink_rcv_skb+0xb0/0x160 <4>[ 96.017540] [<8042a630>] genl_rcv+0x30/0x48 <4>[ 96.021799] [<80429538>] netlink_unicast+0x1a4/0x298 <4>[ 96.026836] [<8042990c>] netlink_sendmsg+0x2e0/0x3c8 <4>[ 96.031877] [<803b8790>] ____sys_sendmsg+0xc4/0x26c <4>[ 96.036823] [<803b9144>] ___sys_sendmsg+0x7c/0xcc <4>[ 96.041595] [<803ba3fc>] sys_sendmsg+0x4c/0x94 <4>[ 96.046098] [<8006e1ac>] syscall_common+0x34/0x58 <4>[ 96.050867] Code: 0002102b ae22000c 24020017 <a4020000> 8e020014 8c4400a8 10800004 00000000 02202825 <4>[ 96.060751] <4>[ 96.062319] ---[ end trace ff181e2552b1e823 ]--- <0>[ 96.077613] Kernel panic - not syncing: Fatal exception
Decoding the stack trace¶
Entries like batadv_netlink_set_mesh+0x40/0x320 hard to understand when not knowing what source code line this would be. Various tools can be used here:
binutils' addr2line¶
The addr2line can be used when the relative address is known. In our example, the batman-adv module was loaded at address 0x86e80000 (see /proc/modules). The relative address is therefore 0x0001f200 (0x8699f200 - 0x86980000)
$ mips-linux-gnu-addr2line -f -e ./build_dir/target-mips_24kc_musl/linux-ath79_generic/batman-adv-2021.3/net/batman-adv/batman-adv.ko 0x0001f200
batadv_netlink_set_mesh
./build_dir/target-mips_24kc_musl/linux-ath79_generic/batman-adv-2021.3/net/batman-adv/netlink.c:448
gdb¶
gdb(-multiarch) can also parse the symbols and is able to decode the symbolic name + offset.
$ gdb-multiarch -q -ex 'list *(batadv_netlink_set_mesh+0x40)' -ex quit ./build_dir/target-mips_24kc_musl/linux-ath79_generic/batman-adv-2021.3/net/batman-adv/batman-adv.ko
Reading symbols from ./build_dir/target-mips_24kc_musl/linux-ath79_generic/batman-adv-2021.3/net/batman-adv/batman-adv.ko...
0x1f240 is in batadv_netlink_set_mesh (./build_dir/target-mips_24kc_musl/linux-ath79_generic/batman-adv-2021.3/net/batman-adv/netlink.c:448).
443 if (info->attrs[BATADV_ATTR_AGGREGATED_OGMS_ENABLED]) {
444 attr = info->attrs[BATADV_ATTR_AGGREGATED_OGMS_ENABLED];
445
446 atomic_set(&bat_priv->aggregated_ogms, !!nla_get_u8(attr));
447 attr = NULL;
448 attr->nla_len = 23;
449 }
450
451 if (info->attrs[BATADV_ATTR_AP_ISOLATION_ENABLED]) {
452 attr = info->attrs[BATADV_ATTR_AP_ISOLATION_ENABLED];
Or when trying to inspect the actual instructions together with the source code:
$ gdb-multiarch -q -ex 'disassemble /m *(batadv_netlink_set_mesh+0x40)' -ex quit ./build_dir/target-mips_24kc_musl/linux-ath79_generic/batman-adv-2021.3/net/batman-adv/batman-adv.ko
Reading symbols from ./build_dir/target-mips_24kc_musl/linux-ath79_generic/batman-adv-2021.3/net/batman-adv/batman-adv.ko...
Dump of assembler code for function batadv_netlink_set_mesh:
[...]
442
443 if (info->attrs[BATADV_ATTR_AGGREGATED_OGMS_ENABLED]) {
0x0001f21c <+28>: lw v0,20(a1)
0x0001f220 <+32>: lw a0,164(v0)
0x0001f224 <+36>: beqz a0,0x1f244 <batadv_netlink_set_mesh+68>
0x0001f228 <+40>: nop
444 attr = info->attrs[BATADV_ATTR_AGGREGATED_OGMS_ENABLED];
445
446 atomic_set(&bat_priv->aggregated_ogms, !!nla_get_u8(attr));
0x0001f22c <+44>: jal 0x1d41c <nla_get_u32+8>
0x0001f230 <+48>: nop
0x0001f234 <+52>: sltu v0,zero,v0
447 attr = NULL;
448 attr->nla_len = 23;
0x0001f23c <+60>: li v0,23
0x0001f240 <+64>: sh v0,0(zero)
449 }
[...]
Linux's faddr2line¶
The kernel has a script which can be used to decode one or multiple line entries - similar to what can also be done with gdb(-multiarch).
$ LXBASE=./build_dir/target-mips_24kc_musl/linux-ath79_generic
$ CROSS_COMPILE=mips-linux-gnu- $LXBASE/linux-5.4.152/scripts/faddr2line --list $LXBASE/batman-adv-2021.3/ipkg-mips_24kc/kmod-batman-adv/lib/modules/5.4.152/batman-adv.ko 'batadv_netlink_set_mesh+0x40/0x320'
batadv_netlink_set_mesh+0x40/0x320:
batadv_netlink_set_mesh at ./build_dir/target-mips_24kc_musl/linux-ath79_generic/batman-adv-2021.3/net/batman-adv/netlink.c:448
443 if (info->attrs[BATADV_ATTR_AGGREGATED_OGMS_ENABLED]) {
444 attr = info->attrs[BATADV_ATTR_AGGREGATED_OGMS_ENABLED];
445
446 atomic_set(&bat_priv->aggregated_ogms, !!nla_get_u8(attr));
447 attr = NULL;
>448< attr->nla_len = 23;
449 }
450
451 if (info->attrs[BATADV_ATTR_AP_ISOLATION_ENABLED]) {
452 attr = info->attrs[BATADV_ATTR_AP_ISOLATION_ENABLED];
453
Linux's decode_stacktrace¶
The faddr2line has no real functional benefits when comparing it with gdb. But the has another useful script which can decode the whole stacktrace in a single run. It can even handle multiple modules when they are under a common folder:
$ LXBASE=./build_dir/target-mips_24kc_musl/linux-ath79_generic
$ CROSS_COMPILE=mips-linux-gnu- $LXBASE/linux-5.4.152/scripts/decode_stacktrace.sh $LXBASE/linux-5.4.152/vmlinux $LXBASE/linux-5.4.152/ $LXBASE < dmesg-ramoops-1
[...]
<1>[ 95.770888] CPU 0 Unable to handle kernel paging request at virtual address 00000000, epc == 8699f200, ra == 8699f1f4
<4>[ 95.781691] Oops[#1]:
<4>[ 95.783999] CPU: 0 PID: 2323 Comm: batctl Not tainted 5.4.152 #0
<4>[ 95.790082] $ 0 : 00000000 00000001 00000017 00000000
<4>[ 95.795379] $ 4 : 86f5d61c 86d7dc08 86d7dc08 869b3218
<4>[ 95.800677] $ 8 : 00000034 805464c8 86d7dc6c 00000002
<4>[ 95.805975] $12 : fffffffd 00000402 80691574 00000040
<4>[ 95.811273] $16 : 86d7dc08 86e85460 86f5d600 8689f3c0
<4>[ 95.816569] $20 : 00000000 86d7dc6c 00000000 8068fed8
<4>[ 95.821867] $24 : 00000000 86d7dde4
<4>[ 95.827164] $28 : 86d7c000 86d7dbc8 868cea00 8699f1f4
<4>[ 95.832463] Hi : 00000000
<4>[ 95.835375] Lo : 00000003
<4>[ 95.838627] epc : 8699f200 batadv_netlink_set_mesh (./build_dir/target-mips_24kc_musl/linux-ath79_generic/batman-adv-2021.3/net/batman-adv/netlink.c:448) batman_adv
<4>[ 95.846091] ra : 8699f1f4 batadv_netlink_set_mesh (./build_dir/target-mips_24kc_musl/linux-ath79_generic/batman-adv-2021.3/net/batman-adv/netlink.c:446) batman_adv
<4>[ 95.853231] Status: 1100fc03 KERNEL EXL IE
<4>[ 95.857474] Cause : 0080000c (ExcCode 03)
<4>[ 95.861529] BadVA : 00000000
<4>[ 95.864443] PrId : 00019750 (MIPS 74Kc)
<4>[ 95.868411] Modules linked in: ath9k ath9k_common pppoe ppp_async iptable_nat batman_adv ath9k_hw ath10k_pci ath10k_core ath xt_state xt_nat xt_conntrack xt_REDIRECT xt_MASQUERADE xt_FLOWOFFLOAD pppox ppp_generic nf_nat nf_flow_table_hw nf_flow_table nf_conntrack mac80211 ipt_REJECT cfg80211 xt_time xt_tcpudp xt_multiport xt_mark xt_mac xt_limit xt_comment xt_TCPMSS xt_LOG slhc nf_reject_ipv4 nf_log_ipv4 nf_defrag_ipv6 nf_defrag_ipv4 libcrc32c iptable_mangle iptable_filter ip_tables crc_ccitt compat nf_log_ipv6 nf_log_common ip6table_mangle ip6table_filter ip6_tables ip6t_REJECT x_tables nf_reject_ipv6 sha256_generic libsha256 seqiv jitterentropy_rng drbg hmac ghash_generic gf128mul gcm ctr cmac ccm fsl_mph_dr_of ehci_platform ehci_fsl ehci_hcd gpio_button_hotplug usbcore nls_base usb_common crc16 aead crypto_null cryptomgr crc32c_generic crypto_hash
<4>[ 95.944865] Process batctl (pid: 2323, threadinfo=92bd6437, task=bec29b92, tls=77e34dcc)
<4>[ 95.953057] Stack : 86f5d600 869b31c8 869b4b64 86f5d600 869b31c8 869b4b64 86f5d600 8042ab40
<4>[ 95.961532] 80691570 86d7dc54 00000000 00000002 00000000 86d7dc6c 868cea00 00000913
<4>[ 95.970005] 616ebdec 00000913 86f5d600 86f5d610 86f5d614 868cea00 8068fed8 86e85460
<4>[ 95.978480] 00000000 86d7dc6c 86f5d600 8689f3c0 fffffffc 8042a96c 80670000 00000000
<4>[ 95.986955] 00000000 00000000 8042962c 80429e2c 8689f3c0 00000006 00000006 8042b2dc
<4>[ 95.995429] ...
<4>[ 95.997905] Call Trace:
<4>[ 96.000709] batadv_netlink_set_mesh (./build_dir/target-mips_24kc_musl/linux-ath79_generic/batman-adv-2021.3/net/batman-adv/netlink.c:448) batman_adv
<4>[ 96.007823] genl_rcv_msg (./build_dir/target-mips_24kc_musl/linux-ath79_generic/linux-5.4.152/net/netlink/genetlink.c:631 ./build_dir/target-mips_24kc_musl/linux-ath79_generic/linux-5.4.152/net/netlink/genetlink.c:654)
<4>[ 96.012595] netlink_rcv_skb (./build_dir/target-mips_24kc_musl/linux-ath79_generic/linux-5.4.152/net/netlink/af_netlink.c:2481)
<4>[ 96.017540] genl_rcv (./build_dir/target-mips_24kc_musl/linux-ath79_generic/linux-5.4.152/net/netlink/genetlink.c:667)
<4>[ 96.021799] netlink_unicast (./build_dir/target-mips_24kc_musl/linux-ath79_generic/linux-5.4.152/net/netlink/af_netlink.c:1306 ./build_dir/target-mips_24kc_musl/linux-ath79_generic/linux-5.4.152/net/netlink/af_netlink.c:1331)
<4>[ 96.026836] netlink_sendmsg (./build_dir/target-mips_24kc_musl/linux-ath79_generic/linux-5.4.152/net/netlink/af_netlink.c:1920)
<4>[ 96.031877] ____sys_sendmsg (./build_dir/target-mips_24kc_musl/linux-ath79_generic/linux-5.4.152/net/socket.c:637 ./build_dir/target-mips_24kc_musl/linux-ath79_generic/linux-5.4.152/net/socket.c:657 ./build_dir/target-mips_24kc_musl/linux-ath79_generic/linux-5.4.152/net/socket.c:2286)
<4>[ 96.036823] ___sys_sendmsg (./build_dir/target-mips_24kc_musl/linux-ath79_generic/linux-5.4.152/net/socket.c:2342)
<4>[ 96.041595] sys_sendmsg (./build_dir/target-mips_24kc_musl/linux-ath79_generic/linux-5.4.152/./include/linux/file.h:30 ./build_dir/target-mips_24kc_musl/linux-ath79_generic/linux-5.4.152/net/socket.c:2388 ./build_dir/target-mips_24kc_musl/linux-ath79_generic/linux-5.4.152/net/socket.c:2395 ./build_dir/target-mips_24kc_musl/linux-ath79_generic/linux-5.4.152/net/socket.c:2393)
<4>[ 96.046098] syscall_common (./build_dir/target-mips_24kc_musl/linux-ath79_generic/linux-5.4.152/arch/mips/kernel/scall32-o32.S:101)
<4>[ 96.050867] Code: 0002102b ae22000c 24020017 <a4020000> 8e020014 8c4400a8 10800004 00000000 02202825
All code
========
0: 0002102b sltu v0,zero,v0
4: ae22000c sw v0,12(s1)
8: 24020017 li v0,23
c:* a4020000 sh v0,0(zero) <-- trapping instruction
10: 8e020014 lw v0,20(s0)
14: 8c4400a8 lw a0,168(v0)
18: 10800004 beqz a0,0x2c
1c: 00000000 nop
20: 02202825 move a1,s1
...
Code starting with the faulting instruction
===========================================
0: a4020000 sh v0,0(zero)
4: 8e020014 lw v0,20(s0)
8: 8c4400a8 lw a0,168(v0)
c: 10800004 beqz a0,0x20
10: 00000000 nop
14: 02202825 move a1,s1
...
<4>[ 96.060751]
<4>[ 96.062319] ---[ end trace ff181e2552b1e823 ]---
<0>[ 96.077613] Kernel panic - not syncing: Fatal exception