Re: tprobe event tracing error

Re: tprobe event tracing error

[Masami Hiramatsu]

Hi,
(Cc: linux-kernel-trace ML for sharing this knowledge)

On Mon, 26 Feb 2024 16:36:29 +0300
Максим Морсков <xxxa0c@mail.ru> wrote:

> 
> Hello, dear Masami.
> I am researching Linux event tracing subsystem in part of tprobes,
> and found interesting behavior in kernel version 6.6:
>  
> echo  't:my_fchmodat sys_enter_fchmodat' | sudo tee ‘/sys/kernel/tracing/dynamic_events’
> bash: line 1: echo: write error: Invalid argument

Yeah, I understand that you are confused by this behavior, but it is
actually expected behavior. syscalls:* events looks like trace events
based on tracepoint, but those are software generated trace event.

You can find raw_syscalls:* trace events, that is based on the tracepoint,
and other syscalls:* are based on that raw_syscalls:* trace points.
(IOW, those are a kind of pre-compiled dynamic events)

e.g.

/sys/kernel/tracing # echo "t sys_enter \$arg*" >> dynamic_events 
/sys/kernel/tracing # cat dynamic_events 
t:tracepoints/sys_enter sys_enter regs=regs id=id

/sys/kernel/tracing # echo "t sys_enter_open \$arg*" >> dynamic_events 
sh: write error: Invalid argument
/sys/kernel/tracing # cat error_log 
[  227.981347] trace_fprobe: error: Tracepoint is not found
  Command: t sys_enter_open $arg*
             ^

So, tprobe can not find the hard-coded tracepoints for those dynamically
generated syscall trace events. But raw_syscall sys_enter/sys_exit are OK.

Thank you,

>  
> sudo cat /sys/kernel/tracing/error_log
> trace_fprobe: error: Tracepoint is not found 
>  Command: t:my_fchmodat sys_enter_fchmodat
>                                                     ^
>  
> But such tracepoint ( sys_enter_fchmodat ) exists in system:
> sudo perf list | grep chmod   
>  syscalls:sys_enter_ chmod                           [Tracepoint event] 
>  syscalls:sys_enter_f chmod                          [Tracepoint event] 
>  syscalls:sys_enter_f chmod at                        [Tracepoint event] 
>  syscalls:sys_enter_f chmod at2                       [Tracepoint event] 
>  syscalls:sys_exit_ chmod                            [Tracepoint event] 
>  syscalls:sys_exit_f chmod                           [Tracepoint event] 
>  syscalls:sys_exit_f chmod at                         [Tracepoint event] 
>  syscalls:sys_exit_f chmod at2                        [Tracepoint event]
>  
> sudo ls -lha /sys/kernel/tracing/events/syscalls/ | grep chmod
> drwxr-xr-x 1 root root 0 фев 26 16:07 sys_enter_ chmod
> drwxr-xr-x 1 root root 0 фев 26 16:07 sys_enter_f chmod
> drwxr-xr-x 1 root root 0 фев 26 16:07 sys_enter_f chmod at 
> drwxr-xr-x 1 root root 0 фев 26 16:07 sys_enter_f chmod at2 
> drwxr-xr-x 1 root root 0 фев 26 16:07 sys_exit_ chmod
> drwxr-xr-x 1 root root 0 фев 26 16:07 sys_exit_f chmod
> drwxr-xr-x 1 root root 0 фев 26 16:07 sys_exit_f chmod at 
> drwxr-xr-x 1 root root 0 фев 26 16:07 sys_exit_f chmod at2
>  
> My kernel config in the attachment.
> I noticed that you are developing event tracing tprobe subsystem.
> May be you could explain such behavior?
> Thank you in advance!
>  
> --
> Best regards
> Maksim Morskov

-- 
Masami Hiramatsu (Google) <mhiramat@kernel.org>

Re: tprobe event tracing error

[Steven Rostedt]

On Mon, 26 Feb 2024 23:41:56 +0900
Masami Hiramatsu (Google) <mhiramat@kernel.org> wrote:

> Hi,
> (Cc: linux-kernel-trace ML for sharing this knowledge)
> 
> On Mon, 26 Feb 2024 16:36:29 +0300
> Максим Морсков <xxxa0c@mail.ru> wrote:
> 
> > 
> > Hello, dear Masami.
> > I am researching Linux event tracing subsystem in part of tprobes,
> > and found interesting behavior in kernel version 6.6:
> >  
> > echo  't:my_fchmodat sys_enter_fchmodat' | 
sudo tee ‘/sys/kernel/tracing/dynamic_events’
> > bash: line 1: echo: write error: Invalid argument  
> 
> Yeah, I understand that you are confused by this behavior, but it is
> actually expected behavior. syscalls:* events looks like trace events
> based on tracepoint, but those are software generated trace event.
> 
> You can find raw_syscalls:* trace events, that is based on the tracepoint,
> and other syscalls:* are based on that raw_syscalls:* trace points.
> (IOW, those are a kind of pre-compiled dynamic events)
> 
> e.g.
> 
> /sys/kernel/tracing # echo "t sys_enter \$arg*" >> dynamic_events 
> /sys/kernel/tracing # cat dynamic_events 
> t:tracepoints/sys_enter sys_enter regs=regs id=id
> 
> /sys/kernel/tracing # echo "t sys_enter_open \$arg*" >> dynamic_events 
> sh: write error: Invalid argument
> /sys/kernel/tracing # cat error_log 
> [  227.981347] trace_fprobe: error: Tracepoint is not found
>   Command: t sys_enter_open $arg*
>              ^
> 
> So, tprobe can not find the hard-coded tracepoints for those dynamically
> generated syscall trace events. But raw_syscall sys_enter/sys_exit are OK.

