os/exec: TestContextCancel flaky (on Windows?)

[alexbrainman]

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

go version devel +e6143e1 Mon Sep 26 01:51:31 2016 +0000 windows/386

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

set GOARCH=386
set GOBIN=
set GOEXE=.exe
set GOHOSTARCH=386
set GOHOSTOS=windows
set GOOS=windows
set GOPATH=c:\dev
set GORACE=
set GOROOT=c:\dev\go
set GOTOOLDIR=c:\dev\go\pkg\tool\windows_386
set CC=gcc
set GOGCCFLAGS=-m32 -mthreads -fmessage-length=0 -fdebug-prefix-map=C:\DOCUME1\brainman\LOCALS1\Temp\go-build338345670=/tmp/go-build -gno-record-gcc-switches
set CXX=g++
set CGO_ENABLED=1

What did you do?

I run all.bat.

What did you expect to see?

all.bat run to successful completion.

What did you see instead?

ok      os      2.015s
--- FAIL: TestContextCancel (0.03s)
        exec_test.go:946: program unexpectedly exited successfully
FAIL
FAIL    os/exec 15.669s

This happens only occasionally. I discovered this while working on CL 29700 which makes this test fail more often.

If I understand TestContextCancel correctly, there is an expected race there between goroutine killing process and another goroutine checking that process was killed. And the error above seems like a wrong turn of that race. I don't see how the race can be avoided altogether. Not sure how to fix this. Maybe I am wrong about this.

Alex

[rsc]

FWIW, I looked for exec_test.*program.unexpectedly.exited in all the build failure logs going back to early this year, and I don't see any such failures. I don't doubt that this happened to you, @alexbrainman, but it's interesting it is not happening on the builders.

TestContextCancel starts a subprocess that prints strings from stdin back to stdout. It writes "echo" to the process once. Then it calls cancel() to kill that subprocess, and then it keeps writing "echo" to the subprocess until finally a write fails. It assumes that the write failing means the subprocess has died. Then it closes the pipe it was writing on. All this time there was a goroutine reading the subprocess's standard output and saving it by calling t.Log. The main goroutine waits for that reading goroutine to see EOF (again this should happen because the subprocess died). Now that we're doubly sure that the subprocess died, the main goroutine calls c.Wait. That should report the unsuccessful exit of the subprocess, but in the example you posted it gets nil instead.

I have no idea why CL 29700 (use RtlGenRandom instead of CryptGenRandom) would make this fail more often.

It's true that the actual c.Process.Kill happens asynchronously after cancel returns, but that kill should be what makes the write fail, and we don't do any of the other teardown until after the write fails.

If the write failed for some reason other than the subprocess dying, then closing the writing pipe and waiting for the EOF on the reading side could possibly tear down the subprocess normally. You could imagine adding

