[PATCH] make strace handle SIGTRAP properly

[Denys Vlasenko]

On Mon, 2011-06-20 at 04:07 +0400, Dmitry V. Levin wrote:
> On Fri, May 20, 2011 at 06:02:14PM +0200, Denys Vlasenko wrote:
> > On Fri, 2011-05-20 at 14:08 +0200, Denys Vlasenko wrote:
> > > Hi,
> > > 
> > > (please don't remove me from CC: when replying)
> > > 
> > > During recent lkml discussions about fixing some long-standing problems
> > > with ptrace, I had to look in strace source and experiment with it a
> > > bit. (CC-ing some participants).
> > > 
> > > One irritating thing I noticed is that we *still* don't handle
> > > user-generated SIGTRAPs. There are users who do want that to work:
> > > 
> > > https://bugzilla.redhat.com/show_bug.cgi?id=162774
> > > 
> > > Currently, strace "handles" SIGTRAP by code like this:
> > > 
> > > #if defined (I386)
> > >         if (upeek(tcp, 4*EAX, &eax) < 0)
> > >                 return -1;
> > >         if (eax != -ENOSYS && !(tcp->flags & TCB_INSYSCALL)) {
> > >                 if (debug)
> > >                         fprintf(stderr, "stray syscall exit: eax = %ld\n", eax);
> > >                 return 0;
> > >         }
> > > #elif ...
> > > 
> > > Think what will happen if SIGTRAP arrives while process is in userspace
> > > and eax happened to contain value equal to -ENOSYS...
> > > 
> > > In order to make it work properly, that is, to detect SIGTRAPs just like
> > > we do with any other signals, we need to use ptrace(PTRACE_SETOPTIONS,
> > > PTRACE_O_TRACESYSGOOD). Otherwise, syscall traps are indistinguishable
> > > from real SIGTRAPs. Well, there is some extremely fragile and/or
> > > arch-specific way way to distinguish them by looking at GETSIGINFO
> > > results or registers (see above), but why should we bother? Linux ptrace
> > > has PTRACE_O_TRACESYSGOOD for many years now, we _can_ use it.
> > > 
> > > Another twist in this story is that pesky extra SIGTRAP generated after
> > > execve. If we start handling real SIGTRAPs, we should not be fooled by
> > > it.
> > > 
> > > And again, even though there may be a difficult way to detect it, I
> > > think we should use the easy one: PTRACE_O_TRACEEXEC option. It disables
> > > post-execve SIGTRAP (and enables intra-execve PTRACE_EVENT_EXEC, which
> > > is easily distinguishable form other stops, so we can ignore it easily).
> > > 
> > > Roland's worry was that in some old kernels ptrace(PTRACE_SETOPTIONS)
> > > was working, but the options themselves were buggy. I trust him that
> > > there were such kernels, but it's history now, right?
> > > So, I propose to attempt ptrace(PTRACE_SETOPTIONS) only on relatively
> > > recent kernels. (say, starting from 2.6.30? (arbitrarily chosen))
> > > 
> > > Any objections to this plan?
> > 
> > And here's the patch against current strace git. Run-tested.
> 
> Unfortunately, this commit introduced a severe regression: starting with
> v4.6-5-g3454e4b, strace -f follows vfork() with low probability.
> Spotted with gcc which uses vfork().
> 
> Test case:
> $ for i in `seq 0 99`; do ./strace -qf -o"|grep -c 'execve(\"'" -- sh -c 'echo "#include <stdio.h>" |gcc -xc -c -o/dev/null -'; done |sort -n |uniq -c
>      83 3
>      17 7

Looking at it.
So far I don't have complete analysis, but I noticed something
which may lead to understanding: strace sometimes exits sooner than
piped-to log process:

sh-4.2# ./strace -qf -o"|grep -c 'execve(\"'" -- sh -c 'echo "#include <stdio.h>" |gcc -xc -c -o/dev/null -'
2
sh-4.2# ./strace -qf -o"|grep -c 'execve(\"'" -- sh -c 'echo "#include <stdio.h>" |gcc -xc -c -o/dev/null -'
2
sh-4.2# ./strace -qf -o"|grep -c 'execve(\"'" -- sh -c 'echo "#include <stdio.h>" |gcc -xc -c -o/dev/null -'
2
sh-4.2# ./strace -qf -o"|grep -c 'execve(\"'" -- sh -c 'echo "#include <stdio.h>" |gcc -xc -c -o/dev/null -'
2
sh-4.2# ./strace -qf -o"|grep -c 'execve(\"'" -- sh -c 'echo "#include <stdio.h>" |gcc -xc -c -o/dev/null -'
2
sh-4.2# ./strace -qf -o"|grep -c 'execve(\"'" -- sh -c 'echo "#include <stdio.h>" |gcc -xc -c -o/dev/null -'
2
sh-4.2# ./strace -qf -o"|grep -c 'execve(\"'" -- sh -c 'echo "#include <stdio.h>" |gcc -xc -c -o/dev/null -'
2

Above runs were ok, but the next one printed exactly this:

sh-4.2# ./strace -qf -o"|grep -c 'execve(\"'" -- sh -c 'echo "#include <stdio.h>" |gcc -xc -c -o/dev/null -'
sh-4.2# 2

See? "2" appeared AFTER shell printed the prompt!

digging deeper right now...

-- 
vda