目標
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 api と違ってローカルで実行することは出来ませんが、代わりにリクエストごとにまとめるのが容易でした。gcp 上での開発は今回のやり方でいいかなって個人的に思っています。