Manager: make Gorm use Zerolog for logging

A wrapper for Zerolog implements the Gorm logger interface. This gives
us coloured output on Windows, and uniform-looking logs in production.

internal/manager/persistence/db.go

@@ -27,6 +27,7 @@ import (
 	"github.com/rs/zerolog/log"
 	"gorm.io/gorm"
 
+	// sqlite "git.blender.org/flamenco/pkg/gorm-modernc-sqlite"
 	"github.com/glebarez/sqlite"
 )
 
@@ -36,6 +37,8 @@ type DB struct {
 }
 
 func OpenDB(ctx context.Context, dsn string) (*DB, error) {
+	log.Info().Str("dsn", dsn).Msg("opening database")
+
 	db, err := openDB(ctx, dsn)
 	if err != nil {
 		return nil, err
@@ -44,17 +47,25 @@ func OpenDB(ctx context.Context, dsn string) (*DB, error) {
 	if err := db.migrate(); err != nil {
 		return nil, err
 	}
+	log.Debug().Msg("database automigration succesful")
 
 	return db, nil
 }
 
 func openDB(ctx context.Context, uri string) (*DB, error) {
-	// TODO: don't log the password.
+	globalLogLevel := log.Logger.GetLevel()
-	log.Info().Str("dsn", uri).Msg("opening database")
+	dblogger := NewDBLogger(log.Level(globalLogLevel))
 
-	connection := sqlite.Open(uri)
+	config := gorm.Config{
-	// connection := postgres.Open(uri)
+		Logger: dblogger,
-	gormDB, err := gorm.Open(connection, &gorm.Config{})
+	}
+
+	return openDBWithConfig(uri, &config)
+}
+
+func openDBWithConfig(uri string, config *gorm.Config) (*DB, error) {
+	dialector := sqlite.Open(uri)
+	gormDB, err := gorm.Open(dialector, config)
 	if err != nil {
 		return nil, err
 	}

internal/manager/persistence/db_migration.go

@@ -22,8 +22,6 @@ package persistence
 
 import (
 	"fmt"
-
-	"github.com/rs/zerolog/log"
 )
 
 func (db *DB) migrate() error {
@@ -31,6 +29,5 @@ func (db *DB) migrate() error {
 	if err != nil {
 		return fmt.Errorf("failed to automigrate database: %v", err)
 	}
-	log.Debug().Msg("database automigration succesful")
 	return nil
 }

internal/manager/persistence/logger.go

@@ -0,0 +1,146 @@
+package persistence
+
+/* ***** BEGIN GPL LICENSE BLOCK *****
+ *
+ * Original Code Copyright (C) 2022 Blender Foundation.
+ *
+ * This file is part of Flamenco.
+ *
+ * Flamenco is free software: you can redistribute it and/or modify it under
+ * the terms of the GNU General Public License as published by the Free Software
+ * Foundation, either version 3 of the License, or (at your option) any later
+ * version.
+ *
+ * Flamenco is distributed in the hope that it will be useful, but WITHOUT ANY
+ * WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS FOR
+ * A PARTICULAR PURPOSE.  See the GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License along with
+ * Flamenco.  If not, see <https://www.gnu.org/licenses/>.
+ *
+ * ***** END GPL LICENSE BLOCK ***** */
+
+import (
+	"context"
+	"errors"
+	"fmt"
+	"time"
+
+	"github.com/rs/zerolog"
+	"gorm.io/gorm"
+	gormlogger "gorm.io/gorm/logger"
+)
+
+// dbLogger implements the behaviour of Gorm's default logger on top of Zerolog.
+// See https://github.com/go-gorm/gorm/blob/master/logger/logger.go
+type dbLogger struct {
+	zlog *zerolog.Logger
+
+	IgnoreRecordNotFoundError bool
+	SlowThreshold             time.Duration
+}
+
+var _ gormlogger.Interface = (*dbLogger)(nil)
+
+var logLevelMap = map[gormlogger.LogLevel]zerolog.Level{
+	gormlogger.Silent: zerolog.Disabled,
+	gormlogger.Error:  zerolog.ErrorLevel,
+	gormlogger.Warn:   zerolog.WarnLevel,
+	gormlogger.Info:   zerolog.InfoLevel,
+}
+
+func gormToZlogLevel(logLevel gormlogger.LogLevel) zerolog.Level {
+	zlogLevel, ok := logLevelMap[logLevel]
+	if !ok {
+		// Just a default value that seemed sensible at the time of writing.
+		return zerolog.DebugLevel
+	}
+	return zlogLevel
+}
+
+// NewDBLogger wraps a zerolog logger to implement a Gorm logger interface.
+func NewDBLogger(zlog zerolog.Logger) *dbLogger {
+	return &dbLogger{
+		zlog: &zlog,
+		// Remaining properties default to their zero value.
+	}
+}
+
+// LogMode returns a child logger at the given log level.
+func (l *dbLogger) LogMode(logLevel gormlogger.LogLevel) gormlogger.Interface {
+	childLogger := l.zlog.Level(gormToZlogLevel(logLevel))
+	newlogger := *l
+	newlogger.zlog = &childLogger
+	return &newlogger
+}
+
+func (l *dbLogger) Info(ctx context.Context, msg string, args ...interface{}) {
+	l.logEvent(zerolog.InfoLevel, msg, args)
+}
+
+func (l *dbLogger) Warn(ctx context.Context, msg string, args ...interface{}) {
+	l.logEvent(zerolog.WarnLevel, msg, args)
+}
+
+func (l *dbLogger) Error(ctx context.Context, msg string, args ...interface{}) {
+	l.logEvent(zerolog.ErrorLevel, msg, args)
+}
+
+// Trace traces the execution of SQL and potentially logs errors, warnings, and infos.
+// Note that it doesn't mean "trace-level logging".
+func (l *dbLogger) Trace(ctx context.Context, begin time.Time, fc func() (sql string, rowsAffected int64), err error) {
+	zlogLevel := l.zlog.GetLevel()
+	if zlogLevel == zerolog.Disabled {
+		return
+	}
+
+	elapsed := time.Since(begin)
+	logCtx := l.zlog.With().CallerWithSkipFrameCount(5)
+
+	// Function to lazily get the SQL, affected rows, and logger.
+	buildLogger := func() (loggerPtr *zerolog.Logger, sql string) {
+		sql, rows := fc()
+		logCtx = logCtx.Err(err)
+		if rows >= 0 {
+			logCtx = logCtx.Int64("rowsAffected", rows)
+		}
+		logger := logCtx.Logger()
+		return &logger, sql
+	}
+
+	switch {
+	case err != nil && zlogLevel <= zerolog.ErrorLevel && (!errors.Is(err, gorm.ErrRecordNotFound) || !l.IgnoreRecordNotFoundError):
+		logger, sql := buildLogger()
+		logger.Error().Msg(sql)
+
+	case elapsed > l.SlowThreshold && l.SlowThreshold != 0 && zlogLevel <= zerolog.WarnLevel:
+		logger, sql := buildLogger()
+		logger.Warn().
+			Str("sql", sql).
+			Dur("elapsed", elapsed).
+			Dur("slowThreshold", l.SlowThreshold).
+			Msg("slow database query")
+
+	case zlogLevel <= zerolog.TraceLevel:
+		logger, sql := buildLogger()
+		logger.Trace().Msg(sql)
+	}
+}
+
+// logEvent logs an even at the given level.
+func (l dbLogger) logEvent(level zerolog.Level, msg string, args ...interface{}) {
+	if l.zlog.GetLevel() > level {
+		return
+	}
+	logger := l.logger(args)
+	logger.WithLevel(level).Msg(msg)
+}
+
+// logger constructs a zerolog logger. The given arguments are added via reflection.
+func (l dbLogger) logger(args ...interface{}) zerolog.Logger {
+	logCtx := l.zlog.With()
+	for idx, arg := range args {
+		logCtx.Interface(fmt.Sprintf("arg%d", idx), arg)
+	}
+	return logCtx.Logger()
+}