gotestyourself / gotestyourself/gotestsum

Inconsistent output when logging after failure

Open
#441 3 comments 1 reaction 0 assignees View on GitHub
test2json-bug
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

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.