こんにちは、エンジニアのクロ(@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を使用していることがわかります。
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という構造体を確認するとカスタマイズできる項目はフォーマット、ライター、ログ出力をスキップするパスの設定のようです。今回はフォーマットの修正で事足りそうなのでこちらを修正していきます。
type LoggerConfig struct {
Formatter LogFormatter
Output io.Writer
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のログのカスタマイズについて調査した結果をまとめてみました。これでアプリケーション間で横断的なログ調査が出来るようになりますね。
何かの参考になれば幸いです。
