恒例のGo 1.21連載が始まります。

Go 1.21は久々の新しいライブラリが大量追加だったり、既存のパッケージへの改良の多数行われたり、あたらしい組み込み巻数が追加されたりで記事などが書きやすいリリースです。残念ながら、フューチャーで一番Goを使っているプロジェクトが山場で今回はちょっと書き手が少ないのですが、今回もお付き合いいただけるとうれしいです。

1.21の更新内容のまとめダイジェスト

• 1.18の時に入るといって直前にキャンセルになった、ジェネリクスのためのパッケージslices/mapsの復活
• 新しい組み込み巻数のmin/max/clearの追加
• 言語仕様の強化
  • パッケージの初期化順序が仕様化
  • 型推論ちょっぴり強力に
  • 次期バージョンで入る予定のループ変数が共有されちゃうバグ対策が実験実装
• ランタイムの性能改善(いつもの)
  • 深いスタックオーバーフロー時のトレースが見やすく(最新100ではなく、最新50と一番外側の50表示されるように)
  • GCの性能改善でTail Latency(レイテンシーの分布図のうち、最悪側）が最大40％減少
  • CGoでCとGoの間のオーバーヘッドが1/10に
• コンパイラの改善
  • 1.20で入ったPGO（プロファイル結果を活用した最適化)でインタフェースを具象実装に展開して高速化
  • PGOがコンパイラ自体にに適用されて性能改善
• コアライブラリの追加(多数)
  • slogパッケージが追加
  • slices/maps/cmpパッケージが追加
  • 既存パッケージへの追加は大量で書ききれないので本家をご覧ください

slogをどう使うべきか

• log/slogリファレンス

今回、新しいロガーが追加されました。ログはアプリケーションの状態を知る上で大切な手がかりを提供します。以前からあったGoのlogパッケージは、とても質素な作りで、デフォルト設定では日時を付与してテキストを出すだけのものでした。他の言語にはあるようなログレベルでのフィルタリングなどもありませんでした。

そのこともあり、zerolog、zapなど、高機能を売りとするサードパーティライブラリがいくつも登場し、人気となっています。もちろん、これらはパフォーマンス重視ということもあり、少しでも高速なものが欲しければこちらもまだ価値はあるでしょう。

自前のアプリケーションであればそれこそ自由に使えばいいのですが、自分が開発するコードがライブラリだったりすると、どういった使い方をすれば行儀が良いのか、というのが気になります。そういった観点でいろいろドキュメントやらソースコードを眺めてみて、きっとこういう使い方をすべきだろうな、というところをまとめてみました。

slogはかなり注目されている新パッケージで、解説もすでにいろいろ書かれているので簡単な使い方の解説などはそちらに譲ります。このエントリーでは実際にアプリケーションに組み込む場合に考えていかないと行けなそうなことにフォーカスします。

slogの構造

slogのドキュメントを見ると、構造体やら何やらがたくさんあります。ぱっと見、どこから手をつけていいのか・・・となりますよね？

Handlerは最後の出力を担うインタフェースです。標準ライブラリにはテキスト出力とJSON出力があります。直接ハンドラーを操作することはありません。Loggerの初期化時に設定しておしまいです。ログ出力の最終段として、「必ず1つだけある」と考えてください。ログ出力の方式を決めるため、基本的にライブラリやアプリケーションのサブパッケージでこれをインスタンス化することはなく、アプリケーションの、いわばmain関数が作ることになると思います。

Handlerを渡してLogger構造体のインスタンスを作り、ログ出力はこのLoggerのインスタンスに対して指令します。このLoggerのInfo()やDebug()やWarn()やらDebug()やらを使うと、その情報がHandlerに渡って出力される、という流れです。ログレベルのフィルタリングなどはHandlerの仕事です。

ロガーは子ロガーを作れます。親ロガーに対して、いくつかの属性（Attr)を付与したロガーです。このロガーで出力すると、付与した属性が毎回出力されます。Javaのlog4jなどを知っている人はMapped Diagnostic Context (MDC)を想像すればすぐに理解できるでしょう。

まあ、この図や説明はわかりやすくするための嘘が入っています。実際は親への関連などはなく、Attrを付与すると、Attrのインスタンスが設定されたHandlerのコピーと、それを参照するロガーのコピーが丸ごと作られます。このように実際にはパフォーマンスのために親をたどって属性収集を毎回したりしなくて済むようにコピーしていますが、まあ、上の図みたいにロガーに親子関係があって、ハンドラーが1つと考えた方がわかりやすいかと思います。コピーされるハンドラとかにはどうせ触れないですし。

