os/exec: consider changing Wait to stop copying goroutines rather than waiting for them

[ianlancetaylor]

When the Stdin, Stdout, or Stderr fields of os/exec.Cmd are set to anything other than nil or a *os.File (a common case is *bytes.Buffer), we call os.Pipe to get a pipe and create goroutines to copy data in or out. The (*Cmd).Wait method first waits for the subprocess to exit, then waits for those goroutines to finish copying data.

If the subprocess C1 itself starts a subsubprocess C2, and if C1 passes any of its stdin/stdout/stderr descriptors to C2, and if C1 exits without waiting for C2 to exit, then C2 will hold an open end of the pipes created by the os/exec package. The (*Cmd).Wait method will wait until the goroutines complete, which means waiting until those pipes are closed, which in practice means waiting until C2 exits. This is confusing, because the user sees that C1 is done, and doesn't understand why their program is still waiting for it.

This confusion has been filed as an issue multiple times, at least #7378, #18874, #20730, #21922, #22485.

It doesn't have to work this way. Although the current goroutines call io.Copy, we could change them to use a loop. After every Read, the loop could check whether the process has been waited for. Then Wait could wait for the child, tell the goroutines to stop, give them a chance for a final write, and then return. The stdout/stderr goroutines would close their end of the pipe. There wouldn't be any race and there wouldn't be any unexpected waits. But in cases where there is a C2 process, not all of the standard output and standard error output that we currently collect would be available.

To be clear, programmers can already handle these cases however they like by calling os.Pipe themselves and using the pipe in the Cmd struct. That is true today and it would be true if change how it works.

The questions I want to raise are: would making this change be less confusing for people? Can we make this change without breaking the Go 1 guarantee?

CC @bradfitz

[karkason]

This change may break existing code, but it does fix unspecified behavior in (*Cmd).Wait that is also confusing and unexpected and will definitely make the use of os.Cmd less confusing.

[ianlancetaylor]

Another case: #24050.

[eliasnaur]

FWIW, it took me quite a while to figure out that this issue was root cause for mobile tests to sometimes hang indefinitely. https://go-review.googlesource.com/#/c/42271/ is the workaround for the Android test harness.

[slrz]

I actually prefer the semantics we have today. That way, it's at least apparent that something is wrong instead of silently leaving long-running processes behind.

The underlying issue of held-open pipe FDs is explained in any basic OS course and can be debugged using readily available Unix tools. I think the alternative will result in more complex failure cases.

[tsl0922]

@slrz It makes many people confusing that Wait do not return after the process exited. Although the document has been improved, but we still don't have a way to cancel the io.Copy in the internal goroutines unless using io.Pipe for the os.Cmd struct which will make code complex.

[ianlancetaylor]

In order to handle the case where C2 doesn't output anything, we would have to put a deadline on reading from the pipe, so that while waiting for output we periodically check whether C1 has exited.

[tv42]

But in cases where there is a C2 process, not all of the standard output and standard error output that we currently collect would be available.

This sounds like a bug to me, and very much unexpected. I wouldn't ever expect Wait to be guaranteed to return until after I have consumed all the output; in this scenario, the output has not ended yet.

Also, I'm not sure if I understood the "give them a chance for a final write" part, but that sounds like there's a race that could also lose C1 output if C1 exits immediately after filling the pipe buffer; that's not guaranteed to come through in a single Read.

[kgadams]

Would it be possible to get back the go1.9 behavior with a flag?
I have a use case where I need to cancel C1 now and where I really don't care about C2 output and where C2 can be left hanging. I have no control over C2. That used to work with go 1.9, but with go 1.10 it insists on waiting for C2 (which I can't control).

[ianlancetaylor]

@kgadams There was no intentional change in this area in 1.10 This issue is about a proposed change to os/exec; the change has not been implemented. If you are finding an unexpected change that you think is a bug, please open a new issue. Thanks.

[tv42]

@kgadams But you are interested in C1 output, and there is no way to tell which is which.

[kgadams]

My scenario is like this: we are writing an interpreter for a specific content. Other people write the content (I have no control over that). Part of that content is shell script snippets.
Now, during execution (which happens behind a UI), the end user can Cancel us at any time.

If at the point of Cancelation by the end user I am executing the shell (C1), and the shell is executing a long running command (C2), I do not care about C1 output nor about C2 output. All I care about is that the whole enchilada is killed and that the function executing C1 returns without waiting for C2.
I even can live with C2 continuing to run in the background.

Cancelation works by canceling the Context that is passed to exec.Cmd.

