zapのLoggerのメソッドError()のログ出力の仕組み①
概要
Goのロギングライブラリとしてzapを使うケースがよくあると思います。
今回はzapの二種類のLoggerのうち高パフォーマンスで構造化ログのみに対応しているLoggerに焦点を当てて、zapのLoggerのメソッドの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),
)
}
}
上記コードを実行すると次のような結果が出力されます。
(ログのキーのうちerrorVerboseやstacktraceの値で実行環境のパスの部分はxxxやyyyなどとしています)
{"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
Errorメソッドの実装を確認すると、メソッド内部でloggerのプライベートメソッドcheck()を呼び出しています。その後その戻りceがnilでない場合にce.Write(fields...)を呼び出しています。
以降ではこの記事ではメソッドlog.checkの実装内容について見ていきます。
後編の記事でce.Write(fields...)の実装を見ていきます。
log.check
checkメソッドのシグネチャを確認すると、引数にzapcore.Levelとmsg(string)を受け取り、
戻り値としてzapcore.CheckedEntryのポインタを返しています。
▼zapcore.CheckedEntry
コメントを確認するとCheckedEntryはログのアウトプットに許可したEntryのコレクションであることがわかります。
詳細は実装の確認時に随時見ていきます。
それではcheckメソッドの実装について見ていきます。
まず最初にint型の定数callerSkipOffsetを宣言して値として2を代入しています。
コメントにある通り、これはlogger.checkとこのメソッドの呼び出しもとであるlogger.Errorのcallerをスキップするために2を指定しています。
後にStackTraceのcapture部分で参照されます。
続いて無効化されているログ呼び出しによるコストを減らすためにこちらで確認しています。
今回の場合!log.core.Enabled(lvl)がtrueのためこの部分は実行されません。
続いてlog.checkの引数のmsg,ログレベルのlvl、log.name、そして現在時刻をフィールドにセットしてzapcore.Entryを生成しています。
zapcore.Entryの定義を見るとEntryはcomple log messageを表しているとのことです。
ここでセットされているフィールドの他にzapcore.EntryCaller型のCallerやstring型のStackなどがあります。
続けてlog.coreのCheckメソッドを呼び出しています。
メソッドCheckは次のようにCoreインターフェースで定義されています。
コメントを確認するとこのCheckメソッドは指定されたEntryがログ出力されるべきかどうかを判定するメソッドです。もしここでログ出力対象として判定されると、EntryはCheckedEntryにappendされてその結果がCheckの戻り値として返却されます。
今回はcoreにはSamplerがセットされているのでSamplerのCheckメソッドが呼び出されます。
この結果、ceにはCheckedEntryが入ります。
続けてlog.Checkの処理に戻ってwillWriteにはtrueがそれぞれ代入されます。
▼zapcore.Entry
zapcore.EntryCallerの定義を確認するとロギング関数のcallerを表す構造体になっています。
フィールドはスタックトレース用にプログラムカウンタのPC、FileやLile、Functionなどが定義されています。
続けてcheckメソッドのコードを見ていきます。EntryのLevelに応じて振る舞いをセットアップしています。今回はErrorLevelのためここでのswitchブロックには当てはまらずにスキップされます。
log.checkの内容を続けて見ていきます。
willWriteの値は今回の場合はtrueが入るのでここの処理はスキップされて処理は継続します。
続けてlog.checkを見ていきます。
CheckedEntryのフィールドのErrorOutput設定と変数addStackの定義を行なっています。
変数addStackにはlog.addStack.Enabled(ce.Level)の結果trueが代入されます。
続けてlog.checkの内容を見ていきます。
変数stackDepthの定義を行なっています。先ほど見た通りaddStackにはtrueがセットされているためstackDepthにはstacktraceFullが代入されます。
続けてプライベート関数のcaptureStacktraceを呼び出して結果を変数stackに代入しています。
captureStacktrace
captureStacktraceのシグネチャを確認すると、引数にint型のskipとstacktraceDepth型(intのtype alias)のdepthを受け取って、プライベートの構造体stacktraceが戻り値となっています。
▼stacktraceDepth型
▼構造体stacktrace
コメントを確認するとcaptureStacktrace指定されたdepthのスタックトレースをキャプチャする関数とのことです。引数skipで指定された分スタックフレームをスキップします。
それでは順に実装をみていきます。
まず関数の冒頭で_stacktracePoolからメソッドGet()でpoolからstacktraceを取得するようにしています。
続けて引数depthに応じてstack.pcsに値をセットしています。
前述で見てきたようにcaptureStacktraceの呼び出し側でdepthにはstacktraceFullが渡されているのでstack.pcsにstack.storageが代入されます。
Go標準のruntimeパッケージの関数Callersを呼び出しています。
コメントにある通り引数skipにskip+2を指定してruntime.CallersとcaptureStacktrace自身の呼び出しのスタックフレームをスキップするように指定しています。
runtime.Callersの実装の詳細についてはここでは長くなるので割愛して別記事で見ていきたいと思います。
そしてdepthの値に応じて処理を分岐しています。
今回の場合のようにstacktraceFullの場合、
stack.storageにpcsを、stack.pcsに実際のスタックフレーム数のstack.pcs[:numFrames]を代入しています。
続けでcaptureStacktraceの実装を見ていきます。
関数の最後にstack.framesにruntimeパッケージの関数CallersFramesの呼び出した結果を代入して、最後に stackをreturnしています。
関数runtime.CallersFramesは[]uintptr型の引数callersを受け取ってruntime.Framesを返却します。
runtime.Framesはスタックフレームの関数、ファイル、実行行数などの情報を保持している構造体になります。
以上がcaptureStacktraceの実装内容になります。
ここから再びlog.checkメソッドの実装に戻ります。
captureStacktraceの呼び出し後はdeferでメソッドFreeを呼び出してstacktraceのリソースをリリースして、poolに戻します。
続けてlog.captureメソッドの実装をみていきます。
stacktrace.Countメソッドでstacktraceのプログラムカウンタの数をチェックしています。
今回の場合はプログラムカウンタ数は3で0ではないのここの処理はスキップされます。
続くlog.checkの行では次のようにstacktraceのメソッドNextを呼び出しています。
これはstack trace中の次のstack frameを返す関数です。次のstack frameがあれば、メソッドNextの第一引数でそのframeを、第二引数moreはtrueを返します。
続いてのlog.checkメソッドの内容を見ていきます。
構造体Logger(log)のbool型のフィールドaddCallerの値がtrueの場合にzapcore.CheckedEntry型の変数ceのフィールドCallerにzapcore.EntryCallerを代入しています。
コメントにある通りzapcore.EntryCallerはロギング関数のcallerを表す構造体になっています。
ここではstack.Next()で取得したFrameのPC,File,Line,Functionなどの値をセットしています。
続けてlog.checkメソッドの内容を確認していきます。
今回の場合では変数addStackの値がtrueなのでこの部分の処理は実行されます。
bufferpool.Get()でpoolからbufferを取得して変数bufferに代入しています。
続けてブライベート関数newStackFormatterを呼び出してプライベート構造体のstackFormatterを生成しています。
構造体stackFormatterの定義を確認するとstack traceを読みやすいようにフォーマットするための構造体とコメントされています。
▼構造体stackFormatter
log.checkメソッドの内容を続けて確認していくと生成したstackFormatterのメソッドFormatFrameを呼び出しています。
メソッドFormatFrameはruntime.Frame型の引数frameをフォーマットします。
メソッド内部で構造体BufferのメソッドAppendStringやメソッドAppendByteなどを利用してスタックフレームの関数やファイル、実行行などの情報をフォーマットしています。
続けてlog.checkメソッドの内容を見ていきます。
先ほど見たframe, more := stack.Next()の行の結果moreにはtrueがセットされており、
その結果stackFormatterのメソッドFormatStackを呼び出します。
メソッドFormatStackは引数にstacktraceを受け取り、そのstack traceのまだ処理していない残りのスタックフレームをフォーマットします。
実装内容としてはfor分で前述で見てきたメソッドstack.Next()を呼び、値が変える限りその戻り値stack frameのメソッドで先ほどもみたFormatFrameを呼び出してstack frameをフォーマットします。
log.checkメソッドの内容に戻ります。
CheckedEntryのフィールドStackにbufferのメソッドString()の結果を代入しています。
最後にメソッドのlog.check戻り値として変数ceを返却しています。
まとめ
この記事でzapのLogger.Errorメソッドの内容の前半部分であるメソッドlog.checkの実装について見ていきます。
メソッドlog.checkではログ出力用に利用する構造体zapcore.Entryやzapcore.CheckedEntryの生成や初期化、ログレベルに応じたログ処理の前設定、ログでstack traceの出力が有効化されている場合はstack traceのキャプチャなどの処理を行なっていました。
▼メソッドLogger.Error(再掲)
▼メソッドlog.check(再掲)
後編の記事ではLogger.Errorメソッドのもう一つのメソッドであるce.Write(fields...)の内容を見ていきます。このメソッドは今回生成したCheckedEntryを利用してログ出力する内容のフォーマット処理を行なっています。
Discussion