go testのtest.testlogfileフラグが時々便利

test.testlogfileを付けてテストを実行すると、テスト中の以下が分かる。

  • os.Stat()したファイル
  • os.Open()したファイル
  • os.Getenvした環境変数

これは、例えば、net/http.FileSystemが使われた様なテストなどで苦しめられたときに便利に働くことがある。

例えば、hello_test.goと以下のようなファイルがあったとして。

.
├── hello_test.go
├── testdata
│   └── hello.json
└── x.log

1 directory, 3 files

おもむろに以下の様な形でテストを実行してみる。

$ go test -v -test.testlogfile=x.log
=== RUN   TestIt
--- PASS: TestIt (0.01s)
PASS
ok      github.com/podhmo/individual-sandbox/daily/20200821/example_go/04file   0.016s

このとき、-test.testlogfileに渡したx.logを覗いてみると以下の様な行が書かれている。

# test log
open testdata/hello.json
open /etc/mime.types
open /etc/apache2/mime.types
open /etc/apache/mime.types

testdata/hello.json。。

そうそう、今回のテストではtestdataの中に書かれたhello.jsonを読み込む様なコードを書いていた。

実際のテストコード

ざっくり説明すると、以下の様な感じのテストコード。

  • GET /hello にアクセスするHello()というメソッドを持ったClient
  • testdataを見て、/helloに対して testdata/hello.jsonを見る様なHandler
  • net/http.HandlerからRoundTripperをTransportに指定するfake
  • (実は、クライアントライブラリのテストにhttptest.Serverではなくhttptest.Recorderも使えるというコード例だったりもする)
package main

import (
    "bytes"
    "fmt"
    "io"
    "net/http"
    "net/http/httptest"
    "strings"
    "testing"
    "time"
)

type Client struct {
    BaseURL    string
    HTTPClient *http.Client
}

func (c *Client) Hello() (*http.Response, error) {
    hc := c.HTTPClient
    if hc == nil {
        hc = http.DefaultClient
    }
    return hc.Get(strings.TrimSuffix(c.BaseURL, "/") + "/hello")
}

type HandlerRoundTripper struct {
    Before  func(*http.Request)
    Handler http.Handler
    After   func(*http.Response, *http.Request)
}

func (t *HandlerRoundTripper) RoundTrip(r *http.Request) (*http.Response, error) {
    if t.Before != nil {
        t.Before(r)
    }
    w := httptest.NewRecorder()
    t.Handler.ServeHTTP(w, r)
    res := w.Result()
    if t.After != nil {
        t.After(res, r)
    }
    return res, nil
}

func TestIt(t *testing.T) {
    c := &Client{
        HTTPClient: &http.Client{
            Timeout: 100 * time.Millisecond,
            Transport: &HandlerRoundTripper{
                Before: func(r *http.Request) {
                    // /hello -> testdata/hello.json
                    r.URL.Path = fmt.Sprintf("%s.json", strings.TrimSuffix(r.URL.Path, "/"))
                },
                Handler: http.FileServer(http.Dir("testdata")),
            },
        },
    }
    res, err := c.Hello()
    if err != nil {
        t.Fatal(err)
    }
    defer res.Body.Close()
    var b bytes.Buffer
    io.Copy(&b, res.Body)

    if res.StatusCode != 200 {
        t.Errorf("unexpected: %s", res.Status)
    }

    if strings.TrimSpace(b.String()) != strings.TrimSpace(`{"message": "hello"}`) {
        t.Errorf("unmatch: %s", b.String())
    }
}

はい。

実際の実装

testing/testing.goを覗くと以下の様な記述がある。

   testlog = flag.String("test.testlogfile", "", "write test action log to `file` (for use only by cmd/go)")

ここでtestlogというフラグをonにしている1

これがonになると、testing.MのRun()の中のbefore()で、m.deps.StartTestLog(f)が呼ばれる。

