“golang.org/x/exp/slog”と”log/slog”

Goの構造化ログを出力するのに公式のslogを利用している。こんな感じで初期化して、Defaultをjsonにしていた。


func initLogger(config *departures.Config) error {
	logLevel := slog.LevelInfo
	switch config.LogLevel {
	case "debug":
		logLevel = slog.LevelDebug
	case "warn":
		logLevel = slog.LevelWarn
	case "error":
		logLevel = slog.LevelError
	}
	ops := slog.HandlerOptions{
		Level: logLevel,
	}
	logOutput := os.Stdout
	if config.LogFile != "" {
		f, err := os.OpenFile(config.LogFile, os.O_RDWR|os.O_CREATE|os.O_APPEND, 0644)
		if err != nil {
			return fmt.Errorf("error opening file :%s", err)
		}
		logOutput = f
	}

	logger := slog.New(slog.NewJSONHandler(logOutput, &ops))
	slog.SetDefault(logger)
	return nil
}

それで、こんな感じでWEBサーバのアクセスログを吐いている。


func Logger(next http.Handler) http.Handler {
	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		reqStart := time.Now()
		rww := newRwWrapper(w)
		next.ServeHTTP(rww, r)
		reqEnd := time.Now()
		slog.Info("request",
			slog.String("method", r.Method),
			slog.String("host", r.Host),
			slog.String("request_uri", r.RequestURI),
			slog.String("remote_addr", r.RemoteAddr),
			slog.Duration("duration", reqEnd.Sub(reqStart)),
			slog.Int("status", rww.status),
			slog.String("content_length", rww.Header().Get("Content-Length")),
		)
	})
}

このときに、こんなログがでていた。

{"time":"2023-11-27T10:26:42.946110367+09:00","level":"INFO","msg":"INFO proxy request.method=GET request.host=example.com request.request_uri=/ request.remote_addr=xxx.xxx.xxx.xxx:yyy request.duration=356.058µs request.status=502 request.content_length=\"\""}  

msgの中にINFOが入れ子になっていて、なんでや〜〜と思ってたら、

vim-goにimportをすべて委ねているので気づかなかった。slogは "golang.org/x/exp/slog" から導入雨が始まった経緯があり、現状のバージョンでは "log/slog" になっている。Defaultの設定は "log/slog" で行っているが、利用するときに "golang.org/x/exp/slog" になっていたので、うまく行ってなかった。