testing: printing in tests without newline and running with -v -json omits a "run" action

[macabu]

Go version

go version go1.24.1 darwin/arm64

Output of go env in your module/workspace:

AR='ar'
CC='clang'
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_ENABLED='1'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
CXX='clang++'
GCCGO='gccgo'
GO111MODULE=''
GOARCH='arm64'
GOARM64='v8.0'
GOAUTH='netrc'
GOBIN='/Users/macabu/go/bin'
GOCACHE='/Users/macabu/Library/Caches/go-build'
GOCACHEPROG=''
GODEBUG=''
GOENV='/Users/macabu/Library/Application Support/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFIPS140='off'
GOFLAGS=''
GOGCCFLAGS='-fPIC -arch arm64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -ffile-prefix-map=/var/folders/1j/6_mdph416630zgmq_7pl7j8m0000gn/T/go-build4105026236=/tmp/go-build -gno-record-gcc-switches -fno-common'
GOHOSTARCH='arm64'
GOHOSTOS='darwin'
GOINSECURE=''
GOMOD='/Users/macabu/Projects/gotestcovjson/go.mod'
GOMODCACHE='/Users/macabu/go/pkg/mod'
GONOPROXY=''
GONOSUMDB=''
GOOS='darwin'
GOPATH='/Users/macabu/go'
GOPRIVATE=''
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/nix/store/ja4jxx60lh1qfqfl4z4p2rff56ia1c3c-go-1.24.1/share/go'
GOSUMDB='sum.golang.org'
GOTELEMETRY='local'
GOTELEMETRYDIR='/Users/macabu/Library/Application Support/go/telemetry'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/nix/store/ja4jxx60lh1qfqfl4z4p2rff56ia1c3c-go-1.24.1/share/go/pkg/tool/darwin_arm64'
GOVCS=''
GOVERSION='go1.24.1'
GOWORK=''
PKG_CONFIG='pkg-config'

What did you do?

With the following test file: https://go.dev/play/p/6WawLVaiaFW

package main

import (
	"fmt"
	"testing"
)

func Foo(v bool) {
	if v {
		fmt.Printf("value: %v", v)
	}
}

func TestFooSubTest(t *testing.T) {
	t.Run("true", func(t *testing.T) {
		Foo(true)
	})

	t.Run("false", func(t *testing.T) {
		Foo(false)
	})
}

What did you see happen?

Running:

go test -json ./...

Correctly outputs 3 run actions:

{"Time":"2025-03-18T17:08:10.054122+01:00","Action":"start","Package":"github.com/grafana/gotestcovjson"}
{"Time":"2025-03-18T17:08:10.054156+01:00","Action":"run","Package":"github.com/grafana/gotestcovjson","Test":"TestFooSubTest"}
{"Time":"2025-03-18T17:08:10.054158+01:00","Action":"output","Package":"github.com/grafana/gotestcovjson","Test":"TestFooSubTest","Output":"=== RUN   TestFooSubTest\n"}
{"Time":"2025-03-18T17:08:10.054162+01:00","Action":"run","Package":"github.com/grafana/gotestcovjson","Test":"TestFooSubTest/true"}
{"Time":"2025-03-18T17:08:10.054163+01:00","Action":"output","Package":"github.com/grafana/gotestcovjson","Test":"TestFooSubTest/true","Output":"=== RUN   TestFooSubTest/true\n"}
{"Time":"2025-03-18T17:08:10.054165+01:00","Action":"output","Package":"github.com/grafana/gotestcovjson","Test":"TestFooSubTest/true","Output":"value: true"}
{"Time":"2025-03-18T17:08:10.05417+01:00","Action":"output","Package":"github.com/grafana/gotestcovjson","Test":"TestFooSubTest/true","Output":"--- PASS: TestFooSubTest/true (0.00s)\n"}
{"Time":"2025-03-18T17:08:10.054183+01:00","Action":"pass","Package":"github.com/grafana/gotestcovjson","Test":"TestFooSubTest/true","Elapsed":0}
{"Time":"2025-03-18T17:08:10.054186+01:00","Action":"run","Package":"github.com/grafana/gotestcovjson","Test":"TestFooSubTest/false"}
{"Time":"2025-03-18T17:08:10.054187+01:00","Action":"output","Package":"github.com/grafana/gotestcovjson","Test":"TestFooSubTest/false","Output":"=== RUN   TestFooSubTest/false\n"}
{"Time":"2025-03-18T17:08:10.054189+01:00","Action":"output","Package":"github.com/grafana/gotestcovjson","Test":"TestFooSubTest/false","Output":"--- PASS: TestFooSubTest/false (0.00s)\n"}
{"Time":"2025-03-18T17:08:10.05419+01:00","Action":"pass","Package":"github.com/grafana/gotestcovjson","Test":"TestFooSubTest/false","Elapsed":0}
{"Time":"2025-03-18T17:08:10.054191+01:00","Action":"output","Package":"github.com/grafana/gotestcovjson","Test":"TestFooSubTest","Output":"--- PASS: TestFooSubTest (0.00s)\n"}
{"Time":"2025-03-18T17:08:10.054195+01:00","Action":"pass","Package":"github.com/grafana/gotestcovjson","Test":"TestFooSubTest","Elapsed":0}
{"Time":"2025-03-18T17:08:10.054289+01:00","Action":"output","Package":"github.com/grafana/gotestcovjson","Output":"PASS\n"}
{"Time":"2025-03-18T17:08:10.05429+01:00","Action":"output","Package":"github.com/grafana/gotestcovjson","Output":"ok  \tgithub.com/grafana/gotestcovjson\t(cached)\n"}
{"Time":"2025-03-18T17:08:10.054294+01:00","Action":"pass","Package":"github.com/grafana/gotestcovjson","Elapsed":0}

