【Go】slog を触ってみる

Sep 22, 2023

はじめに

Go1.21 から新しく log/slog が追加されました。

• https://tip.golang.org/doc/go1.21#slog

今回は slogに関するブログとドキュメントを読んで学んだことを備忘録として残します。

• https://go.dev/blog/slog
• https://pkg.go.dev/log/slog

slog の主な構成要素

slog パッケージに含まれる3つのタイプ

1. Logger
   Info や LogAttrs のように出力を担当する。
2. Record
   ログイベントに関する情報を保持する
3. Handler
   ロガーによって生成されたログレコードを処理する

slog の LogLevel

以下の4 つがあり、整数が割り当てられています。

レベル	整数
Debug	-4
Info	0
Warn	4
Error	8

https://github.com/golang/go/blob/go1.21.0/src/log/slog/level.go#L43-L48

トップレベルのロガー

サンプルで紹介されているような、トップレベルの slog はデフォルトのロガーを使用しています

package main

import (
  "log/slog"
)

func main() {
  slog.Info("hello", "name", "Al")
}

2009/11/10 23:00:00 INFO hello name=Al

playgroynd

"slog.Info" のコードを読んでみる

slog.Info のコードを読んでみます。

どうやら Default().log が呼ばれているようです。
https://github.com/golang/go/blob/go1.21.0/src/log/slog/logger.go#L259-L261

さらに読み進めてみます。
slog パッケージをインポートしたとき init 関数によって defaultLogger が初期化されており、Default 関数は Logger 構造体のインスタンスを返しているようです。
つまり Default().log は Logger 構造体のメソッドである log() が呼ばれている、ということですね。
https://github.com/golang/go/blob/go1.21.0/src/log/slog/logger.go#L17-L24

ちなみに Logger 構造体は以下のフィールドを持っています。

https://github.com/golang/go/blob/go1.21.0/src/log/slog/logger.go#L79-L81

