Re: [PATCH] x86/ftrace: Make sure that ftrace trampolines are not RWX

[Luis R. Rodriguez]

On Wed, May 24, 2017 at 01:47:28PM -0400, Steven Rostedt wrote:
> OK, it crashed on one of my tests. I removed the patch and it boots
> fine, and crashes when I add it back.
> 
> Here's the crash:
> 
> Running tests on all trace events:
> Testing all events: OK
> Testing ftrace filter: OK
> trace_kprobe: Testing kprobe tracing: 
> BUG: unable to handle kernel paging request at ffff880214f5c000
> IP: new_slab+0x1e8/0x2b4
> PGD 338c067 
> P4D 338c067 
> PUD 338f067 
> PMD 212022063 
> PTE 8000000214f5c161

The good news is that this also fixes the other issue I reported with
CONFIG_KPROBES_SANITY_TEST=y and the same WARN complaint without a crash [0].
Please note that the issue I reported actually is present since the
infrastructure to report on these warnings was added through commit
e1a58320a38dfa72be48a0f1a3a92273663ba6db ("x86/mm: Warn on W^X mappings")
which was added through kernel 4.3.0-rc3.

Thomas's patch says: "Fixes: f3bea49115b2 ("ftrace/x86: Add dynamic allocated
trampoline for ftrace_ops"), and this was added through kernel v3.19-rc1 so it
may well be the same issue given the traces on my issue also reflect a
module_alloc() trace after arch_ftrace_update_trampoline() which matches what
Thomas also saw when inspecting his buggy page with kmemleak echo dump [1].

[0] https://lkml.kernel.org/r/20170524175508.GZ8951@xxxxxxxxxxxxx
[1] https://lkml.kernel.org/r/alpine.DEB.2.20.1705232243520.2409@nanos

BUT I'm also able to reprorduce a crash too though easily, as follows where
as before this commit it was passing all 45 tests just fine:

mcgrof@piggy ~/linux-next (git::next-20170519)$ sudo tools/testing/selftests/ftrace/ftracetest
=== Ftrace unit tests ===                                                       
[1] Basic trace file check      [PASS]                                          
[2] Basic test for tracers      [PASS]                                          
[3] Basic trace clock test      [PASS]                                          
[4] Basic event tracing check   [PASS]                                          
[5] event tracing - enable/disable with event level files       [PASS]          
[6] event tracing - restricts events based on pid       [PASS]                  
[7] event tracing - enable/disable with subsystem level files   [PASS]          
[8] event tracing - enable/disable with top level files [PASS]                  
[9] ftrace - function graph filters with stack tracer   [PASS]                  
[10] ftrace - function graph filters    [PASS]                                  
[11] ftrace - test for function event triggers 

<it hangs there>

I managed to get the kernel log:

[  429.416279] in mmio_trace_init
[  429.504315] mmiotrace: Disabling non-boot CPUs...
[  429.545572] Unregister pv shared memory for cpu 1
[  429.551725] smpboot: CPU 1 is now offline
[  429.553044] mmiotrace: CPU1 is down.
[  429.572874] Unregister pv shared memory for cpu 2
[  429.576361] smpboot: CPU 2 is now offline
[  429.578355] mmiotrace: CPU2 is down.
[  429.596755] Unregister pv shared memory for cpu 3
[  429.601946] smpboot: CPU 3 is now offline
[  429.602768] mmiotrace: CPU3 is down.
[  429.603418] mmiotrace: enabled.
[  429.605001] in mmio_trace_reset
[  429.605003] mmiotrace: Re-enabling CPUs...
[  429.605933] x86: Booting SMP configuration:
[  429.606505] smpboot: Booting Node 0 Processor 1 APIC 0x1
[  429.617989] kvm-clock: cpu 1, msr 1:3fff0041, secondary cpu clock
[  429.640600] KVM setup async PF for cpu 1
[  429.640603] kvm-stealtime: cpu 1, msr 13fc8da40
[  429.642384] mmiotrace: enabled CPU1.
[  429.643391] smpboot: Booting Node 0 Processor 2 APIC 0x2
[  429.654788] kvm-clock: cpu 2, msr 1:3fff0081, secondary cpu clock
[  429.675512] KVM setup async PF for cpu 2
[  429.675921] kvm-stealtime: cpu 2, msr 13fd0da40
[  429.676895] mmiotrace: enabled CPU2.
[  429.678531] smpboot: Booting Node 0 Processor 3 APIC 0x3
[  429.689999] kvm-clock: cpu 3, msr 1:3fff00c1, secondary cpu clock
[  429.710808] KVM setup async PF for cpu 3
[  429.711183] kvm-stealtime: cpu 3, msr 13fd8da40
[  429.712123] mmiotrace: enabled CPU3.
[  429.728330] mmiotrace: disabled.
[  440.537183] BUG: unable to handle kernel paging request at ffff964cf9376000
[  440.538899] IP: tlb_next_batch.isra.54+0x41/0x70
[  440.540022] PGD b736f067 
[  440.540024] P4D b736f067 
[  440.540707] PUD b7373067 
[  440.541318] PMD 12ff82063 
[  440.541953] PTE 8000000139376161