Ah, that's because "tprobes" are attached to tracepoints and not
trace events. If you want to attach to trace events, you need to use eprobes
(which I need to add documentation for!).

 # echo 'e:my_fchmodat syscalls/sys_enter_fchmodat' > dynamic_events

Works.

-- Steve

Re: tprobe event tracing error

[Steven Rostedt]

On Wed, 28 Feb 2024 17:25:40 +0300
Максим Морсков <xxxa0c@mail.ru> wrote:

> Dear colleagues,
> One last question — is it bug or feature that trobe event tracing can not correctly dereference string pointers from pt_regs?
> For example:
> echo 't:tmy_chmod sys_enter id=$arg2 filename=+8($arg1):string mode=+16($arg1)'  | sudo tee ‘/sys/kernel/tracing/dynamic_events’

So the tprobe attaches to the tracepoint, which is this:

 trace_sys_enter(regs, syscall);

Where arg1 is pt_regs, which on x86_64 (I'm assuming that's what you are
using) has:

struct pt_regs {
/*
 * C ABI says these regs are callee-preserved. They aren't saved on kernel entry
 * unless syscall needs a complete, fully filled "struct pt_regs".
 */
	unsigned long r15;
	unsigned long r14;
	unsigned long r13;
	unsigned long r12;
	unsigned long rbp;
	unsigned long rbx;
/* These regs are callee-clobbered. Always saved on kernel entry. */
	unsigned long r11;
	unsigned long r10;
	unsigned long r9;
	unsigned long r8;
	unsigned long rax;
	unsigned long rcx;
	unsigned long rdx;
	unsigned long rsi;
	unsigned long rdi;
/*
 * On syscall entry, this is syscall#. On CPU exception, this is error code.
 * On hw interrupt, it's IRQ number:
 */
	unsigned long orig_rax;
/* Return frame for iretq */
	unsigned long rip;
	unsigned long cs;
	unsigned long eflags;
	unsigned long rsp;
	unsigned long ss;
/* top of stack page */
};

Where regs+8 is register r14.  and regs+16 is r13. Is that what you really want?

No, it's not.

Also, I noticed that you are not tracing chmod, but you are tracing id = 268
which is fchownat() (I noticed via strace, that this is what "chmod" uses).

The prototype of fchownat() is:

  int fchmodat(int dirfd, const char *pathname, mode_t mode, int flags);

Where pathname is the third parameter, not the first, and mode is the third.

The calling convention for x86_64 is:  rdi rsi rdx rcx r8-9 

That is, arg1 is in register rdi, arg2 is rsi, arg3 is rdx.

We want arguments 2 and 3. Which is:

  regs:		$arg1
  regs->rsi:	+104($arg1)
  regs->rdx:	+96($arg1)

And since the file name is a string, we need to do one more dereference to
get to it:

  pathname:	+0(+104($arg1)):ustring

(notice I used "ustring" as we now differentiate between kernel and user space)

With the above information I can do:

 # cd /sys/kernel/tracing
 # echo 't:tmy_chmod sys_enter id=$arg2 filename=+0(+104($arg1)):ustring mode=+96($arg1):x16' > dynamic_events
 # echo 'id == 268' > events/tracepoints/tmy_chmod/filter
 # echo 1 > events/tracepoints/tmy_chmod/enable
 # mkdir /tmp/x
 # chmod 100 /tmp/x
 # cat trace

# tracer: nop
#
# entries-in-buffer/entries-written: 2/2   #P:8
#
#                                _-----=> irqs-off/BH-disabled
#                               / _----=> need-resched
#                              | / _---=> hardirq/softirq
#                              || / _--=> preempt-depth
#                              ||| / _-=> migrate-disable
#                              |||| /     delay
#           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
#              | |         |   |||||     |         |
           chmod-1035    [004] ...1.  1744.492490: tmy_chmod: (__probestub_sys_enter+0x4/0x10) id=0x10c filename="/tmp/x" mode=0x40

  TADA!!!

-- Steve


> echo 'id == 268' | sudo tee ‘/sys/kernel/tracing/events/tracepoints/tmy_chmod/filter’
> echo '1' | sudo tee ‘/sys/kernel/tracing/events/tracepoints/tmy_chmod/enable’
> echo ‘1’ | sudo tee ‘/sys/kernel/tracing/tracing_on’
> 
> cat ‘/sys/kernel/tracing/trace’
> #           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION 
> #              | |         |   |||||     |         |
>           chmod-10522   [010] ...1.  8533.321703: tmy_chmod: (__probestub_sys_enter+0x0/0x10) id=0x10c fd=0x81ed filename="" mode=0x1ed
>  
> The pointer is correct (it corresponds to kprobe event args), but dereference never happens
>   

Re: tprobe event tracing error

[Steven Rostedt]

On Wed, 28 Feb 2024 10:52:52 -0500
Steven Rostedt <rostedt@goodmis.org> wrote:

> The prototype of fchownat() is:
> 
>   int fchmodat(int dirfd, const char *pathname, mode_t mode, int flags);
> 
> Where pathname is the third parameter, not the first, and mode is the third.

I meant pathname is the second parameter.

-- Steve