testing: "panic: Log in goroutine after Test..." is unreliable due to lack of synchronization on t.done #67701
Labels
NeedsInvestigation
Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone
Go version
go1.22.3 darwin/arm64
Output of
go env
in your module/workspace:What did you do?
Despite clearly logging after the test has completed, this test does not reliably fail, depending on other code in the test and elsewhere. And when it does not fail,
t.Logf("too late")
is silently not logged anywhere.This is hard to reliably reproduce, but the cause is fairly straightforward: whether it logs or panics is determined by checking
t.done
inside the test's mutex, butt.done
is changed outside the mutex, so that value change may not propagate to the goroutine that produces the faulty log.Forcing a happens-after relationship reliably causes failure:
As much as I am fond of this race-detecting trick, and appreciate the issues it catches:
https://github.com/golang/go/blob/master/src/testing/testing.go#L1675-L1677
I feel like this log-failure-flakiness is an unintended consequence. Maybe the race-detecting access could be moved to a different field, rather than one that has a rather significant impact on behavior?
It's also strange to me that this doesn't seem to be (reliably) catching this race - is that happening inside
t.checkRaces()
, so this all races later than the check? I'm not familiar with this part of race-detection: https://github.com/golang/go/blob/master/src/testing/testing.go#L1548C1-L1549C1What did you see happen?
Tests pass and the too-late log is not caught nor is its output sent to stdout/stderr.
What did you expect to see?
should be produced reliably, as long as the test clearly finishes before the log occurs (as seen from a real-world observer, i.e. me). And it should not require outside-of-test synchronization to behave reliably.
Proof-of-concept fix
#67796
The text was updated successfully, but these errors were encountered: