diff --git a/integration/setup/listener.go b/integration/setup/listener.go index 8c02503477f9..61b3da6c2cb2 100644 --- 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 := ®istry.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 index cd0ed79c6b6e..b477874fc64c 100644 --- 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 index fe94516138b6..4722ee15bb30 100644 --- 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 index 73c4891996db..09dc699cea04 100644 --- 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,11 +115,11 @@ 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 != "" { @@ -120,19 +127,19 @@ func Startup() { *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 != "" { @@ -140,19 +147,19 @@ func Startup() { *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 index fd169204672e..5e9f50fb4a10 100644 --- 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 index 8896d2ebf929..e9a7a6d96b64 100644 --- 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 index 940a0bf90be4..0530d8de6a1c 100644 --- a/internal/util/testutil/logging.go +++ b/internal/util/testutil/logging.go @@ -15,31 +15,55 @@ 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 @@ -47,3 +71,8 @@ func SLogger(tb testtb.TB) *slog.Logger { t := tb.(testing.TB) return slogt.New(t) } + +// check interfaces +var ( + _ io.Writer = (*logWriter)(nil) +)