目標

grpc 使用時に、zap の出力結果が stackdriver logging でまとまるようにしていきます。

cloud run での出力条件

Cloud run の標準出力はデフォルトで logging にエクスポートされます。しかし、特定の出力は特殊フィールドとみなされます。まずは、その特殊フィールドを見ていきます。
公式ドキュメントには以下のように記載されています。

When the Logging agent receives a structured log record, it treats the following fields specially, allowing you to set specific fields in the LogEntry object that get written to the Logging API.

つまり、jsonなどで出力された際に、特定の名前のフィールドが特殊フィールドと扱われることが分かります。

一個ずつ特殊フィールドを見ても公式をなぞるだけなので、今回目指したい出力を以下に記します。

{
  "severity": "ログの重要度(例：DEBUG)",
  "message": "ログメッセージ",
  "time": "ログのタイムスタンプ",
  "logging.googleapis.com/trace": "トレースID(例：projects/[PROJECT-ID]/traces/[V])",
  "logging.googleapis.com/spanId": "同一トレース内のスパンID(例：000ddfff3)"
}

上記のようなフィールドが特殊フィールドとみなされ、標準で出力されるリクエストのログに対してまとまってくれます。それではこれを目指して行きます。logging.googleapis.com/trace_sampled はopencensusなどのtraceライブラリの設定が必要なので、今回はやりません。

zap で出力する

zap の設定

上記のように出力するために、zap の設定は以下のようにしました。今回はプラグインなどを使わず自力で実装しています。

package log

import (
	"cloud.google.com/go/logging"
	"go.uber.org/zap"
	"go.uber.org/zap/zapcore"
)

func NewStackdriverLogging() (*zap.Logger, error) {
	return zap.Config{
		Level:       zap.NewAtomicLevelAt(zapcore.InfoLevel),
		Development: false,
		Sampling: &zap.SamplingConfig{
			Initial:    100,
			Thereafter: 100,
		},
		Encoding: "json",
		EncoderConfig: zapcore.EncoderConfig{
			LevelKey:      "severity",
			NameKey:       "logger",
			CallerKey:     "caller",
			StacktraceKey: "stack_trace",
			TimeKey:       "time",
			MessageKey:    "message",
			LineEnding:    zapcore.DefaultLineEnding,
			EncodeTime:    zapcore.RFC3339NanoTimeEncoder,
			EncodeLevel:   levelEncode,
			EncodeCaller:  zapcore.ShortCallerEncoder,
		},
		OutputPaths:      []string{"stdout"},
		ErrorOutputPaths: []string{"stderr"},
	}.Build()
}

func levelEncode(l zapcore.Level, enc zapcore.PrimitiveArrayEncoder) {
	switch l {
	case zapcore.DebugLevel:
		enc.AppendString(logging.Debug.String())
	case zapcore.InfoLevel:
		enc.AppendString(logging.Info.String())
	case zapcore.WarnLevel:
		enc.AppendString(logging.Warning.String())
	case zapcore.ErrorLevel:
		enc.AppendString(logging.Error.String())
	default:
		enc.AppendString(logging.Critical.String())
	}
}

基本的には先程の json 出力に合わせるようにしています。レベルのエンコードを zap のレベルと logging のレベルと合わせる必要があるので、そこの注意が必要です。また公式ドキュメントには、timestamp のフィールドは timestamp ならオブジェクトで、time という名前なら文字列で指定する必要があります。

request ごとにトレース ID を埋め込む

次に request ごとにトレース ID を埋め込みます。grpc の場合、ヘッダー情報が context に入っているため、以下のようにして、トレース ID と span を取り出して、logger にセットします。

import (
	"context"
	"fmt"
	"regexp"

	"go.uber.org/zap"
	"google.golang.org/grpc/metadata"
)

func InjectTrace(ctx context.Context, logger *zap.Logger, project string) (*zap.Logger) {
	md, _ := metadata.FromIncomingContext(ctx)
	var headerStr string
	if traces := md.Get("X-Cloud-Trace-Context"); len(traces) != 0 {
		headerStr = md.Get("X-Cloud-Trace-Context")[0]
	}

	trace, spanID := deconstructXCloudTraceContext(headerStr)
	return logger.With(
		zap.String("logging.googleapis.com/trace", fmt.Sprintf("projects/%s/traces/%s", project, trace)),
		zap.String("logging.googleapis.com/spanId", spanID),
	)
}

var reCloudTraceContext = regexp.MustCompile(`([a-f\d]+)/([a-f\d]+)`)

func deconstructXCloudTraceContext(s string) (traceID, spanID string) {
	matches := reCloudTraceContext.FindAllStringSubmatch(s, -1)
	if len(matches) != 1 {
		return
	}

	sub := matches[0]
	if len(sub) != 3 {
		return
	}

	traceID, spanID = sub[1], sub[2]
	if spanID == "0" {
		spanID = ""
	}

	return
}

ミドルウェアなどでトレースを仕込んだ、logger を context に入れていけば終わりです。

func LoggerInterceptor(logger *zap.Logger) func(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (resp interface{}, err error) {
	return func(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (resp interface{}, err error) {
		newLogger := InjectTrace(ctx, logger)
		newCtx = ToContext(ctx, newLogger)
		return handler(newCtx, req)
	}
}

type ctxLoggerKey struct{}

func Extract(ctx context.Context) *zap.Logger {
	return ctx.Value(ctxLoggerKey{}).(*zap.Logger)
}

func ToContext(ctx context.Context, logger *zap.Logger) context.Context {
	return context.WithValue(ctx, ctxLoggerKey{}, logger)
}

ミドルウェアの登録は以下のように行います。

	grpcServer := grpc.NewServer(
		grpc.UnaryInterceptor(
			middleware.LoggerInterceptor(logger),
		),
	)

それぞれのリクエストでの使用イメージは以下のような感じです。

func (p *sampleApplication) CreateBlog(ctx context.Context, req *gen.NewBlogRequest) (*gen.BlogReply, error) {
	logger := log.Extract(ctx)

  	logger.Info("create blog", zap.String("blog id", "doffff1"))
  return nil, nil
}

logging での出力

結果としては以下のようにまとまります。grpc の出力は全て post の 200 になってしまうのが少し難点ですね。。。 logging結果

感想

結構簡単に連携できたことに驚きました。logging api と違ってローカルで実行することは出来ませんが、代わりにリクエストごとにまとめるのが容易でした。gcp 上での開発は今回のやり方でいいかなって個人的に思っています。