Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

testing: Example test with runtime.Goexit hangs #41084

Closed
prashantv opened this issue Aug 28, 2020 · 13 comments
Closed

testing: Example test with runtime.Goexit hangs #41084

prashantv opened this issue Aug 28, 2020 · 13 comments
Labels
FrozenDueToAge help wanted NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone

Comments

@prashantv
Copy link
Contributor

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

@go101
Copy link

go101 commented Aug 28, 2020

Is it the documented behavior?

@cagedmantis cagedmantis changed the title testing: Example test with runtime.Goexit hangs runtime: Example test with runtime.Goexit hangs Aug 28, 2020
@odeke-em
Copy link
Member

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
Copy link
Contributor Author

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
Copy link
Member

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

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
Copy link
Contributor Author

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,

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
Copy link
Member

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.

@odeke-em odeke-em reopened this Aug 29, 2020
@cagedmantis cagedmantis changed the title runtime: Example test with runtime.Goexit hangs testing: Example test with runtime.Goexit hangs Aug 30, 2020
@cagedmantis cagedmantis added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Aug 30, 2020
@cagedmantis cagedmantis added this to the Backlog milestone Aug 30, 2020
@cagedmantis
Copy link
Contributor

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

@cagedmantis
Copy link
Contributor

/cc @mpvl

@bcmills
Copy link
Contributor

bcmills commented Aug 31, 2020

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
Copy link
Member

@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
Copy link
Contributor

bcmills commented Aug 31, 2020

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
Copy link
Member

@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
Copy link

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

@golang golang locked and limited conversation to collaborators Sep 1, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
FrozenDueToAge help wanted NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Development

No branches or pull requests

7 participants