Logger.log() を見つけました。 slog.Info や slog.Debug などの関数は、以下の共通したメソッドが呼ばれていることがわかりました。
ちなみに Logger.log メソッドの1行目（コードだと210行目）にある if !l.Enabled(ctx, level) { で、ログレベルによる出力の制御をしていることがわかります。
https://github.com/golang/go/blob/go1.21.0/src/log/slog/logger.go#L209-L226

この Enabled は Handler インターフェイスを実装するために必要なメソッドです。
https://github.com/golang/go/blob/master/src/log/slog/handler.go#L31-L41

デフォルトロガーのログレベル

デフォルトロガーのログレベルは Info なので、 slog.Debug() は出力されません。
https://github.com/golang/go/blob/go1.21.0/src/log/slog/handler.go#L101-L103

package main

import (
  "log/slog"
)

func main() {
  slog.Debug("debug.", "name", "hoge")
  slog.Info("info.", "name", "hoge")
  slog.Warn("warn.", "name", "hoge")
  slog.Error("error.", "name", "hoge")
}

$ go run main.go
2023/09/23 00:53:52 INFO info. name=hoge
2023/09/23 00:53:52 WARN warn. name=hoge
2023/09/23 00:53:52 ERROR error. name=hoge

デフォルトハンドラーは標準エラー出力

以下のコードを実行してみます。

package main

import (
  "log/slog"
)

func main() {
  slog.Debug("debug.", "name", "hoge")
  slog.Info("info.", "name", "hoge")
  slog.Warn("warn.", "name", "hoge")
  slog.Error("error.", "name", "hoge")
}

標準エラー出力を捨てると、何も出力されません。
つまり、デフォルトのロガーを使用すると、ログが標準エラーとして出力されることがわかります。

$ go run main.go 2> /dev/null
$ # 何も出力されない

ここで疑問が湧いてきます。

どこで stderr を定義しているのか？

疑問を解決すべくコードを読んでいきます。

先ほど、 slog.Info のコードを読んでみた結果、src/log/slog/logger.goで以下のコードが呼ばれていることがわかりました。
この関数を見てみると、Logger.log メソッドが直接出力しているようではなさそうです。
https://github.com/golang/go/blob/go1.21.0/src/log/slog/logger.go#L209-L226

プロポーザルによると、ハンドラーが何かをしていそうです。

A typical handler may print log records to standard error, or write them to a file, database or network service, or perhaps augment them with additional attributes and pass them on to another handler.

引用；https://go.googlesource.com/proposal/+/master/design/56345-structured-logging.md#handlers

Logger.log メソッドの最後に _ = l.Handler().Handle(ctx, r) が実行されています。 Handle メソッドを読んでいきます。

Handle メソッドでは、buf.WriteStringも関係していそうですが、最後の行 return h.output(r.PC, *buf) が何者が確認してみます。
https://github.com/golang/go/blob/go1.21.0/src/log/slog/handler.go#L108-L117

h.output は、defaultHandler 構造体のフィールドであり、 newDefaultHandler 関数の第一引数で初期化されています。
https://github.com/golang/go/blob/go1.21.0/src/log/slog/handler.go#L88-L99

そんな　newDefaultHandler 関数は、src/log/slog/logger.go の init 関数で呼ばれています。 第一引数をみると、loginternal.DefaultOutput という値が渡されています。
このファイルのインポート文をみると、loginternal "log/internal" と書いてありますね。
どうやら output するメソッドの実態は log パッケージから来ていることがわかりました。
https://github.com/golang/go/blob/go1.21.0/src/log/slog/logger.go#L7-L21

go/src/log/internal/internal.go に DefaultOutput がありました。
どうやら変数のようです。しかし、何も定義されていません。
https://github.com/golang/go/blob/go1.21.0/src/log/internal/internal.go#L12

internal.DefaultOutput を初期化している init 関数を見つけました。
何やら return std.output(pc, 0, func(buf []byte) []byte { の行が怪しそうです。
std.output が何者か探してみます。
https://github.com/golang/go/blob/go1.21.0/src/log/log.go#L249-L255

slog ではなく、src/log/log.go に定義されている log パッケージに std 変数があり、パッケージ内のグローバル変数に定義されています。
やっと見つけました！ ここで os.Stderr を指定していました。
https://github.com/golang/go/blob/go1.21.0/src/log/log.go#L87

New 関数は、同じファイル内にあり、log パッケージの Logger 構造体を戻り値にしています。
https://github.com/golang/go/blob/go1.21.0/src/log/log.go#L57-L77

この Logger 構造体に output メソッドがあります。これが、先ほどの std.output 正体です。
_, err := l.out.Write(*buf) の行で、stderr 出力していることがわかりました。
https://github.com/golang/go/blob/go1.21.0/src/log/log.go#L202-L247

組み込みHnadler

TextHandler と JSONHandler 2つの組み込み Handler があります。

TextHandler

https://github.com/golang/go/blob/go1.21.0/src/log/slog/text_handler.go#L28

package main

import (
  "log/slog"
  "os"
)

func main() {
  logger := slog.New(slog.NewTextHandler(os.Stdout, nil))
  logger.Info("hello, world")
}

time=2009-11-10T23:00:00.000Z level=INFO msg="hello, world"

playground

JSONHandler

https://github.com/golang/go/blob/go1.21.0/src/log/slog/json_handler.go#L30

package main

import (
  "log/slog"
  "os"
)

func main() {
  logger := slog.New(slog.NewJSONHandler(os.Stdout, nil))
  logger.Info("hello, world")
}

{"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"hello, world"}

playground

HandlerOptions

HandlerOptions には以下の設定が可能です。

type HandlerOptions struct {
  AddSource bool
  Level Leveler
  ReplaceAttr func(groups []string, a Attr) Attr
}

type HandlerOptions - pkg.go.dev

https://github.com/golang/go/blob/go1.21.0/src/log/slog/handler.go#L129-L167

AddSource

HandlerOptions に AddSource を追加してみます。

package main

import (
  "log/slog"
  "os"
)

func main() {
  logger := slog.New(slog.NewJSONHandler(os.Stdout, nil))
  logger.Info("msg")

  souceLogger := slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{AddSource: true}))
  souceLogger.Info("msg")
}

実行すると、 ログの中に source が追加されました。

{"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"msg"}
{"time":"2009-11-10T23:00:00Z","level":"INFO","source":{"function":"main.main","file":"/tmp/sandbox2161312774/prog.go","line":13},"msg":"msg"}

playground

Caution

logger をラップしたい場合、注意が必要です。
slog のドキュメントにも書いてある通り、HandlerOptions の AddSource を有効にした場合、ラップした側のファイルが出力されてしまうため Source　を出力する意味がなくなります。

-- main.go --
package main

func main() {
  Infof("hello, %s", "world")
}
-- logger.go --
package main

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

func Infof(format string, args ...any) {
  replace := func(groups []string, a slog.Attr) slog.Attr {
    if a.Key == slog.TimeKey {
      return slog.Attr{}
    }
    if a.Key == "function" {
      return slog.Attr{}
    }

    return a
  }
  logger := slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{AddSource: true, ReplaceAttr: replace}))

  logger.Info(fmt.Sprintf(format, args...))
}

{"level":"INFO","source":{"file":"/tmp/sandbox2926840352/logger.go","line":22},"msg":"hello, world"}

https://go.dev/play/p/9VyGo1u5XRR

もし自作のロガーを作成したい場合は、slog のメソッドをラップするのではなく、Handler を自分で実装する必要があります。 （Handler の実装はこの記事では取り扱いません）

• https://pkg.go.dev/log/slog#hdr-Writing_a_handler
• https://github.com/golang/example/blob/master/slog-handler-guide/README.md

Level

HandlerOptions の Level にログレベルを設定すると、ログレベルの出力を制御できます。

package main

import (
  "log/slog"
  "os"
)

func main() {
  logger := slog.New(slog.NewJSONHandler(os.Stdout, nil))
  logger.Info("msg")

  warnLogger := slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{Level: slog.LevelWarn}))
  warnLogger.Info("info msg") // ここだけ出力されない
  warnLogger.Warn("warn msg")
}

