• Steven Rostedt (Google)'s avatar
    tracing: Free buffers when a used dynamic event is removed · 4313e5a6
    Steven Rostedt (Google) authored
    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: e18eb878 ("tracing: Add tracing_reset_all_online_cpus_unlocked() function")
    Depends-on: 5448d44c ("tracing: Add unified dynamic event framework")
    Depends-on: 6212dd29 ("tracing/kprobes: Use dyn_event framework for kprobe events")
    Depends-on: 065e63f9 ("tracing: Only have rmmod clear buffers that its events were active in")
    Depends-on: 575380da ("tracing: Only clear trace buffer on module unload if event was traced")
    Fixes: 77b44d1b ("tracing/kprobes: Rename Kprobe-tracer to kprobe-event")
    Reported-by: default avatarZheng Yejian <zhengyejian1@huawei.com>
    Reported-by: default avatarYujie Liu <yujie.liu@intel.com>
    Reported-by: default avatarkernel test robot <yujie.liu@intel.com>
    Acked-by: default avatarMasami Hiramatsu (Google) <mhiramat@kernel.org>
    Signed-off-by: default avatarSteven Rostedt (Google) <rostedt@goodmis.org>
    4313e5a6
trace_events.c 94.5 KB