概要
zapを使っていて
- 書き込み先をio.Writerで自由に設定したい
- テストで時刻を固定値にしたい
- ログレベルによって標準出力、標準エラー出力を分けたい
- GCP Cloud Loggingのフォーマットでログ出力したい
- 全ログに付けたいフィールドがある
- 独自logパッケージでラップしたらcallerがおかしい
とちょっとカスタマイズしたいケースのTipsです。
環境
- Go 1.17
- go.uber.org/zap v1.19.1
Tips
書き込み先をio.Writerで自由に設定したい
zapのデフォルトの出力先は標準エラー出力ですが、期待通りのフォーマットでログが出力されているか確認したい時にio.Writerを渡してそこに書き込んでほしい場合です。
そんなときはzapcore.AddSyncを使います。
func NewWithWriter(w io.Writer) *zap.Logger { sink := zapcore.AddSync(w) lsink := zapcore.Lock(sink) enc := zapcore.NewJSONEncoder(zap.NewProductionEncoderConfig()) core := zapcore.NewCore(enc, lsink, zapcore.InfoLevel) logger := zap.New(core) return logger }
またzapcore.Lockを使うことでConcurrent Safeにできます。
動作確認
io.Writerを渡すと
var buf bytes.Buffer logger := NewWithWriter(&buf) logger.Error("error message") logger.Info("info message") // 標準出力へ fmt.Println(buf.String())
以下のような結果になります。
{"level":"error","ts":1632263325.339954,"msg":"error message"} {"level":"info","ts":1632263325.339966,"msg":"info message"}
テストで時刻を固定値にしたい
ログ自体のテストをする際に、時刻の部分が変動するためテストがしづらいです。
これはzapcore.WithClockで解決できます。
type constantClock time.Time func (c constantClock) Now() time.Time { return time.Time(c) } func (c constantClock) NewTicker(duration time.Duration) *time.Ticker { return &time.Ticker{} }
このようにzapcore.Clockを実装しておき、テストコードのloggerのオプションにセットします。
func ExampleNewMultiOutputLogger() { date := time.Date(2021, 1, 23, 10, 15, 13, 0, time.UTC) clock := constantClock(date) logger := NewMultiOutputLogger() logger = logger.WithOptions(zap.WithClock(clock)) logger.Info("info message") // Output: // 2021-01-23T10:15:13.000Z INFO info message }
これでExampleテストのようなケースでも問題なく通るようになりました。
ログレベルによって標準出力、標準エラー出力を分けたい
ログレベルがInfo以下のログなら標準出力に、Error以上のなら標準エラー出力にしたい場合です。
zapcore.NewTeeを使って複数の出力先を持てるようにします。
func NewMultiOutputLogger() *zap.Logger { highPriority := zap.LevelEnablerFunc(func(lvl zapcore.Level) bool { return lvl >= zapcore.ErrorLevel }) lowPriority := zap.LevelEnablerFunc(func(lvl zapcore.Level) bool { return lvl < zapcore.ErrorLevel }) stdoutSink := zapcore.Lock(os.Stdout) stderrSink := zapcore.Lock(os.Stderr) enc := zapcore.NewConsoleEncoder(zap.NewDevelopmentEncoderConfig()) core := zapcore.NewTee( zapcore.NewCore(enc, stderrSink, highPriority), zapcore.NewCore(enc, stdoutSink, lowPriority), ) logger := zap.New(core) return logger }
動作確認
標準出力をstdoutというファイルに、標準エラー出力をstderrというファイルに出力した結果です。
$ go run . > stdout 2> stderr $ cat stdout 2021-09-22T07:15:32.666+0900 INFO info message $ cat stderr 2021-09-22T07:15:32.666+0900 ERROR error message
GCP Cloud Loggingのフォーマットでログ出力したい
GCP Cloud Loggingのフォーマットに合わせると、Cloud Loggingのフィルタ機能が使えてログの可読性が大きく向上します。
この対応をするのに一番手っ取り早いのは以下のライブラリを使うことです。
GitHub - blendle/zapdriver: Blazing fast, Zap-based Stackdriver logging.
ただ１年以上メンテされてなさそうなので自前で対応する場合は以下の対応をする必要があります。
- ログレベルをCloud Loggingのものに合わせる
- Encoderのキー名をLogEntryのものに合わせる
ログレベルをCloud Loggingのものに合わせる
zapのログレベルは以下です。
const ( // DebugLevel logs are typically voluminous, and are usually disabled in // production. DebugLevel Level = iota - 1 // InfoLevel is the default logging priority. InfoLevel // WarnLevel logs are more important than Info, but don't need individual // human review. WarnLevel // ErrorLevel logs are high-priority. If an application is running smoothly, // it shouldn't generate any error-level logs. ErrorLevel // DPanicLevel logs are particularly important errors. In development the // logger panics after writing the message. DPanicLevel // PanicLevel logs a message, then panics. PanicLevel // FatalLevel logs a message, then calls os.Exit(1). FatalLevel )
ref: zap/level.go at eaeb0fc72fd23af7969c9a9f39e51b66827507ca · uber-go/zap · GitHub
一方でCloud Loggingのログレベルは以下のようになっています。
ref: LogEntry | Cloud Logging | Google Cloud
なのでログレベルをあわせる必要があります。
var logLevelSeverity = map[zapcore.Level]string{ zapcore.DebugLevel: "DEBUG", zapcore.InfoLevel: "INFO", zapcore.WarnLevel: "WARNING", zapcore.ErrorLevel: "ERROR", zapcore.DPanicLevel: "CRITICAL", zapcore.PanicLevel: "ALERT", zapcore.FatalLevel: "EMERGENCY", } func EncodeLevel(l zapcore.Level, enc zapcore.PrimitiveArrayEncoder) { enc.AppendString(logLevelSeverity[l]) }
Encoderのキー名をLogEntryのものに合わせる
Cloud Loggingでは一部zapのキー名と異なるので合わせます。
LogEntry | Cloud Logging | Google Cloud
func newEncoderConfig() zapcore.EncoderConfig { cfg := zap.NewProductionEncoderConfig() cfg.TimeKey = "time" cfg.LevelKey = "severity" cfg.MessageKey = "message" cfg.EncodeLevel = EncodeLevel cfg.EncodeTime = zapcore.RFC3339NanoTimeEncoder return cfg }
timeKey
timeKeyはCloud Loggingへ転送するfluentdやfluentbitがtimeをキーとして使っているのでそれに合わせます。
fluentd
fluentbit
[PARSER]
Name docker
Format json
Time_Key time
Time_Format %Y-%m-%dT%H:%M:%S.%L%z
[PARSER]
Name containerd
Format regex
Regex ^(?<time>.+) (?<stream>stdout|stderr) [^ ]* (?<log>.*)$
Time_Key time
Time_Format %Y-%m-%dT%H:%M:%S.%L%z
またフォーマットとしては
A timestamp in RFC3339 UTC "Zulu" format, with nanosecond resolution and up to nine fractional digits.
とあるのでzapcore.RFC3339NanoTimeEncoderを使います。
動作確認
以下のようにCloud Loggingのフォーマットで出力されるようになりました。
{"severity":"ERROR","time":"2021-09-22T10:34:47.476008+09:00","caller":"zap/main.go:32","message":"error message","stacktrace":"main.main\n\t/Users/jun06t/.go/src/github.com/jun06t/go-sample/zap/main.go:32\nruntime.main\n\t/usr/local/opt/go/libexec/src/runtime/proc.go:255"} {"severity":"INFO","time":"2021-09-22T10:34:47.476048+09:00","caller":"zap/main.go:33","message":"info message"}
全ログに付けたいフィールドがある
例えばログにアプリケーションのバージョンを付けたいケースです。
スタックトレース情報はあったとしても、古いログの場合すでにファイルが書き換えられていてたどり着けない可能性があります。
アプリバージョンをログに持たせることで、GitHubでそのバージョンに戻せばスタックトレースの通りに調べることができます。
対応
Config.InitialFieldsを設定します。
cfg := zap.NewProductionConfig() cfg.InitialFields = map[string]interface{}{"appVersion": "v1.0.0"} cfg.EncoderConfig = newEncoderConfig() logger, _ := cfg.Build()
これを設定すると、どのログに対してもそのフィールドを付けてくれます。
動作確認
エラーログもInfoログにも"appVersion":"v1.0.0"が付いています。
{"severity":"ERROR","timestamp":"2022-01-21T04:58:15.24207+09:00","caller":"zap/main.go:34","message":"error message","appVersion":"v1.0.0","stacktrace":"main.main\n\t/Users/a13156/.go/src/github.com/jun06t/go-sample/zap/main.go:34\nruntime.main\n\t/usr/local/opt/go/libexec/src/runtime/proc.go:255"}
{"severity":"INFO","timestamp":"2022-01-21T04:58:15.242101+09:00","caller":"zap/main.go:35","message":"info message","appVersion":"v1.0.0"}
独自logパッケージでラップしたらcallerがおかしい
こんな感じでzap.Loggerをラップして自前パッケージで扱うと、
呼び出し元はmain関数の行40, 41なのに、
callerの行数が以下のように呼び出し元でなく自前パッケージの定義箇所log/log.go:xxになってしまう問題です。
2021-09-22T11:05:16.137+0900 INFO log/log.go:16 info message 2021-09-22T11:05:16.137+0900 ERROR log/log.go:20 error message
対応
zap.AddCallerSkipを使います。
var logger *zap.Logger func init() { l, err := zap.NewDevelopment(zap.AddCallerSkip(1)) if err != nil { panic(err) } logger = l }
きちんと呼び出し元zap/main.go:40,41で表示されるようになりました。
2021-09-22T11:07:31.131+0900 INFO zap/main.go:40 info message 2021-09-22T11:07:31.131+0900 ERROR zap/main.go:41 error message
サンプルコード
今回のコードはこちら
まとめ
zapを使う上で「こうしたいなぁ」というTipsを紹介しました。
