🔍

Go Echo + Zapで実現するリクエスト追跡と構造化ロギング

に公開

はじめに

この記事では、EchoフレームワークのMiddlewareを使ったリクエスト追跡の手法を、業務で開発しているGoリポジトリでの実装例とともに紹介します。

リクエスト追跡のメリット

本番環境で発生したエラーの調査をする際、リクエスト追跡の仕組みのおかげで、以下のような作業を容易に行えています。

  • エラーログに記録されたリクエストIDを使って、関連する全てのログを収集する
  • 多数のユーザーが同時にアプリを利用している中でも、特定のユーザーの操作に関連するログを正確に特定できる
  • エラー発生前後の処理の流れを追跡できる

この仕組みがなければ、エラー調査に何倍も時間がかかっていたと思います。

リクエストIDを生成・伝播するミドルウェアの実装

今回は、各リクエストに一意のIDを付与し、それを使ってリクエストを追跡するやり方を紹介します。

基本的な実装

type RequestIDMiddleware struct {
    generator func() string
}

func NewRequestIDMiddleware() *RequestIDMiddleware {
    return &RequestIDMiddleware{
        generator: func() string {
            return uuid.New().String()
        },
    }
}

func (m *RequestIDMiddleware) WithRequestID() echo.MiddlewareFunc {
    return func(next echo.HandlerFunc) echo.HandlerFunc {
        return func(c echo.Context) error {
            // ヘッダーからリクエストIDを取得
            rid := c.Request().Header.Get("X-Request-ID")
            if rid == "" {
                // 無ければ新しくリクエストIDを生成
                rid = m.generator()
            }

            // コンテキストにリクエストIDを設定
            c.Set("request_id", rid)
            // レスポンスヘッダーにもリクエストIDを設定
            c.Response().Header().Set("X-Request-ID", rid)

            // ロガーにリクエストIDを関連付け
            logger := c.Logger().With(
                zap.String("request_id", rid),
            )
            c.SetLogger(logger)

            return next(c)
        }
    }
}

実装のポイント

  1. リクエストIDの生成と伝播の仕組み

    • UUIDを使用して一意のIDを生成(並行処理を考慮)
    • クライアントから送られてきたIDを尊重
    • レスポンスヘッダーにIDを含めることで、クライアント側でも追跡可能
  2. ロギングとの連携

    • リクエストIDをロガーに関連付けることで、全てのログにIDが自動的に付与される
    • 構造化ロギングを採用することで、ログの検索や分析が容易に

構造化ロギングの実装

リクエストIDを活用したログ出力の実装をご紹介します。
本プロジェクトでは、ロギングライブラリのZapを使用しています。
Zapは、JSONフォーマットでログを出力でき、フィールドベースのロギングを実現できる便利なライブラリです。
https://pkg.go.dev/go.uber.org/zap

func ZapLogger() echo.MiddlewareFunc {
    return func(next echo.HandlerFunc) echo.HandlerFunc {
        return func(c echo.Context) error {
            start := time.Now()

            // リクエストIDを取得
            rid := c.Get("request_id").(string)

            // リクエスト情報をログ
            logger := logging.Logger.With(
                zap.String("request_id", rid),
                zap.String("method", c.Request().Method),
                zap.String("path", c.Request().URL.Path),
            )

            err := next(c)

            // レスポンス情報をログ
            fields := []zap.Field{
                zap.Duration("latency", time.Since(start)),
                zap.Int("status", c.Response().Status),
            }

            if err != nil {
                fields = append(fields, zap.Error(err))
                logger.Error("request failed", fields...)
            } else {
                logger.Info("request completed", fields...)
            }

            return err
        }
    }
}

構造化ロギングの特徴・メリット

  1. ログの可読性向上

    • JSONフォーマットで出力されるため、ログの構造が明確
    • 情報が整理された状態で表示される
    • リクエストIDと合わせて、メソッド、パス、レイテンシなど重要な情報を記録
  2. エラー調査のしやすさ

    • リクエストIDで検索するだけで、関連するログが全て見つかる(調査時間が大幅に短縮)
    • エラー発生時は自動的にエラー情報が付加される
    • レイテンシも記録されるため、パフォーマンス問題の調査にも有用

ミドルウェアの設定

本プロジェクトのでは、ミドルウェアは以下のように設定されています。

func main() {
    e := echo.New()

    e.Use(middleware.Recover())  // パニック復帰を最初に
    e.Use(libmiddleware.NewRequestIDMiddleware().WithRequestID())  // リクエストID生成
    e.Use(libmiddleware.ZapLogger())  // ログ出力

    // ... ルーティング設定など
}

ミドルウェアの順序

パニックが発生した場合でも確実にリカバリーできるように、Recoverミドルウェアを最初に配置しています。
次に、後続の処理で必ずリクエストIDが利用できるようにRequestIDミドルウェアを2番目に配置しています。
最後に、リクエストIDが設定された後にログを出力できるように、ロギングミドルウェアを配置しています。

エラーハンドリングの実装

エラーハンドリングでも、リクエストIDを活用しています。
エラーハンドラーでは、エラーの種類に応じて適切なステータスコードを設定し、エラー情報をリクエストIDと共に構造化ログとして記録します。
また、クライアント側へのレスポンスにもリクエストIDを含めることで、調査を容易にします。

func ErrorHandler(err error, c echo.Context) {
    rid := c.Get("request_id").(string)

    logger := logging.Logger.With(
        zap.String("request_id", rid),
        zap.String("method", c.Request().Method),
        zap.String("path", c.Request().URL.Path),
    )

    var logMsg string
    code := http.StatusInternalServerError

    switch e := err.(type) {
    case *echo.HTTPError:
        code = e.Code
        logMsg = fmt.Sprintf("HTTP error: %v", e.Message)
    case *customErrors.ValidationError:
        code = http.StatusBadRequest
        logMsg = fmt.Sprintf("Validation error: %v", e.Error())
    default:
        logMsg = fmt.Sprintf("Internal error: %v", err)
    }

    logger.Error(logMsg,
        zap.Int("status_code", code),
        zap.Error(err),
    )

    // クライアントへのエラーレスポンス
    c.JSON(code, map[string]interface{}{
        "error": logMsg,
        "request_id": rid, // リクエストIDも含める
    })
}

実際の運用での効果

普段ログ調査を行う中で、以下のような便利さを感じています。

  1. エラー調査の効率化

    • 関連するログを即座に収集できる
    • エラーの発生した文脈を正確に把握できる
  2. 予期せぬエラーへの対応

    • 本番環境で予期せぬエラーが発生した場合でも、リクエストIDを使って状況を正確に理解できる
    • 修正すべき箇所の特定がしやすい
  3. パフォーマンスの分析

    • 特定のリクエストの処理時間が長い場合、そのリクエストIDを元に詳細な分析が可能
    • ボトルネックの特定がしやすい

まとめ

リクエストIDを使ったロギングの仕組みにより、シンプルでも効果的なリクエスト追跡が実現できています。
皆さんもぜひ、業務の開発やご自身のプロジェクトでリクエスト追跡の仕組みを試してみてください。

Discussion