os/exec: exec.Cmd fails to cancel with non-*os.File outputs on linux

[jbardin]

go1.7, go1.8rc3

When using a Context to cancel an exec.Cmd, if either of the outputs are an io.Writer which isn't an *os.File the command will fail to terminate.

The following panics on amd64 linux

	ctx, cancel := context.WithCancel(context.Background())
	cmd := exec.CommandContext(ctx, "/bin/sh", "-c", "sleep 60")

	var output bytes.Buffer
	cmd.Stdout = &output

	cmd.Start()
	log.Println("started command")

	done := make(chan error)
	go func() {
		done <- cmd.Wait()
	}()

	time.Sleep(50 * time.Millisecond)
	log.Println("canceling command")
	cancel()

	select {
	case err := <-done:
		log.Println("done:", err)
	case <-time.After(time.Second):
		panic("failed to cancel")

The full stack trace is:

main.main()
	/home/user/command_context.go:35 +0x499

goroutine 5 [syscall]:
syscall.Syscall(0x0, 0x4, 0xc420092000, 0x200, 0x7f15a35f4000, 0x19, 0xc420092000)
	/usr/local/go/src/syscall/asm_linux_amd64.s:18 +0x5
syscall.read(0x4, 0xc420092000, 0x200, 0x200, 0xc420026400, 0x7f15a35f4000, 0x0)
	/usr/local/go/src/syscall/zsyscall_linux_amd64.go:783 +0x55
syscall.Read(0x4, 0xc420092000, 0x200, 0x200, 0x425b5f, 0x4dd550, 0xc420023dc0)
	/usr/local/go/src/syscall/syscall_unix.go:162 +0x49
os.(*File).read(0xc42000c038, 0xc420092000, 0x200, 0x200, 0x4602ab, 0x4b38e0, 0x200)
	/usr/local/go/src/os/file_unix.go:165 +0x4f
os.(*File).Read(0xc42000c038, 0xc420092000, 0x200, 0x200, 0x0, 0x7f15a3598028, 0xc420023e60)
	/usr/local/go/src/os/file.go:101 +0x76
bytes.(*Buffer).ReadFrom(0xc420048070, 0x5381e0, 0xc42000c038, 0x7f15a3598028, 0xc420048070, 0x1)
	/usr/local/go/src/bytes/buffer.go:179 +0x160
io.copyBuffer(0x538120, 0xc420048070, 0x5381e0, 0xc42000c038, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
	/usr/local/go/src/io/io.go:384 +0x2cb
io.Copy(0x538120, 0xc420048070, 0x5381e0, 0xc42000c038, 0x0, 0x0, 0x0)
	/usr/local/go/src/io/io.go:360 +0x68
os/exec.(*Cmd).writerDescriptor.func1(0x0, 0x0)
	/usr/local/go/src/os/exec/exec.go:254 +0x4d
os/exec.(*Cmd).Start.func1(0xc42007e000, 0xc42000a2a0)
	/usr/local/go/src/os/exec/exec.go:371 +0x27
created by os/exec.(*Cmd).Start
	/usr/local/go/src/os/exec/exec.go:372 +0x4e4

goroutine 7 [chan receive]:
os/exec.(*Cmd).Wait(0xc42007e000, 0x0, 0x0)
	/usr/local/go/src/os/exec/exec.go:443 +0x118
main.main.func1(0xc4200681e0, 0xc42007e000)
	/home/user/command_context.go:24 +0x2b
created by main.main
	/home/user/command_context.go:25 +0x1eb
exit status 2

[jbardin]

I initially thought that this was caused by Context cancelation, but it turns out to be the same when directly killing the process.

This also hangs/panics

	cmd := exec.Command("/bin/sh", "-c", "sleep 60")
	var output bytes.Buffer
	cmd.Stdout = &output
	cmd.Start()
	log.Println("started command")

	done := make(chan error)
	go func() {
		done <- cmd.Wait()
	}()

	time.Sleep(50 * time.Millisecond)
	log.Println("killing command")
	cmd.Process.Kill()

	select {
	case err := <-done:
		log.Println("done:", err)
	case <-time.After(5 * time.Second):
		panic("failed to cancel")
	}

A second call to wait rightly returns Wait was already called and fails the race detector.

[ianlancetaylor]

It seems to work fine for me. Both programs end immediately with done: signal: killed. I'm on GNU/Linux, Ubuntu Trusty. I checked both Go 1.7 and Go 1.8rc3.

Can you post a complete program, and post the output of the program? Thanks.

[dsnet]

I reproduce the problem on:

$ cat /etc/issue
Linux Mint 17.1 Rebecca \n \l
$ uname -a
Linux carbonite 3.13.0-37-generic #64-Ubuntu SMP Mon Sep 22 21:28:38 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux
$ go version
go version go1.7.4 linux/amd64

[ianlancetaylor]

@dsnet Can you attach your complete program?

[dsnet]

It is quite literally the program from the original post: https://play.golang.org/p/ovO_hVDW49

Interestingly, I'm not able to repro the issue on my work computer.

[ianlancetaylor]

Interesting. I've now tried that program on three different GNU/Linux distros, kernel versions 2.6.32, 2.6.35, 4.2.0. For me it always completes immediately.

@jbardin Tell us more about the system you are running.

[ianlancetaylor]

When the context is cancelled we kill the child process, in this case /bin/sh, with SIGKILL. We don't kill the whole process group, just the immediate child. Depending on which shell you are using, that won't necessarily kill the child process running sleep 60. If the child process does not die, and if sleep does not close its standard output, then the Go program will hang waiting to copy the child process's standard output into the buffer.

I'm not even sure this is wrong.

[silviucm]

If it helps in any way:

Does Panic:
Intel NUC Intel(R) Core(TM) i5-6260U (panics)
Linux medianuc 4.9.3-040903-generic #201701120631 SMP Thu Jan 12 11:33:59 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux
$ cat /etc/issue -> Linux Mint 18 Sarah

Does Panic:
Dell Desktop Intel(R) Core(TM) i7-4790 (panics)
Linux silviu-desktop 4.4.0-59-generic #80-Ubuntu SMP Fri Jan 6 17:47:47 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux
$ cat /etc/issue -> Linux Mint 18 Sarah

Does NOT Panic:
Odroid XU4 - ARMv7 Processor rev 3 (v7l)
Linux odroid 3.10.104-4-ARCH #1 SMP PREEMPT Sun Jan 1 18:12:52 MST 2017 armv7l GNU/Linux
$ cat /etc/issue -> Arch Linux

[jbardin]

I think I see the difference, I bet all the systems where this fails have /bin/sh linked to /bin/dash.

I'm also note sure what the correct behavior is now, but dash is the only common shell I can find that does this.

[silviucm]

confirming the only system where it does not panic is not dash:

ll -a /bin/sh
lrwxrwxrwx 1 root root 4 Jan 25 14:58 /bin/sh -> bash

[ianlancetaylor]

I'm inclined to close this as working as expected. You are asking for the processes's standard output to be collected. That means that the Wait method will block until the process closes its standard output. In the case that fails, the child process still has standard output open. If you want something else to happen, you need to ensure that you kill not just the child, but any other process it starts that may keep standard output open.

[evverx]

@ianlancetaylor , I think this is a documentation bug: Wait and context don't work well together.

The problem is

If c.Stdin is not an *os.File, Wait also waits for the I/O loop copying from
c.Stdin into the process's standard input to complete.

Consider this example:

package main

import (
        "context"
        "fmt"
        "io"
        "os/exec"
        "time"
)

type Hanger time.Duration

func (h Hanger) Read(b []byte) (int, error) {
        time.Sleep(time.Duration(h))
        return 0, io.EOF
}

func main() {
        ctx, _ := context.WithTimeout(context.Background(), 5*time.Second)
        cmd := exec.CommandContext(ctx, "/bin/sh", "-c", "sleep 7")
        cmd.Stdin = Hanger(10 * time.Second)
        cmd.Start()
        now := time.Now()
        go func() {
                <-ctx.Done()
                fmt.Printf("context: %v\n", time.Since(now))
        }()
        cmd.Wait()
        fmt.Printf("wait: %v\n", time.Since(now))
}

This prints

context: 4.999701339s
wait: 10.001522024s