[linus:master] [tracing] bb32500fb9: BUG:KASAN:slab-use-after-free_in_tracing_open_file_tr

From: kernel test robot
Date: Mon Jan 29 2024 - 03:03:22 EST



Hello,

kernel test robot noticed "BUG:KASAN:slab-use-after-free_in_tracing_open_file_tr" on:

commit: bb32500fb9b78215e4ef6ee8b4345c5f5d7eafb4 ("tracing: Have trace_event_file have ref counters")
https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git master

[test failed on linus/master ecb1b8288dc7ccbdcb3b9df005fa1c0e0c0388a7]
[test failed on linux-next/master 01af33cc9894b4489fb68fa35c40e9fe85df63dc]

in testcase: kernel-selftests
version: kernel-selftests-x86_64-60acb023-1_20230329
with following parameters:

group: user_events



compiler: gcc-12
test machine: 36 threads 1 sockets Intel(R) Core(TM) i9-10980XE CPU @ 3.00GHz (Cascade Lake) with 32G memory

(please refer to attached dmesg/kmsg for entire log/backtrace)


we noticed this issue is random (6 out of 20 runs as below).

at the same time, we also observed there is an issue
"dmesg.BUG:KASAN:slab-use-after-free_in_event_enable_write"
always happens on parent in all 20 runs.

the parent dmesg is attached FYI.


dcc4e5728eeaeda8 bb32500fb9b78215e4ef6ee8b43
---------------- ---------------------------
fail:runs %reproduction fail:runs
| | |
20:20 -100% :20 dmesg.BUG:KASAN:slab-use-after-free_in_event_enable_write
:20 30% 6:20 dmesg.BUG:KASAN:slab-use-after-free_in_tracing_open_file_tr