{"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"msg"}
{"time":"2009-11-10T23:00:00Z","level":"WARN","msg":"warn msg"}

playground

ReplaceAttr

ReplaceAttr がどんな値を渡してくるのかイメージができなかったので、とりあえず引数を出力してみました。

package main

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

func main() {
  replace := func(groups []string, a slog.Attr) slog.Attr {
    fmt.Println("groups", groups)
    fmt.Println("attr", a)
    fmt.Println("====================")

    return a
  }

  logger := slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{ReplaceAttr: replace}))
  logger.Info("info msg", slog.Group("group", slog.String("name", "parent"), slog.Group("child", slog.String("name", "child"))))
}

groups []
attr time=2009-11-10 23:00:00 +0000 UTC
====================
groups []
attr level=INFO
====================
groups []
attr msg=info msg
====================
groups [group]
attr name=parent
====================
groups [group child]
attr name=child
====================
{"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"info msg","group":{"name":"parent","child":{"name":"child"}}}

playground

どんな値が引数に入っているのかなんとなくイメージができました。

HandlerOptions の Example にもありますが、特定の key を削除することが可能です。

package main

import (
  "log/slog"
  "os"
)

func main() {
  replace := func(groups []string, a slog.Attr) slog.Attr {

    // remove time key
    if a.Key == slog.TimeKey {
      return slog.Attr{}
    }

    // mask name key
    if a.Key == "name" {
      return slog.Attr{Key: "name", Value: slog.StringValue("**********")}
    }
    return a
  }

  logger := slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{ReplaceAttr: replace}))
  logger.Info("info msg", slog.Group("group", slog.String("name", "parent"), slog.Group("child", slog.String("name", "child"))))
}

{"level":"INFO","msg":"info msg","group":{"name":"**********","child":{"name":"**********"}}}

playground

LogAttr

log.Info を実行するよりも Attr 型を使用した方がメモリ割り当てが最小になるように動作するので、効率が良いそうです。

frequently executed log statements it may be more efficient to use the Attr type and call the LogAttrs method. These work together to minimize memory allocations.

引用：https://go.dev/blog/slog

Attr 型は以下の通りです。

• String
• Int64
• Int
• Uint64
• Float64
• Bool
• Time
• Duration
• Group
• Any

引用：https://github.com/golang/go/blob/go1.21.0/src/log/slog/attr.go

package main

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

func main() {
  slog.LogAttrs(context.Background(), slog.LevelInfo, "this is message.", slog.String("name", "hoge"))

  textLogger := slog.New(slog.NewTextHandler(os.Stdout, nil))
  textLogger.LogAttrs(context.Background(), slog.LevelInfo, "message", slog.String("key", "val"), slog.Group("group", slog.String("key", "val")))

  jsonLogger := slog.New(slog.NewJSONHandler(os.Stdout, nil))
  jsonLogger.LogAttrs(context.Background(), slog.LevelInfo, "message", slog.String("key", "val"), slog.Group("group", slog.String("key", "val")))
}

2009/11/10 23:00:00 INFO this is message. name=hoge
time=2009-11-10T23:00:00.000Z level=INFO msg=message key=val group.key=val
{"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"message","key":"val","group":{"key":"val"}}

playground

Logger.With

Logger のメソッドである、With を使うと、With の引数に指定した属性を含めたロガーを新規に作成できます。

トレース ID のように共通のデータを log の呼び出しごとではなく、属性を含む新しいロガーを使うことで繰り返しを避けることができます。

With なし

package main

import (
  "log/slog"
  "os"
)

func main() {
  logger := slog.New(slog.NewJSONHandler(os.Stdout, nil))
  logger.Info("msg")
}

{"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"msg"}

With あり

package main

import (
  "log/slog"
  "os"
)

func main() {
  logger := slog.New(slog.NewJSONHandler(os.Stdout, nil)).With("id", "asdfas")
  logger.Info("msg")
}

{"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"msg","id":"asdfas"}

感想

slog のパッケージはそれほど大きくないので、コードリーディングしやすいと感じました。

InfoContext や LogAttrs のように、第一引数に Context をとるメソッドや関数がありますが、2023年9月現在、Context は利用されていないようです。

なので、context を渡す必要があるときは、 context.Background() でいいと思います。

https://github.com/golang/go/blob/go1.21.0/src/log/slog/json_handler.go#L90-L92 https://github.com/golang/go/blob/go1.21.0/src/log/slog/json_handler.go#L46-L48

https://github.com/golang/go/blob/go1.21.0/src/log/slog/text_handler.go#L94-L96 https://github.com/golang/go/blob/go1.21.0/src/log/slog/text_handler.go#L44-L46

slog のブログ には、 context.Context からトレース ID のように値を取り出すことができる旨が書いてあります。 しかし、それをしたいのならば自分で実装しましょう。ということなのだと思っています。

As the call to LogAttrs shows, you can pass a context.Context to some log functions so a handler can extract context information like trace IDs. (Canceling the context does not prevent the log entry from being written.)

引用：https://go.dev/blog/slog

Tags:

• Golang

boto3をpytestのmonkeypatchでstubする

静的解析ツールとreviewdogを組み合わせて、レビューを自動化する