Go: syscall: ForkExec with Ptrace flag causes runtime to be traced

[bjames2011]

Environment

> go version
go version go1.6.2 linux/amd64

> uname -a
Linux yoga 4.4.0-83-generic #106-Ubuntu SMP Mon Jun 26 17:54:43 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux

> go env
GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/bjames/Dropbox/go"
GORACE=""
GOROOT="/usr/lib/go-1.6"
GOTOOLDIR="/usr/lib/go-1.6/pkg/tool/linux_amd64"
GO15VENDOREXPERIMENT="1"
CC="gcc"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0"
CXX="g++"
CGO_ENABLED="1"

Issue

This is somewhat of a philosophical question about the design decisions made in the Go runtime, rather than a bug, per-se.

I've been trying to implement a simple strace-like program in Golang, using syscall.ForkExec with the Ptrace flag enabled - my expectation of this flag is that it enables tracing syscalls of the _child_ process _after the fork has occurred_, something like the following (as I would write, if implementing the same program in C):

pid = fork();
switch( pid )
{
    // Error
    case -1:
    {
        printf( "Fork failed!" );
        break
    }

    // Child process.
    case 0:
    {
        // Enable tracing of this process.
        ptrace( PTRACE_TRACEME, 0, 0, 0 );

        // SIGSTOP to allow parent to catch all syscalls from execvp() onwards.
        kill( getpid(), SIGSTOP );
        return execvp( args[0], args );
    }

    // Parent process.
    default:
    {
        // Wait for child to SIGSTOP.
        waitpid( pid, &status, 0 );
        assert( WIFSTOPPED( status ) );

        // Set ptrace options.
        ptrace( PTRACE_SETOPTIONS, pid, 0, PTRACE_O_TRACESYSGOOD );

        // Child is currently entering a kill() syscall - restart and catch the exit of that syscall.
        ptrace( PTRACE_SYSCALL, pid, 0, 0 );
        waitpid( pid, &status, 0 );

        // Child is about to execvp() - start tracing...
        trace( pid );        
    }
}

void trace( int pid )
{
    // Loop until child exits.
    while( 1 )
    {
        // Restart child and wait for next syscall entry.
        ptrace( PTRACE_SYSCALL, pid, 0, 0 );
        waitpid( pid, &status, 0);

        // Check status for child exiting.
        ...

        // Print syscall entry details.
        ...

        // Restart child and wait for syscall exit.
        ptrace( PTRACE_SYSCALL, pid, 0, 0 );
        waitpid( pid, &status, 0 );

        // Check status for child exiting.
        ...

        // Print syscall exit (retval) details.
        ...
    }
}

However it doesn't seem like the above is possible in Go due to the fact that the Ptrace flag is checked too early in https://golang.org/src/syscall/exec_linux.go (forkAndExecInChild()) and a number of (Go runtime) syscalls are performed between enabling tracing and the actual exec call.

Here's a cut-down version of the code I'm using:

// Create process attributes.
attr := syscall.ProcAttr{
    ...
    Sys: &syscall.SysProcAttr{
        Ptrace:  true,
    },
}

// Fork/exec command.
pid, err := syscall.ForkExec( path, args, &attr )
...

// Wait on child.
var wstat syscall.WaitStatus
_, err = syscall.Wait4( pid, &wstat, 0, nil )
...

// Set Ptrace options
err = syscall.PtraceSetOptions( pid, syscall.PTRACE_O_TRACESYSGOOD )

// Trace child...
trace( pid )



func trace {

    for {
        // Restart child and wait for next syscall entry.
        err := syscall.PtraceSyscall( pid, 0 )
        ...
        var wstat syscall.WaitStatus
        _, err = syscall.Wait4( pid, &wstat, 0, nil )
        ...

        // Check status for child exiting.
        ...

        // Print syscall entry details.
        ...

        // Restart child and wait for next syscall entry.
        err := syscall.PtraceSyscall( pid, 0 )
        ...
        var wstat syscall.WaitStatus
        _, err = syscall.Wait4( pid, &wstat, 0, nil )
        ...

        // Check status for child exiting.
        ...

        // Print syscall exit (retval) details.
        ...
    }
}

