slogによる構造化ロギング

Structured Logging with slog by Jonathan Amsterdam

Go 1.21で新たに追加された log/slog パッケージは、構造化ロギングを標準ライブラリにもたらします。構造化ログはキーと値のペアを使うため、迅速かつ確実にパース、フィルタリング、検索、分析ができます。サーバーにとって、ロギングは開発者がシステムの詳細な挙動を観察するための重要な手段であり、デバッグの際に最初に頼ることも多いものです。そのため、ログは大量になりがちで、迅速に検索してフィルタリングできることが欠かせません。

標準ライブラリには、10年以上前のGoの最初のリリース以来、 log というロギングパッケージが存在してきました。時間が経つにつれ、構造化ロギングがGoプログラマにとって重要であることがわかってきました。Goの年次アンケート調査では一貫して高い順位にランクインしており、Goのエコシステムには構造化ロギングを提供するパッケージが数多く存在します。中には非常に人気の高いものもあります。Go向けの初期の構造化ロギングパッケージの1つである logrus は、10万を超える他のパッケージで使われています。

選択肢となる構造化ロギングパッケージが数多く存在する結果、大規模なプログラムでは依存関係を通じて複数のロギングパッケージを取り込んでしまうことがよくあります。メインプログラム側では、ログの出力が同じ場所に同じフォーマットで揃うように、それぞれのロギングパッケージを設定しなければならないかもしれません。構造化ロギングを標準ライブラリに含めることで、他のすべての構造化ロギングパッケージが共有できる共通の基盤を提供できます。

slogを一通り見る

次は slog を使った最もシンプルなプログラムです。

package main

import "log/slog"

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

この記事の執筆時点では、次のように出力されます。

2023/08/04 16:09:19 INFO hello, world

Info 関数は、デフォルトロガーを使ってInfoログレベルでメッセージを出力します。このデフォルトロガーは、今回のケースでは log パッケージのデフォルトロガー、つまり log.Printf を書いたときに使われるのと同じロガーです。これで出力がよく似ている理由がわかります。新しいのは「INFO」の部分だけです。標準の状態でも、 slog と元々の log パッケージは連携して動作するので、簡単に使い始められます。

Info の他にも、 Debug 、 Warn 、 Error という3つのレベル用の関数があり、さらにレベルを引数に取るより汎用的な Log 関数もあります。 slog ではレベルは単なる整数なので、名前の付いた4つのレベルだけに縛られることはありません。例えば Info は0、 Warn は4なので、この間のレベルがロギングシステムに必要であれば、2を使えます。

log パッケージとは異なり、メッセージの後にキーと値のペアを書くだけで簡単に出力に追加できます。

slog.Info("hello, world", "user", os.Getenv("USER"))

出力は次のようになります。

2023/08/04 16:27:19 INFO hello, world user=jba

先に触れたとおり、 slog のトップレベル関数はデフォルトロガーを使います。このロガーを明示的に取得して、そのメソッドを呼び出すこともできます。

logger := slog.Default()
logger.Info("hello, world", "user", os.Getenv("USER"))

すべてのトップレベル関数は slog.Logger のメソッドに対応しています。出力は先ほどと同じです。

初期状態では、 slog の出力はデフォルトの log.Logger を経由するため、ここまで見てきたような出力になります。ロガーが使う ハンドラ を変更することで、出力を変えられます。 slog には2つの組み込みハンドラが用意されています。 TextHandler は、すべてのログ情報を key=value という形式で出力します。次のプログラムは TextHandler を使って新しいロガーを作成し、同じように Info メソッドを呼び出します。

logger := slog.New(slog.NewTextHandler(os.Stdout, nil))
logger.Info("hello, world", "user", os.Getenv("USER"))

出力は次のようになります。

time=2023-08-04T16:56:03.786-04:00 level=INFO msg="hello, world" user=jba

すべてがキーと値のペアに変換され、構造を保つために必要に応じて文字列がクォートされています。

JSON形式で出力したい場合は、代わりに組み込みの JSONHandler を設定します。

logger := slog.New(slog.NewJSONHandler(os.Stdout, nil))
logger.Info("hello, world", "user", os.Getenv("USER"))

これで出力は、ロギングの呼び出し1回につき1つのJSONオブジェクトが並ぶ形になります。

