tracing: user events UAF crash report

Hi Steven, Ajay,

[ @Cc list: I found out issues with tracefs have been reported /
  attempted to get fixed in the past, so you may be interested. ]

I noticed, the user events ftrace selftest is crashing every now and
then in our automated tests. Digging into, I found that the following
is triggering the issue very reliable:

- in one shell, as root:
  # while true; do ./kselftest/user_events/ftrace_test; done

- in a second shell, again as root:
  # cd /sys/kernel/tracing
  # while true; do cat events/user_events/__test_event/format; done 2>/dev/null

Ignoring that the selftest fails for half of its tests -- which is a
regression and therefore yet another bug, I guess -- this triggers an
access fault (GFP/PF/NULL deref) after a few iterations, usually within
a minute, mostly mere seconds. With KASAN enabled it generates a splat
almost instantly, like following:

[   23.790955] ==================================================================
[   23.791692] BUG: KASAN: slab-use-after-free in f_show+0x43b/0x470
[   23.792244] Read of size 8 at addr ffff888007076878 by task cat/755
[   23.792753]
[   23.792947] CPU: 1 PID: 755 Comm: cat Tainted: G      D          N 6.10.0-vanilla-dirty #30
[   23.793563] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.16.3-0-ga6ed6b701f0a-prebuilt.qemu.org 04/01/2014
[   23.794280] Call Trace:
[   23.794470]  <TASK>
[   23.794642]  dump_stack_lvl+0x66/0xa0
[   23.794909]  print_report+0xd0/0x630
[   23.795180]  ? f_show+0x43b/0x470
[   23.795415]  ? __virt_addr_valid+0x208/0x3f0
[   23.795700]  ? f_show+0x43b/0x470
[   23.795935]  kasan_report+0xd8/0x110
[   23.796183]  ? f_show+0x43b/0x470
[   23.796418]  f_show+0x43b/0x470
[   23.796645]  seq_read_iter+0x418/0x11e0
[   23.796907]  ? __page_table_check_ptes_set+0x166/0x1a0
[   23.797280]  seq_read+0x261/0x350
[   23.797537]  ? lock_release+0x453/0x600
[   23.797819]  ? __pfx_seq_read+0x10/0x10
[   23.798103]  ? set_ptes.isra.0+0x11b/0x150
[   23.798402]  vfs_read+0x171/0x9e0
[   23.798657]  ? lock_acquire+0x408/0x4b0
[   23.798970]  ? __pfx_vfs_read+0x10/0x10
[   23.799267]  ? lock_release+0x453/0x600
[   23.799549]  ? do_user_addr_fault+0x45b/0x8b0
[   23.799862]  ? __pfx_lock_release+0x10/0x10
[   23.800162]  ? __pfx___up_read+0x10/0x10
[   23.800448]  ksys_read+0xdd/0x1a0
[   23.800704]  ? __pfx_ksys_read+0x10/0x10
[   23.801007]  ? do_user_addr_fault+0x465/0x8b0
[   23.801341]  do_syscall_64+0x66/0x130
[   23.801615]  entry_SYSCALL_64_after_hwframe+0x71/0x79
[   23.801959] RIP: 0033:0x7f1fdb9df40e
[   23.802230] Code: c0 e9 b6 fe ff ff 50 48 8d 3d 2e 08 0b 00 e8 69 01 02 00 66 0f 1f 84 00 00 00 00 00 64 8b 04 25 18 00 00 00 85 c0 75 14 0f 05 <48> 3d 00 f0 ff ff 77 5a c3 66 0f 1f 84 00 00 00 00 00 48 83 ec 28
[   23.803352] RSP: 002b:00007fff86d62658 EFLAGS: 00000246 ORIG_RAX: 0000000000000000
[   23.803848] RAX: ffffffffffffffda RBX: 0000000000020000 RCX: 00007f1fdb9df40e
[   23.804302] RDX: 0000000000020000 RSI: 00007f1fdb8d3000 RDI: 0000000000000003
[   23.804753] RBP: 00007f1fdb8d3000 R08: 00007f1fdb8d2010 R09: 0000000000000000
[   23.805239] R10: fffffffffffffbc5 R11: 0000000000000246 R12: 0000000000000000
[   23.805694] R13: 0000000000000003 R14: 0000000000020000 R15: 0000000000020000
[   23.806153]  </TASK>
[   23.806352]
[   23.806518] Allocated by task 753:
[   23.806781]  kasan_save_stack+0x20/0x40
[   23.807094]  kasan_save_track+0x14/0x30
[   23.807377]  __kasan_kmalloc+0x8f/0xa0
[   23.807656]  user_event_parse_cmd+0x590/0x25e0
[   23.807969]  user_events_ioctl+0xa52/0x17f0
[   23.808267]  __x64_sys_ioctl+0x133/0x190
[   23.808555]  do_syscall_64+0x66/0x130
[   23.808830]  entry_SYSCALL_64_after_hwframe+0x71/0x79
[   23.809208]
[   23.809370] Freed by task 58:
[   23.809609]  kasan_save_stack+0x20/0x40
[   23.809890]  kasan_save_track+0x14/0x30
[   23.810173]  kasan_save_free_info+0x3b/0x60
[   23.810473]  poison_slab_object+0x10a/0x170
[   23.810771]  __kasan_slab_free+0x14/0x30
[   23.811090]  kfree+0xe0/0x2f0
[   23.811338]  destroy_user_event+0x305/0x450
[   23.811639]  delayed_destroy_user_event+0x5c/0xe0
[   23.811965]  process_one_work+0x81c/0x1970
[   23.812259]  worker_thread+0x608/0x1160
[   23.812542]  kthread+0x2be/0x3b0
[   23.812794]  ret_from_fork+0x2c/0x70
[   23.813098]  ret_from_fork_asm+0x1a/0x30
[   23.813387]
[   23.813551] Last potentially related work creation:
[   23.813885]  kasan_save_stack+0x20/0x40
[   23.814168]  __kasan_record_aux_stack+0x8e/0xa0
[   23.814489]  insert_work+0x20/0x1b0
[   23.814756]  __queue_work+0x67a/0xc60
[   23.815079]  queue_work_on+0x63/0x90
[   23.815350]  user_event_put+0x1f9/0x390
[   23.815631]  user_events_ioctl+0x11ed/0x17f0
[   23.815935]  __x64_sys_ioctl+0x133/0x190
[   23.816223]  do_syscall_64+0x66/0x130
[   23.816498]  entry_SYSCALL_64_after_hwframe+0x71/0x79
[   23.816841]
[   23.817019] The buggy address belongs to the object at ffff888007076800
[   23.817019]  which belongs to the cache kmalloc-cg-512 of size 512
[   23.817799] The buggy address is located 120 bytes inside of
[   23.817799]  freed 512-byte region [ffff888007076800, ffff888007076a00)
[   23.818530]
[   23.818694] The buggy address belongs to the physical page:
[   23.819092] page: refcount:1 mapcount:0 mapping:0000000000000000 index:0x0 pfn:0x7074
[   23.819602] head: order:2 mapcount:0 entire_mapcount:0 nr_pages_mapped:0 pincount:0
[   23.820323] memcg:ffff88800277fd01
[   23.820595] anon flags: 0x40(head|zone=0)
[   23.820885] page_type: 0xffffefff(slab)
[   23.821203] raw: 0000000000000040 ffff88800014cdc0 0000000000000000 0000000000000001
[   23.821706] raw: 0000000000000000 0000000080100010 00000001ffffefff ffff88800277fd01
[   23.822206] head: 0000000000000040 ffff88800014cdc0 0000000000000000 0000000000000001
[   23.822711] head: 0000000000000000 0000000080100010 00000001ffffefff ffff88800277fd01
[   23.823261] head: 0000000000000002 ffffea00001c1d01 ffffffffffffffff 0000000000000000
[   23.823764] head: ffff888000000004 0000000000000000 00000000ffffffff 0000000000000000
[   23.824271] page dumped because: kasan: bad access detected
[   23.824638]
[   23.824799] Memory state around the buggy address:
[   23.825162]  ffff888007076700: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc
[   23.825641]  ffff888007076780: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc
[   23.826116] >ffff888007076800: fa fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb
[   23.826588]                                                                 ^
[   23.827070]  ffff888007076880: fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb
[   23.827545]  ffff888007076900: fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb
[   23.828018] ==================================================================

