Inside of LOVOT

GROOVE X 技術ブログ

go test のログ出力をキャプチャしてテスト管理ツールと連携する話

開発

この記事はGROOVE X Advent Calendar 2024の19日目の記事です。

こんにちは、QAチームに異動してQA自動化に取り組んでいる Junya です。

最近、 Qase というテスト管理ツールをお試しで利用しているのですが、 go test の実行結果をテストケースに紐づけて Qase へアップロードするのに苦労したので、そのお話をします。

Qase についての詳細は割愛するので、詳細が知りたい方は公式ドキュメントなどを参照してください。

実現したいこと

  • テスト実行時のログをキャプチャしたい
  • t.Run の結果をテストケースのステップに紐づけて保存したい（またの機会に）
  • パラメタライズドテストの結果をQaseのパラメータに紐づけたい（またの機会に）

Qase 連携の2つのアプローチ

go test の結果を Qase 連携する方法として、2つのアプローチがあります。

  • go test や gotestsum を実行してから、CLI を使って Qase にアップロードする
  • go test 実行中のログ出力をキャプチャして、Qase にアップロードする

前者は手軽ですが、go test にきめ細やかなアノテーションの仕組みなどがない関係上、Qase のステップやパラメータなどの概念を活かし切ることが出来ません。 Qase の機能をフル活用するために、今回は後者のアプローチでトライすることにしました。

前者の方法に興味のある方は、こちらのドキュメントを参照してください。

テスト実行時のログをキャプチャする

結論から書いてしまいますね。以下のような構造体を用意して、標準出力の内容を buf へ横取りし、 TestMain と各テストの t.Cleanup で呼び出すことで解決しました。

type StdoutCapturer struct {
    r, w      *os.File
    stdout    *os.File
    buf       *bytes.Buffer
    lastIndex int
}

// NewStdoutCapturer 標準出力をキャプチャするための構造体を生成する
func NewStdoutCapturer() *StdoutCapturer {
    r, w, err := os.Pipe()
    if err != nil {
        log.Fatal(err)
    }
    stdout := os.Stdout

    os.Stdout = w
    var buf bytes.Buffer

    // buf と stdout の両方に書き込む
    tee := io.TeeReader(r, stdout)

    go func() {
        _, _ = buf.ReadFrom(tee)
    }()

    return &StdoutCapturer{r: r, w: w, stdout: stdout, buf: &buf}
}

func (c *StdoutCapturer) Close() {
    _ = c.w.Close()
    _ = c.r.Close()
    os.Stdout = c.stdout
}

// Flush 現時点までに出力された内容を返す
func (c *StdoutCapturer) Flush() string {
    full := c.buf.String()
    content := full[c.lastIndex:]
    c.lastIndex = len(full)
    return content
}

TestMain の実装は以下のとおり。

var capturer testutil.Capturer

func TestMain(m *testing.M) {
    // テストが開始されて `testing.T` が生成される前に標準出力を Capturer で置き換える
    capturer = testutil.NewStdoutCapturer()
    m.Run()
    capturer.Close()
}

capturer をパッケージのグローバル変数で定義しておき、以下のようにテスト内の t.Cleanup で標準出力の内容を取得します。

t.Cleanup(func() {
    captured := capturer.Flush()
    UploadResult(t, captured)  // テスト管理ツールに結果をアップロード
})

ハマりポイント

いくつかハマりポイントがあったので紹介します。

テストの setup, teardown ではフックできない

テストパッケージのグローバル変数に capturer がいるのはイケてないので、以下のように各テストの setup, teardown で標準出力を横取りしたくなります。

