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

Strange output with testname format and coverprofile #391

Open
brvoisin opened this issue Mar 19, 2024 · 3 comments
Open

Strange output with testname format and coverprofile #391

brvoisin opened this issue Mar 19, 2024 · 3 comments
Labels
bug Something isn't working

Comments

@brvoisin
Copy link

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 dnephin added the bug Something isn't working label Mar 23, 2024
@dnephin
Copy link
Member

dnephin commented Mar 23, 2024

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:

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

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}

@jorgepsmatos
Copy link

I have the same issue. Any updates regarding this?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

No branches or pull requests

3 participants