[logger] Implement Database.Trace so SQL trace logging is not swallowed

logger/database.go

@@ -2,6 +2,8 @@ package logger
 
 import (
 	"context"
+	"fmt"
+	"strconv"
 	"time"
 
 	"github.com/sirupsen/logrus"
@@ -38,5 +40,30 @@ func (c *Database) Error(ctx context.Context, msg string, data ...interface{}) {
 		msg, data,
 	)
 }
+
+// Trace is called by GORM after every SQL statement. It forwards the statement, its execution
+// time, the affected row count and any error to the underlying logger, matching the format used
+// by GORM's own logger.
 func (c *Database) Trace(ctx context.Context, begin time.Time, fc func() (string, int64), err error) {
+	if c == nil || c.base == nil || fc == nil {
+		return
+	}
+	sql, rows := fc()
+	elapsed := float64(time.Since(begin).Nanoseconds()) / 1e6
+
+	// GORM reports rows as -1 when a row count does not apply to the statement.
+	affected := strconv.FormatInt(rows, 10)
+	if rows == -1 {
+		affected = "-"
+	}
+
+	if err != nil {
+		c.base.errorHandler.Log(logrus.ErrorLevel,
+			fmt.Sprintf("%v [%.3fms] [rows:%s] %s", err, elapsed, affected, sql),
+		)
+		return
+	}
+	c.base.defaultHandler.Log(logrus.InfoLevel,
+		fmt.Sprintf("[%.3fms] [rows:%s] %s", elapsed, affected, sql),
+	)
 }

logger/database_test.go

@@ -0,0 +1,70 @@
+package logger
+
+import (
+	"bytes"
+	"context"
+	"errors"
+	"testing"
+	"time"
+
+	"github.com/sirupsen/logrus"
+	"github.com/stretchr/testify/assert"
+)
+
+func TestDatabase_Trace(t *testing.T) {
+	opts := Options{
+		Format:           TerminalLogFormat,
+		LogLevel:         int(logrus.DebugLevel),
+		EnableCallerInfo: false,
+	}
+	log, err := New("testapp", opts)
+	assert.NoError(t, err)
+	l := log.(*Logger)
+
+	var outBuffer, errBuffer bytes.Buffer
+	l.UpdateLogOutput(&outBuffer)
+	l.UpdateErrorLogOutput(&errBuffer)
+
+	db := l.DatabaseLogger()
+
+	// A successful query is forwarded to the default handler.
+	db.Trace(context.Background(), time.Now(), func() (string, int64) {
+		return "SELECT * FROM meshery_patterns", 3
+	}, nil)
+	assert.Contains(t, outBuffer.String(), "SELECT * FROM meshery_patterns")
+	assert.Contains(t, outBuffer.String(), "[rows:3]")
+	outBuffer.Reset()
+
+	// A failed query is forwarded to the error handler, along with the error.
+	db.Trace(context.Background(), time.Now(), func() (string, int64) {
+		return "SELECT * FROM missing_table", 0
+	}, errors.New("no such table: missing_table"))
+	assert.Contains(t, errBuffer.String(), "SELECT * FROM missing_table")
+	assert.Contains(t, errBuffer.String(), "no such table: missing_table")
+	errBuffer.Reset()
+
+	// GORM reports rows as -1 when a row count does not apply to the statement.
+	db.Trace(context.Background(), time.Now(), func() (string, int64) {
+		return "CREATE TABLE t (id int)", -1
+	}, nil)
+	assert.Contains(t, outBuffer.String(), "[rows:-]")
+}
+
+func TestDatabase_Trace_NilReceiverAndArgs(t *testing.T) {
+	var nilDB *Database
+	assert.NotPanics(t, func() {
+		nilDB.Trace(context.Background(), time.Now(), func() (string, int64) { return "", 0 }, nil)
+	})
+
+	assert.NotPanics(t, func() {
+		(&Database{}).Trace(context.Background(), time.Now(), func() (string, int64) { return "", 0 }, nil)
+	})
+
+	opts := Options{Format: TerminalLogFormat, LogLevel: int(logrus.DebugLevel)}
+	log, err := New("testapp", opts)
+	assert.NoError(t, err)
+	db := log.(*Logger).DatabaseLogger()
+	assert.NotPanics(t, func() {
+		db.Trace(context.Background(), time.Now(), nil, nil)
+	})
+}