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

三行で

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

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

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の引数で、失敗したテストのみを指定して実行しなおして目的のテストに関するログのみを出力することもできますが、実行し直すのは面倒です。

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のシグネチャは下記のようになっています。

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

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

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を指定します。

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を渡す用にしましょう。

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

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

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

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をデフォルトのロギング関数として使用するようにセットしておけば、テスト以外のコードではロギング用関数のことを気にせずコードを書けます。

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

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

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

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が呼び出されクラッシュしたりする危険がないことです。

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

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

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

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を設定する必要があり、忘れるとクラッシュの原因になるため、基本的にオススメしません。シングルトン的なロガーを作る、というアイデアも同様の理由でオススメできません。