Strange output with testname format and coverprofile

[brvoisin]

Hello!

I created a small Go module for the example:

tree .
├── anotherpkg
│   └── anotherpkg.go
├── apackage
│   ├── apackage.go
│   └── apackage_test.go
├── cover.txt
├── go.mod
├── go.sum
├── hello.go
└── hello_test.go

2 directories, 8 files

When I run the command

gotestsum --format testname

the output is normal:

PASS TestHello (0.00s)
PASS . (cached)
EMPTY anotherpkg
PASS apackage.TestFoo (0.00s)
PASS apackage (cached)

DONE 2 tests in 0.037s

But when I run the command to have the coverage

gotestsum --format testname -- ./... -coverprofile=cover.txt

the output is:

PASS TestHello (0.00s)
coverage: 0.0% of statements
	example/hello/anotherpkg		coverage: 0.0% of statements
PASS apackage.TestFoo (0.00s)
PASS . (coverage: 0.0% of statements)
coverage: 100.0% of statements
EMPTY anotherpkg (coverage: 0.0% of statements)
PASS apackage (coverage: 100.0% of statements)

DONE 2 tests in 0.154s

I don't understand the line order and there are duplicated information like

example/hello/anotherpkg		coverage: 0.0% of statements

and

EMPTY anotherpkg (coverage: 0.0% of statements)

Do you know how to have an output more readable?

FYI, without the testname format it's okay:

gotestsum -- ./... -coverprofile=cover.txt
✓  . (2ms) (coverage: 0.0% of statements)
∅  anotherpkg (3ms) (coverage: 0.0% of statements)
✓  apackage (1ms) (coverage: 100.0% of statements)

DONE 2 tests in 0.112s

[dnephin]

Thank you for the bug report! When I was added tests for a change to coverage support I recall there being problems with the testname format when -coverprofile is enabled.

The formatters take the Output field from the events described in https://pkg.go.dev/cmd/test2json and attempt to display the correct ones. The bug seems to be that coverprofile adds extra Output lines that aren't handled correctly.

It's also possible this output has changed in a more recent version of Go, and that may be why there are extra lines now.

The code for the testname format is here:

gotestsum/testjson/format.go

Lines 141 to 184 in 3735b72

	func testNameFormat(out io.Writer) EventFormatter {
	buf := bufio.NewWriter(out)
	// nolint:errcheck
	return eventFormatterFunc(func(event TestEvent, exec *Execution) error {
	formatTest := func() error {
	testNameFormatTestEvent(buf, event)
	return buf.Flush()
	}
	switch {
	case isPkgFailureOutput(event):
	buf.WriteString(event.Output)
	return buf.Flush()
	case event.PackageEvent():
	if !event.Action.IsTerminal() {
	return nil
	}
	result := colorEvent(event)(strings.ToUpper(string(event.Action)))
	pkg := exec.Package(event.Package)
	if event.Action == ActionSkip || (event.Action == ActionPass && pkg.Total == 0) {
	event.Action = ActionSkip // always color these as skip actions
	result = colorEvent(event)("EMPTY")
	}
	event.Elapsed = 0 // hide elapsed for now, for backwards compat
	buf.WriteString(result)
	buf.WriteRune(' ')
	buf.WriteString(packageLine(event, exec.Package(event.Package)))
	return buf.Flush()
	case event.Action == ActionFail:
	pkg := exec.Package(event.Package)
	tc := pkg.LastFailedByName(event.Test)
	pkg.WriteOutputTo(buf, tc.ID)
	return formatTest()
	case event.Action == ActionPass || event.Action == ActionSkip:
	return formatTest()
	}
	return nil
	})
	}

If you can share the go test -json output, that should help fix the problem.

[brvoisin]

I use Go version 1.22.

$ go version
go version go1.22.1 linux/amd64

Below the output of go test -json without and with -coverprofile:

