slog-handler-guide

slog-handler-guide の解説

shandler を作るにあたり(作りながら)参照した “slog-handler-guide” の解説です。

slog の出力先をロギングのサービスにつなげる、出力内容を変更する、などをしたい場合、インターフェイス Handler を満たすオブジェクトを作成することになります。

本投稿の元記事となるslog-handler-guide“では、シンプルな Handler を実装しつつ解説をしています。 シンプルな実装とはいえ、その中にいろいろな情報が詰め込まれています。 本投稿の目的は、部分的ながらも先にそれらの情報をピックアップして理解しておくことで、元記事の実装部分を読み進めやすくすることです。

本投稿は、元記事を翻訳をするわけではありません。 また、詳細な slog.Handler の実装を解説するというものでもありません。 「元記事の理解のために事前にみておくもの」という位置づけでご覧ください。

構成は元記事に倣っていますが、ところどころ別の話題の解説をしたりしています。

Loggers and their handlers

Logger は Handler を保持しており、Logger に対して行ったログ記録の操作が、Handler に伝えられる(その内容が slog.Record)ということです。

実際に Logger のソースコードを見ると、上記のようになっています。

1
2
3

type Logger struct {
	handler Handler // for structured logging
}

1
2
3
4
5
6

r := NewRecord(time.Now(), level, msg, pc)
r.AddAttrs(attrs...)
if ctx == nil {
    ctx = context.Background()
}
_ = l.Handler().Handle(ctx, r)

Logger は呼び出し側への機能(メソッド)を提供し、Handler は記録側の機能を提供します。

上記以外にも、結構この節では雑多なことが語られています。

Enabled

Logger が、Handler.Enabled を呼び出すことで、記録する必要があるか判断します。

Handler が意図したログレベルではない場合に切り捨てるために使っています。

1
2
3
4

func (l *Logger) log(ctx context.Context, level Level, msg string, args ...any) {
	if !l.Enabled(ctx, level) {
		return
	}

上記のコードで呼び出されている Logger.Enabled は、以下のように実装されています。

1
2
3
4
5
6

func (l *Logger) Enabled(ctx context.Context, level Level) bool {
	if ctx == nil {
		ctx = context.Background()
	}
	return l.Handler().Enabled(ctx, level)
}

解説: ログレベルは Handler と Record が保持します。

ログレベルといっても、2つあります。

1. ログを記録しようとするコード(Logger の呼び出し元)により毎回異なるログレベル
   • Logger.Info, Logger.Error など、呼び出しごとに異なるレベル
   • これは、Record が保持します。
   • このログ操作が記録されるべきか、判断される側のログレベルです。
2. 記録されるべき最小レベルとしてのログレベル
   • Handler を New する際に(省略することも可能)作成コード側から伝えられたログレベルのことです。
   • こちらは判断する側が基準とするログレベルです。

「出力側として」記録するかどうか判断するため、Logger ではなく Handler がログレベルを保持します。

1
2
3
4
5

handler := slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{
    Level: slog.LevelDebug,
})

logger := slog.New(handler)

解説: ログレベル

Handler が「記録されるべき最小のログレベル」を保持している、と理解していれば、以下の値の関係も理解しやすいでしょう。

1
2
3
4
5
6
7
8

type Level int

const (
	LevelDebug Level = -4
	LevelInfo  Level = 0
	LevelWarn  Level = 4
	LevelError Level = 8
)

上記の値以外を定義することで、異なるログレベルを定義することも可能なようです。

With

Logger.With や Logger.WithGroup を呼び出すことで、新たな Logger (したがって Handler も) の複製を作成します。

1
2
3
4
5

l1 := slog.New(...)

l2 := l1.WithGroup("group2")

// l1 != l2

With はログとして記録される属性を、WithGroup は名前空間を分けるための名前、…を付与した別の Logger を作成します。

With系を使って付与された情報をどのように出力するかは、Handler が決定します。

Implementing Handler methods

本投稿でもすでに解説したとおり、最小ログレベルを保持する必要があります。

また、出力側として必要なオブジェクト(io.Writer とか)も保持しておくこと、また同時実行されてもいいように sync.Mutex で保護することが求められます。 ログの内容が混在したらイヤですからね。

なお、With系のメソッドによる Handler の複製があるため、ポインターとして sync.Mutex を保持することの利点があるようです。

HandlerOptions

slog には HandlerOptions というものがあります。 これらは記録されるべきログレベルの指定のために使うことが多いと思います。

実際には、必要に応じて独自のオプションも定義することになるでしょう。 外部のログサービスを使うなら接続のための情報も必要でしょうし。(最近の風潮だとenvで渡すのかな)

