test(conga,lagoon): River and GORM bridges

- River logs as component river at warn, conga at log.level, -v lets River info through
- an app-published logger wins for River and conga
- GORM: warn by default, info traces at -vvv, record-not-found ignored, parameterized SQL
- gate: the diary, sunscreen, conga and lagoon names in the go stage

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())
+	}
+}

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)
+		}
+	}
+}

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"
 }