Add SQL tracing via DENDRITE_TRACE_SQL (#968)

* Add SQL tracing via DENDRITE_TRACE_SQL

Add this to `internal/sqlutil` in preparation for #897

* Not entirely

appservice/storage/postgres/storage.go

@@ -21,6 +21,7 @@ import (
 
 	// Import postgres database driver
 	_ "github.com/lib/pq"
+	"github.com/matrix-org/dendrite/internal/sqlutil"
 	"github.com/matrix-org/gomatrixserverlib"
 )
 
@@ -35,7 +36,7 @@ type Database struct {
 func NewDatabase(dataSourceName string) (*Database, error) {
 	var result Database
 	var err error
-	if result.db, err = sql.Open("postgres", dataSourceName); err != nil {
+	if result.db, err = sqlutil.Open("postgres", dataSourceName); err != nil {
 		return nil, err
 	}
 	if err = result.prepare(); err != nil {

appservice/storage/sqlite3/storage.go

@@ -21,6 +21,7 @@ import (
 
 	// Import SQLite database driver
 	"github.com/matrix-org/dendrite/common"
+	"github.com/matrix-org/dendrite/internal/sqlutil"
 	"github.com/matrix-org/gomatrixserverlib"
 	_ "github.com/mattn/go-sqlite3"
 )
@@ -36,7 +37,7 @@ type Database struct {
 func NewDatabase(dataSourceName string) (*Database, error) {
 	var result Database
 	var err error
-	if result.db, err = sql.Open(common.SQLiteDriverName(), dataSourceName); err != nil {
+	if result.db, err = sqlutil.Open(common.SQLiteDriverName(), dataSourceName); err != nil {
 		return nil, err
 	}
 	if err = result.prepare(); err != nil {

clientapi/auth/storage/accounts/postgres/storage.go

@@ -22,6 +22,7 @@ import (
 
 	"github.com/matrix-org/dendrite/clientapi/auth/authtypes"
 	"github.com/matrix-org/dendrite/common"
+	"github.com/matrix-org/dendrite/internal/sqlutil"
 	"github.com/matrix-org/gomatrixserverlib"
 	"golang.org/x/crypto/bcrypt"
 
@@ -46,7 +47,7 @@ type Database struct {
 func NewDatabase(dataSourceName string, serverName gomatrixserverlib.ServerName) (*Database, error) {
 	var db *sql.DB
 	var err error
-	if db, err = sql.Open("postgres", dataSourceName); err != nil {
+	if db, err = sqlutil.Open("postgres", dataSourceName); err != nil {
 		return nil, err
 	}
 	partitions := common.PartitionOffsetStatements{}

clientapi/auth/storage/accounts/sqlite3/storage.go

@@ -23,6 +23,7 @@ import (
 
 	"github.com/matrix-org/dendrite/clientapi/auth/authtypes"
 	"github.com/matrix-org/dendrite/common"
+	"github.com/matrix-org/dendrite/internal/sqlutil"
 	"github.com/matrix-org/gomatrixserverlib"
 	"golang.org/x/crypto/bcrypt"
 
@@ -49,7 +50,7 @@ type Database struct {
 func NewDatabase(dataSourceName string, serverName gomatrixserverlib.ServerName) (*Database, error) {
 	var db *sql.DB
 	var err error
-	if db, err = sql.Open(common.SQLiteDriverName(), dataSourceName); err != nil {
+	if db, err = sqlutil.Open(common.SQLiteDriverName(), dataSourceName); err != nil {
 		return nil, err
 	}
 	partitions := common.PartitionOffsetStatements{}

clientapi/auth/storage/devices/postgres/storage.go

@@ -22,6 +22,7 @@ import (
 
 	"github.com/matrix-org/dendrite/clientapi/auth/authtypes"
 	"github.com/matrix-org/dendrite/common"
+	"github.com/matrix-org/dendrite/internal/sqlutil"
 	"github.com/matrix-org/gomatrixserverlib"
 )
 
@@ -38,7 +39,7 @@ type Database struct {
 func NewDatabase(dataSourceName string, serverName gomatrixserverlib.ServerName) (*Database, error) {
 	var db *sql.DB
 	var err error
-	if db, err = sql.Open("postgres", dataSourceName); err != nil {
+	if db, err = sqlutil.Open("postgres", dataSourceName); err != nil {
 		return nil, err
 	}
 	d := devicesStatements{}

clientapi/auth/storage/devices/sqlite3/storage.go

@@ -22,6 +22,7 @@ import (
 
 	"github.com/matrix-org/dendrite/clientapi/auth/authtypes"
 	"github.com/matrix-org/dendrite/common"
+	"github.com/matrix-org/dendrite/internal/sqlutil"
 	"github.com/matrix-org/gomatrixserverlib"
 
 	_ "github.com/mattn/go-sqlite3"
@@ -40,7 +41,7 @@ type Database struct {
 func NewDatabase(dataSourceName string, serverName gomatrixserverlib.ServerName) (*Database, error) {
 	var db *sql.DB
 	var err error
-	if db, err = sql.Open(common.SQLiteDriverName(), dataSourceName); err != nil {
+	if db, err = sqlutil.Open(common.SQLiteDriverName(), dataSourceName); err != nil {
 		return nil, err
 	}
 	d := devicesStatements{}

common/basecomponent/base.go

@@ -24,6 +24,7 @@ import (
 	"golang.org/x/crypto/ed25519"
 
 	"github.com/matrix-org/dendrite/common/keydb"
+	"github.com/matrix-org/dendrite/internal/sqlutil"
 	"github.com/matrix-org/gomatrixserverlib"
 	"github.com/matrix-org/naffka"
 
@@ -243,7 +244,7 @@ func setupNaffka(cfg *config.Dendrite) (sarama.Consumer, sarama.SyncProducer) {
 
 	uri, err := url.Parse(string(cfg.Database.Naffka))
 	if err != nil || uri.Scheme == "file" {
-		db, err = sql.Open(common.SQLiteDriverName(), string(cfg.Database.Naffka))
+		db, err = sqlutil.Open(common.SQLiteDriverName(), string(cfg.Database.Naffka))
 		if err != nil {
 			logrus.WithError(err).Panic("Failed to open naffka database")
 		}
@@ -253,7 +254,7 @@ func setupNaffka(cfg *config.Dendrite) (sarama.Consumer, sarama.SyncProducer) {
 			logrus.WithError(err).Panic("Failed to setup naffka database")
 		}
 	} else {
-		db, err = sql.Open("postgres", string(cfg.Database.Naffka))
+		db, err = sqlutil.Open("postgres", string(cfg.Database.Naffka))
 		if err != nil {
 			logrus.WithError(err).Panic("Failed to open naffka database")
 		}

common/keydb/postgres/keydb.go

@@ -17,11 +17,11 @@ package postgres
 
 import (
 	"context"
-	"database/sql"
 	"math"
 
 	"golang.org/x/crypto/ed25519"
 
+	"github.com/matrix-org/dendrite/internal/sqlutil"
 	"github.com/matrix-org/gomatrixserverlib"
 )
 
@@ -41,7 +41,7 @@ func NewDatabase(
 	serverKey ed25519.PublicKey,
 	serverKeyID gomatrixserverlib.KeyID,
 ) (*Database, error) {
-	db, err := sql.Open("postgres", dataSourceName)
+	db, err := sqlutil.Open("postgres", dataSourceName)
 	if err != nil {
 		return nil, err
 	}

common/keydb/sqlite3/keydb.go

@@ -17,12 +17,12 @@ package sqlite3
 
 import (
 	"context"
-	"database/sql"
 	"math"
 
 	"golang.org/x/crypto/ed25519"
 
 	"github.com/matrix-org/dendrite/common"
+	"github.com/matrix-org/dendrite/internal/sqlutil"
 	"github.com/matrix-org/gomatrixserverlib"
 
 	_ "github.com/mattn/go-sqlite3"
@@ -44,7 +44,7 @@ func NewDatabase(
 	serverKey ed25519.PublicKey,
 	serverKeyID gomatrixserverlib.KeyID,
 ) (*Database, error) {
-	db, err := sql.Open(common.SQLiteDriverName(), dataSourceName)
+	db, err := sqlutil.Open(common.SQLiteDriverName(), dataSourceName)
 	if err != nil {
 		return nil, err
 	}

federationsender/storage/postgres/storage.go

@@ -21,6 +21,7 @@ import (
 
 	"github.com/matrix-org/dendrite/common"
 	"github.com/matrix-org/dendrite/federationsender/types"
+	"github.com/matrix-org/dendrite/internal/sqlutil"
 )
 
 // Database stores information needed by the federation sender
@@ -35,7 +36,7 @@ type Database struct {
 func NewDatabase(dataSourceName string) (*Database, error) {
 	var result Database
 	var err error
-	if result.db, err = sql.Open("postgres", dataSourceName); err != nil {
+	if result.db, err = sqlutil.Open("postgres", dataSourceName); err != nil {
 		return nil, err
 	}
 	if err = result.prepare(); err != nil {

federationsender/storage/sqlite3/storage.go

@@ -23,6 +23,7 @@ import (
 
 	"github.com/matrix-org/dendrite/common"
 	"github.com/matrix-org/dendrite/federationsender/types"
+	"github.com/matrix-org/dendrite/internal/sqlutil"
 )
 
 // Database stores information needed by the federation sender
@@ -37,7 +38,7 @@ type Database struct {
 func NewDatabase(dataSourceName string) (*Database, error) {
 	var result Database
 	var err error
-	if result.db, err = sql.Open(common.SQLiteDriverName(), dataSourceName); err != nil {
+	if result.db, err = sqlutil.Open(common.SQLiteDriverName(), dataSourceName); err != nil {
 		return nil, err
 	}
 	if err = result.prepare(); err != nil {

go.mod

@@ -22,6 +22,7 @@ require (
 	github.com/matrix-org/util v0.0.0-20190711121626-527ce5ddefc7
 	github.com/mattn/go-sqlite3 v2.0.3+incompatible
 	github.com/nfnt/resize v0.0.0-20160724205520-891127d8d1b5
+	github.com/ngrok/sqlmw v0.0.0-20200129213757-d5c93a81bec6
 	github.com/opentracing/opentracing-go v1.1.0
 	github.com/pierrec/lz4 v2.5.0+incompatible // indirect
 	github.com/pkg/errors v0.9.1

go.sum

@@ -454,6 +454,8 @@ github.com/nbio/st v0.0.0-20140626010706-e9e8d9816f32 h1:W6apQkHrMkS0Muv8G/TipAy
 github.com/nbio/st v0.0.0-20140626010706-e9e8d9816f32/go.mod h1:9wM+0iRr9ahx58uYLpLIr5fm8diHn0JbqRycJi6w0Ms=
 github.com/nfnt/resize v0.0.0-20160724205520-891127d8d1b5 h1:BvoENQQU+fZ9uukda/RzCAL/191HHwJA5b13R6diVlY=
 github.com/nfnt/resize v0.0.0-20160724205520-891127d8d1b5/go.mod h1:jpp1/29i3P1S/RLdc7JQKbRpFeM1dOBd8T9ki5s+AY8=
+github.com/ngrok/sqlmw v0.0.0-20200129213757-d5c93a81bec6 h1:evlcQnJY+v8XRRchV3hXzpHDl6GcEZeLXAhlH9Csdww=
+github.com/ngrok/sqlmw v0.0.0-20200129213757-d5c93a81bec6/go.mod h1:E26fwEtRNigBfFfHDWsklmo0T7Ixbg0XXgck+Hq4O9k=
 github.com/onsi/ginkgo v1.6.0/go.mod h1:lLunBs/Ym6LB5Z9jYTR76FiuTmxDTDusOGeTQH+WWjE=
 github.com/onsi/ginkgo v1.7.0/go.mod h1:lLunBs/Ym6LB5Z9jYTR76FiuTmxDTDusOGeTQH+WWjE=
 github.com/onsi/ginkgo v1.8.0 h1:VkHVNpR4iVnU8XQR6DBm8BqYjN7CRzw+xKUbVVbbW9w=

internal/sqlutil/trace.go

@@ -0,0 +1,89 @@
+// Copyright 2020 The Matrix.org Foundation C.I.C.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+package sqlutil
+
+import (
+	"context"
+	"database/sql"
+	"database/sql/driver"
+	"fmt"
+	"io"
+	"os"
+	"strings"
+	"time"
+
+	"github.com/ngrok/sqlmw"
+	"github.com/sirupsen/logrus"
+)
+
+var tracingEnabled = os.Getenv("DENDRITE_TRACE_SQL") == "1"
+
+type traceInterceptor struct {
+	sqlmw.NullInterceptor
+}
+
+func (in *traceInterceptor) StmtQueryContext(ctx context.Context, stmt driver.StmtQueryContext, query string, args []driver.NamedValue) (driver.Rows, error) {
+	startedAt := time.Now()
+	rows, err := stmt.QueryContext(ctx, args)
+
+	logrus.WithField("duration", time.Since(startedAt)).WithField(logrus.ErrorKey, err).Debug("executed sql query ", query, " args: ", args)
+
+	return rows, err
+}
+
+func (in *traceInterceptor) StmtExecContext(ctx context.Context, stmt driver.StmtExecContext, query string, args []driver.NamedValue) (driver.Result, error) {
+	startedAt := time.Now()
+	result, err := stmt.ExecContext(ctx, args)
+
+	logrus.WithField("duration", time.Since(startedAt)).WithField(logrus.ErrorKey, err).Debug("executed sql query ", query, " args: ", args)
+
+	return result, err
+}
+
+func (in *traceInterceptor) RowsNext(c context.Context, rows driver.Rows, dest []driver.Value) error {
+	err := rows.Next(dest)
+	if err == io.EOF {
+		// For all cases, we call Next() n+1 times, the first to populate the initial dest, then eventually
+		// it will io.EOF. If we log on each Next() call we log the last element twice, so don't.
+		return err
+	}
+	cols := rows.Columns()
+	logrus.Debug(strings.Join(cols, " | "))
+
+	b := strings.Builder{}
+	for i, val := range dest {
+		b.WriteString(fmt.Sprintf("%v", val))
+		if i+1 <= len(dest)-1 {
+			b.WriteString(" | ")
+		}
+	}
+	logrus.Debug(b.String())
+	return err
+}
+
+// Open opens a database specified by its database driver name and a driver-specific data source name,
+// usually consisting of at least a database name and connection information. Includes tracing driver
+// if DENDRITE_TRACE_SQL=1
+func Open(driverName, dsn string) (*sql.DB, error) {
+	if tracingEnabled {
+		// install the wrapped driver
+		driverName += "-trace"
+	}
+	return sql.Open(driverName, dsn)
+}
+
+func init() {
+	registerDrivers()
+}

internal/sqlutil/trace_driver.go

@@ -0,0 +1,35 @@
+// Copyright 2020 The Matrix.org Foundation C.I.C.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+// +build !wasm
+
+package sqlutil
+
+import (
+	"database/sql"
+
+	"github.com/lib/pq"
+	sqlite "github.com/mattn/go-sqlite3"
+	"github.com/ngrok/sqlmw"
+)
+
+func registerDrivers() {
+	if !tracingEnabled {
+		return
+	}
+	// install the wrapped drivers
+	sql.Register("postgres-trace", sqlmw.Driver(&pq.Driver{}, new(traceInterceptor)))
+	sql.Register("sqlite3-trace", sqlmw.Driver(&sqlite.SQLiteDriver{}, new(traceInterceptor)))
+
+}

internal/sqlutil/trace_driver_wasm.go

@@ -0,0 +1,33 @@
+// Copyright 2020 The Matrix.org Foundation C.I.C.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+// +build wasm
+
+package sqlutil
+
+import (
+	"database/sql"
+
+	sqlitejs "github.com/matrix-org/go-sqlite3-js"
+	"github.com/ngrok/sqlmw"
+)
+
+func registerDrivers() {
+	if !tracingEnabled {
+		return
+	}
+	// install the wrapped drivers
+	sql.Register("sqlite3_js-trace", sqlmw.Driver(&sqlitejs.SqliteJsDriver{}, new(traceInterceptor)))
+
+}

mediaapi/storage/postgres/storage.go

@@ -21,6 +21,7 @@ import (
 
 	// Import the postgres database driver.
 	_ "github.com/lib/pq"
+	"github.com/matrix-org/dendrite/internal/sqlutil"
 	"github.com/matrix-org/dendrite/mediaapi/types"
 	"github.com/matrix-org/gomatrixserverlib"
 )
@@ -35,7 +36,7 @@ type Database struct {
 func Open(dataSourceName string) (*Database, error) {
 	var d Database
 	var err error
-	if d.db, err = sql.Open("postgres", dataSourceName); err != nil {
+	if d.db, err = sqlutil.Open("postgres", dataSourceName); err != nil {
 		return nil, err
 	}
 	if err = d.statements.prepare(d.db); err != nil {

mediaapi/storage/sqlite3/storage.go

@@ -21,6 +21,7 @@ import (
 
 	// Import the postgres database driver.
 	"github.com/matrix-org/dendrite/common"
+	"github.com/matrix-org/dendrite/internal/sqlutil"
 	"github.com/matrix-org/dendrite/mediaapi/types"
 	"github.com/matrix-org/gomatrixserverlib"
 	_ "github.com/mattn/go-sqlite3"
@@ -36,7 +37,7 @@ type Database struct {
 func Open(dataSourceName string) (*Database, error) {
 	var d Database
 	var err error
-	if d.db, err = sql.Open(common.SQLiteDriverName(), dataSourceName); err != nil {
+	if d.db, err = sqlutil.Open(common.SQLiteDriverName(), dataSourceName); err != nil {
 		return nil, err
 	}
 	if err = d.statements.prepare(d.db); err != nil {

publicroomsapi/storage/postgres/storage.go

@@ -21,6 +21,7 @@ import (
 	"encoding/json"
 
 	"github.com/matrix-org/dendrite/common"
+	"github.com/matrix-org/dendrite/internal/sqlutil"
 
 	"github.com/matrix-org/gomatrixserverlib"
 )
@@ -38,7 +39,7 @@ type attributeValue interface{}
 func NewPublicRoomsServerDatabase(dataSourceName string) (*PublicRoomsServerDatabase, error) {
 	var db *sql.DB
 	var err error
-	if db, err = sql.Open("postgres", dataSourceName); err != nil {
+	if db, err = sqlutil.Open("postgres", dataSourceName); err != nil {
 		return nil, err
 	}
 	storage := PublicRoomsServerDatabase{

publicroomsapi/storage/sqlite3/storage.go

@@ -23,6 +23,7 @@ import (
 	_ "github.com/mattn/go-sqlite3"
 
 	"github.com/matrix-org/dendrite/common"
+	"github.com/matrix-org/dendrite/internal/sqlutil"
 
 	"github.com/matrix-org/gomatrixserverlib"
 )
@@ -40,7 +41,7 @@ type attributeValue interface{}
 func NewPublicRoomsServerDatabase(dataSourceName string) (*PublicRoomsServerDatabase, error) {
 	var db *sql.DB
 	var err error
-	if db, err = sql.Open(common.SQLiteDriverName(), dataSourceName); err != nil {
+	if db, err = sqlutil.Open(common.SQLiteDriverName(), dataSourceName); err != nil {
 		return nil, err
 	}
 	storage := PublicRoomsServerDatabase{

roomserver/storage/postgres/storage.go

@@ -20,6 +20,7 @@ import (
 	"database/sql"
 	"encoding/json"
 
+	"github.com/matrix-org/dendrite/internal/sqlutil"
 	roomserverVersion "github.com/matrix-org/dendrite/roomserver/version"
 
 	// Import the postgres database driver.
@@ -39,7 +40,7 @@ type Database struct {
 func Open(dataSourceName string) (*Database, error) {
 	var d Database
 	var err error
-	if d.db, err = sql.Open("postgres", dataSourceName); err != nil {
+	if d.db, err = sqlutil.Open("postgres", dataSourceName); err != nil {
 		return nil, err
 	}
 	if err = d.statements.prepare(d.db); err != nil {

roomserver/storage/sqlite3/storage.go

@@ -22,6 +22,7 @@ import (
 	"errors"
 	"net/url"
 
+	"github.com/matrix-org/dendrite/internal/sqlutil"
 	roomserverVersion "github.com/matrix-org/dendrite/roomserver/version"
 
 	"github.com/matrix-org/dendrite/common"
@@ -52,7 +53,7 @@ func Open(dataSourceName string) (*Database, error) {
 	} else {
 		return nil, errors.New("no filename or path in connect string")
 	}
-	if d.db, err = sql.Open(common.SQLiteDriverName(), cs); err != nil {
+	if d.db, err = sqlutil.Open(common.SQLiteDriverName(), cs); err != nil {
 		return nil, err
 	}
 	//d.db.Exec("PRAGMA journal_mode=WAL;")

syncapi/storage/postgres/syncserver.go

@@ -25,6 +25,7 @@ import (
 	"github.com/sirupsen/logrus"
 
 	"github.com/matrix-org/dendrite/clientapi/auth/authtypes"
+	"github.com/matrix-org/dendrite/internal/sqlutil"
 	"github.com/matrix-org/dendrite/roomserver/api"
 
 	// Import the postgres database driver.
@@ -62,7 +63,7 @@ type SyncServerDatasource struct {
 func NewSyncServerDatasource(dbDataSourceName string) (*SyncServerDatasource, error) {
 	var d SyncServerDatasource
 	var err error
-	if d.db, err = sql.Open("postgres", dbDataSourceName); err != nil {
+	if d.db, err = sqlutil.Open("postgres", dbDataSourceName); err != nil {
 		return nil, err
 	}
 	if err = d.PartitionOffsetStatements.Prepare(d.db, "syncapi"); err != nil {

syncapi/storage/sqlite3/syncserver.go

@@ -27,6 +27,7 @@ import (
 	"github.com/sirupsen/logrus"
 
 	"github.com/matrix-org/dendrite/clientapi/auth/authtypes"
+	"github.com/matrix-org/dendrite/internal/sqlutil"
 	"github.com/matrix-org/dendrite/roomserver/api"
 
 	// Import the sqlite3 package
@@ -78,7 +79,7 @@ func NewSyncServerDatasource(dataSourceName string) (*SyncServerDatasource, erro
 	} else {
 		return nil, errors.New("no filename or path in connect string")
 	}
-	if d.db, err = sql.Open(common.SQLiteDriverName(), cs); err != nil {
+	if d.db, err = sqlutil.Open(common.SQLiteDriverName(), cs); err != nil {
 		return nil, err
 	}
 	if err = d.prepare(); err != nil {