Go 1.22リリース連載 vet, log/slog, testing/slogtest

はじめに

TIG 真野です。Go1.22連載の6本目です。

Go 1.22のアップデートのツーリングのうち Vet と、ライブラリのマイナーアップデートである log/slog, testing/slogtest を取り上げて紹介します。

アップデートサマリ

Vetでループ変数の変数キャプチャを検知しなくなった #63888
Vetで slice1 = append(slice1) の操作を検知するようになりました #63888
Vetで defer で time.Since() が呼ぶ操作を検知するようになりました #60448
Vetで不正な log/slog なキーと値のペアを検知するようになりました #59407
log/slog で SetLogLoggerLevel()が追加されました #62418
testing/slogtestで Run() 関数が追加されサブテストの制御がしやすくなりました #61758

Vet ループ変数の変数キャプチャ #63888

Go 1.22リリース連載始まります & ループの変化とTinyGo 0.31で説明されている通り、Goのループ変数は単なる参照だったためgoroutineにループ変数を渡すときにはいくつかのお作法がありました。go vetではありがちなミスを検知してくれていました。

よくありがちな例

func main() {
	const N = 4
	var wg sync.WaitGroup
	for i := 0; i < N; i++ {
		wg.Add(1)
		go func() { defer wg.Done(); fmt.Println(i) }()
	}
	wg.Wait()
}

go1.21以前ですと、次のように0から4の値を出力するはずが、全く直感と反する挙動です。go vetコマンドでその間違いを検知してくれました。

>go run main.go
4
4
4
3

>go vet
main.go:13:44: loop variable i captured by func literal

go1.22以降では、goroutine起動なので順序制御はされないものの（これは想定通りですね）、ループ変数が1つずつgoroutineに渡っていることが分かります。

go run vetloop.go 
3
0
1
2

正しく動いたので、go vetも検知しないようになりました。

go vet                   
.\main.go:13:44: loop variable i captured by func literal

…ってあれ、変わらないですね。なんででしょう。試したのは go1.22rc2 です。まだ作業中なのかも知れません。後で調査したいと思います。

Vet Sliceの意味のないappend #63888

みなさんは知っていましたでしょうか？ append() が引数を取らなくても文法上は有効なことを。例えば次のようなコードはコンパイルもでき実行できます。

package main

import "fmt"

func main() {

	sli1 := []string{"a", "b", "c"}
	sli2 := make([]string, 0)

	for _, v := range sli1 {
		fmt.Println(v)
		sli2 = append(sli2) // ★ポイント
	}
	fmt.Println(sli2) // []
}

本来の想定は sli2 = append(sli2, v) だと思いますが、手違いで上記のようなコードが生まれると、良くて混乱の元、通常はバグの元なので、go vetで検知する事になりました。

さて、Vetに追加するにはポリシーに沿っているかが重要です。ポリシーは次のようなものです。

Vetは利用頻度が高く、実行時間が重要
バグである可能性が高い静的解析であっても、既存リポジトリで該当が少ないのであれば追加しない

今回のチェック内容ですが、約 276,000 の Go プロジェクトのうち650 のプロジェクトで 727 の問題を検知したようです。これは数が少ないので基準を満たしていない？といったコメントもありました。検知した内容でモジュールの利用頻度でソートしたトップ20を提示して、どうするかをディスカッションしています。

これで流れが決まり、Vetに含まれることになりました。空中戦にならず集計調査を実施しファクトから判断する流れは気持ちが良いですね。

ちなみにですが、このチェック内容、StaticCheckにはすでに入っているということで、それを使っている方や、StaticCheckはgolangci-lintのデフォルトリンターでもあるので、golangci-lintをカスタマイズせずに使っている方は、この変更で追加で検知されることは多分無いです。ええええ、残念。

https://github.com/golang/go/blob/go1.21.6/src/cmd/vet/README#L18-L23

Vet deferで time.Since() の呼び出し #60048

