Inconsistent output when logging after failure

[TotalHansson]

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:

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:

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.

[dnephin]

Thank you for the bug report! This is unfortunately a bug with https://pkg.go.dev/cmd/test2json parsing the test output. gotestsum relies on that tool from the Go toolchain to turn test output into json.

In the past I've reported a few of these to https://github.com/golang/go, but I think using t.Parallel is unfortunately going to continue to be unreliable because of how go test outputs logs.

If you try running this test case with go test -json you'll see the same problem. I did that to confirm this was a bug with test2json.

I think many test suites have started to avoid t.Parallel because of these problems. The only way to get reliable test output with t.Parallel is to buffer the output yourself and use t.Cleanup to print the output when t.Failed is true. Using t.Log to output instead of fmt.Println may work in some cases, but can make it more difficult to differentiate log lines from the test failure line.

[TotalHansson]

Hm. Maybe I'm misunderstanding how it is working then. I assumed the idea was the gotestsum reads the json output, which includes the name of the test in each line, so that the order of the logs didn't matter. In the non-json output it's harder to reason about which line belongs to which test, especially when running in parallel, but this should be fine with json output. So in the case where TestFoo fails it would simply print each log line that include "Test": "TestFoo". But maybe this is not the case?

[TotalHansson]

Oh I just realized what you meant when looking at the test with -json again. {"Time":"2024-09-25T10:21:05.288955848+02:00","Action":"output","Package":"hello","Test":"TestBar","Output":"Even later in Foo\n"} I see the line is tagged with the wrong test. Then I understand that it's not really solvable from your side