構造化ログ
構造化ログパッケージ golang.org/x/exp/slog
今年はまったく活動を行わなかった為、少しでも活動した気分になれればと思い筆を取った次第です。
Goは1.20辺りでgo V2になるとかの話もありましたが、一旦1.20もrc1が出てきました。そんな中先日「golang.org/x/exp/slog」というパッケージがリリースされました。
A consistent logging format for Go(YouTube)
標準パッケージのlogは、使ったことがある人ならわかりますが、構造化どころかレベリングにも対応しておらず、ライブラリ作者、またその使用者は苦悩することが多いのではないでしょうか？
例えばライブラリAがサードパーティのlog1パッケージを使って、ライブラリBがlog2パッケージを使ってログを出力した場合、使用者側は双方にレベリングを行う必要があります。もしこれが一本化されたら、、、いいですね！
これが標準に載るようなら、使用者側もそれらをコントロールするだけになります。とはいえ標準になるということは多くの意思を組んだ実装にならなければ行けない為、影響は大きく、議論も盛り上がっております。
上記概要からリンクありますが、一応リンク貼っておきます。
github.com/golang/go/discussions/54763
まだexpの段階（標準になるかも別の話）ですが、今回は現状の仕様をみていきたいと思います。
出力してみる
一旦レベリングを意識して出力してみましょう。
slog.Debug("Debug")
slog.Info("Info")
slog.Warn("Warn")
-----------------------------------------------
2022/12/10 05:29:00 INFO Info
2022/12/10 05:29:00 WARN WarnデフォルトのレベルがInfoなのでDebugが出力されてないことがわかります。 出力されるメソッドにはDebug(),Info(),Warn(),Error() ,Log()があり、Error() は引数にerrorがあり、Log()はレベル指定のメソッドの為、一旦おいておきます。
出力に引数を渡してみる
引数を複数文字列で渡してみましょう
slog.Info(msg + "-0") slog.Info(msg+"-1", "Args1") slog.Info(msg+"-2", "Args1", "Args2") slog.Info(msg+"-3", "Args1", "Args2", "Args3") slog.Info(msg+"-4", "Args1", "Args2", "Args3", "Args4") --------------------------------------- 2022/12/10 05:29:00 INFO Log Info Message-0 2022/12/10 05:29:00 INFO Log Info Message-1 !BADKEY=Args1 2022/12/10 05:29:00 INFO Log Info Message-2 Args1=Args2 2022/12/10 05:29:00 INFO Log Info Message-3 Args1=Args2 !BADKEY=Args3 2022/12/10 05:29:00 INFO Log Info Message-4 Args1=Args2 Args3=Args4
出力系の関数（ここではInfo）は先頭の文字列から複数指定可能ですが、 構造化ってことでKey、Valueで設定する形になっている為、文字列を奇数個渡した場合、"!BADKEY"という文字列が入ります。
構造化までは必要ないってことであれば第一引数を編集するイメージで使用した方がいいのかな？
Attr構造体
slogは構造化データであるため、文字列で渡すのではなく、Attr構造体を利用するような形を取るのがベストだと思います。
type Attr struct {
Key string
Value Value
}Attrを生成する関数はInt() ,String() ,Bool() など型に応じたメソッドが準備されています。
slog.Info("Attr Value",
slog.Int("Int()", 1),
slog.String("String()", "buf"),
slog.Time("Time()", time.Now()),
slog.Any("Any()", "Any"))
---------------------------------------
2022/12/10 06:18:22 INFO Attr Value Int()=1 String()=buf Time()=2022-12-10T06:18:22.590+09:00 Any()=Any他の出力関数
一番高いレベルのError()は第二引数にerrorが追加されていて、errorを"err"というキーで追加してくれます。 Log()はレベルを指定して出力するものです。後述しますが、独自のレベルで出力したい場合に利用すると良いでしょう。
出力形式を変更する
せっかくの構造化なので、出力を変更してみましょう。
デフォルトの設定
まずはデフォルト設定を見てみます。 logger.goのinit()で生成されています。
defaultLogger.Store(New(newDefaultHandler(log.Output)))
slog.New()はslog.Loggerの生成(slog.Handlerを設定しているだけ)
func New(h Handler) *Logger { return &Logger{handler: h} }Handelrが出力をハンドルする部分になっています。slogに準備されているJSONHandlerで出力してみましょう。
デフォルトの切り替えはslog.SetDefault()、取得はDefault()で行います。 ※ちなみにSetDefault()が設定している変数はatomic.Valueで制御されています。
defaultHandlerはこれまたslogで準備されているTextHandlerと同等（一緒ではない）になります。
JSONHandlerに切り替えてみる
先程の出力を切り替えて見ます。 ※出力は１ラインです。見やすいように整形しています
slog.SetDefault(slog.New(slog.NewJSONHandler(os.Stdout)))
---------------------------------------
{
"time":"2022-12-10T07:48:33.8536163+09:00",
"level":"INFO",
"msg":"Attr Value",
"Int()":1,
"String()":"buf",
"Time()":"2022-12-10T07:48:33.8536163+09:00",
"Any()":"Any"
}引数はio.Writerなのでファイルへの出力などはここで切り替えることができます。
レベルを変更
JSONHandler自体はレベルを持っておらず、HandlerOptionsにおいて制御しています。 NewJSONHandler()では
return (HandlerOptions{}).NewJSONHandler(w)という風に生成していてHandlerOptionsのデフォルトがINFO（0）になっている為、何も設定してない状態だとINFOで出力されます。※defaultHandlerも内部でcommonHandlerを利用していて、その内部でHandlerOptionsを利用しています。
レベルを設定してみましょう。
opts := &slog.HandlerOptions{}
opts.Level = slog.WarnLevel
opts.AddSource = true
opts.ReplaceAttr = attrFunc
slog.SetDefault(slog.New(opts.NewJSONHandler(os.Stdout)))これでWarn()以上のものしか出力されない状態になるはずです。
{"output-time":"2022-12-10T08:17:12.8732846+09:00","level":"WARN","source":"C:/Users/secon/GoApp/slog.go:32","message":"Warn"}またAddSourceをtrueにしたため、ソース位置が出ていることがわかります。 ReplaceAttrはキーの重複などを避ける為に使うとよいでしょう。※サンプルではキーを変更してみました。予約キーは定数化されている為、判定は以下のようにして行います。
func attrFunc(a slog.Attr) slog.Attr {
if a.Key == slog.TimeKey {
return slog.Any("output-time", a.Value)
} else if a.Key == "msg" {
return slog.Any("message", a.Value)
}
return a
}まぁデフォルトのキー値をシステムで決まった値に変更するような目的に使う感じだと思います。
もう少し見てみる
ここではもう一歩踏み込んでslogを使ってみたいと思います。
オリジナルのログレベル
初見で見た時にDebug、Info、Warn、Errorのレベルが少ないなぁと思いました。 レベルは slog.Levelで定義されていて、実体は int になっています。
type Level int
const (
DebugLevel Level = -4
InfoLevel Level = 0
WarnLevel Level = 4
ErrorLevel Level = 8
)level.goのコメントを読めばわかりますが、他のレベルが欲しかったら追加してくれって感じになっています。ディスカッションでもこの値に決定した経緯が少しあります。 ソースのコメントで言及されているレベルはTrace、Notice、Fatalですね。
例えば、以下のように定義（※値は適当）して
const (
TraceLevel slog.Level = -2
NoticeLevel slog.Level = 2
FatalLevel slog.Level = 16
)Log()を利用して出力すればより細かいレベリングもできます。 おそらく実際に使用するにはTrace() という関数を作ると思うのでLogDepth()を使用してソースの位置を指定する必要があります。
さらなる構造化を行う
構造化した割に平坦なログを出していましたが、構造体を使ってみましょう。
s := struct {
Value int `json:"value"`
Text string `json:"text"`
ProcTime time.Time `json:"proc"`
}{1, "text", time.Now()}
slog.Info("sample", slog.Any("struct attr", &s))
-----------------------------------
{
"time":"2022-12-11T14:21:14.1437448+09:00",
"level":"INFO",
"msg":"sample",
"struct attr":{
"value":1,
"text":"text",
"proc":"2022-12-11T14:21:14.1437448+09:00"
}
}jsonタグを効かせないと大文字の変数名になります。 またこれと同等の値を実現する為にGroupという作成関数があります。
slog.Info("sample",
slog.Group("group attr",
slog.Int("value", 1),
slog.String("text", "text"),
slog.Group("nest", slog.String("nestValue", "val"))))
-----------------------------------
{
"time":"2022-12-11T14:32:06.2619176+09:00",
"level":"INFO",
"msg":"sample",
"group attr":{
"value":1,
"text":"text",
"nest":{"nestValue":"val"}
}
}ある程度定義されているはずなので構造体で残すのが自然かな？と思います。
自作 Handler
独自実装はHandlerがinterfaceになっている為、その実装を行えば色々変更できます。
type Handler interface {
Enabled(Level) bool
Handle(r Record) error
WithAttrs(attrs []Attr) Handler
WithGroup(name string) Handler
}どちらかというと実際の出力は既存のHandlerにまかせておいて、Enabled() 部分をカスタマイズする実装が多いかな？と思います。 サンプルは実際に使われているslogにありますので気になる方は、試しにYAMLとかで出力してみたらいかがでしょうか？
最後に
まぁなんとなく使ってみましたが、ログ出力の部分はLogger、Handlerが握っている為、デフォルトを使用しなくても出力自体は可能です。ただデフォルトにまかせて後はHandlerがうまくハンドルしてくれたらいいように作っちゃうのがいいのかな？と思いました。
ディスカッションでも出ていますが、ライブラリでログの粒度が違ってくるのでそれをうまくハンドリングする仕組みが必要になってくると思います。実現できればライブラリはslogを利用するだけ。利用者はHandlerを設定（おそらくサードパーティ製）するだけ。って感じになりうまく動くかな？
試しにオリジナルのHandlerを作ってパッケージによるレベリングをやってみました。
速度はruntime.Caller()は想像より速かったので、パッケージを検索する仕組みを工夫したらまぁ実用に耐えるかな？
Shizuoka.goとしての2022年の総括ですがまったく活動をやれませんでした。 来年こそは少しでもログを残して行けたらなぁという言葉で締めくくりたいと思います。
The Go gopher was designed by Renee French.
The design is licensed under the Creative Commons 3.0 Attributions license. Read this article for more details: