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

3 files changed, 157 insertions, 0 deletions

diff --git a/internal/sqlutil/trace.go b/internal/sqlutil/trace.go
new file mode 100644
index 00000000..3d5fa7dc
--- /dev/null
+++ b/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()
+}
diff --git a/internal/sqlutil/trace_driver.go b/internal/sqlutil/trace_driver.go
new file mode 100644
index 00000000..f123b1e4
--- /dev/null
+++ b/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)))
+
+}
diff --git a/internal/sqlutil/trace_driver_wasm.go b/internal/sqlutil/trace_driver_wasm.go
new file mode 100644
index 00000000..a3c163f5
--- /dev/null
+++ b/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)))
+
+}