package lagoon import ( "bytes" "context" "errors" "strings" "testing" "time" "git.golem15.com/golem15/summercms/modules/bonfire" "git.golem15.com/golem15/summercms/modules/diary" "gorm.io/driver/postgres" "gorm.io/gorm" "gorm.io/gorm/logger" ) // TestGormLoggerLevels: GORM logs at warn by default and info (SQL traces) // at verbosity 3; a record-not-found error is not logged; slow queries and // other errors are; and traces carry parameterized SQL, never bound values. func TestGormLoggerLevels(t *testing.T) { var buf bytes.Buffer t.Cleanup(diary.Reset) diary.Bootstrap(&buf, diary.Options{Color: bonfire.ColorNever}) ctx := context.Background() trace := func(l logger.Interface, begin time.Time, err error) { l.Trace(ctx, begin, func() (string, int64) { return `SELECT * FROM "users" WHERE email = $1`, 1 }, err) } l := gormLogger() trace(l, time.Now(), nil) trace(l, time.Now(), gorm.ErrRecordNotFound) if buf.Len() != 0 { t.Fatalf("verbosity 0 logged a fast trace or record-not-found:\n%s", buf.String()) } trace(l, time.Now(), errors.New("relation does not exist")) trace(l, time.Now().Add(-time.Second), nil) out := buf.String() for _, want := range []string{"level=ERROR", "relation does not exist", "level=WARN", "component=db", `trace.sql="SELECT * FROM \"users\" WHERE email = $1"`} { if !strings.Contains(out, want) { t.Errorf("verbosity 0 output lacks %q:\n%s", want, out) } } buf.Reset() diary.SetVerbosity(3, false) l = gormLogger() trace(l, time.Now(), nil) trace(l, time.Now(), gorm.ErrRecordNotFound) out = buf.String() if strings.Count(out, "SQL executed") != 2 || strings.Contains(out, "record not found") { t.Errorf("verbosity 3: want two info traces and no record-not-found error:\n%s", out) } // The SQL in a trace keeps its placeholders: GORM asks the logger to // filter the parameters, and lagoon's logger drops them. filter, ok := l.(gorm.ParamsFilter) if !ok { t.Fatal("lagoon's GORM logger does not filter parameters") } if _, params := filter.ParamsFilter(ctx, "SELECT $1", "secret-value"); params != nil { t.Errorf("ParamsFilter kept the bound values %v", params) } // End to end with a dry-run GORM session (no database is reached). buf.Reset() db, err := gorm.Open(postgres.New(postgres.Config{DSN: "host=127.0.0.1 port=1 user=nobody dbname=none sslmode=disable"}), &gorm.Config{Logger: l, DryRun: true, DisableAutomaticPing: true}) if err != nil { t.Fatalf("dry-run gorm: %v", err) } var row struct{ ID int } db.Table("users").Where("email = ?", "ada@example.test").Where("password = ?", "secret-value").Find(&row) out = buf.String() if !strings.Contains(out, "SQL executed") || !strings.Contains(out, "$1") || !strings.Contains(out, "$2") { t.Errorf("dry-run trace lacks the parameterized SQL:\n%s", out) } for _, leaked := range []string{"ada@example.test", "secret-value"} { if strings.Contains(out, leaked) { t.Errorf("dry-run trace leaks the bound value %q:\n%s", leaked, out) } } }