[  440.543555] Oops: 0003 [#1] SMP
[  440.543966] Modules linked in: ppdev(E) joydev(E) evdev(E) serio_raw(E) pcspkr(E) bochs_drm(E) drm_kms_helper(E) ttm(E) drm(E) i2c_piix4(E) sg(E) parport_pc(E) parport(E) acpi_cpufreq(E) button(E) sch_fq_codel(E) autofs4(E) crc32c_generic(E) ext4(E) crc16(E) jbd2(E) mbcache(E) sr_mod(E) cdrom(E) sd_mod(E) ata_generic(E) psmouse(E) floppy(E) ata_piix(E) e1000(E) libata(E) scsi_mod(E)
[  440.548057] CPU: 2 PID: 1765 Comm: ftracetest Tainted: G            E   4.12.0-rc1-next-20170519+ #155
[  440.549159] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.10.2-0-g5f4c7b1-prebuilt.qemu-project.org 04/01/2014
[  440.550329] task: ffff964cf14e2600 task.stack: ffffbe7c80b58000
[  440.550921] RIP: 0010:tlb_next_batch.isra.54+0x41/0x70
[  440.551385] RSP: 0018:ffffbe7c80b5bc40 EFLAGS: 00010202
[  440.551855] RAX: ffff964cf9376000 RBX: ffffbe7c80b5bdf0 RCX: 000000000001dd18
[  440.552493] RDX: 0000000000000000 RSI: 0000000000000011 RDI: 0000000000000246
[  440.553134] RBP: ffffbe7c80b5bc50 R08: ffff964cf0b6d958 R09: 0000000000000000
[  440.553750] R10: 0000000000000000 R11: 0000000000000000 R12: ffffbe7c80b5be48
[  440.554386] R13: ffffbe7c80b5bdd0 R14: 00005560d7a30000 R15: ffff964cf035c178
[  440.555025] FS:  0000000000000000(0000) GS:ffff964cffd00000(0000) knlGS:0000000000000000
[  440.555743] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  440.556255] CR2: ffff964cf9376000 CR3: 0000000139688000 CR4: 00000000000006e0
[  440.556895] Call Trace:
[  440.557107]  unmap_page_range+0x722/0x930
[  440.557443]  ? cpumask_any_but+0x24/0x40
[  440.557773]  unmap_single_vma+0x59/0xe0
[  440.558088]  ? lru_deactivate_file_fn+0x360/0x360
[  440.558485]  unmap_vmas+0x51/0xa0
[  440.558769]  exit_mmap+0xa7/0x170
[  440.559054]  mmput+0x53/0x140
[  440.559309]  do_exit+0x286/0xb30
[  440.559582]  ? __do_page_fault+0x266/0x4e0
[  440.559928]  do_group_exit+0x43/0xb0
[  440.560230]  SyS_exit_group+0x14/0x20
[  440.560539]  entry_SYSCALL_64_fastpath+0x1e/0xa9
[  440.560963] RIP: 0033:0x7f9533db24d8
[  440.561287] RSP: 002b:00007ffda4899cf8 EFLAGS: 00000246 ORIG_RAX: 00000000000000e7
[  440.561963] RAX: ffffffffffffffda RBX: 00005560d821c110 RCX: 00007f9533db24d8
[  440.562601] RDX: 0000000000000000 RSI: 000000000000003c RDI: 0000000000000000
[  440.563253] RBP: 00007f9534092b00 R08: 00000000000000e7 R09: ffffffffffffff98
[  440.563863] R10: 00005560d82208a0 R11: 0000000000000246 R12: 0000000000000000
[  440.564437] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
[  440.565023] Code: 00 00 c3 83 3e 13 74 4f 55 48 89 e5 41 54 53 49 89 f4 48 89 fb 31 f6 bf 00 02 00 01 e8 d9 f0 fc ff 48 85 c0 74 2d 41 83 04 24 01 <48> c7 00 00 00 00 00 c7 40 08 00 00 00 00 c7 40 0c fe 01 00 00 
[  440.566681] RIP: tlb_next_batch.isra.54+0x41/0x70 RSP: ffffbe7c80b5bc40
[  440.567283] CR2: ffff964cf9376000
[  440.567592] ---[ end trace 382f2593927e722f ]---
[  440.567991] Fixing recursive fault but reboot is needed!

  Luis