Re: [PATCH v4 00/10] tracing: introducing eventfs

[Ajay Kaher <akaher@vmware.com>]

> On 19-Jul-2023, at 7:53 PM, Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> !! External Email
> 
> On Wed, 19 Jul 2023 10:25:28 +0000
> Ajay Kaher <akaher@vmware.com> wrote:
> 
>> - Is it also reproducible on v3?
>> - Is it manually reproducible or reproducible using any specific script?
>> 
>> Let me know if I can help.
> 
> Just tried it against v3, and it gave me the splat that I originally had
> and starting to fix, which now gives me another splat. I'll spend a couple
> more days on it and start sharing code and seeing if we can work together
> on this.
> 
> Here's the reproducer (of both v3 splat and the bug I'm hitting now).
> 
> ~# echo 'p:sock_getattr 0xffffffff9b55cef0 sk=%di' > /sys/kernel/tracing/kprobe_events
> ~# ls /sys/kernel/debug/tracing/events/kprobes/sock_getattr/
> ~# echo '-:sock_getattr 0xffffffff9b55cef0 sk=%di' > /sys/kernel/tracing/kprobe_events

I tried above steps on v4 but couldn’t reproduce:

root@photon-6 [ ~/sdb/linux ]# echo 'p:sock_getattr 0xffffffff9b55cef0 sk=%di' > /sys/kernel/tracing/kprobe_events
root@photon-6 [ ~/sdb/linux ]# ls /sys/kernel/debug/tracing/events/kprobes/sock_getattr/
enable  filter  format  id  trigger
root@photon-6 [ ~/sdb/linux ]# echo '-:sock_getattr 0xffffffff9b55cef0 sk=%di' > /sys/kernel/tracing/kprobe_events
-bash: echo: write error: No such file or directory

I have doubt on call_srcu(), it may first end the grace period for parent then for child. If this is true then free_list
will have unordered list and could cause problem.
 

> 
> v3 gives me (and my updates too)
> 
> ======================================================
> WARNING: possible circular locking dependency detected
> 6.5.0-rc1-test+ #576 Not tainted
> ------------------------------------------------------
> trace-cmd/840 is trying to acquire lock:
> ffff8881007e5de0 (&sb->s_type->i_mutex_key#5){++++}-{3:3}, at: dcache_dir_open_wrapper+0xc1/0x1b0
> 
> but task is already holding lock:
> ffff888103ad7e70 (eventfs_rwsem/1){.+.+}-{3:3}, at: dcache_dir_open_wrapper+0x6f/0x1b0
> 
> which lock already depends on the new lock.
> 
> 
> the existing dependency chain (in reverse order) is:
> 
> -> #1 (eventfs_rwsem/1){.+.+}-{3:3}:
>        down_read_nested+0x41/0x180
>        eventfs_root_lookup+0x42/0x120
>        __lookup_slow+0xff/0x1b0
>        walk_component+0xdb/0x150
>        path_lookupat+0x67/0x1a0
>        filename_lookup+0xe4/0x1f0
>        vfs_statx+0x9e/0x180
>        vfs_fstatat+0x51/0x70
>        __do_sys_newfstatat+0x3f/0x80
>        do_syscall_64+0x3a/0xc0
>        entry_SYSCALL_64_after_hwframe+0x6e/0xd8
> 
> -> #0 (&sb->s_type->i_mutex_key#5){++++}-{3:3}:
>        __lock_acquire+0x165d/0x2390
>        lock_acquire+0xd4/0x2d0
>        down_write+0x3b/0xd0
>        dcache_dir_open_wrapper+0xc1/0x1b0
>        do_dentry_open+0x20c/0x510
>        path_openat+0x7ad/0xc60
>        do_filp_open+0xaf/0x160
>        do_sys_openat2+0xab/0xe0
>        __x64_sys_openat+0x6a/0xa0
>        do_syscall_64+0x3a/0xc0
>        entry_SYSCALL_64_after_hwframe+0x6e/0xd8
> 
> other info that might help us debug this:
> 
>  Possible unsafe locking scenario:
> 
>        CPU0                    CPU1
>        ----                    ----
>   rlock(eventfs_rwsem/1);
>                                lock(&sb->s_type->i_mutex_key#5);
>                                lock(eventfs_rwsem/1);
>   lock(&sb->s_type->i_mutex_key#5);
> 
>  *** DEADLOCK ***
> 
> 1 lock held by trace-cmd/840:
>  #0: ffff888103ad7e70 (eventfs_rwsem/1){.+.+}-{3:3}, at: dcache_dir_open_wrapper+0x6f/0x1b0
> 
> stack backtrace:
> CPU: 7 PID: 840 Comm: trace-cmd Not tainted 6.5.0-rc1-test+ #576
> Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.16.2-debian-1.16.2-1 04/01/2014
> Call Trace:
>  <TASK>
>  dump_stack_lvl+0x57/0x90
>  check_noncircular+0x14b/0x160
>  __lock_acquire+0x165d/0x2390
>  lock_acquire+0xd4/0x2d0
>  ? dcache_dir_open_wrapper+0xc1/0x1b0
>  down_write+0x3b/0xd0
>  ? dcache_dir_open_wrapper+0xc1/0x1b0
>  dcache_dir_open_wrapper+0xc1/0x1b0
>  ? __pfx_dcache_dir_open_wrapper+0x10/0x10
>  do_dentry_open+0x20c/0x510
>  path_openat+0x7ad/0xc60
>  do_filp_open+0xaf/0x160
>  do_sys_openat2+0xab/0xe0
>  __x64_sys_openat+0x6a/0xa0
>  do_syscall_64+0x3a/0xc0
>  entry_SYSCALL_64_after_hwframe+0x6e/0xd8
> RIP: 0033:0x7f1743267e41
> Code: 44 24 18 31 c0 41 83 e2 40 75 3e 89 f0 25 00 00 41 00 3d 00 00 41 00 74 30 89 f2 b8 01 01 00 00 48 89 fe bf 9c ff ff ff 0f 05 <48> 3d 00 f0 ff ff 77 3f 48 8b 54 24 18 64 48 2b 14 25 28 00 00 00
> RSP: 002b:00007ffec10ff5d0 EFLAGS: 00000287 ORIG_RAX: 0000000000000101
> RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f1743267e41
> RDX: 0000000000090800 RSI: 00007ffec10ffdb0 RDI: 00000000ffffff9c
> RBP: 00007ffec10ffda0 R08: 00007ffec11003e0 R09: 0000000000000040
> R10: 0000000000000000 R11: 0000000000000287 R12: 00007ffec11003e0
> R13: 0000000000000040 R14: 0000000000000000 R15: 00007ffec110034b
>  </TASK>
> 

This is expected from v3 (just ignore as of now), if eventfs_set_ef_status_free crash not
reproduced on v3 then it’s v4 issue.

-Ajay

> 
> I moved the code around a bit, and it appears that kprobes is getting
> dput() more than once.
> 
> I moved the d_invalidate() and dput() into the workqueue function, and on
> kprobes going away, d_invalidate() frees it, and dput() is now corrupted.
> 
> Still investigating. The VFS layer is a magic box that needs the right
> wizard hat to deal with, but I unfortunately am waiting on back order to
> retrieve that specific hat :-p
> 
> -- Steve
> 
> !! External Email: This email originated from outside of the organization. Do not click links or open attachments unless you recognize the sender.