Re: [PATCH] trace-cmd: document expected behaviour of execvp for record command

[Paulo Miguel Almeida <paulo.miguel.almeida.rodenas@gmail.com>]

On Thu, Jan 05, 2023 at 06:13:17PM -0500, Steven Rostedt wrote:
> On Fri, 6 Jan 2023 11:52:19 +1300
> Paulo Miguel Almeida <paulo.miguel.almeida.rodenas@gmail.com> wrote:
> 
> > In tracecmd/trace-record.c:<run_cmd>, trace-cmd record -F <executable>
> > is launched via the libc's execvp() routine.
> > 
> > If you run a command which is meant to be found in one of the entries
> > of the PATH env var then you should see <n> invocations of the
> > __x64_sys_execve() syscall where <n> will be equal to the number of
> > attempts that execvp() routine had done until it could find the
> > executable.
> > 
> > While the routine works as expected, its behaviour can seem a bit
> > cryptic for untrained eyes and makes one wonder whether there is
> > something wrong in any of the parts involved in the tracing operation.
> > Some time after one digs into trace-cmd's and libc's code base, one
> > realises that everything is working as expected but documenting it could
> > save other people's time :-)
> > 
> > Document the expected behaviour ftrace users should see depending on
> > the way -F <executable> is used.
> > 
> > Signed-off-by: Paulo Miguel Almeida <paulo.miguel.almeida.rodenas@gmail.com>
> > ---
> > Additional context:
> > 
> > - absolute path example:
> > 
> > 	# trace-cmd record -p function_graph \
> > 		-g __x64_sys_execve -O nofuncgraph-irqs \
> > 	        -n __cond_resched --max-graph-depth 1  \
> > 		-F /usr/bin/echo "ftrace" > /dev/null
> > 	
> > 	# trace-cmd report 
> > 	echo-172994 [000] 185539.798539: funcgraph_entry:      ! 803.376 us |  __x64_sys_execve();
> > 
> > - PATH-dependent path example:
> > 
> > 	# trace-cmd record -p function_graph \
> > 		-g __x64_sys_execve -O nofuncgraph-irqs \
> > 		-n __cond_resched --max-graph-depth 1  \
> > 		-F echo "ftrace" > /dev/null
> > 
> > 	# trace-cmd report
> >         echo-172656 [002] 185009.671586: funcgraph_entry:      ! 288.732 us |  __x64_sys_execve();
> >         echo-172656 [002] 185009.671879: funcgraph_entry:      ! 158.337 us |  __x64_sys_execve();
> >         echo-172656 [002] 185009.672042: funcgraph_entry:      ! 161.843 us |  __x64_sys_execve();
> >         echo-172656 [002] 185009.672207: funcgraph_entry:      ! 157.656 us |  __x64_sys_execve();
> >         echo-172656 [002] 185009.672369: funcgraph_entry:      ! 156.343 us |  __x64_sys_execve();
> >         echo-172656 [002] 185009.672529: funcgraph_entry:      ! 863.629 us |  __x64_sys_execve();
> 
> Honestly, the above should be in the change log.

Fair enough. I will send a new patch shortly.

> 
> > 
> > ---
> >  Documentation/trace-cmd/trace-cmd-record.1.txt | 4 ++++
> >  1 file changed, 4 insertions(+)
> > 
> > diff --git a/Documentation/trace-cmd/trace-cmd-record.1.txt b/Documentation/trace-cmd/trace-cmd-record.1.txt
> > index b709e48..a000cbe 100644
> > --- a/Documentation/trace-cmd/trace-cmd-record.1.txt
> > +++ b/Documentation/trace-cmd/trace-cmd-record.1.txt
> > @@ -113,6 +113,10 @@ OPTIONS
> >      Using *-F* will let you trace only events that are caused by the given
> >      command.
> >  
> > +    Note: if the specified filename is neither absolute or relative then libc
> > +    will invoke execve() syscall for every entry in the colon-separated list of
> > +    directory pathnames specified in the PATH environment variable.
> > +
> 
> Hmm, do you think it may be worth open-coding execvp() and looking for it
> from trace-cmd, and then only enabling tracing when it found the full path?
> 
> -- Steve

That's a good point. I thought about it for a while and this is really a pickle.

I'll dump the things I'm thinking about and peharps you can help me
choosing between the approaches :-)

Launching executables via:

libc->execvp: It avoid some sorts of TOCTOU race conditions by trying to
execve executables and leave it up to the kernel to do a 'single'
file-exists validation (best case scenario) instead of validate whether
file exists twice, once in user-space and again in kernel (best case
scenario).

bash: As a counter point (and also because that's most
likely how trace-cmd will be executed). Bash actually does the
open-coding execvp() approach as shown below:

# trace-cmd record -p function_graph \
	-g __x64_sys_execve -O nofuncgraph-irqs \
	--max-graph-depth 1  \
	-F /usr/bin/bash -c "ls" > /dev/null


ls-178525 [010] 197387.772776: funcgraph_entry:      ! 775.074 us |  __x64_sys_execve(); # for /usr/bin/bash
ls-178525 [010] 197387.775568: funcgraph_entry:      ! 993.453 us |  __x64_sys_execve(); # for /usr/bin/ls

I guess this will boil down to whether you want to make trace-cmd as
'transparent' as possible (in comparison to running the command without
prepending trace-cmd) OR if you actually care about/want to abide by
the TOCTOU 'guarantees' that libc implements for userspace applications

Let me know your thoughts. I'm flexible with either approach

- Paulo Almeida

> 
> 
> >  *-P* 'pid'::
> >       Similar to *-F* but lets you specify a process ID to trace.
> >  
>