Carpe Diem

備忘録

GoのロギングライブラリzapのTips

概要

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.

ただ1年以上メンテされてなさそうなので自前で対応する場合は以下の対応をする必要があります。

  • ログレベルを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のログレベルは以下のようになっています。

f:id:quoll00:20210922095413p:plain

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 = "timestamp"
        cfg.LevelKey = "severity"
        cfg.MessageKey = "message"
        cfg.EncodeLevel = EncodeLevel
        cfg.EncodeTime = zapcore.RFC3339NanoTimeEncoder

        return cfg
}

timestampは

A timestamp in RFC3339 UTC "Zulu" format, with nanosecond resolution and up to nine fractional digits.

とあるのでzapcore.RFC3339NanoTimeEncoderを使います。

動作確認

以下のようにCloud Loggingのフォーマットで出力されるようになりました。

{"severity":"ERROR","timestamp":"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","timestamp":"2021-09-22T10:34:47.476048+09:00","caller":"zap/main.go:33","message":"info message"}

独自logパッケージでラップしたらcallerがおかしい

こんな感じでzap.Loggerをラップして自前パッケージで扱うと、

f:id:quoll00:20210922110556p:plain

呼び出し元はmain関数の行40, 41なのに、

f:id:quoll00:20210922111209p:plain

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

サンプルコード

今回のコードはこちら

github.com

まとめ

zapを使う上で「こうしたいなぁ」というTipsを紹介しました。