Merge pull request #1005 from go-kivik/queryLogging

Optionally log queries in tests

x/sqlite/common_test.go

@@ -29,6 +29,7 @@ import (
 
 	"github.com/google/go-cmp/cmp"
 
+	"github.com/go-kivik/kivik/v4"
 	"github.com/go-kivik/kivik/v4/driver"
 	"github.com/go-kivik/kivik/v4/int/mock"
 )
@@ -81,6 +82,18 @@ func (tdb *testDB) tDelete(docID string, options ...driver.Options) string { //n
 	return rev
 }
 
+type multiOptions []kivik.Option
+
+var _ kivik.Option = (multiOptions)(nil)
+
+func (o multiOptions) Apply(t interface{}) {
+	for _, opt := range o {
+		if opt != nil {
+			opt.Apply(t)
+		}
+	}
+}
+
 // newDB creates a new driver.DB instance backed by an in-memory SQLite database,
 // and registers a cleanup function to close the database when the test is done.
 func newDB(t *testing.T) *testDB {
@@ -104,7 +117,11 @@ func newDB(t *testing.T) *testDB {
 	d := drv{}
 	buf := &bytes.Buffer{}
 	logger := log.New(buf, "", 0)
-	client, err := d.NewClient(dsn, OptionLogger(logger))
+	options := OptionLogger(logger)
+	if os.Getenv("QUERY_LOG") != "" {
+		options = multiOptions{options, OptionQueryLogger(log.New(os.Stderr, "", 0))}
+	}
+	client, err := d.NewClient(dsn, options)
 	if err != nil {
 		t.Fatal(err)
 	}

x/sqlite/go.mod

@@ -9,6 +9,7 @@ require (
 	github.com/google/go-cmp v0.6.0
 	github.com/google/uuid v1.6.0
 	github.com/mitchellh/mapstructure v1.5.0
+	gitlab.com/flimzy/errsql v0.1.3
 	gitlab.com/flimzy/testy v0.14.0
 	golang.org/x/text v0.15.0
 	modernc.org/sqlite v1.29.8

x/sqlite/go.sum

@@ -66,6 +66,8 @@ github.com/valyala/bytebufferpool v1.0.0/go.mod h1:6bBcMArwyJ5K/AmCkWv1jt77kVWyC
 github.com/valyala/fasttemplate v1.2.1 h1:TVEnxayobAdVkhQfrfes2IzOB6o+z4roRkPF52WA1u4=
 github.com/valyala/fasttemplate v1.2.1/go.mod h1:KHLXt3tVN2HBp8eijSv/kGJopbvo7S+qRAEEKiv+SiQ=
 github.com/yuin/goldmark v1.4.13/go.mod h1:6yULJ656Px+3vBD8DxQVa3kxgyrAnzto9xy5taEt/CY=
+gitlab.com/flimzy/errsql v0.1.3 h1:XRjZhW6SVHwjuGo8Rm3EVedw95bmysEVuPnG9M68V8I=
+gitlab.com/flimzy/errsql v0.1.3/go.mod h1:8tGMnnsTD13xJV3bSstTmu93kE25qRNEFiHVyFWdY4s=
 gitlab.com/flimzy/testy v0.14.0 h1:2nZV4Wa1OSJb3rOKHh0GJqvvhtE03zT+sKnPCI0owfQ=
 gitlab.com/flimzy/testy v0.14.0/go.mod h1:m3aGuwdXc+N3QgnH+2Ar2zf1yg0UxNdIaXKvC5SlfMk=
 golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w=

x/sqlite/logging.go

@@ -13,7 +13,13 @@
 package sqlite
 
 import (
+	"database/sql"
+	"database/sql/driver"
+	"fmt"
 	"log"
+	"strings"
+
+	"gitlab.com/flimzy/errsql"
 
 	"github.com/go-kivik/kivik/v4"
 )
@@ -36,3 +42,81 @@ func (o optionLogger) Apply(target interface{}) {
 func OptionLogger(logger *log.Logger) kivik.Option {
 	return optionLogger{Logger: logger}
 }
+
+// connector is used temporarily on startup, to connect to a database, and
+// to possibly switch to the errsql driver if query logging is enabled.
+type connector struct {
+	dsn         string
+	queryLogger *log.Logger
+}
+
+func tx(e *errsql.Event) string {
+	if e.InTransaction {
+		return " (tx)"
+	}
+	return ""
+}
+
+func args(a []driver.NamedValue) string {
+	result := make([]string, 0, len(a))
+	for _, arg := range a {
+		name := arg.Name
+		if name == "" {
+			name = fmt.Sprintf("$%d", arg.Ordinal)
+		}
+		result = append(result, fmt.Sprintf("%s=%v", name, arg.Value))
+	}
+	return strings.Join(result, ", ")
+}
+
+func (c *connector) Connect() (*sql.DB, error) {
+	db, err := sql.Open("sqlite", c.dsn)
+	if err != nil {
+		return nil, err
+	}
+	if c.queryLogger != nil {
+		drv := errsql.NewWithHooks(db.Driver(), &errsql.Hooks{
+			ErrorHook: func(e *errsql.Event, err error) error {
+				return fmt.Errorf("[%s.%s] %s", e.Entity, e.Method, err)
+			},
+			BeforePrepare: func(e *errsql.Event, query string) (string, error) {
+				c.queryLogger.Printf("[%s.%s]%s Preparing query:\n%s\n", e.Entity, e.Method, tx(e), query)
+				return query, nil
+			},
+			BeforePreparedQueryContext: func(e *errsql.Event, a []driver.NamedValue) ([]driver.NamedValue, error) {
+				c.queryLogger.Printf("[%s.%s]%s arguments:\n%s\n", e.Entity, e.Method, tx(e), args(a))
+				return a, nil
+			},
+			BeforeQueryContext: func(e *errsql.Event, query string, a []driver.NamedValue) (string, []driver.NamedValue, error) {
+				c.queryLogger.Printf("[%s.%s]%s Query:\n%s\narguments:\n%s\n", e.Entity, e.Method, tx(e), query, args(a))
+				return query, a, nil
+			},
+		})
+		cn, err := drv.OpenConnector(c.dsn)
+		if err != nil {
+			return nil, err
+		}
+		db = sql.OpenDB(cn)
+	}
+	_, err = db.Exec("PRAGMA foreign_keys = ON")
+	if err != nil {
+		return nil, err
+	}
+	return db, nil
+}
+
+type optionQueryLog struct {
+	*log.Logger
+}
+
+func (o optionQueryLog) Apply(target interface{}) {
+	if cn, ok := target.(*connector); ok {
+		cn.queryLogger = o.Logger
+	}
+}
+
+// OptionQueryLogger enables query logging for the SQLite driver. Query logs are
+// sent to the logger (see [OptionLogger]) at DEBUG level.
+func OptionQueryLogger(logger *log.Logger) kivik.Option {
+	return optionQueryLog{Logger: logger}
+}

x/sqlite/sqlite.go

@@ -42,16 +42,15 @@ var _ driver.Driver = (*drv)(nil)
 // NewClient returns a new SQLite client. dsn should be the full path to your
 // SQLite database file.
 func (drv) NewClient(dsn string, options driver.Options) (driver.Client, error) {
-	db, err := sql.Open("sqlite", dsn)
-	if err != nil {
-		return nil, err
-	}
-	_, err = db.Exec("PRAGMA foreign_keys = ON")
+	cn := &connector{dsn: dsn}
+	options.Apply(cn)
+	db, err := cn.Connect()
 	if err != nil {
 		return nil, err
 	}
 
 	c := &client{
+		dsn:    dsn,
 		db:     db,
 		logger: log.Default(),
 	}
@@ -61,6 +60,7 @@ func (drv) NewClient(dsn string, options driver.Options) (driver.Client, error)
 }
 
 type client struct {
+	dsn    string
 	db     *sql.DB
 	logger *log.Logger
 }