gorm test logger (#1417)

* gorm test logger refactor
* add env variable for gorm logs

.vscode/settings.json

@@ -4,4 +4,7 @@
         "--fast"
     ],
     "go.lintOnSave": "workspace",
+    "go.testEnvVars": {
+        "JIMM_TEST_LOG_SQL": "false"
+    }
 }

CONTRIBUTING.md

@@ -70,6 +70,9 @@ E.g. in `internal/jujuapi` an example command to only run a single suite test wo
 $ go test ./internal/jujuapi -check.f modelManagerSuite.TestListModelSummaries -run TestPackage ./internal/jujuapi
 ```
 
+### Env variables
+- `JIMM_TEST_LOG_SQL`: default is `"false"`, set this to `"true"` to show gorm SQL logs on test failure.
+
 ## Building/Publishing
 Below are instructions on building the various binaries that are part of the project as well as
 some information on how they are published.

cmd/jimmsrv/service/service.go

@@ -523,7 +523,7 @@ func openDB(ctx context.Context, dsn string, logSQL bool) (*gorm.DB, error) {
 		return nil, errors.E(errors.CodeServerConfiguration, "unsupported DSN")
 	}
 	return gorm.Open(dialect, &gorm.Config{
-		Logger: logger.GormLogger{LogSQL: logSQL},
+		Logger: &logger.GormLogger{LogSQL: logSQL},
 		NowFunc: func() time.Time {
 			// This is to set the timestamp precision at the service level.
 			return time.Now().Truncate(time.Microsecond)

internal/db/pgx_test.go

@@ -17,10 +17,9 @@ import (
 	"github.com/jackc/pgx/v4/stdlib"
 	"gorm.io/driver/postgres"
 	"gorm.io/gorm"
-	"gorm.io/gorm/logger"
 
 	"github.com/canonical/jimm/v3/internal/db"
-	"github.com/canonical/jimm/v3/internal/testutils/jimmtest"
+	"github.com/canonical/jimm/v3/internal/logger"
 )
 
 const (
@@ -75,14 +74,10 @@ func (s *postgresSuite) Init(c *qt.C) {
 			c.Logf("error closing database: %s", err)
 		}
 	})
-	_, present := os.LookupEnv("TERSE")
-	logLevel := logger.Info
-	if present {
-		logLevel = logger.Warn
-	}
+
 	cfg := gorm.Config{
 		NowFunc: func() time.Time { return time.Now().UTC().Round(time.Millisecond) },
-		Logger:  jimmtest.NewGormLogger(c, logLevel),
+		Logger:  logger.NewGormTestLogger(c),
 	}
 	pCfg := postgres.Config{
 		Conn: sqlDB,

internal/logger/gorm_logger.go

@@ -22,8 +22,13 @@ type GormLogger struct {
 
 // LogMode implements the LogMode function of logger.Interface. This always
 // returns an identical implementation, the log level is handled by zap.
-func (GormLogger) LogMode(logger.LogLevel) logger.Interface {
-	return GormLogger{}
+func (gl *GormLogger) LogMode(level logger.LogLevel) logger.Interface {
+	if level == logger.Silent {
+		gl.LogSQL = false
+	} else {
+		gl.LogSQL = true
+	}
+	return gl
 }
 
 // Error implements logger.Interface, it logs at ERROR level.
@@ -47,19 +52,15 @@ func (g GormLogger) Trace(ctx context.Context, begin time.Time, fc func() (strin
 	if !g.LogSQL {
 		return
 	}
-	ce := zapctx.Logger(ctx).Check(zapcore.DebugLevel, "TRACE")
-	if ce == nil {
-		return
-	}
 	fields := make([]zapcore.Field, 3, 4)
-	fields[0] = zap.Stringer("time", time.Since(begin))
+	fields[0] = zap.Stringer("elapsed", time.Since(begin))
 	sql, rows := fc()
 	fields[1] = zap.String("sql", sql)
 	fields[2] = zap.Int64("rows", rows)
 	if err != nil {
 		fields = append(fields, zap.Error(err))
 	}
-	ce.Write(fields...)
+	zapctx.Debug(ctx, "sql log", fields...)
 }
 
-var _ logger.Interface = GormLogger{}
+var _ logger.Interface = &GormLogger{}

internal/logger/gormtest_logger.go

@@ -0,0 +1,67 @@
+// Copyright 2024 Canonical.
+package logger
+
+import (
+	"os"
+	"strconv"
+
+	"github.com/juju/zaputil/zapctx"
+	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
+	"gorm.io/gorm/logger"
+)
+
+// A Tester is the test interface required by gorm for the logger.
+type Tester interface {
+	Fatalf(format string, args ...interface{})
+	Logf(format string, args ...interface{})
+	Name() string
+	Cleanup(f func())
+}
+
+// A gormLogger is a gorm.Logger that is used in tests. It logs everything
+// to the test. The logs are flushed only if the test fails.
+type gormLogger struct {
+	GormLogger
+	t Tester
+}
+
+// NewGormLogger returns a gorm logger.Interface that can be used in a test
+// All output is logged to the test.
+func NewGormTestLogger(t Tester) logger.Interface {
+	output := gormTesterZapWriter{t}
+
+	devConfig := zap.NewDevelopmentEncoderConfig()
+	devConfig.EncodeLevel = zapcore.CapitalColorLevelEncoder
+	devConfig.EncodeTime = shortTimeEncoder
+
+	logger := zap.New(
+		zapcore.NewCore(
+			zapcore.NewConsoleEncoder(devConfig),
+			output,
+			zap.DebugLevel,
+		))
+	zapctx.Default = logger
+	logSQL, _ := strconv.ParseBool(os.Getenv("JIMM_TEST_LOG_SQL"))
+	return &gormLogger{
+		t: t,
+		GormLogger: GormLogger{
+			LogSQL: logSQL,
+		},
+	}
+}
+
+// gormTesterZapWriter is a zap writer wrapping the Tester interface.
+// It is used to comply with the behaviour of flushing the logs only in case of failure.
+type gormTesterZapWriter struct {
+	t Tester
+}
+
+func (w gormTesterZapWriter) Write(buf []byte) (int, error) {
+	w.t.Logf(string(buf))
+	return len(buf), nil
+}
+
+func (w gormTesterZapWriter) Sync() error {
+	return nil
+}

internal/testutils/jimmtest/gorm.go

@@ -20,10 +20,10 @@ import (
 	"github.com/google/uuid"
 	"gorm.io/driver/postgres"
 	"gorm.io/gorm"
-	"gorm.io/gorm/logger"
 
 	"github.com/canonical/jimm/v3/internal/db"
 	"github.com/canonical/jimm/v3/internal/errors"
+	"github.com/canonical/jimm/v3/internal/logger"
 )
 
 // A Tester is the test interface required by this package.
@@ -34,52 +34,6 @@ type Tester interface {
 	Cleanup(f func())
 }
 
-// A gormLogger is a gorm.Logger that is used in tests. It logs everything
-// to the test.
-type gormLogger struct {
-	t     Tester
-	level logger.LogLevel
-}
-
-// NewGormLogger returns a gorm logger.Interface that can be used in a test
-// All output is logged to the test.
-func NewGormLogger(t Tester, l logger.LogLevel) logger.Interface {
-	return gormLogger{t: t, level: l}
-}
-
-func (l gormLogger) LogMode(_ logger.LogLevel) logger.Interface {
-	return l
-}
-
-func (l gormLogger) Info(_ context.Context, fmt string, args ...interface{}) {
-	if l.level >= logger.Info {
-		l.t.Logf(fmt, args...)
-	}
-}
-
-func (l gormLogger) Warn(_ context.Context, fmt string, args ...interface{}) {
-	if l.level >= logger.Warn {
-		l.t.Logf(fmt, args...)
-	}
-}
-
-func (l gormLogger) Error(_ context.Context, fmt string, args ...interface{}) {
-	if l.level >= logger.Error {
-		l.t.Logf(fmt, args...)
-	}
-}
-
-func (l gormLogger) Trace(ctx context.Context, begin time.Time, fc func() (string, int64), err error) {
-	sql, rows := fc()
-	errS := "<nil>"
-	if err != nil {
-		errS = fmt.Sprintf("%q", err.Error())
-	}
-	l.Info(ctx, "sql:%q rows:%d, error:%s, duration:%0.3fms", sql, rows, errS, float64(time.Since(begin).Microseconds())/10e3)
-}
-
-var _ logger.Interface = gormLogger{}
-
 // PostgresDB returns a PostgreSQL database instance for tests. To improve
 // performance it creates a new database from a template (which has no data but
 // is already-migrated).
@@ -94,11 +48,6 @@ func PostgresDB(t Tester, nowFunc func() time.Time) *gorm.DB {
 // Useful for GoCheck tests that don't support a cleanup function and require the DB
 // name for manual cleanup.
 func PostgresDBWithDbName(t Tester, nowFunc func() time.Time) (*gorm.DB, string) {
-	_, present := os.LookupEnv("TERSE")
-	logLevel := logger.Info
-	if present {
-		logLevel = logger.Warn
-	}
 
 	wrappedNowFunc := func() time.Time {
 		var now time.Time
@@ -110,7 +59,7 @@ func PostgresDBWithDbName(t Tester, nowFunc func() time.Time) (*gorm.DB, string)
 		return now.Truncate(time.Microsecond)
 	}
 	cfg := gorm.Config{
-		Logger:  NewGormLogger(t, logLevel),
+		Logger:  logger.NewGormTestLogger(t),
 		NowFunc: wrappedNowFunc,
 	}
 

local/seed_db/main.go

@@ -26,7 +26,7 @@ func main() {
 	ctx := context.Background()
 
 	gdb, err := gorm.Open(postgres.Open("postgresql://jimm:jimm@localhost/jimm"), &gorm.Config{
-		Logger: logger.GormLogger{},
+		Logger: &logger.GormLogger{},
 	})
 
 	if err != nil {