🐥

Gin + slogで構造化ログ実装

に公開
Go
slog
tech

はじめに

Ginで開発をしているがGinの提供するログが構造化されていないので、別のloggerを利用してログを出すことにした

ちなみにzap→slogに移行したので

Ginのログ

Ginでは gin.Default() を使うことで、デフォルトのミドルウェアが自動的に設定されます

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

gin.Default()の中身

gin.Default() の実装を見ると、以下のようになっています

func Default() *Engine {
    debugPrintWARNINGDefault()
    engine := New()
    engine.Use(Logger(), Recovery()) // こいつでミドルウェアとしてLogger と Recoverを読んでいる
    return engine
}

Logger()ミドルウェアの動作

Logger()ミドルウェアは各HTTPリクエストに対して以下の情報をログ出力します

[GIN] 2024/09/16 - 15:30:45 | 200 |     123.456µs |             ::1 | GET      "/"

このログフォーマットには以下が含まれる：

  • タイムスタンプ
  • ステータスコード
  • レスポンス時間
  • クライアントIP
  • HTTPメソッド
  • リクエストパス

問題点としてGinのログが構造化されてないです
見にくいので構造化していきたい

構造化されたログを出力するには

今回は slog を利用する前提で実装していきます

slog の選定理由としては go の標準パッケージとして Go 1.21 から導入されており、外部依存なしで構造化ログが利用できるのでこれを利用します

プロジェクト構造

実際のプロジェクトでは以下のような構造でslogを実装します。

backend/
├── cmd/api/main.go
├── internal/
│   ├── middleware/logger.go
│   └── http/routes.go

main.go

package main

import (
    "example.com/myapp/internal/http"
)

func main() {
    r := http.SetupRoutes()
    r.Run(":8080")
}

routes.go

package http

import (
    "github.com/gin-gonic/gin"
    "example.com/myapp/internal/middleware"
)

func SetupRoutes() *gin.Engine {
    logger := middleware.NewLogger()

    r := gin.New()
    r.Use(middleware.Logger(logger))
    r.Use(gin.Recovery())

    // routes
    r.GET("/health", healthHandler.GetHealth)

    return r
}

middleware/logger.go

NewLogger関数でslogロガーを初期化し、Logger関数でGinのミドルウェアとして動作します。

package middleware

import (
    "log/slog"
    "os"
    "time"

    "github.com/gin-gonic/gin"
    "github.com/google/uuid"
)

func NewLogger() *slog.Logger {
    opts := &slog.HandlerOptions{
        Level: slog.LevelInfo,
    }
    handler := slog.NewJSONHandler(os.Stdout, opts)
    return slog.New(handler)
}

func Logger(l *slog.Logger) gin.HandlerFunc {
    return func(c *gin.Context) {
        // トレースIDを生成してコンテキストに設定
        traceID := uuid.New().String()
        c.Set("trace_id", traceID)

        start := time.Now()
        c.Next()

        // レスポンス時間を計算
        duration := time.Since(start)

        // ログレベルを決定（4xx, 5xxはwarn、その他はinfo）
        status := c.Writer.Status()
        var level slog.Level
        if status >= 400 {
            level = slog.LevelWarn
        } else {
            level = slog.LevelInfo
        }

        // 必要最小限の情報のみログ出力（トレースID含む）
        l.Log(c.Request.Context(), level, "HTTP",
            slog.String("trace_id", traceID),
            slog.Int("status", status),
            slog.String("method", c.Request.Method),
            slog.String("path", c.Request.URL.Path),
            slog.String("duration", duration.String()),
        )
    }
}

パニック処理について

Ginの標準的な gin.Recovery() を使用しています。これにより、パニックが発生した際の基本的な処理が行われます。

r.Use(gin.Recovery())

構造化ログの出力例

上記の実装により、以下のような構造化されたJSONログが出力されます。

{
  "time": "2024-09-19T15:30:45.123456789+09:00",
  "level": "INFO",
  "msg": "HTTP",
  "trace_id": "abc123-def456-ghi789-jkl012",
  "status": 200,
  "method": "GET",
  "path": "/",
  "duration": "123.456µs"
}

まとめ

Gin の logger を利用しないで slog や zap を利用するケースは他の記事もあるぐらいかなり多い印象で、似た実装はかなり多くありました。

しかし Gin の Logger を自作することでもいい感じに構造化したログを出すこともできるのでGo の logger を検討する際に参考になればと思います

Discussion