なお、これらの値も同時実行中に参照される可能性があるため、Handler の外部から容易に変更できないようにする必要はあると思います。 変更できるようにする場合、設定全体の整合性を保ちつつ排他制御もする必要があるのではないかなと思います。 元記事でも slog の実装でも、オプションはポインターではなく実体を保持する形にしており、かつ外からは参照できないようにしています。

slog での Context の扱い

情報の伝達用途であり、キャンセルの扱いのためではない、ということのようです。

The Enabled method

すでに解説した通り、Logger が「本当にこのログ操作は記録に値するのか」を判断するために使われます。

ここには Record は渡されません。 context.Context が渡されるので、アプリケーション固有の情報をもとに判断する必要があるのであれば、これを介して行う必要があります。

The Handle method

Logger から渡された Record と自身の持っているオプション等の情報を使い、出力を行います。

Enabled が false を返した場合は、このメソッドは呼ばれません。

簡単なラッパーを作るのであれば、Record をそのまま(もしくは加工して)ラップした Handler に渡すのもありですね。

ここで重要なのは、出力は一度で行うということです。 これは、ログ内容の信頼性のためです。 バッファーを用意し、各属性値やメッセージ文字列を適切にバッファーに蓄積していき、そして Handle の最後で出力します。 また、出力の際には排他制御も行います。

なお、このメソッドには WithAttrs や WithGroup (いずれも後述) の情報は渡されないため、事前に自前で保持しておく必要があります。

Logger.Info 等で渡された属性値は Record.Attrs を使って取り出すことになります。 取り出した属性は、以下の2点を行う必要があります。

• 空の属性は無視する (a.Equal(slog.Attr{}) な属性 a は無視する)
• 値を Attr.Value.Resolve で解決する(メソッド LogValue を実装した値については、そのメソッドの結果に置き換える) を行う必要がある

The WithAttrs method

Logger.With から呼び出されるもので、Handler としては、渡された属性を保持した複製を作る(そして自身は変えない)必要があります。

自身は変えない、というところに注意してください。 このメソッドに渡された属性はすべて、複製が保持すべきものです。

ラッパーを作っている場合は、ラップされた側の WithAttrs を呼び出しつつ自身についても複製を作り、再度ラッピングすることになるでしょう。

なお、ここで渡された属性は(変なことをする属性でなければ)すべて不変とみなせますので、この時点で出力に都合の良い形に変えても問題ないようです。

The WithGroup method

Logger.With から呼び出されるもので、Handler としては、渡されたグループ名を保持した複製を作る(そして自身は変えない)必要があります。

これも WithAttrs と同様に、複製された方にグループ名を保持させる必要があります。

グループ名は、この呼び出し以降の WithAttrs や Handle で渡される属性の名前空間に影響させるべきものです。

TextHandler の場合↓のように、属性名がグループ名で装飾されるようになります。

time=2024-05-03T11:42:27.515+09:00 level=DEBUG msg=one attr1=value1 group1.attr2=value2

ログ出力の形式にもよりますが、グループ名はリストの形で保持した方が便利かもしれません。

Testing

Handler としての制約をテストするのはパッケージ testing/slogtest を使うとできますよ、ということが書いてあります。

出力内容については、それをチェックするテストコードを書いていくことになります。 JSON や YAML などの Unmarshaler 的なものがある形式であれば多少楽ができるかもしれません。

General considerations

実装を進めるうえで参考になることが記載されています。

Copying records

特殊用途についての解説のようで、通常、受け取った Record をそのまま使うのであればあまり考慮しなくてよさそうです。

Record は内部に参照値をもつため、コピーを他に渡したい場合は Record.Clone 使ってねということです。

Concurrency safety

Logger が多数のゴルーチンから呼び出される可能性があるので、Handler としても同時実行されても安全なようにしておこうね、ということが書かれています。

Handler が実装するべきメソッドそれぞれについての安全性の注意事項を説明しています。

Robustness

アプリケーションに対する調査の手がかりとしてログが使われることは想像に難くありません。

そういうこともあり、Handler としては、想定外の内容が来た場合に落ちるのではなく、エラーを返したり、無視したりできるようにしようね、ということが書かれれています。

Speed

まずは、速度以上に、きちんとログを記録できることの方が重要。あと本当に遅いのか実務データで計測した方が良い、と書かれています。

それでも高速化する必要がある場合は、以下の手法を挙げています。

• Logger.With 後の速度が問題なら、事前に属性を出力形式に加工しておく
• ログの出力が問題なら、出力を実行する部分をゴルーチンとして独立させ、Handle ではそのゴルーチンに投げて、自身はすぐに戻るようにする
• アロケーションの問題の場合は、バッファーに詰め込む際に高機能な重い関数を使うのではなく、細かいが効率的な関数を使った方がアロケーションを減らせる
• またバッファーの確保や拡張に時間がかかる場合 sync.Pool を使う