testing: tests that panic sometimes log "warning: no tests to run" instead

[dmitshur]

The TestScript/test_exit test in cmd/go failed on the linux-386-longtest builder in https://build.golang.org/log/6f34555f06c618921fe4b9e85fbe1522a1a8078e because a panic wasn't seen:

--- FAIL: TestScript (0.00s)
    --- FAIL: TestScript/test_exit (0.78s)
        script_test.go:211: 
            # Builds and runs test binaries, so skip in short mode. (0.000s)
            # If a test invoked by 'go test' exits with a zero status code,
            # it will panic. (0.777s)
            > ! go test ./zero
            [stdout]
            --- FAIL: TestExitZero (0.00s)
            testing: warning: no tests to run
            FAIL
            FAIL	m/zero	0.024s
            FAIL
            [exit status 1]
            > ! stdout ^ok
            > ! stdout 'exit status'
            > stdout 'panic'
            FAIL: testdata/script/test_exit.txt:11: no match for `(?m)panic` found in stdout
            
FAIL
FAIL	cmd/go	99.358s

The passing behavior for that test is something like:

# If a test invoked by 'go test' exits with a zero status code,
# it will panic. (0.418s)
> ! go test ./zero
[stdout]
--- FAIL: TestExitZero (0.00s)
panic: unexpected call to os.Exit(0) during test [recovered]
panic: unexpected call to os.Exit(0) during test

Another failure on linux-386-longtest builder around 20 commits ago in https://build.golang.org/log/63ec772b8d735f614581991b172dc91b86f64b5c also involved not finding panic in stdout:

--- FAIL: TestScript (0.00s)
    --- FAIL: TestScript/test_cleanup_failnow (0.79s)
        script_test.go:211: 
            # For issue 41355 (0.787s)
            > [short] skip
            > ! go test -v cleanup_failnow/panic_nocleanup_test.go
            [stdout]
            === RUN   TestX
            === RUN   TestX/x
            --- FAIL: TestX (0.00s)
                --- FAIL: TestX/x (0.00s)
            --- FAIL: TestX (0.00s)
            testing: warning: no tests to run
            FAIL
            FAIL	command-line-arguments	0.041s
            FAIL
            [exit status 1]
            > stdout '(?s)panic: die \[recovered\].*panic: die'
            FAIL: testdata/script/test_cleanup_failnow.txt:5: no match for `(?m)(?s)panic: die \[recovered\].*panic: die` found in stdout
            
FAIL
FAIL	cmd/go	86.983s

Not sure if the issue is in cmd/go or the runtime.

/cc @bcmills

[bcmills]

Only those two in the logs. Hrm.

I suspect that this is more likely a bug in the testing package, or in runtime or even cmd/compile, than in cmd/go proper, although without a root cause of course I can't be sure.

2020-09-18T14:36:22-789d77a/linux-386-longtest
2020-09-17T15:51:14-07d5eb0/linux-386-longtest

[bcmills]

The first of these was observed Sept. 17, which isn't too long after CL 254637 (CC @ianlancetaylor @odeke-em @changkun), which changed the panic behavior of the testing package.

[bcmills]

The testing: warning: no tests to run lines in the output are also very suspicious. I suspect that they indicate a race between the panic-propagation code and the test-cleanup code. (Probably the testing package is not waiting for whatever is supposed to propagate the panic to complete.)

Unfortunately, that error string is not unique. It has two possible origins:

go/src/testing/testing.go

Line 1395 in a408139

fmt.Fprintln(os.Stderr, "testing: warning: no tests to run")

go/src/testing/testing.go

Line 1457 in a408139

fmt.Fprintln(os.Stderr, "testing: warning: no tests to run")

[gopherbot]

Change https://golang.org/cl/256098 mentions this issue: testing: send t.signal only if there is no panic

[changkun]

Sorry for making trouble again. I think the bug was indeed introduced in CL 254637.

The reason is CL 254637 sends the t.signal earlier before the panic statement.
Since t.Run calls runtime.Goexit() on panicking tests, if t.Run receives the signal earlier than invoking the panic. The callee runTests may not record the running test, which results in "warning: no tests to run."

I don't have an idea about how to reproduce the bug, but I think my suspicion is reasonable. Thus I just moved the signaling code a few lines down and sent a CL that should fix the bug.

Another option would be to revert the CL 254637, but this choice would lead to #41355 open again.