diff --git a/src/os/exec/exec_test.go b/src/os/exec/exec_test.go
index b143437..d02051a 100644
--- a/src/os/exec/exec_test.go
+++ b/src/os/exec/exec_test.go
@@ -949,6 +949,7 @@ func TestContextCancel(t *testing.T) {
    start := time.Now()
    for {
        if _, err := io.WriteString(w, "echo"); err != nil {
+           t.Logf("write: %v", err)
            break
        }
        if time.Since(start) > time.Second {

to see exactly what error write gets. However, the read side is logging all the messages it gets back, and in the case of a graceful shutdown it should have gotten back the very first "echo" (sent before the cancel), and in the transcript there is nothing logged by the reading goroutine. This suggests the subprocess really did die, and c.Wait somehow failed to report that fact correctly.

Looking at package os's (*Process).wait, I can't see how that could happen. However, this comment is concerning:

// NOTE(brainman): It seems that sometimes process is not dead
// when WaitForSingleObject returns. But we do not know any
// other way to wait for it. Sleeping for a while seems to do
// the trick sometimes. So we will sleep and smell the roses.
defer time.Sleep(5 * time.Millisecond)
defer p.Release()

It really should not be the case that the process is not dead when WaitForSingleObject returns. On top of that, if the process were not dead, then GetExitCodeProcess would return ec=259 (STILL_ACTIVE), which would end up becoming a non-nil error from c.Wait. But c.Wait returned nil. So probably the process really was dead at least in this case.

On the other hand, if somehow GetExitCodeProcess failed (returned false) but we didn't notice the failure, then maybe ec is uninitialized, so zero, which looks like success.

I notice that runtime.asmstdcall returns a uintptr, which is the whole AX register after the DLL call. I wonder if maybe the functions that return a bool only guarantee to set the bottom 8 bits of that register (just AL), in which case the test r1 == 0 in syscall.GetExitCodeProcess would more properly be uint8(r1) == 0. If the high bits had garbage in them and were not expected to be used, that could manifest as a false "true" result. Whether this happened would probably be highly dependent on the specific code being called and what that code happens to have done or not done with the full AX register.

If you can reproduce the problem on demand, maybe try uint8(r1) in GetExitCodeProcess and see if that changes anything.

Otherwise I'm out of ideas.

[alexbrainman]

I can still reproduce this with +db82cf4:

diff --git a/src/os/exec.go b/src/os/exec.go
index 8a53e5d..148e308 100644
--- a/src/os/exec.go
+++ b/src/os/exec.go
@@ -15,6 +15,8 @@ import (
 // Process stores the information about a process created by StartProcess.
 type Process struct {
    Pid    int
+   Alex   error
+   Alex2  syscall.Rusage
    handle uintptr      // handle is accessed atomically on Windows
    isdone uint32       // process has been successfully waited on, non zero if true
    sigMu  sync.RWMutex // avoid race between wait and signal
diff --git a/src/os/exec/exec_test.go b/src/os/exec/exec_test.go
index 8d44401..b24e357 100644
--- a/src/os/exec/exec_test.go
+++ b/src/os/exec/exec_test.go
@@ -924,11 +924,13 @@ func TestContextCancel(t *testing.T) {

    cancel()

+   var alexerr error
    // Calling cancel should have killed the process, so writes
    // should now fail.  Give the process a little while to die.
    start := time.Now()
    for {
        if _, err := io.WriteString(w, "echo"); err != nil {
+           alexerr = err
            break
        }
        if time.Since(start) > time.Second {
@@ -943,6 +945,10 @@ func TestContextCancel(t *testing.T) {
    <-readDone

    if err := c.Wait(); err == nil {
+       fmt.Printf("c.Process.Alex: %v\n", c.Process.Alex)
+       fmt.Printf("c.Process.Alex2: %+v\n", c.Process.Alex2)
+       fmt.Printf("c.ProcessState: %#v\n", c.ProcessState)
+       fmt.Printf("write: %v\n", alexerr)
        t.Error("program unexpectedly exited successfully")
    } else {
        t.Logf("exit status: %v", err)
diff --git a/src/os/exec_windows.go b/src/os/exec_windows.go
index d89db20..c849e55 100644
--- a/src/os/exec_windows.go
+++ b/src/os/exec_windows.go
@@ -26,6 +26,7 @@ func (p *Process) wait() (ps *ProcessState, err error) {
    }
    var ec uint32
    e = syscall.GetExitCodeProcess(syscall.Handle(handle), &ec)
+   p.Alex = e
    if e != nil {
        return nil, NewSyscallError("GetExitCodeProcess", e)
    }
@@ -34,6 +35,7 @@ func (p *Process) wait() (ps *ProcessState, err error) {
    if e != nil {
        return nil, NewSyscallError("GetProcessTimes", e)
    }
+   p.Alex2 = u
    p.setDone()
    // NOTE(brainman): It seems that sometimes process is not dead
    // when WaitForSingleObject returns. But we do not know any

occasionally, if I run test in a loop:

go test -v -i && for /l %x in (1, 1, 100) do go test -short os/exec

...
C:\dev\go\src\os\exec>go test -short
c.Process.Alex: <nil>
c.Process.Alex2: {CreationTime:{LowDateTime:38306894 HighDateTime:30552088} ExitTime:{LowDateTime:38306894 HighDateTime:30552088} KernelTime:{LowDateTime:0 HighDateTime:0} UserTime:{LowDateTime:0 HighDateTime:0}}
c.ProcessState: &os.ProcessState{pid:1732, status:syscall.WaitStatus{ExitCode:0x0}, rusage:(*syscall.Rusage)(0x1102ca80)}
write: write |1: The pipe is being closed.
--- FAIL: TestContextCancel (0.00s)
        exec_test.go:952: program unexpectedly exited successfully
FAIL
exit status 1
FAIL    os/exec 4.422s

C:\dev\go\src\os\exec>go test -short
c.Process.Alex: <nil>
c.Process.Alex2: {CreationTime:{LowDateTime:91900987 HighDateTime:30552088} ExitTime:{LowDateTime:91900987 HighDateTime:30552088} KernelTime:{LowDateTime:0 HighDateTime:0} UserTime:{LowDateTime:0 HighDateTime:0}}
c.ProcessState: &os.ProcessState{pid:5976, status:syscall.WaitStatus{ExitCode:0x0}, rusage:(*syscall.Rusage)(0x10fdc580)}
write: write |1: The pipe is being closed.
--- FAIL: TestContextCancel (0.00s)
        exec_test.go:952: program unexpectedly exited successfully
FAIL
exit status 1
FAIL    os/exec 4.109s

C:\dev\go\src\os\exec>go test -short
...

I do not buy your GetExitCodeProcess return code theory. GetExitCodeProcess returns BOOL, and BOOL is C int

typedef int BOOL;

https://msdn.microsoft.com/en-us/library/windows/desktop/aa383751(v=vs.85).aspx
so it should be the same as uintptr.

And if I start using uint8(r1) == 0 in syscall.GetExitCodeProcess the test still fails for me.

Alex

[bradfitz]

This has been happening pretty regularly on our new Windows XP builders, @rsc.

https://build.golang.org/log/929cb405f2485a5071853e9912feb3ddcec91ab1
https://build.golang.org/log/add46db4ba87885622dcd34ca43654b086717e75
https://build.golang.org/log/2384b6530461bbf2363241f2b6e47fea5fe4ab2e
etc

Also, very similar:
https://build.golang.org/log/c808dfad032954fa1936cbfa6e0aa2a8aec41fd5

And with both:
https://build.golang.org/log/499976e810d424df182331b25db509c3f66d004a