os/exec: panic after execute Start

[ayanamist]

Please answer these questions before submitting your issue. Thanks!

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

go version go1.7.5 linux/amd64

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

GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH=""
GORACE=""
GOROOT="/usr/local/go"
GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
CC="gcc"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build059832473=/tmp/go-build -gno-record-gcc-switches"
CXX="g++"
CGO_ENABLED="1"

What did you do?

        cmd := exec.Command("some command")
	cmd.Stderr = ioutil.Discard
	stdout, err := cmd.StdoutPipe()
	if err != nil {
		return "", "", err
	}
	if err := cmd.Start(); err != nil {  // main.go:186
		if cmd.Process != nil {
			cmd.Process.Kill()
		}
		return "", "", err
	}
        .......

func panicRecoverWrap(f func()) func() {
	return func() {
		defer func() {
			if err := recover(); err != nil {
				log.Printf("panic %v: %s", err, debug.Stack()) // util.go:28
			}
		}()
		f()
	}
}

What did you expect to see?

Code execute without panic, maybe some errors

What did you see instead?

2017/04/11 08:00:41.089750 util.go:28: panic runtime error: invalid memory address or nil pointer dereference: goroutine 137 [running]:
runtime/debug.Stack(0xc42004f8c8, 0x67aa60, 0xc42000c100)
        /usr/local/go/src/runtime/debug/stack.go:24 +0x79
main.panicRecoverWrap.func1.1()
        /home/foobar/.GOPATH/src/foobar/util.go:28 +0x76
panic(0x67aa60, 0xc42000c100)
        /usr/local/go/src/runtime/panic.go:458 +0x243
runtime.SetFinalizer(0x676c40, 0xc42000e420, 0x0, 0x0)
        /usr/local/go/src/runtime/mfinal.go:303 +0x84
os.(*file).close(0xc42000e420, 0x6cd67f, 0x1e)
        /usr/local/go/src/os/file_unix.go:146 +0xe0
os.(*File).Close(0xc42003c9a8, 0xc42004fcc0, 0xc420124630)
        /usr/local/go/src/os/file_unix.go:132 +0x33
os/exec.(*Cmd).closeDescriptors(0xc42009e580, 0xc4200c4bc0, 0x3, 0x4)
        /usr/local/go/src/os/exec/exec.go:262 +0x49
os/exec.(*Cmd).Start(0xc42009e580, 0x7e3820, 0xc42003c9a0)
        /usr/local/go/src/os/exec/exec.go:365 +0x442
created by main.main.func3
        /home/foobar/.GOPATH/src/foobar/main.go:186 +0x1cc

[odeke-em]

@ayanamist would you mind posting a full/complete program, say in a playground snippet that can
be re-runnable by anyone?
Currently your code snippet doesn't match up with the execution lines in the crash report,
so it is hard to traceback to what tripped out.
Thanks.

[ayanamist]

@odeke-em I have modified the description to add pointed line number in the line comment.
The full program is very complicated, but above provided code has been running for months without panic and i don't use any unsafe package methods and any third party package.
The original program restarts after panic and running well now, and at the same time it runs the same code provided above every 5 minutes on other thousands machines.
I think it maybe related with some race conditions?

[davecheney]

Have you built and run a version of this program using the race detector?

…

On Tue, 11 Apr 2017, 11:21 ayanamist ***@***.***> wrote: @odeke-em <https://github.com/odeke-em> I have modified the description to add pointed line number in the line comment. The full program is very complicated, but above provided code has been running for months without panic and i don't use any unsafe package methods and any third party package. The original program restarts after panic and running well now, and at the same time it runs the same code provided above every 5 minutes on other thousands machines. I think it maybe related with some race conditions? — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub <#19918 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAAcA5a3ABkCGO-QCZY_Hxl1mAv05ew1ks5rutWrgaJpZM4M5fxm> .

[ayanamist]

@davecheney I add -race after found this issue, but runs for hour but got nothing.
I think the race condition occurs in runtime but not my program, because the code provided shows that, after constructing a os.Command object, i call Start immediately within the same method.

[davecheney]

Can you please provide the output from the race detector that shows the error occurs in the runtime. Thank you.

