Re: tprobe event tracing error

[Steven Rostedt <rostedt@goodmis.org>]

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
>