diff --git a/logger/database.go b/logger/database.go index d2ebb3b3d..333e5695f 100644 --- a/logger/database.go +++ b/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), + ) } diff --git a/logger/database_test.go b/logger/database_test.go new file mode 100644 index 000000000..e4164f65e --- /dev/null +++ b/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) + }) +}