goでSQLのquery logを出力させるのにsimukti/sqldb-loggerが便利かもしれない
goでRDBMSを利用したコードを書いているときに、実際に発行されたqueryを知りたいことがある。特定のORMやquery builderでは対応していて何らかの設定を追加すると見えるものがあるが、そもそもquery logの出力に対応しているかどうかを判別することも、その設定方法を調べるのもめんどくさいことがある1。
そんなときに便利なパッケージを見つけたのでメモ。
query log無しでの実行
テキトーにSQLを使っているコードを探してくる。dockerなどを用意するのも面倒なのでsqliteを使うことにする。
こういうフィールドを持ったテーブルが欲しいらしい。
+--------------+---------+------+-----+---------+-------+ | Field | Type | Null | Key | Default | Extra | +--------------+---------+------+-----+---------+-------+ | number | int(11) | NO | PRI | NULL | | | squareNumber | int(11) | NO | | NULL | | +--------------+---------+------+-----+---------+-------+
insert.sql
CREATE TABLE squareNum ( number int PRIMARY KEY, squareNumber int );
以下の様なコードを実行する(go-sql-driver/mysql/wiki/Examplesから拝借)。
main00.go
package main import ( "database/sql" "fmt" "os" _ "github.com/mattn/go-sqlite3" ) func main() { driver := os.Getenv("DRIVER") if driver == "" { driver = "sqlite3" } dbSource := os.Getenv("DB") if dbSource == "" { dbSource = "sample.db" } db, err := sql.Open(driver, dbSource) if err != nil { panic(err.Error()) // Just for example purpose. You should use proper error handling instead of panic } defer db.Close() // Prepare statement for inserting data stmtIns, err := db.Prepare("INSERT INTO squareNum VALUES( ?, ? )") // ? = placeholder if err != nil { panic(err.Error()) // proper error handling instead of panic in your app } defer stmtIns.Close() // Close the statement when we leave main() / the program terminates // Prepare statement for reading data stmtOut, err := db.Prepare("SELECT squareNumber FROM squarenum WHERE number = ?") if err != nil { panic(err.Error()) // proper error handling instead of panic in your app } defer stmtOut.Close() // Insert square numbers for 0-24 in the database for i := 0; i < 25; i++ { _, err = stmtIns.Exec(i, (i * i)) // Insert tuples (i, i^2) if err != nil { panic(err.Error()) // proper error handling instead of panic in your app } } var squareNum int // we "scan" the result in here // Query the square-number of 13 err = stmtOut.QueryRow(13).Scan(&squareNum) // WHERE number = 13 if err != nil { panic(err.Error()) // proper error handling instead of panic in your app } fmt.Printf("The square number of 13 is: %d\n", squareNum) // Query another number.. 1 maybe? err = stmtOut.QueryRow(1).Scan(&squareNum) // WHERE number = 1 if err != nil { panic(err.Error()) // proper error handling instead of panic in your app } fmt.Printf("The square number of 1 is: %d\n", squareNum) }
実行結果はこちら。
$ go run main00.go The square number of 13 is: 169 The square number of 1 is: 1
なんとも寂しい。そしてどのようなqueryが実行されたかわからない。
sqldb-loggerを使う
それでは実際にsqldb-loggerを使ってみる。いくつかのロガーライブラリ用のアダプターが用意されているのでそれを使う。今回はzerolog用のアダプターを使ってみることにする。
コードに以下のような変更を加える。せっかくなのでJSONでの出力ではなくカラフルな出力になるようにした。
--- main00.go 2020-09-30 07:02:35.000000000 +0900 +++ main01.go 2020-09-30 07:11:17.000000000 +0900 @@ -6,6 +6,9 @@ "os" _ "github.com/mattn/go-sqlite3" + "github.com/rs/zerolog" + sqldblogger "github.com/simukti/sqldb-logger" + "github.com/simukti/sqldb-logger/logadapter/zerologadapter" ) func main() { @@ -18,12 +21,24 @@ dbSource = "sample.db" } + var db *sql.DB db, err := sql.Open(driver, dbSource) if err != nil { panic(err.Error()) // Just for example purpose. You should use proper error handling instead of panic } defer db.Close() + logger := zerolog.New( + zerolog.ConsoleWriter{Out: os.Stdout, NoColor: false}, + ) + // populate log pre-fields here before set to + db = sqldblogger.OpenDriver( + dbSource, + db.Driver(), + zerologadapter.New(logger), + // optional config... + ) + // Prepare statement for inserting data stmtIns, err := db.Prepare("INSERT INTO squareNum VALUES( ?, ? )") // ? = placeholder if err != nil {
実行結果は以下の様な感じになる。
何やらいろいろと出力された感じになってますね。
自作のlogger
READMEにも書いてあるけれど、以下のようなインターフェイスを満たしていれば良い2。
type Logger interface { Log(ctx context.Context, level Level, msg string, data map[string]interface{}) }
そんなわけで自分で標準ライブラリのlogパッケージで作ったロガーに対応してみる。
--- main00.go 2020-09-30 07:02:35.000000000 +0900 +++ main02.go 2020-09-30 07:24:16.000000000 +0900 @@ -1,13 +1,35 @@ package main import ( + "bytes" + "context" "database/sql" "fmt" + "log" "os" _ "github.com/mattn/go-sqlite3" + sqldblogger "github.com/simukti/sqldb-logger" ) +type logAdapter struct { + Logger *log.Logger +} + +func (a *logAdapter) Log( + ctx context.Context, + level sqldbLevel, + msg string, + data map[string]interface{}, +) { + var b bytes.Buffer + fmt.Fprintf(&b, "level:%s msg:%s", level, msg) + for k, v := range data { + fmt.Fprintf(&b, " %v:%v", k, v) + } + a.Logger.Println(b.String()) +} + func main() { driver := os.Getenv("DRIVER") if driver == "" { @@ -18,12 +40,19 @@ dbSource = "sample.db" } + var db *sql.DB db, err := sql.Open(driver, dbSource) if err != nil { panic(err.Error()) // Just for example purpose. You should use proper error handling instead of panic } defer db.Close() + db = sqldblogger.OpenDriver( + dbSource, + db.Driver(), + &logAdapter{Logger: log.New(os.Stdout, "**", 0)}, + ) + // Prepare statement for inserting data stmtIns, err := db.Prepare("INSERT INTO squareNum VALUES( ?, ? )") // ? = placeholder if err != nil {
できた。実行してみる。実行結果は以下。
go run main02.go **level:debug msg:Connect time:1601418265 duration:0.960381 conn_id:wk0siYeCE0YW888Y **level:info msg:PrepareContext duration:0.074679 conn_id:wk0siYeCE0YW888Y query:INSERT INTO squareNum VALUES( ?, ? ) stmt_id:sCoWQkqqe4YmwcmW time:1601418265 **level:info msg:PrepareContext time:1601418265 duration:0.041618 conn_id:wk0siYeCE0YW888Y query:SELECT squareNumber FROM squarenum WHERE number = ? stmt_id:sOkeMoGq0u_oy0O8 **level:info msg:StmtExecContext query:INSERT INTO squareNum VALUES( ?, ? ) args:[0 0] time:1601418265 duration:0.725621 conn_id:wk0siYeCE0YW888Y stmt_id:sCoWQkqqe4YmwcmW **level:info msg:StmtExecContext stmt_id:sCoWQkqqe4YmwcmW query:INSERT INTO squareNum VALUES( ?, ? ) args:[1 1] time:1601418265 duration:0.489481 conn_id:wk0siYeCE0YW888Y **level:info msg:StmtExecContext time:1601418265 duration:0.457999 conn_id:wk0siYeCE0YW88... **level:info msg:StmtExecContext query:INSERT INTO squareNum VALUES( ?, ? ) args:[23 529] time:1601418265 duration:0.67136 conn_id:wk0siYeCE0YW888Y stmt_id:sCoWQkqqe4YmwcmW **level:info msg:StmtExecContext time:1601418265 duration:0.766738 conn_id:wk0siYeCE0YW888Y stmt_id:sCoWQkqqe4YmwcmW query:INSERT INTO squareNum VALUES( ?, ? ) args:[24 576] **level:info msg:StmtQueryContext stmt_id:sOkeMoGq0u_oy0O8 query:SELECT squareNumber FROM squarenum WHERE number = ? args:[13] time:1601418265 duration:0.006216 conn_id:wk0siYeCE0YW888Y The square number of 13 is: 169 **level:info msg:StmtQueryContext stmt_id:sOkeMoGq0u_oy0O8 query:SELECT squareNumber FROM squarenum WHERE number = ? args:[1] time:1601418265 duration:0.00428 conn_id:wk0siYeCE0YW888Y The square number of 1 is: 1 **level:debug msg:StmtClose query:SELECT squareNumber FROM squarenum WHERE number = ? time:1601418265 duration:0.008333 conn_id:wk0siYeCE0YW888Y stmt_id:sOkeMoGq0u_oy0O8 **level:debug msg:StmtClose stmt_id:sCoWQkqqe4YmwcmW query:INSERT INTO squareNum VALUES( ?, ? ) time:1601418265 duration:0.004507 conn_id:wk0siYeCE0YW888Y
はい。
気になるところ
go.modがこういう感じ。zerologとlogrusとzapを依存が加わるのはどうなんだろう?と言う気持ちがちょっとあったりする。3
go.mod
module github.com/simukti/sqldb-logger go 1.13 require ( github.com/francoispqt/onelog v0.0.0-20190306043706-8c2bb31b10a4 github.com/rs/zerolog v1.19.0 github.com/sirupsen/logrus v1.6.0 github.com/stretchr/objx v0.2.0 // indirect github.com/stretchr/testify v1.6.0 go.uber.org/zap v1.15.0 gopkg.in/yaml.v3 v3.0.0-20200601152816-913338de1bd2 // indirect )
理由は、単純でそれぞれのロガーライブラリ用のアダプターを提供しているから。
$ tree -d . . └── logadapter ├── logrusadapter ├── onelogadapter ├── zapadapter └── zerologadapter 5 directories
一応1つのリポジトリで複数のパッケージを提供する方法自体は存在していて、v<major>.<minor>.<patch>
の代わりに <sub package>/v<major>.<minor>.<patch>
という形式のtagを打てば良い。
- https://github.com/golang/go/wiki/Modules#publishing-a-release
- https://github.com/golang/go/wiki/Modules#faqs--multi-module-repositories
とはいえ、全てのサブパッケージごとにgo.modを作り、それ用のreleaseを打つというのも面倒な気もする。
sql/database以外のライブラリでも
例えば、entなどは以下の様なコードを書けば良い。
package main import ( "bytes" "context" "database/sql" "encoding/json" "fmt" "log" "<my package>/ent" "<my package>/ent/user" "os" entsql "github.com/facebook/ent/dialect/sql" _ "github.com/mattn/go-sqlite3" sqldblogger "github.com/simukti/sqldb-logger" "golang.org/x/xerrors" ) type logger struct{} func (l *logger) Log(ctx context.Context, level sqldblogger.Level, msg string, data map[string]interface{}) { w := bytes.NewBufferString(fmt.Sprintf("\x1b[90m%s:%v", level, msg)) // todo: sort? for k, v := range data { fmt.Fprintf(w, "\t%s:%v", k, v) } fmt.Fprintf(w, "\x1b[0m") log.Println(w.String()) } // Open new connection and start stats recorder. func Open(dsn string) (*ent.Client, error) { inner, err := sql.Open("sqlite3", dsn) if err != nil { return nil, xerrors.Errorf("open: %w", err) } db := sqldblogger.OpenDriver(dsn, inner.Driver(), &logger{}) drv := entsql.OpenDB("sqlite3", db) return ent.NewClient(ent.Driver(drv)), nil } func main() { client, err := Open("file:ent?mode=memory&cache=shared&_fk=1") if err != nil { log.Fatalf("failed opening connection to sqlite: %v", err) } defer client.Close() ctx := context.Background() // Run the auto migration tool. if err := client.Schema.Create(ctx); err != nil { log.Fatalf("failed creating schema resources: %v", err) } }
query logを自前で出力するには
ちなみにquery logを自前で出力するには database/sql/driverを実装してあげれば良い。元のdriverをwrapするようなwrapperを書いてあげる。
例えばこんなかんじに。
より一般的にしたい場合にはopencensus用のtracerなどを使ってみると良いかもしれない(?)4。