While running:

go test -json -v ./...

Outputs 2 run actions, TestFooSubTest/false missing it:

{"Time":"2025-03-18T17:08:22.035856+01:00","Action":"start","Package":"github.com/grafana/gotestcovjson"}
{"Time":"2025-03-18T17:08:22.035892+01:00","Action":"run","Package":"github.com/grafana/gotestcovjson","Test":"TestFooSubTest"}
{"Time":"2025-03-18T17:08:22.035894+01:00","Action":"output","Package":"github.com/grafana/gotestcovjson","Test":"TestFooSubTest","Output":"=== RUN   TestFooSubTest\n"}
{"Time":"2025-03-18T17:08:22.035898+01:00","Action":"run","Package":"github.com/grafana/gotestcovjson","Test":"TestFooSubTest/true"}
{"Time":"2025-03-18T17:08:22.0359+01:00","Action":"output","Package":"github.com/grafana/gotestcovjson","Test":"TestFooSubTest/true","Output":"=== RUN   TestFooSubTest/true\n"}
{"Time":"2025-03-18T17:08:22.035903+01:00","Action":"output","Package":"github.com/grafana/gotestcovjson","Test":"TestFooSubTest/true","Output":"value: true=== RUN   TestFooSubTest/false\n"}
{"Time":"2025-03-18T17:08:22.035906+01:00","Action":"output","Package":"github.com/grafana/gotestcovjson","Test":"TestFooSubTest","Output":"--- PASS: TestFooSubTest (0.00s)\n"}
{"Time":"2025-03-18T17:08:22.035919+01:00","Action":"output","Package":"github.com/grafana/gotestcovjson","Test":"TestFooSubTest/true","Output":"    --- PASS: TestFooSubTest/true (0.00s)\n"}
{"Time":"2025-03-18T17:08:22.035921+01:00","Action":"pass","Package":"github.com/grafana/gotestcovjson","Test":"TestFooSubTest/true","Elapsed":0}
{"Time":"2025-03-18T17:08:22.035925+01:00","Action":"output","Package":"github.com/grafana/gotestcovjson","Test":"TestFooSubTest/false","Output":"    --- PASS: TestFooSubTest/false (0.00s)\n"}
{"Time":"2025-03-18T17:08:22.035929+01:00","Action":"pass","Package":"github.com/grafana/gotestcovjson","Test":"TestFooSubTest/false","Elapsed":0}
{"Time":"2025-03-18T17:08:22.03593+01:00","Action":"pass","Package":"github.com/grafana/gotestcovjson","Test":"TestFooSubTest","Elapsed":0}
{"Time":"2025-03-18T17:08:22.035932+01:00","Action":"output","Package":"github.com/grafana/gotestcovjson","Output":"PASS\n"}
{"Time":"2025-03-18T17:08:22.035933+01:00","Action":"output","Package":"github.com/grafana/gotestcovjson","Output":"ok  \tgithub.com/grafana/gotestcovjson\t(cached)\n"}
{"Time":"2025-03-18T17:08:22.035998+01:00","Action":"pass","Package":"github.com/grafana/gotestcovjson","Elapsed":0}

If you tweak the Foo function to print with a newline \n:

func Foo(v bool) {
	if v {
		fmt.Printf("value: %v\n", v)
	}
}

And re-run with:

go test -json -v ./...

It outputs the expected 3 run actions:

