os: os.StartProcess test grandchild inconsistent behavior

[davidmanzanares]

What version of Go are you using (go version)?

$ go version
go version go1.14 linux/amd64

Does this issue reproduce with the latest release?

Yes

What operating system and processor architecture are you using (go env)?

go env Output

$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/dv/.cache/go-build"
GOENV="/home/dv/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/dv/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build376726503=/tmp/go-build -gno-record-gcc-switches"

What did you do?

I ran the following test.

Firstly with go test -v -count 1, then with go test -v -count 1 ./.

package asd

import (
	"log"
	"os"
	"testing"
	"time"
)

func TestGrandChildWait(t *testing.T) {
	p, err := os.StartProcess("tmp.sh", nil, &os.ProcAttr{
		Files: []*os.File{os.Stdin, os.Stdout, os.Stderr},
	})
	if err != nil {
		log.Fatalln(err)
	}
	go func() {
		s, err := p.Wait()
		log.Println(s, err)
	}()
	go func() {
		time.Sleep(time.Second)
		err = p.Kill()
		if err != nil {
			log.Fatalln(err)
		}
	}()
	time.Sleep(2 * time.Second)
}

The test requires an auxiliar bash script "tmp.sh" (with execution permissions):

#!/bin/sh
sleep 5

What did you expect to see?

I expected a similar execution time, (waiting or not for the grandchild to exit). In fact, in both cases the test gets done is ~2 seconds, but in the "./" case, go test only returns when the grand child (the "sleep" command) ends.

What did you see instead?

$ go test -count 1 -v
=== RUN   TestGrandChildWait
2020/03/08 14:15:38 signal: killed <nil>
--- PASS: TestGrandChildWait (2.00s)
PASS
ok      github.com/davidmanzanares/dsd  2.003s

$ go test -count 1 -v ./
=== RUN   TestGrandChildWait
2020/03/08 14:16:10 signal: killed <nil>
--- PASS: TestGrandChildWait (2.00s)
PASS
ok      github.com/davidmanzanares/dsd  5.004s

Additional info

I found that if I don't pass the stdtin, stdout and stderr file descriptors the issue doesn't appear.

[toothrot]

@davidmanzanares thanks for filing!

@ianlancetaylor may know more.

I think testing and os.StartProcess is a bit of a red herring here. This also happens if you use cmd/exec with os.Stdout in my testing (which, by the way, has better utilities for handling input and output than using os.Stdout directly). I would guess that this is in part due to your use of sleep 5, and possibly the thread state being inherited when referencing os.Stdout and friends. I don't see how else that file descriptor could be shared.

If the calling goroutine has locked the operating system thread with runtime.LockOSThread and modified any inheritable OS-level thread state (for example, Linux or Plan 9 name spaces), the new process will inherit the caller's thread state.

Changing test.sh to the following:

sleep 0.5
echo "hi"
sleep 5
echo "bye"

... will only print out "hi" in the test. This leads me to believe that things are behaving as intended. My guess is that the kill signal is sent while the command is in a blocking syscall (sleep), and the signal isn't handled until afterwards.

I am not an expert though.

[ianlancetaylor]

When using go test, the difference between plain go test and go test ./ is that when go test is invoked with no arguments it streams output directly, and when it is invoked with arguments (in this case ./ it buffers the output. This means that the test binary is being invoked with different standard output: in one case standard output is the terminal, and in the other case it is a pipe. Also significant here is that go test uses the os/exec package to run the test binary.

Once those facts are taken into consideration, this is a dup of #23019. Closing as a dup.

[davidmanzanares]

You're welcome! Thank you! It's nice to know why/how this happens