linux/kernel/trace
Steven Rostedt (Google) 4313e5a613 tracing: Free buffers when a used dynamic event is removed
After 65536 dynamic events have been added and removed, the "type" field
of the event then uses the first type number that is available (not
currently used by other events). A type number is the identifier of the
binary blobs in the tracing ring buffer (known as events) to map them to
logic that can parse the binary blob.

The issue is that if a dynamic event (like a kprobe event) is traced and
is in the ring buffer, and then that event is removed (because it is
dynamic, which means it can be created and destroyed), if another dynamic
event is created that has the same number that new event's logic on
parsing the binary blob will be used.

To show how this can be an issue, the following can crash the kernel:

 # cd /sys/kernel/tracing
 # for i in `seq 65536`; do
     echo 'p:kprobes/foo do_sys_openat2 $arg1:u32' > kprobe_events
 # done

For every iteration of the above, the writing to the kprobe_events will
remove the old event and create a new one (with the same format) and
increase the type number to the next available on until the type number
reaches over 65535 which is the max number for the 16 bit type. After it
reaches that number, the logic to allocate a new number simply looks for
the next available number. When an dynamic event is removed, that number
is then available to be reused by the next dynamic event created. That is,
once the above reaches the max number, the number assigned to the event in
that loop will remain the same.

Now that means deleting one dynamic event and created another will reuse
the previous events type number. This is where bad things can happen.
After the above loop finishes, the kprobes/foo event which reads the
do_sys_openat2 function call's first parameter as an integer.

 # echo 1 > kprobes/foo/enable
 # cat /etc/passwd > /dev/null
 # cat trace
             cat-2211    [005] ....  2007.849603: foo: (do_sys_openat2+0x0/0x130) arg1=4294967196
             cat-2211    [005] ....  2007.849620: foo: (do_sys_openat2+0x0/0x130) arg1=4294967196
             cat-2211    [005] ....  2007.849838: foo: (do_sys_openat2+0x0/0x130) arg1=4294967196
             cat-2211    [005] ....  2007.849880: foo: (do_sys_openat2+0x0/0x130) arg1=4294967196
 # echo 0 > kprobes/foo/enable

Now if we delete the kprobe and create a new one that reads a string:

 # echo 'p:kprobes/foo do_sys_openat2 +0($arg2):string' > kprobe_events

And now we can the trace:

 # cat trace
        sendmail-1942    [002] .....   530.136320: foo: (do_sys_openat2+0x0/0x240) arg1=             cat-2046    [004] .....   530.930817: foo: (do_sys_openat2+0x0/0x240) arg1="������������������������������������������������������������������������������������������������"
             cat-2046    [004] .....   530.930961: foo: (do_sys_openat2+0x0/0x240) arg1="������������������������������������������������������������������������������������������������"
             cat-2046    [004] .....   530.934278: foo: (do_sys_openat2+0x0/0x240) arg1="������������������������������������������������������������������������������������������������"
             cat-2046    [004] .....   530.934563: foo: (do_sys_openat2+0x0/0x240) arg1="������������������������������������������������������������������������������������������������"
            bash-1515    [007] .....   534.299093: foo: (do_sys_openat2+0x0/0x240) arg1="kkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkk���������@��4Z����;Y�����U

And dmesg has:

==================================================================
BUG: KASAN: use-after-free in string+0xd4/0x1c0
Read of size 1 at addr ffff88805fdbbfa0 by task cat/2049

 CPU: 0 PID: 2049 Comm: cat Not tainted 6.1.0-rc6-test+ #641
 Hardware name: Hewlett-Packard HP Compaq Pro 6300 SFF/339A, BIOS K01 v03.03 07/14/2016
 Call Trace:
  <TASK>
  dump_stack_lvl+0x5b/0x77
  print_report+0x17f/0x47b
  kasan_report+0xad/0x130
  string+0xd4/0x1c0
  vsnprintf+0x500/0x840
  seq_buf_vprintf+0x62/0xc0
  trace_seq_printf+0x10e/0x1e0
  print_type_string+0x90/0xa0
  print_kprobe_event+0x16b/0x290
  print_trace_line+0x451/0x8e0
  s_show+0x72/0x1f0
  seq_read_iter+0x58e/0x750
  seq_read+0x115/0x160
  vfs_read+0x11d/0x460
  ksys_read+0xa9/0x130
  do_syscall_64+0x3a/0x90
  entry_SYSCALL_64_after_hwframe+0x63/0xcd
 RIP: 0033:0x7fc2e972ade2
 Code: c0 e9 b2 fe ff ff 50 48 8d 3d b2 3f 0a 00 e8 05 f0 01 00 0f 1f 44 00 00 f3 0f 1e fa 64 8b 04 25 18 00 00 00 85 c0 75 10 0f 05 <48> 3d 00 f0 ff ff 77 56 c3 0f 1f 44 00 00 48 83 ec 28 48 89 54 24
 RSP: 002b:00007ffc64e687c8 EFLAGS: 00000246 ORIG_RAX: 0000000000000000
 RAX: ffffffffffffffda RBX: 0000000000020000 RCX: 00007fc2e972ade2
 RDX: 0000000000020000 RSI: 00007fc2e980d000 RDI: 0000000000000003
 RBP: 00007fc2e980d000 R08: 00007fc2e980c010 R09: 0000000000000000
 R10: 0000000000000022 R11: 0000000000000246 R12: 0000000000020f00
 R13: 0000000000000003 R14: 0000000000020000 R15: 0000000000020000
  </TASK>

 The buggy address belongs to the physical page:
 page:ffffea00017f6ec0 refcount:0 mapcount:0 mapping:0000000000000000 index:0x0 pfn:0x5fdbb
 flags: 0xfffffc0000000(node=0|zone=1|lastcpupid=0x1fffff)
 raw: 000fffffc0000000 0000000000000000 ffffea00017f6ec8 0000000000000000
 raw: 0000000000000000 0000000000000000 00000000ffffffff 0000000000000000
 page dumped because: kasan: bad access detected

 Memory state around the buggy address:
  ffff88805fdbbe80: ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff
  ffff88805fdbbf00: ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff
 >ffff88805fdbbf80: ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff
                                ^
  ffff88805fdbc000: ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff
  ffff88805fdbc080: ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff
 ==================================================================

This was found when Zheng Yejian sent a patch to convert the event type
number assignment to use IDA, which gives the next available number, and
this bug showed up in the fuzz testing by Yujie Liu and the kernel test
robot. But after further analysis, I found that this behavior is the same
as when the event type numbers go past the 16bit max (and the above shows
that).

As modules have a similar issue, but is dealt with by setting a
"WAS_ENABLED" flag when a module event is enabled, and when the module is
freed, if any of its events were enabled, the ring buffer that holds that
event is also cleared, to prevent reading stale events. The same can be
done for dynamic events.

If any dynamic event that is being removed was enabled, then make sure the
buffers they were enabled in are now cleared.

Link: https://lkml.kernel.org/r/20221123171434.545706e3@gandalf.local.home
Link: https://lore.kernel.org/all/20221110020319.1259291-1-zhengyejian1@huawei.com/

Cc: stable@vger.kernel.org
Cc: Andrew Morton <akpm@linux-foundation.org>
Depends-on: e18eb8783e ("tracing: Add tracing_reset_all_online_cpus_unlocked() function")
Depends-on: 5448d44c38 ("tracing: Add unified dynamic event framework")
Depends-on: 6212dd2968 ("tracing/kprobes: Use dyn_event framework for kprobe events")
Depends-on: 065e63f951 ("tracing: Only have rmmod clear buffers that its events were active in")
Depends-on: 575380da8b ("tracing: Only clear trace buffer on module unload if event was traced")
Fixes: 77b44d1b7c ("tracing/kprobes: Rename Kprobe-tracer to kprobe-event")
Reported-by: Zheng Yejian <zhengyejian1@huawei.com>
Reported-by: Yujie Liu <yujie.liu@intel.com>
Reported-by: kernel test robot <yujie.liu@intel.com>
Acked-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>
Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
2022-11-23 19:07:12 -05:00
..
rv rv/monitor: Add __init/__exit annotations to module init/exit funcs 2022-09-26 18:10:51 -04:00
blktrace.c blktrace: remove unnessary stop block trace in 'blk_trace_shutdown' 2022-10-20 06:02:52 -07:00
bpf_trace.c bpf: Fix sample_flags for bpf_perf_event_output 2022-10-17 16:32:06 +02:00
bpf_trace.h
error_report-traces.c
fgraph.c arm64 fixes for 5.19-rc1: 2022-06-03 14:05:34 -07:00
fprobe.c tracing/fprobe: Fix to check whether fprobe is registered correctly 2022-11-04 08:50:07 +09:00
ftrace_internal.h
ftrace.c ftrace: Fix null pointer dereference in ftrace_add_mod() 2022-11-17 17:16:44 -05:00
Kconfig ftrace: Add HAVE_DYNAMIC_FTRACE_NO_PATCHABLE 2022-09-16 22:16:48 +02:00
kprobe_event_gen_test.c tracing: kprobe: Fix potential null-ptr-deref on trace_array in kprobe_event_gen_test_exit() 2022-11-18 10:15:34 +09:00
Makefile rv: Add Runtime Verification (RV) interface 2022-07-30 14:01:28 -04:00
pid_list.c tracing: Cleanup double word in comment 2022-04-26 17:58:50 -04:00
pid_list.h tracing: Create a sparse bitmask for pid filtering 2021-10-05 17:38:45 -04:00
power-traces.c
preemptirq_delay_test.c
rethook.c rethook: fix a potential memleak in rethook_alloc() 2022-11-18 10:15:34 +09:00
ring_buffer_benchmark.c
ring_buffer.c ring_buffer: Do not deactivate non-existant pages 2022-11-17 17:10:40 -05:00
rpm-traces.c
synth_event_gen_test.c tracing: Fix memory leak in test_gen_synth_cmd() and test_empty_synth_event() 2022-11-17 17:51:38 -05:00
trace_benchmark.c tracing: Add numeric delta time to the trace event benchmark 2022-09-26 13:01:09 -04:00
trace_benchmark.h tracing: Add numeric delta time to the trace event benchmark 2022-09-26 13:01:09 -04:00
trace_boot.c tracing: Initialize integer variable to prevent garbage return value 2022-05-26 21:13:00 -04:00
trace_branch.c
trace_clock.c
trace_dynevent.c tracing: Free buffers when a used dynamic event is removed 2022-11-23 19:07:12 -05:00
trace_dynevent.h tracing: Add DYNAMIC flag for dynamic events 2021-08-18 18:10:32 -04:00
trace_entries.h
trace_eprobe.c tracing/probes: Fixes for v6.1 2022-11-20 15:31:20 -08:00
trace_event_perf.c tracing/perf: Fix double put of trace event when init fails 2022-08-21 15:56:07 -04:00
trace_events_filter_test.h
trace_events_filter.c tracing/filter: Call filter predicate functions directly via a switch statement 2022-09-26 13:01:10 -04:00
trace_events_hist.c tracing: Fix race where histograms can be called before the event 2022-11-23 19:05:50 -05:00
trace_events_inject.c tracing: Support __rel_loc relative dynamic data location attribute 2021-12-06 15:37:21 -05:00
trace_events_synth.c tracing: Add tracing_reset_all_online_cpus_unlocked() function 2022-11-23 19:06:11 -05:00
trace_events_trigger.c tracing: Fix to check event_mutex is held while accessing trigger list 2022-09-06 22:26:00 -04:00
trace_events_user.c tracing/user_events: Fix memory leak in user_event_create() 2022-11-22 18:09:50 -05:00
trace_events.c tracing: Free buffers when a used dynamic event is removed 2022-11-23 19:07:12 -05:00
trace_export.c
trace_functions_graph.c tracing: in_irq() cleanup 2021-10-13 18:19:41 -04:00
trace_functions.c ftrace: disable preemption when recursion locked 2021-10-27 11:21:49 -04:00
trace_hwlat.c trace/hwlat: make use of the helper function kthread_run_on_cpu() 2022-01-15 16:30:24 +02:00
trace_irqsoff.c
trace_kdb.c
trace_kprobe_selftest.c
trace_kprobe_selftest.h
trace_kprobe.c tracing: Move duplicate code of trace_kprobe/eprobe.c into header 2022-10-12 13:50:00 -04:00
trace_mmiotrace.c
trace_nop.c
trace_osnoise.c tracing/osnoise: Fix duration type 2022-11-22 18:12:01 -05:00
trace_output.c tracing: Remove usage of list iterator after the loop body 2022-04-27 17:19:30 -04:00
trace_output.h
trace_preemptirq.c tracing: hold caller_addr to hardirq_{enable,disable}_ip 2022-09-06 22:26:00 -04:00
trace_printk.c tracing: Disable "other" permission bits in the tracefs files 2021-10-08 18:08:43 -04:00
trace_probe_kernel.h tracing: Add "(fault)" name injection to kernel probes 2022-10-12 13:50:20 -04:00
trace_probe_tmpl.h tracing/probes: Have process_fetch_insn() take a void * instead of pt_regs 2021-08-19 09:09:03 -04:00
trace_probe.c tracing/probes: Have kprobes and uprobes use $COMM too 2022-08-21 15:56:08 -04:00
trace_probe.h tracing/eprobe: Add eprobe filter support 2022-09-26 13:01:08 -04:00
trace_recursion_record.c tracing: Use trace_create_file() to simplify creation of tracefs entries 2022-05-26 21:12:52 -04:00
trace_sched_switch.c sched/tracing: Append prev_state to tp args instead 2022-05-12 00:37:11 +02:00
trace_sched_wakeup.c sched/tracing: Append prev_state to tp args instead 2022-05-12 00:37:11 +02:00
trace_selftest_dynamic.c
trace_selftest.c tracing: Reset the function filter after completing trampoline/graph selftest 2022-05-25 16:57:37 -04:00
trace_seq.c
trace_stack.c tracing: Disable "other" permission bits in the tracefs files 2021-10-08 18:08:43 -04:00
trace_stat.c tracing: Disable "other" permission bits in the tracefs files 2021-10-08 18:08:43 -04:00
trace_stat.h
trace_synth.h tracing: synth events: increase max fields count 2021-09-08 15:29:16 -04:00
trace_syscalls.c tracing: Remove unused __bad_type_size() method 2022-11-17 20:21:06 -05:00
trace_uprobe.c Tracing updates for 5.20 / 6.0 2022-08-05 09:41:12 -07:00
trace.c tracing: Add tracing_reset_all_online_cpus_unlocked() function 2022-11-23 19:06:11 -05:00
trace.h tracing: Add tracing_reset_all_online_cpus_unlocked() function 2022-11-23 19:06:11 -05:00
tracing_map.c tracing: Remove unused variable 'dups' 2022-10-03 12:20:31 -04:00
tracing_map.h