GORMでSQL文を確認する方法【Debug()とLogMode・v1/v2対応】

Dec 5, 202210分で読めるテック

GORMを使ってDBの処理を書いていると、「本当にこのSQL文が実行されているのか」と確認したくなる場面があります。go run main.go は正常終了するのに意図しない結果になっていた、という経験から、SQL文をコンソールに出力して確認できる2つの方法をまとめました。

今回使用したサンプルコードはGitHubに置いてあります。

GitHub - isaka1022/gorm-debug-sample

Contribute to isaka1022/gorm-debug-sample development by creating an account on GitHub.

GitHub

前提: どんな状況か

まず、GORMでDB処理を書いた基本的なコードを確認します。

package main

import (
	"log"

	"github.com/joho/godotenv"
	"github.com/kelseyhightower/envconfig"
	"gorm.io/driver/mysql"
	"gorm.io/gorm"
)

type Product struct {
	gorm.Model
	Code  string
	Price uint
}

type dbConfig struct {
	Username string
	Userpass string
	Host     string
	Port     string
	Name     string
}

func main() {
	err := godotenv.Load(".env")
	if err != nil {
		panic("Error loading .env file")
	}

	var config dbConfig
	err = envconfig.Process("db", &config)
	if err != nil {
		log.Fatal(err.Error())
	}

	dsn := config.Username + ":" + config.Userpass + "@(" + config.Host + ":" + config.Port + ")/" + config.Name + "?charset=utf8&parseTime=true"
	db, err := gorm.Open(mysql.Open(dsn), &gorm.Config{})
	if err != nil {
		panic("failed to connect database")
	}

	db.AutoMigrate(&Product{})
	db.Create(&Product{Code: "D42", Price: 100})

	var product Product
	db.First(&product)

	db.Model(&product).Update("Price", 200)
	db.Model(&product).Updates(Product{Price: 200, Code: "F42"})

	db.Delete(&product, product.ID)
}

これを実行しても、出力は何もありません。

$ go run main.go
$

処理は通っているのですが、どんなSQLが走ったか分からない状態です。意図しないデータが残っていたときのデバッグがかなり辛くなります。

方法1: `Debug()` で単一クエリのSQLを確認する

特定の処理だけSQLを確認したい場合は、メソッドチェーンに Debug() を追加します。

db.Debug().Create(&Product{Code: "D42", Price: 100})

これだけで、その処理で実行されたSQLが標準出力に表示されます。

$ go run main.go
2022/12/04 22:12:31 /Users/amane/sandbox/gorm-test/main.go:47
[8.092ms] [rows:1] INSERT INTO `products` (`created_at`,`updated_at`,`deleted_at`,`code`,`price`) VALUES ('2022-12-04 22:12:31.739','2022-12-04 22:12:31.739',NULL,'D42',100)
$

確認したいクエリが1つ2つの場合は、これが一番手軽です。

方法2: `LogMode(logger.Info)` で全クエリを追う

すべての処理にいちいち Debug() を追加するのは手間です。全体のSQLの流れをまとめて確認したいときは、DB接続後にロガーの設定を変更します。

db, err := gorm.Open(mysql.Open(dsn), &gorm.Config{})
if err != nil {
    panic("failed to connect database")
}
db.Logger = db.Logger.LogMode(logger.Info) // この行を追加

これで、以降のすべてのDB操作でSQL文が出力されるようになります。

$ go run main.go

2022/12/04 22:18:22 /Users/amane/sandbox/gorm-test/main.go:48
[1.094ms] [rows:-] SELECT DATABASE()

2022/12/04 22:18:22 /Users/amane/sandbox/gorm-test/main.go:48
[3.301ms] [rows:1] SELECT SCHEMA_NAME from Information_schema.SCHEMATA where SCHEMA_NAME LIKE 'sampledb_for_gorm%' ORDER BY SCHEMA_NAME='sampledb_for_gorm' DESC,SCHEMA_NAME limit 1

... （中略）

2022/12/04 22:18:22 /Users/amane/sandbox/gorm-test/main.go:49
[7.892ms] [rows:1] INSERT INTO `products` (`created_at`,`updated_at`,`deleted_at`,`code`,`price`) VALUES ('2022-12-04 22:18:22.625','2022-12-04 22:18:22.625',NULL,'D42',100)

2022/12/04 22:18:22 /Users/amane/sandbox/gorm-test/main.go:52
[2.450ms] [rows:1] SELECT * FROM `products` WHERE `products`.`deleted_at` IS NULL ORDER BY `products`.`id` LIMIT 1

2022/12/04 22:18:22 /Users/amane/sandbox/gorm-test/main.go:54
[8.584ms] [rows:1] UPDATE `products` SET `price`=200,`updated_at`='2022-12-04 22:18:22.635' WHERE `products`.`deleted_at` IS NULL AND `id` = 8

2022/12/04 22:18:22 /Users/amane/sandbox/gorm-test/main.go:55
[6.597ms] [rows:1] UPDATE `products` SET `updated_at`='2022-12-04 22:18:22.644',`code`='F42',`price`=200 WHERE `products`.`deleted_at` IS NULL AND `id` = 8

2022/12/04 22:18:22 /Users/amane/sandbox/gorm-test/main.go:57
[5.562ms] [rows:1] UPDATE `products` SET `deleted_at`='2022-12-04 22:18:22.65' WHERE `products`.`id` = 8 AND `products`.`id` = 8 AND `products`.`deleted_at` IS NULL

AutoMigrate が内部でどんなSQLを実行しているかまで全部見えます。初めてGORMを触る段階で全体の動きを把握するのにも役立ちます。

v1との違い

GORM v1 では db.LogMode(true) という設定でした。v2 で API が変わっているので、v1の記事を参考にするときは注意が必要です。

qiita.com/earl2/articles/e2ae573128d077cf088e

qiita.com

応用: 環境変数でログ出力を切り替える

開発中は常時ログを見たいけれど、本番環境では出力したくない、という場合は環境変数で分岐させると管理しやすくなります。

.env に設定を用意して:

DEBUG_MODE=true

Go側でその値を読んで分岐します:

if _, isDebugMode := os.LookupEnv("DEBUG_MODE"); isDebugMode {
    db.Logger = db.Logger.LogMode(logger.Info)
}

本番では DEBUG_MODE を設定しないか削除するだけで、SQL出力が止まります。本番環境でSQLが垂れ流しになるのを防げるので、習慣として入れておくと安心です。

さらに環境ごとにログレベルを細かく制御したい場合は:

if environment, _ := os.LookupEnv("ENVIRONMENT"); environment == "development" {
    db.Logger = db.Logger.LogMode(logger.Info)
}

のようにも書けます。

参考

GORMガイド

デベロッパーフレンドリーを目指した、Go言語のORMライブラリです。特徴フル機能ORM アソシエーション(Has One, Has Many, Belongs To, Many To Many, Polymorphism, Single-table inheritance) フック (Before/After Create/Save/Update/Del