🐁

GORM の Logger に slog を設定する備忘録

2024/08/18に公開

GORM

slog

tech

はじめに

Go 1.21 で追加された slog とようやく向き合い始めました。

https://pkg.go.dev/log/slog

コンテキストの連れ回し方などもわかってきたのでそろそろ本格的に使い始めようかなと思います。
そんななか GORM の Logger で slog 対応したいなって思った備忘録です。

GORM

GORM は Go 言語の ORM ライブラリでありおそらく最も Go 言語で使われている ORM ライブラリです。

https://gorm.io/ja_JP/

https://github.com/go-gorm/gorm

Logger

GORM の公式ドキュメントに Logger に関する記載があります。

https://gorm.io/ja_JP/docs/logger.html

公式ドキュメントによると独自の Logger を定義するには以下のインターフェイスを実装する必要があるそうです。

type Interface interface {
    LogMode(LogLevel) Interface
    Info(context.Context, string, ...interface{})
    Warn(context.Context, string, ...interface{})
    Error(context.Context, string, ...interface{})
    Trace(ctx context.Context, begin time.Time, fc func() (sql string, rowsAffected int64), err error)
}

実装

インターフェイスを実装するにあたり GORM の default logger を参考にします。
最終的に以下の実装をしました。
（最近のマイブームで gorm + x = gormx というようなパッケージの命名をしてます。）

package gormx

import (
	"context"
	"fmt"
	"log/slog"
	"time"

	"gorm.io/gorm/logger"
)

var _ logger.Interface = (*Logger)(nil) // インターフェースを実装するためのおまじない

type Logger struct {
	LogLevel      logger.LogLevel
	SlowThreshold time.Duration
}

// LogMode implements logger.Interface.
func (log *Logger) LogMode(level logger.LogLevel) logger.Interface {
	log.LogLevel = level
	return log
}

// Info implements logger.Interface.
func (log *Logger) Info(ctx context.Context, msg string, data ...interface{}) {
	if log.LogLevel >= logger.Info {
		slog.InfoContext(ctx, fmt.Sprintf(msg, data...))
	}
}

// Warn implements logger.Interface.
func (log *Logger) Warn(ctx context.Context, msg string, data ...interface{}) {
	if log.LogLevel >= logger.Warn {
		slog.WarnContext(ctx, fmt.Sprintf(msg, data...))
	}
}

// Error implements logger.Interface.
func (log *Logger) Error(ctx context.Context, msg string, data ...interface{}) {
	if log.LogLevel >= logger.Error {
		slog.ErrorContext(ctx, fmt.Sprintf(msg, data...))
	}
}

// default logger をなんとなく模倣
// Trace implements logger.Interface.
func (log *Logger) Trace(ctx context.Context, begin time.Time, fc func() (sql string, rowsAffected int64), err error) {
	if log.LogLevel <= logger.Silent {
		return
	}
	elapsed := time.Since(begin)
	sql, rows := fc()
	switch {
	case err != nil && log.LogLevel >= logger.Error:
		if rows == -1 {
			slog.ErrorContext(ctx, fmt.Sprintf("[%.3fms] [rows:%s] %s", float64(elapsed.Nanoseconds())/1e6, "-", sql), slog.String("error", err.Error()))
		} else {
			slog.ErrorContext(ctx, fmt.Sprintf("[%.3fms] [rows:%d] %s", float64(elapsed.Nanoseconds())/1e6, rows, sql), slog.String("error", err.Error()))
		}
	case elapsed > log.SlowThreshold && log.SlowThreshold != 0 && log.LogLevel >= logger.Warn:
		if rows == -1 {
			slog.WarnContext(ctx, fmt.Sprintf("[%.3fms] [rows:%s] %s", float64(elapsed.Nanoseconds())/1e6, "-", sql))
		} else {
			slog.WarnContext(ctx, fmt.Sprintf("[%.3fms] [rows:%d] %s", float64(elapsed.Nanoseconds())/1e6, rows, sql))
		}
	case log.LogLevel == logger.Info:
		if rows == -1 {
			slog.InfoContext(ctx, fmt.Sprintf("[%.3fms] [rows:%s] %s", float64(elapsed.Nanoseconds())/1e6, "-", sql))
		} else {
			slog.InfoContext(ctx, fmt.Sprintf("[%.3fms] [rows:%d] %s", float64(elapsed.Nanoseconds())/1e6, rows, sql))
		}
	}
}

導入

コンテキストがちゃんと伝播されていることを確認するために OpenTelemtry のトレースを連れ回してみます。

https://opentelemetry.io/

slog も以下のように拡張します。

package slogx

import (
	"context"
	"log/slog"

	"go.opentelemetry.io/otel/trace"

	"github.com/otakakot/sample-gorm-slog/internal/contextx"
)

var keys = []contextx.Key{
	contextx.UserIDKey,
}

type LogHandler struct {
	slog.Handler
}

func New(
	handler slog.Handler,
) *LogHandler {
	return &LogHandler{
		Handler: handler,
	}
}

