diff --git a/modules/conga/logger_test.go b/modules/conga/logger_test.go new file mode 100644 index 00000000..f4d1ddec --- /dev/null +++ b/modules/conga/logger_test.go @@ -0,0 +1,91 @@ +package conga + +import ( + "bytes" + "log/slog" + "strings" + "testing" + + "git.golem15.com/golem15/summercms/modules/backpack" + "git.golem15.com/golem15/summercms/modules/bonfire" + "git.golem15.com/golem15/summercms/modules/compass" + "git.golem15.com/golem15/summercms/modules/diary" +) + +// TestRiverLoggerComponent: River logs as component river, which the +// framework defaults hold at warn while conga's own lines (component +// conga) follow log.level; verbosity 1 lets River's info through. +func TestRiverLoggerComponent(t *testing.T) { + var buf bytes.Buffer + t.Cleanup(diary.Reset) + cfg, err := compass.Open(compass.Options{Dir: t.TempDir(), Environ: []string{"SUMMER_LOG__DEFAULT=console"}}) + if err != nil { + t.Fatal(err) + } + if err := diary.Setup(cfg, diary.Options{Stderr: &buf, Color: bonfire.ColorNever, Root: t.TempDir(), Environ: []string{}}); err != nil { + t.Fatal(err) + } + + riverLogger(nil).Info("river info at v0") + riverLogger(nil).Warn("river warn at v0") + loggerFromApp(nil).Info("conga info at v0") + out := buf.String() + if strings.Contains(out, "river info at v0") { + t.Errorf("River info passed its warn floor:\n%s", out) + } + for _, want := range []string{"component=river", "river warn at v0", "component=conga", "conga info at v0"} { + if !strings.Contains(out, want) { + t.Errorf("output lacks %q:\n%s", want, out) + } + } + for _, line := range strings.Split(strings.TrimSpace(out), "\n") { + if strings.Contains(line, "river warn at v0") && !strings.Contains(line, "component=river") { + t.Errorf("River line without component=river: %q", line) + } + if strings.Contains(line, "conga info at v0") && !strings.Contains(line, "component=conga") { + t.Errorf("conga line without component=conga: %q", line) + } + } + + buf.Reset() + diary.SetVerbosity(1, false) + riverLogger(nil).Info("river info at v1") + if !strings.Contains(buf.String(), "river info at v1") { + t.Errorf("River info missing at verbosity 1:\n%s", buf.String()) + } +} + +// TestRiverLoggerPublishedOverride: a *slog.Logger the application +// published wins for River and for conga's own lines; without one, an app +// still gets the diary loggers. +func TestRiverLoggerPublishedOverride(t *testing.T) { + var buf bytes.Buffer + t.Cleanup(diary.Reset) + diary.Bootstrap(&buf, diary.Options{Color: bonfire.ColorNever}) + + bare := backpack.New(&compass.Config{}) + riverLogger(bare).Warn("bare app river") + loggerFromApp(bare).Warn("bare app conga") + if !strings.Contains(buf.String(), "bare app river") || !strings.Contains(buf.String(), "bare app conga") { + t.Fatalf("an app without a published logger does not use diary:\n%s", buf.String()) + } + + var capture bytes.Buffer + app := backpack.New(&compass.Config{}) + published := slog.New(slog.NewTextHandler(&capture, &slog.HandlerOptions{Level: slog.LevelDebug})) + if err := app.Publish(published); err != nil { + t.Fatal(err) + } + buf.Reset() + if riverLogger(app) != published || loggerFromApp(app) != published { + t.Fatal("the published logger is not the one handed out") + } + riverLogger(app).Info("published river info") + loggerFromApp(app).Info("published conga info") + if !strings.Contains(capture.String(), "published river info") || !strings.Contains(capture.String(), "published conga info") { + t.Errorf("published logger lacks the records:\n%s", capture.String()) + } + if buf.Len() != 0 { + t.Errorf("records reached diary although the app published a logger:\n%s", buf.String()) + } +} diff --git a/modules/lagoon/logger_test.go b/modules/lagoon/logger_test.go new file mode 100644 index 00000000..aa188034 --- /dev/null +++ b/modules/lagoon/logger_test.go @@ -0,0 +1,83 @@ +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) + } + } +} diff --git a/scripts/check-phase19.8.sh b/scripts/check-phase19.8.sh index c4c8fee3..14580d10 100755 --- a/scripts/check-phase19.8.sh +++ b/scripts/check-phase19.8.sh @@ -63,6 +63,23 @@ SUMMERCMSIO_APP="${SUMMERCMSIO_APP:-$ROOT/../sm-summercmsio-app}" DIARY_TESTS=( # Plan 01. TestDiaryTracerSmoke TestConfigEnvSmoke TestDailyDegradesSmoke + # Plan 04: config rules, floors, verbosity, quiet (D-08, D-09). + TestConfigRules TestConfigEnvStrings TestDefaultConfig + TestComponentFloors TestVerbosityLevels TestQuietConsoleOnly + # Plan 04: daily files (D-10). + TestDailyRotation TestDailyRetention TestDailyPermissions + TestDailyUnwritable TestDailyLazyOpen TestPathConfinement + # Plan 04: redaction, the console handler, lifecycle, concurrency (D-12). + TestRedactionEveryDriver TestConsoleStripsControlChars + TestConsoleComponentPrefix TestConsoleStyledOnlyOnTerminal + TestConsoleLevelFromOptions TestForBeforeSetup TestResetRestoresDefault + TestNoRecursionWithoutState TestHideOnTTY TestConcurrentWrites + # Plan 04: testing/slogtest conformance. + TestSlogtestConsoleHandler TestSlogtestPipeline +) +SUNSCREEN_TESTS=( + # Plan 04: the compatibility entry point. + TestInstallDefault TestInstallDefaultUnchanged ) BONFIRE_TESTS=( # Plan 02. @@ -72,10 +89,14 @@ BONFIRE_TESTS=( CONGA_TESTS=( # Plan 01. TestRiverLoggerUsesDiarySmoke + # Plan 04 (D-09). + TestRiverLoggerComponent TestRiverLoggerPublishedOverride ) LAGOON_TESTS=( # Plan 01. TestGormLoggerUsesDiarySmoke + # Plan 04 (D-09). + TestGormLoggerLevels ) SURF_TESTS=( # Plan 03. @@ -293,18 +314,19 @@ run_go() { go_vet "$ROOT" ./... go_short "$ROOT" go_named "$ROOT" ./modules/diary -short "${DIARY_TESTS[@]}" + go_named "$ROOT" ./modules/sunscreen -short "${SUNSCREEN_TESTS[@]}" go_named "$ROOT" ./modules/bonfire -short "${BONFIRE_TESTS[@]}" go_named "$ROOT" ./modules/conga -short "${CONGA_TESTS[@]}" go_named "$ROOT" ./modules/lagoon -short "${LAGOON_TESTS[@]}" go_named "$ROOT" ./modules/surf -short "${SURF_TESTS[@]}" go_named "$ROOT" ./cmd/summer -short "${SUMMER_TESTS[@]}" local out - if ! out="$(cd "$ROOT" && go test -count=1 -race -short ./modules/diary/... ./modules/bonfire/... 2>&1)"; then + if ! out="$(cd "$ROOT" && go test -count=1 -race -short ./modules/diary/... ./modules/sunscreen/... ./modules/bonfire/... 2>&1)"; then printf '%s\n' "$out" | tail -n 60 >&2 - echo "refuse: go test -race -short of diary and bonfire" >&2 + echo "refuse: go test -race -short of diary, sunscreen and bonfire" >&2 return 1 fi - echo "race: modules/diary, modules/bonfire" + echo "race: modules/diary, modules/sunscreen, modules/bonfire" echo "phase19.8 go passed" }