Golang1.14でt.Logの出力がちょっと変わったらしいので今更試してみた

□ 背景っぽいもの

最近golangの最新情報追えてないなーと思いながら、golang1.14のリリースノートを眺めていたらにこんな事が書いてありました。

Testing
go test -v now streams t.Log output as it happens, rather than at the end of all tests.

引用 https://golang.org/doc/go1.14

英語が苦手なニワトリが和訳に自信がなかったので、Google先生に頼んで翻訳してもらうと
「go test -vt.Logすべてのテストの最後ではなく、発生時に出力をストリーミングするようになりました。」
とのこと。

正直これを見て
「ほーん、なるほど（え？大して変わってなくない？）」
程度にしか感じていなかったのですが、何事も知ったかぶりは良くない。
慢心、ダメ絶対。

というわけで、「そうだ試してみよう」と思い立ったので試した結果をまとめていきます。

□ 試してあそぼう

というわけで適当なテストコードを作っていきます。
今回はログ出力を見ることが目的なので、めっちゃ適当に作ってみました。

package main

import "testing"

func Test3の倍数を入れるとアホになる関数(t *testing.T) {
	t.Log("アホになる関数のテスト開始")
	if _, err := aho(4); err != nil {
		t.Error(err, "アホになれませんでした")
	}
	t.Log("アホになる関数のテスト終了")
}

で、これは実行したらこんな感じになります。
まあ、見慣れた子ですね。

$ go test -v
=== RUN   Test3の倍数を入れるとアホになる関数
--- FAIL: Test3の倍数を入れるとアホになる関数 (0.00s)
    main_test.go:6: アホになる関数のテスト開始
    main_test.go:8: これは3じゃないからアホにはなれません アホになれませんでした
    main_test.go:10: アホになる関数のテスト終了
FAIL
exit status 1
FAIL    _/Users/i-dach/Documents/sandbox/toy    0.234s

ちなみにバージョンは「1.13.5」です。

$ go version
go version go1.13.5 darwin/amd64

ということで、下準備はできたので早速Versionを1.14に変えましょう。
バージョン管理ツールを使ってgolangを入れておくと便利で、私はgvmを使ってます（好きなのをお使いください）
gvmだとこんな感じで切り替えができます。

# まずは対象がDLできるかどうかを確認
$ gvm listall

gvm gos (available)

~
   go1.13.9
   go1.13.10
   go1.14
   go1.14beta1
   go1.14rc1
   go1.14.1
   go1.14.2
~   

# できそうだったらinstallして適用する
$ gvm install go1.14
Updating Go source...
Installing go1.14...
 * Compiling...
successfully installed!

$ gvm use go1.14
Now using version go1.14

$ go version
go version go1.14 darwin/amd64

これでgolangのVersionが1.14になりました。
では早速試してみる。

$ go test -v 
=== RUN   Test3の倍数を入れるとアホになる関数
    Test3の倍数を入れるとアホになる関数: main_test.go:6: アホになる関数のテスト開始
    Test3の倍数を入れるとアホになる関数: main_test.go:8: これは3じゃないからアホにはなれません アホになれませんでした
    Test3の倍数を入れるとアホになる関数: main_test.go:10: アホになる関数のテスト終了
--- FAIL: Test3の倍数を入れるとアホになる関数 (0.00s)
FAIL
exit status 1
FAIL    _/Users/i-dach/Documents/sandbox/toy    0.256s

お？確かに微妙に変わってる？

単体で見ても分かりづらかったので、並べてみます。

golang1.13.5

$ go test -v
=== RUN   Test3の倍数を入れるとアホになる関数
--- FAIL: Test3の倍数を入れるとアホになる関数 (0.00s)
    main_test.go:6: アホになる関数のテスト開始
    main_test.go:8: これは3じゃないからアホにはなれません アホになれませんでした
    main_test.go:10: アホになる関数のテスト終了
FAIL
exit status 1
FAIL    _/Users/i-dach/Documents/sandbox/toy    0.234s

golang1.14

$ go test -v 
=== RUN   Test3の倍数を入れるとアホになる関数
    Test3の倍数を入れるとアホになる関数: main_test.go:6: アホになる関数のテスト開始
    Test3の倍数を入れるとアホになる関数: main_test.go:8: これは3じゃないからアホにはなれません アホになれませんでした
    Test3の倍数を入れるとアホになる関数: main_test.go:10: アホになる関数のテスト終了
--- FAIL: Test3の倍数を入れるとアホになる関数 (0.00s)
FAIL
exit status 1
FAIL    _/Users/i-dach/Documents/sandbox/toy    0.256s

すべてのテストの最後ではなく、発生時に出力をストリーミングするようになりました

なるほど、確かに書いてある通りですね。
しかし、良さがわからない。

そうだ、テストを増やしてみよう。

package main

import "testing"

func Test3の倍数を入れるとアホになる関数(t *testing.T) {
	for i := 0; i < 100; i++ {
		t.Log("アホになる関数のテスト開始 - ", i)
		if _, err := aho(i); err != nil {
			t.Error(err, i, "はアホになれませんでした")
		}
		t.Log("アホになる関数のテスト終了 - ", i)
	}
}

とりあえずテストはこんな感じに修正して、100個サブケースが回るようにしてみます。
で、実行した結果を並べて比較してみます。