func (hdl *LogHandler) Handle(
	ctx context.Context,
	record slog.Record,
) error {
	span := trace.SpanFromContext(ctx)
	record.AddAttrs(slog.Attr{Key: "trace", Value: slog.StringValue(span.SpanContext().TraceID().String())})
	record.AddAttrs(slog.Attr{Key: "span", Value: slog.StringValue(span.SpanContext().SpanID().String())})
	for _, key := range keys {
		if val := ctx.Value(key); val != nil {
			record.AddAttrs(slog.Attr{Key: key.String(), Value: slog.AnyValue(val)})
		}
	}
	return hdl.Handler.Handle(ctx, record)
}

package contextx

type Key struct {
	name string
}

func (k Key) String() string {
	return k.name
}

var UserIDKey = Key{
	name: "uid",
}

OpenTelemtry と slog を以下のように設定します。

var tracer = otel.Tracer("gorm")

func init() {
	// TraceID と SpanID をログに出力するために設定
	provider := trace.NewTracerProvider()
	otel.SetTracerProvider(provider)
	// slog の設定
	log := slog.New(slogx.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{})))
	slog.SetDefault(log)
	slog.SetLogLoggerLevel(slog.LevelInfo)
}

コードでこれらの設定を反映して GORM を実行するコードは以下になります。

func main() {
	ctx, span := tracer.Start(context.Background(), "main")
	defer span.End()
	dsn := "postgres://postgres:postgres@localhost:5432/postgres?sslmode=disable" // ローカルで起動していること前提
	db, err := gorm.Open(postgres.Open(dsn), &gorm.Config{
		Logger: &gormx.Logger{
			LogLevel:      logger.Info,          // ログレベルの設定
			SlowThreshold: 5 * time.Millisecond, // スロークエリの閾値
		},
	})
	if err != nil {
		panic("failed to connect database. error: " + err.Error())
	}
	user := &User{}
	if err := db.WithContext(ctx).Create(user).Error; err != nil {
		panic("failed to create user. error: " + err.Error())
	}
	ctx = context.WithValue(ctx, contextx.UserIDKey, user.ID)
	found := &User{
		Model: gorm.Model{
			ID: user.ID,
		},
	}
	ctx, span = tracer.Start(ctx, "find")
	defer span.End()
	if err := db.WithContext(ctx).First(found).Error; err != nil {
		panic("failed to find user. error: " + err.Error())
	}
	ctx, span = tracer.Start(ctx, "delete")
	defer span.End()
	if err := db.WithContext(ctx).Delete(found).Error; err != nil {
		panic("failed to delete user. error: " + err.Error())
	}
	ctx, span = tracer.Start(ctx, "unscoped_delete")
	defer span.End()
	if err := db.WithContext(ctx).Unscoped().Delete(found).Error; err != nil {
		panic("failed to unscoped delete user. error: " + err.Error())
	}
	fu := &User{
		Model: gorm.Model{
			ID: user.ID,
		},
	}
	ctx, span = tracer.Start(ctx, "not_found")
	defer span.End()
	db.WithContext(ctx).First(fu)
}

type User struct {
	gorm.Model
}

上記コードを実行すると以下のログが出力されます。
これらはすべて GORM に設定した slog により出力されています。

{"time":"2024-08-18T13:42:17.80843+09:00","level":"WARN","msg":"[6.079ms] [rows:1] INSERT INTO \"users\" (\"created_at\",\"updated_at\",\"deleted_at\") VALUES ('2024-08-18 13:42:17.804','2024-08-18 13:42:17.804',NULL) RETURNING \"id\"","trace":"79ae90e58bfe595ffc539574d2f3c20f","span":"55fdd851fe1bff99"}
{"time":"2024-08-18T13:42:17.809917+09:00","level":"INFO","msg":"[1.444ms] [rows:1] SELECT * FROM \"users\" WHERE \"users\".\"deleted_at\" IS NULL AND \"users\".\"id\" = 29 ORDER BY \"users\".\"id\" LIMIT 1","trace":"79ae90e58bfe595ffc539574d2f3c20f","span":"b726eddaf9fb07de","uid":29}
{"time":"2024-08-18T13:42:17.812084+09:00","level":"INFO","msg":"[2.145ms] [rows:1] UPDATE \"users\" SET \"deleted_at\"='2024-08-18 13:42:17.81' WHERE \"users\".\"id\" = 29 AND \"users\".\"deleted_at\" IS NULL","trace":"79ae90e58bfe595ffc539574d2f3c20f","span":"98cced3900df7679","uid":29}
{"time":"2024-08-18T13:42:17.813614+09:00","level":"INFO","msg":"[1.484ms] [rows:1] DELETE FROM \"users\" WHERE \"users\".\"id\" = 29","trace":"79ae90e58bfe595ffc539574d2f3c20f","span":"df7e990688e01ce4","uid":29}
{"time":"2024-08-18T13:42:17.814166+09:00","level":"ERROR","msg":"[0.512ms] [rows:0] SELECT * FROM \"users\" WHERE \"users\".\"deleted_at\" IS NULL AND \"users\".\"id\" = 29 ORDER BY \"users\".\"id\" LIMIT 1","error":"record not found","trace":"79ae90e58bfe595ffc539574d2f3c20f","span":"73921c8084b43962","uid":29}

トレースIDもちゃんと伝播できてますね。

おわりに

案外簡単に GORM に slog を設定することができました。

今回実装したコードは以下に置いておきます。

はじめに

GORM

Logger

実装

導入

おわりに

Discussion