Synamon’s Engineer blog

Synamonはリアルとデジタルの融合を加速させるため、メタバース領域で法人向けにサービス提供を行うテックカンパニーです。現在開発を進めている「メタバース総合プラットフォーム」をはじめ、メタバース市場の発展に向けた事業展開を行っています。このブログでは、メタバース技術とその周辺の技術、開発全般に関してエンジニアがお話しします。

【Golang】GinのログをカスタマイズしてリクエストIDを追加する

こんにちは、エンジニアのクロ(@kro96_xr)です。バックエンドを中心にフロントエンドやらインフラやら色々担当しています。

少し前にタイトルの件について調べていたのですが、あまりまとまった記事がなさそうだったのでまとめることにしました。
もし本記事の内容に間違っている記述や不適切な記述がある場合にはコメントやTwitterDMなどでお知らせいただけると幸いです。

Ginのデフォルトログ設定について

まず、カスタマイズする前にGinのデフォルトのログ設定がどうなっているかを確認します。

巷のGinの入門記事などを読むと、まずgin.Default()を呼ぶように書かれています。下記がよくある例かと思います。

package main

import (
    "github.com/gin-gonic/gin"
)

func main() {
    r := gin.Default() // これ
    r.GET("/hello", func(c *gin.Context) {
        c.JSON(200, gin.H{"message": "Hello World!"})
    })
    r.Run()
}

このgin.Default()関数の実装を確認するとgin.New()でインスタンスを生成した後、Logger()Recovery()というMiddlewareを使用していることがわかります。

// Default returns an Engine instance with the Logger and Recovery middleware already attached.
func Default() *Engine {
    debugPrintWARNINGDefault()
    engine := New()
    engine.Use(Logger(), Recovery())
    return engine
}

というわけで、gin.Default()を使わず、gin.New()を使ってmiddewareをカスタマイズしてやればよさそうです。

ちなみにデフォルトだと下記のようなログになります。

[GIN] 2022/09/27 - 23:49:56 | 200 | 34.435µs | 172.23.0.1 | GET "/hello"

ロガーのカスタマイズについて

続いてロガーのカスタマイズです。

ロガーの実体はmiddlewareであることがわかりましたので、自分でカスタムミドルウェアを実装してもいいのですが、ginにはgin.LoggerWithConfig(conf LoggerConfig)というコンフィグ付きでロガーを生成できる関数が用意されています。

LoggerConfigという構造体を確認するとカスタマイズできる項目はフォーマット、ライター、ログ出力をスキップするパスの設定のようです。今回はフォーマットの修正で事足りそうなのでこちらを修正していきます。

// LoggerConfig defines the config for Logger middleware.
type LoggerConfig struct {
    // Optional. Default value is gin.defaultLogFormatter
    Formatter LogFormatter

    // Output is a writer where logs are written.
    // Optional. Default value is gin.DefaultWriter.
    Output io.Writer

    // SkipPaths is an url path array which logs are not written.
    // Optional.
    SkipPaths []string
}

まずはカスタマイズしたLoggerConfigを返す関数を実装します。一瞬です。

func customLogger() gin.LoggerConfig {
    conf := gin.LoggerConfig{}
    conf.Formatter = customLogFormatter // 次に実装します
    return conf
}

次にcustomLogFormatterを作っていきます。一旦タイムスタンプの後に適当な文字列を追加してみましょう。

デフォルトのログのフォーマットを参考に実装(ほぼ丸コピ)していきます。

var customLogFormatter = func(param gin.LogFormatterParams) string {
    var statusColor, methodColor, resetColor string
    if param.IsOutputColor() {
        statusColor = param.StatusCodeColor()
        methodColor = param.MethodColor()
        resetColor = param.ResetColor()
    }

    if param.Latency > time.Minute {
        param.Latency = param.Latency.Truncate(time.Second)
    }

        // ここでフォーマットを決めている
    return fmt.Sprintf("[GIN] %v| %s |%s %3d %s| %13v | %15s |%s %-7s %s %#v\n%s",
        param.TimeStamp.Format("2006/01/02 - 15:04:05"),
        "ここに追加", // ここに追加
        statusColor,
        param.StatusCode,
        resetColor,
        param.Latency,
        param.ClientIP,
        methodColor,
        param.Method,
        resetColor,
        param.Path,
        param.ErrorMessage,
    )
}

最後に作成したgin.LoggerWithConfig(conf LoggerConfig)を使用するためにr.Use(gin.LoggerWithConfig(customLogger()))を追加します。

package main

import (
    "fmt"
    "time"
    
    "github.com/gin-gonic/gin"
)

// ログフォーマッタ
var customLogFormatter = func(param gin.LogFormatterParams) string {
    var statusColor, methodColor, resetColor string
    if param.IsOutputColor() {
        statusColor = param.StatusCodeColor()
        methodColor = param.MethodColor()
        resetColor = param.ResetColor()
    }

    if param.Latency > time.Minute {
        param.Latency = param.Latency.Truncate(time.Second)
    }

    // ここでフォーマットを決めている
    return fmt.Sprintf("[GIN] %v| %s |%s %3d %s| %13v | %15s |%s %-7s %s %#v\n%s",
        param.TimeStamp.Format("2006/01/02 - 15:04:05"),
        "ここに追加", // ここに追加
        statusColor,
        param.StatusCode,
        resetColor,
        param.Latency,
        param.ClientIP,
        methodColor,
        param.Method,
        resetColor,
        param.Path,
        param.ErrorMessage,
    )
}