I did a bisect run and ended up on commit 27152bceea1d ("eventfs: Move
tracing/events to eventfs"). This is, of cause, only the enabling
commit. The bug is likely in one of the preceeding commits introducing
eventfs infrastructure.

The git bisect log (I jumped around a little in the beginning, but yeah,
v6.10 is still broken):

git bisect start
# status: waiting for both good and bad commits
# bad: [a38297e3fb012ddfa7ce0321a7e5a8daeb1872b6] Linux 6.9
git bisect bad a38297e3fb012ddfa7ce0321a7e5a8daeb1872b6
# status: waiting for good commit(s), bad commit known
# bad: [0c3836482481200ead7b416ca80c68a29cfdaabd] Linux 6.10
git bisect bad 0c3836482481200ead7b416ca80c68a29cfdaabd
# status: waiting for good commit(s), bad commit known
# bad: [ffc253263a1375a65fa6c9f62a893e9767fbebfa] Linux 6.6
git bisect bad ffc253263a1375a65fa6c9f62a893e9767fbebfa
# status: waiting for good commit(s), bad commit known
# good: [6995e2de6891c724bfeb2db33d7b87775f913ad1] Linux 6.4
git bisect good 6995e2de6891c724bfeb2db33d7b87775f913ad1
# good: [692f5510159c79bfa312a4e27a15e266232bfb4c] Merge tag 'asoc-v6.6' of https://git.kernel.org/pub/scm/linux/kernel/git/broonie/sound into for-linus
git bisect good 692f5510159c79bfa312a4e27a15e266232bfb4c
# good: [0e72db77672ff4758a31fb5259c754a7bb229751] Merge tag 'soc-dt-6.6' of git://git.kernel.org/pub/scm/linux/kernel/git/soc/soc
git bisect good 0e72db77672ff4758a31fb5259c754a7bb229751
# bad: [5eea5820c7340d39e56e169e1b87199391105f6b] Merge tag 'mm-stable-2023-09-04-14-00' of git://git.kernel.org/pub/scm/linux/kernel/git/akpm/mm
git bisect bad 5eea5820c7340d39e56e169e1b87199391105f6b
# good: [28a4f91f5f251689c69155bc6a0b1afc9916c874] Merge tag 'driver-core-6.6-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/gregkh/driver-core
git bisect good 28a4f91f5f251689c69155bc6a0b1afc9916c874
# bad: [f7e97ce26972ae7be8bbbae8d819ff311d4c5900] Merge tag 'for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/rdma/rdma
git bisect bad f7e97ce26972ae7be8bbbae8d819ff311d4c5900
# good: [9a5d660fdb25d20748d7f9e9559c86073c3bb368] media: ivsc: Add ACPI dependency
git bisect good 9a5d660fdb25d20748d7f9e9559c86073c3bb368
# good: [704e2c6107f1a5353a1038bac137dda0df2a6dd0] Merge tag 'icc-6.6-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/djakov/icc into char-misc-next
git bisect good 704e2c6107f1a5353a1038bac137dda0df2a6dd0
# good: [bd30fe6a7d9b72e73c5ac9109cbc3066dde08034] Merge tag 'wq-for-6.6' of git://git.kernel.org/pub/scm/linux/kernel/git/tj/wq
git bisect good bd30fe6a7d9b72e73c5ac9109cbc3066dde08034
# good: [d952f54d01ec2ea5ee9d5e21f2ea3a5807b4bcbc] RDMA/hns: Remove unused declaration hns_roce_modify_srq()
git bisect good d952f54d01ec2ea5ee9d5e21f2ea3a5807b4bcbc
# bad: [34232fcfe9a383bea802af682baae5c99f22376c] Merge tag 'trace-v6.6' of git://git.kernel.org/pub/scm/linux/kernel/git/trace/linux-trace
git bisect bad 34232fcfe9a383bea802af682baae5c99f22376c
# bad: [7c1130ea5cae215588e6d51242b877fd405e6c32] test: ftrace: Fix kprobe test for eventfs
git bisect bad 7c1130ea5cae215588e6d51242b877fd405e6c32
# good: [5bdcd5f5331a276a3ddf1fba8605986d0d15298a] eventfs: Implement removal of meta data from eventfs
git bisect good 5bdcd5f5331a276a3ddf1fba8605986d0d15298a
# bad: [27152bceea1df27ffebb12ac9cd9adbf2c4c3f35] eventfs: Move tracing/events to eventfs
git bisect bad 27152bceea1df27ffebb12ac9cd9adbf2c4c3f35
# first bad commit: [27152bceea1df27ffebb12ac9cd9adbf2c4c3f35] eventfs: Move tracing/events to eventfs

I stared quite hard at the inode/dentry/file handling and, imho, it's
quite broken as it leaks pointers to refcounted objects which may go
away anytime, e.g. &user->call via trace_add_event_call() in
user_event_set_call_visible(). That'll lead to a user reachable file
hierarchy below events/user_events/$eventname/ that isn't bound to the
creator's mm.

Assume one process opens events/user_events/$eventname/format, then the
walked fields -- the whole object, actually -- may go away anytime, once
the creator either removes the user probe again or closes its fd to
/sys/kernel/tracing/user_events_data, leading to user_events_release()
doing the final user_event_put() leading to object destruction. The
concurrent reader of events/user_events/$eventname/format will now
operate on a free'd object. Boom!

As mentioned, I stared quite hard at the code and tried to fix it via
numerous ways but the core issue is, imho, the lack of refcounting the
&user->call object, or even better, 'user', for the files created below
events/user_events/$eventname/. However, I found no easy way to do that.

My hopes are, you may be able to, now that there's an easy reproducer.

Beside the obvious bug, I noticed the following (not fixing the issue,
tho):

diff --git a/fs/tracefs/event_inode.c b/fs/tracefs/event_inode.c
index 5d88c184f0fc..687ad0a26458 100644
--- a/fs/tracefs/event_inode.c
+++ b/fs/tracefs/event_inode.c

@@ -112,7 +112,7 @@ static void release_ei(struct kref *ref)
 			entry->release(entry->name, ei->data);
 	}
 
-	call_rcu(&ei->rcu, free_ei_rcu);
+	call_srcu(&eventfs_srcu, &ei->rcu, free_ei_rcu);
 }
 
 static inline void put_ei(struct eventfs_inode *ei)

