cmd/test2json: misparses subtest names with : in them

[antifuchs]

What version of Go are you using (go version)?

go version go1.10 darwin/amd64

Does this issue reproduce with the latest release?

Yes.

What operating system and processor architecture are you using (go env)?

GOARCH="amd64"
GOBIN="/Users/asf/go/bin"
GOCACHE="/Users/asf/Library/Caches/go-build"
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/asf/go"
GORACE=""
GOROOT="/usr/local/Cellar/go/1.10/libexec"
GOTMPDIR=""
GOTOOLDIR="/usr/local/Cellar/go/1.10/libexec/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/08/j4g_jn953lngpvgmyg8dygk00000gn/T/go-build539276007=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

This test file makes go test -json ./ produce very weird output on Action: "run":

package main

import "testing"

func TestSubtestNames(t *testing.T) {
	t.Run("words are ok", func(t *testing.T) {
		t.Log("they get _")
	})

	t.Run("[::1] is not ok", func(t *testing.T) {
		t.Log("...yeah")
	})

	t.Run("127.0.0.1 to 127.0.0.1:0", func(t *testing.T) {
		t.Log("seems the : is the problem.")
	})
}

What did you expect to see?

JSON containing consistent references to the subtest names.

What did you see instead?

This produces mostly-correct looking output, but only mostly.

Here's the entire json dump in case you're interested

{"Time":"2018-02-19T10:14:40.900984116+01:00","Action":"run","Package":"github.com/antifuchs/simple_tests/test2json","Test":"TestSubtestNames"}
{"Time":"2018-02-19T10:14:40.901516634+01:00","Action":"output","Package":"github.com/antifuchs/simple_tests/test2json","Test":"TestSubtestNames","Output":"=== RUN   TestSubtestNames\n"}
{"Time":"2018-02-19T10:14:40.901547154+01:00","Action":"run","Package":"github.com/antifuchs/simple_tests/test2json","Test":"TestSubtestNames/words_are_ok"}
{"Time":"2018-02-19T10:14:40.901567463+01:00","Action":"output","Package":"github.com/antifuchs/simple_tests/test2json","Test":"TestSubtestNames/words_are_ok","Output":"=== RUN   TestSubtestNames/words_are_ok\n"}
{"Time":"2018-02-19T10:14:40.901580108+01:00","Action":"run   testsubtestnames/[","Package":"github.com/antifuchs/simple_tests/test2json","Test":":1]_is_not_ok"}
{"Time":"2018-02-19T10:14:40.901598665+01:00","Action":"output","Package":"github.com/antifuchs/simple_tests/test2json","Test":":1]_is_not_ok","Output":"=== RUN   TestSubtestNames/[::1]_is_not_ok\n"}
{"Time":"2018-02-19T10:14:40.902368883+01:00","Action":"run   testsubtestnames/127.0.0.1_to_127.0.0.1","Package":"github.com/antifuchs/simple_tests/test2json","Test":"0"}
{"Time":"2018-02-19T10:14:40.90239884+01:00","Action":"output","Package":"github.com/antifuchs/simple_tests/test2json","Test":"0","Output":"=== RUN   TestSubtestNames/127.0.0.1_to_127.0.0.1:0\n"}
{"Time":"2018-02-19T10:14:40.902421482+01:00","Action":"output","Package":"github.com/antifuchs/simple_tests/test2json","Test":"TestSubtestNames","Output":"--- PASS: TestSubtestNames (0.00s)\n"}
{"Time":"2018-02-19T10:14:40.902433995+01:00","Action":"output","Package":"github.com/antifuchs/simple_tests/test2json","Test":"TestSubtestNames/words_are_ok","Output":"    --- PASS: TestSubtestNames/words_are_ok (0.00s)\n"}
{"Time":"2018-02-19T10:14:40.902444064+01:00","Action":"output","Package":"github.com/antifuchs/simple_tests/test2json","Test":"TestSubtestNames/words_are_ok","Output":"    \tmain_test.go:7: they get _\n"}
{"Time":"2018-02-19T10:14:40.939809762+01:00","Action":"pass","Package":"github.com/antifuchs/simple_tests/test2json","Test":"TestSubtestNames/words_are_ok","Elapsed":0}
{"Time":"2018-02-19T10:14:40.939849539+01:00","Action":"output","Package":"github.com/antifuchs/simple_tests/test2json","Test":"TestSubtestNames/[::1]_is_not_ok","Output":"    --- PASS: TestSubtestNames/[::1]_is_not_ok (0.00s)\n"}
{"Time":"2018-02-19T10:14:40.939859759+01:00","Action":"output","Package":"github.com/antifuchs/simple_tests/test2json","Test":"TestSubtestNames/[::1]_is_not_ok","Output":"    \tmain_test.go:11: ...yeah\n"}
{"Time":"2018-02-19T10:14:40.939872701+01:00","Action":"pass","Package":"github.com/antifuchs/simple_tests/test2json","Test":"TestSubtestNames/[::1]_is_not_ok","Elapsed":0}
{"Time":"2018-02-19T10:14:40.939879283+01:00","Action":"output","Package":"github.com/antifuchs/simple_tests/test2json","Test":"TestSubtestNames/127.0.0.1_to_127.0.0.1:0","Output":"    --- PASS: TestSubtestNames/127.0.0.1_to_127.0.0.1:0 (0.00s)\n"}
{"Time":"2018-02-19T10:14:40.96860519+01:00","Action":"output","Package":"github.com/antifuchs/simple_tests/test2json","Test":"TestSubtestNames/127.0.0.1_to_127.0.0.1:0","Output":"    \tmain_test.go:15: seems the : is the problem.\n"}
{"Time":"2018-02-19T10:14:40.968645737+01:00","Action":"pass","Package":"github.com/antifuchs/simple_tests/test2json","Test":"TestSubtestNames/127.0.0.1_to_127.0.0.1:0","Elapsed":0}
{"Time":"2018-02-19T10:14:40.968662449+01:00","Action":"pass","Package":"github.com/antifuchs/simple_tests/test2json","Test":"TestSubtestNames","Elapsed":0}
{"Time":"2018-02-19T10:14:40.968672499+01:00","Action":"output","Package":"github.com/antifuchs/simple_tests/test2json","Output":"PASS\n"}
{"Time":"2018-02-19T10:14:40.968821377+01:00","Action":"output","Package":"github.com/antifuchs/simple_tests/test2json","Output":"ok  \tgithub.com/antifuchs/simple_tests/test2json\t0.077s\n"}
{"Time":"2018-02-19T10:14:40.972550837+01:00","Action":"pass","Package":"github.com/antifuchs/simple_tests/test2json","Elapsed":0.081}

