testing: Example test with runtime.Goexit hangs

[prashantv]

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

$ go version
go version go1.15 linux/amd64

(Also verified on 1.14 on both linux and darwin)

Does this issue reproduce with the latest release?

Yes

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

go env Output

$ go env
GO111MODULE="on"
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/user/.cache/go-build"
GOENV="/home/user/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/opt/go/path/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/opt/go/path"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/home/user/.gimme/versions/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/home/user/.gimme/versions/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/home/user/go-test/go.mod"
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-build701379955=/tmp/go-build -gno-record-gcc-switches"

What did you do?

Used runtime.Goexit in an example test from the main test goroutine.

package main

import "runtime"

func ExampleGoexit() {
        runtime.Goexit()
        // Output:
}

What did you expect to see?

A failure, similar to when runtime.Goexit is used in a test,

package main

import "runtime"
import "testing"

func TestGoexit(t *testing.T) {
        runtime.Goexit()
}

> go test -v -run Test
=== RUN   TestGoexit
--- FAIL: TestGoexit (0.00s)
panic: test executed panic(nil) or runtime.Goexit
[...]

What did you see instead?

The example test hangs (until the test timeout is hit):

> go test -v -run Example -timeout 10s
=== RUN   ExampleGoexit
--- PASS: ExampleGoexit (0.00s)
panic: test timed out after 10s

goroutine 8 [running]:
testing.(*M).startAlarm.func1()
	[...]/go/src/testing/testing.go:1609 +0xe5
created by time.goFunc
	[...]/go/src/time/sleep.go:167 +0x45
exit status 2
FAIL	goexit_test	10.008s

I can send a SIGQUIT to get the backtrace:

=== RUN   ExampleGoexit
--- PASS: ExampleGoexit (0.00s)
^\SIGQUIT: quit
PC=0x7fff6a9c4766 m=0 sigcode=0

goroutine 0 [idle]:
runtime.kevent(0x7ffe00000003, 0x0, 0x0, 0x7ffeefbfece8, 0x40, 0x7ffeefbfecc0, 0x0)
        /usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/sys_darwin.go:355 +0x39
runtime.netpoll(0x25408e43c, 0xadf60b77b01)
        /usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/netpoll_kqueue.go:120 +0xae
runtime.findrunnable(0xc000026800, 0x0)
        /usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/proc.go:2323 +0x72b
runtime.schedule()
        /usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/proc.go:2520 +0x2fc
runtime.park_m(0xc000000180)
        /usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/proc.go:2690 +0x9d
runtime.mcall(0x105f4a6)
        /usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/asm_amd64.s:318 +0x5b

In the Go playground, this triggers a deadlock:
https://play.golang.org/p/xaSFhxBPeKB

[zigo101]

Is it the documented behavior?

[odeke-em]

Thank you for filing this @prashantv, and thank you @go101 for responding to @prashantv’s question. Indeed as @go101 points out, that is the behavior of Goexit(), and in the main test code, there are other goroutines running in the background and as documented it can’t return until all the other goroutines have. I shall close this issue, but thank you again.

[prashantv]

Hi @odeke-em, I think this is a testing package issue, since TestGoexit works correctly (as I documented in my issue), while ExampleGoexit hangs. Shouldn't they both behave in the same way?

The Goexit function is expected to end the goroutine, but the testing package handles this correctly for TestX functions, but not for ExampleX functions.

[odeke-em]

@prashantv there are other goroutines running for Example as I had mentioned and for example if you see the implementation in

go/src/testing/run_example.go

Line 21 in 4fc3896