Question

Why was this design decision made and what is the intended usage of the Ptrace flag? Is it the intended behaviour to trace the Go runtime in the child process before the exec? If so, that's a bit counter-intuitive to the user.

Even better, is there a code example demonstrating the intended usage of the Ptrace flag and how one might implement strace using Go?

[odeke-em]

@bjames2011 there was a presentation at Gophercon by Liz Rice @lizrice at https://medium.com/@lizrice/strace-in-60-lines-of-go-b4b76e3ecd64 "Strace in 60 lines of Go", that might help you.

[ianlancetaylor]

It's true that there are various optional system calls that may be executed after the ptrace system call, but it's not obvious to me why that matters one way or another.

For what it's worth, it's unusually to call syscall.ForkExec directly. Normally people call os.StartProcess or use the os/exec package. But I don't know whether that makes a difference here.

What fix do you suggest? To simply move the ptrace system call down to just before the execve system call?

[bjames2011]

@bjames2011 there was a presentation at Gophercon by Liz Rice @lizrice at https://medium.com/@lizrice/strace-in-60-lines-of-go-b4b76e3ecd64 "Strace in 60 lines of Go", that might help you.

Thanks; for some reason, I'd completely failed to find anything like this when Googling. The code in that presentation is very similar to what I ended up with - albeit using os.StartProcess() instead of syscall.ForkExec().

but it's not obvious to me why that matters one way or another

Hence my intro text "This is somewhat of a philosophical question about the design decisions made in the Go runtime, rather than a bug, per-se."

