Goのslog使い方まとめ

こちらは[ラクス Advent Calendar 2023](https://qiita.com/advent-calendar/2023/rakus)の17日目の記事になります。

## はじめに

Go 1.21より、標準パッケージとして[`log/slog`](https://pkg.go.dev/log/slog)パッケージが追加されました。
自己学習も兼ねて、この[`log/slog`](https://pkg.go.dev/log/slog)パッケージの使い方について簡単にまとめたいと思います。


:::note info
この記事はGo 1.21.4時点でのコードを元に記述しています。
:::

## slogの概要

`log/slog`パッケージは、構造化されたロギングを実行するロガーを提供するパッケージで、
Go1.21より標準パッケージに追加されました。

ログレコードは時間、メッセージ、ログレベルに加え、任意のキー/値のペアによって構成されます。

## シンプルなログ出力

`log/slog`にはログレベルを指定してシンプルにログを出力する関数が定義されています。
例として、INFOレベルのログを出力してみます。

```go:main.go
package main

import "log/slog"

func main() {
	slog.Info("Hello, World!", "foo", "bar", "hoge", "fuga")
}
```
実行結果として、以下のような形式のログが標準出力されます。
`実行日時 ログレベル ログメッセージ キー/値ペアのリスト`
```bash:実行結果
$ go run main.go
2023/12/16 23:09:04 INFO Hello, World! foo=bar hoge=fuga
```

ログレベルを指定する関数は以下4種類です。
- `Debug(msg string, args ...any)`
- `Info(msg string, args ...any)`
- `Warn(msg string, args ...any)`
- `Error(msg string, args ...any)`

これらの関数は`slog`パッケージで宣言されているデフォルトのロガーから作成された`slog.Logger`型の変数のメソッドを呼び出しています。
例えば、`Info(msg string, args ...any)`は内部的には`*Logger`のレシーバメソッドである`func (l *Logger) Info(msg string, args ...any)`を呼び出しています。

## ログ出力形式を変更する

デフォルトの出力形式から変更する場合、`slog.Logger`が内部的に保持しているハンドラを置き換える必要があります。
`slog`パッケージで提供されているハンドラは`TextHandler`と`JSONHandler`の2種類になります。
ハンドラは`slog.New(h Handler)`関数でLoggerを生成することで置き換え可能です。

### TextHandler

TextHandlerは`time`, `level`, `msg`キーを付与したログを出力します。
また、`time`はRFC3339形式でミリ秒までの出力となります。

```go:main.go
package main

import (
	"log/slog"
	"os"
)

func main() {
	logger := slog.New(slog.NewTextHandler(os.Stdout, nil))
	logger.Info("Hello, World!", "foo", "bar", "hoge", "fuga")
}
```
```bash:実行結果
$ go run main.go
time=2023-12-16T23:31:56.723+09:00 level=INFO msg="Hello, World!" foo=bar hoge=fuga
```

### JSONHandler

JSONHandlerはTextHandlerと同じく`time`, `level`, `msg`キーを付与した上で、JSON形式でログを出力します。
また、`time`の値の出力形式がRFC3339形式でナノ秒までの出力となります。

```go:main.go
package main

import (
	"log/slog"
	"os"
)

func main() {
	logger := slog.New(slog.NewJSONHandler(os.Stdout, nil))
	logger.Info("Hello, World!", "foo", "bar", "hoge", "fuga")
}
```
```bash:実行結果
$ go run main.go
{"time":"2023-12-16T23:56:48.437291886+09:00","level":"INFO","msg":"Hello, World!","foo":"bar","hoge":"fuga"}
```

## デフォルトのロガーの更新

デフォルトのロガーを置き換えたい場合は`slog.SetDefault(l *Logger)`関数を使います。
以下は、`JSONHandler`をデフォルトのロガーとして置き換えた場合の例です。

```go:main.go
package main

import (
	"log/slog"
	"os"
)

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

	// デフォルトロガーを使ってInfoレベルのログを出力
	slog.Info("Hello, World!", "foo", "bar")
	slog.Info("Hello, Japan!", "hoge", "fuga")
}
```
```bash:実行結果
$ go run main.go
{"time":"2023-12-17T00:13:24.043539852+09:00","level":"INFO","msg":"Hello, World!","foo":"bar"}
{"time":"2023-12-17T00:13:24.043606469+09:00","level":"INFO","msg":"Hello, Japan!","hoge":"fuga"}
```

## 共通の属性を複数のログに付与する

複数のログに対して共通のログを付与する場合、全てのログ出力時に同じキー/値のペアを与えていくのは冗長です。
その場合は`Logger`の`With`メソッドを使うことで共通化することができます。

```go:main.go
package main

import (
	"log/slog"
	"os"
)

func main() {
	logger := slog.New(slog.NewJSONHandler(os.Stdout, nil)).With("url", "https://example.com")

	// url属性は付与しない
	logger.Info("Hello, World!", "foo", "bar")
	logger.Info("Hello, Japan!", "hoge", "fuga")
}
```
```bash:出力結果
# url属性が付与されている
$ go run main.go
{"time":"2023-12-17T00:18:09.990452722+09:00","level":"INFO","msg":"Hello, World!","url":"https://example.com","foo":"bar"}
{"time":"2023-12-17T00:18:09.990524639+09:00","level":"INFO","msg":"Hello, Japan!","url":"https://example.com","hoge":"fuga"}
```

## 出力するログレベルの設定

デフォルトだとINFOレベル以上のログが出力されます。
それ以下のログレベル（デフォルトで用意されているのはDEBUGログ）を出力する場合は、
`HandlerOptions`の`Level`フィールドを変更する必要があります。

```go:main.go
package main

import (
	"log/slog"
	"os"
)

func main() {
	var debugLevel = new(slog.LevelVar)
	debugLevel.Set(slog.LevelDebug)

	infoLogger := slog.New(slog.NewJSONHandler(os.Stdout, nil))
	debugLogger := slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{Level: debugLevel}))

	// Debugログ出力
	infoLogger.Debug("InfoLogger Debug")
	debugLogger.Debug("DebugLogger Debug")
}
```
```bash:実行結果
# debugLoggerのログのみ出力される
$ go run main.go
{"time":"2023-12-17T00:33:12.173001185+09:00","level":"DEBUG","msg":"DebugLogger Debug"}
```

## 属性の階層化

属性を階層化する場合は`slog.Group(key string, args ...any)`関数を使用します。
これまでの単純なstringのキー/値ペア同様、`With`メソッドや`Info`メソッドに直接引数として渡すことができます。

```go:main.go
package main

import (
	"log/slog"
	"os"
)

func main() {
    // リクエスト情報
	req := slog.Group("request", "method", "GET", "url", "https://example.com")
    // Withで共通属性を付与
	logger := slog.New(slog.NewJSONHandler(os.Stdout, nil)).With(req)

    // 多段の階層構造
	attrs := slog.Group("attrs", slog.Group("attr1", "hoge", "fuga"), slog.Group("attr2", "hoge", "fuga"))
    // Infoメソッドに直接渡す    
	logger.Info("Hello, World!", attrs)
}
```
```bash:実行結果
$ go run main.go
{"time":"2023-12-17T00:57:13.665926599+09:00","level":"INFO","msg":"Hello, World!","request":{"method":"GET","url":"https://example.com"},"attrs":{"attr1":{"hoge":"fuga"},"attr2":{"hoge":"fuga"}}}
```

ちなみにTextHandlerを使う場合は以下のように出力されます。
```bash:実行結果
time=2023-12-17T01:01:40.161+09:00 level=INFO msg="Hello, World!" request.method=GET request.url=https://example.com attrs.attr1.hoge=fuga attrs.attr2.hoge=fuga
```

## キー/値を`Attr`型で指定する

`slog.Attr`型は属性のキー/値を表す型で、以下のように定義された構造体です。
```go
type Attr struct {
	Key   string
	Value Value
}
```

例えばキー/値を別々の引数として渡していた部分を以下のように書き換えることができます。
`slog.String(key, value string)`関数は`slog.Attr`型を返却します。

```go
// Before
logger.Info("Hello, World!", "hoge", "fuga")

// After
logger.Info("Hello, World!", slog.String("hoge", "fuga"))
```

`String`以外にも、`Int`, `Bool`, `Any`等の`Attr`のコンストラクタ関数があります。
また、前述した`slog.Group(key string, args ...any)`関数も`Attr`を返却しています。

## Contextから取り出した値をロギング

各種ロギング関数には、`context.Context`型の引数を取る別名関数が準備されています。
例えば、`Info(msg string, args ...any)`関数に対して、
第一引数に`context.Context`を取る`InfoContext(ctx context.Context, msg string, args ...any)`関数が準備されています。

この関数の主な使用目的は、例えばトレースID等、`ctx`で引き回す値をロギング時に使用することです。

ただし、`context.WithValue(ctx, key, val)`でセットされたキー/値を自動的に取り出してくれる類の関数ではないので、
必要な値を取得する処理は自作する必要があります。

以下は、トレースIDを取得する自作の`TraceHandler`です。
`context.Context`から`"traceID"`というキーでセットされた値を取得してログレコードに属性として追加するよう、`Handle`メソッドを実装しています。

```go:trace_handler.go
package main

import (
	"context"
	"log/slog"
)

type key struct{}

var traceIDKey = key{}

type TraceHandler struct {
	slog.Handler
}

func NewTraceHandler(h slog.Handler) *TraceHandler {
	return &TraceHandler{h}
}

func (h *TraceHandler) Handle(ctx context.Context, r slog.Record) error {
	r.AddAttrs(slog.String("traceID", ctx.Value(traceIDKey).(string)))
	return h.Handler.Handle(ctx, r)
}
```

main処理では`slog.New`関数に`TraceHandler`を渡しています。
```go:main.go
package main

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

func main() {
	ctx := context.WithValue(context.Background(), traceIDKey, "1234567890")
	logger := slog.New(NewTraceHandler(slog.NewJSONHandler(os.Stdout, nil)))
	logger.InfoContext(ctx, "Hello, World!")
}
```

実行結果には`traceID`が含まれています。
```bash:実行結果
$ go run main.go trace_handler.go 
{"time":"2023-12-17T01:46:24.252425848+09:00","level":"INFO","msg":"Hello, World!","traceID":"1234567890"}
```

## 秘密情報をマスクする

パスワード等の秘密情報をそのままログ出力したくない場合は、
該当する型に以下の`slog.LogValuer`インターフェースを実装します。
```go
type LogValuer interface {
	LogValue() Value
}
```

`string`の拡張型である`Password`型を定義して、`slog.LogValuer`を実装します。

```go:password.go
package main

import "log/slog"

type Password string

func (p Password) LogValue() slog.Value {
	return slog.StringValue("********")
}
```

ロギング処理は以下のように実装します。
```go:main.go
package main

import (
	"log/slog"
	"os"
)

func main() {
	logger := slog.New(slog.NewJSONHandler(os.Stdout, nil))
	logger.Info("Hello, World!", slog.Any("password", Password("secret")))
}
```
実行結果を見ると、`password`がマスクされていることが分かります。
```bash:実行結果
$ go run main.go password.go 
{"time":"2023-12-17T01:55:29.979530405+09:00","level":"INFO","msg":"Hello, World!","password":"********"}
```

## おわりに

簡単にではありますが、今回は`log/slog`パッケージの使用方法をまとめてみました。
今後触る機会が増えるかと思うので、実践で更に使い方を身に着けていきたいと思います。

それでは、少し早いですがメリークリスマス！