<div dir="ltr"><div><div><div><div>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.</div><div><br></div><div>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.</div><div><br></div><div>        $ ./strace-4.10/strace -f -o strace.log -e trace=file go build main.go</div><div>        $ grep 'resumed' strace.log</div><div>        4039  <... select resumed> )            = ? <unavailable></div><div>        $</div><div><br></div><div>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.</div><div><br></div><div>        $ grep "select(" strace.log</div><div>        $</div><div><br></div><div>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.</div><div><br></div><div>I just compiled strace-4.10.  The Go toolchain is version go1.4.2.linux-amd64.  Here is my machine information:</div><div><br></div><div>        $ uname -a</div><div>        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</div><div><br></div><div>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:</div><div><br></div><div>        package main</div><div>        import "fmt"</div><div>        func main() { fmt.Println("hello, world") }</div><div><br></div><div>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.</div><div><br></div><div>Please look things over and let me know what you think.  Thanks for you help.  Cheers</div><div><br></div><div>diff --git a/syscall.c b/syscall.c</div><div>--- a/syscall.c</div><div>+++ b/syscall.c</div><div>@@ -2213,6 +2213,19 @@ trace_syscall_exiting(struct tcb *tcp)</div><div>                        goto ret;</div><div>        }</div><div> </div><div>+</div><div>+    /* Filter the syscall before it gets counted. It's etime wasn't</div><div>+     * counted on entry.</div><div>+     * */</div><div>+       if (!(tcp->qual_flg & QUAL_TRACE)</div><div>+        || (tracing_paths && !pathtrace_match(tcp))</div><div>+       ) {</div><div>+               tcp->flags |= TCB_INSYSCALL | TCB_FILTERED;</div><div>+               return 0;</div><div>+       }</div><div>+</div><div>+       tcp->flags &= ~TCB_FILTERED;</div><div>+</div><div>        if (cflag) {</div><div>                count_syscall(tcp, &tv);</div><div>                if (cflag == CFLAG_ONLY_STATS) {</div></div></div></div><div><br></div></div>