{"Time":"2025-03-18T17:09:39.595521+01:00","Action":"start","Package":"github.com/grafana/gotestcovjson"}
{"Time":"2025-03-18T17:09:39.595571+01:00","Action":"run","Package":"github.com/grafana/gotestcovjson","Test":"TestFooSubTest"}
{"Time":"2025-03-18T17:09:39.595574+01:00","Action":"output","Package":"github.com/grafana/gotestcovjson","Test":"TestFooSubTest","Output":"=== RUN   TestFooSubTest\n"}
{"Time":"2025-03-18T17:09:39.595577+01:00","Action":"run","Package":"github.com/grafana/gotestcovjson","Test":"TestFooSubTest/true"}
{"Time":"2025-03-18T17:09:39.59558+01:00","Action":"output","Package":"github.com/grafana/gotestcovjson","Test":"TestFooSubTest/true","Output":"=== RUN   TestFooSubTest/true\n"}
{"Time":"2025-03-18T17:09:39.595585+01:00","Action":"output","Package":"github.com/grafana/gotestcovjson","Test":"TestFooSubTest/true","Output":"value: true\n"}
{"Time":"2025-03-18T17:09:39.59559+01:00","Action":"run","Package":"github.com/grafana/gotestcovjson","Test":"TestFooSubTest/false"}
{"Time":"2025-03-18T17:09:39.595592+01:00","Action":"output","Package":"github.com/grafana/gotestcovjson","Test":"TestFooSubTest/false","Output":"=== RUN   TestFooSubTest/false\n"}
{"Time":"2025-03-18T17:09:39.5956+01:00","Action":"output","Package":"github.com/grafana/gotestcovjson","Test":"TestFooSubTest","Output":"--- PASS: TestFooSubTest (0.00s)\n"}
{"Time":"2025-03-18T17:09:39.595602+01:00","Action":"output","Package":"github.com/grafana/gotestcovjson","Test":"TestFooSubTest/true","Output":"    --- PASS: TestFooSubTest/true (0.00s)\n"}
{"Time":"2025-03-18T17:09:39.595603+01:00","Action":"pass","Package":"github.com/grafana/gotestcovjson","Test":"TestFooSubTest/true","Elapsed":0}
{"Time":"2025-03-18T17:09:39.595605+01:00","Action":"output","Package":"github.com/grafana/gotestcovjson","Test":"TestFooSubTest/false","Output":"    --- PASS: TestFooSubTest/false (0.00s)\n"}
{"Time":"2025-03-18T17:09:39.595609+01:00","Action":"pass","Package":"github.com/grafana/gotestcovjson","Test":"TestFooSubTest/false","Elapsed":0}
{"Time":"2025-03-18T17:09:39.595681+01:00","Action":"pass","Package":"github.com/grafana/gotestcovjson","Test":"TestFooSubTest","Elapsed":0}
{"Time":"2025-03-18T17:09:39.595682+01:00","Action":"output","Package":"github.com/grafana/gotestcovjson","Output":"PASS\n"}
{"Time":"2025-03-18T17:09:39.595683+01:00","Action":"output","Package":"github.com/grafana/gotestcovjson","Output":"ok  \tgithub.com/grafana/gotestcovjson\t(cached)\n"}
{"Time":"2025-03-18T17:09:39.595689+01:00","Action":"pass","Package":"github.com/grafana/gotestcovjson","Elapsed":0}

What did you expect to see?

The output json to contain 3 run actions in all cases.

[ianlancetaylor]

Probably related to the issues discussed in #38063.

[macabu]

Thanks! We will use the workaround of adding \n

Perhaps this one can be closed then as duplicate of the one mentioned.

[gabyhelp]

Related Issues

• stdout messes up `go test --json` #36576 (closed)
• cmd/go: -json test report ordering #28953
• cmd/test2json: adding an fmt.Print in tests skip the pass action in json output #49630 (closed)
• testing: bad output formatting when test stdout ends in an incomplete line #38063 (closed)
• cmd/test2json: test output without trailing newline missing final status #57172 (closed)
• cmd/go: test2json does not recognize test status if output did not end with new line #47032 (closed)
• cmd/test2json: colon in test name breaks JSON #24974 (closed)
• cmd/test2json: misparses subtest names with : in them #23920 (closed)
• "go test -v" and compile test binary outputs are inconsistent for post-completion panics #58979 (closed)
• testing: parallel subtest log output not properly constrained in go1.14rc1 #37203 (closed)

_{(Emoji vote if this was helpful or unhelpful; more detailed feedback welcome in this discussion.)}