func TestExample(t *testing.T) {
    capturer := testutil.NewStdoutCapturer()
    t.Cleanup(func() {
        captured := capturer.Flush()
    })

しかし、これは機能しませんでした。testing のこちらの箇所 で、そもそもテストに入る前に、 T オブジェクトのライターとして os.Stdout を紐づけているためです。

t := &T{
    common: common{
        signal:    make(chan bool, 1),
        barrier:   make(chan bool),
        w:         os.Stdout,
        ctx:       ctx,
        cancelCtx: cancelCtx,
    },
    tstate: tstate,
}

仕方がないので、 TestMain でテスト実行前に os.Stdout を書き換えるようにしました。

t.Cleanup では取得できないログがある（未解決）

go test -v を実行した際の、個別のテストに対する出力は以下のようになります。

1  === RUN   TestExample
2      run_test.go:49: TestExample が呼ばれたよ
3  === NAME  TestExample_Title
4     run_test.go:46: {"status":true,"result":{"case_id":1115,"hash":"xxx"}}
5  --- PASS: TestExample_Title (0.45s)
6      --- PASS: TestExample_Title/TestExample_Title (0.00s)

この中の4行目までは t.Cleanup でキャプチャできるのですが、5行目・6行目は、テスト実行後に go test がログ出力するので、 t.Cleanup では取りこぼしてしまいますが、いったんここは諦めることにしました。

取りこぼした分は、次のテストの実行結果に含まれてしまうので、以下のように Capturer を書き換えて、余計な文字列を除去しています。

// Flush 現時点までに出力された内容を返す
func (c *StdoutCapturer) Flush() string {
    full := c.buf.String()
    content := full[c.lastIndex:]
    c.lastIndex = len(full)

    // Note: PASS, FAIL の判定結果は含まれず、次の Flush に入ってしまうので、一行ずつ読んで "=== RUN" までを無視する
    // TODO: PASS, FAIL の判定結果も Flush に含まれるようにする
    for {
        index := strings.Index(content, "\n")
        if index == -1 {
            break
        }
        line := content[:index]
        if strings.HasPrefix(line, "=== RUN") {
            break
        }
        content = content[index+1:]
    }
    return content
}

t.Log をラップする

以下のようにログ出力をラップする仕組みも試しました。

package wrapper

type Wrapper struct {
    t *testing.T
}

func T (t *testing.T) *Wrapper {
    return &Wrapper{t: t}
}

func (w *Wrapper) Log(args ...interface{}) {
    t.T.Helper()
    // ここに保存処理を書く
    t.T.Log(args...)
}

以下のように使うイメージです。（testify.suite にも似た仕組みがあります）

wrapper.T(t).Log("...")

この場合、テストの中で明示的に t.Log を呼んでいる箇所は置き換えられるのですが、testing モジュールが内部的に出力するログはキャプチャできませんでした。 ただ、このアーキテクチャは有用なので、Qase のステップにログを紐づけたい場合に活用しています。

テスト並行実行時のふるまい（未検証）

os.Stdout を書き換え、各テストの終了時点でフックして標準出力をキャプチャしているので、テストが並行実行されると、キャプチャに複数のテストの内容が混在してしまう可能性があります。

いったん -p 1 オプション（並列数: 1）をつけて go test を実行することで、この問題を回避する予定です。

まとめ

os.Stdout を上書きする強引なアプローチによって、テスト時のログ出力をなんとか Qase （テスト管理ツール）にアップロードできました。 一方で、一部保存できないログがあったり、複数テスト同時実行時のふるまいに不安があったりするので、今後も改善していきたいと思います。

以下のような改善案があるかな、と思ってます。

  • テスト実行時に標準出力を見張る、単一のサービスを動かし、出力をパースして管理する
  • gotestsum の go test -json による json 出力などを活用する（デフォルトのログ出力より解析しやすい）
  • gotestsum や qasectlの開発に貢献して、テスト実行結果 + CLI でも、よりきめ細やかなデータを連携できるようにする

パラメタライズドテストの連携や、Qase のテストケースのステップとの連携部分など、他にも話したいことが沢山あるのですが、それはまたの機会に。

一緒に働く仲間を募集中！

弊社では、そんな開発チームで働く仲間を募集中です。 ぜひご応募ください！

recruit.jobcan.jp