log/slogとcontextで妥協しないロギングを実現する

はじめに

この記事は バイセルテクノロジーズ Advent Calendar 2024の10日目の記事です。

こんにちは。開発1部の鴨野です。

前日の記事は私、鴨野の「【13分→4分】開発効率向上のためのCloud Buildデプロイ速度改善」でした。

現在はバックエンドエンジニアとして、リユースプラットフォーム「Cosmos」の出張訪問買取アプリケーション「Visit」の開発に携わっています。

今回は、Visitチームで課題となっていた障害対応や問い合わせ対応を改善するために実装したカスタムロガーについてご紹介します。

作成したロガーは、実際に利用する際のサンプルとともに公開しています。なお、この記事で使用したサンプルコードは以下のリポジトリから抜粋したものです。

github.com

なぜカスタムロガーを実装したのか

私が現在所属しているVisitチームは6月にプロダクトをリリースし、私自身がチームに参加した7月はリリースに伴う修正などが多少落ち着いてきた頃でした。とはいえ、引き続き新規機能開発が進められていました。そこで課題になっていたのが、エラーのトリアージや障害対応、問い合わせ対応で開発にかけられる時間が削られているということでした。

7月時点では、何らかのエラーが検知された際には、アプリケーションが出力するHTTPレスポンスとPrintログだけが頼りでした。Printログの内容を読み、そこから得られる情報をもとにログを全文検索したり、時には推測で原因の特定と対処を行っていました。しかし、この方法は新規参入者にとって非常に困難で、既存メンバーにとっても時間がかかるものでした。

このような現状を改善するため、ロガーを改良し、エラーのトリアージや障害対応、問い合わせ対応を効率化することを目指しました。

ロガーが満たすべき要件

上記の目的を達成するために、必要だと考えられるロガーの要件は以下の通りです。

• 十分な情報量を出力できる
• 検索が容易なログを出力できる
  • 構造化されている
  • リクエストからレスポンスまでの一連の流れを追える
    • コンテキストを利用して情報の取得、付加ができる
• 実装が容易である
  • 開発者が都度ログの設計をせずとも適切なログを出力できる
• 既存のアプリケーションをできる限り変更せずに導入できる

この要件を満たすために、チームに最適化されたカスタムロガーを実装することにしました。

ログの要件やあるべき姿については以前社内勉強会で登壇した資料がありますので、こちらも併せてご覧いただけると幸いです。

www.docswell.com

前提: Visitアプリケーションの構成

Visitアプリケーションは、バックエンドにGo言語のWebフレームワークであるEchoを使用しています。Cloud Runにデプロイしており、Log Explorerを利用してログを確認していました。アプリケーション内のロギングはEchoが提供しているecho.Loggerを主に使用していました。

技術選定

カスタムロガーを実装するにあたり、既存のロギングライブラリをラップする形で実装することを検討しました。

---

まず候補に上がったのは、Echoのロガーであるecho.Loggerを利用する方法です。

echo.Loggerは標準でecho.Contextから取り出すことが可能で、リクエストからレスポンスまでの情報伝達が可能です。しかし、社内の他のプロダクトではEchoを利用していないものも多く、他のプロダクトでも導入ができるよう、echo.Loggerをラップする方法は見送りました。また、echo.LoggerはすでにNew RelicやSentryなどのミドルウェアと連携されているため、それらのミドルウェアとの連携も考慮する必要があり、既存の運用に影響を与えると判断したのも、採用を見送った理由の1つです。

---

次に候補に上がったのは、zap を利用する方法です。

zapはGo言語のロギングライブラリの中でも高速に動作し、構造化ログを出力できます。また、zapはcontext.Contextを利用して情報の伝達が可能で、リクエストからレスポンスまで一貫した情報を保持できます。zapは、社内の他のプロダクトでも利用されていることが多く、要件に適しているかと思われました。しかし、今回のように決まった要件を満たすために様々な設定を行っていく場合は、zap自体に対する理解と、それをラップしているコードの理解が必要になり、zapが高機能であるがゆえに学習コストが高くなると考えました。また、要件に合わせるためにラップするという利用方法では、柔軟な利用ができるzapである必要性が薄いと考え、こちらも採用を見送りました。