{"time":"2023-08-04T16:58:02.939245411-04:00","level":"INFO","msg":"hello, world","user":"jba"}

組み込みのハンドラだけに限られているわけではありません。誰でも slog.Handler インターフェースを実装することでハンドラを書けます。ハンドラは特定のフォーマットで出力を生成することも、別のハンドラをラップして機能を追加することもできます。 slog のドキュメントにあるサンプルの1つでは、ログメッセージが表示される最小レベルを変更するラッピングハンドラの書き方を示しています。

これまで使ってきた、属性をキーと値を交互に並べる構文は便利ですが、頻繁に実行されるログ出力文では、 Attr 型を使って LogAttrs メソッドを呼び出すほうが効率的な場合があります。これらは連携してメモリアロケーションを最小限に抑えます。文字列や数値、その他一般的な型から Attr を組み立てるための関数が用意されています。次の LogAttrs の呼び出しは上記と同じ出力を生成しますが、より高速です。

slog.LogAttrs(context.Background(), slog.LevelInfo, "hello, world",
    slog.String("user", os.Getenv("USER")))

slog にはこの他にもたくさんの機能があります。

先ほどの LogAttrs の呼び出しで示したとおり、一部のログ関数には context.Context を渡せるので、ハンドラがトレースIDのようなコンテキスト情報を取り出せます。（コンテキストをキャンセルしても、ログエントリの書き込みが妨げられることはありません。）
Logger.With を呼び出すことで、そのロガーのすべての出力に現れる属性を追加でき、複数のログ出力文に共通する部分を実質的に括り出せます。これは便利なだけでなく、後述するようにパフォーマンスの向上にも役立ちます。
属性はグループにまとめられます。これによってログ出力により多くの構造を持たせられ、そのままでは同じになってしまうキーを区別しやすくなります。
値の型に LogValue メソッドを実装することで、その値がログにどう現れるかを制御できます。これは、例えば構造体のフィールドをグループとしてログ出力することや、機密データを伏せ字にするといった用途に使えます。

slog のすべてを学ぶには、パッケージのドキュメントを読むのが一番です。

パフォーマンス

私たちは slog を高速にしたいと考えました。大規模なパフォーマンス向上のために、 Handler インターフェースを、最適化の余地を残す形で設計しました。 Enabled メソッドはすべてのログイベントの最初に呼び出され、ハンドラが不要なログイベントを素早く捨てる機会を与えます。 WithAttrs と WithGroup メソッドによって、ハンドラは Logger.With で追加された属性を、ログ出力の呼び出しごとではなく一度だけフォーマットできます。この事前フォーマットは、 http.Request のような大きな属性を Logger に追加し、それを多数のログ出力呼び出しで使う場合に、大きな高速化をもたらします。

パフォーマンス最適化の作業の指針とするために、既存のオープンソースプロジェクトにおけるロギングの典型的なパターンを調査しました。その結果、ロギングメソッドの呼び出しの95%以上が5個以下の属性しか渡していないことがわかりました。また属性の型も分類し、少数の一般的な型が大部分を占めていることがわかりました。そこで、よくあるケースを捉えたベンチマークを書き、それを指針として時間がどこに費やされているかを調べました。最も大きな成果が得られたのは、メモリアロケーションに注意深く気を配った部分でした。

設計プロセス

slog パッケージは、2012年にGo 1がリリースされて以来、標準ライブラリに対する最大級の追加の1つです。私たちはこの設計にじっくり時間をかけたいと考えており、コミュニティからのフィードバックが不可欠であることもわかっていました。

2022年4月までに、構造化ロギングがGoコミュニティにとって重要であることを示すのに十分なデータが集まりました。Goチームは、これを標準ライブラリに追加することを検討することにしました。

私たちはまず、既存の構造化ロギングパッケージがどのように設計されているかを調べることから始めました。またGoモジュールプロキシに保存されている大量のオープンソースGoコードを活用して、これらのパッケージが実際にどう使われているかを学びました。最初の設計は、この調査とGoのシンプルさという精神の両方に基づいたものでした。パフォーマンスを犠牲にすることなく、コード上で軽く、理解しやすいAPIにしたいと考えました。

