When a bug occurs, one of the first things we look at is the stack trace because the function calls leading up to the error give us an idea of what the problem could be. And at the very least, it gives us a place to start investigating.
In this post, we’ll walk through an analysis of the stack trace of a bug reported by Syzbot, an automated system running the Syzkaller fuzzer on the Linux kernel. The stack trace in question can be found here: https://syzkaller.appspot.com/text?tag=CrashLog&x=17f5743fe00000
In particular, we’ll be using the scripts/decode_stacktrace.sh tool introduced by Sasha Levin to make sense of the stack trace.
So you have a stack trace
Great. A bug that is known to exist is infinitely more solvable than a bug whose existent we’re not sure of. But wait, it just looks like a bunch of gibberish. Take the first few lines of our stack trace for example:
[ 844.569701][ T7073] Call Trace:
[ 844.569734][ T7073] <IRQ>
[ 844.569805][ T7073] dump_stack+0x188/0x20d
[ 844.569823][ T7073] ? uncore_pmu_event_add+0xa25/0x16d0
[ 844.569884][ T7073] __kasan_report.cold+0x5/0x4d
[ 844.569902][ T7073] ? uncore_pmu_event_add+0xa25/0x16d0
[ 844.569919][ T7073] ? uncore_pmu_event_add+0xa25/0x16d0
[ 844.569931][ T7073] kasan_report+0x33/0x50
[ 844.569953][ T7073] check_memory_region+0x141/0x190
[ 844.569969][ T7073] uncore_pmu_event_add+0xa25/0x16d0
[ 844.570036][ T7073] ? interrupt_entry+0xb8/0xc0
[ 844.570050][ T7073] ? apic_timer_interrupt+0xa/0x20
[ 844.570056][ T7073] </IRQ>
...
As Sasha Levin pointed out in her patch, the only useful things that we can get out of these are the function names in the call trace (admittedly, still useful). But the +<offset>/<length> that follows the function names aren’t very useful.
Decoding symbols
This is where scripts/decode_stacktrace.sh comes to the rescue. What this script essentially does is that it parses the stack trace for you and calls addr2line for every symbol, giving you all the file names and line numbers for each call in your stack trace.
Since addr2line (and by extension scripts/decode_stacktrace.sh) requires an executable to carry out the conversion, we must first obtain an appropriate kernel image. Using any old kernel image wouldn’t do, because different versions of the kernel, along with different configurations, means that the translation that you get becomes meaningless.
So to generate the appropriate image we need two things: the source code, and the configuration. A little hunting on the internet brings us to the original bug report by Syzbot: https://syzkaller.appspot.com/bug?extid=832ccf42c61e3c63654e. Here, the specific commit and configuration of the test are conveniently provided. Checking out this commit, and compiling the kernel with this configuration, we get the desired vmlinux kernel image.
Now we run scripts/decode_stacktrace.sh vmlinux /home/desmond/linux_work/linux_mainline < ../linux_misc/learn_decode_stacktrace/sample.log to get a more readable stack trace. I included the full trace at the end of this post, for now let's take a look at the same lines of the call trace that we previously saw:
[ 844.569701][ T7073] Call Trace:
[ 844.569734][ T7073] <IRQ>
[ 844.569805][ T7073] dump_stack (lib/dump_stack.c:120)
[ 844.569823][ T7073] ? uncore_pmu_event_add (arch/x86/events/intel/uncore.h:375 arch/x86/events/intel/uncore.c:230 arch/x86/events/intel/uncore.c:602)
[ 844.569884][ T7073] __kasan_report.cold (mm/kasan/report.c:518)
[ 844.569902][ T7073] ? uncore_pmu_event_add (arch/x86/events/intel/uncore.h:375 arch/x86/events/intel/uncore.c:230 arch/x86/events/intel/uncore.c:602)
[ 844.569919][ T7073] ? uncore_pmu_event_add (arch/x86/events/intel/uncore.h:375 arch/x86/events/intel/uncore.c:230 arch/x86/events/intel/uncore.c:602)
[ 844.569931][ T7073] kasan_report (mm/kasan/common.c:625)
[ 844.569953][ T7073] check_memory_region (mm/kasan/generic.c:194)
[ 844.569969][ T7073] uncore_pmu_event_add (arch/x86/events/intel/uncore.h:375 arch/x86/events/intel/uncore.c:230 arch/x86/events/intel/uncore.c:602)
[ 844.570036][ T7073] ? interrupt_entry (arch/x86/entry/entry_64.S:581)
[ 844.570050][ T7073] ? apic_timer_interrupt (arch/x86/entry/entry_64.S:829)
[ 844.570056][ T7073] </IRQ>
Much better, isn’t it?
Notice that some symbols seem to have multiple files. This happens when symbols are inlined, so the address in question is involves definitions in multiple parts of the code. Let’s consider the symbol at [ 844.569823][ T7073] ? uncore_pmu_event_add (arch/x86/events/intel/uncore.h:375 arch/x86/events/intel/uncore.c:230 arch/x86/events/intel/uncore.c:602) as an example.
arch/x86/events/intel/uncore.c:602:
int uncore_pmu_event_add(struct perf_event *event, int flags)
{
...
uncore_assign_hw_event(box, event, assign[i]);
...
}
arch/x86/events/intel/uncore.c:230:
static void uncore_assign_hw_event(struct intel_uncore_box *box,
struct perf_event *event, int idx)
{
...
hwc->event_base = uncore_perf_ctr(box, hwc->idx);
}
arch/x86/events/intel/uncore.h:375:
unsigned uncore_perf_ctr(struct intel_uncore_box *box, int idx)
{
if (box->pci_dev || box->io_addr)
...
}
Looking at these lines of code, we see that box is a NULL pointer, hence the dereference at arch/x86/events/intel/uncore.h:375 to get box->pci_dev || box->io_addr triggers the kernel error.
At the same time, that conclusion smells fishy to me, because just a few lines before arch/x86/events/intel/uncore.c:230, we get the following line:
static void uncore_assign_hw_event(struct intel_uncore_box *box,
struct perf_event *event, int idx)
{
struct hw_perf_event *hwc = &event->hw;
hwc->idx = idx;
hwc->last_tag = ++box->tags[idx];
if (uncore_pmc_fixed(hwc->idx)) {
hwc->event_base = uncore_fixed_ctr(box);
hwc->config_base = uncore_fixed_ctl(box);
return;
}
hwc->config_base = uncore_event_ctl(box, hwc->idx);
hwc->event_base = uncore_perf_ctr(box, hwc->idx);
}
There was seemingly no issues dereferencing box on line 221, so why was there an issue later? Moreover, the uncore_pmu_event_add function also includes a NULL pointer check:
int uncore_pmu_event_add(struct perf_event *event, int flags)
{
struct intel_uncore_box *box = uncore_event_to_box(event);
struct hw_perf_event *hwc = &event->hw;
int assign[UNCORE_PMC_IDX_MAX];
int i, n, ret;
if (!box)
return -ENODEV;
...
More detective work needs to be done to unravel this mystery. For now, let’s continue analyzing the stack trace.
From the stack trace, prior to the function call to uncore_pmu_event_add, it seems that various KASAN checks and timer interrupts were invoked, and prior to that, most of the function calls came from the fbdev video driver, i.e. the video driver for framebuffer devices.
Further investigation of this kernel error should thus begin with looking closer at the Intel uncore functions as well as the framebuffer device video driver.
The full output log
For reference, here’s the complete output from scripts/decode_stacktrace.sh:
# scripts/decode_stacktrace.sh vmlinux /home/desmond/linux_work/linux_mainline < ../linux_misc/learn_decode_stacktrace/sample.log
[ [0;32m OK [0m] Reached target Login Prompts.
[ [0;32m OK [0m] Reached target Multi-User System.
[ [0;32m OK [0m] Reached target Graphical Interface.
Starting Update UTMP about System Runlevel Changes...
[ [0;32m OK [0m] Started Update UTMP about System Runlevel Changes.
Debian GNU/Linux 9 syzkaller ttyS0
Warning: Permanently added '10.128.10.30' (ECDSA) to the list of known hosts.
executing program
executing program
syzkaller login: [ 844.569463][ T7073] ==================================================================
[ 844.569638][ T7073] BUG: KASAN: null-ptr-deref in uncore_pmu_event_add (arch/x86/events/intel/uncore.h:375 arch/x86/events/intel/uncore.c:230 arch/x86/events/intel/uncore.c:602)
[ 844.569649][ T7073] Read of size 8 at addr 0000000000000000 by task syz-executor764/7073
[ 844.569653][ T7073]
[ 844.569668][ T7073] CPU: 0 PID: 7073 Comm: syz-executor764 Not tainted 5.7.0-rc1-next-20200415-syzkaller #0
[ 844.569676][ T7073] Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
[ 844.569701][ T7073] Call Trace:
[ 844.569734][ T7073] <IRQ>
[ 844.569805][ T7073] dump_stack (lib/dump_stack.c:120)
[ 844.569823][ T7073] ? uncore_pmu_event_add (arch/x86/events/intel/uncore.h:375 arch/x86/events/intel/uncore.c:230 arch/x86/events/intel/uncore.c:602)
[ 844.569884][ T7073] __kasan_report.cold (mm/kasan/report.c:518)
[ 844.569902][ T7073] ? uncore_pmu_event_add (arch/x86/events/intel/uncore.h:375 arch/x86/events/intel/uncore.c:230 arch/x86/events/intel/uncore.c:602)
[ 844.569919][ T7073] ? uncore_pmu_event_add (arch/x86/events/intel/uncore.h:375 arch/x86/events/intel/uncore.c:230 arch/x86/events/intel/uncore.c:602)
[ 844.569931][ T7073] kasan_report (mm/kasan/common.c:625)
[ 844.569953][ T7073] check_memory_region (mm/kasan/generic.c:194)
[ 844.569969][ T7073] uncore_pmu_event_add (arch/x86/events/intel/uncore.h:375 arch/x86/events/intel/uncore.c:230 arch/x86/events/intel/uncore.c:602)
[ 844.570036][ T7073] ? interrupt_entry (arch/x86/entry/entry_64.S:581)
[ 844.570050][ T7073] ? apic_timer_interrupt (arch/x86/entry/entry_64.S:829)
[ 844.570056][ T7073] </IRQ>
[ 844.570104][ T7073] ? vga16fb_fillrect (drivers/video/fbdev/vga16fb.c:924)
[ 844.570118][ T7073] ? vga16fb_fillrect (drivers/video/fbdev/vga16fb.c:922)
[ 844.570161][ T7073] ? __sanitizer_cov_trace_pc (kernel/kcov.c:197)
[ 844.570176][ T7073] ? vga16fb_fillrect (drivers/video/fbdev/vga16fb.c:922)
[ 844.570192][ T7073] ? memcpy (mm/kasan/common.c:106 (discriminator 1))
[ 844.570229][ T7073] ? bit_clear_margins (drivers/video/fbdev/core/bitblit.c:224)
[ 844.570244][ T7073] ? bit_bmove (drivers/video/fbdev/core/bitblit.c:207)
[ 844.570259][ T7073] ? vesafb_probe.cold (drivers/video/fbdev/vga16fb.c:219)
[ 844.570301][ T7073] ? fbcon_clear_margins (drivers/video/fbdev/core/fbcon.c:1382)
[ 844.570317][ T7073] ? fbcon_switch (drivers/video/fbdev/core/fbcon.c:2359)
[ 844.570337][ T7073] ? fbcon_set_def_font (drivers/video/fbdev/core/fbcon.c:2647)
[ 844.570365][ T7073] ? fbcon_cursor (drivers/video/fbdev/core/fbcon.c:1401)
[ 844.570377][ T7073] ? bit_clear (./include/linux/slab.h:593)
[ 844.570412][ T7073] ? is_console_locked (kernel/printk/printk.c:2351)
[ 844.570424][ T7073] ? fbcon_set_origin (drivers/video/fbdev/core/fbcon.c:2939)
[ 844.570467][ T7073] ? redraw_screen (drivers/tty/vt/vt.c:1010)
[ 844.570479][ T7073] ? vesafb_probe.cold (drivers/video/fbdev/vga16fb.c:219)
[ 844.570494][ T7073] ? respond_string (drivers/tty/vt/vt.c:623)
[ 844.570510][ T7073] ? fbcon_set_palette (drivers/video/fbdev/core/fbcon.c:2765)
[ 844.570527][ T7073] ? fbcon_modechanged (drivers/video/fbdev/core/fbcon.c:3002)
[ 844.570545][ T7073] ? fbcon_set_all_vcs (drivers/video/fbdev/core/fbcon.c:3038)
[ 844.570564][ T7073] ? fbcon_update_vcs (drivers/video/fbdev/core/fbcon.c:3048)
[ 844.570578][ T7073] ? fb_set_var (drivers/video/fbdev/core/fbmem.c:1006)
[ 844.570593][ T7073] ? fb_blank (drivers/video/fbdev/core/fbmem.c:959)
[ 844.570617][ T7073] ? mark_held_locks (kernel/locking/lockdep.c:4213)
[ 844.570666][ T7073] ? _raw_spin_unlock_irqrestore (./arch/x86/include/asm/paravirt.h:759 ./include/linux/spinlock_api_smp.h:160 kernel/locking/spinlock.c:191)
[ 844.570685][ T7073] ? do_fb_ioctl (drivers/video/fbdev/core/fbmem.c:1113)
[ 844.570700][ T7073] ? fb_mmap (drivers/video/fbdev/core/fbmem.c:1086)
[ 844.570786][ T7073] ? tomoyo_execute_permission (security/tomoyo/file.c:710)
[ 844.570818][ T7073] ? __sanitizer_cov_trace_switch (kernel/kcov.c:319 (discriminator 3))
[ 844.570878][ T7073] ? do_vfs_ioctl (fs/ioctl.c:597 fs/ioctl.c:696)
[ 844.570908][ T7073] ? up_read (./include/linux/instrumented.h:56 (discriminator 12) ./include/asm-generic/atomic-instrumented.h:837 (discriminator 12) ./include/asm-generic/atomic-long.h:29 (discriminator 12) kernel/locking/rwsem.c:1649 (discriminator 12))
[ 844.570924][ T7073] ? down_read_nested (kernel/locking/rwsem.c:1617)
[ 844.570948][ T7073] ? fb_ioctl (drivers/video/fbdev/core/fbmem.c:1185)
[ 844.570961][ T7073] ? do_fb_ioctl (./include/linux/fs.h:1324 drivers/video/fbdev/core/fbmem.c:753 drivers/video/fbdev/core/fbmem.c:1181)
[ 844.570974][ T7073] ? ksys_ioctl (fs/ioctl.c:48 fs/ioctl.c:763)
[ 844.570991][ T7073] ? __x64_sys_ioctl (fs/ioctl.c:770)
[ 844.571004][ T7073] ? lockdep_hardirqs_on (kernel/locking/lockdep.c:3657 kernel/locking/lockdep.c:3702)
[ 844.571041][ T7073] ? do_syscall_64 (arch/x86/entry/common.c:295)
[ 844.571058][ T7073] ? entry_SYSCALL_64_after_hwframe (arch/x86/entry/entry_64.S:177)
[ 844.571079][ T7073] ==================================================================
[ 844.571083][ T7073] Disabling lock debugging due to kernel taint
[ 844.571090][ T7073] Kernel panic - not syncing: panic_on_warn set ...
[ 844.571103][ T7073] CPU: 0 PID: 7073 Comm: syz-executor764 Tainted: G B 5.7.0-rc1-next-20200415-syzkaller #0
[ 844.571110][ T7073] Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
[ 844.571113][ T7073] Call Trace:
[ 844.571117][ T7073] <IRQ>
[ 844.571128][ T7073] dump_stack (lib/dump_stack.c:120)
[ 844.571176][ T7073] panic (kernel/panic.c:239)
[ 844.571189][ T7073] ? add_taint.cold (kernel/panic.c:168)
[ 844.571205][ T7073] ? uncore_pmu_event_add (arch/x86/events/intel/uncore.h:375 arch/x86/events/intel/uncore.c:230 arch/x86/events/intel/uncore.c:602)
[ 844.571223][ T7073] ? trace_hardirqs_off (kernel/trace/trace_preemptirq.c:45)
[ 844.571234][ T7073] ? trace_hardirqs_off (kernel/trace/trace_preemptirq.c:45)
[ 844.571248][ T7073] ? uncore_pmu_event_add (arch/x86/events/intel/uncore.h:375 arch/x86/events/intel/uncore.c:230 arch/x86/events/intel/uncore.c:602)
[ 844.571260][ T7073] end_report (mm/kasan/report.c:106)
[ 844.571272][ T7073] __kasan_report.cold (mm/kasan/report.c:519)
[ 844.571287][ T7073] ? uncore_pmu_event_add (arch/x86/events/intel/uncore.h:375 arch/x86/events/intel/uncore.c:230 arch/x86/events/intel/uncore.c:602)
[ 844.571300][ T7073] ? uncore_pmu_event_add (arch/x86/events/intel/uncore.h:375 arch/x86/events/intel/uncore.c:230 arch/x86/events/intel/uncore.c:602)
[ 844.571311][ T7073] kasan_report (mm/kasan/common.c:625)
[ 844.571324][ T7073] check_memory_region (mm/kasan/generic.c:194)
[ 844.571338][ T7073] uncore_pmu_event_add (arch/x86/events/intel/uncore.h:375 arch/x86/events/intel/uncore.c:230 arch/x86/events/intel/uncore.c:602)
[ 844.571348][ T7073] ? interrupt_entry (arch/x86/entry/entry_64.S:581)
[ 844.571360][ T7073] ? apic_timer_interrupt (arch/x86/entry/entry_64.S:829)
[ 844.571364][ T7073] </IRQ>
[ 844.571377][ T7073] ? vga16fb_fillrect (drivers/video/fbdev/vga16fb.c:924)
[ 844.571386][ T7073] ? vga16fb_fillrect (drivers/video/fbdev/vga16fb.c:922)
[ 844.571396][ T7073] ? __sanitizer_cov_trace_pc (kernel/kcov.c:197)
[ 844.571408][ T7073] ? vga16fb_fillrect (drivers/video/fbdev/vga16fb.c:922)
[ 844.571419][ T7073] ? memcpy (mm/kasan/common.c:106 (discriminator 1))
[ 844.571432][ T7073] ? bit_clear_margins (drivers/video/fbdev/core/bitblit.c:224)
[ 844.571443][ T7073] ? bit_bmove (drivers/video/fbdev/core/bitblit.c:207)
[ 844.571454][ T7073] ? vesafb_probe.cold (drivers/video/fbdev/vga16fb.c:219)
[ 844.571471][ T7073] ? fbcon_clear_margins (drivers/video/fbdev/core/fbcon.c:1382)
[ 844.571483][ T7073] ? fbcon_switch (drivers/video/fbdev/core/fbcon.c:2359)
[ 844.571497][ T7073] ? fbcon_set_def_font (drivers/video/fbdev/core/fbcon.c:2647)
[ 844.571513][ T7073] ? fbcon_cursor (drivers/video/fbdev/core/fbcon.c:1401)
[ 844.571523][ T7073] ? bit_clear (./include/linux/slab.h:593)
[ 844.571534][ T7073] ? is_console_locked (kernel/printk/printk.c:2351)
[ 844.571544][ T7073] ? fbcon_set_origin (drivers/video/fbdev/core/fbcon.c:2939)
[ 844.571557][ T7073] ? redraw_screen (drivers/tty/vt/vt.c:1010)
[ 844.571567][ T7073] ? vesafb_probe.cold (drivers/video/fbdev/vga16fb.c:219)
[ 844.571580][ T7073] ? respond_string (drivers/tty/vt/vt.c:623)
[ 844.571592][ T7073] ? fbcon_set_palette (drivers/video/fbdev/core/fbcon.c:2765)
[ 844.571604][ T7073] ? fbcon_modechanged (drivers/video/fbdev/core/fbcon.c:3002)
[ 844.571617][ T7073] ? fbcon_set_all_vcs (drivers/video/fbdev/core/fbcon.c:3038)
[ 844.571630][ T7073] ? fbcon_update_vcs (drivers/video/fbdev/core/fbcon.c:3048)
[ 844.571642][ T7073] ? fb_set_var (drivers/video/fbdev/core/fbmem.c:1006)
[ 844.571654][ T7073] ? fb_blank (drivers/video/fbdev/core/fbmem.c:959)
[ 844.571667][ T7073] ? mark_held_locks (kernel/locking/lockdep.c:4213)
[ 844.571694][ T7073] ? _raw_spin_unlock_irqrestore (./arch/x86/include/asm/paravirt.h:759 ./include/linux/spinlock_api_smp.h:160 kernel/locking/spinlock.c:191)
[ 844.571708][ T7073] ? do_fb_ioctl (drivers/video/fbdev/core/fbmem.c:1113)
[ 844.571719][ T7073] ? fb_mmap (drivers/video/fbdev/core/fbmem.c:1086)
[ 844.571732][ T7073] ? tomoyo_execute_permission (security/tomoyo/file.c:710)
[ 844.571751][ T7073] ? __sanitizer_cov_trace_switch (kernel/kcov.c:319 (discriminator 3))
[ 844.571763][ T7073] ? do_vfs_ioctl (fs/ioctl.c:597 fs/ioctl.c:696)
[ 844.571781][ T7073] ? up_read (./include/linux/instrumented.h:56 (discriminator 12) ./include/asm-generic/atomic-instrumented.h:837 (discriminator 12) ./include/asm-generic/atomic-long.h:29 (discriminator 12) kernel/locking/rwsem.c:1649 (discriminator 12))
[ 844.571793][ T7073] ? down_read_nested (kernel/locking/rwsem.c:1617)
[ 844.571806][ T7073] ? fb_ioctl (drivers/video/fbdev/core/fbmem.c:1185)
[ 844.571818][ T7073] ? do_fb_ioctl (./include/linux/fs.h:1324 drivers/video/fbdev/core/fbmem.c:753 drivers/video/fbdev/core/fbmem.c:1181)
[ 844.571829][ T7073] ? ksys_ioctl (fs/ioctl.c:48 fs/ioctl.c:763)
[ 844.571843][ T7073] ? __x64_sys_ioctl (fs/ioctl.c:770)
[ 844.571854][ T7073] ? lockdep_hardirqs_on (kernel/locking/lockdep.c:3657 kernel/locking/lockdep.c:3702)
[ 844.571867][ T7073] ? do_syscall_64 (arch/x86/entry/common.c:295)
[ 844.571880][ T7073] ? entry_SYSCALL_64_after_hwframe (arch/x86/entry/entry_64.S:177)
[ 845.748127][ T7073] Shutting down cpus with NMI
[ 845.750244][ T7073] Kernel Offset: disabled
[ 846.436980][ T7073] Rebooting in 86400 seconds..
@DesmondCheong, thanks for this article, it was very helpfull to start with syzkaller fuzzer,
Have query to ask, how to find the .config or bug report for any crash report (https://syzkaller.appspot.com/text?tag=CrashLog&x=17f5743fe00000)
Pingback: Vignettes of a Linux Kernel Mentee – Desmond Cheong
Why did you used particular .config file?