zapを導入してCloud Loggingに構造化ログを出力する

サーバーのログの出力を見直したので記載

PR

github.com

実装

ログの実装にはzapを導入。

github.com

以下みたいな感じでログ出力が可能。

logger, _ := zap.NewProduction()
defer logger.Sync()
logger.Info("failed to fetch URL",
  zap.String("url", url),
  zap.Int("attempt", 3),
  zap.Duration("backoff", time.Second),
)

memoirではGCPを使用しているので、ログはCloud Loggingのフォーマットで出力できるように以下のように修正。

■usecase/logger/model.go

var logLevelSeverity = map[zapcore.Level]string{
    zapcore.DebugLevel:  "DEBUG",
    zapcore.InfoLevel:   "INFO",
    zapcore.WarnLevel:   "WARNING",
    zapcore.ErrorLevel:  "ERROR",
    zapcore.DPanicLevel: "CRITICAL",
    zapcore.PanicLevel:  "ALERT",
    zapcore.FatalLevel:  "EMERGENCY",
}

func EncodeLevel(l zapcore.Level, enc zapcore.PrimitiveArrayEncoder) {
    enc.AppendString(logLevelSeverity[l])
}

func newProductionEncoderConfig() zapcore.EncoderConfig {
    cfg := zap.NewProductionEncoderConfig()

    cfg.TimeKey = "time"
    cfg.LevelKey = "severity"
    cfg.MessageKey = "message"
    cfg.EncodeLevel = EncodeLevel
    cfg.EncodeTime = zapcore.RFC3339NanoTimeEncoder

    return cfg
}

func newProductConfig() zap.Config {
    cfg := zap.NewProductionConfig()
    cfg.Level.SetLevel(zap.ErrorLevel)
    cfg.EncoderConfig = newProductionEncoderConfig()

    return cfg
}

func New(ctx context.Context) *zap.Logger {
    cfg := newProductConfig()
    logger, _ := cfg.Build()

    return logger
}

上記で設定することで、以下のようにログを出力できる

log := logger.New(ctx)
log.Error("graphql error", zap.Error(e))

今回はさらに、Requestに紐づくログを追えるようにしたかったので、以下を参考にさらに処理を追加した。

dev.to

Cloud Runで紐づくRequestとログを紐付けるには、ヘッダーのX-Cloud-Trace-Contextを使用する必要があるので、以下のMiddlewareを作成。

■ usecase/logger/middleware.go

package logger

import (
    "context"
    "net/http"
    "regexp"
)

var TraceCtxKey = &contextKey{"trace"}

type contextKey struct {
    name string
}

type Trace struct {
    TraceID string
    SpanID  string
    Sampled bool
}

func Middleware() func(http.Handler) http.Handler {
    return func(next http.Handler) http.Handler {
        return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
            header := r.Header.Get("X-Cloud-Trace-Context")
            if len(header) > 0 {
                traceID, spanID, sampled := deconstructXCloudTraceContext(header)

                t := &Trace{
                    TraceID: traceID,
                    SpanID:  spanID,
                    Sampled: sampled,
                }

                ctx := context.WithValue(r.Context(), TraceCtxKey, t)
                r = r.WithContext(ctx)
            }

            next.ServeHTTP(w, r)
        })
    }

}

var reCloudTraceContext = regexp.MustCompile(
    // Matches on "TRACE_ID"
    `([a-f\d]+)?` +
        // Matches on "/SPAN_ID"
        `(?:/([a-f\d]+))?` +
        // Matches on ";0=TRACE_TRUE"
        `(?:;o=(\d))?`)

func deconstructXCloudTraceContext(s string) (traceID, spanID string, traceSampled bool) {
    matches := reCloudTraceContext.FindStringSubmatch(s)

    traceID, spanID, traceSampled = matches[1], matches[2], matches[3] == "1"

    if spanID == "0" {
        spanID = ""
    }

    return
}

func ForContext(ctx context.Context) *Trace {
    raw, _ := ctx.Value(TraceCtxKey).(*Trace)
    return raw
}

上記のMiddlewareで取得したX-Cloud-Trace-Contextをパースで保持。 以下で、ログ出力時にlogger.Withで設定することで、アクセス毎のログ出力を追うことが可能になる。

■usecase/logger/model.go

func New(ctx context.Context) *zap.Logger {
    cfg := newProductConfig()
    logger, _ := cfg.Build()

    trace := ForContext(ctx)
    if trace != nil {
        fields := zapdriver.TraceContext(trace.TraceID, trace.SpanID, trace.Sampled, os.Getenv("GCP_PROJECT_ID"))
        logger = logger.With(fields...)
    }

    return logger
}

上記を実装して実際にCloud Loggingで確認すると以下のように出力される。

Cloud Loggingのアクセスログのtraceの値から一致するエントリを表示させるとRequestに紐づくログを出力することができる。

これでやりたいことの実装は完了。ただし、このままだと1点だけ問題があり、ローカル開発時に出力されログが以下のように見辛くなってしまう。

なので、以下のようにローカル時にログの出力する形式を変更するように修正。

■usecase/logger/model.go

func newDevelopmentConfig() zap.Config {
    cfg := zap.NewDevelopmentConfig()
    cfg.EncoderConfig.EncodeLevel = zapcore.CapitalColorLevelEncoder
    cfg.Level.SetLevel(zap.InfoLevel)

    return cfg
}

func New(ctx context.Context) *zap.Logger {
    if os.Getenv("APP_ENV") == "local" {
        cfg := newDevelopmentConfig()
        logger, _ := cfg.Build()

        return logger
    }

    cfg := newProductConfig()
    logger, _ := cfg.Build()

    trace := ForContext(ctx)
    if trace != nil {
        fields := zapdriver.TraceContext(trace.TraceID, trace.SpanID, trace.Sampled, os.Getenv("GCP_PROJECT_ID"))
        logger = logger.With(fields...)
    }

    return logger
}

これでローカル開発時のログ出力は以下のようになり、視認性が上がった。