もっと log/slog を使おう
はじめに
この記事は Go アドベントカレンダー 2023 の最終日 25 日目の記事です。
皆さん log/slog 使ってますか。便利なのでぜひ使ってください。
slog は構造化ログを出力する為のパッケージで Go 1.21 で導入されました。これまでも zap や zerolog といったサードパーティ製のロガーを使う事で構造化ログを出力する事ができましたが、構造化ログを出力する機能が Go の標準ライブラリになりました。
slog とは
通常の log パッケージは、時刻とメッセージの単純な出力になります。
log.Printf("name=%v, value=%v", name, value)
2023/12/14 15:00:48 name=Orange, value=200
slog を使うとこうなります。
slog.Info("fruit", "name", name, "value", value)
2023/12/14 15:05:38 INFO fruit name=Orange value=200
コードを見ただけでも INFO というログレベルも出力される様になっていて幾分便利になった気もします。
ただ slog の実際の威力はそこではないのです。
logger := slog.New(slog.NewJSONHandler(os.Stderr, nil))
logger.Info("fruit", "name", name, "value", value)
これを実行すると以下が出力されます。
{"time":"2023-12-06T15:05:38.027288704+09:00","level":"INFO","msg":"fruit","name":"Orange","value":200}
引数で key/value を指定するのではなく slog.Int や slog.String を使って出力する事もできます。
logger.Info("fruit", slog.String("name", name), slog.Int("value", value)))
JSON ハンドラを使う事で構造化されたログを出力できる様になりました。これが標準ライブラリで扱える様になったのはとても大きな事なのです。
ちなみに変数 logger を各関数に引き回すのが嫌だという方はこんな感じにデフォルトにしちゃうと良いです。
package main
import (
"log/slog"
"os"
)
func init() {
slog.SetDefault(slog.New(slog.NewJSONHandler(os.Stderr, nil)))
}
func main() {
slog.Error("my-app", "name", "foo")
}
slog で何が嬉しい？
ログが JSON で出力される様になって何が嬉しいか。それは運用し始めた後で分かります。
ログをデータとして扱える
みなさんもこれまで、アプリケーションが出力したログから特定の値だけ抜き出したいと思った事が数万回はあると思います。
そして出力してしまった後から「もうちょい正規表現で扱いやすいログの形式にしておけば良かったなぁ」と思ったりもしたと思います。slog で出力したログはそのまま値になるのです。
{"time":"2023-12-14T15:43:37.361994592+09:00","level":"INFO","msg":"fruit","name":"Apple","value":195}
{"time":"2023-12-14T15:43:37.361997454+09:00","level":"INFO","msg":"fruit","name":"Banana","value":199}
{"time":"2023-12-14T15:43:37.362001007+09:00","level":"INFO","msg":"fruit","name":"Banana","value":199}
{"time":"2023-12-14T15:43:37.362005631+09:00","level":"INFO","msg":"fruit","name":"Orange","value":203}
{"time":"2023-12-14T15:43:37.362008957+09:00","level":"INFO","msg":"fruit","name":"Apple","value":195}
{"time":"2023-12-14T15:43:37.362011694+09:00","level":"INFO","msg":"fruit","name":"Banana","value":204}
{"time":"2023-12-14T15:43:37.362015401+09:00","level":"INFO","msg":"fruit","name":"Apple","value":204}
{"time":"2023-12-14T15:43:37.362019635+09:00","level":"INFO","msg":"fruit","name":"Banana","value":197}
{"time":"2023-12-14T15:43:37.362023534+09:00","level":"INFO","msg":"fruit","name":"Apple","value":200}
{"time":"2023-12-14T15:43:37.362028067+09:00","level":"INFO","msg":"fruit","name":"Grape","value":198}
{"time":"2023-12-14T15:43:37.36203106+09:00","level":"INFO","msg":"fruit","name":"Apple","value":202}
{"time":"2023-12-14T15:43:37.36203375+09:00","level":"INFO","msg":"fruit","name":"Orange","value":196}
{"time":"2023-12-14T15:43:37.362036514+09:00","level":"INFO","msg":"fruit","name":"Apple","value":201}
{"time":"2023-12-14T15:43:37.362039196+09:00","level":"INFO","msg":"fruit","name":"Banana","value":199}
{"time":"2023-12-14T15:43:37.362041986+09:00","level":"INFO","msg":"fruit","name":"Orange","value":203}
この様なログが出力されていた時、「名前と値と日付で抽出して CSV 形式で出力したいな」と思った時、これまでの形式だと、日付が先頭に出力されていたので正規表現などを使って加工する必要がありました。
しかし構造化されたログであれば
$ cat output.log | jq -r '[.name, .time] | @csv'
"Banana","2023-12-06T15:43:37.362011694+09:00"
"Apple","2023-12-06T15:43:37.362015401+09:00"
"Banana","2023-12-06T15:43:37.362019635+09:00"
"Apple","2023-12-06T15:43:37.362023534+09:00"
"Grape","2023-12-06T15:43:37.362028067+09:00"
"Apple","2023-12-06T15:43:37.36203106+09:00"
"Orange","2023-12-06T15:43:37.36203375+09:00"
"Apple","2023-12-06T15:43:37.362036514+09:00"
"Banana","2023-12-06T15:43:37.362039196+09:00"
"Orange","2023-12-06T15:43:37.362041986+09:00"
こんなに簡単にフォーマット変換ができるのです。例えばログレベルが INFO の場合だけ抽出したいのであれば
$ cat output.log | jq -r 'select(.level == "INFO") | [.name, .time] | @csv'
こうです。便利！
CloudWatch Logs で使える
構造化されていると嬉しいのはこれだけではありません。AWS CloudWatch Logs を使っておられる皆さんであれば、CloudWatch Logs Insights を使ってログを検索された事があると思います。通常のログであれば日付とメッセージ部にしか分けられないので
fields @timestamp, @message
というクエリを流さざるを得ません。もちろん parse コマンドを使ってフィールド定義を頑張る事もできますが、構造化されていると
fields @timestamp, level, msg, name, value
| filter level = "INFO"
これだけで良いのです。
便利すぎませんか？CloudWatch Logs で検索窓に
{ $.level = "INFO" }
を入力し、INFO のみに絞られた結果からメトリクスフィルタを作れば
サブスクリプションフィルタからアラームも構築できる。便利。
PostgreSQL で使える
fluent-bit を使えばログをそのまま PostgreSQL や MySQL に格納できます。
[SERVICE]
flush 3
Parsers_File ./parsers.conf
[INPUT]
name stdin
tag my-log
[FILTER]
Name parser
Parser slog
Match my-log
Key_Name time
Reserve_Data On
Preserve_Key On
[OUTPUT]
name stdout
match *
[OUTPUT]
Name pgsql
Match *
Host 127.0.0.1
Port 5432
User postgres
Password postgres
Database slog-example
Table fluentbit
[PARSER]
Name slog
Format json
Time_Key time
Time_Keep On
例では入力に stdin プラグインを使っていますが実際は tail プラグインを使い、ログ出力ディレクトリのファイルを扱って下さい。もし検証の為に実行されるのであれば以下のソースコードをビルドして実行して下さい。
package main
import (
"log/slog"
"math/rand"
"os"
"time"
)
func main() {
logger := slog.New(slog.NewJSONHandler(os.Stderr, nil))
ss := []string{
"Orange",
"Banana",
"Apple",
"Grape",
}
for i := 0; i < 100; i++ {
s := ss[rand.Int()%len(ss)]
logger.Info("fruit", "name", s, "value", 200+rand.Int()%10-5)
time.Sleep(500 * time.Millisecond)
}
}
$ ./slog-example |& /opt/fluent-bit/bin/fluent-bit -c config.conf
この様に指定してログを fluent-bit に入力すると PostgreSQL のデータベース slog-example、テーブル fluentbit にデータが追加されます。テーブルのカラム情報は以下の通り。
slog-example=# \d fluentbit;
Table "public.fluentbit"
Column | Type | Collation | Nullable | Default
--------+-----------------------------+-----------+----------+---------
tag | character varying | | |
time | timestamp without time zone | | |
data | jsonb | | |
data が jsonb 型になっています。
つまり JSON 演算子を使って data の中身を SELECT できるという事です。
slog-example=# SELECT data->>'name' name, data->'value' value
slog-example-# FROM fluentbit WHERE data->>'level' = 'INFO';
name | value
--------+-------
Apple | 202
Banana | 191
Banana | 190
Apple | 191
Apple | 209
Banana | 201
Grape | 206
Banana | 203
Apple | 204
Apple | 195
(10 rows)
とても便利。
slog はカスタマイズできる
slog はかなり柔軟な作りになっており、カスタマイズすればいろいろな実装を行う事ができます。
slog.Group
slog.Info や slog.Warn、slog.Error の第２引数以降で渡した属性名および属性値は通常、JSON のルート属性に出力されますが、slog.Group を使う事でグルーピング出来ます。
logger.Info("This is info log", slog.Group("attr",
slog.String("name", "banana"),
slog.Int("count", 1),
))
{
"time": "2023-12-17T23:34:42.120558315+09:00",
"level": "INFO",
"msg": "This is info log",
"attr": {
"name": "banana",
"count": 1
}
}
※ jq にて整形済み
付加した属性値だけを取り出す場合に
$ jq .attr
で取り出せて便利です。
slog.HandlerOptions
slog のハンドラを作成する NewXXX 関数には一般的に slog.HandlerOptions を渡す様になっています。
type HandlerOptions struct {
AddSource bool
Level Leveler
ReplaceAttr func(groups []string, a Attr) Attr
}
ソースコードのパスを出力する
AddSource に true を設定するとログ出力関数を呼び出したソースコードのパスが出力されます。
{
"time": "2023-12-17T22:43:52.528248746+09:00",
"level": "INFO",
"source": {
"function": "main.main",
"file": "/home/mattn/dev/slog-example/main.go",
"line": 83
},
"msg": "This is info log"
}
{
"time": "2023-12-17T22:43:53.229435794+09:00",
"level": "WARN",
"source": {
"function": "main.main",
"file": "/home/mattn/dev/slog-example/main.go",
"line": 85
},
"msg": "This is warn log"
}
※ jq にて整形済み
ログレベルを動的に変更する
Leveler を設定すると、ログレベルを動的に変更する事ができます。
type Leveler interface {
Level() Level
}
だいたい実装が想像できると思いますので実装は割愛しますが、この Level は書いたプログラムの意図 (Info/Warn/Error) とは異なるレベルが出力される事になるため、デバッグをし辛くする可能性があります。
特定の属性を変更する
ReplaceAttr を使うと特定の属性の値を変更する事ができます。これを利用する事で Info/Warn/Error の第一引数である msg 属性を消すこともできます。
jh := slog.NewJSONHandler(os.Stderr, &slog.HandlerOptions{
ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr {
if a.Key == slog.MessageKey && len(groups) == 0 {
return slog.Attr{}
}
return a
},
})
Leveler 同様に、プログラムコードの意図とは異なる動作になり得ます。ご注意を。
付加情報を足すログハンドラ
slog.Info や slog.Warn ではメッセージしか出力しないけれど、かならず勝手に付加情報を与えたい場合もあります。例えば固定のキーで変動しうる属性を付け足したいとします。現在のメトリクス値でも良いですね。そういう場合に便利なのが slog.Handler です。slog.Handler はインタフェースであり、これに合った実装を行うと slog.New にハンドラとして渡す事ができます。
type Handler interface {
Enabled(context.Context, Level) bool
Handle(context.Context, Record) error
WithAttrs(attrs []Attr) Handler
WithGroup(name string) Handler
}
もともと用意されたハンドラを wrap する形式で新しいハンドラを作るとカスタマイズできます。
package main
import (
"context"
"log/slog"
"math/rand"
"os"
)
type ExtraAttrHandler struct {
handler slog.Handler
fn ExtraAttrFunc
}
type ExtraAttrFunc func() []slog.Attr
func NewExtraAttrHandler(h slog.Handler, fn ExtraAttrFunc) *ExtraAttrHandler {
if lh, ok := h.(*ExtraAttrHandler); ok {
h = lh.Handler()
}
return &ExtraAttrHandler{handler: h, fn: fn}
}
func (h *ExtraAttrHandler) Enabled(ctx context.Context, level slog.Level) bool {
return h.handler.Enabled(ctx, level)
}
func (h *ExtraAttrHandler) Handle(ctx context.Context, r slog.Record) error {
r.AddAttrs(h.fn()...)
return h.handler.Handle(ctx, r)
}
func (h *ExtraAttrHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
return NewExtraAttrHandler(h.handler.WithAttrs(attrs), h.fn)
}
func (h *ExtraAttrHandler) WithGroup(name string) slog.Handler {
return NewExtraAttrHandler(h.handler.WithGroup(name), h.fn)
}
func (h *ExtraAttrHandler) Handler() slog.Handler {
return h.handler
}
この様に実装する事で、例えば以下のように JSONHandler に付加情報を与える事ができます。
var janken = []string{"ぐー", "ちょき", "ぱー"}
func main() {
jh := slog.NewJSONHandler(os.Stderr, nil)
logger := slog.New(NewExtraAttrHandler(jh, func() []slog.Attr {
return []slog.Attr{
slog.String("じゃんけん", janken[rand.Int()%len(janken)]),
}
}))
logger.Info("This is info log")
logger.Warn("This is warn log")
}
実行すると以下の様に毎行 "じゃんけん" の結果が出力されます。
{
"time": "2023-12-17T22:19:00.596395695+09:00",
"level": "INFO",
"msg": "This is info log",
"じゃんけん": "ぱー"
}
{
"time": "2023-12-17T22:19:00.596856731+09:00",
"level": "WARN",
"msg": "This is warn log",
"じゃんけん": "ぐー"
}
※ jq にて整形済み
この与えた属性付与の関数はログの出力を遅らせてしまう可能性があり本意ではないはずです。そういった場合には sync.Map と併用すると簡単です。
func main() {
m := sync.Map{}
go func() {
for {
m.Store("じゃんけん", janken[rand.Int()%len(janken)])
time.Sleep(time.Second)
}
}()
jh := slog.NewJSONHandler(os.Stderr, nil)
logger := slog.New(NewExtraAttrHandler(jh, func() []slog.Attr {
attrs := []slog.Attr{}
m.Range(func(key, value any) bool {
attrs = append(attrs, slog.Any(fmt.Sprint(key), value))
return true
})
return attrs
}))
time.Sleep(700 * time.Millisecond)
logger.Info("This is info log")
time.Sleep(700 * time.Millisecond)
logger.Warn("This is warn log")
}
高速に logger.Info を使うと同じ値が出力されてしまいますが、例えば CPU の負荷やメモリの負荷を付与するといった要件では使える方法だと思います。ただし実用的には、一般のメッセージを出力するログと、メトリクス情報を出力するログは、別途出力を行い、区別できる付加属性(typeなど)を付与するべきです。例えば以下の様に。
{
"time": "2023-12-17T22:19:00.596395695+09:00",
"level": "INFO",
"msg": "This is info log",
"type": "app"
}
{
"time": "2023-12-17T22:19:00.596856731+09:00",
"level": "WARN",
"msg": "This is warn log",
"type": "app"
}
{
"time": "2023-12-17T22:19:00.596856731+09:00",
"level": "WARN",
"msg": "metrics",
"type": "metric",
"cpu": 66,
"memory": 25
}
※ jq にて整形済み
こうする事で後から jq で抽出したり AWS CloudWatch Logs Insights でメトリクスの値だけを抽出したりしやすくなります。
おわりに
今まで雑に出力していたログが簡単にデータとなりました。今まで苦労して大量のログファイルを grep し sed で加工していた作業はもう必要ありません。ぜひ slog を使って「楽」をして下さい。
さて Go アドベントカレンダーに参加して頂いた皆様、ありがとうございました。そして今年も1年、お疲れ様でした。後少しで今年も終わりです。風邪などひかず暖かくしてお過ごし下さい。
Discussion