How to use decode_stacktrace.sh?

Viewed 147

Q1: admin-guide/bug-hunting.html says that:

If the kernel is compiled with CONFIG_DEBUG_INFO, you can enhance the quality of the stack trace by using file:scripts/decode_stacktrace.sh.

Is CONFIG_DEBUG_INFO a prerequisite for running the script decode_stacktrace.sh?"

Q2: this patch says:

./decode_stacktrace.sh vmlinux /home/sasha/linux/ < input.log > output.log

Where can I find the input.log? I know it's sort of stack info. Will it only be available when CONFIG_DEBUG_INFO is y or when there is a kernel panic or oops?

2 Answers

Yes, you will need CONFIG_DEBUG_INFO=y in order for decode_stacktrace.sh to extract useful debugging information (such as file names and line numbers) from the kernel image (vmlinux). In theory, the script will run fine even without debug info, but it will give you less information (no file names and line numbers).

NOTE: in recent kernels (>= v5.12) a multiple choice option for the DWARF version was added (CONFIG_DEBUG_INFO_DWARF{4,5,_TOOLCHAIN_DEFAULT}). Then, in v5.18 CONFIG_DEBUG_INFO was completely removed, and the multiple choice option is now the one responsible for enabling debug info. Any choice except CONFIG_DEBUG_INFO_NONE is fine as long as your toolchain supports it.

Where can I find the input.log?

The "log" they are referring to is simply the kernel log. This will be available regardless of CONFIG_DEBUG_INFO. Kernel panics and other OOPSes will usually write stack traces to the kernel log. You can take this directly from the console (if console logging is enabled), or using the dmesg command. See also this doc page for more info. Once you have the log, simply copy-paste it into a text file (input.log), and pass that file to the script's standard input with < input.log.

For an actual panic on the same system you are working on (and not simply inside QEMU or a VM), chances are that the logging can only be done to console, so you might want to enable that:

$ dmesg --console-level 7
$ dmesg --console-on

Take a look at Where are kernel panic logs? on Ask Ubuntu for more ways to capture the log in case of a panic.

As an example, here's the log for a crash generated running echo c > /proc/sysrq-trigger as root on a system running inside QEMU on my machine. I copy-pasted the kernel log into input.log, which contains the following:

[    7.952685] sysrq: Trigger a crash
[    7.952850] Kernel panic - not syncing: sysrq triggered crash
[    7.953098] CPU: 0 PID: 71 Comm: linuxrc Not tainted 5.19.0-rc2 #1
[    7.953259] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.14.0-2 04/01/2014
[    7.953655] Call Trace:
[    7.954133]  <TASK>
[    7.954332]  dump_stack_lvl+0x34/0x44
[    7.954651]  panic+0x102/0x27b
[    7.954756]  ? _printk+0x53/0x6a
[    7.954847]  sysrq_handle_crash+0x11/0x20
[    7.954953]  __handle_sysrq.cold+0x43/0x11b
[    7.955065]  write_sysrq_trigger+0x1f/0x30
[    7.955167]  proc_reg_write+0x4c/0x90
[    7.955267]  vfs_write+0xb4/0x290
[    7.955362]  ksys_write+0x5a/0xd0
[    7.955453]  do_syscall_64+0x3b/0x90
[    7.955553]  entry_SYSCALL_64_after_hwframe+0x46/0xb0
[    7.955773] RIP: 0033:0x4a8531
[    7.955999] Code: e0 ff ff ff f7 d8 64 89 02 48 c7 c0 ff ff ff ff eb b3 0f 1f 80 00 00 00 00 8b 05 d2 26 1e 00 85 c0 75 16 b8 01 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 57 c3 66 0f 1f 44 00 00 8
[    7.956427] RSP: 002b:00007ffde8168508 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
[    7.956625] RAX: ffffffffffffffda RBX: 000000000101a8a0 RCX: 00000000004a8531
[    7.956787] RDX: 0000000000000002 RSI: 00000000010201e0 RDI: 0000000000000001
[    7.956949] RBP: 0000000000000001 R08: fefefefefefefeff R09: fefefefefefeff62
[    7.957113] R10: 00000000000001b6 R11: 0000000000000246 R12: 00000000010201e0
[    7.957275] R13: 0000000000000002 R14: 00007ffde8168701 R15: 00007ffde8168578
[    7.957467]  </TASK>
[    7.957806] Kernel Offset: 0x34a00000 from 0xffffffff81000000 (relocation range: 0xffffffff80000000-0xffffffffbfffffff)
[    7.958215] ---[ end Kernel panic - not syncing: sysrq triggered crash ]---

