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。
gist
httptest.ResponseRecorderを使っていてもRoundTripperを使いたい
時折、テスト中にRoundTripper (client.Transport) を挟んで良い結果を得ようと企む事がある。コレに対応可能なのがhttptest.Serverを利用した通信のときだけだと思っていたけれど。一手間加えるとRecorderを利用したテストでも対応可能な事に気づいたのでメモ。
Recorder, Server?
httptestを使ったhttp requestのテストを書くときには2つの方針がある
- Recorderを使ったもの
- Serverを使ったもの
前者は基本的にはnet/http.HandlerFuncなどを直接関数として利用するもの。後者は適当なポートでローカルに本物のサーバーを立てて通信を行うもの。前者はユニットテスト、後者は結合テストで使われる事が多い。
RoundTripperの利用
例えば以下の様な何の変哲もないHandlerがあるとする。hello worldを返すだけのもの。
func Handler(w http.ResponseWriter, r *http.Request) { fmt.Fprintf(w, "hello world"+r.URL.Query().Get("suffix")) }
このHandlerへのrequestに触りたい。とりあえず変更されることがわかれば良いのでquery stringの"suffix"を追加するようなRoundTripperを書いてみる。
// このRoundTripperを利用したい type AddSuffixQuery struct { Transport http.RoundTripper } func (t *AddSuffixQuery) RoundTrip(req *http.Request) (*http.Response, error) { // <url> -> <url>?suffix=!! q := req.URL.Query() q.Add("suffix", "!!") req.URL.RawQuery = q.Encode() tranport := t.Transport if tranport == nil { tranport = http.DefaultTransport } return tranport.RoundTrip(req) }
コレを使ったServerのテストはそのまますんなり書き下せる。hello worldではなくhello world!!が返るかどうかを確認すれば良い。
// TestUseTestServer テストサーバーを使う場合は本物の通信を行う。Transportを見てくれる。 func TestUseTestServer(t *testing.T) { ts := httptest.NewServer(http.HandlerFunc(Handler)) defer ts.Close() client := &http.Client{Transport: &AddSuffixQuery{}} res, err := client.Get(ts.URL) if err != nil { t.Fatalf("res: %+v", err) } if want, got := http.StatusOK, res.StatusCode; want != got { t.Errorf("status code\nwant\n\t%d\nbut\n\t%d", want, got) } got, _ := ioutil.ReadAll(res.Body) if want := "hello world!!"; want != string(got) { t.Errorf("body\nwant\n\t%+v\nbut\n\t%+v", want, string(got)) } }
レスポンスのstatusとbodyを確認しているだけのコード。OK。
PASS ok m/example_go5/02record 0.010s
Recorderの利用
通常Recorderを利用したコードは以下の様な形になる。このコードは先程定義したRoundTripperを利用していない。 これを利用する形に書き換えたい。
// TestUseRecord 通常のhttptest.Recorderを使う例 func TestUseRecord(t *testing.T) { rec := httptest.NewRecorder() req := httptest.NewRequest("", "http:", nil) Handler(rec, req) res := rec.Result() if want, got := http.StatusOK, res.StatusCode; want != got { t.Errorf("status code\nwant\n\t%d\nbut\n\t%d", want, got) } got, _ := ioutil.ReadAll(res.Body) if want := "hello world"; want != string(got) { t.Errorf("body\nwant\n\t%+v\nbut\n\t%+v", want, string(got)) } }
呼び出すだけなのでコレでおしまい。関数を直接呼び出すのでrequestのContextに詰め込んだ値がそのままHandlerで使えたりと便利なことがあったりする。今回も利用したかったRoundTripperの効果を得るだけ(query stringの追加だけ)なら直接渡すrequestに変更を加えれば良いだけなので、不要かもしれないが、この記事の本題としてはRoundTripperの利用を強制したいということだった。
実はRoundTripperをネストした構造にすることは概ねmiddlewareのように機能する。そして最も下層の処理はnet/http.Transport
の実装ということになる。これをHandlerを呼ぶものに差し替えてあげれば良い。そんなわけで以下のようなRoundTripperのHandlerTripperを定義してあげて使ってあげれば良い1。
type HandlerTripper struct { Rec *httptest.ResponseRecorder Handler http.HandlerFunc } func (t *HandlerTripper) RoundTrip(req *http.Request) (*http.Response, error) { t.Handler(t.Rec, req) return t.Rec.Result(), nil } // TestUseRecordWithTransport そういうTransportを書いてあげれば済む話だ func TestUseRecordWithTransport(t *testing.T) { rec := httptest.NewRecorder() req := httptest.NewRequest("", "http:", nil) transport := &AddSuffixQuery{ Transport: &HandlerTripper{Rec: rec, Handler: Handler}, } res, err := transport.RoundTrip(req) if err != nil { t.Fatalf("res: %+v", err) } if want, got := http.StatusOK, res.StatusCode; want != got { t.Errorf("status code\nwant\n\t%d\nbut\n\t%d", want, got) } got, _ := ioutil.ReadAll(res.Body) if want := "hello world!!"; want != string(got) { t.Errorf("body\nwant\n\t%+v\nbut\n\t%+v", want, string(got)) } }
テストも通る。
$ go test PASS ok m/example_go5/02record 0.013s
RoundTripperを使えると何が嬉しいの?
直近での用途を考えてみると、例えばweb APIの呼び出しのテストに失敗したときだけ、あるいはgo test -v
で実行したときだけ、request/responseのtraceを表示するRoundTripperを追加することができたりする2。
まとめ
- RecorderでもServerでもRoundTripperを使える
- こういう一手間のためのライブラリが欲しいかも
gist
-
直接Recorderを渡す必要もなくて、下層のRoundTripperの中で作って使う形にしても良い。実は以前の記事でその様な実装を書いていた。https://pod.hatenablog.com/entry/2020/08/28/212325。↩
-
こういう失敗したときだけの出力を作るときに
t.Logf()
を使って書き出すのが便利。↩