Expose database errors in QueryTiming logs

mautrix · Mar 8, 2023 · 07d6de5 · 07d6de5
1 parent 7d0ca91
commit 07d6de5
Show file tree

Hide file tree

Showing 2 changed files with 12 additions and 11 deletions.
diff --git a/util/dbutil/connlog.go b/util/dbutil/connlog.go
@@ -23,15 +23,15 @@ func (le *LoggingExecable) ExecContext(ctx context.Context, query string, args .
 	start := time.Now()
 	query = le.db.mutateQuery(query)
 	res, err := le.UnderlyingExecable.ExecContext(ctx, query, args...)
-	le.db.Log.QueryTiming(ctx, "Exec", query, args, -1, time.Since(start))
+	le.db.Log.QueryTiming(ctx, "Exec", query, args, -1, time.Since(start), err)
 	return res, err
 }
 
 func (le *LoggingExecable) QueryContext(ctx context.Context, query string, args ...interface{}) (Rows, error) {
 	start := time.Now()
 	query = le.db.mutateQuery(query)
 	rows, err := le.UnderlyingExecable.QueryContext(ctx, query, args...)
-	le.db.Log.QueryTiming(ctx, "Query", query, args, -1, time.Since(start))
+	le.db.Log.QueryTiming(ctx, "Query", query, args, -1, time.Since(start), err)
 	return &LoggingRows{
 		ctx:   ctx,
 		db:    le.db,
@@ -46,7 +46,7 @@ func (le *LoggingExecable) QueryRowContext(ctx context.Context, query string, ar
 	start := time.Now()
 	query = le.db.mutateQuery(query)
 	row := le.UnderlyingExecable.QueryRowContext(ctx, query, args...)
-	le.db.Log.QueryTiming(ctx, "QueryRow", query, args, -1, time.Since(start))
+	le.db.Log.QueryTiming(ctx, "QueryRow", query, args, -1, time.Since(start), nil)
 	return row
 }
 
@@ -73,7 +73,7 @@ type loggingDB struct {
 func (ld *loggingDB) BeginTx(ctx context.Context, opts *sql.TxOptions) (*LoggingTxn, error) {
 	start := time.Now()
 	tx, err := ld.db.RawDB.BeginTx(ctx, opts)
-	ld.db.Log.QueryTiming(ctx, "Begin", "", nil, -1, time.Since(start))
+	ld.db.Log.QueryTiming(ctx, "Begin", "", nil, -1, time.Since(start), err)
 	if err != nil {
 		return nil, err
 	}
@@ -97,14 +97,14 @@ type LoggingTxn struct {
 func (lt *LoggingTxn) Commit() error {
 	start := time.Now()
 	err := lt.UnderlyingTx.Commit()
-	lt.db.Log.QueryTiming(lt.ctx, "Commit", "", nil, -1, time.Since(start))
+	lt.db.Log.QueryTiming(lt.ctx, "Commit", "", nil, -1, time.Since(start), err)
 	return err
 }
 
 func (lt *LoggingTxn) Rollback() error {
 	start := time.Now()
 	err := lt.UnderlyingTx.Rollback()
-	lt.db.Log.QueryTiming(lt.ctx, "Rollback", "", nil, -1, time.Since(start))
+	lt.db.Log.QueryTiming(lt.ctx, "Rollback", "", nil, -1, time.Since(start), err)
 	return err
 }
 
@@ -120,7 +120,7 @@ type LoggingRows struct {
 
 func (lrs *LoggingRows) stopTiming() {
 	if !lrs.start.IsZero() {
-		lrs.db.Log.QueryTiming(lrs.ctx, "EndRows", lrs.query, lrs.args, lrs.nrows, time.Since(lrs.start))
+		lrs.db.Log.QueryTiming(lrs.ctx, "EndRows", lrs.query, lrs.args, lrs.nrows, time.Since(lrs.start), lrs.rs.Err())
 		lrs.start = time.Time{}
 	}
 }

diff --git a/util/dbutil/log.go b/util/dbutil/log.go
@@ -11,7 +11,7 @@ import (
 )
 
 type DatabaseLogger interface {
-	QueryTiming(ctx context.Context, method, query string, args []interface{}, nrows int, duration time.Duration)
+	QueryTiming(ctx context.Context, method, query string, args []interface{}, nrows int, duration time.Duration, err error)
 	WarnUnsupportedVersion(current, latest int)
 	PrepareUpgrade(current, latest int)
 	DoUpgrade(from, to int, message string, txn bool)
@@ -28,7 +28,7 @@ func (n noopLogger) PrepareUpgrade(_, _ int)              {}
 func (n noopLogger) DoUpgrade(_, _ int, _ string, _ bool) {}
 func (n noopLogger) Warn(msg string, args ...interface{}) {}
 
-func (n noopLogger) QueryTiming(_ context.Context, _, _ string, _ []interface{}, _ int, _ time.Duration) {
+func (n noopLogger) QueryTiming(_ context.Context, _, _ string, _ []interface{}, _ int, _ time.Duration, _ error) {
 }
 
 type mauLogger struct {
@@ -52,7 +52,7 @@ func (m mauLogger) DoUpgrade(from, to int, message string, _ bool) {
 	m.l.Infofln("Upgrading database from v%d to v%d: %s", from, to, message)
 }
 
-func (m mauLogger) QueryTiming(_ context.Context, method, query string, _ []interface{}, _ int, duration time.Duration) {
+func (m mauLogger) QueryTiming(_ context.Context, method, query string, _ []interface{}, _ int, duration time.Duration, _ error) {
 	if duration > 1*time.Second {
 		m.l.Warnfln("%s(%s) took %.3f seconds", method, query, duration.Seconds())
 	}
@@ -103,7 +103,7 @@ func (z zeroLogger) DoUpgrade(from, to int, message string, txn bool) {
 
 var whitespaceRegex = regexp.MustCompile(`\s+`)
 
-func (z zeroLogger) QueryTiming(ctx context.Context, method, query string, args []interface{}, nrows int, duration time.Duration) {
+func (z zeroLogger) QueryTiming(ctx context.Context, method, query string, args []interface{}, nrows int, duration time.Duration, err error) {
 	log := zerolog.Ctx(ctx)
 	if log.GetLevel() == zerolog.Disabled || log == zerolog.DefaultContextLogger {
 		log = z.l
@@ -117,6 +117,7 @@ func (z zeroLogger) QueryTiming(ctx context.Context, method, query string, args
 	}
 	query = strings.TrimSpace(whitespaceRegex.ReplaceAllLiteralString(query, " "))
 	log.Trace().
+		Err(err).
 		Int64("duration_µs", duration.Microseconds()).
 		Str("method", method).
 		Str("query", query).