あとは、1つのログの情報がRecordということぐらい知っておけば十分かと思います。

Fluentbitやsyslogに情報を流すハンドラーとか、そのままウェブアプリケーションが立ち上がってブラウザ上でログが見れるハンドラーとか、サードパーティ製のハンドラーはこれからぼちぼち登場するんじゃないかと思います。

slogとcontext.Context

slogにはcontext.Contextを扱う関数がたくさんあります。Goのコンテキストを知っている人やOpenTelemetryのGo実装を使ってみた人、Javaのlog4jとかを知っているからすると「属性設定済みのロガーをcontext.Contextに詰めて、予備先の関数でログを出した時に情報が出るようにするんでしょ？」と思うかもしれません。GoはOSスレッドがないのでスレッドローカルストレージがなく、コンテキストはその代替としてcontextのWithValue()は利用されている、というのをご存知の方も多いと思います。そのため、僕も僕もそう思っていました。

しかし、どんなにドキュメントをみても、ロガーを出し入れする関数はありません。そういう使い方を議論するissueもありましたが　現状はハンドラーにそのまま渡しているだけです。

よくよく考えればトレーシングIDなどは、コンテキストに格納されているはずで、ロガーにも属性として持つと2重持ちになってしまいます。出力時だけハンドラ自身がそれを取り出して書き出せば良い、という思想に思えます。

そのためにはハンドラーを自分でつくることになります。ウェブアプリケーションのミドルウェアのような構造でハンドラーをたくさん数珠繋ぎにすることになるかと思います。コンテキストに載せた情報を抽出してログに追加するハンドララッパーは次のようなコードになります。

package sloghelper

import (
	"context"
	"log/slog"

	"github.com/shibukawa/uuid62/v2"
)

// コンテキストにIDを設定
type _CtxKeyType struct{}

var ctxKey = _CtxKeyType{}

func WithTraceID(ctx context.Context) context.Context {
	traceID, _ := uuid62.V7()
	return context.WithValue(ctx, ctxKey, traceID)
}

// ハンドラーのラッパー
type WriteTraceIDHandler struct {
	parent slog.Handler
}

func WithWriteTraceIDHandler(parent slog.Handler) *WriteTraceIDHandler {
	return &WriteTraceIDHandler{
		parent: parent,
	}
}

// ログ出力に情報を付与するメソッド
func (h *WriteTraceIDHandler) Handle(ctx context.Context, record slog.Record) error {
	record.Add(slog.String("traceID", ctx.Value(ctxKey).(string)))
	return h.parent.Handle(ctx, record)
}

func (h *WriteTraceIDHandler) Enabled(ctx context.Context, level slog.Level) bool {
	return h.parent.Enabled(ctx, level)
}

func (h *WriteTraceIDHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
	return &WriteTraceIDHandler{h.parent.WithAttrs(attrs)}
}

func (h *WriteTraceIDHandler) WithGroup(name string) slog.Handler {
	return &WriteTraceIDHandler{h.parent.WithGroup(name)}
}

var _ slog.Handler = (*WriteTraceIDHandler)(nil)

// ハンドラとロガーの初期化
handler := WithWriteTraceIDHandler(slog.NewTextHandler(
    os.Stdout,
    &slog.HandlerOptions{
    	Level: slog.LevelDebug,
    }
))
slog.SetDefault(slog.New(handler))

// コンテキストに情報を載せてslogを呼ぶ
ctx := sloghelper.WithTraceID(context.Background())
slog.InfoContext(ctx, "test")

無事トレースIDが出力されました。たぶん、アプリケーションごとにハンドララッパーは今後たくさん作られることになると思います。まあ、Handle()メソッドだけが関心ごとなので、http.HandlerFuncみたいにもっと軽量な書き方をするヘルパーライブラリが作られる気もします。

time=2023-07-27T12:57:07.862+09:00 level=INFO msg=test traceID=2ts7gl7Y2bPmfd9L651m1

(参考)Pythonのログのベストプラクティス

