🦚

zapのLoggerのメソッドError()のログ出力の仕組み①

2023/01/04に公開約12,300字

概要

Goのロギングライブラリとしてzapを使うケースがよくあると思います。
今回はzapの二種類のLoggerのうち高パフォーマンスで構造化ログのみに対応しているLoggerに焦点を当てて、zapLoggerのメソッドの1つErrorメソッドがエラーをどのようにログ出力しているのかを確認するためzapの実装を見てみました。
この記事ではその時の個人の備忘録としてまとめていきます。

長くなるので前後編で二つの記事に分ける予定です。

全体のコード

まずサンプルコードとして次のようなコードを今回は使用しました。
(実行環境はMacOSになります。)

package main

import (
	"fmt"
	"go.uber.org/zap"
	"golang.org/x/xerrors"
	"log"
)

var (
	errInfra = xerrors.New("infra error")
)

type MyError struct {
	msg   string
	err   error
	frame xerrors.Frame
}

func (m *MyError) Error() string {
	return fmt.Sprint(m)
}

// Format implements fmt.Format
func (m *MyError) Format(s fmt.State, c rune) {
	xerrors.FormatError(m, s, c)
}

// FormatError implements xerrors.FormatError
func (m *MyError) FormatError(p xerrors.Printer) error {
	p.Print(m.msg)
	m.frame.Format(p)
	return m.err
}

func NewMyError(err error, msg string) error {
	return &MyError{
		msg:   msg,
		err:   err,
		frame: xerrors.Caller(1),
	}
}

func ui() error {
	if err := usecase(); err != nil {
		return NewMyError(err, "failed to exec usecase()")
	}
	return nil
}

func usecase() error {
	if err := infra(); err != nil {
		return NewMyError(err, "failed to exec infra()")
	}
	return nil
}

func infra() error {
	return errInfra
}

func main() {
	logger, err := zap.NewProduction()
	if err != nil {
		log.Fatalf("can't initialize zap logger: %v", err)
	}
	defer logger.Sync()

	if err := ui(); err != nil {
		msg := "my test msg"
		logger.Error(
			msg,
			zap.Error(err),
		)
	}
}

上記コードを実行すると次のような結果が出力されます。
(ログのキーのうちerrorVerbosestacktraceの値で実行環境のパスの部分はxxxyyyなどとしています)

