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: loses log messages made in a goroutine after test has completed #30389

Open
ianlancetaylor opened this issue Feb 25, 2019 · 2 comments
Labels
NeedsFix The path to resolution is known, but the work has not been done.
Milestone

Comments

@ianlancetaylor
Copy link
Contributor

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)
}
@ianlancetaylor ianlancetaylor added the NeedsFix The path to resolution is known, but the work has not been done. label Feb 25, 2019
@ianlancetaylor ianlancetaylor added this to the Go1.13 milestone Feb 25, 2019
@rhnvrm
Copy link
Contributor

rhnvrm commented Feb 27, 2019

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

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
  1. 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!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
NeedsFix The path to resolution is known, but the work has not been done.
Projects
None yet
Development

No branches or pull requests

5 participants