概要
先日リリースを控えているプロジェクトがあり、リリース前にログを整備したいという話になりました。
そこでGoのライブラリであるzapを使用してみたので、使い方の備忘を残そうと思います。
これからzapを導入しようと思っている方などに参考になりますと幸いです。
環境
- Go v1.17
- go.uber.org/zap v1.16.0
- google.golang.org/grpc v1.36.0
はじめに
とにかくzapを使って簡単なロギングをしてみます。サーバーを立てつつzapからlogを出力してみました。
func main() {
logger, _ := zap.NewDevelopment()
logger.Info("Hello zap")
conn, err := repository.InitDBConnection("qiita")
if err != nil {
log.Fatalf("db connection failed: %v", err)
}
s := grpc.NewServer()
// GRPCのserviceを登録する独自関数です
rpc.RegisterServices(s, conn)
lis, err := net.Listen("tcp", ":50000")
if err != nil {
log.Fatalf("failed to listen: %v", err)
}
if err := s.Serve(lis); err != nil {
log.Fatalf("failed to serve: %v", err)
}
}
サーバを起動すると下記のように出力されました
2022-06-22T11:04:38.884Z INFO main.go:19 Hello zap
ログ設定の変更
上記のログだと情報が少なく、扱いづらい印象かと思います。そこでzap.Configを使ってログ設定をカスタマイズすることができます。
func main() {
conf := zap.Config{
Level: zap.NewAtomicLevel(),
Development: false,
Encoding: "json",
EncoderConfig: zapcore.EncoderConfig{
TimeKey: "timestamp",
LevelKey: "level",
NameKey: "name",
CallerKey: "caller",
MessageKey: "msg",
StacktraceKey: "stacktrace",
EncodeLevel: zapcore.LowercaseLevelEncoder,
EncodeTime: zapcore.ISO8601TimeEncoder,
EncodeDuration: zapcore.StringDurationEncoder,
EncodeCaller: zapcore.ShortCallerEncoder,
},
OutputPaths: []string{"stdout", "./log/development.out.log"},
ErrorOutputPaths: []string{"stderr", "./log/development.err.log"},
}
logger, err := conf.Build()
if err != nil {
log.Fatalf(err.Error())
}
logger.Info("Hello zap")
...省略
サーバを起動すると下記のように出力されました
{"level":"info","timestamp":"2022-06-22T11:17:48.703Z","caller":"main.go:44","msg":"Hello zap"}
このようにzap.Configを使うと出力するログの定型を変更することができます。
さらにはEncodeTimeなどはfuncを引数に取るため、独自のメソッドを用意してカスタマイズすることもできます。
インターセプターの導入
実案件では、リクエストログを出力したいというものがありました。
そこでインターセプターを導入することでリクエスト、レスポンスの際に自動でzapのログを出力させることとしました。
gRPCを使っているため、grpc_middleware.ChainUnaryServer()にAccessLog関数を渡します。
サーバー起動側
... 省略
s := grpc.NewServer(
grpc.UnaryInterceptor(
grpc_middleware.ChainUnaryServer(
middleware.AccessLog(logger),
),
),
)
rpc.RegisterServices(s, conn)
lis, err := net.Listen("tcp", ":50000")
if err != nil {
log.Fatalf("failed to : %v", err)
}
if err := s.Serve(lis); err != nil {
log.Fatalf("failed to serve: %v", err)
}
}
ミドルウェア側
func AccessLog(logger *zap.Logger) grpc.UnaryServerInterceptor {
return func(
ctx context.Context,
req interface{},
info *grpc.UnaryServerInfo,
handler grpc.UnaryHandler,
) (interface{}, error) {
startTime := time.Now()
logger.Info(
"request start",
zap.String("grpc.start_time", startTime.Format(time.RFC3339Nano)),
zap.Any("req", req),
)
resp, respErr := handler(ctx, req)
// エラーが発生した時もrespとerrを表示したいので、この行でdefer実行
defer logger.Info(
"request end",
zap.String("grpc.end_time", time.Now().Format(time.RFC3339Nano)),
zap.Int64("grpc.duration_nano", time.Since(startTime).Nanoseconds()),
zap.String("grpc.code", grpc_logging.DefaultErrorToCode(respErr).String()),
zap.Any("resp", resp),
zap.Error(respErr),
)
if respErr != nil {
return nil, respErr
}
return resp, nil
}
}
実際にリクエストを送ってみると下記のような出力がされました。
{"level":"info","timestamp":"2022-06-22T12:09:56.524Z","caller":"middleware/logger.go:86","msg":"request start","grpc.start_time":"2022-06-22T12:09:56.52180518Z","req":""}
{"level":"info","timestamp":"2022-06-22T12:09:57.137Z","caller":"middleware/logger.go:108","msg":"request end","grpc.end_time":"2022-06-22T12:09:57.136804555Z","grpc.duration_nano":615124750,"grpc.code":"OK","resp":"status:SERVING"}
リクエスト開始のログとリクエスト終了時のログが出ていることがわかります。
logger.Withの利用
ここまでで概ねのロギングはできるようになったのですが、実際に運用を開始すると複数のリクエストが飛んでくるため、今のログでは大量のログが残るだけでリクエストの関連性がわかりません。
そこでトラッキングIDをログに埋め込むことにしました。
ログに特定の値を埋め込むために使用するのがlogger.Withです。先ほどのmiddleware側を以下のように改修しました。
func AccessLog(logger *zap.Logger) grpc.UnaryServerInterceptor {
return func(
ctx context.Context,
req interface{},
info *grpc.UnaryServerInfo,
handler grpc.UnaryHandler,
) (interface{}, error) {
startTime := time.Now()
loggerWithField := logger.With(
zap.String("tracking_id", cuid.New()),
)
loggerWithField.Info(
"request start",
zap.String("grpc.start_time", startTime.Format(time.RFC3339Nano)),
zap.Any("req", req),
)
resp, respErr := handler(ctx, req)
// エラーが発生した時もrespとerrを表示したいので、この行でdefer実行
defer loggerWithField.Info(
"request end",
zap.String("grpc.end_time", time.Now().Format(time.RFC3339Nano)),
zap.Int64("grpc.duration_nano", time.Since(startTime).Nanoseconds()),
zap.String("grpc.code", grpc_logging.DefaultErrorToCode(respErr).String()),
zap.Any("resp", resp),
zap.Error(respErr),
)
if respErr != nil {
return nil, respErr
}
return resp, nil
}
}
実際にリクエストを送ると下記のようになります。
{"level":"info","timestamp":"2022-06-22T12:15:27.451Z","caller":"middleware/logger.go:91","msg":"request start","tracking_id":"cl4pk6jmb0000gclnllgxfn1y","grpc.start_time":"2022-06-22T12:15:27.443746222Z","req":""}
{"level":"info","timestamp":"2022-06-22T12:15:28.141Z","caller":"middleware/logger.go:113","msg":"request end","tracking_id":"cl4pk6jmb0000gclnllgxfn1y","grpc.end_time":"2022-06-22T12:15:28.14022175Z","grpc.duration_nano":695503916,"grpc.code":"OK","resp":"status:SERVING"}
ログの中にtracking_idの項目があるのがわかるかと思います。
こちらのloggerWithFieldを取り回すことで、リクエストとログの紐付きがわかるようになります。
loggerをcontextに埋め込む
ここまででmiddleware領域のロギングの大枠は作ることができました。
しかし実際は、handlerなどのアプリケーション実装部分でもログを出力したいことがあるはずです。
そのためにはcontextごとにloggerを持たせることができればと考えました。そこでctxzap.ToContext()と ctxzap.Extract()という関数を使用します。
まず、middlewareの中でctxzap.ToContext()を使用します。
...省略
loggerWithField := logger.With(
zap.String("tracking_id", cuid.New()),
)
loggerWithField.Info(
"request start",
zap.String("grpc.start_time", startTime.Format(time.RFC3339Nano)),
zap.Any("req", req),
)
newCtx := ctxzap.ToContext(ctx, loggerWithField)
resp, respErr := handler(newCtx, req)
// エラーが発生した時もrespとerrを表示したいので、この行でdefer実行
defer loggerWithField.Info(
"request end",
zap.String("grpc.end_time", time.Now().Format(time.RFC3339Nano)),
zap.Int64("grpc.duration_nano", time.Since(startTime).Nanoseconds()),
zap.String("grpc.code", grpc_logging.DefaultErrorToCode(respErr).String()),
zap.Any("resp", resp),
zap.Error(respErr),
)
...省略
この記述により、ctxに中にloggerが埋め込まれたnewCtxという変数が生まれます。
newCtxをhandlerに渡すため、handlerではこのnewCtxからloggerを抽出することができます。
ctxからloggerを抽出するためには、ctxzap.Extract()を使用します。
handlerの記述が下記のとおりです。
func (hcs HealthCheckService) Check(ctx context.Context, req *health.HealthCheckRequest) (*health.HealthCheckResponse, error) {
logger := ctxzap.Extract(ctx)
logger.Info("handler now")
return &health.HealthCheckResponse{
Status: health.HealthCheckResponse_SERVING,
}, nil
}
実際にログを出力してみます。
{"level":"info","timestamp":"2022-06-22T12:27:41.155Z","caller":"middleware/logger.go:91","msg":"request start","tracking_id":"cl4pkm9r400009rlnkrrwwyr5","grpc.start_time":"2022-06-22T12:27:41.152376131Z","req":""}
{"level":"info","timestamp":"2022-06-22T12:27:41.161Z","caller":"rpc/health_check_service.go:35","msg":"handler now","tracking_id":"cl4pkm9r400009rlnkrrwwyr5"}
{"level":"info","timestamp":"2022-06-22T12:27:41.162Z","caller":"middleware/logger.go:114","msg":"request end","tracking_id":"cl4pkm9r400009rlnkrrwwyr5","grpc.end_time":"2022-06-22T12:27:41.162372464Z","grpc.duration_nano":10019667,"grpc.code":"OK","resp":"status:SERVING"}
request startとrequest endの間にhandler nowが存在することがわかるかと思います。
さらにhandler nowのログにはtracking_idが付与されているため、リクエストの関係性がわかるようになっています。
まとめ
zapの使い方について簡単にまとめてみました
個人的には非常に簡単に設定ができる上、カスタマイズも難しくない印象を受けています。
さらには軽量で実行速度も速いとか・・・かなり使い勝手の良いライブラリなのではないでしょうか。
さいごに
トレタでは一緒に開発する仲間を募集しています。
興味がある方は是非カジュアル面談へお越しください！