{"level":"error","ts":1672820212.1863208,"caller":"my-logger/main.go:71","msg":"my test msg","error":"failed to exec usecase(): failed to exec infra(): infra error","errorVerbose":"failed to exec usecase():\n    main.ui\n        /Users/xxx/yyy/my-logger/main.go:46\n  - failed to exec infra():\n    main.usecase\n        /Users/xxx/yyy/my-logger/main.go:53\n  - infra error:\n    main.init\n        /Users/xxx/yyy/my-logger/main.go:11",,"stacktrace":"main.main\n\t/Users/xxx/yyy/my-logger/main.go:71\nruntime.main\n\t/usr/local/Cellar/go/1.19.4/libexec/src/runtime/proc.go:250"

上記コード中で今回見ていくのは下記部分になります。

		logger.Error(
			msg,
			zap.Error(err),
		)

loggerインスタンス生成部分のzap.NewProduction()などの処理は割愛します。
それでは次章以降で順にlogger.Errorの実装を見ていきます。

log.Error

loggerのメソッドErrorは引数に指定されたメッセージをlevel ErrorLevelでログ出力します。

▼メソッドlog.Error
https://github.com/uber-go/zap/blob/v1.24.0/logger.go#L234-L238

https://pkg.go.dev/go.uber.org/zap#Logger.Error

Errorメソッドの実装を確認すると、メソッド内部でloggerのプライベートメソッドcheck()を呼び出しています。その後その戻りceがnilでない場合にce.Write(fields...)を呼び出しています。
以降ではこの記事ではメソッドlog.checkの実装内容について見ていきます。

後編の記事でce.Write(fields...)の実装を見ていきます。

log.check

checkメソッドのシグネチャを確認すると、引数にzapcore.Levelmsg(string)を受け取り、
戻り値としてzapcore.CheckedEntryのポインタを返しています。

https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/logger.go#L289

▼zapcore.CheckedEntry
コメントを確認するとCheckedEntryはログのアウトプットに許可したEntryのコレクションであることがわかります。
詳細は実装の確認時に随時見ていきます。

https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/zapcore/entry.go#L206-L218

それではcheckメソッドの実装について見ていきます。

まず最初にint型の定数callerSkipOffsetを宣言して値として2を代入しています。
コメントにある通り、これはlogger.checkとこのメソッドの呼び出しもとであるlogger.Errorのcallerをスキップするために2を指定しています。
後にStackTraceのcapture部分で参照されます。

https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/logger.go#L289-L294

続いて無効化されているログ呼び出しによるコストを減らすためにこちらで確認しています。
今回の場合!log.core.Enabled(lvl)がtrueのためこの部分は実行されません。

https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/logger.go#L296-L300

続いてlog.checkの引数のmsg,ログレベルのlvllog.name、そして現在時刻をフィールドにセットしてzapcore.Entryを生成しています。

https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/logger.go#L302-L311

zapcore.Entryの定義を見るとEntrycomple log messageを表しているとのことです。
ここでセットされているフィールドの他にzapcore.EntryCaller型のCallerやstring型のStackなどがあります。

続けてlog.coreCheckメソッドを呼び出しています。
メソッドCheckは次のようにCoreインターフェースで定義されています。
コメントを確認するとこのCheckメソッドは指定されたEntryがログ出力されるべきかどうかを判定するメソッドです。もしここでログ出力対象として判定されると、EntryCheckedEntryにappendされてその結果がCheckの戻り値として返却されます。

https://github.com/uber-go/zap/blob/v1.24.0/zapcore/core.go#L36

https://github.com/uber-go/zap/blob/v1.24.0/zapcore/sampler.go#L215

今回はcoreにはSamplerがセットされているのでSamplerCheckメソッドが呼び出されます。

https://github.com/uber-go/zap/blob/v1.24.0/zapcore/sampler.go#L215

この結果、ceにはCheckedEntryが入ります。

続けてlog.Checkの処理に戻ってwillWriteにはtrueがそれぞれ代入されます。

▼zapcore.Entry
https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/zapcore/entry.go#L138-L152

zapcore.EntryCallerの定義を確認するとロギング関数のcallerを表す構造体になっています。
フィールドはスタックトレース用にプログラムカウンタのPCFileLileFunctionなどが定義されています。

https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/zapcore/entry.go#L71-78

続けてcheckメソッドのコードを見ていきます。EntryLevelに応じて振る舞いをセットアップしています。今回はErrorLevelのためここでのswitchブロックには当てはまらずにスキップされます。

https://github.com/uber-go/zap/blob/v1.24.0/level.go#L40

https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/logger.go#L313-L338

log.checkの内容を続けて見ていきます。
willWriteの値は今回の場合はtrueが入るのでここの処理はスキップされて処理は継続します。

https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/logger.go#L340-L345

続けてlog.checkを見ていきます。
CheckedEntryのフィールドのErrorOutput設定と変数addStackの定義を行なっています。
変数addStackにはlog.addStack.Enabled(ce.Level)の結果trueが代入されます。

https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/logger.go#L347-L353

続けてlog.checkの内容を見ていきます。

https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/logger.go#L355-L362

変数stackDepthの定義を行なっています。先ほど見た通りaddStackにはtrueがセットされているためstackDepthにはstacktraceFullが代入されます。

続けてプライベート関数のcaptureStacktraceを呼び出して結果を変数stackに代入しています。

captureStacktrace

https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/stacktrace.go#L70

captureStacktraceのシグネチャを確認すると、引数にint型のskipstacktraceDepth型(intのtype alias)のdepthを受け取って、プライベートの構造体stacktraceが戻り値となっています。

stacktraceDepth
https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/stacktrace.go#L53-L54

▼構造体stacktrace
https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/stacktrace.go#L39-L51

コメントを確認するとcaptureStacktrace指定されたdepthのスタックトレースをキャプチャする関数とのことです。引数skipで指定された分スタックフレームをスキップします。

https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/stacktrace.go#L65-L69

それでは順に実装をみていきます。

https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/stacktrace.go#L71

まず関数の冒頭で_stacktracePoolからメソッドGet()でpoolからstacktraceを取得するようにしています。

https://pkg.go.dev/sync#Pool.Get

続けて引数depthに応じてstack.pcsに値をセットしています。
前述で見てきたようにcaptureStacktraceの呼び出し側でdepthにはstacktraceFullが渡されているのでstack.pcsstack.storageが代入されます。

https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/stacktrace.go#L73-L78

https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/stacktrace.go#L80-L85

Go標準のruntimeパッケージの関数Callersを呼び出しています。
コメントにある通り引数skipskip+2を指定してruntime.CallerscaptureStacktrace自身の呼び出しのスタックフレームをスキップするように指定しています。

https://pkg.go.dev/runtime#Callers

runtime.Callersの実装の詳細についてはここでは長くなるので割愛して別記事で見ていきたいと思います。

そしてdepthの値に応じて処理を分岐しています。
今回の場合のようにstacktraceFullの場合、
stack.storagepcsを、stack.pcsに実際のスタックフレーム数のstack.pcs[:numFrames]を代入しています。

続けでcaptureStacktraceの実装を見ていきます。

https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/stacktrace.go#L87-L104

関数の最後にstack.framesruntimeパッケージの関数CallersFramesの呼び出した結果を代入して、最後に stackをreturnしています。

https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/stacktrace.go#L106-L107

関数runtime.CallersFrames[]uintptr型の引数callersを受け取ってruntime.Framesを返却します。

https://pkg.go.dev/runtime#CallersFrames

runtime.Framesはスタックフレームの関数、ファイル、実行行数などの情報を保持している構造体になります。

https://github.com/golang/go/blob/release-branch.go1.19/src/runtime/symtab.go#L14-L23

https://pkg.go.dev/runtime#Frames

以上がcaptureStacktraceの実装内容になります。

ここから再びlog.checkメソッドの実装に戻ります。

https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/logger.go#L361-L362

captureStacktraceの呼び出し後はdeferでメソッドFreeを呼び出してstacktraceのリソースをリリースして、poolに戻します。

https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/stacktrace.go#L110-L116

続けてlog.captureメソッドの実装をみていきます。

https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/logger.go#L364-L370

stacktrace.Countメソッドでstacktraceのプログラムカウンタの数をチェックしています。
今回の場合はプログラムカウンタ数は30ではないのここの処理はスキップされます。

https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/stacktrace.go#L118-L122

続くlog.checkの行では次のようにstacktraceのメソッドNextを呼び出しています。

https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/logger.go#L372

これはstack trace中の次のstack frameを返す関数です。次のstack frameがあれば、メソッドNextの第一引数でそのframeを、第二引数moretrueを返します。

https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/stacktrace.go#L124-L128

続いてのlog.checkメソッドの内容を見ていきます。

https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/logger.go#L374-L382

構造体Logger(log)のbool型のフィールドaddCallerの値がtrueの場合にzapcore.CheckedEntry型の変数ceのフィールドCallerzapcore.EntryCallerを代入しています。

コメントにある通りzapcore.EntryCallerはロギング関数のcallerを表す構造体になっています。
ここではstack.Next()で取得したFramePC,File,Line,Functionなどの値をセットしています。

https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/zapcore/entry.go#L71-L78

続けてlog.checkメソッドの内容を確認していきます。

https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/logger.go#L384-L399

今回の場合では変数addStackの値がtrueなのでこの部分の処理は実行されます。
bufferpool.Get()でpoolからbufferを取得して変数bufferに代入しています。

続けてブライベート関数newStackFormatterを呼び出してプライベート構造体のstackFormatterを生成しています。

https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/stacktrace.go#L148-L151

構造体stackFormatterの定義を確認するとstack traceを読みやすいようにフォーマットするための構造体とコメントされています。

▼構造体stackFormatter
https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/stacktrace.go#L142-L146

log.checkメソッドの内容を続けて確認していくと生成したstackFormatterのメソッドFormatFrameを呼び出しています。

https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/stacktrace.go#L164-L176

メソッドFormatFrameruntime.Frame型の引数frameをフォーマットします。
メソッド内部で構造体BufferのメソッドAppendStringやメソッドAppendByteなどを利用してスタックフレームの関数やファイル、実行行などの情報をフォーマットしています。

https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/buffer/buffer.go#L45-L48

https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/buffer/buffer.go#L40-L43

続けてlog.checkメソッドの内容を見ていきます。

https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/logger.go#L393-L395

先ほど見たframe, more := stack.Next()の行の結果moreにはtrueがセットされており、
その結果stackFormatterのメソッドFormatStackを呼び出します。

https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/stacktrace.go#L153-L162

メソッドFormatStackは引数にstacktraceを受け取り、そのstack traceのまだ処理していない残りのスタックフレームをフォーマットします。

実装内容としてはfor分で前述で見てきたメソッドstack.Next()を呼び、値が変える限りその戻り値stack frameのメソッドで先ほどもみたFormatFrameを呼び出してstack frameをフォーマットします。

log.checkメソッドの内容に戻ります。

https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/logger.go#L396-L399

CheckedEntryのフィールドStackbufferのメソッドString()の結果を代入しています。

https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/buffer/buffer.go#L93

最後にメソッドのlog.check戻り値として変数ceを返却しています。

まとめ

この記事でzapLogger.Errorメソッドの内容の前半部分であるメソッドlog.checkの実装について見ていきます。
メソッドlog.checkではログ出力用に利用する構造体zapcore.Entryzapcore.CheckedEntryの生成や初期化、ログレベルに応じたログ処理の前設定、ログでstack traceの出力が有効化されている場合はstack traceのキャプチャなどの処理を行なっていました。

▼メソッドLogger.Error(再掲)
https://github.com/uber-go/zap/blob/v1.24.0/logger.go#L232-L238

▼メソッドlog.check(再掲)
https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/logger.go#L289-L400

後編の記事ではLogger.Errorメソッドのもう一つのメソッドであるce.Write(fields...)の内容を見ていきます。このメソッドは今回生成したCheckedEntryを利用してログ出力する内容のフォーマット処理を行なっています。

Discussion

ログインするとコメントできます