$ go test -json ./...
{"Time":"2024-03-26T09:09:49.992462224+01:00","Action":"start","Package":"example/hello"}
{"Time":"2024-03-26T09:09:49.992569598+01:00","Action":"start","Package":"example/hello/anotherpkg"}
{"Time":"2024-03-26T09:09:49.992599308+01:00","Action":"output","Package":"example/hello/anotherpkg","Output":"?   \texample/hello/anotherpkg\t[no test files]\n"}
{"Time":"2024-03-26T09:09:49.992607825+01:00","Action":"skip","Package":"example/hello/anotherpkg","Elapsed":0}
{"Time":"2024-03-26T09:09:49.993343854+01:00","Action":"run","Package":"example/hello","Test":"TestHello"}
{"Time":"2024-03-26T09:09:49.993365569+01:00","Action":"output","Package":"example/hello","Test":"TestHello","Output":"=== RUN   TestHello\n"}
{"Time":"2024-03-26T09:09:49.99339785+01:00","Action":"output","Package":"example/hello","Test":"TestHello","Output":"--- PASS: TestHello (0.00s)\n"}
{"Time":"2024-03-26T09:09:49.993404184+01:00","Action":"pass","Package":"example/hello","Test":"TestHello","Elapsed":0}
{"Time":"2024-03-26T09:09:49.993408811+01:00","Action":"output","Package":"example/hello","Output":"PASS\n"}
{"Time":"2024-03-26T09:09:49.993696835+01:00","Action":"output","Package":"example/hello","Output":"ok  \texample/hello\t0.001s\n"}
{"Time":"2024-03-26T09:09:49.994080965+01:00","Action":"pass","Package":"example/hello","Elapsed":0.002}
{"Time":"2024-03-26T09:09:50.004938203+01:00","Action":"start","Package":"example/hello/apackage"}
{"Time":"2024-03-26T09:09:50.005625687+01:00","Action":"run","Package":"example/hello/apackage","Test":"TestFoo"}
{"Time":"2024-03-26T09:09:50.005637775+01:00","Action":"output","Package":"example/hello/apackage","Test":"TestFoo","Output":"=== RUN   TestFoo\n"}
{"Time":"2024-03-26T09:09:50.005677401+01:00","Action":"output","Package":"example/hello/apackage","Test":"TestFoo","Output":"foo\n"}
{"Time":"2024-03-26T09:09:50.005688205+01:00","Action":"output","Package":"example/hello/apackage","Test":"TestFoo","Output":"--- PASS: TestFoo (0.00s)\n"}
{"Time":"2024-03-26T09:09:50.005696831+01:00","Action":"pass","Package":"example/hello/apackage","Test":"TestFoo","Elapsed":0}
{"Time":"2024-03-26T09:09:50.005706491+01:00","Action":"output","Package":"example/hello/apackage","Output":"PASS\n"}
{"Time":"2024-03-26T09:09:50.006033933+01:00","Action":"output","Package":"example/hello/apackage","Output":"ok  \texample/hello/apackage\t0.001s\n"}
{"Time":"2024-03-26T09:09:50.006302826+01:00","Action":"pass","Package":"example/hello/apackage","Elapsed":0.001}

$ go test -json ./... -coverprofile=cover.txt
{"Time":"2024-03-26T09:09:54.45858177+01:00","Action":"start","Package":"example/hello"}
{"Time":"2024-03-26T09:09:54.458725526+01:00","Action":"start","Package":"example/hello/anotherpkg"}
{"Time":"2024-03-26T09:09:54.45879087+01:00","Action":"start","Package":"example/hello/apackage"}
{"Time":"2024-03-26T09:09:54.459795512+01:00","Action":"run","Package":"example/hello","Test":"TestHello"}
{"Time":"2024-03-26T09:09:54.459805312+01:00","Action":"output","Package":"example/hello","Test":"TestHello","Output":"=== RUN   TestHello\n"}
{"Time":"2024-03-26T09:09:54.45983974+01:00","Action":"output","Package":"example/hello","Test":"TestHello","Output":"--- PASS: TestHello (0.00s)\n"}
{"Time":"2024-03-26T09:09:54.459844837+01:00","Action":"pass","Package":"example/hello","Test":"TestHello","Elapsed":0}
{"Time":"2024-03-26T09:09:54.459850483+01:00","Action":"output","Package":"example/hello","Output":"PASS\n"}
{"Time":"2024-03-26T09:09:54.459854333+01:00","Action":"output","Package":"example/hello","Output":"coverage: 0.0% of statements\n"}
{"Time":"2024-03-26T09:09:54.45986771+01:00","Action":"run","Package":"example/hello/apackage","Test":"TestFoo"}
{"Time":"2024-03-26T09:09:54.45987908+01:00","Action":"output","Package":"example/hello/apackage","Test":"TestFoo","Output":"=== RUN   TestFoo\n"}
{"Time":"2024-03-26T09:09:54.459892145+01:00","Action":"output","Package":"example/hello/apackage","Test":"TestFoo","Output":"foo\n"}
{"Time":"2024-03-26T09:09:54.459898106+01:00","Action":"output","Package":"example/hello/apackage","Test":"TestFoo","Output":"--- PASS: TestFoo (0.00s)\n"}
{"Time":"2024-03-26T09:09:54.459900914+01:00","Action":"pass","Package":"example/hello/apackage","Test":"TestFoo","Elapsed":0}
{"Time":"2024-03-26T09:09:54.459903831+01:00","Action":"output","Package":"example/hello/apackage","Output":"PASS\n"}
{"Time":"2024-03-26T09:09:54.460030451+01:00","Action":"output","Package":"example/hello","Output":"ok  \texample/hello\t0.001s\tcoverage: 0.0% of statements\n"}
{"Time":"2024-03-26T09:09:54.460038761+01:00","Action":"pass","Package":"example/hello","Elapsed":0.001}
{"Time":"2024-03-26T09:09:54.460176944+01:00","Action":"output","Package":"example/hello/apackage","Output":"coverage: 100.0% of statements\n"}
{"Time":"2024-03-26T09:09:54.460359785+01:00","Action":"output","Package":"example/hello/apackage","Output":"ok  \texample/hello/apackage\t0.001s\tcoverage: 100.0% of statements\n"}
{"Time":"2024-03-26T09:09:54.46036672+01:00","Action":"pass","Package":"example/hello/apackage","Elapsed":0.002}
{"Time":"2024-03-26T09:09:54.465235329+01:00","Action":"output","Package":"example/hello/anotherpkg","Output":"\texample/hello/anotherpkg\t\tcoverage: 0.0% of statements\n"}
{"Time":"2024-03-26T09:09:54.466021445+01:00","Action":"pass","Package":"example/hello/anotherpkg","Elapsed":0.007}