既存のサードパーティ製ロギングパッケージを置き換えることは、そもそも目標にしていませんでした。それらはいずれもそれぞれの役割をうまく果たしていますし、うまく動いている既存のコードを置き換えるのは、開発者の時間の使い方としてはめったに良い選択ではありません。私たちはAPIをフロントエンドである Logger とバックエンドのインターフェースである Handler に分けました。こうすることで、既存のロギングパッケージが共通のバックエンドとやりとりできるようになり、それらを使っているパッケージは書き直すことなく相互運用できます。 Zap 、 logr 、 hclog をはじめとする、多くの一般的なロギングパッケージ向けのハンドラがすでに書かれているか、開発が進められています。

最初の設計は、Goチーム内と、ロギングについて豊富な経験を持つ他の開発者たちに共有しました。彼らからのフィードバックをもとに変更を加え、2022年8月までには実用に足る設計になったと感じました。8月29日、実験的な実装を公開し、コミュニティの意見を聞くための GitHub discussionを開始しました。反響は熱心で、おおむね好意的なものでした。他の構造化ロギングパッケージの設計者やユーザーからの洞察に富んだコメントのおかげで、いくつかの変更を行い、グループや LogValuer インターフェースといった機能をいくつか追加しました。ログレベルと整数の対応付けは2度変更しました。

2か月と約300件のコメントを経て、正式なプロポーザルと、それに付随する設計ドキュメントを出せる状態になったと感じました。このプロポーザルのissueには800件を超えるコメントが寄せられ、APIと実装の両方に多くの改善がもたらされました。ここでは、いずれも context.Context に関するAPI変更の例を 2つ紹介します。

当初のAPIでは、ロガーをコンテキストに追加できるようになっていました。多くの人が、ロガーを気にしないコード層を通じて簡単に受け渡すための便利な方法だと感じました。しかし別の人たちは、これは暗黙の依存関係をこっそり持ち込むものであり、コードを理解しにくくすると感じました。最終的に、議論を呼びすぎるという理由でこの機能を削除しました。
また、ロギングメソッドにコンテキストを渡すべきかという関連する問題にも取り組み、いくつもの設計を試しました。当初は、すべてのロギング呼び出しでコンテキストを必須にしたくなかったため、コンテキストを第一引数として渡すという標準的なパターンに抵抗していましたが、最終的にはコンテキストありとコンテキストなしの、2種類のロギングメソッドを用意しました。

変更しなかった点の1つが、属性を表現するためのキーと値を交互に並べる構文についてです。

slog.Info("message", "k1", v1, "k2", v2)

多くの人が、これは良くない考え方だと強く感じていました。読みにくく、キーや値を書き漏らすといった間違いも起こしやすいという意見です。彼らは、構造を表現するために明示的な属性を使うほうを好みました。

slog.Info("message", slog.Int("k1", v1), slog.String("k2", v2))

しかし私たちは、特にGoを使い始めたばかりのプログラマにとって、Goを簡単で楽しく使えるものであり続けるためには、この軽量な構文が重要だと考えました。また、 logr 、 go-kit/log 、（ SugaredLogger を使った） zap といった複数のGo向けロギングパッケージが、キーと値を交互に並べる方式をうまく使いこなしていることも知っていました。私たちはよくある間違いを捕まえるための vetチェックを追加しましたが、設計自体は変更しませんでした。

2023年3月15日にこのプロポーザルは受理されましたが、まだいくつかの細かい未解決の問題が残っていました。その後の数週間で、さらに10件の変更が提案され、解決されました。7月初旬までには、 log/slog パッケージの実装が完成し、ハンドラを検証するための testing/slogtest パッケージや、キーと値を交互に並べる書き方が正しいかを確認するvetチェックも揃いました。

そして8月8日、Go 1.21がリリースされ、 slog もそれとともに世に出ました。 slog が皆さんの役に立ち、私たちが作っていて楽しかったのと同じくらい、使っていて楽しいものであることを願っています。

最後に、議論とプロポーザルのプロセスに参加してくださったすべての方に、大きな感謝を伝えます。皆さんの貢献のおかげで、 slog は大きく改善されました。

参考資料

log/slog パッケージのドキュメントには、使い方の説明といくつかのサンプルが用意されています。

wikiページには、様々なハンドラをはじめとする、Goコミュニティが提供する追加のリソースがあります。

ハンドラを書きたい場合は、ハンドラ作成ガイドを参照してください。

By Jonathan Amsterdam