If you fix the issue in a separate patch/commit (i.e. not just a new version of
the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <oliver.sang@xxxxxxxxx>
| Closes: https://lore.kernel.org/oe-lkp/202401291521.1322c280-oliver.sang@xxxxxxxxx


[ 108.154115][ T2177] BUG: KASAN: slab-use-after-free in tracing_open_file_tr (kernel/trace/trace.c:4984)
[ 108.154911][ T2177] Read of size 8 at addr ffff888273293a50 by task ftrace_test/2177
[ 108.155680][ T2177]
[ 108.156009][ T2177] CPU: 8 PID: 2177 Comm: ftrace_test Not tainted 6.6.0-rc4-00021-gbb32500fb9b7 #1
[ 108.156886][ T2177] Hardware name: Gigabyte Technology Co., Ltd. X299 UD4 Pro/X299 UD4 Pro-CF, BIOS F8a 04/27/2021
[ 108.157878][ T2177] Call Trace:
[ 108.158275][ T2177] <TASK>
[ 108.158650][ T2177] dump_stack_lvl (lib/dump_stack.c:108)
[ 108.159135][ T2177] print_address_description+0x2c/0x3a0
[ 108.159775][ T2177] ? tracing_open_file_tr (kernel/trace/trace.c:4984)
[ 108.160351][ T2177] print_report (mm/kasan/report.c:476)
[ 108.160795][ T2177] ? kasan_addr_to_slab (mm/kasan/common.c:35)
[ 108.161279][ T2177] ? tracing_open_file_tr (kernel/trace/trace.c:4984)
[ 108.161798][ T2177] kasan_report (mm/kasan/report.c:590)
[ 108.162246][ T2177] ? tracing_open_file_tr (kernel/trace/trace.c:4984)
[ 108.162768][ T2177] tracing_open_file_tr (kernel/trace/trace.c:4984)
[ 108.163277][ T2177] do_dentry_open (fs/open.c:929)
[ 108.163750][ T2177] ? tracing_is_disabled (kernel/trace/trace.c:4973)
[ 108.164257][ T2177] ? may_open (fs/namei.c:3268)
[ 108.164686][ T2177] do_open (fs/namei.c:3639)
[ 108.165105][ T2177] path_openat (fs/namei.c:3797)
[ 108.165549][ T2177] ? path_lookupat (fs/namei.c:3778)
[ 108.166018][ T2177] ? __lock_acquire (kernel/locking/lockdep.c:5136)
[ 108.166513][ T2177] do_filp_open (fs/namei.c:3823)
[ 108.166974][ T2177] ? may_open_dev (fs/namei.c:3817)
[ 108.167425][ T2177] ? _raw_spin_unlock (arch/x86/include/asm/preempt.h:95 include/linux/spinlock_api_smp.h:143 kernel/locking/spinlock.c:186)
[ 108.167910][ T2177] ? alloc_fd (fs/file.c:555 (discriminator 10))
[ 108.168361][ T2177] do_sys_openat2 (fs/open.c:1422)
[ 108.168838][ T2177] ? build_open_flags (fs/open.c:1408)
[ 108.169333][ T2177] __x64_sys_openat (fs/open.c:1448)
[ 108.169824][ T2177] ? __x64_sys_open (fs/open.c:1448)
[ 108.170304][ T2177] ? lockdep_hardirqs_on_prepare (kernel/locking/lockdep.c:4565)
[ 108.170935][ T2177] ? syscall_enter_from_user_mode (arch/x86/include/asm/irqflags.h:42 arch/x86/include/asm/irqflags.h:77 kernel/entry/common.c:111)
[ 108.171545][ T2177] do_syscall_64 (arch/x86/entry/common.c:50 arch/x86/entry/common.c:80)
[ 108.172051][ T2177] entry_SYSCALL_64_after_hwframe (arch/x86/entry/entry_64.S:120)
[ 108.172672][ T2177] RIP: 0033:0x7f955d2e6e51
[ 108.173166][ T2177] Code: 75 57 89 f0 25 00 00 41 00 3d 00 00 41 00 74 49 80 3d 9a 27 0e 00 00 74 6d 89 da 48 89 ee bf 9c ff ff ff b8 01 01 00 00 0f 05 <48> 3d 00 f0 ff ff 0f 87 93 00 00 00 48 8b 54 24 28 64 48 2b 14 25
All code
========
0: 75 57 jne 0x59
2: 89 f0 mov %esi,%eax
4: 25 00 00 41 00 and $0x410000,%eax
9: 3d 00 00 41 00 cmp $0x410000,%eax
e: 74 49 je 0x59
10: 80 3d 9a 27 0e 00 00 cmpb $0x0,0xe279a(%rip) # 0xe27b1
17: 74 6d je 0x86
19: 89 da mov %ebx,%edx
1b: 48 89 ee mov %rbp,%rsi
1e: bf 9c ff ff ff mov $0xffffff9c,%edi
23: b8 01 01 00 00 mov $0x101,%eax
28: 0f 05 syscall
2a:* 48 3d 00 f0 ff ff cmp $0xfffffffffffff000,%rax <-- trapping instruction
30: 0f 87 93 00 00 00 ja 0xc9
36: 48 8b 54 24 28 mov 0x28(%rsp),%rdx
3b: 64 fs
3c: 48 rex.W
3d: 2b .byte 0x2b
3e: 14 25 adc $0x25,%al

Code starting with the faulting instruction
===========================================
0: 48 3d 00 f0 ff ff cmp $0xfffffffffffff000,%rax
6: 0f 87 93 00 00 00 ja 0x9f
c: 48 8b 54 24 28 mov 0x28(%rsp),%rdx
11: 64 fs
12: 48 rex.W
13: 2b .byte 0x2b
14: 14 25 adc $0x25,%al
[ 108.174927][ T2177] RSP: 002b:00007ffd1c637260 EFLAGS: 00000202 ORIG_RAX: 0000000000000101
[ 108.175759][ T2177] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f955d2e6e51
[ 108.176539][ T2177] RDX: 0000000000000000 RSI: 000055b82b59e6e8 RDI: 00000000ffffff9c
[ 108.177333][ T2177] RBP: 000055b82b59e6e8 R08: 0000000000000007 R09: 000055b82cfcc2b0
[ 108.178119][ T2177] R10: 0000000000000000 R11: 0000000000000202 R12: 0000000000000000
[ 108.178896][ T2177] R13: 00007ffd1c637898 R14: 000055b82b5a0dc8 R15: 00007f955d4f0020
[ 108.179680][ T2177] </TASK>
[ 108.180055][ T2177]
[ 108.180383][ T2177] Allocated by task 2177:
[ 108.180856][ T2177] kasan_save_stack (mm/kasan/common.c:46)
[ 108.181356][ T2177] kasan_set_track (mm/kasan/common.c:52)
[ 108.181825][ T2177] __kasan_slab_alloc (mm/kasan/common.c:328)
[ 108.182340][ T2177] kmem_cache_alloc (mm/slab.h:762 mm/slub.c:3478 mm/slub.c:3486 mm/slub.c:3493 mm/slub.c:3502)
[ 108.182884][ T2177] trace_create_new_event (kernel/trace/trace_events.c:2908)
[ 108.183438][ T2177] trace_add_event_call (kernel/trace/trace_events.c:2974 kernel/trace/trace_events.c:3728 kernel/trace/trace_events.c:3040)
[ 108.183950][ T2177] user_event_set_call_visible (kernel/trace/trace_events_user.c:1455)
[ 108.184500][ T2177] user_event_parse (kernel/trace/trace_events_user.c:1908 kernel/trace/trace_events_user.c:2020)
[ 108.184977][ T2177] user_events_ioctl_reg (kernel/trace/trace_events_user.c:2332)
[ 108.185496][ T2177] user_events_ioctl (kernel/trace/trace_events_user.c:2528)
[ 108.185987][ T2177] __x64_sys_ioctl (fs/ioctl.c:52 fs/ioctl.c:871 fs/ioctl.c:857 fs/ioctl.c:857)
[ 108.186464][ T2177] do_syscall_64 (arch/x86/entry/common.c:50 arch/x86/entry/common.c:80)
[ 108.186912][ T2177] entry_SYSCALL_64_after_hwframe (arch/x86/entry/entry_64.S:120)
[ 108.187484][ T2177]
[ 108.187761][ T2177] Freed by task 400:
[ 108.188166][ T2177] kasan_save_stack (mm/kasan/common.c:46)
[ 108.188628][ T2177] kasan_set_track (mm/kasan/common.c:52)
[ 108.189089][ T2177] kasan_save_free_info (mm/kasan/generic.c:524)
[ 108.189582][ T2177] __kasan_slab_free (mm/kasan/common.c:238 mm/kasan/common.c:200 mm/kasan/common.c:244)
[ 108.190078][ T2177] slab_free_freelist_hook (mm/slub.c:1826)
[ 108.190614][ T2177] kmem_cache_free (mm/slub.c:3809 mm/slub.c:3831)
[ 108.191092][ T2177] event_remove (kernel/trace/trace_events.c:2609 kernel/trace/trace_events.c:2648)
[ 108.191551][ T2177] trace_remove_event_call (kernel/trace/trace_events.c:3054 kernel/trace/trace_events.c:3090 kernel/trace/trace_events.c:3110)
[ 108.192083][ T2177] user_event_set_call_visible (kernel/trace/trace_events_user.c:1457)
[ 108.192624][ T2177] destroy_user_event (kernel/trace/trace_events_user.c:1474 (discriminator 9))
[ 108.193116][ T2177] delayed_destroy_user_event (kernel/trace/trace_events_user.c:239)
[ 108.193655][ T2177] process_one_work (kernel/workqueue.c:2635)
[ 108.194151][ T2177] worker_thread (kernel/workqueue.c:2697 kernel/workqueue.c:2784)
[ 108.194673][ T2177] kthread (kernel/kthread.c:388)
[ 108.195136][ T2177] ret_from_fork (arch/x86/kernel/process.c:153)
[ 108.195641][ T2177] ret_from_fork_asm (arch/x86/entry/entry_64.S:312)
[ 108.196148][ T2177]
[ 108.196483][ T2177] The buggy address belongs to the object at ffff888273293a08
[ 108.196483][ T2177] which belongs to the cache trace_event_file of size 96
[ 108.197819][ T2177] The buggy address is located 72 bytes inside of
[ 108.197819][ T2177] freed 96-byte region [ffff888273293a08, ffff888273293a68)
[ 108.199072][ T2177]
[ 108.199388][ T2177] The buggy address belongs to the physical page:
[ 108.200028][ T2177] page:ffffea0009cca480 refcount:1 mapcount:0 mapping:0000000000000000 index:0xffff888273293e18 pfn:0x273292
[ 108.201100][ T2177] head:ffffea0009cca480 order:1 entire_mapcount:0 nr_pages_mapped:0 pincount:0
[ 108.201955][ T2177] flags: 0x17ffffc0000840(slab|head|node=0|zone=2|lastcpupid=0x1fffff)
[ 108.202751][ T2177] page_type: 0xffffffff()
[ 108.203248][ T2177] raw: 0017ffffc0000840 ffff888100053140 ffff8881000550c8 ffff8881000550c8
[ 108.204085][ T2177] raw: ffff888273293e18 0000000000270021 00000001ffffffff 0000000000000000
[ 108.204926][ T2177] page dumped because: kasan: bad access detected
[ 108.205549][ T2177]
[ 108.205869][ T2177] Memory state around the buggy address:
[ 108.206475][ T2177] ffff888273293900: fc fc fc fc fc fc fc 00 00 00 00 00 00 00 00 00
[ 108.207228][ T2177] ffff888273293980: 00 00 00 fc fc fc fc fc fc fc fc fc fc fc fc fc
[ 108.207978][ T2177] >ffff888273293a00: fc fa fb fb fb fb fb fb fb fb fb fb fb fc fc fc
[ 108.208725][ T2177] ^
[ 108.209362][ T2177] ffff888273293a80: fc fc fc fc fc fc fc fc fc fc fc fa fb fb fb fb
[ 108.210109][ T2177] ffff888273293b00: fb fb fb fb fb fb fb fc fc fc fc fc fc fc fc fc
[ 108.210854][ T2177] ==================================================================
[ 108.211632][ T2177] Disabling lock debugging due to kernel taint


The kernel config and materials to reproduce are available at:
https://download.01.org/0day-ci/archive/20240129/202401291521.1322c280-oliver.sang@xxxxxxxxx



--
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki

Attachment: dmesg-parent.xz
Description: application/xz