I'll provide an example later of a test that succeeded with go-1.9 but fails with go-1.10.

[kgadams]

Hi,
this is the example that demonstrates the problem.
We read from the StdoutPipe.
Context is canceled after one second.
With go 1.9 Cmd.Wait() returns immediately.
With go 1.10 it waits till C2 (sleep 5) is done.

If you can tell me a way to get the go 1.9 behavior with go 1.10, my problem would be solved.

package cmd_test

import (
	"bufio"
	"context"
	"os/exec"
	"strings"
	"syscall"
	"testing"
	"time"

	"github.com/stretchr/testify/assert"
	"github.com/stretchr/testify/require"
)

func TestCmd(t *testing.T) {
	ctx, cancel := context.WithTimeout(context.Background(), time.Second)
	defer cancel()

	cmd := exec.CommandContext(ctx, "sh", "-c", "echo hello world && sleep 5")
	assert.NotNil(t, cmd)

	stdoutPipe, err := cmd.StdoutPipe()
	assert.Nil(t, err)
	assert.NotNil(t, stdoutPipe)

	start := time.Now()

	err = cmd.Start()
	assert.Nil(t, err)

	var stdout string
	go func() {
		buf := bufio.NewReader(stdoutPipe)
		for {
			line, err := buf.ReadString('\n')
			if len(line) > 0 {
				stdout = stdout + line + "\n"
			}
			if err != nil {
				return
			}
		}
	}()

	err = cmd.Wait()
	d := time.Since(start)

	if err != nil {
		exiterr, ok := err.(*exec.ExitError)
		require.True(t, ok)
		status, ok := exiterr.Sys().(syscall.WaitStatus)
		require.True(t, ok)
		assert.NotEqual(t, 0, status.ExitStatus())
	}
	assert.True(t, strings.HasPrefix(stdout, "hello world"), "Stdout: %v", stdout)

	assert.True(t, d.Seconds() < 3, "Duration was %v", d)
}

[davecheney]

I’m sorry but your program has a data race assigning to the stdout variable which is shared between goroutines. Please run your program with -race to find out more.

…

On 7 Jun 2018, at 17:57, kgadams ***@***.***> wrote: Hi, this is the example that demonstrates the problem. We read from the StdoutPipe. Context is canceled after one second. With go 1.9 Cmd.Wait() returns immediately. With go 1.10 it waits till C2 (sleep 5) is done. If you can tell me a way to get the go 1.9 behavior with go 1.10, my problem would be solved. `package cmd_test import ( "bufio" "context" "os/exec" "strings" "syscall" "testing" "time" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) func TestCmd(t *testing.T) { ctx, cancel := context.WithTimeout(context.Background(), time.Second) defer cancel() cmd := exec.CommandContext(ctx, "sh", "-c", "echo hello world && sleep 5") assert.NotNil(t, cmd) stdoutPipe, err := cmd.StdoutPipe() assert.Nil(t, err) assert.NotNil(t, stdoutPipe) start := time.Now() err = cmd.Start() assert.Nil(t, err) var stdout string go func() { buf := bufio.NewReader(stdoutPipe) for { line, err := buf.ReadString('\n') if len(line) > 0 { stdout = stdout + line + "\n" } if err != nil { return } } }() err = cmd.Wait() d := time.Since(start) if err != nil { exiterr, ok := err.(*exec.ExitError) require.True(t, ok) status, ok := exiterr.Sys().(syscall.WaitStatus) require.True(t, ok) assert.NotEqual(t, 0, status.ExitStatus()) } assert.True(t, strings.HasPrefix(stdout, "hello world"), "Stdout: %v", stdout) assert.True(t, d.Seconds() < 3, "Duration was %v", d) } ` — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub, or mute the thread.

[kgadams]

Ok, thanks for pointing this out.
For me go test -race did not detect the problem. However moving stdout and the assert into the goroutine fixes the race (which was not germane to my problem: Wait() not returning in go 1.10, but in 1.9).

The go routine now looks like this:

go func() {
        var stdout string
        buf := bufio.NewReader(stdoutPipe)
        for {
            line, err := buf.ReadString('\n')
            if len(line) > 0 {
                stdout = stdout + line + "\n"
            }
            if err != nil {
                assert.True(t, strings.HasPrefix(stdout, "hello world"), "Stdout: %v", stdout)
                return
            }
        }
    }()

[kgadams]

Sorry, I did not yet figure out how to correctly insert code blocks here. Any pointers?

[ysmolski]