time.Since() のユースケースは何かしらの時間を計測するときに用いられます。例えば、処理性能をロギングしたい場合は次のように書きがちです。

time.Sinceの誤用例

package main

import (
	"fmt"
	"time"
)

func main() {
	start := time.Now()
	defer fmt.Println(time.Since(start))

	// 何かしらの処理の代わりに、1秒スリープする
	time.Sleep(1 * time.Second)
}

これを実行すると 0s が出力されます。

正しくは以下です。

正しい例

package main

import (
	"fmt"
	"time"
)

func main() {
	start := time.Now()
-	defer fmt.Println(time.Since(start))
+	defer func() { fmt.Println(time.Since(start)) }()

	// 何かしらの処理の代わりに、1秒スリープする
	time.Sleep(1 * time.Second)
}

実行すると 1.0081377s などと想定通りの結果となります。

defer へ渡された関数の呼び出しは、元の関数がreturnするタイミングですが、その関数に渡した 引数は即時評価されるためです。 defer\ [^{]*time.Since などで検索すると、GoogleCloudPlatform/prometheus　など大物リポジトリでもヒット、他にも多数該当するリポジトリがあるということで、Vet入りが決まりました。

検知されると次のようなメッセージが出力されます。分かりやすいですね。

>go vet
main.go:11:20: call to time.Since is not deferred

Vet log/slogで不正なキーと値のペア #59407

slogのキーと値のペアのうち、以下の2条件で検知してくれるようになりました。

キーがstringでもslog.Attrでもない
最後のキーが見つからない（ペアになっていない）

簡単な例です。この実装では 2 が本来キー名に当たるのですが、数値型となり不正です。

1のパターン

package main

import "log/slog"

func main() {
	slog.Info("", "key1", 1, 2, 3, slog.String("attr1", "b")) // key1=1 !BADKEY=2 !BADKEY=3 attr1=b
}

run と vet の結果は次の通りです。vetでは2 が string か slog.Attr にしろと教えてくれますね。便利。

>go run main.go
2024/01/30 11:16:35 INFO  key1=1 !BADKEY=2 !BADKEY=3 attr1=b

>go vet
.\main.go:6:27: slog.Info arg "2" should be a string or a slog.Attr (possible missing key or value)

しかし、... を利用したスプレッド構文で渡した場合は検知できません。

package main

import "log/slog"

func main() {
	args := []any{"key1", 1, 2, 3, slog.String("attr1", "b")}
	slog.Info("", args...)
}

上記は次のように、 run では正しく無いレイアウトでありますが、 vet では検知されません。

>go run main.go
2024/01/30 11:23:01 INFO  key1=1 !BADKEY=2 !BADKEY=3 attr1=b

>go vet

この点はプロポーサルでも触れられており、スプレッド構文は一律NGとしてはどうか、という話もありましたが、こちらは誤検知が考えられ、vetのポリシーから外れるとして棄却されていました。方針と対応が一貫しており、有無を言わさない感じがGoぽいと思いました。

log/slog SetLogLoggerLevel()の追加 #62418

slog繋がりで log/slog アップデートです。

SetLogLoggerLevel() 関数の新規追加されました。SetLogLoggerLevel() でデフォルトlogパッケージ側のログレベルを変更できます（現状はINFO固定だと思います）。

本当にレベルを変えて出力したい場合は、標準のlog.Printf()などではなく、slog.Warn() などを使えば良いので、悪くないデフォルト値だと思いますが、プロポーサルでは、デフォルト log パッケージはデフォルトで stderrに出力するため、ログレベルを変更できたほうが便利だろう、という提案です。

func SetLogLoggerLevel(level Level) (oldLevel Level)

この関数ですが、slog.SetDefault() が呼ばれる前と後で、slog.Debug() など、slog経由のロギングにも影響します。業務などでは slog.SetDefault() をおそらくmainのエントリーポイントに近い場所で呼び出すと思うため、通常は細かい挙動の差を意識しなくても良いと思います。繰り返しますが本来の意図としては、標準のlogパッケージのログレベルを変更するためのものです。

…と言いながらもも slog.SetDefault() を呼び出さず、
SetLogLoggerLevel() を呼んで、slogと標準のlogパッケージで挙動がどう変わるか試します。

package main

import (
	"log"
	"log/slog"
)

func main() {
	log.Println("========デフォルトのログレベルはINFO=========")
	log.Print("log debug🐛")   // log debug
	slog.Debug("slog debug🐛") // ★no output
	slog.Info("slog info🔍")   // INFO info

	log.Println("========ログレベルをDEBUGに変更=========")
	slog.SetLogLoggerLevel(slog.LevelDebug)
	log.Print("log debug🐛")   // log debug
	slog.Debug("slog debug🐛") // ★「DEBUG debug」となり出力されるようになる
	slog.Info("slog info🔍")   // INFO info
}

>go run main.go
2024/01/30 12:53:14 ========デフォルトのログレベルはINFO=========
2024/01/30 12:53:14 log debug🐛
2024/01/30 12:53:14 INFO slog info🔍
2024/01/30 12:53:14 ========ログレベルをDEBUGに変更=========
2024/01/30 12:53:14 log debug🐛
2024/01/30 12:53:14 DEBUG slog debug🐛
2024/01/30 12:53:14 INFO slog info🔍

動きを見ると、slog.SetLogLoggerLevel(slog.LevelDebug) を呼び出すと、slog.Debug() が出力されるようになったことが分かります。slog.SetDefault()を呼び出さない前提だと、slog パッケージ経由のログ出力を、ログレベルでフィルターするような挙動となります。

次に、 slog.SetDefault() でlogパッケージで用いるロガーをslog形式に変更した場合に、slog.SetLogLoggerLevel() がどう影響するか試します。

package main

import (
	"log"
	"log/slog"
	"os"
)

func main() {
	slog.SetLogLoggerLevel(slog.LevelError)
	slog.SetDefault(slog.New(slog.NewJSONHandler(os.Stdout, nil)))

	slog.Info("slog info: go1.22 blog series🔍")
	slog.Warn("slog warn: go1.22 blog series⚠️")
	slog.Error("slog error: go1.22 blog series🚨")

	log.Print("log print: go1.22 blog series📝")
}

これを実行すると次のように、logパッケージ経由の出力も、ログレベルがERRORで出力されることがわかります。このケースですと、ややこしいですがslog側のERROR未満のログは抑制されません。

出力結果

>go run main2.go
{"time":"2024-01-30T13:02:46.9325009+09:00","level":"INFO","msg":"slog info: go1.22 blog series🔍"}
{"time":"2024-01-30T13:02:46.9659968+09:00","level":"WARN","msg":"slog warn: go1.22 blog series⚠️"}
{"time":"2024-01-30T13:02:46.966573+09:00","level":"ERROR","msg":"slog error: go1.22 blog series🚨"}
{"time":"2024-01-30T13:02:46.966573+09:00","level":"ERROR","msg":"log print: go1.22 blog series📝"}

少しややこしいですが、 slog.SetLogLoggerLevel() は slog.SetDefault() の呼び出し有無で、 slog.Debug()やslog.Info() などを制御するモードが変わると思った方が理解しやすいです。

ちなみに、次のように、 slog.SetLogLoggerLevel() ではERRORレベル、 slog.SetDefault() にわたすHandlerのログレベルにWARNを渡しても、標準のlog パッケージの出力はERRORレベルで出力されます。

package main

import (
	"log"
	"log/slog"
	"os"
)

func main() {
	slog.SetLogLoggerLevel(slog.LevelError) // ERROR
	slog.SetDefault(slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{
		Level: slog.LevelWarn, //WARN
	})))
	log.Print("log print: go1.22 blog series🐙")
}

