🌿

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

2023/01/05に公開

tech

概要

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

この下記記事の後編記事になります。

log.Error

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

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

CheckedEntry.Write

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

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

続けてみていきます。

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

続けて見ていきます。

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

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

▼インタフェースCore

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

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

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

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

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

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

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

▼CheckedEntry.Write中でのメソッドioCore.Writeの呼び出し部分(再掲)

ioCore.Write

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

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

▼構造体ioCore

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

▼インターフェースEncoder

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

▼メソッドEncoder.EncodeEntry

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

▼関数NewProductionConfig

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

▼関数NewProductionConfigでEncodingにjsonを指定

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

▼構造体jsonEncoder

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

▼ioCore.Writeメソッド内部でのEncoder.EncodeEntryの呼び出し部分(再掲)

jsonEncoder.EncodeEntry

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

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

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

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

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

▼構造体EncoderConfig

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

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

▼メソッドaddKey

▼"level"が追加されたログ

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

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

▼メソッドAddTime

▼TimeKeyが追加されたログ

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

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

enc.LoggerNameは今回は空

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

xxxで見てきた通りent.Callerは今回の場合はセットされているためent.Caller.Definedがtrueになり以降の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の内容を見ていきます

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分のブロックはスキップされます。

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

▼関数AddFields

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

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

▼Field.AddTo

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

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

▼Field.TypeがErrorTypeの場合

関数encodeError

▼関数encodeError

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

関数冒頭のコメントに例が記載されてあるように、関数encodeErrorは引数errをログ出力用のObjectEncoderのフィールドにエンコードします。
後続で見ますがログ出力用のkeyは"error"になります。
さらに加えて、err型に応じてログ出力に追加でフィールドを追加します。このコメントにあるようにerrがfmt.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) {

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

まず最初に変数basicにerr.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の型に応じて処理を条件分岐しています。

今回のerrはlogger.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)
}

(参考:全体のコードは下記の前編の記事に記載しています)

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

下記記事部分とも関連しています。

そのため、今回は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処理を定義しています。

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

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

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

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

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

ent.Stackとfinal.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を追加しています。

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

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

▼関数PutJSONEncoder

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.LevelがErrorLevelより大きい場合にc.Sync()を呼び出しています。今回はent.LevelはErrorLevelのためこの部分は実行されません。

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

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

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

まとめ

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

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

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

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

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

▼メソッドlog.Error(再掲)

概要

log.Error

CheckedEntry.Write

ioCore.Write

jsonEncoder.EncodeEntry

関数encodeError

まとめ

Discussion