internal/testlog で遊ぼう

layerx.go #5 LT
https://layerx.connpass.com/event/402006/

Transcript

1. internal/testlog で遊ぼう 2026-08-24 layerx.go #5 @rokuosan_dev
2. whoami @rokuosan_dev rokuosan（ろくお） id:rokuokun 敬称は省略できます LayerX バクラク事業部 (2026-08 -) Platform Engineering 部 Enabling チーム インターンです 京都在住 Kyoto.kt 主催 © LayerX Inc.
3. go test (cached)
4. 緊急 キャッシュされる？されない？クイズ
5. Q1. 通常の Go test 例えばこんなテスト © LayerX Inc. 5
6. Q1. 通常の Go test go test を素直に実行する 当然テストが実行される © LayerX Inc. 6
7. Q1. 通常の Go test Q1. 2回目は？ © LayerX Inc. 7
8. Q1. 通常の Go test A2. 2回目は cached そうですね © LayerX Inc. 8
9. Q2. 依存する環境変数やファイルを変更したテスト Q2. 環境変数やモジュール内のファイルを変更すると？ © LayerX Inc. 9
10. Q2. 依存する環境変数やファイルを変更したテスト A2. 実行される © LayerX Inc. 10
11. Q3. モジュール外の変更 モジュール外のファイルを参照してみる © LayerX Inc. 11
12. Q3. モジュール外の変更 Q3. モジュール外のファイルを書き換えたら？ © LayerX Inc. 12
13. Q3. モジュール外の変更 キャッシュされてテストは走らない ファイルを書き換えたのに走らない 困った © LayerX Inc. 13
14. Q3. モジュール外の変更 強制的に実行させる 無事失敗 © LayerX Inc. 14
15. cache の仕組み
16. キャッシュ利用の判定 testID で testlog.txt を取得 testID = テストバイナリの build ID + キャッシュ可能な引数 testlog の各行を今の状態でハッシュして inputsID を作る → 現在の値。未設定かどうかも込み open → mtime と size (中身は読まない) stat → Stat と Lstat の結果 GODEBUG はログに出てこなくても必ず混ぜる getenv subkey(testID, inputsID) © LayerX Inc. で前回の出力を取得できれば (cached) ※ subkey(parent, desc) は親キーと説明文字列を混ぜて派生キーを作る cmd/go 共通のヘルパ。stdout や coverprofile の保存にも使われている 16
17. キャッシュ判定の擬似コード © LayerX Inc. ref: cmd/go/internal/test/test.go tryCacheWithID / computeTestInputsID 17
18. testlog.txt テストが os 越しに触ったものが、そのまま1行ずつ載る モジュール root の外にあるファイルはログには載るが、ハッシュの対象にならない フォーマットについては後述 © LayerX Inc. 18
19. internal/testlog
20. internal/testlog Package testlog provides a back-channel communication path between tests and package os, so that cmd/go can see which environment variables and files a test consults. テストと os の間のバックチャネル cmd/go testing が「テストがどの env / file を見たか」を知るためにある が実装を挿し、 os がそれを呼ぶ 両者が共通で依存できる最下層に置かれている © LayerX Inc. ref: https://github.com/golang/go/blob/go1.26.7/src/internal/testlog/log.go#L5-L7 20
21. Interface os © LayerX Inc. 側は testlog.Open(name) と呼ぶだけ logger が nil なら何もしない ※ atomic.Pointer なのは、init で起きた goroutine と競合しても race detector に引っかからないようにするため 21
22. internal/testlog を自作する
23. Interface を用意する 同じメソッドを同じシグネチャで並べた interface を自前で定義する internal/testlog.Interface © LayerX Inc. は internal なため... 23
24. フォーマットにそって実装する 1行目は # test log で固定 これが無いと malformed 扱いで丸ごと捨てられる あとは op name を1行ずつ。末尾は必ず改行 op は open / stat / getenv / chdir の4つだけ © LayerX Inc. ref: cmd/go/internal/test/test.go testlogMagic 24
25. どうやって動かす？ © LayerX Inc. 25
26. go:linkname による差し込み 本体の無い関数を宣言して、リンカに繋がせる 実体は internal/testlog.SetLogger 渡すのはさっきの自前 interface © LayerX Inc. 26
27. 敗北... Go 1.23 以降のリンカの制限 定義側にマークが無いシンボルは引けない -ldflags=-checklinkname=0 © LayerX Inc. で黙らせる 27
28. checklinkname=0 でも敗北... SetLogger © LayerX Inc. は一度しか呼び出せない ref: https://github.com/golang/go/blob/go1.26.7/src/testing/internal/testdeps/deps.go#L117-L130 28
29. SetLogger を呼ぶ経路 © LayerX Inc. ref: https://github.com/golang/go/blob/go1.26.7/src/testing/testing.go#L2600-L2680 29
30. SetLogger を呼ぶ経路 -test.testlogfile © LayerX Inc. は go test が毎回付けてくる cmd/go がテストバイナリの os.Args を組み立てている *testlog はその値を flag.Parse が受け取ったもの ref: https://github.com/golang/go/blob/go1.26.7/src/testing/testing.go#L2600-L2680 30
31. SetLogger を呼ぶ経路 ここで一度目の SetLogger が呼ばれる さっきの panic はここと衝突 © LayerX Inc. ref: https://github.com/golang/go/blob/go1.26.7/src/testing/testing.go#L2600-L2680 31
32. SetLogger を呼ぶ経路 ここを false のままにしたい os.Args © LayerX Inc. から -test.testlogfile を消せば、この経路ごと実行されない ref: https://github.com/golang/go/blob/go1.26.7/src/testing/testing.go#L2600-L2680 32
33. SetLogger を呼ぶ経路 init © LayerX Inc. で os.Args を書き換えると良さそう ref: https://github.com/golang/go/blob/go1.26.7/src/testing/testing.go#L2600-L2680 33
34. os.Args の書き換えと Logger の置き換え を空文字にしてデフォルトの testlog を無効化 独自実装の testlog を差し込む *testlog © LayerX Inc. 34
35. 自作 testlog を仕込む
36. blank import による利用 で書いたのでこれで完了 ただしパッケージ単位... init() 差し替えたい全パッケージに1行ずつ書く必要がある © LayerX Inc. 36
37. overlay による差し込み -overlay © LayerX Inc. は存在しないパスを実ファイルに割り当てられる 37
38. 差し込んでみる © LayerX Inc. 38
39. 実行してみる © LayerX Inc. 39
40. ここからが本題
41. 自作 testlog で遊んでみる © LayerX Inc. 41
42. GitHub Actions で (cached) 出ない問題 checkout のたびに全ファイルの mtime が更新される キャッシュを復元しても無駄 中身ではなく mtime で判定しているため golang/go にも issue がある golang/go #58571 © LayerX Inc. ref: golang/go#58571 「cmd/go: test cache hash inputs include ModTime, often causing cache misses on CI」 42
43. mtime はどこでハッシュに入るか(1/2) / mode / mtime / isdir をハッシュに書く #58571 でも言及されている size © LayerX Inc. ref: https://github.com/golang/go/blob/go1.26.7/src/cmd/go/internal/test/test.go#L2138-L2140 43
44. mtime はどこでハッシュに入るか(2/2) これを実行すると以下の testlog が出る cmd/go はこの行を見て os.Stat し、実ファイルの mtime をハッシュに混ぜる これによって checkout のたびに実ファイルの mtime は新品になる © LayerX Inc. 44
45. 余談: なぜ中身ではなく mtime なのか 中身を丸ごとハッシュしない 巨大なファイルを毎回読むコストを避けるため 代わりに mtime + size で「たぶん変わっていない」を推測する 正確だが遅い方法を捨てて、速いが不正確な方法を選んでいる © LayerX Inc. ref: https://github.com/golang/go/blob/go1.26.7/src/cmd/go/internal/test/test.go#L2107-L2110 45
46. 中身が変わったものだけ mtime が動いてほしい © LayerX Inc. 46
47. 自作 testlog で見る先をすり替える testlog.txt は扱えるようになった 実ファイルの代わりに、中身が変わった時だけ mtime が動く代理ファイルを指すよう に書き換える test 実行前に中身が更新されていたら上書きする © LayerX Inc. 47
48. 余談: なぜ open ではなく stat で書くか hashOpen では2秒以内に更新されたファイルの結果を保存しない仕様がある mtime の精度ではごく短い間隔の更新を区別できないことがあるため © LayerX Inc. ref: https://github.com/golang/go/blob/go1.26.7/src/cmd/go/internal/test/test.go#L2112-L2118 48
49. こんな感じ テスト実行前に生成を忘れると破滅することには注意 古いハッシュを見続けるためずっと OK のまま © LayerX Inc. 49
50. まとめ (cached) は中身ではなくサイズや mtime で判断している internal/testlog を通じて、前回何を触ったかが記録されている internal package でも linkname と overlay で挙動を変更できる GitHub Actions で別ジョブを跨ぐと go test は cached にならない checkout のたびに mtime が新品になるため 自作 testlog を使えば常に成功する go test を爆誕させることも可能 © LayerX Inc. 50