もうみなさんはエキスパートPythonプログラミング改訂4版を手にとっていただき、一人10冊ぐらいはお買い上げいただいたと思いますが、この中ではPythonのログのベストプラクティスというのがあります。ログのシステムはこうあるべき、というイメージを共有する上でも参考になると思うのでこちらを軽く紹介します。

まず、slogを使えば勝手に実現できることとしては以下の通りです。

• ログハンドラをルートロガーレベルに維持する
• 構造化ログメッセージを使用する
• ログの設定は一箇所で行う
• 可能であれば、標準出力またはエラーストリームに直接ログを記録する

Goのslogはトップでハンドラを1つしか持てないので、ハンドラは1つしか持てません。構造化ログも利用できます。ばっちりですね。設定もハンドラの初期化部分のみなのでこれも1箇所というのが自然と実現できます。また、Pythonには標準で15種類のログハンドラーがありますが、Goはテキスト出力とJSON出力だけです。出力先はio.Writerなのでos.Stdoutなどを指定すればすぐにコンソールに書き出せます。クラウド時代はこれだけでログコレクターが集めてくれるので必要十分と言えます。

Goでもそのまま共通で使えそうなプラクティスは以下の通りです。

• 1つのイベントは1行に
• システムのログ機能や分散ログシステムに委譲する
• カスタム分散ログシステムを作成する衝動を避ける

構造化ログというと、たくさんの情報が格納できますが、それぞれの行で独立したイベントを出力すると扱いやすくなります。共通の属性を持たせて、それでフィルタリングできるようにするとなお良いでしょう。

2つ目と3つ目ですが、Goだけですごく複雑なログ処理を実装するのは得策ではありません。ログをファイル出力してローテーションしつつ、定期的にどこかのファイルサーバーにバックアップなど、そう言った仕組みを作りこんだりはしない方が良いでしょう。もちろん、そういった車輪の再発明は間違いなく楽しいのですが、信頼性も要求されるため、既存のログ収集の仕組みを活用すべきです。

次の仕組みは今のslogでは利用できない機能です。

• モジュールごとのロガーを使用する

Pythonはfuture.cool.appみたいにロガーにピリオド区切りの名前をつけられます。これが階層になっており、下の階層から上の階層にフィルタリングしながらログを集約していく、という構成になっています。ロガーごとにハンドラーを設定し、特定のパッケージのログはファイルに書くが、それ以外のログは出力しない、みたいな制御ができたりしますが、ここまでの柔軟性はslogにはありません。

slogの使い方の参考のためにもっと詳しく知りたい人はPythonのlogging HOWTOも参考になると思います。ロガーがたくさん持てたり、slogにはないフィルターというのがある以外は用語も近いし、アーキテクチャを考える人であれば何かしら得るものはあると思います。

現状でのサードパーティライブラリのログ方針

アプリケーションのログはハンドラの初期化も、どのようなメタデータを渡すのかも含めてなんでも自由にすれば良いのですが、ライブラリ側が好き勝手にログを出すと嫌われるでしょう。使う側のアプリケーション側からはライブラリに対して次のような情報を制御したいと思うでしょう。

• ログのフィルタリング
• ログに渡す追加情報

ログのフィルタリングは出力するログレベルの制御です。デバッグ中は細かく出したい、本番ではクリティカルなエラーの情報だけ出したい、ということが考えられます。現状はルートのハンドラ側での制御しかないため、ライブラリ側で「ライブラリごとの制御」というのは標準APIをそのまま使うだけでは実現できません。

例えば、アプリケーションがDBアクセスのライブラリだったとして、アプリケーションが持っているサーバーのインスタンスIDみたいな情報を、ライブラリから出すにも付与したい、というのが後者です。これは、前述のハンドラのラッパーを使えば実現できます。

問題は前者です。ハンドラ側でも呼び出し元情報が得られるので制御ができますが、ライブラリ側がアプリ側に特別なハンドラを使わせるのを強要するのは無理筋でしょう。そのため、ハンドラに手を加える案はこの場合利用できません。そうなると、ライブラリがロガーを呼び出す部分に干渉するしかなさそうです。

ということでロガーのメソッドをまるごとシミュレートしつつ、ライブラリ内部だけでログレベルでフィルタリングするようなものが必要になると思われます。だいたいこんなコードです。

type LoggerFactory struct {
	level  slog.Level
	logger *slog.Logger
}

func NewLoggerFactory() *LoggerFactory {
	return &LoggerFactory{
		level: slog.Error,
	}
}

