From 641ed7ace9d026396810963797b348d1c4a39176 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Sybren=20A=2E=20St=C3=BCvel?= Date: Thu, 3 Mar 2022 13:52:50 +0100 Subject: [PATCH] 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 | 21 ++- internal/manager/persistence/db_migration.go | 3 - internal/manager/persistence/logger.go | 146 +++++++++++++++++++ 3 files changed, 162 insertions(+), 8 deletions(-) create mode 100644 internal/manager/persistence/logger.go diff --git a/internal/manager/persistence/db.go b/internal/manager/persistence/db.go index c42835f5..6d6af5f9 100644 --- a/internal/manager/persistence/db.go +++ b/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. - log.Info().Str("dsn", uri).Msg("opening database") + globalLogLevel := log.Logger.GetLevel() + dblogger := NewDBLogger(log.Level(globalLogLevel)) - connection := sqlite.Open(uri) - // connection := postgres.Open(uri) - gormDB, err := gorm.Open(connection, &gorm.Config{}) + config := gorm.Config{ + Logger: dblogger, + } + + 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 } diff --git a/internal/manager/persistence/db_migration.go b/internal/manager/persistence/db_migration.go index bed83b99..5793baad 100644 --- a/internal/manager/persistence/db_migration.go +++ b/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 } diff --git a/internal/manager/persistence/logger.go b/internal/manager/persistence/logger.go new file mode 100644 index 00000000..1e15809b --- /dev/null +++ b/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 . + * + * ***** 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() +}