Golangで自作Logger中でzapライブラリを使う際、CallerにLoggerより上の階層を出す方法

この記事を参考に、zapというログライブラリを使ってみました。
その時にログ出力されるCallerの情報についてハマったことをメモとして残します。

2021/1/6追記
conf.Build(zap.AddCallerSkip(x)) のように指定することで変更できることを知りました。

おさらい

• よく見かけるmainに記載するコーディング例で実行した場合を記載します。
• 出力例からわかる通りmain/main.go:30 という内容が出力されます。
• これはzapのログを出力したファイルのディレクトリ、ファイル、行が出力されており、トレースしやすい内容となっています。

package main

import (
	"go.uber.org/zap"
	"go.uber.org/zap/zapcore"
	"time"
)

func main() {
	conf := zap.Config{
		Level:            zap.NewAtomicLevelAt(zap.DebugLevel),
		Development:      true,
		Encoding:         "console",
		OutputPaths:      []string{"stdout"},
		ErrorOutputPaths: []string{"stdout"},
		EncoderConfig: zapcore.EncoderConfig{
			LevelKey:     "level",
			TimeKey:      "time",
			MessageKey:   "msg",
			CallerKey:    "caller",
			EncodeTime:   zapcore.ISO8601TimeEncoder,
			EncodeLevel:  zapcore.LowercaseLevelEncoder,
			EncodeCaller: zapcore.ShortCallerEncoder,
		},
	}
	l, err := conf.Build()
	if err != nil {
		panic(err)
	}
	l.Info("Zap Start.", zap.Time("time", time.Now()))
}

// Output:
// 2021-01-04T23:46:14.963+0900    info    main/main.go:30 Zap Start.      {"time": "2021-01-04T23:46:14.963+0900"}

// フォルダ構成はこんな感じ。
// main
// ├── go.mod
// ├── go.sum
// └── main.go

困ったこと

• Webアプリで作るために、一度生成したzapインスタンスを使い回したいと思い、loggerパッケージを自作しました。
• これで問題なし！と思いきや、logがlogger/logger.go:41になっちゃった。
• 確かにzapのメソッドを呼び出しているのはlogger/logger.goだけど、それよりもひとつ上のCallerを知りたいのよ。
• ソースを読む限り、zapのConfigではひとつ上のCallerを指定することはできないみたい。
• runtimeパッケージで別で出力するしかないのか。。。

2021/1/6追記
conf.Build(zap.AddCallerSkip(x)) のように指定することで変更できることを知りました。

// フォルダ構成はこんな感じ(Goのスタンダードから外れるけど今回は説明のため簡略化)。
// main
// ├── go.mod
// ├── go.sum
// ├── main.go
// └── logger
//     └── logger.go

logger.go

package logger

import (
	"go.uber.org/zap"
	"go.uber.org/zap/zapcore"
)


var (
	l *zap.Logger
)

func SetUp() error {

	conf := zap.Config{
		Level:            zap.NewAtomicLevelAt(zap.DebugLevel),
		Development:      true,
		Encoding:         "console",
		OutputPaths:      []string{"stdout"},
		ErrorOutputPaths: []string{"stdout"},
		EncoderConfig: zapcore.EncoderConfig{
			LevelKey:     "level",
			TimeKey:      "time",
			MessageKey:   "msg",
			CallerKey:    "caller",
			EncodeTime:   zapcore.ISO8601TimeEncoder,
			EncodeLevel:  zapcore.LowercaseLevelEncoder,
			EncodeCaller: zapcore.ShortCallerEncoder,
		},
	}
	var err error
	l, err = conf.Build()
	if err != nil {
		return err
	}

	return nil
}

func Info(msg string, fields ...zap.Field){
	l.Info(msg,fields...)
}

main.go

package main

import (
	"go.uber.org/zap"
	"main/logger"
	"time"
)

func main() {
	err := logger.SetUp()
	if err != nil {
		panic(err)
	}
	logger.Info("Zap Start.", zap.Time("time", time.Now()))
}
// Output:
// 2021-01-05T00:12:44.683+0900    info    logger/logger.go:41     Zap Start.      {"time": "2021-01-05T00:12:44.683+0900"}
//                                          ↑ここをlogger/logger.goじゃなく、main/main.goにしたい。