// before runs before all testing.
func (m *M) before() {

// ... (ちなみにここでcpuprofileやmemprofileの設定などをしていたりする)

    if *testlog != "" {
        // Note: Not using toOutputDir.
        // This file is for use by cmd/go, not users.
        var f *os.File
        var err error
        if m.numRun == 1 {
            f, err = os.Create(*testlog)
        } else {
            f, err = os.OpenFile(*testlog, os.O_WRONLY, 0)
            if err == nil {
                f.Seek(0, io.SeekEnd)
            }
        }
        if err != nil {
            fmt.Fprintf(os.Stderr, "testing: %s\n", err)
            os.Exit(2)
        }
        m.deps.StartTestLog(f) // <- これ
        testlogFile = f
    }

それでは m.deps というものは何者かと言うと、こういうinterface。コメントに書いてある通り、go testで生成されるコードのmainパッケージの中でimportされる。

// testDeps is an internal interface of functionality that is
// passed into this package by a test's generated main package.
// The canonical implementation of this interface is
// testing/internal/testdeps's TestDeps.
type testDeps interface {
    ImportPath() string
    MatchString(pat, str string) (bool, error)
    StartCPUProfile(io.Writer) error
    StopCPUProfile()
    StartTestLog(io.Writer)
    StopTestLog() error
    WriteProfileTo(string, io.Writer, int) error
}

testing/internal/testdepsを覗いてみる。それっぽいhookが定義されてきつつありますね。

// testLog implements testlog.Interface, logging actions by package os.
type testLog struct {
    mu  sync.Mutex
    w   *bufio.Writer
    set bool
}

func (l *testLog) Getenv(key string) {
    l.add("getenv", key)
}

func (l *testLog) Open(name string) {
    l.add("open", name)
}

func (l *testLog) Stat(name string) {
    l.add("stat", name)
}

func (l *testLog) Chdir(name string) {
    l.add("chdir", name)
}

ここでおもむろにos.Stat()あたりの実装を覗いてみましょう。

os/stat.go

import "internal/testlog"

// Stat returns a FileInfo describing the named file.
// If there is an error, it will be of type *PathError.
func Stat(name string) (FileInfo, error) {
    testlog.Stat(name)
    return statNolog(name)
}

そして internal/testlog/log.go

// logger is the current logger Interface.
// We use an atomic.Value in case test startup
// is racing with goroutines started during init.
// That must not cause a race detector failure,
// although it will still result in limited visibility
// into exactly what those goroutines do.
var logger atomic.Value

// SetLogger sets the test logger implementation for the current process.
// It must be called only once, at process startup.
func SetLogger(impl Interface) {
    if logger.Load() != nil {
        panic("testlog: SetLogger must be called only once")
    }
    logger.Store(&impl)
}

// Stat calls Logger().Stat, if a logger has been set.
func Stat(name string) {
    if log := Logger(); log != nil {
        log.Stat(name)
    }
}

あらためて、testing/internal/testdeps/deps.goを

package testdeps

import (
    "bufio"
    "internal/testlog"
    "io"
    "regexp"
    "runtime/pprof"
    "strings"
    "sync"
)

...
var log testLog

func (TestDeps) StartTestLog(w io.Writer) {
    log.mu.Lock()
    log.w = bufio.NewWriter(w)
    if !log.set {
        // Tests that define TestMain and then run m.Run multiple times
        // will call StartTestLog/StopTestLog multiple times.
        // Checking log.set avoids calling testlog.SetLogger multiple times
        // (which will panic) and also avoids writing the header multiple times.
        log.set = true
        testlog.SetLogger(&log) // <- これ!
        log.w.WriteString("# test log\n") // known to cmd/go/internal/test/test.go
    }
    log.mu.Unlock()
}

はい。つまりそういうわけでした。おしまい。

gist


  1. go testの実行のされ方を追いかけてみると意外と参考になる部分があったりするのでおすすめ。injectされるコード自体は https://github.com/golang/go/blob/master/src/cmd/go/internal/load/test.go あたりにあります。injectするコードはもちろん go test に関連がある https://github.com/golang/go/blob/master/src/cmd/go/internal/test/test.go あたりですね。