@@ -735,7 +735,9 @@ struct eventfs_inode *eventfs_create_dir(const char *name, struct eventfs_inode
 
 	/* Was the parent freed? */
 	if (list_empty(&ei->list)) {
+		mutex_lock(&eventfs_mutex);
 		cleanup_ei(ei);
+		mutex_unlock(&eventfs_mutex);
 		ei = NULL;
 	}
 	return ei;

The s/call_rcu/call_srcu/ one is because not only do the comments talk
about SRCU protection, the code does so as well, e.g. eventfs_iterate().

Similar argumentation for taking the mutex around cleanup_ei(). It sets
the 'is_freed' member which others expect only to be set -- or at least
to have a stable value -- when the mutex is hold. As 'ei' was exposed to
its parent before, it may have escaped to other users, e.g. via
eventfs_iterate().

I may have missed something, painting these changes completely void,
therefore spared me the time to do proper patches. However, below one is
legit ("git am --scissors ..." yada yada):

---8<---
Subject: [PATCH] eventfs: Don't return NULL in eventfs_create_dir()

Commit 77a06c33a22d ("eventfs: Test for ei->is_freed when accessing
ei->dentry") added another check, testing if the parent was freed after
we released the mutex. If so, the function returns NULL. However, all
callers expect it to either return a valid pointer or an error pointer,
at least since commit 5264a2f4bb3b ("tracing: Fix a NULL vs IS_ERR() bug
in event_subsystem_dir()"). Returning NULL will therefore fail the error
condition check in the caller.

Fix this by substituting the NULL return value with a fitting error
pointer.

Fixes: 77a06c33a22d ("eventfs: Test for ei->is_freed when accessing ei->dentry")
Cc: Dan Carpenter <redacted>
Signed-off-by: Mathias Krause <redacted>
---
 fs/tracefs/event_inode.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/fs/tracefs/event_inode.c b/fs/tracefs/event_inode.c
index 5d88c184f0fc..a9c28a1d5dc8 100644
--- a/fs/tracefs/event_inode.c
+++ b/fs/tracefs/event_inode.c

@@ -736,7 +736,7 @@ struct eventfs_inode *eventfs_create_dir(const char *name, struct eventfs_inode
 	/* Was the parent freed? */
 	if (list_empty(&ei->list)) {
 		cleanup_ei(ei);
-		ei = NULL;
+		ei = ERR_PTR(-EBUSY);
 	}
 	return ei;
 }
--->8---

Thanks,
Mathias

On Fri, Jul 19, 2024 at 10:47:01PM +0200, Mathias Krause wrote:

Reviewed-by: Dan Carpenter <redacted>

Yeah.  It's unfortunate how the timing worked where we merged
conflicting patches at basically the same time.  In an ideal would we
would have found this bug through static analysis but the callers don't
dereference "ei" so we can't tell if it's intentional or not.  This
bug seems like it would be annoying to hit but I'm not sure how if it
would lead to a crash.

Anyway, thanks for the patch.  I hope Steven is able to fix the more
complicated bug.

regards,
dan carpenter

On Sat, Jul 20, 2024 at 2:17 AM Mathias Krause [off-list ref] wrote:

Hi Steven, Ajay,

[ @Cc list: I found out issues with tracefs have been reported /
  attempted to get fixed in the past, so you may be interested. ]

I noticed, the user events ftrace selftest is crashing every now and
then in our automated tests. Digging into, I found that the following
is triggering the issue very reliable:

- in one shell, as root:
  # while true; do ./kselftest/user_events/ftrace_test; done

- in a second shell, again as root:
  # cd /sys/kernel/tracing
  # while true; do cat events/user_events/__test_event/format; done 2>/dev/null

Tried to reproduced on 6.10.0-rc7-100.ph5+, only getting repeated output as:

# while true; do cat events/user_events/__test_event/format; done 2>/dev/null
print fmt: ""
name: __test_event
ID: 2390
format:
field:unsigned short common_type; offset:0; size:2; signed:0;
field:unsigned char common_flags; offset:2; size:1; signed:0;
field:unsigned char common_preempt_count; offset:3; size:1; signed:0;
field:int common_pid; offset:4; size:4; signed:1;

# while true; do ./kselftest/user_events/ftrace_test; done
TAP version 13
1..6
# Starting 6 tests from 1 test cases.
#  RUN           user.register_events ...
#            OK  user.register_events
ok 1 user.register_events
#  RUN           user.write_events ...
#            OK  user.write_events
ok 2 user.write_events
#  RUN           user.write_empty_events ...
#            OK  user.write_empty_events
ok 3 user.write_empty_events
#  RUN           user.write_fault ...
#            OK  user.write_fault
ok 4 user.write_fault
#  RUN           user.write_validator ...
#            OK  user.write_validator
ok 5 user.write_validator
#  RUN           user.print_fmt ...
#            OK  user.print_fmt
ok 6 user.print_fmt
# PASSED: 6 / 6 tests passed.
# Totals: pass:6 fail:0 xfail:0 xpass:0 skip:0 error:0

Am I missing any step?

Must have. LGTM. Thanks.
Reviewed-by: Ajay Kaher <ajay.kaher@broadcom.com>

- Ajay

On 22.07.24 13:13, Ajay Kaher wrote:

On Sat, Jul 20, 2024 at 2:17 AM Mathias Krause [off-list ref] wrote:

quoted

I noticed, the user events ftrace selftest is crashing every now and
then in our automated tests. Digging into, I found that the following
is triggering the issue very reliable:

- in one shell, as root:
  # while true; do ./kselftest/user_events/ftrace_test; done

- in a second shell, again as root:
  # cd /sys/kernel/tracing
  # while true; do cat events/user_events/__test_event/format; done 2>/dev/null

Tried to reproduced on 6.10.0-rc7-100.ph5+, only getting repeated output as:

I don't know what that version refers to, but, in case the .config
matters, I'm attaching mine. It has KASAN enabled and works in a QEMU VM
(Debian bullseye amd64 userland, in case it matters).

# while true; do cat events/user_events/__test_event/format; done 2>/dev/null
print fmt: ""
name: __test_event
ID: 2390
format:
field:unsigned short common_type; offset:0; size:2; signed:0;
field:unsigned char common_flags; offset:2; size:1; signed:0;
field:unsigned char common_preempt_count; offset:3; size:1; signed:0;
field:int common_pid; offset:4; size:4; signed:1;

# while true; do ./kselftest/user_events/ftrace_test; done
TAP version 13
1..6
# Starting 6 tests from 1 test cases.
#  RUN           user.register_events ...
#            OK  user.register_events
ok 1 user.register_events
#  RUN           user.write_events ...
#            OK  user.write_events
ok 2 user.write_events
#  RUN           user.write_empty_events ...
#            OK  user.write_empty_events
ok 3 user.write_empty_events
#  RUN           user.write_fault ...
#            OK  user.write_fault
ok 4 user.write_fault
#  RUN           user.write_validator ...
#            OK  user.write_validator
ok 5 user.write_validator
#  RUN           user.print_fmt ...
#            OK  user.print_fmt
ok 6 user.print_fmt
# PASSED: 6 / 6 tests passed.
# Totals: pass:6 fail:0 xfail:0 xpass:0 skip:0 error:0

Am I missing any step?

Hmm, for me the output looks like this:

TAP version 13
1..6
# Starting 6 tests from 1 test cases.
#  RUN           user.register_events ...
#            OK  user.register_events
ok 1 user.register_events
#  RUN           user.write_events ...
# ftrace_test.c:348:write_events:Expected after (515) > before (515)
# write_events: Test terminated by assertion
#          FAIL  user.write_events
not ok 2 user.write_events
#  RUN           user.write_empty_events ...
# ftrace_test.c:386:write_empty_events:Expected after (515) > before (515)
# write_empty_events: Test terminated by assertion
#          FAIL  user.write_empty_events
not ok 3 user.write_empty_events
#  RUN           user.write_fault ...
#            OK  user.write_fault
ok 4 user.write_fault
#  RUN           user.write_validator ...
# ftrace_test.c:468:write_validator:Expected after (515) > before (515)
# write_validator: Test terminated by assertion
#          FAIL  user.write_validator
not ok 5 user.write_validator
#  RUN           user.print_fmt ...
#            OK  user.print_fmt
ok 6 user.print_fmt
# FAILED: 3 / 6 tests passed.
# Totals: pass:3 fail:3 xfail:0 xpass:0 skip:0 error:0

And that's v6.10 with only the additional patch from below applied on
top. But even without any changes, plain v6.10 with my config triggers
the bug easily.

quoted

Ignoring that the selftest fails for half of its tests -- which is a
regression and therefore yet another bug, I guess -- this triggers an
access fault (GFP/PF/NULL deref) after a few iterations, usually within
a minute, mostly mere seconds. With KASAN enabled it generates a splat
almost instantly, like following:

[   23.790955] ==================================================================
[   23.791692] BUG: KASAN: slab-use-after-free in f_show+0x43b/0x470
[...]
[   23.828018] ==================================================================

If you add "kasan_multi_shot" you should see loads of reports in the
kernel log while running both loops instead of only the first one.

Thanks,
Mathias

On Fri, 19 Jul 2024 22:47:01 +0200
Mathias Krause [off-list ref] wrote:

Subject: [PATCH] eventfs: Don't return NULL in eventfs_create_dir()

Commit 77a06c33a22d ("eventfs: Test for ei->is_freed when accessing
ei->dentry") added another check, testing if the parent was freed after
we released the mutex. If so, the function returns NULL. However, all
callers expect it to either return a valid pointer or an error pointer,
at least since commit 5264a2f4bb3b ("tracing: Fix a NULL vs IS_ERR() bug
in event_subsystem_dir()"). Returning NULL will therefore fail the error
condition check in the caller.

Fix this by substituting the NULL return value with a fitting error
pointer.

Fixes: 77a06c33a22d ("eventfs: Test for ei->is_freed when accessing ei->dentry")
Cc: Dan Carpenter <redacted>
Signed-off-by: Mathias Krause <redacted>

This will not get into the workflow without being sent as a normal patch.

Please send it and Cc those listed in MAINTAINERS (see get_maintainers.pl).

-- Steve

Commit 77a06c33a22d ("eventfs: Test for ei->is_freed when accessing
ei->dentry") added another check, testing if the parent was freed after
we released the mutex. If so, the function returns NULL. However, all
callers expect it to either return a valid pointer or an error pointer,
at least since commit 5264a2f4bb3b ("tracing: Fix a NULL vs IS_ERR() bug
in event_subsystem_dir()"). Returning NULL will therefore fail the error
condition check in the caller.

Fix this by substituting the NULL return value with a fitting error
pointer.

Fixes: 77a06c33a22d ("eventfs: Test for ei->is_freed when accessing ei->dentry")
Reviewed-by: Dan Carpenter <redacted>
Reviewed-by: Ajay Kaher <ajay.kaher@broadcom.com>
Signed-off-by: Mathias Krause <redacted>
---
v2: send as a separate patch, picking up review tags from Dan and Ajay

 fs/tracefs/event_inode.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/fs/tracefs/event_inode.c b/fs/tracefs/event_inode.c
index 5d88c184f0fc..a9c28a1d5dc8 100644
--- a/fs/tracefs/event_inode.c
+++ b/fs/tracefs/event_inode.c

@@ -736,7 +736,7 @@ struct eventfs_inode *eventfs_create_dir(const char *name, struct eventfs_inode
 	/* Was the parent freed? */
 	if (list_empty(&ei->list)) {
 		cleanup_ei(ei);
-		ei = NULL;
+		ei = ERR_PTR(-EBUSY);
 	}
 	return ei;
 }

-- 
2.43.0

On Fri, 19 Jul 2024 22:47:01 +0200
Mathias Krause [off-list ref] wrote:

This should be fixed too. Care to send a patch for this as well?

It use to need RCU but then everything was switched over to SRCU. This was
just leftover.

Why do you think this is needed? The ei is not on the list and has not been
made visible. It was just allocated but the parent it was going to be
attached to is about to be freed.

 		ei = NULL;
 	}
 	return ei;

Thanks,

-- Steve

On 23.07.24 16:43, Steven Rostedt wrote:

On Fri, 19 Jul 2024 22:47:01 +0200
Mathias Krause [off-list ref] wrote:

quoted

Beside the obvious bug, I noticed the following (not fixing the issue,
tho):

diff --git a/fs/tracefs/event_inode.c b/fs/tracefs/event_inode.c
index 5d88c184f0fc..687ad0a26458 100644
--- a/fs/tracefs/event_inode.c
+++ b/fs/tracefs/event_inode.c

@@ -112,7 +112,7 @@ static void release_ei(struct kref *ref)
 			entry->release(entry->name, ei->data);
 	}
 
-	call_rcu(&ei->rcu, free_ei_rcu);
+	call_srcu(&eventfs_srcu, &ei->rcu, free_ei_rcu);
 }

This should be fixed too. Care to send a patch for this as well?

Sure, will do.

It use to need RCU but then everything was switched over to SRCU. This was
just leftover.

SRCU usage came up with commit 63940449555e ("eventfs: Implement eventfs
lookup, read, open functions") and following, was further extended just
to get almost completely nuked by [1] earlier this year.

[1]
https://lore.kernel.org/linux-trace-kernel/20240131184918.945345370@goodmis.org/

quoted

 
 static inline void put_ei(struct eventfs_inode *ei)

@@ -735,7 +735,9 @@ struct eventfs_inode *eventfs_create_dir(const char *name, struct eventfs_inode
 
 	/* Was the parent freed? */
 	if (list_empty(&ei->list)) {
+		mutex_lock(&eventfs_mutex);
 		cleanup_ei(ei);
+		mutex_unlock(&eventfs_mutex);

Why do you think this is needed? The ei is not on the list and has not been
made visible. It was just allocated but the parent it was going to be
attached to is about to be freed.

I have no strong understanding of the code, just reading into what the
context told me the rules should be, which would be on one hand the
following comment...:

/*
 * The eventfs_inode (ei) itself is protected by SRCU. It is released from
 * its parent's list and will have is_freed set (under eventfs_mutex).
 * After the SRCU grace period is over and the last dput() is called
 * the ei is freed.
 */

...and on the other the common pattern, mostly complying to the rule of
first taking the eventfs_mutex, then checking 'is_freed' for a given ei
-- supposedly implying, it can only be set under that very same mutex.

As cleanup_ei() is just a glorified free_ei() which sets ei->is_freed to
1, I was implying the lack of taking eventfs_mutex is a bug. But looking
further for the precondition, getting 'ei' unchained again after it was
put to the parent's children list, I can find eventfs_remove_rec() which
is only ever called under eventfs_mutex and does:

    list_del(&ei->list);
    free_ei(ei);

So you're right and I wasn't paying close enough attention and got
mislead by cleanup_ei() also setting ei->is_freed. But as it should
already be 1 at that point, no bug here.

Thanks,
Mathias

To mirror the SRCU lock held in eventfs_iterate() when iterating over
eventfs inodes, use call_srcu() to free them too.

This was accidentally(?) degraded to RCU in commit 43aa6f97c2d0
("eventfs: Get rid of dentry pointers without refcounts").

Cc: Ajay Kaher <ajay.kaher@broadcom.com>
Cc: Linus Torvalds <torvalds@linux-foundation.org>
Fixes: 43aa6f97c2d0 ("eventfs: Get rid of dentry pointers without refcounts")
Signed-off-by: Mathias Krause <redacted>
---
 fs/tracefs/event_inode.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/fs/tracefs/event_inode.c b/fs/tracefs/event_inode.c
index a9c28a1d5dc8..01e99e98457d 100644
--- a/fs/tracefs/event_inode.c
+++ b/fs/tracefs/event_inode.c

@@ -112,7 +112,7 @@ static void release_ei(struct kref *ref)
 			entry->release(entry->name, ei->data);
 	}
 
-	call_rcu(&ei->rcu, free_ei_rcu);
+	call_srcu(&eventfs_srcu, &ei->rcu, free_ei_rcu);
 }
 
 static inline void put_ei(struct eventfs_inode *ei)

-- 
2.43.0

On Tue, 23 Jul 2024 23:07:53 +0200
Mathias Krause [off-list ref] wrote:

To mirror the SRCU lock held in eventfs_iterate() when iterating over
eventfs inodes, use call_srcu() to free them too.

This was accidentally(?) degraded to RCU in commit 43aa6f97c2d0
("eventfs: Get rid of dentry pointers without refcounts").

Yeah, I missed that. Linus cleaned up the code code quite a bit, but
missed the subtleties of the RCU clean ups. I should have caught that
in my review.

Thanks for sending this.

-- Steve

On Mon, Jul 22, 2024 at 5:38 PM Mathias Krause [off-list ref] wrote:

On 22.07.24 13:13, Ajay Kaher wrote:

quoted

On Sat, Jul 20, 2024 at 2:17 AM Mathias Krause [off-list ref] wrote:

quoted

I noticed, the user events ftrace selftest is crashing every now and
then in our automated tests. Digging into, I found that the following
is triggering the issue very reliable:

- in one shell, as root:
  # while true; do ./kselftest/user_events/ftrace_test; done

- in a second shell, again as root:
  # cd /sys/kernel/tracing
  # while true; do cat events/user_events/__test_event/format; done 2>/dev/null

Tried to reproduced on 6.10.0-rc7-100.ph5+, only getting repeated output as:

Mathias, thanks for reporting. I am able to reproduce the 'KASAN:
slab-use-after-free'.

Steve, let me know if anything wrong in my investigation:

[ 6264.339882] ==================================================================
[ 6264.339970] BUG: KASAN: slab-use-after-free in f_start+0x2b5/0x370

This belongs to  f_start() ->  f_next() -> trace_get_fields():

    trace_get_fields(struct trace_event_call *event_call)
    {
        if (!event_call->class->get_fields)
        return &event_call->class->fields;
        return event_call->class->get_fields(event_call);
    }

This happens while reading 'events/user_events/__test_event/format'.


Allocation:
[ 6264.347212] Allocated by task 3287:
[ 6264.348247]  kasan_save_stack+0x26/0x50
[ 6264.348256]  kasan_save_track+0x14/0x40
[ 6264.348260]  kasan_save_alloc_info+0x37/0x50
[ 6264.348265]  __kasan_kmalloc+0xb3/0xc0
[ 6264.348268]  kmalloc_trace_noprof+0x168/0x330
[ 6264.348280]  user_event_parse_cmd+0x57b/0x26c0
[ 6264.348286]  user_events_ioctl+0xa92/0x1850
[ 6264.348290]  __x64_sys_ioctl+0x138/0x1b0
[ 6264.348295]  x64_sys_call+0x9a4/0x1f20
[ 6264.348299]  do_syscall_64+0x4b/0x110

user_event_parse_cmd() -> user_event_parse() {
    .
    user = kzalloc(sizeof(*user), GFP_KERNEL_ACCOUNT);

Link: https://elixir.bootlin.com/linux/v6.10/source/kernel/trace/trace_events_user.c#L2118


Freed:
[ 6264.350333]  kfree+0xd1/0x2b0
[ 6264.350337]  destroy_user_event.part.0+0x313/0x450
[ 6264.350341]  destroy_user_event+0x129/0x1a0
[ 6264.350344]  delayed_destroy_user_event+0x62/0xd0
[ 6264.350347]  process_one_work+0x621/0xf60
[ 6264.350359]  worker_thread+0x760/0x14f0

static int destroy_user_event(struct user_event *user) {
    .
    kfree(user->call.print_fmt);
    kfree(EVENT_NAME(user));
    kfree(user);  <--

Link: https://elixir.bootlin.com/linux/v6.10/source/kernel/trace/trace_events_user.c#L1510


Race condition:

Thread A i.e. event reader able to reach the f_start() as the path is
valid. Thread A waiting
for lock. At the sametime, Thread B has acquired lock and removing
events entry followed
by free the user_event object. Later once Thread A got the lock it
tried to read address
which belongs to struct trace_event_call (struct trace_event_call is
member of struct
user_event)

    Thread A (read event)                         Thread B (remove event)

    .                                                           worker_thread()
    .
delayed_destroy_user_event() -> acquire event_mutex
    .
destroy_user_event()
    vfs_read()                                            .
    seq_read()                                           .
    f_start() -> acquire event_mutex         eventfs_remove_dir()
    . (waiting)                                             kfree(user)
    . (waiting)                                             released event_mutex
    acquired event_mutex
    f_next()
    trace_get_fields():

I think you have added the following check in f_start() to prevent
this race condition,
but somehow with eventfs still some gap to race condition.

static void *f_start(struct seq_file *m, loff_t *pos) {
    mutex_lock(&event_mutex);
    if (!event_file_data(m->private))   <--
        return ERR_PTR(-ENODEV);

-Ajay

On Mon, Jul 22, 2024 at 5:38 PM Mathias Krause [off-list ref] wrote:

On 22.07.24 13:13, Ajay Kaher wrote:

quoted

On Sat, Jul 20, 2024 at 2:17 AM Mathias Krause [off-list ref] wrote:

quoted

I noticed, the user events ftrace selftest is crashing every now and
then in our automated tests. Digging into, I found that the following
is triggering the issue very reliable:

- in one shell, as root:
  # while true; do ./kselftest/user_events/ftrace_test; done

- in a second shell, again as root:
  # cd /sys/kernel/tracing
  # while true; do cat events/user_events/__test_event/format; done 2>/dev/null

Tried to reproduced on 6.10.0-rc7-100.ph5+, only getting repeated output as:

< sending again after correcting alignments >

Mathias, thanks for reporting. I am able to reproduce the 'KASAN:
slab-use-after-free'.

Steve, let me know if anything wrong in my investigation:

[ 6264.339882] ==================================================================
[ 6264.339970] BUG: KASAN: slab-use-after-free in f_start+0x2b5/0x370

This belongs to  f_start() ->  f_next() -> trace_get_fields():

    trace_get_fields(struct trace_event_call *event_call)
    {
        if (!event_call->class->get_fields)
        return &event_call->class->fields;
        return event_call->class->get_fields(event_call);
    }

This happens while reading 'events/user_events/__test_event/format'.


Allocation:
[ 6264.347212] Allocated by task 3287:
[ 6264.348247]  kasan_save_stack+0x26/0x50
[ 6264.348256]  kasan_save_track+0x14/0x40
[ 6264.348260]  kasan_save_alloc_info+0x37/0x50
[ 6264.348265]  __kasan_kmalloc+0xb3/0xc0
[ 6264.348268]  kmalloc_trace_noprof+0x168/0x330
[ 6264.348280]  user_event_parse_cmd+0x57b/0x26c0
[ 6264.348286]  user_events_ioctl+0xa92/0x1850
[ 6264.348290]  __x64_sys_ioctl+0x138/0x1b0
[ 6264.348295]  x64_sys_call+0x9a4/0x1f20
[ 6264.348299]  do_syscall_64+0x4b/0x110

user_event_parse_cmd() -> user_event_parse() {
    .
    user = kzalloc(sizeof(*user), GFP_KERNEL_ACCOUNT);

Link: https://elixir.bootlin.com/linux/v6.10/source/kernel/trace/trace_events_user.c#L2118


Freed:
[ 6264.350333]  kfree+0xd1/0x2b0
[ 6264.350337]  destroy_user_event.part.0+0x313/0x450
[ 6264.350341]  destroy_user_event+0x129/0x1a0
[ 6264.350344]  delayed_destroy_user_event+0x62/0xd0
[ 6264.350347]  process_one_work+0x621/0xf60
[ 6264.350359]  worker_thread+0x760/0x14f0

static int destroy_user_event(struct user_event *user) {
    .
    kfree(user->call.print_fmt);
    kfree(EVENT_NAME(user));
    kfree(user);  <--

Link: https://elixir.bootlin.com/linux/v6.10/source/kernel/trace/trace_events_user.c#L1510


Race condition:

Thread A i.e. event reader able to reach the f_start() as the path is
valid. Thread A waiting for lock. At the sametime, Thread B has
acquired lock and removing events entry followed by free the
user_event object. Later once Thread A got the lock it tried to read
address which belongs to struct trace_event_call (struct
trace_event_call is member of struct user_event)

Thread A (read event)                      Thread B (remove event)

.                                                        worker_thread()
.
delayed_destroy_user_event()
.                                                               ->
acquire event_mutex
.                                                        destroy_user_event()
vfs_read()                                         .
seq_read()                                        .
f_start() -> acquire event_mutex      eventfs_remove_dir()
. (waiting)                                          kfree(user)
. (waiting)                                          -> released event_mutex
acquired event_mutex
f_next()
trace_get_fields():

I think you have added the following check in f_start() to prevent
this race condition, but somehow with eventfs still some gap to race condition.

static void *f_start(struct seq_file *m, loff_t *pos) {
    mutex_lock(&event_mutex);
    if (!event_file_data(m->private))   <--
        return ERR_PTR(-ENODEV);

-Ajay

On Thu, Jul 25, 2024 at 9:45 PM Ajay Kaher [off-list ref] wrote:

On Mon, Jul 22, 2024 at 5:38 PM Mathias Krause [off-list ref] wrote:

quoted

On 22.07.24 13:13, Ajay Kaher wrote:

quoted

On Sat, Jul 20, 2024 at 2:17 AM Mathias Krause [off-list ref] wrote:

quoted

I noticed, the user events ftrace selftest is crashing every now and
then in our automated tests. Digging into, I found that the following
is triggering the issue very reliable:

- in one shell, as root:
  # while true; do ./kselftest/user_events/ftrace_test; done

- in a second shell, again as root:
  # cd /sys/kernel/tracing
  # while true; do cat events/user_events/__test_event/format; done 2>/dev/null

Tried to reproduced on 6.10.0-rc7-100.ph5+, only getting repeated output as:

< sending again after correcting alignments >

Mathias, thanks for reporting. I am able to reproduce the 'KASAN:
slab-use-after-free'.

Steve, let me know if anything wrong in my investigation:

[ 6264.339882] ==================================================================
[ 6264.339970] BUG: KASAN: slab-use-after-free in f_start+0x2b5/0x370

This belongs to  f_start() ->  f_next() -> trace_get_fields():

    trace_get_fields(struct trace_event_call *event_call)
    {
        if (!event_call->class->get_fields)
        return &event_call->class->fields;
        return event_call->class->get_fields(event_call);
    }

This happens while reading 'events/user_events/__test_event/format'.


Allocation:
[ 6264.347212] Allocated by task 3287:
[ 6264.348247]  kasan_save_stack+0x26/0x50
[ 6264.348256]  kasan_save_track+0x14/0x40
[ 6264.348260]  kasan_save_alloc_info+0x37/0x50
[ 6264.348265]  __kasan_kmalloc+0xb3/0xc0
[ 6264.348268]  kmalloc_trace_noprof+0x168/0x330
[ 6264.348280]  user_event_parse_cmd+0x57b/0x26c0
[ 6264.348286]  user_events_ioctl+0xa92/0x1850
[ 6264.348290]  __x64_sys_ioctl+0x138/0x1b0
[ 6264.348295]  x64_sys_call+0x9a4/0x1f20
[ 6264.348299]  do_syscall_64+0x4b/0x110

user_event_parse_cmd() -> user_event_parse() {
    .
    user = kzalloc(sizeof(*user), GFP_KERNEL_ACCOUNT);

Link: https://elixir.bootlin.com/linux/v6.10/source/kernel/trace/trace_events_user.c#L2118


Freed:
[ 6264.350333]  kfree+0xd1/0x2b0
[ 6264.350337]  destroy_user_event.part.0+0x313/0x450
[ 6264.350341]  destroy_user_event+0x129/0x1a0
[ 6264.350344]  delayed_destroy_user_event+0x62/0xd0
[ 6264.350347]  process_one_work+0x621/0xf60
[ 6264.350359]  worker_thread+0x760/0x14f0

static int destroy_user_event(struct user_event *user) {
    .
    kfree(user->call.print_fmt);
    kfree(EVENT_NAME(user));
    kfree(user);  <--

Link: https://elixir.bootlin.com/linux/v6.10/source/kernel/trace/trace_events_user.c#L1510


Race condition:

Thread A i.e. event reader able to reach the f_start() as the path is
valid. Thread A waiting for lock. At the sametime, Thread B has
acquired lock and removing events entry followed by free the
user_event object. Later once Thread A got the lock it tried to read
address which belongs to struct trace_event_call (struct
trace_event_call is member of struct user_event)

Thread A (read event)                      Thread B (remove event)

.                                                        worker_thread()
.
delayed_destroy_user_event()
.                                                               ->
acquire event_mutex
.                                                        destroy_user_event()
vfs_read()                                         .
seq_read()                                        .
f_start() -> acquire event_mutex      eventfs_remove_dir()
. (waiting)                                          kfree(user)
. (waiting)                                          -> released event_mutex
acquired event_mutex
f_next()
trace_get_fields():

Thread A (read event)                      Thread B (remove event)

.                                          worker_thread()
.                                          delayed_destroy_user_event()
.                                                   -> acquire event_mutex
.                                          destroy_user_event()
vfs_read()                                 .
seq_read()                                .
f_start() -> acquire event_mutex           eventfs_remove_dir()
. (waiting)                                kfree(user)
. (waiting)                                 -> released event_mutex
acquired event_mutex
f_next()
trace_get_fields():

- Ajay

I think you have added the following check in f_start() to prevent
this race condition, but somehow with eventfs still some gap to race condition.

static void *f_start(struct seq_file *m, loff_t *pos) {
    mutex_lock(&event_mutex);
    if (!event_file_data(m->private))   <--
        return ERR_PTR(-ENODEV);

-Ajay

On Thu, 25 Jul 2024 21:45:03 +0530
Ajay Kaher [off-list ref] wrote:

On Mon, Jul 22, 2024 at 5:38 PM Mathias Krause [off-list ref] wrote:

quoted

On 22.07.24 13:13, Ajay Kaher wrote:  

quoted

On Sat, Jul 20, 2024 at 2:17 AM Mathias Krause [off-list ref] wrote:  

quoted

I noticed, the user events ftrace selftest is crashing every now and
then in our automated tests. Digging into, I found that the following
is triggering the issue very reliable:

- in one shell, as root:
  # while true; do ./kselftest/user_events/ftrace_test; done

- in a second shell, again as root:
  # cd /sys/kernel/tracing
  # while true; do cat events/user_events/__test_event/format; done 2>/dev/null
 

Tried to reproduced on 6.10.0-rc7-100.ph5+, only getting repeated output as:  

< sending again after correcting alignments >

Mathias, thanks for reporting. I am able to reproduce the 'KASAN:
slab-use-after-free'.

Steve, let me know if anything wrong in my investigation:

Hi Ajay,

Thanks for analyzing this.

[ 6264.339882] ==================================================================
[ 6264.339970] BUG: KASAN: slab-use-after-free in f_start+0x2b5/0x370

This belongs to  f_start() ->  f_next() -> trace_get_fields():

    trace_get_fields(struct trace_event_call *event_call)
    {
        if (!event_call->class->get_fields)
        return &event_call->class->fields;
        return event_call->class->get_fields(event_call);
    }

This happens while reading 'events/user_events/__test_event/format'.


Allocation:
[ 6264.347212] Allocated by task 3287:
[ 6264.348247]  kasan_save_stack+0x26/0x50
[ 6264.348256]  kasan_save_track+0x14/0x40
[ 6264.348260]  kasan_save_alloc_info+0x37/0x50
[ 6264.348265]  __kasan_kmalloc+0xb3/0xc0
[ 6264.348268]  kmalloc_trace_noprof+0x168/0x330
[ 6264.348280]  user_event_parse_cmd+0x57b/0x26c0
[ 6264.348286]  user_events_ioctl+0xa92/0x1850
[ 6264.348290]  __x64_sys_ioctl+0x138/0x1b0
[ 6264.348295]  x64_sys_call+0x9a4/0x1f20
[ 6264.348299]  do_syscall_64+0x4b/0x110

user_event_parse_cmd() -> user_event_parse() {
    .
    user = kzalloc(sizeof(*user), GFP_KERNEL_ACCOUNT);

Link: https://elixir.bootlin.com/linux/v6.10/source/kernel/trace/trace_events_user.c#L2118


Freed:
[ 6264.350333]  kfree+0xd1/0x2b0
[ 6264.350337]  destroy_user_event.part.0+0x313/0x450
[ 6264.350341]  destroy_user_event+0x129/0x1a0
[ 6264.350344]  delayed_destroy_user_event+0x62/0xd0
[ 6264.350347]  process_one_work+0x621/0xf60
[ 6264.350359]  worker_thread+0x760/0x14f0

static int destroy_user_event(struct user_event *user) {
    .
    kfree(user->call.print_fmt);
    kfree(EVENT_NAME(user));
    kfree(user);  <--

Link: https://elixir.bootlin.com/linux/v6.10/source/kernel/trace/trace_events_user.c#L1510


Race condition:

Thread A i.e. event reader able to reach the f_start() as the path is
valid. Thread A waiting for lock. At the sametime, Thread B has
acquired lock and removing events entry followed by free the
user_event object. Later once Thread A got the lock it tried to read
address which belongs to struct trace_event_call (struct
trace_event_call is member of struct user_event)

Thread A (read event)                      Thread B (remove event)

.                                                        worker_thread()
.
delayed_destroy_user_event()
.                                                               ->
acquire event_mutex
.                                                        destroy_user_event()
vfs_read()                                         .
seq_read()                                        .
f_start() -> acquire event_mutex      eventfs_remove_dir()
. (waiting)                                          kfree(user)
. (waiting)                                          -> released event_mutex
acquired event_mutex
f_next()
trace_get_fields():

What really bothers me is that refcnt logic. I'm not sure if this is an
issue, but the fact that you can inc the refcnt without holding the
event_mutex looks wrong to me. I would guess it would WARN if that refcnt
was incremented when zero, but there is a window where it gets set to 1
again. Too bad there's not a way to do a refcnt_set_if_zero() or something
to atomically set the value but warn if it's not zero. But then again, if
it did get incremented when zero, there should have been a warning then too.

But I don't think that's causing this.

Will look further.

-- Steve

I think you have added the following check in f_start() to prevent
this race condition, but somehow with eventfs still some gap to race condition.

static void *f_start(struct seq_file *m, loff_t *pos) {
    mutex_lock(&event_mutex);
    if (!event_file_data(m->private))   <--
        return ERR_PTR(-ENODEV);

-Ajay

On Thu, 25 Jul 2024 22:00:14 +0530
Ajay Kaher [off-list ref] wrote:

Thread A (read event)                      Thread B (remove event)

.                                          worker_thread()
.                                          delayed_destroy_user_event()
.                                                   -> acquire event_mutex
.                                          destroy_user_event()
vfs_read()                                 .
seq_read()                                .
f_start() -> acquire event_mutex           eventfs_remove_dir()
. (waiting)                                kfree(user)
. (waiting)                                 -> released event_mutex
acquired event_mutex
f_next()
trace_get_fields():

Hmm, I wonder if this would fix it?

-- Steve

diff --git a/kernel/trace/trace_events_user.c b/kernel/trace/trace_events_user.c
index 3a2b46847c8b..e9ed2826ff46 100644
--- a/kernel/trace/trace_events_user.c
+++ b/kernel/trace/trace_events_user.c

@@ -321,6 +321,8 @@ static void user_event_put(struct user_event *user, bool locked)
 	 */
 	refcount_set(&user->refcnt, 1);
 
+	user->call.data = NULL;
+
 	if (WARN_ON_ONCE(!schedule_work(&user->put_work))) {
 		/*
 		 * If we fail we must wait for an admin to attempt delete or

@@ -973,6 +975,11 @@ size_t copy_nofault(void *addr, size_t bytes, struct iov_iter *i)
 static struct list_head *user_event_get_fields(struct trace_event_call *call)
 {
 	struct user_event *user = (struct user_event *)call->data;
+	static LIST_HEAD(head);
+
+	/* If the user event is about to be deleted, return no fields */
+	if (!user)
+		return &head;
 
 	return &user->fields;
 }

On Thu, 25 Jul 2024 13:10:21 -0400
Steven Rostedt [off-list ref] wrote:

Hmm, it may be possible to just have:

	user->call.get_fields = NULL;

and then it will just use the call->class->fields instead and that should
be initialized to empty.

-- Steve

On 25.07.24 19:16, Steven Rostedt wrote:

On Thu, 25 Jul 2024 13:10:21 -0400
Steven Rostedt [off-list ref] wrote:

quoted

diff --git a/kernel/trace/trace_events_user.c b/kernel/trace/trace_events_user.c
index 3a2b46847c8b..e9ed2826ff46 100644
--- a/kernel/trace/trace_events_user.c
+++ b/kernel/trace/trace_events_user.c

@@ -321,6 +321,8 @@ static void user_event_put(struct user_event *user, bool locked)
 	 */
 	refcount_set(&user->refcnt, 1);
 
+	user->call.data = NULL;

Hmm, it may be possible to just have:

	user->call.get_fields = NULL;

and then it will just use the call->class->fields instead and that should
be initialized to empty.

Uhm, it's 'user' that has been free'd which makes all of the above
reading/writing already free'd memory. So no, I don't think that'll fly.

In fact, in our test environment with memory sanitation features enabled
we saw that dereferencing 'class' in trace_get_fields() trapping
(because the underlying object was free'd).

-- Steve

quoted

+
 	if (WARN_ON_ONCE(!schedule_work(&user->put_work))) {
 		/*
 		 * If we fail we must wait for an admin to attempt delete or

@@ -973,6 +975,11 @@ size_t copy_nofault(void *addr, size_t bytes, struct iov_iter *i)
 static struct list_head *user_event_get_fields(struct trace_event_call *call)
 {
 	struct user_event *user = (struct user_event *)call->data;

Dereferencing a potentially free'd object, so 'user' is now "random" data.

quoted

+	static LIST_HEAD(head);
+
+	/* If the user event is about to be deleted, return no fields */
+	if (!user)
+		return &head;
 
 	return &user->fields;
 }

Thanks,
Mathias

On Thu, 25 Jul 2024 20:12:33 +0200
Mathias Krause [off-list ref] wrote:

quoted

quoted

+
 	if (WARN_ON_ONCE(!schedule_work(&user->put_work))) {
 		/*
 		 * If we fail we must wait for an admin to attempt delete or

@@ -973,6 +975,11 @@ size_t copy_nofault(void *addr, size_t bytes, struct iov_iter *i)
 static struct list_head *user_event_get_fields(struct trace_event_call *call)
 {
 	struct user_event *user = (struct user_event *)call->data;  

Dereferencing a potentially free'd object, so 'user' is now "random" data.

This is the callback function of user->call.get_fields.

That is, we have:

	user->call.get_fields = user_event_get_fields;

And the f_start() code eventually calls trace_get_fields() that has (from a
previous email in this thread).

    trace_get_fields(struct trace_event_call *event_call)
    {
	if (!event_call->class->get_fields)
        	return &event_call->class->fields;
        return event_call->class->get_fields(event_call);
    }

Where it calls the ->class->get_fields(event_call);

that calls this function. By setting:

	user->call.get_fields = NULL;

this will never get called and no random data will be accessed.

That said, I was talking with Beau, we concluded that this shouldn't be the
responsibility of the user of event call, and should be cleaned up by the
event system.

quoted

quoted

+	static LIST_HEAD(head);
+
+	/* If the user event is about to be deleted, return no fields */
+	if (!user)
+		return &head;
 
 	return &user->fields;
 }  

Here's the proper fix:

diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index 6ef29eba90ce..3a2d2ff1625b 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c

@@ -3140,8 +3140,10 @@ EXPORT_SYMBOL_GPL(trace_add_event_call);
  */
 static void __trace_remove_event_call(struct trace_event_call *call)
 {
+	lockdep_assert_held(&event_mutex);
 	event_remove(call);
 	trace_destroy_fields(call);
+	call->get_fields = NULL;
 	free_event_filter(call->filter);
 	call->filter = NULL;
 }

Can you try it out?

-- Steve

On 25.07.24 21:05, Steven Rostedt wrote:

On Thu, 25 Jul 2024 20:12:33 +0200
Mathias Krause [off-list ref] wrote:

quoted

quoted

quoted

@@ -973,6 +975,11 @@ size_t copy_nofault(void *addr, size_t bytes, struct iov_iter *i)
 static struct list_head *user_event_get_fields(struct trace_event_call *call)
 {
 	struct user_event *user = (struct user_event *)call->data;  

Dereferencing a potentially free'd object, so 'user' is now "random" data.

This is the callback function of user->call.get_fields.

That is, we have:

	user->call.get_fields = user_event_get_fields;

And the f_start() code eventually calls trace_get_fields() that has (from a
previous email in this thread).

    trace_get_fields(struct trace_event_call *event_call)
    {
	if (!event_call->class->get_fields)
        	return &event_call->class->fields;
        return event_call->class->get_fields(event_call);
    }

Right. But the point is, that 'event_call' is really some '&user->call'.
With 'user' being free'd memory, what gives? Dereferencing 'event_call'
is UB, so this function is doomed to fail because it cannot know if its
only argument points to still valid memory or not. And that's the core
issue -- calling that function for an object that's long gone -- the
missing refcounting I hinted at in my first Email.

Where it calls the ->class->get_fields(event_call);

that calls this function. By setting:

	user->call.get_fields = NULL;

this will never get called and no random data will be accessed.

As 'user' is free'd or soon-to-be-free'd memory, that's a non-starter.

I can try but I don't think that's the proper fix for above reasons, I'm
sorry.

Thanks,
Mathias

On 25.07.24 21:05, Steven Rostedt wrote:

That should be:
+       call->class->get_fields = NULL;

 	free_event_filter(call->filter);
 	call->filter = NULL;
 }

Can you try it out?

Just tried, dies the same way, as expected.

Thanks,
Mathias

On Thu, 25 Jul 2024 21:42:41 +0200
Mathias Krause [off-list ref] wrote:

Right. But the point is, that 'event_call' is really some '&user->call'.
With 'user' being free'd memory, what gives? Dereferencing 'event_call'
is UB, so this function is doomed to fail because it cannot know if its
only argument points to still valid memory or not. And that's the core
issue -- calling that function for an object that's long gone -- the
missing refcounting I hinted at in my first Email.

Ah, I missed that the call was part of the user structure. But I think I
found the real fix.

quoted

Where it calls the ->class->get_fields(event_call);

that calls this function. By setting:

	user->call.get_fields = NULL;

this will never get called and no random data will be accessed.  

As 'user' is free'd or soon-to-be-free'd memory, that's a non-starter.

quoted

That said, I was talking with Beau, we concluded that this shouldn't be the
responsibility of the user of event call, and should be cleaned up by the
event system.

Here's the proper fix:

diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index 6ef29eba90ce..3a2d2ff1625b 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c

@@ -3140,8 +3140,10 @@ EXPORT_SYMBOL_GPL(trace_add_event_call);
  */
 static void __trace_remove_event_call(struct trace_event_call *call)
 {
+	lockdep_assert_held(&event_mutex);
 	event_remove(call);
 	trace_destroy_fields(call);
+	call->get_fields = NULL;

Actually, this is wrong as it would be: call->class->get_fields, and this
is not the right place to clear it, as class can be used by multiple calls.

quoted

 	free_event_filter(call->filter);
 	call->filter = NULL;
 }

Can you try it out?  

I can try but I don't think that's the proper fix for above reasons, I'm
sorry.

I believe the issue is that f_start() needs to check if the event file has
been freed.

New patch:

diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index 6ef29eba90ce..5fbfa1c885de 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c

@@ -1627,12 +1627,14 @@ static int f_show(struct seq_file *m, void *v)
 
 static void *f_start(struct seq_file *m, loff_t *pos)
 {
+	struct trace_event_file *file;
 	void *p = (void *)FORMAT_HEADER;
 	loff_t l = 0;
 
 	/* ->stop() is called even if ->start() fails */
 	mutex_lock(&event_mutex);
-	if (!event_file_data(m->private))
+	file = event_file_data(m->private);
+	if (!file || (file->flags & EVENT_FILE_FL_FREED))
 		return ERR_PTR(-ENODEV);
 
 	while (l < *pos && p)


-- Steve

On 25.07.24 22:15, Steven Rostedt wrote:

Nope, still the same splats.

Sorry,
Mathias

On Thu, 25 Jul 2024 22:41:23 +0200
Mathias Krause [off-list ref] wrote:

quoted

diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index 6ef29eba90ce..5fbfa1c885de 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c

@@ -1627,12 +1627,14 @@ static int f_show(struct seq_file *m, void *v)
 
 static void *f_start(struct seq_file *m, loff_t *pos)
 {
+	struct trace_event_file *file;
 	void *p = (void *)FORMAT_HEADER;
 	loff_t l = 0;
 
 	/* ->stop() is called even if ->start() fails */
 	mutex_lock(&event_mutex);
-	if (!event_file_data(m->private))
+	file = event_file_data(m->private);
+	if (!file || (file->flags & EVENT_FILE_FL_FREED))
 		return ERR_PTR(-ENODEV);
 
 	while (l < *pos && p)

  

Nope, still the same splats.

Can you reshow the splats. Because I'm now confused.

destroy_user_event() which is under event_mutex calls
user_event_set_call_visible() with false, that will then call:

trace_remove_event_call() -> probe_remove_event_call() ->
 __trace_remove_event_call() -> event_remove() ->
 remove_event_from_tracers()

Where remove_event_from_tracers() loops over all the instances and will set
each of the file pointers flags associated to the event: EVENT_FILE_FL_FREED

Then it returns back to destroy_user_event() that would free the event.

The f_start() that was in your crash, with the new patch, should take the
event_mutex before referencing the event that was freed. And with that flag
being set, it should exit out.

Did you remove all the other patches before applying this one?

-- Steve

On 25.07.24 23:14, Steven Rostedt wrote:

On Thu, 25 Jul 2024 22:41:23 +0200
Mathias Krause [off-list ref] wrote:

quoted

quoted

diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index 6ef29eba90ce..5fbfa1c885de 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c

@@ -1627,12 +1627,14 @@ static int f_show(struct seq_file *m, void *v)
 
 static void *f_start(struct seq_file *m, loff_t *pos)
 {
+	struct trace_event_file *file;
 	void *p = (void *)FORMAT_HEADER;
 	loff_t l = 0;
 
 	/* ->stop() is called even if ->start() fails */
 	mutex_lock(&event_mutex);
-	if (!event_file_data(m->private))
+	file = event_file_data(m->private);
+	if (!file || (file->flags & EVENT_FILE_FL_FREED))
 		return ERR_PTR(-ENODEV);
 
 	while (l < *pos && p)

  

Nope, still the same splats.

Can you reshow the splats. Because I'm now confused.

Sure, see attached serial.log.

That was for a single run of
tools/testing/selftests/user_events/ftrace_test with the read loop of
/sys/kernel/tracing/events/user_events/__test_event/format in a
different shell.

destroy_user_event() which is under event_mutex calls
user_event_set_call_visible() with false, that will then call:

trace_remove_event_call() -> probe_remove_event_call() ->
 __trace_remove_event_call() -> event_remove() ->
 remove_event_from_tracers()

Where remove_event_from_tracers() loops over all the instances and will set
each of the file pointers flags associated to the event: EVENT_FILE_FL_FREED

Then it returns back to destroy_user_event() that would free the event.

The f_start() that was in your crash, with the new patch, should take the
event_mutex before referencing the event that was freed. And with that flag
being set, it should exit out.

Looking at the very first report:

[   76.306946] BUG: KASAN: slab-use-after-free in f_start+0x36e/0x3d0

That's what faddr2line gives me:

f_start+0x36e/0x3d0:
f_start at kernel/trace/trace_events.c:1637 (discriminator 1)

Which is:
1635     mutex_lock(&event_mutex);
1636     file = event_file_data(m->private);
1637     if (!file || (file->flags & EVENT_FILE_FL_FREED))
1638         return ERR_PTR(-ENODEV);

Apparently, 'file' was free'd now and reading the 'flags' member
triggers KASAN.

Second report is:

[   76.367688] BUG: KASAN: slab-use-after-free in f_start+0x2e4/0x3d0

which faddr2line says is:

f_start+0x2e4/0x3d0:
trace_get_fields at include/linux/trace_events.h:482
(inlined by) f_next at kernel/trace/trace_events.c:1545
(inlined by) f_start at kernel/trace/trace_events.c:1641

480 trace_get_fields(struct trace_event_call *event_call)
481 {
482     if (!event_call->class->get_fields)
483         return &event_call->class->fields;

The one we ran into first.

So still something doesn't match up with how lifetimes of objects are
managed.

Did you remove all the other patches before applying this one?

Sure. That's what I have on top of v6.10:

minipli@nuc:~/src/linux (tracefs)$ git diff v6.10 > ~/6.10-tracefs_dbg.diff

Please ignore the WARN()s. They're left-overs from earlier debug
attempts of mine.

Thanks,
Mathias

On Thu, 25 Jul 2024 23:32:30 +0200
Mathias Krause [off-list ref] wrote:

That was for a single run of
tools/testing/selftests/user_events/ftrace_test with the read loop of
/sys/kernel/tracing/events/user_events/__test_event/format in a
different shell.

quoted

destroy_user_event() which is under event_mutex calls
user_event_set_call_visible() with false, that will then call:

trace_remove_event_call() -> probe_remove_event_call() ->
 __trace_remove_event_call() -> event_remove() ->
 remove_event_from_tracers()

Where remove_event_from_tracers() loops over all the instances and will set
each of the file pointers flags associated to the event: EVENT_FILE_FL_FREED

Then it returns back to destroy_user_event() that would free the event.

The f_start() that was in your crash, with the new patch, should take the
event_mutex before referencing the event that was freed. And with that flag
being set, it should exit out.  

Looking at the very first report:

[   76.306946] BUG: KASAN: slab-use-after-free in f_start+0x36e/0x3d0

That's what faddr2line gives me:

f_start+0x36e/0x3d0:
f_start at kernel/trace/trace_events.c:1637 (discriminator 1)

Which is:
1635     mutex_lock(&event_mutex);
1636     file = event_file_data(m->private);
1637     if (!file || (file->flags & EVENT_FILE_FL_FREED))
1638         return ERR_PTR(-ENODEV);

BAH! I finally figured it out.

I was able to reproduce it and this does stop the UAF from happening.

The issue was, as a short cut, I had the "format" file's i_private point to
the "call" entry directly, and not go via the "file". This is because the
all format files are the same for the same "call", so no reason to
differentiate them.  The other files maintain state (like the "enable",
"trigger", etc). But this means if the file were to disappear, the "format"
file would be unaware of it.

This should fix it for you. It fixed it for me.

-- Steve

diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index 6ef29eba90ce..852643d957de 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c

@@ -1540,7 +1540,8 @@ enum {
 
 static void *f_next(struct seq_file *m, void *v, loff_t *pos)
 {
-	struct trace_event_call *call = event_file_data(m->private);
+	struct trace_event_file *file = event_file_data(m->private);
+	struct trace_event_call *call = file->event_call;
 	struct list_head *common_head = &ftrace_common_fields;
 	struct list_head *head = trace_get_fields(call);
 	struct list_head *node = v;

@@ -1572,7 +1573,8 @@ static void *f_next(struct seq_file *m, void *v, loff_t *pos)
 
 static int f_show(struct seq_file *m, void *v)
 {
-	struct trace_event_call *call = event_file_data(m->private);
+	struct trace_event_file *file = event_file_data(m->private);
+	struct trace_event_call *call = file->event_call;
 	struct ftrace_event_field *field;
 	const char *array_descriptor;
 

@@ -1627,12 +1629,14 @@ static int f_show(struct seq_file *m, void *v)
 
 static void *f_start(struct seq_file *m, loff_t *pos)
 {
+	struct trace_event_file *file;
 	void *p = (void *)FORMAT_HEADER;
 	loff_t l = 0;
 
 	/* ->stop() is called even if ->start() fails */
 	mutex_lock(&event_mutex);
-	if (!event_file_data(m->private))
+	file = event_file_data(m->private);
+	if (!file || (file->flags & EVENT_FILE_FL_FREED))
 		return ERR_PTR(-ENODEV);
 
 	while (l < *pos && p)

@@ -2485,7 +2489,6 @@ static int event_callback(const char *name, umode_t *mode, void **data,
 	if (strcmp(name, "format") == 0) {
 		*mode = TRACE_MODE_READ;
 		*fops = &ftrace_event_format_fops;
-		*data = call;
 		return 1;
 	}
 

-- 
2.43.0

On 26.07.24 01:06, Steven Rostedt wrote:

On Thu, 25 Jul 2024 23:32:30 +0200
Mathias Krause [off-list ref] wrote:

quoted

That was for a single run of
tools/testing/selftests/user_events/ftrace_test with the read loop of
/sys/kernel/tracing/events/user_events/__test_event/format in a
different shell.

quoted

destroy_user_event() which is under event_mutex calls
user_event_set_call_visible() with false, that will then call:

trace_remove_event_call() -> probe_remove_event_call() ->
 __trace_remove_event_call() -> event_remove() ->
 remove_event_from_tracers()

Where remove_event_from_tracers() loops over all the instances and will set
each of the file pointers flags associated to the event: EVENT_FILE_FL_FREED

Then it returns back to destroy_user_event() that would free the event.

The f_start() that was in your crash, with the new patch, should take the
event_mutex before referencing the event that was freed. And with that flag
being set, it should exit out.  

Looking at the very first report:

[   76.306946] BUG: KASAN: slab-use-after-free in f_start+0x36e/0x3d0

That's what faddr2line gives me:

f_start+0x36e/0x3d0:
f_start at kernel/trace/trace_events.c:1637 (discriminator 1)

Which is:
1635     mutex_lock(&event_mutex);
1636     file = event_file_data(m->private);
1637     if (!file || (file->flags & EVENT_FILE_FL_FREED))
1638         return ERR_PTR(-ENODEV);

BAH! I finally figured it out.

I was able to reproduce it and this does stop the UAF from happening.

The issue was, as a short cut, I had the "format" file's i_private point to
the "call" entry directly, and not go via the "file". This is because the
all format files are the same for the same "call", so no reason to
differentiate them.  The other files maintain state (like the "enable",
"trigger", etc). But this means if the file were to disappear, the "format"
file would be unaware of it.

This should fix it for you. It fixed it for me.

Heureka, it did!

Thanks, Steve!

Will ack the patch you send.

Thanks again,
Mathias