出力結果

> go run main.go
{"time":"2024-01-30T13:20:15.5788942+09:00","level":"ERROR","msg":"log print: go1.22 blog series🐙"}

逆に、slog.SetLogLoggerLevel() ではINFOレベルに返ると出力されません。logパッケージのログレベルがINFO、デフォルトロガーのレベルがWARNのため、WARN未満である log.Print() の内容は出力されません。

package main

import (
	"log"
	"log/slog"
	"os"
)

func main() {
-	slog.SetLogLoggerLevel(slog.LevelError) // ERROR
+	slog.SetLogLoggerLevel(slog.LevelInfo) // INFO
	slog.SetDefault(slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{
		Level: slog.LevelWarn, //WARN
	})))
	log.Print("log print: go1.22 blog series🐙")
}

>go run main.go

理にかなった挙動に見えますが、それぞれにしたログレベル値によっては、log, slog どちらも併用すると混乱しそうですね。

testing/slogtest Run()の追加 #61758

slogは slog.Handler インタフェースを満たすことで、最終的な出力レイアウトを切り替える仕組みがあります。さきほどの slog.NewJSONHandler() はJSONで出力するHandlerでしたよね。調べるとgo-slog/awesome-slog のようなAwesomeなリポジトリも見つかるほど、多くのHandlerが存在することが分かります。