The only section that you really need to extract from the above is the following:

[    7.954332]  dump_stack_lvl+0x34/0x44
[    7.954651]  panic+0x102/0x27b
[    7.954756]  ? _printk+0x53/0x6a
[    7.954847]  sysrq_handle_crash+0x11/0x20
[    7.954953]  __handle_sysrq.cold+0x43/0x11b
[    7.955065]  write_sysrq_trigger+0x1f/0x30
[    7.955167]  proc_reg_write+0x4c/0x90
[    7.955267]  vfs_write+0xb4/0x290
[    7.955362]  ksys_write+0x5a/0xd0
[    7.955453]  do_syscall_64+0x3b/0x90
[    7.955553]  entry_SYSCALL_64_after_hwframe+0x46/0xb0
[    7.955773] RIP: 0033:0x4a8531
[    7.955999] Code: e0 ff ff ff f7 d8 64 89 02 48 c7 c0 ff ff ff ff eb b3 0f 1f 80 00 00 00 00 8b 05 d2 26 1e 00 85 c0 75 16 b8 01 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 57 c3 66 0f 1f 44 00 00 8

Running decode_stacktrace.sh poiting it to my vmlinux and the kernel source directory yields more info:

$ ./scripts/decode_stacktrace.sh /path/to/vmlinux /path/to/kernel-source-dir < input.log

[    7.952685] sysrq: Trigger a crash
[    7.952850] Kernel panic - not syncing: sysrq triggered crash
[    7.953098] CPU: 0 PID: 71 Comm: linuxrc Not tainted 5.19.0-rc2 #1
[    7.953259] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.14.0-2 04/01/2014
[    7.953655] Call Trace:
[    7.954133]  <TASK>
[    7.954332] dump_stack_lvl (/path/to/kernel-source-dir/lib/dump_stack.c:107 (discriminator 1))
[    7.954651] panic (/path/to/kernel-source-dir/kernel/panic.c:292)
[    7.954756] ? _printk (/path/to/kernel-source-dir/kernel/printk/printk.c:2426)
[    7.954847] sysrq_handle_crash (/path/to/kernel-source-dir/drivers/tty/sysrq.c:155)
[    7.954953] __handle_sysrq.cold (/path/to/kernel-source-dir/drivers/tty/sysrq.c:626)
[    7.955065] write_sysrq_trigger (/path/to/kernel-source-dir/drivers/tty/sysrq.c:1168)
[    7.955167] proc_reg_write (/path/to/kernel-source-dir/fs/proc/inode.c:335 /path/to/kernel-source-dir/fs/proc/inode.c:347)
[    7.955267] vfs_write (/path/to/kernel-source-dir/fs/read_write.c:589)
[    7.955362] ksys_write (/path/to/kernel-source-dir/fs/read_write.c:644)
[    7.955453] do_syscall_64 (/path/to/kernel-source-dir/arch/x86/entry/common.c:50 /path/to/kernel-source-dir/arch/x86/entry/common.c:80)
[    7.955553] entry_SYSCALL_64_after_hwframe (/path/to/kernel-source-dir/arch/x86/entry/entry_64.S:115)
[    7.955773] RIP: 0033:0x4a8531
[ 7.955999] Code: e0 ff ff ff f7 d8 64 89 02 48 c7 c0 ff ff ff ff eb b3 0f 1f 80 00 00 00 00 8b 05 d2 26 1e 00 85 c0 75 16 b8 01 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 57 c3 66 0f 1f 44 00 00 8
All code
========
   0:   e0 ff                   loopne 0x1
   2:   ff                      (bad)
   3:   ff f7                   push   %rdi
   5:   d8 64 89 02             fsubs  0x2(%rcx,%rcx,4)
   9:   48 c7 c0 ff ff ff ff    mov    $0xffffffffffffffff,%rax
  10:   eb b3                   jmp    0xffffffffffffffc5
  12:   0f 1f 80 00 00 00 00    nopl   0x0(%rax)
  19:   8b 05 d2 26 1e 00       mov    0x1e26d2(%rip),%eax        # 0x1e26f1
  1f:   85 c0                   test   %eax,%eax
  21:   75 16                   jne    0x39
  23:   b8 01 00 00 00          mov    $0x1,%eax
  28:   0f 05                   syscall
  2a:*  48 3d 00 f0 ff ff       cmp    $0xfffffffffffff000,%rax         <-- trapping instruction
  30:   77 57                   ja     0x89
  32:   c3                      retq
  33:   66 0f 1f 44 00 00       nopw   0x0(%rax,%rax,1)
  39:   08                      .byte 0x8

