goでSQLのquery logを出力させるのにsimukti/sqldb-loggerが便利かもしれない

github.com

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用のアダプターを使ってみることにする。

github.com

コードに以下のような変更を加える。せっかくなので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 {

実行結果は以下の様な感じになる。

zerologでの実行結果

何やらいろいろと出力された感じになってますね。

自作の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を打てば良い。

とはいえ、全てのサブパッケージごとにgo.modを作り、それ用のreleaseを打つというのも面倒な気もする。

sql/database以外のライブラリでも

github.com

例えば、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

gist


  1. ちなみにgorpは対応していたはず

  2. ところでmapを受け取るインターフェイスは好きではないかもしれない。順序が崩れるので。

  3. build時に使われたものしかバイナリには含まれないので、バイナリのサイズ自体には影響がない。ただし、依存パッケージではあるのでgo get時にdownloadされてしまう。

  4. 名前はまだOpen Telemetryではなさそう。あと結構調整が必要そうだった感覚があった。viewerに擬えて良い感じになるように調整が必要そう。GCP関連のスタックを使っている場合には便利かもしれない。