https://guides.github.com/features/mastering-markdown/

[crvv]

I guess you are talking about #24050, which is a change of go test.
Can you reproduce it without go test?

[kgadams]

Here is the reproduction as a main function with correct markdown :-)
THX @ysmolsky!

Result does not change: works with go 1.9, breaks with go 1.10.

package main

import (
	"bufio"
	"context"
	"fmt"
	"os"
	"os/exec"
	"strings"
	"syscall"
	"time"
)

func fatal(format string, args ...interface{}) {
	fmt.Println(fmt.Sprintf(format, args...))
	os.Exit(1)
}

func main() {
	ctx, cancel := context.WithTimeout(context.Background(), time.Second)
	defer cancel()

	cmd := exec.CommandContext(ctx, "sh", "-c", "echo hello world && sleep 5")
	stdoutPipe, err := cmd.StdoutPipe()
	if err != nil {
		fatal("no pipe: %v", err)
	}
	start := time.Now()

	if err = cmd.Start(); err != nil {
		fatal("start failed: %v", err)
	}

	go func() {
		var stdout string
		buf := bufio.NewReader(stdoutPipe)
		for {
			line, err := buf.ReadString('\n')
			if len(line) > 0 {
				stdout = stdout + line + "\n"
			}
			if err != nil {
				if !strings.HasPrefix(stdout, "hello world") {
					fatal("wrong output: %q", stdout)
				}
				return
			}
		}
	}()

	err = cmd.Wait()
	d := time.Since(start)

	if err != nil {
		exiterr := err.(*exec.ExitError)
		status := exiterr.Sys().(syscall.WaitStatus)
		if status.ExitStatus() == 0 {
			fatal("wrong exit status: %v", status.ExitStatus())
		}
	}

	if d.Seconds() >= 3 {
		fatal("Cancelation took too long: %v", d)
	}
	fmt.Println("Success!")
}

[fraenkel]

I get Success! with 1.10.2 and tip on my Ubuntu laptop.

[gopherbot]

Change https://go.dev/cl/400877 mentions this issue: cmd/go/internal/test: used lockedStdout instead of os.Stdout

[gopherbot]

Change https://go.dev/cl/400877 mentions this issue: cmd/go/internal/test: wrap os.Stdout always

[lixd]

there are some workarounds to use before this proposal implement.

we can kill all child process when context is done.

func main() {
	ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second)
	defer cancel()

	cmd := exec.CommandContext(ctx, "bash","/root/sleep.sh")
	cmd.SysProcAttr = &syscall.SysProcAttr{Setpgid: true}
	doneCh := make(chan struct{}, 1)
	defer func() {
		doneCh <- struct{}{}
		close(doneCh)
	}()
	go func() {
		select {
		case <-ctx.Done():
			err := syscall.Kill(-cmd.Process.Pid, syscall.SIGKILL)
			if err != nil {
				fmt.Printf("kill error   : [%v]\n", err)
				return
			}
			fmt.Printf("run command(%s) timeout,kill all child process\n", cmd.String())
		case <-doneCh:
		}
	}()
	output, err := cmd.CombinedOutput()
	if err != nil {
		fmt.Println(err)
		return
	}

	fmt.Println("output:", string(output))
	fmt.Printf("ctx.Err : [%v]\n", ctx.Err())
	fmt.Printf("error   : [%v]\n", err)
}

or set stdout、stderr use *os.File type to avoid bloking

in this case,when context is done，program will return and child process will run background.

func main() {
	ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second)
	defer cancel()

	cmd := exec.CommandContext(ctx, "bash", sh)
	combinedOutput, err := ioutil.TempFile("", "stdouterr")
	if err != nil {
		fmt.Println(err)
		return
	}
	defer func() { _ = os.Remove(combinedOutput.Name()) }()
	cmd.Stdout = combinedOutput
	cmd.Stderr = combinedOutput
	err = cmd.Run()
	if err != nil {
		fmt.Println(err)
	}
	_, err = combinedOutput.Seek(0, 0)

	var b bytes.Buffer
	_, err = io.Copy(&b, combinedOutput)
	if err != nil {
		fmt.Println(err)
		return
	}
	err = combinedOutput.Close()
	if err != nil {
		fmt.Println(err)
		return
	}
	fmt.Println("output:", b.String())

	fmt.Printf("ctx.Err : [%v]\n", ctx.Err())
	fmt.Printf("error   : [%v]\n", err)
}

[ianlancetaylor]

I'm retracting this proposal in favor of #50436.