gotestyourself / gotestyourself/gotestsum
Inconsistent output when logging after failure
- Dominant language
- Go
- Stars
- 2.7k
- Forks
- 171
- PR merge metrics
- No merged PRs in 30d
Description
When longer running tests run in parallel and are printing things after a test has called `t.Fail()` the log output is very inconsistent. They always get cut off at some point soon after `t.Fail()` was called, but there will be different amount of logs each time. Sometimes there are even logs from other tests being added to the output of the failed test which was a real head-scratcher before realizing what was happening.
Test case to reproduce the issue:
```go
package main_test
import (
"fmt"
"testing"
"time"
)
func TestFoo(t *testing.T) {
t.Parallel()
defer func() {
fmt.Println("defer Foo")
}()
fmt.Println("Before fail Foo")
t.Fail()
fmt.Println("After fail Foo")
for i := 0; i < 10; i++ {
fmt.Println("Foo", i)
}
time.Sleep(100 * time.Millisecond)
fmt.Println("Later in Foo")
time.Sleep(1000 * time.Millisecond)
fmt.Println("Even later in Foo")
}
func TestBar(t *testing.T) {
t.Parallel()
fmt.Println("Running Bar")
defer func() {
fmt.Println("defer Bar")
}()
time.Sleep(100 * time.Millisecond)
fmt.Println("This should not be printed")
time.Sleep(1000 * time.Millisecond)
fmt.Println("This should not be printed either")
}
```
Example output:
```shell
hansson:~/go/hello$ gotestsum
✖ . (1.104s)
=== Failed
=== FAIL: . TestFoo (1.10s)
Before fail Foo
After fail Foo
Foo 0
Foo 1
Foo 2
Foo 3
Foo 4
Foo 5
Foo 6
Foo 7
Foo 8
Foo 9
This should not be printed either
defer Bar
DONE 2 tests, 1 failure in 1.266s
```
Here the last two logs and the defer are missing from the `TestFoo` output, and for some reason the last log and the defer from `TestBar` are included.
Increasing the loop to print 100 times will also show the fact that the cut-off is random. I have seem it cut off anywhere between 7 and 97 runs in the loop.
Contributor guide
No contributing guide indexed for this repository
Research direction
Run the provided Go reproduction with gotestsum and compare the captured output for TestFoo and TestBar across repeated runs. Trace the test-output handling from the gotestsum entry point; done means failed tests retain all their logs, deferred output is attributed to the correct test, and parallel tests do not mix output.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- go
- Domain
- testing
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Mostly clear
- Newbie friendliness
- 35/100