func runExample(eg InternalExample) (ok bool) {

by you invoking runtime.Goexit() you are killing that goroutine in its main without ever returning yet there are other goroutines that haven't yet been terminated and are waiting for output. This is an implementation detail about Example tests that I don't think needs to be changed.

You can validate that the goroutines are running by printing the stack of the entire system like this

package main

import (
        "runtime"
)

func ExampleGoexit() {
        buf := make([]byte, 1024)
        for {
            n := runtime.Stack(buf, true)
            if n < len(buf) {
                break
            }
            buf = make([]byte, 2*len(buf))
        }
        println(string(buf))
        runtime.Goexit()
        // Output:
}

which will produce

$ go test
goroutine 1 [running]:
github.com/odeke-em/bugs/golang/41084.ExampleGoexit()
	/Users/emmanuelodeke/Desktop/openSrc/bugs/golang/41084/example_test.go:10 +0x9f
testing.runExample(0x1140b3b, 0xd, 0x1148c80, 0x0, 0x0, 0x0, 0x0)
	/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/testing/run_example.go:62 +0x209
testing.runExamples(0xc00009ce80, 0x12149c0, 0x1, 0x1, 0xbfcacc4fada05fc8)
	/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/testing/example.go:44 +0x1af
testing.(*M).Run(0xc0000cc000, 0x0)
	/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/testing/testing.go:1354 +0x2cd
github.com/odeke-em/bugs/golang/41084.TestMain(...)
	/Users/emmanuelodeke/Desktop/openSrc/bugs/golang/41084/it_test.go:8
main.main()
	_testmain.go:45 +0x165

goroutine 19 [runnable]:
syscall.syscall(0x1076d00, 0x6, 0xc000102000, 0x8000, 0xffffffffffffffff, 0xffffffffffffffff, 0x23)
	/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/runtime/sys_darwin.go:63 +0x2e
syscall.read(0x6, 0xc000102000, 0x8000, 0x8000, 0x1208840, 0x1723fd8, 0x100a3bf)
	/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/syscall/zsyscall_darwin_amd64.go:1242 +0x66
syscall.Read(0x6, 0xc000102000, 0x8000, 0x8000, 0x72, 0x0, 0x0)
	/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/syscall/syscall_unix.go:187 +0x49
internal/poll.ignoringEINTRIO(0x11492d0, 0x6, 0xc000102000, 0x8000, 0x8000, 0x1723fd8, 0x1106d01, 0x10100000111eb80)
	/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/internal/poll/fd_unix.go:563 +0x52
internal/poll.(*FD).Read(0xc0000a41e0, 0xc000102000, 0x8000, 0x8000, 0x0, 0x0, 0x0)
	/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/internal/poll/fd_unix.go:155 +0x149
os.(*File).read(...)
	/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/os/file_posix.go:31
os.(*File).Read(0xc0000a2030, 0xc000102000, 0x8000, 0x8000, 0x0, 0xc000040700, 0x100645d)
	/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/os/file.go:116 +0x71
io.copyBuffer(0x11694b8, 0xc000100000, 0x11693d8, 0xc0000a2030, 0xc000102000, 0x8000, 0x8000, 0xc00008c120, 0xc0000407a8, 0x1005eab)
	/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/io/io.go:409 +0x12c
io.Copy(...)
	/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/io/io.go:368
testing.runExample.func1(0xc0000a2030, 0xc00008c1e0)
	/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/testing/run_example.go:37 +0x85
created by testing.runExample
	/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/testing/run_example.go:35 +0x176

and you'll see the goroutine that's still waiting in there.

[prashantv]

I understand why it's hanging, but it doesn't hang for TestX functions, since there's explicit logic to detect and handle this case,

go/src/testing/testing.go

Line 1069 in 4fc3896

err = errNilPanicOrGoexit

This logic doesn't exist for example tests, and so it hangs, which doesn't seem ideal. It seems beneficial to users to detect a runtime.Goexit or panic(nil) in an example test the same way as a TestX function, and in general for consistency.

Perhaps I'm missing a reason for why Example tests should not have consistent behaviour with standard test functions, I thought it might have just been overlooked.

[odeke-em]

Thank you for the follow-up question @prashantv, you raise a great concern which I don't have an answer to off the top of my head, thus I shall re-open this for investigation and other comments.

[cagedmantis]

@prashantv I misunderstood the issue and incorrectly renamed it with the runtime package. It's been corrected.

[cagedmantis]

/cc @mpvl

[bcmills]

In theory we could run each Example function in its own goroutine, and move the output-checking to a defer statement so that it can trigger even in case of a Goexit.

That said, use of runtime.Goexit outside of the testing package itself should be rare enough that I'm not sure this is worth the risk of the refactoring. (If someone wants to contribute a fix, we can see just how invasive it is and decide at that point.)

[changkun]

@bcmills I don't know refactoring to run Example in its own goroutine is the planned approach. But the current examples are executed sequentially, it seems that I can send a simple CL to fix what was reported originally. Should I do that?

[bcmills]

If the examples are executed sequentially on the same goroutine, then a runtime.Goexit in an Example is always wrong. A change to panic in that case instead of deadlocking seems like it would be fine, but it still wouldn't let you safely write that ExampleGoexit function.

[changkun]

@bcmills Thanks for the quick response. What's the behavior to safely write ExampleGoexit? I thought the bug report is expecting to fail the ExampleGoexit and panicking on errNilPanicOrGoexit whereas the current behavior is getting a PASS on ExampleGoexit with a long pause.

[gopherbot]

Change https://golang.org/cl/251857 mentions this issue: testing: fail Example tests that involves runtime.Goexit