テストのロギングにはlog.Printlnではなくt.Logを使った方が良い理由

# 三行で
* Go言語でテストを書くときに、ログの出力に `t.Log()` / `t.Logf()` を使うとログが見やすくなってデバッグが快適になる。
* `log.Printf()` や `log.Println()` で出力したログは、テストが一つでも失敗した場合に全て表示されてしまうが、 `t.Log()` / `t.Logf()` で出力したログは「失敗したテストに関するものだけ」が表示されるので、見やすい。
* ロガーを自作して、テスト対象のコードのログも`t.Log()`で出すようにするともっと便利。

# 失敗したテストのログだけを表示できる

```golang
func TestFoo(t *testing.T) {
	log.Println("Fooのログ1")
	log.Println("Fooのログ2")
	log.Println("Fooのログ3")
}

func TestBar(t *testing.T) {
	log.Println("Barのログ1")
	log.Println("Barのログ2")
	log.Println("Barのログ3")
	t.Error("something went wrong")
}
```

このような形で`log.Printf`あるいは`log.Println`でログを出力すると、`TestFoo`に関するログも`TestBar`に関するログも、全てログに出力されます。

```
2019/04/10 13:22:38 Fooのログ1
2019/04/10 13:22:38 Fooのログ2
2019/04/10 13:22:38 Fooのログ3
2019/04/10 13:22:38 Barのログ1
2019/04/10 13:22:38 Barのログ2
2019/04/10 13:22:38 Barのログ3
--- FAIL: TestBar (0.00s)
    some_test.go:18: something went wrong
FAIL
FAIL	tlogexp	0.008s
Error: Tests failed.
```

`TestBar`のFAILの原因を調べるのに見たいのは`TestBar`内で出力されたログです。成功している`TestFoo`のログは調査には不要で邪魔です。テストの数が少なければ、そこまで問題にはなりませんが、テストの数が増えてくると目的のログにたどり着くまでのコストが高くなり、非効率です。

`go test`の引数で、失敗したテストのみを指定して実行しなおして目的のテストに関するログのみを出力することもできますが、実行し直すのは面倒です。

```golang 
func TestFoo(t *testing.T) {
	t.Log("Fooのログ1")
	t.Log("Fooのログ2")
	t.Log("Fooのログ3")
}

func TestBar(t *testing.T) {
	t.Log("Barのログ1")
	t.Log("Barのログ2")
	t.Log("Barのログ3")
	t.Error("something went wrong")
}
```

これを`t.Log()`に置き換えるだけで、失敗したテストのログだけが結果に表示されるようになります。

```
--- FAIL: TestBar (0.00s)
    some_test.go:14: Barのログ1
    some_test.go:15: Barのログ2
    some_test.go:16: Barのログ3
    some_test.go:17: something went wrong
FAIL	tlogexp	0.006s
Error: Tests failed.
```

ログがテスト名の下にネストされた状態で表示され、さらに発生場所の行番号などもわかります。

# テスト対象コード内のログも見たい

`t.Log`は基本的にはテストコード内でしか利用できません。テスト対象コード内のログを見たいときは工夫が必要になります。

## 基本的なアイデア: ロギング用の関数を用意してテストと通常時で切り替える

シンプルなソリューションは、ロギング用の関数(`t.Log` / `t.Logf`)をテストコード側からテスト対象コードに提供することです。

好みの問題ではありますが、ここでは文字列出力が便利な`t.Logf`の方を渡してみましょう。`t.Logf`のシグネチャは下記のようになっています。

```golang
func (format string, args ...interface{})
```

この型の関数を引数として渡せるようにします。

```golang 
func render(title, body string, log func(format string, args ...interface{})) string {
	template := "TITLE: %s\nBODY: %s"
	log("Template: %v", template)
	return fmt.Sprintf(template, title, body)
}

```

テストから呼び出す時は、`t.Logf`を指定します。

```golang
func TestRender(t *testing.T) {
	r := render("Foo", "Bar", t.Logf)
	t.Logf("Result: %v", r)
	t.Errorf("something went wrong")
}
```

テスト対象コード内の`log()`の呼び出しが`t.Logf()`の呼び出しとして処理され、ログに表示されます。

```
--- FAIL: TestRender (0.00s)
    render.go:7: Template: TITLE: %s
        BODY: %s
    render_test.go:27: Result: TITLE: Foo
        BODY: Bar
    render_test.go:28: something went wrong
FAIL	tlogexp	0.005s
Error: Tests failed.
```

幸い、`log.Printf`のシグネチャと`t.Logf`のシグネチャは共通なので、ロギング用関数には`log.Printf`を指定することもできます。テストではなく通常のコードからメソッドを呼び出すときは、`log.Printf`を渡す用にしましょう。

```golang
func main() {
	r := render("Title", "Body", log.Printf)
	log.Printf("Result: %v", r)
}
```

# structにロギング用関数を持たせる

テスト対象が関数ではなくメソッドの場合は、対象のstructにロギング用関数を持たせてしまった方が便利です。毎回のメソッド呼び出しでロギング用関数を引数で渡す必要がなくなります。

```golang 
type renderer struct {
	log func(format string, a ...interface{})
}

func (r *renderer) render(title, body string) string {
	template := "TITLE: %s\nBODY: %s"
	r.log("Template: %v", template)
	return fmt.Sprintf(template, title, body)
}

```

イニシャライザで`log.Printf`をデフォルトのロギング関数として使用するようにセットしておけば、テスト以外のコードではロギング用関数のことを気にせずコードを書けます。

```golang 
func newRenderer() *renderer {
	return &renderer{log: log.Printf}
}

func main() {
	r := newRenderer().render("Title", "Body")
	log.Printf("Result: %v", r)
}
```

テストコードでは、`log`を`t.Logf`で上書きします。

```golang 
func TestRender(t *testing.T) {
	renderer := newRenderer()
	renderer.log = t.Logf

	r := renderer.render("Foo", "Bar")
	t.Logf("Result: %v", r)
	t.Errorf("something went wrong")
}
```

この方式の良いところは、引数でロギング関数を指定する必要がなくなり、テスト対象コードの実装がシンプルになることと、テスト時にロギング関数の指定をしなかった場合でもデフォルトのロギング用関数`log.Printf`が呼び出されクラッシュしたりする危険がないことです。

## 備考: グローバルなロギング関数は?

```golang 
var DebugLog func(format string, a ...interface{})
```

グローバルな関数をどこかに用意しておき、通常の実行時は`log.Printf`をセット、テストでは`t.Logf`をセットする、というやり方も考えられます。

```golang
func main() {
	DebugLog = log.Printf

	r := render("Title", "Body")
	log.Printf("Result: %v", r)
}

func render(title, body string, log func(format string, a ...interface{})) string {
	template := "TITLE: %s\nBODY: %s"
	DebugLog("Template: %v", template)
	return fmt.Sprintf(template, title, body)
}

...

func TestRender(t *testing.T) {
	DebugLog = t.Logf

	r := render("Foo", "Bar")
	t.Logf("Result: %v", r)
	t.Errorf("something went wrong")
}
```

この方法はシンプルで、メソッドではなく関数の実装でもロギング関数を引数として渡す必要がなくなるというメリットがありますが、並列でテストを実行した場合に`DebugLog`が後から実行されたテストで上書きされ、正しいテストのログとして出力できなくなるという問題があります。また、全部のテストケースの先頭で漏れなくDebugLogを設定する必要があり、忘れるとクラッシュの原因になるため、**基本的にオススメしません**。シングルトン的なロガーを作る、というアイデアも同様の理由でオススメできません。