解決策

• ラップするのではなく、zapの関数をそのままloggerのPublicな変数にぶちこむ！

logger.go

package logger

import (
	"go.uber.org/zap"
	"go.uber.org/zap/zapcore"
)

var (
	l    *zap.Logger
	Info func(msg string, fields ...zap.Field) //ここが変更点1
)

func SetUp() error {

	conf := zap.Config{
		Level:            zap.NewAtomicLevelAt(zap.DebugLevel),
		Development:      true,
		Encoding:         "console",
		OutputPaths:      []string{"stdout"},
		ErrorOutputPaths: []string{"stdout"},
		EncoderConfig: zapcore.EncoderConfig{
			LevelKey:     "level",
			TimeKey:      "time",
			MessageKey:   "msg",
			CallerKey:    "caller",
			EncodeTime:   zapcore.ISO8601TimeEncoder,
			EncodeLevel:  zapcore.LowercaseLevelEncoder,
			EncodeCaller: zapcore.ShortCallerEncoder,
		},
	}
	var err error
	l, err = conf.Build()
	if err != nil {
		return err
	}

	Info = l.Info //ここが変更点2
	return nil
}

main.goはさっきと一緒なので省略。
無事、main/main.goが取れました。
↓出力結果

2021-01-05T00:19:47.157+0900    info    main/main.go:14 Zap Start.      {"time": "2021-01-05T00:19:47.157+0900"}

最終的なLoggerの形

以下の方針のもと、最終的に以下の形にしました。

• 開発生産性を考慮し、基本的に zap.SugaredLogger でLoggingする方針にしました（zap.field書くのはめんどくさい）。
• なんども出力して速度がどうしても気になる時にだけ、zap.Loggerを使う。
• zap.Logger は以下の理由からInfoとWarnのみ。
  • エラー出力が出る時なんて速度より別問題。
  • Debugは本番で出力しない＝速度気にしなくていい。

これで進めようと思うlogger.go

package logger

import (
	"go.uber.org/zap"
	"go.uber.org/zap/zapcore"
)

var (
	l *zap.Logger
	s *zap.SugaredLogger

	Debug     func(args ...interface{})
	Info      func(args ...interface{})
	Warn      func(args ...interface{})
	Error     func(args ...interface{})
	Debugf    func(tmpl string, args ...interface{})
	Infof     func(tmpl string, args ...interface{})
	Warnf     func(tmpl string, args ...interface{})
	Errorf    func(tmpl string, args ...interface{})
	InfoQuick func(msg string, fields ...zap.Field)
	WarnQuick func(msg string, fields ...zap.Field)
)

func SetUp() error {

	//TODO: 環境変数つかって設定できるようにする
	conf := zap.Config{
		Level:            zap.NewAtomicLevelAt(zap.DebugLevel),
		Development:      true,
		Encoding:         "console",
		OutputPaths:      []string{"stdout"},
		ErrorOutputPaths: []string{"stdout"},
		EncoderConfig: zapcore.EncoderConfig{
			LevelKey:     "level",
			TimeKey:      "time",
			MessageKey:   "msg",
			CallerKey:    "caller",
			EncodeTime:   zapcore.ISO8601TimeEncoder,
			EncodeLevel:  zapcore.LowercaseLevelEncoder,
			EncodeCaller: zapcore.ShortCallerEncoder,
		},
	}
	var err error
	l, err = conf.Build()
	if err != nil {
		return err
	}
	s = l.Sugar()

	//LogのCallerを正しく表示させるために、ファンクションをDIする形にする
	//例えば、別ファンクション func Debug(...){ s.Debug(...) } のように定義した場合、
	//出力されるログのcallerが全てlogger/logger.goになってしまう。
	Debug = s.Debug
	Info = s.Info
	Warn = s.Warn
	Error = s.Error
	Debugf = s.Debugf
	Infof = s.Infof
	Warnf = s.Warnf
	Errorf = s.Errorf
	InfoQuick = l.Info
	WarnQuick = l.Warn

	return nil
}

---

• 思考錯誤しながらも最終的にはいい形になったのではないかと思っています。
• これを元に開発するのはこれからなので変わるかもしれませんが。
• loggerの実装自体、デファクトスタンダードがありそう、もっといい方法あれば教えてほしいです！