And here are the bits that are concerning:

{"Time":"2018-02-19T10:14:40.901580108+01:00","Action":"run   testsubtestnames/[","Package":"github.com/antifuchs/simple_tests/test2json","Test":":1]_is_not_ok"}
{"Time":"2018-02-19T10:14:40.902368883+01:00","Action":"run   testsubtestnames/127.0.0.1_to_127.0.0.1","Package":"github.com/antifuchs/simple_tests/test2json","Test":"0"}
{"Time":"2018-02-19T10:14:40.90239884+01:00","Action":"output","Package":"github.com/antifuchs/simple_tests/test2json","Test":"0","Output":"=== RUN   TestSubtestNames/127.0.0.1_to_127.0.0.1:0\n"}
{"Time":"2018-02-19T10:14:40.901598665+01:00","Action":"output","Package":"github.com/antifuchs/simple_tests/test2json","Test":":1]_is_not_ok","Output":"=== RUN   TestSubtestNames/[::1]_is_not_ok\n"}

Note the weird "Action" name, and the bad "Test" entry

It looks like the action name gets extracted greedily, and everything in the test name up to the first : gets dragged in. Other stuff like "pass" makes it through ok, but this seems like a bug.

[gopherbot]

Change https://golang.org/cl/98445 mentions this issue: cmd/internal/test2json: support subtests containing colons

[zolotov]

@bradfitz any chance to backport it to Go 1.10.x?

[bradfitz]

@zolotov, it's not clear it meets the bar for our backport policy, but it's also small and trivial, with no great user workaround, so ... maybe? @andybons, @ianlancetaylor?

[andybons]

I'm on the fence. It doesn't appear to be a regression (correct me if I'm wrong) but also doesn't have a user workaround and is fairly small as Brad said. I give a soft yes. Will leave to @ianlancetaylor to make final decision.

[ianlancetaylor]

Backporting is OK with me.

[andybons]

@gopherbot please backport

[gopherbot]

Backport issue(s) opened: #25027 (for 1.10), #25028 (for 1.9).

Remember to create the cherry-pick CL(s) as soon as the patch is submitted to master, according to https://golang.org/wiki/MinorReleases.

[gopherbot]

Backport issue(s) opened: #25027 (for 1.10), #25029 (for 1.9).

Remember to create the cherry-pick CL(s) as soon as the patch is submitted to master, according to https://golang.org/wiki/MinorReleases.

[FiloSottile]

Closing this in favor of #25027 as the issue is fixed in master.

(EDIT: It was already closed, as I only noticed while clicking "Reopen and comment" -.-)