---

最終的に採用したのは、slog を利用する方法です。

slogはGo 1.21から標準パッケージとして利用が可能で、構造化されたログを出力できます。また、slogはcontext.Contextを利用でき、その際の実装は自前で行う必要がありますが、その分柔軟な利用が可能です。標準パッケージであるため、他のプロダクトでの利用ハードルも低く、今後より多くのプロダクトで利用が可能になると考え、採用に至りました。

slogの基本的な利用方法

slogの基本的な利用方法は以下のとおりです。

// main.go
func main() {
  // ロガーを作成
  logger := slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{
    AddSource: true, // ログの出力元のファイル名、関数名、行番号を表示
  })

  // グローバルロガーを設定
  slog.SetDefault(logger)

  // ロガーを利用
  slog.Info("Info message")

  // contextを利用してロガーを利用
  // デフォルトではcontextに対してなにもしない
  ctx := context.Background()
  slog.InfoContext(ctx, "Info message")
}

slogはslog.SetDefaultを利用することで、グローバルに利用するロガーを設定できます。このロガーはslogを利用するすべての場所で利用されます。これによってコンテキストにロガーをセットすることなく、どこからでもロガーを利用できます。そのため、コンテキストを利用していない関数でも、このロガーを使ってログを出力できます。

また、AddSourceをtrueにすることで、ログの出力元のファイル名と行番号を表示させることができます。

context.Contextを利用した値の受け渡し

slogではslog.Handlerを渡すことで、slog.InfoContextなどで渡したcontext.Contextに対する処理を行うことができます。 定数化したキーに対応した値を取り出すだけのシンプルな処理を実装しました。

// handler.go
func (h Handler) Handle(ctx context.Context, record slog.Record) error {
  if v, ok := ctx.Value(logContextKey{}).(*sync.Map); ok {
    v.Range(func(key, val any) bool {
      if keyString, ok := key.(string); ok {
        record.AddAttrs(slog.Any(keyString, val))
      }
      return true
    })
  }

  return h.handler.Handle(ctx, record)
}

context.Contextに値をセットする関数の方は少し工夫をして、以下のようになりました。

// context.go
type logContextKey struct{}

type Attrs map[string]any

func WithValue(parent context.Context, attrs Attrs) context.Context {
  if parent == nil {
    parent = context.Background()
  }
  if v, ok := parent.Value(logContextKey{}).(*sync.Map); ok {
    mapCopy := copySyncMap(v)
    for key, val := range attrs {
      mapCopy.Store(key, val)
    }
    return context.WithValue(parent, logContextKey{}, mapCopy)
  }
  v := &sync.Map{}
  for key, val := range attrs {
    v.Store(key, val)
  }
  return context.WithValue(parent, logContextKey{}, v)
}

func copySyncMap(m *sync.Map) *sync.Map {
  var cp sync.Map
  m.Range(func(k, v interface{}) bool {
    cp.Store(k, v)
    return true
  })
  return &cp
}

このようにsync.Mapを利用した実装にしているのは、context.Contextをgoroutine間で共有する際に、sync.Mapを利用することで安全に値を取り出すことができるためです。

echo.Contextでも使えるようにする

今までの例は標準のcontext.Contextを利用した例でしたが、Echoのcontextを利用する場合はslog.xxxContext(InfoContext, WarnContext, ErrorContext)のラッパー関数を用意して対応します。

echo.Contextはecho.Context().Requestで*http.Requestを取得でき、このリクエストに存在するcontext.Contextを利用することでecho.Contextに対応できます。

// wrapper/echo.go

// echo.Contextで使う関数のみをインターフェースで定義
type customContext interface {
  Request() *http.Request
  SetRequest(r *http.Request)
}

func getContext(eCtx customContext) context.Context {
  ctx := eCtx.Request().Context()
  return ctx
}

