os/exec: document that you must call Wait before accessing copied output

[HouzuoGuo]

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

go version go1.10 linux/amd64

Does this issue reproduce with the latest release?

The bug does not appear in 1.9.4, therefore it seems to be a regression in 1.10.

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

GOARCH="amd64"
GOBIN=""
GOCACHE="/home/howard/.cache/go-build"
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/howard/gopath"
GORACE=""
GOROOT="/home/howard/go"
GOTMPDIR=""
GOTOOLDIR="/home/howard/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
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-build479455967=/tmp/go-build -gno-record-gcc-switches"

What did you do?

Run the following piece of code:

package main

import (
	"os/exec"
	"bytes"
	"time"
	"fmt"
)

func main() {
	c := exec.Command("/bin/bash", "-c", "echo abc && sleep 10")
	var outBuf bytes.Buffer
	c.Stdout = &outBuf

	if err := c.Start(); err != nil {
		panic(err)
	}

	time.Sleep(3 * time.Second)
	if err := c.Process.Kill(); err != nil {
		panic(err)
	}

	fmt.Println(outBuf.Bytes())
}

Using previous go 1.9.4, the output correctly shows individual bytes in string abc\n:

[97 98 99 10] 

However, using go 1.10, the output shows:

[97 98 99 10 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]

Oddly, if the bash command does not say && sleep 10, which means the bash program exits normally before it is killed, both 1.10 and 1.9.4 will collect the correct output [97 98 99 10].

This is potentially a regression in 1.10.

[agnivade]

I can confirm that the repro works in my machine.

It has something to do with killing the process after it has written to the buffer. This program gives correct output in both 1.10 and 1.9.

package main

import (
  "os/exec"
  "bytes"
  "fmt"
)

func main() {
  c := exec.Command("/bin/bash", "-c", "echo abc && sleep 10")
  var outBuf bytes.Buffer
  c.Stdout = &outBuf

  if err := c.Start(); err != nil {
    panic(err)
  }

  if err := c.Wait(); err != nil {
   panic(err)
  }
  
  fmt.Println(outBuf.Bytes())
}

[ianlancetaylor]

This program has a data race, which you will see if you run it under the race detector. As @agnivade suggests, the problem is that you are accessing the output buffer before calling Wait. This means that you are accessing the buffer while the goroutine copying stdout is also accessing it. The fix is to call Wait.

I don't think there is a bug in the code, but I don't see anything in the documentation that clarifies that you need to call Wait before accessing the buffer. I will repurpose this issue to be to improve the docs.

[HouzuoGuo]

Thanks Ian. Does that mean when Kill() function returns, the process may still be alive for a short moment? Otherwise, would it be more intuitive to let Kill() automatically call Wait() internally?

[agnivade]

The issue is that you are using bash to start new processes - echo and sleep. When you kill the process, the underlying sleep does not exit (I just tested it). Hence, the race.

Call Wait() after Kill().

package main

import (
	"bytes"
	"fmt"
	"os/exec"
	"time"
)

func main() {
	c := exec.Command("/bin/bash", "-c", "echo abc && sleep 10")
	var outBuf bytes.Buffer
	c.Stdout = &outBuf

	if err := c.Start(); err != nil {
		panic(err)
	}

	time.Sleep(3 * time.Second)
	if err := c.Process.Kill(); err != nil {
		panic(err)
	}
	if err := c.Wait(); err != nil {
		if _, ok := err.(*exec.ExitError); !ok {
			panic(err)
		}
	}

	fmt.Println(outBuf.Bytes())
}

[HouzuoGuo]

@agnivade are you suggesting that there is no way to kill a process and immediately collect program output generated up to that moment?

[HouzuoGuo]

Ah I see, it's just normal process behaviour for sleep process to continue running. Do you by any chance have a workaround for reliable killing of an entire tree of processes in go?

[ianlancetaylor]

The "waiting for a tree of processes" problem is #23019. We don't have any approach to "killing a tree of processes" although of course you can put them in a new process group and use Kill with the negative process group ID (see the Setpgid field of syscall.SysProcAttrandman 2 kill`).

We should not have Kill call Wait, as Kill does not always succeed.

[HouzuoGuo]

Many thanks & have a lovely weekend!

[gopherbot]

Change https://golang.org/cl/98395 mentions this issue: os/exec: add an extra note on Wait

[ysmolski]

@ianlancetaylor, I examined the related tickets. The common theme is that programmers do not see from documentation what Process.Kill does. What if we add to Process.Kill this:

// Kill causes the Process to exit immediately. Kill does not wait until the Process has 
// actually exited. If the process has subprocesses, they are not caused to exit. 

Also, Process.Kill does not explain to programmers that Kill sends the roughest signal to end the process and it cannot be caught in the process, thus Process cannot propagate SIGHUP or SIGTERM to child subprocesses. But I don't know if we can introduce such details into go Process type b/c they are actually relevant to unices mostly.

[ianlancetaylor]

Your suggested text sounds good to me.

I agree that I would rather not get into details about signals. People who understand those issues can use the Signal method.

[gopherbot]

Change https://golang.org/cl/98715 mentions this issue: os/exec: document Process.Kill behaviour