// カスタムログ
func customLogger() gin.LoggerConfig {
    conf := gin.LoggerConfig{}
    conf.Formatter = customLogFormatter
    return conf
}

func main() {
    r := gin.New()
    r.Use(gin.LoggerWithConfig(customLogger())) // ここ
    r.Use(gin.Recovery()) // お忘れなく

    r.GET("/hello", func(c *gin.Context) {
        c.JSON(200, gin.H{"message": "Hello World!"})
    })
    r.Run()
}

これで下記のようなログになります。

[GIN] 2022/09/27 - 23:52:26| ここに追加 | 200 | 50.529µs | 172.23.0.1 | GET "/hello"

リクエスト毎にUUIDを付与してみる

次にリクエストに対してUUID(リクエストID)を発行してログに追加していきます。

今回は下記のモジュールを使用します。

github.com

githubのREADMEのExampleの通りに実装してみます。こちらもmiddlewareとして設定するだけなので簡単ですね。

func main() {
    r := gin.New()
    r.Use(requestid.New()) // ここ
    r.Use(gin.LoggerWithConfig(customLogger()))
    r.Use(gin.Recovery())

    r.GET("/hello", func(c *gin.Context) {
        c.JSON(200, gin.H{"message": "Hello World!"})
    })
    r.Run()
}

上記実装でレスポンスヘッダにリクエストIDが付与されます。

あとはcustomLogFormatterの中でIDを取得すれば…と思いますが、gin.LogFormatterParamsは*gin.Context()をもっていないので取得できません。

 return fmt.Sprintf("[GIN] %v| %s |%s %3d %s| %13v | %15s |%s %-7s %s %#v\n%s",
        param.TimeStamp.Format("2006/01/02 - 15:04:05"),
        requestId.Get(c), //こうすればできそうだけどできない
        statusColor,
        param.StatusCode,
        resetColor,
        param.Latency,
        param.ClientIP,
        methodColor,
        param.Method,
        resetColor,
        param.Path,
        param.ErrorMessage,
    )

仕方がないのでドキュメントを確認すると、カスタムハンドラ(呼び方はよくわからない)を実装できることがわかります。

それを利用して、下記のようにリクエストヘッダに追加するようにします。

package main

import (
    "fmt"
    "time"
    
    "github.com/gin-gonic/gin"
)

// ログフォーマッタ
var customLogFormatter = func(param gin.LogFormatterParams) string {
    var statusColor, methodColor, resetColor string
    if param.IsOutputColor() {
        statusColor = param.StatusCodeColor()
        methodColor = param.MethodColor()
        resetColor = param.ResetColor()
    }

    if param.Latency > time.Minute {
        param.Latency = param.Latency.Truncate(time.Second)
    }

    return fmt.Sprintf("[GIN] %v| %s |%s %3d %s| %13v | %15s |%s %-7s %s %#v\n%s",
        param.TimeStamp.Format("2006/01/02 - 15:04:05"),
        param.Request.Header.Get("X-Request-Id"), // 修正
        statusColor,
        param.StatusCode,
        resetColor,
        param.Latency,
        param.ClientIP,
        methodColor,
        param.Method,
        resetColor,
        param.Path,
        param.ErrorMessage,
    )
}

// カスタムログ
func customLogger() gin.LoggerConfig {
    conf := gin.LoggerConfig{}
    conf.Formatter = customLogFormatter
    return conf
}

// カスタムハンドラを追加
func customRequestidHandler() requestid.Handler {
    return func(c *gin.Context, requestID string) {
        c.Request.Header.Set("X-Request-Id", requestID)
    }
}

func main() {
    r := gin.New()
    r.Use(requestid.New(customRequestidHandler())) // 修正
    r.Use(gin.LoggerWithConfig(customLogger()))
    r.Use(gin.Recovery())

    r.GET("/hello", func(c *gin.Context) {
        c.JSON(200, gin.H{"message": "Hello World!"})
    })
    r.Run()
}

こうすることで、無事ログにリクエストIDを残すことができました。下記のようにログに出力されます。

もちろん他の場所にリクエストID込みのログを仕込むことも可能です。これで大量のログの中からgrepなりなんなりで調査したいログを拾い上げることができますね。

[GIN] 2022/09/28 - 00:41:36| c6500909-bd3c-409e-8ff4-1236da298019 | 200 | 49.806µs | 172.23.0.1 | GET "/hello"

おまけ:特定のAPIのログを残さないようにする

同様のカスタマイズで特定のAPのログを残さないようにカスタマイズすることも可能です。
ALBを使っているとターゲットグループに対するヘルスチェックで特定のAPIを一定間隔で叩いたりするかと思います。死活監視のログで他のログが埋もれてしまうのは本末転倒ですが、この方法でスキップすることができます。

func customLogger() gin.LoggerConfig {
    conf := gin.LoggerConfig{
            SkipPaths: []string{"/healthcheck"} // 追加
        }
    conf.Formatter = customLogFormatter
    return conf
}

おわりに

今回はGinのログのカスタマイズについて調査した結果をまとめてみました。これでアプリケーション間で横断的なログ調査が出来るようになりますね。 何かの参考になれば幸いです。