Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

os: os.StartProcess test grandchild inconsistent behavior #37745

Closed
davidmanzanares opened this issue Mar 8, 2020 · 3 comments
Closed

os: os.StartProcess test grandchild inconsistent behavior #37745

davidmanzanares opened this issue Mar 8, 2020 · 3 comments
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone
Backlog

Comments

@davidmanzanares
Copy link

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 toothrot changed the title go test: grandchild inconsistent behavior cmd/go: test grandchild inconsistent behavior Mar 9, 2020
@toothrot toothrot changed the title cmd/go: test grandchild inconsistent behavior os: os.StartProcess test grandchild inconsistent behavior Mar 9, 2020
@toothrot
Copy link
Contributor

toothrot commented Mar 9, 2020

@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.

@toothrot toothrot added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Mar 9, 2020
@toothrot toothrot added this to the Backlog milestone Mar 9, 2020
@ianlancetaylor
Copy link
Contributor

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
Copy link
Author

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

@golang golang locked and limited conversation to collaborators Mar 10, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Milestone
Backlog
Development

No branches or pull requests
4 participants
@toothrot @davidmanzanares @ianlancetaylor @gopherbot