Unexpected output with -f -e trace=file when tracing the Go compiler

[Bryan Matsuo]

I've stumbled onto some behavior that I believe to be a bug in strace.  I
haven't found any documentation of it so I wanted to report it.

Every once and a while when tracing the Go (golang) compiler using the -f
flag system calls that (afaict) should be filtered out with the
``trace=file'' expression show up in the output.

        $ ./strace-4.10/strace -f -o strace.log -e trace=file go build
main.go
        $ grep 'resumed' strace.log
        4039  <... select resumed> )            = ? <unavailable>
        $

The select system call is not in the group of file calls.  So I don't think
this line should show up in the output.  Also, there is no matching entry
point for the call.

        $ grep "select(" strace.log
        $

This behavior is not exclusive to the select call.  I have also seen
similar behavior involving the futex system call.  I've noticed that the
spurious exiting line always has a "?" return code.

I just compiled strace-4.10.  The Go toolchain is version
go1.4.2.linux-amd64.  Here is my machine information:

        $ uname -a
        Linux test-5 3.13.0-43-generic #72-Ubuntu SMP Mon Dec 8 19:35:06
UTC 2014 x86_64 x86_64 x86_64 GNU/Linux

>From what I've seen any Go program will eventually trigger behavior like
this from strace with enough repeated compilations.  In this case ./main.go
contained a "hello world" program:

        package main
        import "fmt"
        func main() { fmt.Println("hello, world") }

I put together a fairly ham-fisted patch that seemed to fix the problem and
still passed the tests for my system (patch below).  I mirrored some
existing behavior from the trace_syscall_entering function in the
trace_syscall_exiting function.  With my limited understanding of the
codebase it seemed to make sense.  But I don't have a full understanding of
the problem and I couldn't explain why this a patch like this wasn't
necessary in what seem to be the majority of cases.

Please look things over and let me know what you think.  Thanks for you
help.  Cheers

diff --git a/syscall.c b/syscall.c
--- a/syscall.c
+++ b/syscall.c
@@ -2213,6 +2213,19 @@ trace_syscall_exiting(struct tcb *tcp)
                        goto ret;
        }

+
+    /* Filter the syscall before it gets counted. It's etime wasn't
+     * counted on entry.
+     * */
+       if (!(tcp->qual_flg & QUAL_TRACE)
+        || (tracing_paths && !pathtrace_match(tcp))
+       ) {
+               tcp->flags |= TCB_INSYSCALL | TCB_FILTERED;
+               return 0;
+       }
+
+       tcp->flags &= ~TCB_FILTERED;
+
        if (cflag) {
                count_syscall(tcp, &tv);
                if (cflag == CFLAG_ONLY_STATS) {
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.strace.io/pipermail/strace-devel/attachments/20150629/ca663b55/attachment.html>