Go で gRPC を開発するときのロギング戦略と実践

わんわん！

Showcase Gig SRE チームの赤嶺(@kazz187)です。 皆さん、 2021年はたくさん Go を書きましたか？

皆さんも初心のころは、 Go にはこれといったオールインワンなフレームワークがなく、プロジェクトの下地を整えるときの技術選定やアーキテクチャなどで悩まれたことでしょう。

その中でもロギングは、プロジェクト開始時においてはどうでもよいようで、いざ開発を進めてから改修するととても大変です。 サービスの結合時や障害対応時にオブザーバビリティが備わっているかどうかは非常に重要となります。開発の初期からロギング戦略を立て効率的な開発ライフをスタートさせましょう！

今回は我々のチームで取ったロギング戦略とその実践を紹介します。Go で開発を始めたばかりで悩まれている方の参考になれば幸いです。

基本的なロギング戦略

ログを構造化し、1リクエスト1ログとする

サービスの結合テスト時や障害対応時にとある問題が発生した際、膨大なログの海からシーケンスを把握し、問題点を探し出すことは面倒な作業です。

そこで普段から INFO レベルのログ量を減らすことを心がけましょう。 (DEBUG レベルは本番では基本吐かないので適切な量のログを仕込んでください。) リアルタイム要素が絡まない Unary なリクエストを処理する場合、1リクエスト1ログで十分なことがほとんどです。

5W1H な要素が処理の途中に出てくる度にログを仕込みたくなることは重々承知ですが、要素が決まったタイミングでログを吐くのはやめて、1ログの中の1つの要素としてカラムをどんどん追加していきましょう。

もちろん不要なログを減らすとコストも減ります！

不要なログを削減する

ヘルスチェックのログなどのログは本番運用においてはノイズになります。除外するようにしましょう。

実践してみよう

zap がとても人気で優秀なツールであることは知っていますが、 logrus が我々の戦略にマッチしているため今回はその例を紹介していきます。

ロガーの作成

プログラムの冒頭でロガーを作成します。

今回は JSON 形式でログを標準出力へと出力する設定を加えます。コンテナ時代のログは標準出力に出すのがベスプラです。

Info や Debug などのログレベルを環境変数や設定ファイルなどから読み込んで設定しましょう。

logger := logrus.New()
logger.SetFormatter(&logrus.JSONFormatter{
	TimestampFormat: time.RFC3339Nano,
})
logger.SetOutput(os.Stdout)

level, err := logrus.ParseLevel(logLevel)
if err != nil {
	return fmt.Errorf("failed to parse log level: %w", err)
}
logger.SetLevel(level)

gRPC の Interceptor でアクセスログを出力する

他のフレームワークにおけるミドルウェアのような存在として、 gRPC には Interceptor というしくみが存在します。

Interceptor はすべての gRPC の処理が実行される前後に実行されるため、ログを漏らさずに仕込むには最適なポイントです。

毎プロジェクトで独自のアクセスログをカスタムしていては、ログ検索時や SLI の設定時などに各プロダクト別の実装を意識することになり手間がかかります。

gRPC にはそのような共通で使い回せる便利なコード群を ecosystem として公開し、みんなで利用できるすばらしい文化がありますのでそれに乗っからない手はありません。

logrus を用いた ecosystem の実装は こちら です。

ではこれをプロジェクトに取り込んでいきましょう。

gRPC server を作成時に設定するのですが、同じく ecosystem で提供されている ChainUnaryServer を利用して複数の Interceptor を列挙して定義できます。

UnaryServerInterceptor を利用するとリクエスト終了時にアクセスログを出力してくれるのですが、加えて次に紹介する context.Context 内にロガーを仕込んでくれるといううれしい機能もあります。

また、ここではログの出力を決定する Decider をカスタマイズすることでヘルスチェックログを除外できます。 ヘルスチェックも独自で実装する必要はなく、 grpc.health.v1.Health を使うとよいですがここでは割愛します。

entry := logrus.NewEntry(logger)
grpcServer := grpc.NewServer(
	grpc.UnaryInterceptor(
		grpc_middleware.ChainUnaryServer(
// ここにも他の Interceptor を列挙できる
			grpc_logrus.UnaryServerInterceptor(entry, grpc_logrus.WithDecider(
				func(fullMethodName string, err error) bool {
					return fullMethodName != "/grpc.health.v1.Health/Check"
				}),
			),
// ここにも他の Interceptor を列挙できる
		),
	),
)

各 gRPC 処理内でカスタムフィールドを仕込む

先程の Interceptor を設定すると context.Context 内にロガーが仕込まれて渡されます。

Go では外部の変数などを参照せずリクエスト毎のリソースを context.Context の中に詰めて受け渡しするという文化があり、今回もそれを利用しています。 (ロガーを Context に含めてはいけないという説もありはしますが今回は入れます。)

今回はリクエスト内に含まれる OrderID を order_id というフィールドに追加する例を紹介します。

ログに対して出力するときも ctxlogrus という便利な ecosystem が提供されています。

ここでは ctxlogrus.AddFields を使って ctx 内のログリソースにフィールドを仕込みます。ここに仕込んだものはアクセスログ出力時に合わせて出力されます。

func (s *Server) Example(ctx context.Context, req *example.ExampleRequest) (*example.ExampleResponse, error) {
	ctxlogrus.AddFields(ctx, logrus.Fields{
		"order_id": req.OrderID,
	})
}

これを Interceptor 内で利用して、 Datadog のトレースログ向けのフィールドである dd.trace_id を全ログに仕込むということもやっています。

func TraceIDUnaryServerInterceptor() grpc.UnaryServerInterceptor {
	return func(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (interface{}, error) {
		span, ok := tracer.SpanFromContext(ctx)
		if ok {
			ctxlogrus.AddFields(ctx, logrus.Fields{
				"dd.trace_id": span.Context().TraceID(),
			})
		}
		return handler(ctx, req)
	}
}

一般的なログの出力方法

その他エラーログなど一般的なログを出力するときにも ctxlogrus を利用することで設定したフィールドとともに出力できます。

ctxlogrus.Extract(ctx).Errorln(fmt.Errorf("failed to create order: %w", err))

さいごに

メリークリスマス！我々のチームで試行錯誤してきたロギング事例のささやかなプレゼントでした！

2022年も運用負荷を減らして素敵なハッキングライフを！