cmd/go: go test hangs when exec.CommandContext program uses stdout/stderr

[stapelberg]

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

go version go1.11.1 linux/amd64

Does this issue reproduce with the latest release?

Yes.

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

GOARCH="amd64"
GOBIN=""
GOCACHE="/home/michael/.cache/go-build"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/michael/go"
GOPROXY=""
GORACE=""
GOROOT="/home/michael/sdk/go1.11.1"
GOTMPDIR=""
GOTOOLDIR="/home/michael/sdk/go1.11.1/pkg/tool/linux_amd64"
GCCGO="/usr/bin/gccgo"
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-build672074712=/tmp/go-build -gno-record-gcc-switches"

What did you do?

package repro_test

import (
	"context"
	"os"
	"os/exec"
	"testing"
)

func TestRepro(t *testing.T) {
	ctx, canc := context.WithCancel(context.Background())
	defer canc()
	sleep := exec.CommandContext(ctx, "sleep", "1d")
	sleep.Stdout = os.Stdout // sleep.Stderr = os.Stderr triggers the same symptom
	if err := sleep.Start(); err != nil {
		t.Fatal(err)
	}
}

What did you expect to see?

The test should pass.

What did you see instead?

go test -count=1 ./repro_test.go hangs indefinitely.

• Removing the sleep.Stdout assignment makes the test pass.
• Adding defer func() { sleep.Process.Kill() }() after sleep.Stdout makes the test pass. I would have expected the context cancellation to have the same effect.
• Interactively running killall sleep makes the test pass with result ok.

[ianlancetaylor]

This is a race condition in the test. You aren't waiting for the sleep program to complete.

cmd/go works by building the test program and then running it. Standard output of the test program will be a pipe being read by cmd/go. cmd/go will keep reading from the pipe until all data has been read (this is related to #23019).

Using exec.CommandContext works by setting up a background goroutine that waits for the context to be canceled and then kills the process. In your case your test cancels the context and then immediately returns. Returning from the single test causes the test program to exit. This typically happens before the background goroutine wakes up to see that the context has been canceled. That means that your program exits without killing the sleep subprocess.

Since you set sleep.Stdout = os.Stdout, the sleep subprocess is writing to the pipe that cmd/go passed to the test program. So cmd/go will read from that pipe, which means that it will wait for the sleep program to close the pipe. Since nothing stopped the sleep program, cmd/go will wait for a full day.

This is easy to fix in the test by writing it as

	ctx, canc := context.WithCancel(context.Background())
	sleep := exec.CommandContext(ctx, "sleep", "1d")
	defer sleep.Wait()
	defer canc()

The only other fix would be to fix #23019. So closing this issue as a dup.

[stapelberg]

Thanks for the explanation, especially the reason why context cancellation doesn’t seem to have any effect here is now clear.

Note that the suggested fix (defer sleep.Wait() before defer canc()) only works in this minimal reproduction case.

I extracted this issue from a more elaborate test, where I have a helper function to set up a server process, which is called from multiple tests, e.g.:

func setupEnv(ctx context.Context) error {
  	sleep := exec.CommandContext(ctx, "sleep", "1d")
	sleep.Stdout = os.Stdout // sleep.Stderr = os.Stderr triggers the same symptom
	if err := sleep.Start(); err != nil {
		return err
	}
	return nil
}

func TestFoo(t *testing.T) {
	ctx, canc := context.WithCancel(context.Background())
	defer canc()

	if err := setupEnv(ctx); err != nil {
		t.Fatal(err)
	}

	// test the server process works correctly
}

Obviously, I can’t defer sleep.Wait() before defer canc() in this case. Is there any way around it, or will I have to return a cleanup function from setupEnv?

[ianlancetaylor]

You should definitely arrange for your tests to wait for the server process to exit before they return, one way or another. Apart from this issue it's not great practice to leave a process around potentially writing to stdout as you start a new test. There are various ways you could wait. Returning a cleanup function from setupEnv would work. Or use a sync.WaitGroup.