It is somewhat counter-intuitive, when tracing a process, to see completely unrelated system calls _not executed by the process_. From a user point-of-view, what the runtime does in order to set up the new process is completely unrelated to the process itself (and simply a side-effect of the fact that we're writing Go).

After all, the only way to know which syscalls were executed by the subprocess - rather than the Go runtime - is to track the syscall type and ignore all syscalls until the execve(), however this makes the code rather ugly (and makes it very obvious that you're "working around" an idiosyncrasy of the runtime). Such a work-around also exposes implementation details of the Go runtime and would need to be updated if the runtime decided to use a different member of the exec*() family, for example.

What fix do you suggest? To simply move the ptrace system call down to just before the execve system call?

That's _exactly_ what I was implying with my C example. ;-)

Unless there was a conscious design decision made to include the Go runtime calls in the trace (and I can't see any logical reason why this would make sense), I would very much suggest moving the ptrace() down to the line immediately before the execve() - this would fix this issue.

If you need further justification, it would also be a moral victory (as you will have converted one more C programmer to using Go, as - at present - I've rewritten my program in C).

[lizrice]

Thanks for the shout-out @odeke-em :-)

Just reading the source quickly there, the Ptrace flag is checked as soon as the Clone syscall creates the child process. So yes, it's tracing the syscalls that the Go runtime calls before the execve, but they _are_ executed by the child process - so I think it's right that they are included in the trace. If the ptrace wasn't started until just before the execve, I think we'd just lose the ability to trace those syscalls, wouldn't we?

[bjames2011]

...but they are executed by the child process - so I think it's right that they are included in the trace.

Yes, they are executed by the child _process_, but not by the _program_ that the user specified in the call to os.Command(), but instead by the runtime.

If the ptrace wasn't started until just before the execve, I think we'd just lose the ability to trace those syscalls, wouldn't we?

Yes, but all the syscalls executed before the exec are completely unrelated to the thing the user asked to trace. In this case, the user API exposes "trace this program" (n.b. the forked process is just a side-effect of how the program is run), but the outcome is "trace this program (and some unexpected stuff the runtime decides to do)".

A few points here:

1. If you decide to change the runtime, it will appear to the user as if the child program (which may well be completely unchanged) has mysteriously changed its behaviour.
2. Even though you lose the ability to trace the _process_ syscalls before the execve, there is no information lost here - all the syscalls before the execve are a result of the data passed by the user anyway.

I can't think of a use-case where the user of this API would want to trace the runtime implicitly like this; the only time it would make sense to trace those runtime syscalls would be from an external process (i.e. a debugger attaching to the parent Go process) and in that case, the suggested change would not cause any syscalls to be lost.

Overall, I'd say that the current behaviour falls into the realm of "exposing the implementation" and the suggested change should be considered.

[bjames2011]

Also, the "missing syscalls" argument has a hole in it as there are other syscalls between the fork() and the ptrace() which won't be caught (from: https://golang.org/src/syscall/exec_linux.go):

...
    // Fork succeeded, now in child.

    // Wait for User ID/Group ID mappings to be written.
    if sys.UidMappings != nil || sys.GidMappings != nil {
        if _, _, err1 = RawSyscall(SYS_CLOSE, uintptr(p[1]), 0, 0); err1 != 0 {
            goto childerror
        }
        r1, _, err1 = RawSyscall(SYS_READ, uintptr(p[0]), uintptr(unsafe.Pointer(&err2)), unsafe.Sizeof(err2))
        if err1 != 0 {
            goto childerror
        }
        if r1 != unsafe.Sizeof(err2) {
            err1 = EINVAL
            goto childerror
        }
        if err2 != 0 {
            err1 = err2
            goto childerror
        }
    }

    // Enable tracing if requested.
    if sys.Ptrace {
        _, _, err1 = RawSyscall(SYS_PTRACE, uintptr(PTRACE_TRACEME), 0, 0)
        if err1 != 0 {
            goto childerror
        }
    }
...

[lizrice]

fwiw I agree with you that the call to SYS_PTRACE is either too early or too late (and without checking the history, I'd bet that that the UID/GID mappings section was added more recently.)

@ianlancetaylor pretty sure that os.StartProcess() ends up calling syscall.ForkExec() anyway, so would result in the same behaviour

[ianlancetaylor]

I have no opinion on the right fix. Does somebody want to send in a change?

[jessfraz]

I can send a patch to move the ptrace call before execve

[gopherbot]

Change https://golang.org/cl/55811 mentions this issue: syscall: move ptrace setup to right before exec

[ianlancetaylor]

@jessfraz Thanks. Does anybody who cares about this issue object to https://golang.org/cl/55811?

[lizrice]

don't know how qualified I am to say this, but lgtm!

[odeke-em]

@lizrice I don't know if you are interested, but if you can log into Gerrit with a gmail account, it'd be awesome to have you there as a reviewer and you can put your approvals or disapprovals on there, and then in merges, yours will be there on the record as a Go reviewer!

[bjames2011]

The review looks good to me. Thanks to everyone on the quick responses so far.

[odeke-em]

Same thing for you too @bjames2011 as I had mentioned in https://github.com/golang/go/issues/21428#issuecomment-322563408 :)

[lizrice]

Thanks @odeke-em - I added myself as a reviewer on there. Exciting, my first Go review is a LGTM on a @jessfraz change :-)

[jessfraz]

:) appreciate it and definitely review more o/

On Aug 15, 2017 5:28 PM, "Liz Rice" [e-mail] wrote:

Thanks @odeke-em https://github.com/odeke-em - I added myself as a
reviewer on there. Exciting, my first Go review is a LGTM on a @jessfraz
https://github.com/jessfraz change :-)

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/golang/go/issues/21428#issuecomment-322594782, or mute
the thread
https://github.com/notifications/unsubscribe-auth/ABYNbBhNw3sG-u-Vv4tvb6_4s3jkF9DGks5sYg1vgaJpZM4O1r4m
.