🌿

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

2023/01/05に公開

概要

GoのロギングライブラリのzapのLoggerのメソッドErrorのログ出力の仕組みが気になり、
コードを読んで実装内容を確認していきました。
この記事では個人の備忘録としてその時の内容をまとめていきます。

この下記記事の後編記事になります。
https://zenn.dev/sasakiki/articles/8371acd4cc2991

log.Error

再度zapの構造体LoggerのメソッドErrorの実装内容について確認していきます。

https://github.com/uber-go/zap/blob/v1.24.0/logger.go#L232-L238

上記コードのうち、前編の記事ではメソッドlog.checkの内容を確認していきました。
以降のこの記事ではlog.checkの戻り値であるCheckedEntryのメソッドWriteの実装内容について見ていきたいと思います。

CheckedEntry.Write

CheckedEntry.Writeの実装の全体は次のような内容になっています。
https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/zapcore/entry.go#L232-L267

まず関数の冒頭でレシーバのCheckedEntry型の変数ceがnilかどうかをチェックしています。nilの場合は早期リターンしています。今回の場合は前の記事で見た通りnilではないのでこのif文部分は実行されません。

https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/zapcore/entry.go#L235-L238

続けてみていきます。

https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/zapcore/entry.go#L240-L251

レシーバーCheckedEntryのフィールドdirtyの値がtrueかどうかをチェックしています。このフィールドはpoolがミスユースされているかどうかをベストエフォートで確認するためのフィールドになっています。
今回の場合はfalseなのでこの部分は実行されません。

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

続けて見ていきます。

https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/zapcore/entry.go#L253-L256

レシーバーCheckedEntryのプライベートフィールドでCoreのスライス型であるcoresの要素の数分for ~ rangeでイテレートしています。

Coreは次のようにloggerのインターフェースとして実装されています。

▼インタフェースCore
https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/zapcore/core.go#L23-L45

このインターフェースで定義されているメソッドのうち、ここでは引数にce.EntryfieldsをとりWriteメソッドを呼び出しています。

https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/zapcore/core.go#L37-L42

CoreインターフェースのメソッドWriteの定義部分のコメントを見ると、このメソッドはEntryfieledsをログ出力用にシリアライズするとあります。

今回はloggerの生成に関数NewProductionを利用しています。

https://github.com/uber-go/zap/blob/v1.24.0/logger.go#L94-L100

この関数は内部でConfigBuildメソッドを利用して指定されたOptionとレシーバーのConfigを元にLoggerを生成します。

https://github.com/uber-go/zap/blob/v1.24.0/config.go#L172-L196

このBuildメソッド内部ではLoggerの生成で関数zapcore.NewCoreを呼び出しています。

https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/zapcore/core.go#L57-L64

この関数NewCoreではCoreとしてioCoreを返却しています。
そのため今回のCheckedEntryでもioCoreが利用されています。

そのため次章でioCoreのWriteメソッドの実装を確認していきます。

CheckedEntry.Write中でのメソッドioCore.Writeの呼び出し部分(再掲)
https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/zapcore/entry.go#L254-L256

ioCore.Write

メソッドioCore.Writeの全体の実装は次のようになっています。

https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/zapcore/core.go#L94-L110

まず関数の冒頭でレシーバioCoreのフィールドでEncoder型のencのメソッドEncodeEntryを呼び出しています。

▼構造体ioCore
https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/zapcore/core.go#L66-L70

このフィールドEncoderは次のようにinterface型として定義されています。

▼インターフェースEncoder
https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/zapcore/encoder.go#L432-L451

このインターフェースはlog entryのmarshalersとして定義されています。

▼メソッドEncoder.EncodeEntry
https://github.com/uber-go/zap/blob/ee349f9e2995499f66628dc573382939b6941b09/zapcore/json_encoder.go#L365

今回のケースではこれまで見てきた通りLoggerの生成に関数NewProductionを利用していて、その関数内部ではConfigの生成に関数NewProductionConfigを利用しています。

▼関数NewProductionConfig
https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/config.go#L115-L133

そしてこの関数ではEncodingjsonを指定しています。

▼関数NewProductionConfigEncodingjsonを指定
https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/config.go#L128

そのため今回ioCoreのフィールドEncoderにはjsonEncoderが利用されます。

▼構造体jsonEncoder
https://github.com/uber-go/zap/blob/ee349f9e2995499f66628dc573382939b6941b09/zapcore/json_encoder.go#L58-L67

次節でjsonEncoderのメソッドEncodeEntryの実装内容について見ていきます。

ioCore.Writeメソッド内部でのEncoder.EncodeEntryの呼び出し部分(再掲)
https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/zapcore/core.go#L94-L95

jsonEncoder.EncodeEntry