func (lf *LoggerFactory) SetLevel(level slog.Level) {
	lf.level = level
}

func (lf *LoggerFactory) SetLogger(logger *slog.Logger) {
	lf.logger = logger
}

func (lf *LoggerFactory) Get() *FilterLogger {
	if lf.logger == nil {
		return &FilterLogger{
			level:  lf.level,
			logger: slog.Default(),
		}
	} else {
		return &FilterLogger{
			level:  lf.level,
			logger: lf.logger,
		}
	}
}

type FilterLogger struct {
	level  slog.Level
	logger *slog.Logger
}

func (l *FilterLogger) Enabled(ctx context.Context, level slog.Level) bool {
	if l == nil || l.level > level {
		return false
	}
	return l.logger.Enabled(ctx, level)
}

func (l *FilterLogger) Log(ctx context.Context, level slog.Level, msg string, args ...any) {
	if l == nil || l.level > level {
		return
	}
	l.logger.Log(ctx, level, msg, args...)
}

func (l *FilterLogger) LogAttrs(ctx context.Context, level slog.Level, msg string, attrs ...slog.Attr) {
	if l == nil || l.level > level {
		return
	}
	l.logger.LogAttrs(ctx, level, msg, attrs...)
}

func (l *FilterLogger) Debug(msg string, args ...any) {
	if l == nil || l.level > slog.LevelDebug {
		return
	}
	l.logger.Debug(msg, args...)
}

:
// 以下、DebugContext, Info, InfoContext, Warn, WarnContext, Error, ErrorContextは
// それぞれのログレベルで比較して親ロガーを呼ぶだけでほぼ同じなのでしょうりゃく　

利用するライブラリ側では、このファクトリー関数の初期化と、これを呼び出して2つ公開関数を追加します

// ↓ここから
var lf = sloghelper.NewLoggerFactory()

// これを公開しておく
func SetLogLevel(level slog.Level) {
	lf.SetLevel(level)
}

func SetLogger(logger *slog.Logger) {
	lf.SetLogger(logger)
}
// ↑ここまでは定型句としてパッケージごとにSetLogger()公開関数を定義する

あとはslogではなくて、このGet()メソッドで取り出したFilterLoggerのメソッドを代わりに呼べば、制御が可能です。

// すごい計算アルゴリズム
func Calc(n int) int {
	// 1からnまでの合計を計算しちゃう
	lf.Get().Info("計算開始", slog.Int("入力値", n))
	total := 0
	for i := 1; i < n+1; i++ {
		total += i
		lf.Get().Debug("計算途中", slog.Int("番目", i), slog.Int("合計", total))
	}
	if total > 256 {
		// たいへん！オーバーフローだ！
		lf.Get().Error("オーバーフロー", slog.Int("入力値", n))
	}
	lf.Get().Info("計算結果", slog.Int("結果", total))
	return total
}

さらにこのファクトリーの初期化時に環境変数からエラーレベルを変えるとか制御できるようになると夢が広がりますね。

func packageName(depth int) string {
	pc, _, _, ok := runtime.Caller(depth + 1)
	if !ok {
		panic("can't get caller")
	}
	fullName := runtime.FuncForPC(pc).Name()
	lastSlash := strings.LastIndexByte(fullName, '/')
	if lastSlash < 0 {
		lastSlash = 0
	}
	lastDot := strings.IndexByte(fullName[lastSlash:], '.') + lastSlash
	return fullName[:lastDot]
}
func NewLoggerFactory() *LoggerFactory {
	pn := packageName(1)
	env := os.Getenv("SLOG_" + strings.ReplaceAll(strings.ReplaceAll(pn, "/", "_"), ".", "_"))
	level := slog.LevelError
	if env != "" {
		err := level.UnmarshalText([]byte(env))
		if err != nil {
			fmt.Fprintf(os.Stderr, "Unknown Log Level for package %s: %s (fallback to LevelError)", pn, env)
			level = slog.LevelError
		}
	}
	return &LoggerFactory{
		level: level,
	}
}

まとめ

slogの基本的な使い方はすっ飛ばして、新しいアプリケーションやライブラリの開発にslogを組み込むにあたって、どのようにラッパーを作成するか、利用者側からは行儀の良いライブラリになるのか、といった観点でまとめてみました。

明日は真野隼記さんの記事になります。