…

On 11 Apr 2017, at 11:42, ayanamist ***@***.***> wrote: @davecheney I add -race after found this issue, but runs for hour but got nothing. I think the race condition occurs in runtime but not my program, because the code provided shows that, after constructing a os.Command object, i call Start immediately within the same method. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or mute the thread.

[ayanamist]

@davecheney I mentioned above that i got nothing after enabled -race. I suspect race occurs in runtime because i don't use unsafe to manipulate anything and i don't use any third party library, and the exec.Command object does not escape out of the same method.

[davecheney]

If there is a data race in the runtime package, the race detector will spot it.

…

On Tue, Apr 11, 2017 at 12:31 PM, ayanamist ***@***.***> wrote: @davecheney <https://github.com/davecheney> I mentioned above that i got nothing after enabled -race. I suspect race occurs in runtime because i don't use unsafe to manipulate anything and i don't use any third party library, and the object does not escape out of the same method. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#19918 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAAcAxiAB5m9FUNHmlL0GdAWf3635aRKks5ruuYCgaJpZM4M5fxm> .

[ayanamist]

@davecheney So i have no idea why it panics on runtime.SetFinalizer

[davecheney]

Is your source code available? Can you please provide a runnable code sample that will let others try to reproduce and debug the issue.

[ayanamist]

@davecheney Sorry but source code is not available, and even i attach it, i think it won't reproduce. The same code has been running for months on thousands machines, and even it panics this morning, after restart it runs well until now.

[bradfitz]

For questions about Go, see https://golang.org/wiki/Questions.

[ayanamist]

@bradfitz Why this issue closed? I'm reporting a panic happening in runtime.SetFinalizer but not consulting for any golang usage.

[odeke-em]

@ayanamist unfortunately your report as is isn't self contained/reproducible.
@davecheney and I have both asked for a complete program in our comments. Currently with the above content, it looks like more like a question for the Go help sites than a bug report with actionable items for contributors to look at.

Perhaps to help move up its status, here are some points that might be useful:

1. What is "some-command"?
2. stdout in your snippet is created but not used, anything related to that?
3. Here is a sample complete snippet as the template encourages https://play.golang.org/p/JnGVQ8Xyr3 or

package main

import (
	"fmt"
	"io/ioutil"
	"os/exec"
)

func execIt() error {
	cmd := exec.Command("echo")
	cmd.Stderr = ioutil.Discard
	if _, err := cmd.StdoutPipe(); err != nil {
		return err
	}
	if err := cmd.Start(); err != nil {
		if cmd.Process != nil {
			cmd.Process.Kill()
		}
		return err
	}
	return cmd.Wait()
}

func main() {
	fmt.Printf("err: %v\n", execIt())
}

hope that looks similar to what you are doing
4) What is the nature of the code being ran? How heavily is the code used? I see your stack trace points to the use of SetFinalizer which for go1.7.5 is at https://github.com/golang/go/blob/release-branch.go1.7/src/runtime/mfinal.go#L303. Maybe that might help.

[ayanamist]

1. some-command is not part of my code, and i think it will not interfere with my program memory.
2. 3. More codes here

func func3() (boolean, error) {
	foundSomething := false
	cmd := exec.Command("echo", "foobar")
	cmd.Stderr = ioutil.Discard
	stdout, err := cmd.StdoutPipe()
	if err != nil {
		return foundSomething, err
	}
	if err := cmd.Start(); err != nil {  // main.go:186
		if cmd.Process != nil {
			cmd.Process.Kill()
		}
		return foundSomething, err
	}
	go func() {
		time.Sleep(5 * time.Second)
		cmd.Process.Kill()
	}()
	scanner := bufio.NewScanner(stdout)
	for scanner.Scan() {
		line := scanner.Text()
		i := strings.Index(line, ":")
		if i < 0 {
			continue
		}
		if strings.Contains(line, "foo") {
			foundSomething = true
		}
	}
	err = cmd.Wait()
	return foundSomething, err
}

4. Every 5 minutes run this code in a single goroutine, and runtime.SetFinalizer is used directly by os.exec package but not my code.