func setContent(eCtx customContext, ctx context.Context) {
  eCtx.SetRequest(eCtx.Request().WithContext(ctx))
}

func split(attrs slogcontext.Attrs) []any {
  args := make([]any, 0, len(attrs)*2)
  for k, v := range attrs {
    args = append(args, k, v)
  }
  return args
}

func InfoContext(eCtx customContext, msg string, attrs slogcontext.Attrs) {
  ctx := getContext(eCtx)
  ctx = slogcontext.WithPC(ctx)
  slog.InfoContext(ctx, msg, split(attrs)...)
}

func WithValue(eCtx customContext, attrs slogcontext.Attrs) {
  ctx := slogcontext.WithValue(getContext(eCtx), attrs)
  setContent(eCtx, ctx)
}

このようにslog.InfoContextをラップして利用すると、ログを実行した際のsourceLocationがこのラッパー関数を指すようになってしまいます。そのため、WithPCを利用してcontext.Contextに実行元のsourceLocationをセットすることで、正しいsourceLocationを取得できます。

// handler.go
func (h Handler) Handle(ctx context.Context, record slog.Record) error {
  if v, ok := ctx.Value(logContextKey{}).(*sync.Map); ok {
    v.Range(func(key, val any) bool {
      if keyString, ok := key.(string); ok {
        record.AddAttrs(slog.Any(keyString, val))
      }
      return true
    })
  }

  // この部分を追加
  // ctxからプログラムカウンタを取得し、Recordを更新する
  pc, ok := ctx.Value(pcKey).(uintptr)
  if ok {
    record.PC = pc
  }

  return h.handler.Handle(ctx, record)
}

実際にアプリケーション内で使う際は以下のように使用します。

// example/echo/main.go
func main() {
  e := echo.New()

  setupLogger()

  // Set up server
  e.GET("/", func(c echo.Context) error {
    // Log with context
    echoContextLogger.WithValue(c, slogcontext.Attrs{"key": "value"})
    echoContextLogger.InfoContext(c, "Hello, World!", slogcontext.Attrs{"key2": "value2"})
    return c.String(http.StatusOK, "Hello, World!")
  })
  e.Logger.Fatal(e.Start(":1323"))
}

func setupLogger() {
  baseLogHandler := slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{
    AddSource: true,
  })
  logHandler := slogcontext.NewHandler(baseLogHandler)
  slog.SetDefault(slog.New(logHandler))
}

Google Cloud対応

Log Explorerを最大限活用するためには特殊なフィールドを出力する必要があります。

これを実現するために、ReplaceAttrで利用できるように対応するキーを定数化するか、または既存のキーを置き換えることで対応しました。

特にGoogle Cloudではlevelではなくseverityを利用する必要があったり、msgではなくmessageを利用する必要があるため、これらのキーを置き換えることで、Log Explorerでのログの見やすさを向上させることが重要です。

// adapter/googleCloud/field.go
const (
  SourceKey     = "logging.googleapis.com/sourceLocation"
  LabelKey      = "logging.googleapis.com/labels"
  TraceKey      = "logging.googleapis.com/trace"
  SpanKey       = "logging.googleapis.com/spanId"
  MessageKey    = "message"
  LevelKey      = "severity"
  StackTraceKey = "stack_trace"
)

// adapter/googleCloud/replaceRule.go
func KeyRule() adapter.ReplaceRule {
  return func(a slog.Attr) slog.Attr {
    switch a.Key {
    case slog.LevelKey:
      if a.Value.String() == slog.LevelWarn.String() {
        return slog.String(LevelKey, "WARNING")
      }
      a.Key = LevelKey
    case slog.MessageKey:
      a.Key = MessageKey
    case slog.SourceKey:
      a.Key = SourceKey
    }
    return a
  }
}

// adapter/replacer.go

// implement Handler interface
type replacer func(groups []string, a slog.Attr) slog.Attr

var _ = slog.HandlerOptions{
  ReplaceAttr: replacer(nil),
}

type ReplaceRule func(a slog.Attr) slog.Attr