Code starting with the faulting instruction
===========================================
   0:   48 3d 00 f0 ff ff       cmp    $0xfffffffffffff000,%rax
   6:   77 57                   ja     0x5f
   8:   c3                      retq
   9:   66 0f 1f 44 00 00       nopw   0x0(%rax,%rax,1)
   f:   08                      .byte 0x8
[    7.956427] RSP: 002b:00007ffde8168508 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
[    7.956625] RAX: ffffffffffffffda RBX: 000000000101a8a0 RCX: 00000000004a8531
[    7.956787] RDX: 0000000000000002 RSI: 00000000010201e0 RDI: 0000000000000001
[    7.956949] RBP: 0000000000000001 R08: fefefefefefefeff R09: fefefefefefeff62
[    7.957113] R10: 00000000000001b6 R11: 0000000000000246 R12: 00000000010201e0
[    7.957275] R13: 0000000000000002 R14: 00007ffde8168701 R15: 00007ffde8168578
[    7.957467]  </TASK>
[    7.957806] Kernel Offset: 0x34a00000 from 0xffffffff81000000 (relocation range: 0xffffffff80000000-0xffffffffbfffffff)
[    7.958215] ---[ end Kernel panic - not syncing: sysrq triggered crash ]---

Regarding Q2, I setup a serial console where I can get all the kernel messages, including the input.log. Below I list the steps to setup a serial console. Components: 1x Linux machine, 1 x PC with Win10 and Putty, 1x USB to Serial Converter enter image description here

  1. Your Win10 should automatically recognize the USB2Serial converter and install the driver. The converter appears in Device Manager, in my case COM6.
  2. Setup Putty, Serial, baud-rate 115200, Databits 8, Stopbits 1, Parity none, Flowcontrol XON/XOFF.
  3. Make sure that serial port is enabled in Linux machine.

$ dmesg | grep tty

[    0.108687] printk: console [tty0] enabled 
[    2.752397] 00:03:ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A 
[   2.773666] 00:04: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A

It shows that both ttyS0(COM1) and ttyS1(COM2) work fine. In my case I choose ttyS1.

  1. Use getty to manage ttyS1.

sudo /sbin/getty -L 115200 ttyS1 vt102

Then the Putty would prompt login, just input your username and password to get into the command line interface. But still at this stage, the ttyS1 is another pseudo-terminal, but not a console. You need to configure it as a console.

  1. Make sure that you've already compiled in the serail port in your Linux kernel image. make menuconfig : Device driver ‣ Character devices ‣ Serial drivers ‣ 8250/16550 and compatible serial support ‣ Console on 8250/16550 and compatible serial port: choose built-in. If it's alreay that, leave it. Otherwise, change the configuration, rebuilt the kernel, and reboot.
  2. Check the current console.

$cat /sys/devices/virtual/tty/console/active

tty0

It means that current console is tty0. We need to add ttyS1 as a console.

  1. Add console=ttyS1 in Linux kernel boot argument.

$sudo vim /etc/default/grub

Change the line GRUB_CMDLINE_LINUX_DEFAULT="quiet splash" to GRUB_CMDLINE_LINUX_DEFAULT="quiet console=ttyS1,115200 splash" Then

$sudo update-grub

$sudo reboot

  1. Check the current console.

$ cat /sys/devices/virtual/tty/console/active

ttyS1

That's it.

  1. Call getty again.

sudo /sbin/getty -L 115200 ttyS1 vt102

Then Putty would get the login prompt and after you login, it becomes a real console.

Related