golang1.13

$ go test -v
=== RUN   Test3の倍数を入れるとアホになる関数
--- FAIL: Test3の倍数を入れるとアホになる関数 (0.00s)
    main_test.go:7: アホになる関数のテスト開始 -  0
    main_test.go:11: アホになる関数のテスト終了 -  0
    main_test.go:7: アホになる関数のテスト開始 -  1
    main_test.go:9: これは3じゃないからアホにはなれません 1 はアホになれませんでした
    main_test.go:11: アホになる関数のテスト終了 -  1
    main_test.go:7: アホになる関数のテスト開始 -  2
(中略)
    main_test.go:9: これは3じゃないからアホにはなれません 94 はアホになれませんでした
    main_test.go:11: アホになる関数のテスト終了 -  94
    main_test.go:7: アホになる関数のテスト開始 -  95
    main_test.go:9: これは3じゃないからアホにはなれません 95 はアホになれませんでした
    main_test.go:11: アホになる関数のテスト終了 -  95
    main_test.go:7: アホになる関数のテスト開始 -  96
    main_test.go:11: アホになる関数のテスト終了 -  96
    main_test.go:7: アホになる関数のテスト開始 -  97
    main_test.go:9: これは3じゃないからアホにはなれません 97 はアホになれませんでした
    main_test.go:11: アホになる関数のテスト終了 -  97
    main_test.go:7: アホになる関数のテスト開始 -  98
    main_test.go:9: これは3じゃないからアホにはなれません 98 はアホになれませんでした
    main_test.go:11: アホになる関数のテスト終了 -  98
    main_test.go:7: アホになる関数のテスト開始 -  99
    main_test.go:11: アホになる関数のテスト終了 -  99
FAIL
exit status 1
FAIL    _/Users/i-dach/Documents/sandbox/toy    0.312s

golang1.14

$ go test -v
=== RUN   Test3の倍数を入れるとアホになる関数
    Test3の倍数を入れるとアホになる関数: main_test.go:7: アホになる関数のテスト開始 -  0
    Test3の倍数を入れるとアホになる関数: main_test.go:11: アホになる関数のテスト終了 -  0
    Test3の倍数を入れるとアホになる関数: main_test.go:7: アホになる関数のテスト開始 -  1
    Test3の倍数を入れるとアホになる関数: main_test.go:9: これは3じゃないからアホにはなれません 1 はアホになれませんでした
    Test3の倍数を入れるとアホになる関数: main_test.go:11: アホになる関数のテスト終了 -  1
    Test3の倍数を入れるとアホになる関数: main_test.go:7: アホになる関数のテスト開始 -  2
(中略)
    Test3の倍数を入れるとアホになる関数: main_test.go:9: これは3じゃないからアホにはなれません 94 はアホになれませんでした
    Test3の倍数を入れるとアホになる関数: main_test.go:11: アホになる関数のテスト終了 -  94
    Test3の倍数を入れるとアホになる関数: main_test.go:7: アホになる関数のテスト開始 -  95
    Test3の倍数を入れるとアホになる関数: main_test.go:9: これは3じゃないからアホにはなれません 95 はアホになれませんでした
    Test3の倍数を入れるとアホになる関数: main_test.go:11: アホになる関数のテスト終了 -  95
    Test3の倍数を入れるとアホになる関数: main_test.go:7: アホになる関数のテスト開始 -  96
    Test3の倍数を入れるとアホになる関数: main_test.go:11: アホになる関数のテスト終了 -  96
    Test3の倍数を入れるとアホになる関数: main_test.go:7: アホになる関数のテスト開始 -  97
    Test3の倍数を入れるとアホになる関数: main_test.go:9: これは3じゃないからアホにはなれません 97 はアホになれませんでした
    Test3の倍数を入れるとアホになる関数: main_test.go:11: アホになる関数のテスト終了 -  97
    Test3の倍数を入れるとアホになる関数: main_test.go:7: アホになる関数のテスト開始 -  98
    Test3の倍数を入れるとアホになる関数: main_test.go:9: これは3じゃないからアホにはなれません 98 はアホになれませんでした
    Test3の倍数を入れるとアホになる関数: main_test.go:11: アホになる関数のテスト終了 -  98
    Test3の倍数を入れるとアホになる関数: main_test.go:7: アホになる関数のテスト開始 -  99
    Test3の倍数を入れるとアホになる関数: main_test.go:11: アホになる関数のテスト終了 -  99
--- FAIL: Test3の倍数を入れるとアホになる関数 (0.03s)
FAIL
exit status 1
FAIL    _/Users/i-dach/Documents/sandbox/toy    0.352s

大量データで比較してみるとgo1.14のほうが結果が追いやすくなっていることが見て取れますね。
この理由を言語化するなら下記のような理由となるのではないでしょうか。

1. どのテストでの実行の結果なのか、サブケースが入れ子になっているので、ぱっと見でわかりやすい
2. 実行ファイル名の前に親テストの名称が入るので、テストケースが膨大になって親ファイル名が見えなくなってもなんのテストでのサブケースなのかがわかりやすい
3. 最後に親テストの終了が来るので、サブケースが全て終わったかどうかがわかりやすい

□ 結論

go1.14のテストログは見やすくなった！