testing: loses log messages made in a goroutine after test has completed

[ianlancetaylor]

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.

package main

import (
	"testing"
	"time"
)

func TestLateLog(t *testing.T) {
	c := make(chan bool)
	go func() {
		<-c
		time.Sleep(time.Millisecond)
		t.Log("log after test")
	}()
	close(c)
}

[rhnvrm]

Hey,

I tried investigating and wrote a test and modifying various places in testing.go like the log and logDepth function in my fork with debug statements (fmt.Fprintf(os.Stdout, "%s", string(s))) but the log never ran.

I might be naively making a mistake here but I guess after the TestLateLog function exits t.output or t.parent output is never changed and flush output never has anything to print.

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)
parent.output = append(parent.output, parent.decorate(s, depth+1)...)
is there a way to detect that it was a test without a tRunner

[AHNakbari]

problem: the testing package in Go silently drops "t.Log" messages that are made by a goroutine after the test has completed.
why we should worry about that: This behavior can sometimes lead to missing important log messages and make debugging more challenging.
reason: The issue arises because the parent context in which the test runs discards any accumulated output.
solution:
there is 2 way to fix this problem:

1. To capture and display log messages from goroutines after the test has completed, you can create a custom logger and collect the log messages manually.

package main

import (
	"bytes"
	"log"
	"testing"
	"time"
)

func TestLateLog(t *testing.T) {
	c := make(chan bool)
	logOutput := bytes.Buffer{}
	logger := log.New(&logOutput, "", 0) // Create custom logger
	go func() {
		<-c
		time.Sleep(time.Millisecond)
		logger.Println("log after test")
	}()
	close(c)
	time.Sleep(10 * time.Millisecond)
	t.Log(logOutput.String())
}

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.
now the output after test is:

=== RUN   TestLateLog
    main_test.go:21: log after test
        
--- PASS: TestLateLog (0.03s)
PASS

2. another way is to create a temporary file to capture the log messages.

package main

import (
	"io/ioutil"
	"log"
	"os"
	"testing"
	"time"
)

func TestLateLog(t *testing.T) {
	c := make(chan bool)
	logFile, err := ioutil.TempFile("", "testlog-") // Temporary file
	if err != nil {
		t.Fatal(err)
	}
	defer func(name string) {
		err := os.Remove(name)
		if err != nil {

		}
	}(logFile.Name())
	log.SetOutput(logFile)
	go func() {
		<-c
		time.Sleep(time.Millisecond)
		log.Println("log after test")
	}()
	close(c)
	time.Sleep(10 * time.Millisecond)
	logFile.Seek(0, 0)
	logData, _ := ioutil.ReadAll(logFile)
	t.Log(string(logData))
}

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:

=== RUN   TestLateLog
    main_test.go:33: 2023/06/26 19:21:48 log after test
        
--- PASS: TestLateLog (0.02s)
PASS

now with this 2 way we show the log even after test has completed!