On Sun, Aug 07, 2016 at 01:58:16AM -0700, Andy Lutomirski wrote:
> Hi Steven and Josh-
>
> This test recursively faulted in is_ftrace_trampoline. It's not
> immediately obvious to me what went wrong -- is_ftrace_trampoline
> doesn't seem to be dereferencing the provided address.
It seems to be faulting because one of the entries in the
ftrace_ops_list is corrupt.
00000000000013cc <is_ftrace_trampoline>:
13cc: 55 push %rbp
13cd: 65 ff 05 00 00 00 00 incl %gs:0x0(%rip) # 13d4
<is_ftrace_trampoline+0x8>
13d0: R_X86_64_PC32 __preempt_count-0x4
13d4: 48 89 e5 mov %rsp,%rbp
13d7: 41 54 push %r12
13d9: 49 89 fc mov %rdi,%r12
13dc: 53 push %rbx
13dd: 48 8b 1d 00 00 00 00 mov 0x0(%rip),%rbx # 13e4
<is_ftrace_trampoline+0x18>
13e0: R_X86_64_PC32 .data..read_mostly+0x7c4
13e4: e8 00 00 00 00 callq 13e9 <is_ftrace_trampoline+0x1d>
13e5: R_X86_64_PC32 debug_lockdep_rcu_enabled-0x4
13e9: 48 8b 83 98 01 00 00 mov 0x198(%rbx),%rax
^^^^ faults here because rbx (ops) is a bad pointer (RBX: 6b6b6b6b6b6b6b6b)
13f0: 48 85 c0 test %rax,%rax
13f3: 74 19 je 140e <is_ftrace_trampoline+0x42>
13f5: 4c 39 e0 cmp %r12,%rax
13f8: 48 8b 93 a0 01 00 00 mov 0x1a0(%rbx),%rdx
13ff: 77 0d ja 140e <is_ftrace_trampoline+0x42>
1401: 48 85 d2 test %rdx,%rdx
1404: 74 08 je 140e <is_ftrace_trampoline+0x42>
1406: 48 01 d0 add %rdx,%rax
1409: 49 39 c4 cmp %rax,%r12
140c: 72 21 jb 142f <is_ftrace_trampoline+0x63>
140e: 48 8b 5b 08 mov 0x8(%rbx),%rbx
1412: e8 00 00 00 00 callq 1417 <is_ftrace_trampoline+0x4b>
1413: R_X86_64_PC32 debug_lockdep_rcu_enabled-0x4
1417: 48 81 fb 00 00 00 00 cmp $0x0,%rbx
141a: R_X86_64_32S .data..read_mostly+0x800
141e: 0f 95 c2 setne %dl
1421: 48 85 db test %rbx,%rbx
1424: 0f 95 c0 setne %al
1427: 84 c2 test %al,%dl
1429: 75 be jne 13e9 <is_ftrace_trampoline+0x1d>
Note that shortly before the recursive fault started, another ftrace
error occurred:
[ 59.235185] ftrace: Failed on adding breakpoints (124910):
[ 59.848448] ------------[ cut here ]------------
[ 59.853011] WARNING: CPU: 0 PID: 1625 at kernel/trace/ftrace.c:2006
ftrace_bug+0x102/0x24a
[ 59.898634] Modules linked in:
[ 59.902617] CPU: 0 PID: 1625 Comm: trinity-main Not tainted
4.7.0-06443-g4bc0303 #82
[ 59.909984] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS
Debian-1.8.2-1 04/01/2014
[ 59.926316] 0000000000000000 ffffc90004f9fbe0 ffffffff81780126
0000000000000000
[ 59.946998] 0000000000000000 ffffc90004f9fc20 ffffffff810e4fd9
000007d600000000
[ 59.955226] ffff880031ebfee0 ffffffff8324c9a0 ffffffff85652b30
0000000000000001
[ 59.976130] Call Trace:
[ 59.979819] [<ffffffff81780126>] dump_stack+0x82/0xb8
[ 59.997638] [<ffffffff810e4fd9>] __warn+0xc2/0xdd
[ 60.001832] [<ffffffff810e50b0>] warn_slowpath_null+0x1d/0x1f
[ 60.006141] [<ffffffff81187920>] ftrace_bug+0x102/0x24a
[ 60.023201] [<ffffffff810979c6>] ftrace_replace_code+0x227/0x350
[ 60.027709] [<ffffffff81188065>] ftrace_modify_all_code+0x41/0xc9
[ 60.032357] [<ffffffff81097aff>] arch_ftrace_update_code+0x10/0x19
[ 60.049494] [<ffffffff81186b6a>] ftrace_run_update_code+0x1e/0x3f
[ 60.054082] [<ffffffff81186bbd>] ftrace_startup_enable+0x32/0x34
[ 60.070761] [<ffffffff81186d54>] ftrace_startup+0x195/0x1a7
[ 60.075193] [<ffffffff81186d8c>] register_ftrace_function+0x26/0x3c
[ 60.079704] [<ffffffff811a1163>] perf_ftrace_event_register+0x42/0xe7
[ 60.114514] [<ffffffff811a0fd6>] perf_trace_init+0x29d/0x2dc
[ 60.119309] [<ffffffff811ad345>] perf_tp_event_init+0x29/0x3b
[ 60.124026] [<ffffffff811ade86>] perf_try_init_event+0x46/0x76
[ 60.147114] [<ffffffff811b0034>] perf_event_alloc+0x3c4/0x6ad
[ 60.169443] [<ffffffff811b2e47>] SYSC_perf_event_open+0x490/0xb2c
[ 60.174482] [<ffffffff811b6b7b>] SyS_perf_event_open+0x9/0xb
[ 60.197378] [<ffffffff81003c42>] do_int80_syscall_32+0x65/0x74
[ 60.202211] [<ffffffff82ee2598>] entry_INT80_compat+0x38/0x50
[ 60.221358] ---[ end trace e31eb279467a53f4 ]---
[ 60.604454] ftrace faulted on writing [<ffffffff8324c9a0>]
lkdtm_rodata_do_nothing+0x0/0x10
[ 60.612963] Setting ftrace call site to call ftrace function
[ 60.653362] ftrace record flags: 10000001
[ 60.658136] (1)
expected tramp: ffffffff82ee25d0
This seems to be an expected error caused by the test case (tracing an
rodata function). But maybe there's something in the ftrace error path
which corrupts ftrace_ops_list somehow? Or triggers a use-after-free?
>
> On Fri, Aug 5, 2016 at 7:07 AM, kernel test robot <[email protected]>
> wrote:
> >
> > FYI, we noticed the following commit:
> >
> > https://git.kernel.org/pub/scm/linux/kernel/git/luto/linux.git
> > x86/vmap_stack
> > commit 4bc0303affaa75add8c5c2fbfd6d27d9b644fa0d ("x86/mm/64: Enable vmapped
> > stacks")
> >
> > in testcase: boot
> >
> > on test machine: 1 threads qemu-system-x86_64 -enable-kvm -cpu Westmere
> > with 512M memory
> >
> > caused below changes:
> >
> >
> > +-------------------------------------------------------+------------+------------+
> > | | ee12d3b8b1 |
> > 4bc0303aff |
> > +-------------------------------------------------------+------------+------------+
> > | boot_successes | 388 | 398
> > |
> > | boot_failures | 32 | 39
> > |
> > | WARNING:at_kernel/trace/ftrace.c:#ftrace_bug | 32 | 39
> > |
> > | general_protection_fault:#[##]SMP | 32 | 37
> > |
> > | RIP:is_ftrace_trampoline | 32 | 37
> > |
> > | Kernel_panic-not_syncing:Fatal_exception_in_interrupt | 18 | 8
> > |
> > | backtrace:perf_ftrace_event_register | 32 | 39
> > |
> > | backtrace:perf_trace_init | 32 | 39
> > |
> > | backtrace:perf_tp_event_init | 32 | 39
> > |
> > | backtrace:perf_try_init_event | 32 | 39
> > |
> > | backtrace:SYSC_perf_event_open | 31 | 38
> > |
> > | backtrace:SyS_perf_event_open | 32 | 39
> > |
> > | Kernel_panic-not_syncing:Fatal_exception | 12 | 13
> > |
> > | WARNING:at_include/linux/uaccess.h:#pagefault_enable | 4 |
> > |
> > | RIP:#d:[<#>][<#>]is_ftrace_trampoline | 1 |
> > |
> > | BUG:kernel_test_hang | 1 | 16
> > |
> > | BUG:unable_to_handle_kernel | 1 |
> > |
> > | Oops | 1 |
> > |
> > | RIP:task_curr | 1 |
> > |
> > | BUG:stack_guard_page_was_hit_at#(stack_is#..#) | 0 | 17
> > |
> > | RIP:fb_get_color_depth | 0 | 3
> > |
> > | RIP:cfb_imageblit | 0 | 8
> > |
> > | RIP:fb_get_buffer_offset | 0 | 4
> > |
> > | RIP:get_attribute | 0 | 1
> > |
> > | RIP:number | 0 | 1
> > |
> > +-------------------------------------------------------+------------+------------+
> >
> > [ 68.243445] Call Trace:
> > [ 68.244310] general protection fault: 0000 [#18] SMP
> > [ 68.249171] BUG: stack guard page was hit at ffffc900001bbff8 (stack is
> > ffffc900001bc000..ffffc900001bffff)
> > [ 68.249174] kernel stack overflow (double-fault): 0000 [#19] SMP
> > [ 68.249175] Modules linked in:
> > [ 68.249178] CPU: 0 PID: 6 Comm: kworker/u2:0 Tainted: G W
> > 4.7.0-06443-g4bc0303 #82
> > [ 68.249179] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS
> > Debian-1.8.2-1 04/01/2014
> > [ 68.249185] Workqueue: netns cleanup_net
> > [ 68.249187] task: ffff8800314ec180 task.stack: ffffc900001bc000
> > [ 68.249192] RIP: 0010:[<ffffffff817f31f0>] [<ffffffff817f31f0>]
> > fb_get_buffer_offset+0x18/0x8c
> > [ 68.249193] RSP: 0000:ffffc900001bc000 EFLAGS: 00010002
> > [ 68.249194] RAX: 0000000000000001 RBX: ffff88002deab000 RCX:
> > 0000000000000001
> > [ 68.249195] RDX: 0000000000000001 RSI: ffff88002deab320 RDI:
> > ffff88002deab000
> > [ 68.249197] RBP: ffffc900001bc018 R08: 0000000000000000 R09:
> > 0000000000000048
> > [ 68.249198] R10: 0000000000000000 R11: ffffffff83174d50 R12:
> > ffff88002cb68000
> > [ 68.249199] R13: 00000000ffffffff R14: 0000000000000010 R15:
> > ffff880031c0d800
> > [ 68.249202] FS: 0000000000000000(0000) GS:ffff880033200000(0000)
> > knlGS:0000000000000000
> > [ 68.249203] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > [ 68.249204] CR2: ffffc900001bbff8 CR3: 0000000004021000 CR4:
> > 00000000000006f0
> > [ 68.249208] DR0: 0000000008c45968 DR1: 0000000000000000 DR2:
> > 0000000000000000
> > [ 68.249210] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7:
> > 0000000000000600
> > [ 68.249210] Stack:
> > [ 68.249211]
> >
> >
> > FYI, raw QEMU command line is:
> >
> > qemu-system-x86_64 -enable-kvm -cpu Westmere -kernel
> > /pkg/linux/x86_64-allyesdebian/gcc-6/4bc0303affaa75add8c5c2fbfd6d27d9b644fa0d/vmlinuz-4.7.0-06443-g4bc0303
> > -append 'ip=::::vm-kbuild-yocto-ia32-29::dhcp root=/dev/ram0 user=lkp
> > job=/lkp/scheduled/vm-kbuild-yocto-ia32-29/boot-1-yocto-minimal-i386.cgz-4bc0303affaa75add8c5c2fbfd6d27d9b644fa0d-20160801-54711-lk1j2k-228.yaml
> > ARCH=x86_64 kconfig=x86_64-allyesdebian
> > branch=linux-devel/devel-catchup-201607300515
> > commit=4bc0303affaa75add8c5c2fbfd6d27d9b644fa0d
> > BOOT_IMAGE=/pkg/linux/x86_64-allyesdebian/gcc-6/4bc0303affaa75add8c5c2fbfd6d27d9b644fa0d/vmlinuz-4.7.0-06443-g4bc0303
> > max_uptime=600
> > RESULT_ROOT=/result/boot/1/vm-kbuild-yocto-ia32/yocto-minimal-i386.cgz/x86_64-allyesdebian/gcc-6/4bc0303affaa75add8c5c2fbfd6d27d9b644fa0d/227
> > LKP_SERVER=inn debug apic=debug sysrq_always_enabled
> > rcupdate.rcu_cpu_stall_timeout=100 panic=-1 softlockup_panic=1
> > nmi_watchdog=panic oops=panic load_ramdisk=2 prompt_ramdisk=0
> > systemd.log_level=err ignore_loglevel earlyprintk=ttyS0,115200
> > console=ttyS0,115200 console=tty0 vga=normal rw drbd.minor_count=8'
> > -initrd /fs/sdh1/initrd-vm-kbuild-yocto-ia32-29 -m 832 -smp 1 -device
> > e1000,netdev=net0 -netdev user,id=net0 -boot order=nc -no-reboot -watchdog
> > i6300esb -watchdog-action debug -rtc base=localtime -drive
> > file=/fs/sdh1/disk0-vm-kbuild-yocto-ia32-29,media=disk,if=virtio -pidfile
> > /dev/shm/kboot/pid-vm-kbuild-yocto-ia32-29 -serial
> > file:/dev/shm/kboot/serial-vm-kbuild-yocto-ia32-29 -daemonize -display none
> > -monitor null
> >
> >
> >
> >
> >
> > Thanks,
> > Xiaolong
>
>
>
> --
> Andy Lutomirski
> AMA Capital Management, LLC
--
Josh