Go1.21のslogの登場とともに、Handlerをテストする testing/slogtest というパッケージが追加されましたが、そこにRun()関数が追加されました。

まずslogtestパッケージってなに？ってことですが、簡単にいうと予め準備されたslogのテストケースを呼び出すテストヘルパーです。どのようなケースかと言いますと、slogtest.go のcases変数を見ると分かります。

slogtestのテストケース

var cases = []testCase{
	{
		name:        "built-ins",
		explanation: withSource("this test expects slog.TimeKey, slog.LevelKey and slog.MessageKey"),
		f: func(l *slog.Logger) {
			l.Info("message")
		},
		checks: []check{
			hasKey(slog.TimeKey),
			hasKey(slog.LevelKey),
			hasAttr(slog.MessageKey, "message"),
		},
	},
	{
		name:        "attrs",
		explanation: withSource("a Handler should output attributes passed to the logging function"),
		f: func(l *slog.Logger) {
			l.Info("message", "k", "v")
		},
		checks: []check{
			hasAttr("k", "v"),
//以下略

GoDocのExampleに書いてある使い方としては、テスト対象のslog.Handlerを引数に渡して、 slogtest.TestHandler(h, results) のように呼び出すと、上記であげたテストケースが実行されます。

import (
	"bytes"
	"encoding/json"
	"log"
	"log/slog"
	"testing/slogtest"
)

func TestMySlogHandler() {
	var buf bytes.Buffer
	h := slog.NewJSONHandler(&buf, nil)

	results := func() []map[string]any {
		var ms []map[string]any
		for _, line := range bytes.Split(buf.Bytes(), []byte{'\n'}) {
			if len(line) == 0 {
				continue
			}
			var m map[string]any
			if err := json.Unmarshal(line, &m); err != nil {
				t.Fatal(err) // JSONに変換できない場合は失敗扱い
			}
			ms = append(ms, m)
		}
		return ms
	}
	err := slogtest.TestHandler(h, results)
	if err != nil {
		t.Errorf("report from testing/slogtest.TestHandler: %v", err)
	}

}

この課題ですが、プロポーサルに記載されているように、TestSlogHandler という1つのフラットな関数でテストが実行されるため、どこか1ケースが落ちた際に切り分けがしにくいということが上げられていました。そこでgo test -run TestSlogHandler/ignore.an.empty.Attr のように各1ケースごとサブテストで動かすことを行う Run() 関数が追加されました。

slog.Handlerを作る人は要チェックだと思います。作り方はガイドラインもあるようなので、併せて確認すると良さそうです。