func NewReplacer(rules ...ReplaceRule) replacer {
  return func(groups []string, a slog.Attr) slog.Attr {
    for _, rule := range rules {
      a = rule(a)
    }
    return a
  }
}

このようなキーを用いることで、Log Explorerで使用できるフィールドが増え、より扱いやすいログを出力できます。

// example/googleCloud/main.go

func setupLogger() {
  baseLogHandler := slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{
    AddSource: true,
    ReplaceAttr: adapter.NewReplacer(
      googleCloudAdapter.KeyRule(), // Google Cloud用のキーに置き換える
    ),
  })
  logHandler := slogcontext.NewHandler(baseLogHandler)
  slog.SetDefault(slog.New(logHandler))
}

検索性をさらに高める定数Attributeパターン

context.Contextに含められるAttributeキーを事前定義したものに限定することでキーの一意性を確保し、ログの検索性を高めることができます。Attributeキーはプライベートなフィールドを持った構造体を利用することで、WithValueの際に必ず決まったAttributeキーが利用されるように強制できます。

// wrapper/strict/logger.go
type strictKey struct{ keyStr string }

var (
  UserIDKey    = strictKey{keyStr: "user_id"}
  ReqIDKey     = strictKey{keyStr: "req_id"}
  TraceIDKey   = strictKey{keyStr: "trace_id"}
  SessionIDKey = strictKey{keyStr: "session_id"}
)

func WithValue(ctx context.Context, key strictKey, val string) context.Context {
  return slogcontext.WithValue(ctx, slogcontext.Attrs{key.keyStr: val})
}

JWTミドルウェアとの親和性

CosmosではJWTを利用して認証を行っています。アプリケーション内でJWTの検証、デコードをするミドルウェアを実装しているため、このミドルウェア内でコンテキストにユーザーの情報をセットすることで、ほぼすべてのログにユーザー情報を含めることができます。

これによってユーザーの行動が追えるようになります。

結果

今回作成したカスタムロガーを導入すると、Log Explorerでのログが非常に見やすくなりました。

画像のように、Log Explorerでは構造化ログに含まれているフィールドを概要行として一覧画面に表示できます。ログの詳細画面から、概要行にフィールドを追加をクリックすることで、ログの詳細画面に含まれているフィールドが緑色のチップとして表示されます。

また、設定 > 概要フィールドの管理から、概要行に表示するフィールドを一覧で追加・削除できます。

また、概要フィールドを基に1クリックでログの検索クエリを実行できるため、ログの検索が非常に容易になりました。

その結果、障害対応や問い合わせ対応にかかる時間が大幅に短縮され、開発メンバーの負担も大きく軽減されました。 また、以下のようなフィードバックを得ることができました。

• 全文検索が不要になり、必要なログがすぐに見つかるようになった
• ログの検索が容易になり、障害対応がしやすくなった
• カスタムロガーのおかげで日々のアラート対応業務が格段に楽になりました !
• 情報量が多くて検索しやすいのは当たり前なのですが、これだけのことが外部パッケージを生やすだけで手軽にできたというのが素晴らしいです。
• 時代が変わった

また、今回出力されたログをBigQueryにエクスポートして分析することで、アプリケーションの利用状況やユーザーの行動分析が可能になりました。チームの課題解決に貢献するだけでなく、新たな価値を生み出すことができ、やってよかったと感じています。

まとめ

最後までお読みいただき、ありがとうございました。

今回は、課題解決を最優先とした実践的なカスタムロガーの実装について紹介しました。 このカスタムロガーによって削減できた時間を新規機能開発に充て、Visitアプリケーションのさらなる成長を目指していきます。

最後に、バイセルでは一緒に働くエンジニアを募集しています、興味がある方は、以下よりご応募ください。 herp.careers

明日の バイセルテクノロジーズ Advent Calendar 2024 はメントスさんによる 「マイクロサービスに向き合った結果、新規サービスのバックエンドを既存の基盤システムに組み込む意思決定をした話」です。お楽しみに！