Use slog in integration tests (#4481)

Closes #4013.
FerretDB · Jul 22, 2024 · 6312dab · 6312dab
1 parent a4b7e70
commit 6312dab
Show file tree

Hide file tree

Showing 7 changed files with 87 additions and 45 deletions.
diff --git a/integration/setup/listener.go b/integration/setup/listener.go
@@ -101,7 +101,7 @@ func listenerMongoDBURI(tb testtb.TB, hostPort, unixSocketPath, newAuthDB string
 
 // setupListener starts in-process FerretDB server that runs until ctx is canceled.
 // It returns basic MongoDB URI for that listener.
-func setupListener(tb testtb.TB, ctx context.Context, logger *zap.Logger, opts *BackendOpts) string {
+func setupListener(tb testtb.TB, ctx context.Context, logger *slog.Logger, opts *BackendOpts) string {
 	tb.Helper()
 
 	ctx, span := otel.Tracer("").Start(ctx, "setupListener")
@@ -176,7 +176,7 @@ func setupListener(tb testtb.TB, ctx context.Context, logger *zap.Logger, opts *
 	}
 
 	handlerOpts := &registry.NewHandlerOpts{
-		Logger:        logger,
+		Logger:        zap.L(),
 		SLogger:       slog.Default(), // TODO https://github.com/FerretDB/FerretDB/issues/4013
 		ConnMetrics:   listenerMetrics.ConnMetrics,
 		StateProvider: sp,
@@ -216,7 +216,7 @@ func setupListener(tb testtb.TB, ctx context.Context, logger *zap.Logger, opts *
 		Mode:           clientconn.NormalMode,
 		Metrics:        listenerMetrics,
 		Handler:        h,
-		Logger:         slog.Default(),
+		Logger:         slog.Default(), // TODO https://github.com/FerretDB/FerretDB/issues/4013
 		TestRecordsDir: testutil.TmpRecordsDir,
 	}
 
@@ -274,7 +274,7 @@ func setupListener(tb testtb.TB, ctx context.Context, logger *zap.Logger, opts *
 
 	uri := listenerMongoDBURI(tb, hostPort, unixSocketPath, handlerOpts.SetupDatabase, tlsAndAuth)
 
-	logger.Info("Listener started", zap.String("handler", handler), zap.String("uri", uri))
+	logger.InfoContext(ctx, "Listener started", slog.String("handler", handler), slog.String("uri", uri))
 
 	return uri
 }
diff --git a/integration/setup/setup.go b/integration/setup/setup.go
@@ -18,6 +18,7 @@ package setup
 import (
 	"context"
 	"flag"
+	"log/slog"
 	"net/url"
 	"slices"
 	"strings"
@@ -28,7 +29,6 @@ import (
 	"go.mongodb.org/mongo-driver/mongo"
 	"go.mongodb.org/mongo-driver/mongo/options"
 	"go.opentelemetry.io/otel"
-	"go.uber.org/zap"
 
 	"github.com/FerretDB/FerretDB/internal/util/iterator"
 	"github.com/FerretDB/FerretDB/internal/util/testutil"
@@ -59,7 +59,7 @@ var (
 
 	// Disable noisy setup logs by default.
 	debugSetupF = flag.Bool("debug-setup", false, "enable debug logs for tests setup")
-	logLevelF   = zap.LevelFlag("log-level", zap.DebugLevel, "log level for tests")
+	logLevelF   = flag.String("log-level", slog.LevelDebug.String(), "log level for tests")
 
 	disablePushdownF = flag.Bool("disable-pushdown", false, "disable pushdown")
 )
@@ -144,11 +144,13 @@ func SetupWithOpts(tb testtb.TB, opts *SetupOpts) *SetupResult {
 		opts = new(SetupOpts)
 	}
 
-	level := zap.NewAtomicLevelAt(zap.ErrorLevel)
+	var levelVar slog.LevelVar
+	levelVar.Set(slog.LevelError)
 	if *debugSetupF {
-		level = zap.NewAtomicLevelAt(zap.DebugLevel)
+		levelVar.Set(slog.LevelDebug)
 	}
-	logger := testutil.LevelLogger(tb, level)
+
+	logger := testutil.LevelLogger(tb, &levelVar)
 
 	uri := *targetURLF
 	if uri == "" {
@@ -179,7 +181,8 @@ func SetupWithOpts(tb testtb.TB, opts *SetupOpts) *SetupResult {
 
 	collection := setupCollection(tb, setupCtx, client, opts)
 
-	level.SetLevel(*logLevelF)
+	err := levelVar.UnmarshalText([]byte(*logLevelF))
+	require.NoError(tb, err)
 
 	return &SetupResult{
 		Ctx:        ctx,

diff --git a/integration/setup/setup_compat.go b/integration/setup/setup_compat.go
@@ -16,12 +16,12 @@ package setup
 
 import (
 	"context"
+	"log/slog"
 	"strings"
 
 	"github.com/stretchr/testify/require"
 	"go.mongodb.org/mongo-driver/mongo"
 	"go.opentelemetry.io/otel"
-	"go.uber.org/zap"
 
 	"github.com/FerretDB/FerretDB/internal/util/testutil"
 	"github.com/FerretDB/FerretDB/internal/util/testutil/testtb"
@@ -90,11 +90,13 @@ func SetupCompatWithOpts(tb testtb.TB, opts *SetupCompatOpts) *SetupCompatResult
 
 	opts.baseCollectionName = testutil.CollectionName(tb)
 
-	level := zap.NewAtomicLevelAt(zap.ErrorLevel)
+	var levelVar slog.LevelVar
+	levelVar.Set(slog.LevelError)
 	if *debugSetupF {
-		level = zap.NewAtomicLevelAt(zap.DebugLevel)
+		levelVar.Set(slog.LevelDebug)
 	}
-	logger := testutil.LevelLogger(tb, level)
+
+	logger := testutil.LevelLogger(tb, &levelVar)
 
 	var targetClient *mongo.Client
 	if *targetURLF == "" {
@@ -112,7 +114,8 @@ func SetupCompatWithOpts(tb testtb.TB, opts *SetupCompatOpts) *SetupCompatResult
 	compatClient := setupClient(tb, setupCtx, *compatURLF, false)
 	compatCollections := setupCompatCollections(tb, setupCtx, compatClient, opts, "mongodb")
 
-	level.SetLevel(*logLevelF)
+	err := levelVar.UnmarshalText([]byte(*logLevelF))
+	require.NoError(tb, err)
 
 	return &SetupCompatResult{
 		Ctx:               ctx,

diff --git a/integration/setup/startup.go b/integration/setup/startup.go
@@ -25,7 +25,6 @@ import (
 	"time"
 
 	"github.com/prometheus/client_golang/prometheus"
-	"go.uber.org/zap"
 
 	"github.com/FerretDB/FerretDB/internal/clientconn/connmetrics"
 	"github.com/FerretDB/FerretDB/internal/util/debug"
@@ -46,11 +45,20 @@ var startupWG sync.WaitGroup
 
 // Startup initializes things that should be initialized only once.
 func Startup() {
-	logging.Setup(zap.DebugLevel, "console", "")
+	opts := &logging.NewHandlerOpts{
+		Base:        "console",
+		Level:       slog.LevelDebug,
+		RemoveTime:  true,
+		RemoveLevel: true,
+	}
+	logging.SetupSlog(opts, "")
+	l := slog.Default()
+
+	ctx := context.Background()
 
 	// https://docs.github.com/en/actions/learn-github-actions/variables#default-environment-variables
 	if t, _ := strconv.ParseBool(os.Getenv("RUNNER_DEBUG")); t {
-		zap.S().Info("Enabling setup debug logging on GitHub Actions.")
+		l.InfoContext(ctx, "Enabling setup debug logging on GitHub Actions")
 		*debugSetupF = true
 	}
 
@@ -59,24 +67,23 @@ func Startup() {
 	// use any available port to allow running different configurations in parallel
 	h, err := debug.Listen(&debug.ListenOpts{
 		TCPAddr: "127.0.0.1:0",
-		L:       logging.WithName(slog.Default(), "debug"), // TODO https://github.com/FerretDB/FerretDB/issues/4013
+		L:       logging.WithName(l, "debug"),
 		R:       prometheus.DefaultRegisterer,
 	})
 	if err != nil {
-		zap.S().Fatalf("Failed to create debug handler: %s.", err)
+		l.LogAttrs(ctx, logging.LevelFatal, "Failed to create debug handler", logging.Error(err))
 	}
 
 	ot, err := observability.NewOtelTracer(&observability.OtelTracerOpts{
-		Logger:   logging.WithName(slog.Default(), "otel"),
+		Logger:   logging.WithName(l, "otel"),
 		Service:  "integration-tests",
 		Endpoint: "127.0.0.1:4318",
 	})
 	if err != nil {
-		zap.S().Fatalf("Failed to create Otel tracer: %s.", err)
+		l.LogAttrs(ctx, logging.LevelFatal, "Failed to create Otel tracer", logging.Error(err))
 	}
 
-	var ctx context.Context
-	ctx, shutdown = context.WithCancel(context.Background())
+	ctx, shutdown = context.WithCancel(ctx)
 
 	startupWG.Add(1)
 
@@ -92,13 +99,13 @@ func Startup() {
 		ot.Run(ctx)
 	}()
 
-	clientCtx, clientCancel := context.WithTimeout(context.Background(), 5*time.Second)
+	clientCtx, clientCancel := context.WithTimeout(ctx, 5*time.Second)
 	defer clientCancel()
 
 	// do basic flags validation earlier, before all tests
 
 	if *benchDocsF <= 0 {
-		zap.S().Fatal("-bench-docs must be > 0.")
+		l.LogAttrs(ctx, logging.LevelFatal, "-bench-docs must be > 0")
 	}
 
 	for _, p := range shareddata.AllBenchmarkProviders() {
@@ -108,51 +115,51 @@ func Startup() {
 	}
 
 	if *targetBackendF == "" {
-		zap.S().Fatal("-target-backend must be set.")
+		l.LogAttrs(ctx, logging.LevelFatal, "-target-backend must be set")
 	}
 
 	if !slices.Contains(allBackends, *targetBackendF) {
-		zap.S().Fatalf("Unknown target backend %q.", *targetBackendF)
+		l.LogAttrs(ctx, logging.LevelFatal, "Unknown target backend", slog.String("target_backend", *targetBackendF))
 	}
 
 	if *targetURLF != "" {
 		var err error
 
 		*targetURLF, err = setClientPaths(*targetURLF)
 		if err != nil {
-			zap.S().Fatal(err)
+			l.LogAttrs(ctx, logging.LevelFatal, "Failed to set target client path", logging.Error(err))
 		}
 
 		client, err := makeClient(clientCtx, *targetURLF, false)
 		if err != nil {
-			zap.S().Fatalf("Failed to connect to target system %s: %s", *targetURLF, err)
+			l.LogAttrs(ctx, logging.LevelFatal, "Failed to connect to target system", slog.String("target_url", *targetURLF), logging.Error(err))
 		}
 
 		_ = client.Disconnect(clientCtx)
 
-		zap.S().Infof("Target system: %s (%s).", *targetBackendF, *targetURLF)
+		l.InfoContext(ctx, "Target system", slog.String("target_backend", *targetBackendF), slog.String("target_url", *targetURLF))
 	} else {
-		zap.S().Infof("Target system: %s (built-in).", *targetBackendF)
+		l.InfoContext(ctx, "Target system (built-in)", slog.String("target_backend", *targetBackendF))
 	}
 
 	if *compatURLF != "" {
 		var err error
 
 		*compatURLF, err = setClientPaths(*compatURLF)
 		if err != nil {
-			zap.S().Fatal(err)
+			l.LogAttrs(ctx, logging.LevelFatal, "Failed to set compat client path", logging.Error(err))
 		}
 
 		client, err := makeClient(clientCtx, *compatURLF, false)
 		if err != nil {
-			zap.S().Fatalf("Failed to connect to compat system %s: %s", *compatURLF, err)
+			l.LogAttrs(ctx, logging.LevelFatal, "Failed to connect to compat system", slog.String("compat_url", *compatURLF), logging.Error(err))
 		}
 
 		_ = client.Disconnect(clientCtx)
 
-		zap.S().Infof("Compat system: MongoDB (%s).", *compatURLF)
+		l.InfoContext(ctx, "Compat system: MongoDB", slog.String("compat_url", *compatURLF))
 	} else {
-		zap.S().Infof("Compat system: none, compatibility tests will be skipped.")
+		l.InfoContext(ctx, "Compat system: none, compatibility tests will be skipped")
 	}
 }
 

diff --git a/internal/util/logging/logging.go b/internal/util/logging/logging.go
@@ -62,8 +62,8 @@ func WithName(l *slog.Logger, name string) *slog.Logger {
 	return l.With(slog.String(nameKey, name))
 }
 
-// setupSlog initializes slog logging with given options and UUID.
-func setupSlog(opts *NewHandlerOpts, uuid string) {
+// SetupSlog initializes slog logging with given options and UUID.
+func SetupSlog(opts *NewHandlerOpts, uuid string) {
 	must.NotBeZero(opts)
 
 	h := NewHandler(os.Stderr, opts)

diff --git a/internal/util/logging/zap.go b/internal/util/logging/zap.go
@@ -47,7 +47,7 @@ func Setup(level zapcore.Level, encoding, uuid string) {
 		Base:  encoding,
 		Level: slogLevel,
 	}
-	setupSlog(slogOpts, uuid)
+	SetupSlog(slogOpts, uuid)
 
 	config := zap.Config{
 		Level:             zap.NewAtomicLevelAt(level),

diff --git a/internal/util/testutil/logging.go b/internal/util/testutil/logging.go
@@ -15,35 +15,64 @@
 package testutil
 
 import (
+	"io"
 	"log/slog"
+	"strings"
 	"testing"
 
 	"github.com/neilotoole/slogt"
 	"go.uber.org/zap"
 	"go.uber.org/zap/zaptest"
 
+	"github.com/FerretDB/FerretDB/internal/util/logging"
 	"github.com/FerretDB/FerretDB/internal/util/testutil/testtb"
 )
 
-// Logger returns zap test logger with valid configuration.
-func Logger(tb testtb.TB) *zap.Logger {
-	return LevelLogger(tb, zap.NewAtomicLevelAt(zap.DebugLevel))
+// logWriter provides [io.Writer] for [testing.TB].
+type logWriter struct {
+	tb testtb.TB
+}
+
+// Write implements [io.Writer].
+func (lw *logWriter) Write(p []byte) (int, error) {
+	// "logging.go:xx" is added by testing.TB.Log itself; there is nothing we can do about it.
+	// lw.tb.Helper() does not help. See:
+	// https://github.com/golang/go/issues/59928
+	// https://github.com/neilotoole/slogt/tree/v1.1.0?tab=readme-ov-file#deficiency
+	lw.tb.Log(strings.TrimSuffix(string(p), "\n"))
+	return len(p), nil
 }
 
-// LevelLogger returns zap test logger with given level and valid configuration.
-func LevelLogger(tb testtb.TB, level zap.AtomicLevel) *zap.Logger {
+// Logger returns zap test logger with valid configuration.
+func Logger(tb testtb.TB) *zap.Logger {
 	opts := []zaptest.LoggerOption{
-		zaptest.Level(level),
+		zaptest.Level(zap.NewAtomicLevelAt(zap.DebugLevel)),
 		zaptest.WrapOptions(zap.AddCaller(), zap.Development()),
 	}
 
 	return zaptest.NewLogger(tb, opts...)
 }
 
+// LevelLogger returns a test logger for the given level (which might be dynamic).
+func LevelLogger(tb testtb.TB, level slog.Leveler) *slog.Logger {
+	h := logging.NewHandler(&logWriter{tb: tb}, &logging.NewHandlerOpts{
+		Base:       "console",
+		Level:      level,
+		RemoveTime: true,
+	})
+
+	return slog.New(h)
+}
+
 // SLogger returns slog test logger.
 //
 // TODO https://github.com/FerretDB/FerretDB/issues/4013
 func SLogger(tb testtb.TB) *slog.Logger {
 	t := tb.(testing.TB)
 	return slogt.New(t)
 }
+
+// check interfaces
+var (
+	_ io.Writer = (*logWriter)(nil)
+)