この記事を参考に、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の実装自体、デファクトスタンダードがありそう、もっといい方法あれば教えてほしいです！