go の slog with JSON の謎

これは何？

go の slog に嫌がらせをしてみた記録。

普通の使い方

普通はこういう感じで使うんだと思う

go

opts := &slog.HandlerOptions{
	Level: slog.LevelError,
}
logger := slog.New(slog.NewJSONHandler(os.Stdout, opts))

logger.Error("hoge")
//=> {"time":"2024-略","level":"ERROR","msg":"hoge"}

logger.Error("hoge", "fuga", "piyo")
//=> {"time":"2024-略","level":"ERROR","msg":"hoge","fuga":"piyo"}

logger.Error("hoge", slog.String("fuga", "piyo"))
// => {"time":"2024-略","level":"ERROR","msg":"hoge","fuga":"piyo"}

logger.Error の引数が気持ち悪いなと思い（個人の感想です）、嫌がらせをしたくなった。

嫌がらせ

数が合わない

go

logger.Error("hoge", "fuga")
//=> {"time":"2024-略","level":"ERROR","msg":"hoge","!BADKEY":"fuga"}

"!BADKEY" と文句をいってくるが、コンパイルは普通にできる。
staticcheck（たぶん）が

call to slog.Logger.Error missing a final valueslogdefault

という警告を出してくれるけれど。

キーが "time"

go

logger.Error("hoge", "time", "TIME!")
// => {"time":"2024-略","level":"ERROR","msg":"hoge","time":"TIME!"}

この嫌がらせをやるきっかけになった思いつき。
キーが "time" だとどうなるの？　と思ったら、上記のとおりになった。
これを例えば ruby に食べさせると

ruby

JSON.parse(%Q<{"time":"2024-略","level":"ERROR","msg":"hoge","time":"TIME!"}>)
# => {"time"=>"TIME!", "level"=>"ERROR", "msg"=>"hoge"}

と、本来の時間は読めない。そりゃそうだ。

キーの重複

go

logger.Error("hoge", "fuga", 2, "fuga", "3")
// {"time":"2024-略","level":"ERROR","msg":"hoge","fuga":2,"fuga":"3"}

logger.Error("hoge", slog.Int("fuga", 4), slog.Any("fuga", "5"))
// {"time":"2024-略","level":"ERROR","msg":"hoge","fuga":4,"fuga":"5"}

キーの重複を突っ込んでみたら、やはり順番通りに出る。
エラーも警告も出ないので重複チェックはしていない模様。

もちろんこれもまともな JSON パーサに食べさせるとまともには読めない。エラーか後勝ちだと思う。

まともな JSON パーサが読めないものをカジュアルに出力しちゃうものなので、JSON を出しているとはちょっと言いにくいと思う。

string のような値

go

type STR string
logger.Error("hoge", "fuga", STR("piyo"))
//=> {"time":"2024-略","level":"ERROR","msg":"hoge","fuga":"piyo"}

string のような値をいれると、string ではないという情報は失われる。それは JSON なんだから仕方ない。

string のようなキー

go

type STR string
logger.Error("hoge", STR("hoge"), STR("fuga"))
//=> {"time":"2024-略","level":"ERROR","msg":"hoge","!BADKEY":"hoge","!BADKEY":"fuga"}

キーの方に string のようなものをいれると、"!BADKEY" になる。

!BADKEY のあと

go

type STR string
logger.Error("hoge", STR("key0"), "val0", "key1", "val1")
//=> {"time":"2024-略","level":"ERROR","msg":"hoge","!BADKEY":"key0","val0":"key1","!BADKEY":"val1"}

途中で型を間違えると、その先のキーと値が逆になる。

値が slog.Int

go

logger.Error("hoge", "fuga", slog.Int("piyo", 1))
//=> {"time":"2024-略","level":"ERROR","msg":"hoge","fuga":{"Key":"piyo","Value":{}}}

"!BADVALUE" などにはならない。
そしてなぜか {"Key":"piyo","Value":1} ではなく {"Key":"piyo","Value":{}} となる。なぜなのか。

まあミスと嫌がらせ以外でこういうことを書くことはないからよいのだけれど。

値が []uint8

これは slog というよりも go の JSON シリアライザがどうかしている（個人の感想です）という話だけれど。

go

logger.Error("hoge", "fuga", []int{1})
//=> {"time":"2024-略","level":"ERROR","msg":"hoge","fuga":[1]}
logger.Error("hoge", "fuga", [1]uint8{1})
//=> {"time":"2024-略","level":"ERROR","msg":"hoge","fuga":[1]}
logger.Error("hoge", "fuga", []uint8{1})
//=> {"time":"2024-略","level":"ERROR","msg":"hoge","fuga":"AQ=="}

上記の通り []uint8 のときだけ頼んでないのに base64 になる。
base64 になって嬉しい人が稀にいるのはわかるけれど、デフォルトで base64 になるのはどうかしていると思っている（個人の感想です）。

まとめ

logger.Error("hoge", slog.Int("fuga", val)) のような形式だと安心感があるけど、書くのがめんどくさいよね。

かといって、go には key-value-pair を簡単に書く文法はない。

ということで、現状の、書きやすいけど気持ち悪い（個人の感想です）書式になったんだと思う（思っているだけ。調べてない）

それと。
slog が出す 1行 JSON のようなものは、キーの重複を来にしないという点はあまり JSON らしくない。
かといって、コンマで区切って読めるということでもないので、真剣にパースしようと思うとなにか書く必要がありそう。

そういう事態を避けるためには、"time" などのキーを避ければよいわけだけれど、"!BADKEY" のようなものもあり「これを避ければ安全」というリストは今のところ発見できていない。

あと。

この調査の前は

json

{"time":"2024-略","level":"ERROR","msg":"hoge","fuga":"piyo"}

等とせずに、下記のように

json

{"time":"2024-略","level":"ERROR", "msg":"hoge", "opts":{"fuga":"piyo"}}

ユーザー定義キーと slog が勝手に決めたキーを別の空間にすればいいのにとも思っていたけれど、どうせユーザー定義キーが重複してもエラーも警告も出さずにダラダラ出してくるのでもうどうでもよくなった。

ということで。

まあ キーの重複に気をつけながら普通に使えば便利と思うので普通に使いましょうということだと思う。