jsonEncoder.EncodeEntryの実装全体は次のような内容になっています。

https://github.com/uber-go/zap/blob/ee349f9e2995499f66628dc573382939b6941b09/zapcore/json_encoder.go#L365-L435

それでは関数の冒頭から順に見ていきます。

https://github.com/uber-go/zap/blob/ee349f9e2995499f66628dc573382939b6941b09/zapcore/json_encoder.go#L365-L367'

まず最初にjsonEncoderのメソッドcloneを呼び出してその結果を変数finalに代入しています。

https://github.com/uber-go/zap/blob/ee349f9e2995499f66628dc573382939b6941b09/zapcore/json_encoder.go#L356

このメソッドはgetJsonEncoderなどを呼び出してjsonEncoderのクローンを生成しています。

https://github.com/uber-go/zap/blob/ee349f9e2995499f66628dc573382939b6941b09/zapcore/json_encoder.go#L41

▼構造体EncoderConfig

https://github.com/uber-go/zap/blob/ee349f9e2995499f66628dc573382939b6941b09/zapcore/encoder.go#L316

続けて生成した変数finalのフィールドbufに対してメソッドAppendByteを呼び出してjsonログの最初の{をappendしています。

続けて変数finalのフィールドLevelKeyの値が空でないかつfinalのフィールドEncodeLevelnilでない場合にログの出力結果に"level"を含めるようにjsonEncoderのメソッドaddKeyを呼び出してbuf"level"を追加しています。

https://github.com/uber-go/zap/blob/ee349f9e2995499f66628dc573382939b6941b09/zapcore/json_encoder.go#L369-L378

▼メソッドaddKey

https://github.com/uber-go/zap/blob/ee349f9e2995499f66628dc573382939b6941b09/zapcore/json_encoder.go#L448-L457

"level"が追加されたログ

{"level":"error", ...

続いてfinal.TimeKeyの値の有無を見てlogにTimeKeyを出力するかどうかを判断しています。
今回の場合final.TimeKeyの値は"ts"のためfinalのメソッドAddTimeでログにTimeKeyを出力するように設定します。

https://github.com/uber-go/zap/blob/ee349f9e2995499f66628dc573382939b6941b09/zapcore/json_encoder.go#L379-L381

▼メソッドAddTime

https://github.com/uber-go/zap/blob/ee349f9e2995499f66628dc573382939b6941b09/zapcore/json_encoder.go#L204-L207

TimeKeyが追加されたログ

{"level":"error","ts":1672820212.1863208,

続けてメソッドEncodeEntryの内容を見ていきます。
encLoggerNamefinalNameKeyの値が共に空でないかどうかをチェックしています。
今回の場合はenc.LoggerNameが空でないためこの部分はスキップされます。

https://github.com/uber-go/zap/blob/ee349f9e2995499f66628dc573382939b6941b09/zapcore/json_encoder.go#L382-L399


enc.LoggerNameは今回は空

続けてメソッドEncodeEntryの内容を見ていきます

https://github.com/uber-go/zap/blob/ee349f9e2995499f66628dc573382939b6941b09/zapcore/json_encoder.go#L400-L415

xxxで見てきた通りent.Callerは今回の場合はセットされているためent.Caller.Definedtrueになり以降のif分部分が実行されます。


ent.Caller.Definedが今回はtrue

続くif分のif final.CallerKey != ""の判定に関して今回のケースではfinal.CallerKeyの値には"caller"の値がセットされているためこのKeyをログ出力に含めるように前述で見てきたようにメソッドaddKeyでログに追加しています。

CallerKeyが追加されたログ

{"level":"error","ts":1672820212.1863208,"caller":"my-logger/main.go:71", ...

続く行のif final.FunctionKey != ""は今回の場合は空なのでスキップされログには追加されません。

続けてメソッドEncodeEntryの内容を見ていきます

https://github.com/uber-go/zap/blob/ee349f9e2995499f66628dc573382939b6941b09/zapcore/json_encoder.go#L416-L419

final.MessageKeyの値はlogger.Errorメソッドの引数で設定しており今回の場合は空でないのでif分部分が実行され、ログにMessageKeyの内容が出力されます。

MessageKeyが追加されたログ

{"level":"error","ts":1672820212.1863208,"caller":"my-logger/main.go:71","msg":"my test msg",

続けてメソッドEncodeEntryの内容を見ていきます

enc.buf.Len()の長さが0より大きいかをチェックしています。今回の場合は0のためこのif分のブロックはスキップされます。

https://github.com/uber-go/zap/blob/ee349f9e2995499f66628dc573382939b6941b09/zapcore/json_encoder.go#L420-L423

続く行でプライベート関数addFieldsを呼んでいます。

https://github.com/uber-go/zap/blob/ee349f9e2995499f66628dc573382939b6941b09/zapcore/json_encoder.go#L424

▼関数AddFields
https://github.com/uber-go/zap/blob/ee349f9e2995499f66628dc573382939b6941b09/zapcore/field.go#L208-L212

今回の場合では引数fieldsKey"error"Fieldをもつ要素数1のFieldのスライスになります。

関数AddFieldsは引数fieldsの要素数分イテレートしてその要素FieldのメソッドAddToを呼び出しています。

Field.AddTo
https://github.com/uber-go/zap/blob/ee349f9e2995499f66628dc573382939b6941b09/zapcore/field.go#L114

AddToメソッドではレシーバのFieldTypeに応じてFieldのKeyとその値をログに追加する処理を出し分けています。

先ほど見たように今回の場合はErrorTypeのため下記部分のプライベート関数encodeErrorが呼び出されます。

Field.TypeErrorTypeの場合
https://github.com/uber-go/zap/blob/ee349f9e2995499f66628dc573382939b6941b09/zapcore/field.go#L176

関数encodeError

▼関数encodeError
https://github.com/uber-go/zap/blob/ee349f9e2995499f66628dc573382939b6941b09/zapcore/error.go#L29-L78

関数encodeErrorのシグネチャは引数にstring型のkeyerr、そしてObjectEncoder型のencを取り、戻り値としてerror型のretErrを返します。

関数冒頭のコメントに例が記載されてあるように、関数encodeErrorは引数errをログ出力用のObjectEncoderのフィールドにエンコードします。
後続で見ますがログ出力用のkeyは"error"になります。
さらに加えて、err型に応じてログ出力に追加でフィールドを追加します。このコメントにあるようにerrfmt.Formatterを実装していれば${key}Verboseを、errorGroup型であればerrorCausesをログに追加します。

zapcore/error.go#L29
// Encodes the given error into fields of an object. A field with the given
// name is added for the error message.
//
// If the error implements fmt.Formatter, a field with the name ${key}Verbose
// is also added with the full verbose error message.
//
// Finally, if the error implements errorGroup (from go.uber.org/multierr) or
// causer (from github.com/pkg/errors), a ${key}Causes field is added with an
// array of objects containing the errors this error was comprised of.
//
//	{
//	  "error": err.Error(),
//	  "errorVerbose": fmt.Sprintf("%+v", err),
//	  "errorCauses": [
//	    ...
//	  ],
//	}
func encodeError(key string, err error, enc ObjectEncoder) (retErr error) {

それでは順番に処理内容を具体的に見ていきます。

https://github.com/uber-go/zap/blob/ee349f9e2995499f66628dc573382939b6941b09/zapcore/error.go#L63-L64

まず最初に変数basicerr.Error()エラーメッセージを代入します。
続く行でenc.AddString(key, basic)keyに(今回の場合は"error")basic,つまりエラーメッセージをログ出力用に設定しています。

"error"が追加されたログ

{"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",

続いて引数errの型に応じて処理を条件分岐しています。

https://github.com/uber-go/zap/blob/ee349f9e2995499f66628dc573382939b6941b09/zapcore/error.go#L66-L78

今回のerrlogger.Errorの呼び出し側ではcustom errorとしてMyError型として実装しており、Goの標準のfmtパッケージのFormatterインターフェースを満たすようにFormatメソッドを実装していました。

https://pkg.go.dev/fmt#Formatter

main.go
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)
}

(参考:全体のコードは下記の前編の記事に記載しています)
https://zenn.dev/sasakiki/articles/8371acd4cc2991#全体のコード

FormatメソッドはgoのfmtパッケージのPrintfなどI/O系の関数で独自にフォーマット出力したい場合にこのインターフェースを満たすようにFormatメソッドを実装するとその内容でフォーマットするようにこのFormatメソッドを呼び出してくれます。
今回は詳細は長くなってしまうため別の記事でまとめていきたいと思います。

下記記事部分とも関連しています。
https://zenn.dev/sasakiki/articles/1080465e9e88a6#formatterインターフェース

そのため、今回はfmt.Formatter:の場合が実行されます。

	case fmt.Formatter:
		verbose := fmt.Sprintf("%+v", e)
		if verbose != basic {
			// This is a rich error type, like those produced by
			// github.com/pkg/errors.
			enc.AddString(key+"Verbose", verbose)
		}
	}
	return nil

ここで行なっているのはkey"errorVerbose"にエラーのstack trace用を出力しています。

"errorVerbose"が追加されたログ

{"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"

最後にこの関数内でエラーが発生した場合に備えてdeferでエラーのrecover処理を定義しています。

https://github.com/uber-go/zap/blob/ee349f9e2995499f66628dc573382939b6941b09/zapcore/error.go#L49-L61

以上で関数encodeErrorの内容は終わりです。
それではjsonEncoder.EncodeEntryの内容に戻ります。

関数addFieldsに続く行でfinal.closeOpenNamespacesを呼び出しています。

https://github.com/uber-go/zap/blob/ee349f9e2995499f66628dc573382939b6941b09/zapcore/json_encoder.go#L425

enc.openNamespacesの数だけfor文でイテレートしてログに"}"を追加する処理です。

https://github.com/uber-go/zap/blob/ee349f9e2995499f66628dc573382939b6941b09/zapcore/json_encoder.go#L441-L446

今回の場合はenc.openNamespaces0なのでこの関数では処理はスキップされます。

jsonEncoder.EncodeEntryの内容に戻ります。

https://github.com/uber-go/zap/blob/ee349f9e2995499f66628dc573382939b6941b09/zapcore/json_encoder.go#L426-L428

ent.Stackfinal.StacktraceKeyの値が共にセットされている場合にログにKeyをfinal.StacktraceKeyに値ent.Stackをログに追加します。

今回の場合はこれまで見てきたように共に値がセットされているためログに追加されます(今回はfinal.StacktraceKey"stacktrace"になります)

"stacktrace"が追加されたログ

{"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"

続く行ではログ出力するの全てフィールドのkeyの設定が完了したのでログの内容に"}"final.LineEndingを追加しています。

https://github.com/uber-go/zap/blob/ee349f9e2995499f66628dc573382939b6941b09/zapcore/json_encoder.go#L429-L430

そして最後に戻り値用の変数retfinal.bufの値を代入し、
putJSONEncoder(final)を呼び出した後、retを戻り値として返しています。

https://github.com/uber-go/zap/blob/ee349f9e2995499f66628dc573382939b6941b09/zapcore/json_encoder.go#L432-L435

関数PutJSONEncoderではjsonEncoderのリソースクリーンアップ処理を行なっています。

▼関数PutJSONEncoder
https://github.com/uber-go/zap/blob/ee349f9e2995499f66628dc573382939b6941b09/zapcore/json_encoder.go#L45-L56

jsonEncoder.EncodeEntryの実装は以上になります。

では再びjsonEncoder.EncodeEntryの呼び出しもとであるメソッドioCore.Writeの実装に戻ります。

zapcore/core.go#L94
func (c *ioCore) Write(ent Entry, fields []Field) error {
	buf, err := c.enc.EncodeEntry(ent, fields)
	if err != nil {
		return err
	}
	_, err = c.out.Write(buf.Bytes())
	buf.Free()
	if err != nil {
		return err
	}
	if ent.Level > ErrorLevel {
		// Since we may be crashing the program, sync the output. Ignore Sync
		// errors, pending a clean solution to issue #370.
		c.Sync()
	}
	return nil
}

ログ出力の値でありjsonEncoder.EncodeEntryの戻り値を変数bufに代入し、
その結果をc.out.Write(buf.Bytes())で書き込んでいます。
その後、buf.Free()でクリーンアップ処理をして、ent.LevelErrorLevelより大きい場合にc.Sync()を呼び出しています。今回はent.LevelErrorLevelのためこの部分は実行されません。

ioCore.Writeの実装も以上になります。
そしてioCore.Writeの呼び出しもとであるCheckedEntry.Writeの実装内容に戻ります。

https://github.com/uber-go/zap/blob/a55bdc32f526699c3b4cc51a2cc97e944d02fbbf/zapcore/entry.go#L253-L267

残りはエラーハンドリングやpoolにcheckedEntryを戻したりなどのクリーンアップ処理を行なっています。

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

CheckedEntry.Write実装の内容も以上です。
最後にCheckedEntry.Writeの呼び出しもとであるlog.Errorメソッドの内容を再掲します。

https://github.com/uber-go/zap/blob/v1.24.0/logger.go#L232-L238

まとめ

この記事ではロギングライブラリのzapのLoggerのメソッドErrorの実装の後半部分である
CheckedEntry.Writeの実装内容についてみていきました。

このメソッドは実際にログで出力する各フィールドのフォーマットを行なっていることがわかりました。
そしてフォーマットした内容をio.Writeメソッドで出力していました。

共通部分はinterfaceとして実装してLoggerやEncoderの種類に応じて各interfaceを実装したレシーバーである構造値がそれぞれのメソッドを具体的に実装して処理を出し分けていることも分かりました。

また、エラー発生までのstack traceの出力ではfmtパッケージのFormatterインタフェースの実装を満たしているかをチェックしてFormatメソッドで実際にstack traceの内容をフォーマットしていることも分かりました。

前編の記事と共に今回学んだことを自分でログのフォーマットを変えたいなどのケースに活かしていけたらと思いました。

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

Discussion

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