-
Notifications
You must be signed in to change notification settings - Fork 18k
testing: loses log messages made in a goroutine after test has completed #30389
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
Comments
Hey, I tried investigating and wrote a test and modifying various places in I might be naively making a mistake here but I guess after the func TestLateLogWrapper(t *testing.T) {
testenv.MustHaveGoBuild(t)
tempDir, err := ioutil.TempDir("", "issue-30389")
if err != nil {
t.Fatalf("Failed to create temp directory: %v", err)
}
defer os.RemoveAll(tempDir)
code := `
package main
import (
"testing"
"time"
"fmt"
)
func TestLateLog(t *testing.T) {
c := make(chan bool)
go func(t *testing.T) {
<-c
time.Sleep(10*time.Millisecond)
fmt.Printf("-> %v\n", t)
t.Log("log after test")
}(t)
close(c)
}
`
destFile := filepath.Join(tempDir, "issue30389_test.go")
if err := ioutil.WriteFile(destFile, []byte(code), 0644); err != nil {
t.Fatalf("Failed to save test code: %v", err)
}
got, err := exec.Command(testenv.GoToolPath(t), "test", destFile).CombinedOutput()
if err == nil {
t.Fatal("The command unexpectedly passed")
}
want := []byte(`xxx`)
if !bytes.HasPrefix(got, want) {
t.Errorf("Did not print previous output\nGot:\n%s\n\nWant prefix:\n%s", got, want)
}
} Another thing I had a doubt about was, if we are to add a panic before the following to notify users that this information will be lost (or even for debugging if we reach there for this specific case) |
problem: the testing package in Go silently drops "t.Log" messages that are made by a goroutine after the test has completed.
The log messages from the goroutine are written using the custom logger (logger.Println). After the goroutine has finished, we can access the collected log messages from the bytes.Buffer (logOutput) using logOutput.String() and display them using t.Log.
After the goroutine has finished, we seek to the beginning of the temporary file using and read all logs and display them with t.log! second way is faster but get memory more that the first way. as you can see the time to finish the test is less than previous one:
now with this 2 way we show the log even after test has completed! |
The testing package silently drops
t.Log
messages that are made by a goroutine after the test has completed. For example, the following test passes and logs nothing.This should be fixed by extending the code added in 1.12 that panics if a goroutine logs after a test has completed to not silently discard the log message. The silent discarding is occurring in the current code because every test runs in a parent context, and the output accumulated by the parent context is discarded.
The text was updated successfully, but these errors were encountered: