Diary of a Perpetual Student

Perpetual Student: A person who remains at university far beyond the normal period

Go言語のloggerをDefault1つで済ませる方法：slog Handlerがcontextの中身を見てよしなにするパターン

テクノロジー Go OpenTelemetry

先日、kamakura.go #6にて、「slog登場に伴うloggerの取り回し手法の見直し」という題で登壇しました。Go Conference 2024にこの内容でproposalを出していて落選してしまったのですが、kamakura.go #6のテーマ「昔のGo、今のGo」とピッタリだったので応募して発表の機会を頂いたという経緯です。

speakerdeck.com

この発表は以下のエントリのrefinement版となる内容です。今度は机上論ではなく実践経験をもとに話を組み立てています。

blog.arthur1.dev

loggerの引き回しと、なぜそれが必要だったのか

あるアプリケーション・モジュールの構造化ログについて、常に特定のフィールドを付与したいというニーズがあります。例えばWebアプリケーションなら、ソースコードの関数・モジュール名、リクエストID、ユーザIDといったログの検索に有益な情報をログに付与したいでしょう。

その時に、ログの出力命令ごとにいちいちフィールドを指定しまくるのは大変です。単純にコード量が多いし、仮に付与したいフィールドが増えたときに一行一行変更して回らないといけません。ログに出したい変数を持って回る必要もあります。

log.WithFields(log.Fields{"module": "userService", "user_id": 1}).Info("validation passed")
...
log.WithFields(log.Fields{"module": "userService", "user_id": 1}).Info("succeeded")

（このあたりのサンプルコードは構造化ログのライブラリとしてhttps://github.com/sirupsen/logrusを使用したケースです。）

そこで、必要に応じてloggerインスタンスを作り、呼び出し先でも利用できるように引き回す手法があります。例えば、ユーザIDが確定した時点でユーザIDを常にログに含むようなloggerを作って、それ以降の処理ではこのloggerを利用してログを書くといったやり方です。

logger := log.WithFields(log.Fields{"module": "userService", "user_id": 1})
logger.Info("validation passed")
...
// loggerを作った命令とは別の関数の場合、loggerをここでも使えるように引き回す必要がある
logger.Info("succeeded")

loggerの引き回し手法はいくつかありますが、私個人としては以下の記事で推奨されている手法の1つである「contextにloggerを入れる」パターンが好みです。

zenn.dev

package mylog

import "context"

type key struct{}

func ContextWithLogger(ctx context.Context, logger Logger) context.Context {
    return context.WithValue(ctx, key{}, logger)
}

func FromContext(ctx context.Context) Logger {
    return ctx.Value(key{}).(Logger)
}

func A() {
    logger := log.WithFields(log.Fields{"user_id", 1})
    ctx := mylog.ContextWithLogger(context.Background(), logger)
    B(ctx)
}

func B(ctx context.Context) {
    logger := mylog.FromContext(ctx)
    logger.Info("Hello, world!")
}

ただし、この手法はloggerを利用したい関数でcontextからloggerを取り出す命令を書かなければいけないので、そこだけ若干煩雑でコードの美しさが損なわれると感じていました。

slogの特徴

さて、Go 1.21からはGoビルトインのlog/slogパッケージが登場しました。https://go.googlesource.com/proposal/+/master/design/56345-structured-logging.mdがプロポーザルの内容で、こちらを読むとどのような思想で設計されたのかを知ることができます。

Logger/Handler

LoggerとHandlerという２つのインタフェースに概念が分離されました。

Loggerのほうはフロントエンド・ファサードのような立ち位置で、たとえばloggerのInfo(msg string, args ...any)というメソッドを呼ぶことでINFOレベルのログが書けますというインタフェースが定義されています。

Handlerは実際にログのレコードを作って書き込むという処理を担います。text、jsonといった出力フォーマットを変えることができるのはもちろん、ログレコードに特定のフィールドを追加するといった処理も可能です。

Loggerのインタフェースとして、contextを引数に持つ関数が用意される

InfoContext(ctx context.Context, msg string, args ...any) のように、ログを出力する関数の引数にcontextを持つものが用意されました。Handlerは渡されたcontextの値を利用することができます。

デフォルトLogger

従来のlog packageと同様にslog.SetDefault(l *Logger)というデフォルトのloggerを登録しておける関数が用意されています。デフォルトのloggerを登録しておくと、loggerのインスタンスからログ出力関数を呼び出さなくてもslog.Info()のようにpackage名から直接ログを書き出すことができます。

実装としてはグローバル変数にloggerが格納されているのと大差ないのですが、複数のgoroutineから呼ばれことを考慮してsync/atomicが利用されています*1。

contextの中身を見て自動でフィールドを追加するHandlerがあれば……

これらの特徴を見て私は「場所によって構造化ログに自動で入れたいフィールドを制御したいという理由だけで、リクエストごとloggerを作って引き回す必要はなくなったのでは」と思いました。具体的には、contextの値を読み取って自動でフィールドを追加するようなHandlerを作り、これを用いて作ったloggerをデフォルトとして登録してしまえば、リクエストごと作ったloggerを引き回す必要がなくなるという見立てです。

こういった方針で作ってみたのが以下のコードです。contextに含まれる特定のキーの値をHandlerがログレコードのフィールドに追加するようなHandlerができました。

package main

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

var keys = []string{"user_id", "request_id"}

type MyLogHandler struct {
    slog.Handler
}

var _ slog.Handler = &MyLogHandler{}

func (h *MyLogHandler) Handle(ctx context.Context, r slog.Record) error {
    for _, key := range keys {
        if v := ctx.Value(key); v != nil {
            r.AddAttrs(slog.Attr{Key: string(key), Value: slog.AnyValue(v)})
        }
    }
    return h.Handler.Handle(ctx, r)
}

func main() {
    logger := slog.New(&MyLogHandler{slog.NewJSONHandler(os.Stderr, nil)})
    slog.SetDefault(logger)
    A()
}

func A() {
    ctx := context.WithValue(context.Background(), "user_id", 1)
    ctx = context.WithValue(ctx, "request_id", "000")
    B(ctx)
}

func B(ctx context.Context) {
    slog.InfoContext(ctx, "Hello, world!")
}

https://go.dev/play/p/pjs7A-WNptj

slog.InfoContext(ctx, "Hello, world!")という呼び出しで

{"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"Hello, world!","user_id":1,"request_id":"000"}

というログが書き出されます。

任意のkeyでもログに書けるようなHandler

先ほどの手法では、ログに書き出したいcontextのフィールドのリストを定義しておく必要があります。しかし、ログに書き出したいものが増えるたびにリストを編集するのは大変だし、そもそもloggerという存在がアプリケーションの内部のことを知っている（たとえばrequest_idというログに書き出したい存在がいること）ように見えて微妙な感じがします。

contextにsync.Mapを持ち、その中身をログに書くHandler

ログに書き出したいcontextのkeyを1つ1つ管理しなくても良い手法として、contextにmapを持ってしまい、handlerとしてはmapの中身を全部書き出してしまうやり方があります。mapのキーだけ決めてしまえば良いです。

  • context
    • user_id <- このキーをログに出すと管理
    • request_id <- このキーをログに出すと管理

という構造だったのが、

  • context
    • logcontext (map) <- このキーをログに出すと管理
      • user_id
      • request_id
      • その他なんでも

という構造になるイメージです。

ただし、goroutine safeになるようにただのmapではなくsync.Mapを使うと良いでしょう。実際にこの指針で実装されたslog HandlerがGitHubで公開されています。

github.com

2024-05-22 追記：上記slog-contextの実装は、親のcontextに入っているmapを子から破壊する実装になっていました。issueとPRが出ていたのでそのうち直されるかも WithValue on contex with existing fields affects the parent context · Issue #5 · PumpkinSeed/slog-context

OpenTelemetry Baggageの中身をログに書くHandler

また、ログに書き出したいものの置き場としてOpenTelemetryのBaggageを利用するのも手です。

opentelemetry.io

Baggageはテレメトリのためのコンテキスト情報をspan（service）をまたいでも伝達するためのキーバリューストアです。Baggageの基本的な使い方として挙げられるのは、下流のサービスに上流のサービスのコンテキスト情報（何らかのIDとか）を受け渡し、下流のサービスではBaggageから値を取り出してspanのattributeに追加する、といった流れです。Baggageに入れるのはテレメトリに付与したい情報なので、その中身をログに書きだしても大抵は不都合がないでしょう。

OpenTelemetry Baggageをcontextから取り出してログに書くslog handlerについても、すでにサードパーティの実装があります。Baggageの中身だけでなくトレースIDもログレコードに付与してくれるので、ログとトレースを紐づけたいときにとても便利です。

github.com

まとめ

典型的なWebアプリケーションにおいて、「ここだけはJSONログにしたい」など複数のslog handlerを併用したいことは少ないと感じています。やりたいのは高々ログに付与する属性を制御したい程度でしょう。その役割はcontextの中身を見てよしなにするリッチなhandlerに任せることで、リクエストごとにloggerインスタンスを作る必要がなくなります。リクエストごとloggerが作られないのなら、頑張って引き回す必要もなくなり、デフォルトのloggerに登録しておけばどこでもslog packageから呼び出してシンプルにログを書き出すことができます。Webアプリケーションのloggerとしてはこの考え方で十分実用に適うと思います。

*1:https://github.com/golang/go/blob/66d34c7d08d7c536c3165dc49ed318e73ea5acc2/src/log/slog/logger.go#L61-L74