From 16c05af75cd077f2d211952cd9d4f41f3d21e95a Mon Sep 17 00:00:00 2001 From: Chi Fujii Date: Wed, 17 Jul 2024 17:03:44 +0900 Subject: [PATCH 01/11] use slog in handler --- cmd/ferretdb/main.go | 1 + ferretdb/ferretdb.go | 2 + integration/setup/listener.go | 2 + internal/handler/cmd_query.go | 9 ++-- internal/handler/commands.go | 17 +++---- internal/handler/common/count.go | 4 +- internal/handler/common/delete_params.go | 4 +- internal/handler/common/distinct.go | 5 +- internal/handler/common/explain.go | 4 +- internal/handler/common/find.go | 4 +- internal/handler/common/findandmodify.go | 5 +- internal/handler/common/insert.go | 5 +- internal/handler/common/unimplemented.go | 7 ++- internal/handler/common/update_params.go | 4 +- internal/handler/handler.go | 46 ++++++++++++------- .../handler/handlerparams/extract_params.go | 9 ++-- .../handlerparams/extract_params_test.go | 4 +- internal/handler/msg_aggregate.go | 13 ++++-- internal/handler/msg_find.go | 23 ++++++---- internal/handler/msg_getlog.go | 5 +- internal/handler/msg_getmore.go | 10 ++-- internal/handler/msg_listdatabases.go | 7 ++- internal/handler/msg_saslcontinue.go | 22 ++++----- internal/handler/msg_saslstart.go | 21 +++++---- internal/handler/registry/hana.go | 3 +- internal/handler/registry/mysql.go | 3 +- internal/handler/registry/postgresql.go | 3 +- internal/handler/registry/registry.go | 2 + internal/handler/registry/sqlite.go | 3 +- 29 files changed, 137 insertions(+), 110 deletions(-) diff --git a/cmd/ferretdb/main.go b/cmd/ferretdb/main.go index 58e23b7b153d..1128c76d734b 100644 --- a/cmd/ferretdb/main.go +++ b/cmd/ferretdb/main.go @@ -498,6 +498,7 @@ func run() { h, closeBackend, err := registry.NewHandler(cli.Handler, ®istry.NewHandlerOpts{ Logger: logger, + SLogger: slogger, ConnMetrics: metrics.ConnMetrics, StateProvider: stateProvider, TCPHost: cli.Listen.Addr, diff --git a/ferretdb/ferretdb.go b/ferretdb/ferretdb.go index df2747f8c91c..91a4f50124cf 100644 --- a/ferretdb/ferretdb.go +++ b/ferretdb/ferretdb.go @@ -22,6 +22,7 @@ import ( "context" "errors" "fmt" + "log/slog" "net/url" "sync" @@ -126,6 +127,7 @@ func New(config *Config) (*FerretDB, error) { h, closeBackend, err := registry.NewHandler(config.Handler, ®istry.NewHandlerOpts{ Logger: log, + SLogger: slog.Default(), // TODO https://github.com/FerretDB/FerretDB/issues/4013 ConnMetrics: metrics.ConnMetrics, StateProvider: sp, TCPHost: config.Listener.TCP, diff --git a/integration/setup/listener.go b/integration/setup/listener.go index 2d1e6e21b1a7..383e90a2071e 100644 --- a/integration/setup/listener.go +++ b/integration/setup/listener.go @@ -16,6 +16,7 @@ package setup import ( "context" + "log/slog" "net/url" "os" "path/filepath" @@ -179,6 +180,7 @@ func setupListener(tb testtb.TB, ctx context.Context, logger *zap.Logger, opts * handlerOpts := ®istry.NewHandlerOpts{ Logger: logger, + SLogger: slog.Default(), // TODO https://github.com/FerretDB/FerretDB/issues/4013 ConnMetrics: listenerMetrics.ConnMetrics, StateProvider: sp, diff --git a/internal/handler/cmd_query.go b/internal/handler/cmd_query.go index b569ccb029a9..927dd02a20e7 100644 --- a/internal/handler/cmd_query.go +++ b/internal/handler/cmd_query.go @@ -19,12 +19,11 @@ import ( "fmt" "strings" - "go.uber.org/zap" - "github.com/FerretDB/FerretDB/internal/handler/common" "github.com/FerretDB/FerretDB/internal/handler/handlererrors" "github.com/FerretDB/FerretDB/internal/types" "github.com/FerretDB/FerretDB/internal/util/lazyerrors" + "github.com/FerretDB/FerretDB/internal/util/logging" "github.com/FerretDB/FerretDB/internal/util/must" "github.com/FerretDB/FerretDB/internal/wire" ) @@ -75,7 +74,7 @@ func (h *Handler) CmdQuery(connCtx context.Context, query *wire.OpQuery) (*wire. dbName, err := common.GetRequiredParam[string](authDoc, "db") if err != nil { - h.L.Debug("No `db` in `speculativeAuthenticate`", zap.Error(err)) + h.L.DebugContext(connCtx, "No `db` in `speculativeAuthenticate`", logging.Error(err)) opReply.SetDocument(reply) @@ -84,7 +83,7 @@ func (h *Handler) CmdQuery(connCtx context.Context, query *wire.OpQuery) (*wire. speculativeAuthenticate, err := h.saslStart(connCtx, dbName, authDoc) if err != nil { - h.L.Debug("Speculative authentication failed", zap.Error(err)) + h.L.DebugContext(connCtx, "Speculative authentication failed", logging.Error(err)) // unsuccessful speculative authentication leave `speculativeAuthenticate` field unset // and let `saslStart` return an error @@ -93,7 +92,7 @@ func (h *Handler) CmdQuery(connCtx context.Context, query *wire.OpQuery) (*wire. return &opReply, nil } - h.L.Debug("Speculative authentication passed") + h.L.DebugContext(connCtx, "Speculative authentication passed") reply.Set("speculativeAuthenticate", speculativeAuthenticate) diff --git a/internal/handler/commands.go b/internal/handler/commands.go index c523c54b6bd2..98a39046b535 100644 --- a/internal/handler/commands.go +++ b/internal/handler/commands.go @@ -16,8 +16,7 @@ package handler import ( "context" - - "go.uber.org/zap" + "log/slog" "github.com/FerretDB/FerretDB/internal/clientconn/conninfo" "github.com/FerretDB/FerretDB/internal/handler/handlererrors" @@ -295,23 +294,25 @@ func (h *Handler) initCommands() { } // checkSCRAMConversation returns error if SCRAM conversation is not valid. -func checkSCRAMConversation(ctx context.Context, l *zap.Logger) error { +func checkSCRAMConversation(ctx context.Context, l *slog.Logger) error { _, _, conv, _ := conninfo.Get(ctx).Auth() switch { case conv == nil: - l.Warn("checkSCRAMConversation: no conversation") + l.WarnContext(ctx, "checkSCRAMConversation: no conversation") case !conv.Valid(): - l.Warn( + l.WarnContext( + ctx, "checkSCRAMConversation: invalid conversation", - zap.String("username", conv.Username()), zap.Bool("valid", conv.Valid()), zap.Bool("done", conv.Done()), + slog.String("username", conv.Username()), slog.Bool("valid", conv.Valid()), slog.Bool("done", conv.Done()), ) default: - l.Debug( + l.DebugContext( + ctx, "checkSCRAMConversation: passed", - zap.String("username", conv.Username()), zap.Bool("valid", conv.Valid()), zap.Bool("done", conv.Done()), + slog.String("username", conv.Username()), slog.Bool("valid", conv.Valid()), slog.Bool("done", conv.Done()), ) return nil diff --git a/internal/handler/common/count.go b/internal/handler/common/count.go index 642faeb14c0c..7cbdeeef6a05 100644 --- a/internal/handler/common/count.go +++ b/internal/handler/common/count.go @@ -15,7 +15,7 @@ package common import ( - "go.uber.org/zap" + "log/slog" "github.com/FerretDB/FerretDB/internal/handler/handlerparams" "github.com/FerretDB/FerretDB/internal/types" @@ -44,7 +44,7 @@ type CountParams struct { } // GetCountParams returns the parameters for the count command. -func GetCountParams(document *types.Document, l *zap.Logger) (*CountParams, error) { +func GetCountParams(document *types.Document, l *slog.Logger) (*CountParams, error) { var count CountParams err := handlerparams.ExtractParams(document, "count", &count, l) diff --git a/internal/handler/common/delete_params.go b/internal/handler/common/delete_params.go index 30e5dfa77eab..36e3d806176f 100644 --- a/internal/handler/common/delete_params.go +++ b/internal/handler/common/delete_params.go @@ -15,7 +15,7 @@ package common import ( - "go.uber.org/zap" + "log/slog" "github.com/FerretDB/FerretDB/internal/handler/handlerparams" "github.com/FerretDB/FerretDB/internal/types" @@ -55,7 +55,7 @@ type Delete struct { } // GetDeleteParams returns parameters for delete operation. -func GetDeleteParams(document *types.Document, l *zap.Logger) (*DeleteParams, error) { +func GetDeleteParams(document *types.Document, l *slog.Logger) (*DeleteParams, error) { params := DeleteParams{ Ordered: true, } diff --git a/internal/handler/common/distinct.go b/internal/handler/common/distinct.go index 66622c73c38c..e3e1f5435277 100644 --- a/internal/handler/common/distinct.go +++ b/internal/handler/common/distinct.go @@ -17,8 +17,7 @@ package common import ( "errors" "fmt" - - "go.uber.org/zap" + "log/slog" "github.com/FerretDB/FerretDB/internal/handler/commonpath" "github.com/FerretDB/FerretDB/internal/handler/handlererrors" @@ -49,7 +48,7 @@ type DistinctParams struct { } // GetDistinctParams returns `distinct` command parameters. -func GetDistinctParams(document *types.Document, l *zap.Logger) (*DistinctParams, error) { +func GetDistinctParams(document *types.Document, l *slog.Logger) (*DistinctParams, error) { var dp DistinctParams err := handlerparams.ExtractParams(document, "distinct", &dp, l) diff --git a/internal/handler/common/explain.go b/internal/handler/common/explain.go index 857c2b1cbf3f..14b28487741f 100644 --- a/internal/handler/common/explain.go +++ b/internal/handler/common/explain.go @@ -15,7 +15,7 @@ package common import ( - "go.uber.org/zap" + "log/slog" "github.com/FerretDB/FerretDB/internal/handler/handlererrors" "github.com/FerretDB/FerretDB/internal/handler/handlerparams" @@ -45,7 +45,7 @@ type ExplainParams struct { } // GetExplainParams returns the parameters for the explain command. -func GetExplainParams(document *types.Document, l *zap.Logger) (*ExplainParams, error) { +func GetExplainParams(document *types.Document, l *slog.Logger) (*ExplainParams, error) { var err error var db, collection string diff --git a/internal/handler/common/find.go b/internal/handler/common/find.go index ace9752043bf..4ee10a0d5947 100644 --- a/internal/handler/common/find.go +++ b/internal/handler/common/find.go @@ -15,7 +15,7 @@ package common import ( - "go.uber.org/zap" + "log/slog" "github.com/FerretDB/FerretDB/internal/handler/handlererrors" "github.com/FerretDB/FerretDB/internal/handler/handlerparams" @@ -65,7 +65,7 @@ type FindParams struct { } // GetFindParams returns `find` command parameters. -func GetFindParams(doc *types.Document, l *zap.Logger) (*FindParams, error) { +func GetFindParams(doc *types.Document, l *slog.Logger) (*FindParams, error) { params := FindParams{ BatchSize: 101, } diff --git a/internal/handler/common/findandmodify.go b/internal/handler/common/findandmodify.go index b11be8ed0765..0de40a780977 100644 --- a/internal/handler/common/findandmodify.go +++ b/internal/handler/common/findandmodify.go @@ -16,8 +16,7 @@ package common import ( "fmt" - - "go.uber.org/zap" + "log/slog" "github.com/FerretDB/FerretDB/internal/handler/handlererrors" "github.com/FerretDB/FerretDB/internal/handler/handlerparams" @@ -59,7 +58,7 @@ type FindAndModifyParams struct { } // GetFindAndModifyParams returns `findAndModifyParams` command parameters. -func GetFindAndModifyParams(doc *types.Document, l *zap.Logger) (*FindAndModifyParams, error) { +func GetFindAndModifyParams(doc *types.Document, l *slog.Logger) (*FindAndModifyParams, error) { var params FindAndModifyParams err := handlerparams.ExtractParams(doc, "findAndModify", ¶ms, l) diff --git a/internal/handler/common/insert.go b/internal/handler/common/insert.go index dcf6c087bab0..e63bdf770e1c 100644 --- a/internal/handler/common/insert.go +++ b/internal/handler/common/insert.go @@ -16,8 +16,7 @@ package common import ( "fmt" - - "go.uber.org/zap" + "log/slog" "github.com/FerretDB/FerretDB/internal/handler/handlererrors" "github.com/FerretDB/FerretDB/internal/handler/handlerparams" @@ -45,7 +44,7 @@ type InsertParams struct { } // GetInsertParams returns the parameters for an insert command. -func GetInsertParams(document *types.Document, l *zap.Logger) (*InsertParams, error) { +func GetInsertParams(document *types.Document, l *slog.Logger) (*InsertParams, error) { params := InsertParams{ Ordered: true, } diff --git a/internal/handler/common/unimplemented.go b/internal/handler/common/unimplemented.go index 153a23ae5ea5..c80f45a7c3cf 100644 --- a/internal/handler/common/unimplemented.go +++ b/internal/handler/common/unimplemented.go @@ -16,8 +16,7 @@ package common import ( "fmt" - - "go.uber.org/zap" + "log/slog" "github.com/FerretDB/FerretDB/internal/handler/handlererrors" "github.com/FerretDB/FerretDB/internal/types" @@ -60,12 +59,12 @@ func UnimplementedNonDefault(doc *types.Document, field string, isDefault func(v } // Ignored logs a message if doc has any of the given fields. -func Ignored(doc *types.Document, l *zap.Logger, fields ...string) { +func Ignored(doc *types.Document, l *slog.Logger, fields ...string) { for _, field := range fields { if v, err := doc.Get(field); err == nil { l.Debug( "ignoring field", - zap.String("command", doc.Command()), zap.String("field", field), zap.Any("value", v), + slog.String("command", doc.Command()), slog.String("field", field), slog.Any("value", v), ) } } diff --git a/internal/handler/common/update_params.go b/internal/handler/common/update_params.go index fc943a50481c..dd2c5fde7aec 100644 --- a/internal/handler/common/update_params.go +++ b/internal/handler/common/update_params.go @@ -15,7 +15,7 @@ package common import ( - "go.uber.org/zap" + "log/slog" "github.com/FerretDB/FerretDB/internal/handler/handlererrors" "github.com/FerretDB/FerretDB/internal/handler/handlerparams" @@ -84,7 +84,7 @@ type UpdateResult struct { } // GetUpdateParams returns parameters for update command. -func GetUpdateParams(document *types.Document, l *zap.Logger) (*UpdateParams, error) { +func GetUpdateParams(document *types.Document, l *slog.Logger) (*UpdateParams, error) { var params UpdateParams err := handlerparams.ExtractParams(document, "update", ¶ms, l) diff --git a/internal/handler/handler.go b/internal/handler/handler.go index 74b46eb3332e..8faeeda17a23 100644 --- a/internal/handler/handler.go +++ b/internal/handler/handler.go @@ -19,6 +19,7 @@ import ( "context" "errors" "fmt" + "log/slog" "sync" "time" @@ -35,6 +36,7 @@ import ( "github.com/FerretDB/FerretDB/internal/util/ctxutil" "github.com/FerretDB/FerretDB/internal/util/iterator" "github.com/FerretDB/FerretDB/internal/util/lazyerrors" + "github.com/FerretDB/FerretDB/internal/util/logging" "github.com/FerretDB/FerretDB/internal/util/must" "github.com/FerretDB/FerretDB/internal/util/password" "github.com/FerretDB/FerretDB/internal/util/state" @@ -88,7 +90,7 @@ type NewOpts struct { SetupPassword password.Password SetupTimeout time.Duration - L *zap.Logger + L *slog.Logger ConnMetrics *connmetrics.ConnMetrics StateProvider *state.Provider @@ -119,12 +121,12 @@ func New(opts *NewOpts) (*Handler, error) { opts.MaxBsonObjectSizeBytes = types.MaxDocumentLen } - b := oplog.NewBackend(opts.Backend, opts.L.Named("oplog")) + b := oplog.NewBackend(opts.Backend, zap.L().Named("oplog")) h := &Handler{ b: b, NewOpts: opts, - cursors: cursor.NewRegistry(opts.L.Named("cursors")), + cursors: cursor.NewRegistry(zap.L().Named("cursors")), cappedCleanupStop: make(chan struct{}), cleanupCappedCollectionsDocs: prometheus.NewCounterVec( @@ -184,7 +186,7 @@ func (h *Handler) setup() error { ctx = conninfo.Ctx(ctx, info) - l := h.L.Named("setup") + l := logging.WithName(h.L, "setup") var retry int64 @@ -194,7 +196,7 @@ func (h *Handler) setup() error { break } - l.Debug("Status failed", zap.Error(err)) + l.DebugContext(ctx, "Status failed", logging.Error(err)) retry++ ctxutil.SleepWithJitter(ctx, time.Second, retry) @@ -206,11 +208,16 @@ func (h *Handler) setup() error { } if len(res.Databases) > 0 { - l.Debug("Database already exists") + l.DebugContext(ctx, "Database already exists") return nil } - l.Info("Setting up database and user", zap.String("database", h.SetupDatabase), zap.String("username", h.SetupUsername)) + l.InfoContext( + ctx, + "Setting up database and user", + slog.String("database", h.SetupDatabase), + slog.String("username", h.SetupUsername), + ) db, err := h.b.Database(h.SetupDatabase) if err != nil { @@ -245,7 +252,7 @@ func (h *Handler) runCappedCleanup() { return } - h.L.Info("Capped collections cleanup enabled.", zap.Duration("interval", h.CappedCleanupInterval)) + h.L.Info("Capped collections cleanup enabled.", slog.Duration("interval", h.CappedCleanupInterval)) ticker := time.NewTicker(h.CappedCleanupInterval) defer ticker.Stop() @@ -254,7 +261,7 @@ func (h *Handler) runCappedCleanup() { select { case <-ticker.C: if err := h.cleanupAllCappedCollections(context.Background()); err != nil { - h.L.Error("Failed to cleanup capped collections.", zap.Error(err)) + h.L.Error("Failed to cleanup capped collections.", logging.Error(err)) } case <-h.cappedCleanupStop: @@ -290,11 +297,11 @@ func (h *Handler) Collect(ch chan<- prometheus.Metric) { // cleanupAllCappedCollections drops the given percent of documents from all capped collections. func (h *Handler) cleanupAllCappedCollections(ctx context.Context) error { - h.L.Debug("cleanupAllCappedCollections: started", zap.Uint8("percentage", h.CappedCleanupPercentage)) + h.L.DebugContext(ctx, "cleanupAllCappedCollections: started", slog.Any("percentage", h.CappedCleanupPercentage)) start := time.Now() defer func() { - h.L.Debug("cleanupAllCappedCollections: finished", zap.Duration("duration", time.Since(start))) + h.L.DebugContext(ctx, "cleanupAllCappedCollections: finished", slog.Duration("duration", time.Since(start))) }() connInfo := conninfo.New() @@ -333,9 +340,13 @@ func (h *Handler) cleanupAllCappedCollections(ctx context.Context) error { } if deleted > 0 || bytesFreed > 0 { - h.L.Info("Capped collection cleaned up.", - zap.String("db", dbInfo.Name), zap.String("collection", cInfo.Name), - zap.Int32("deleted", deleted), zap.Int64("bytesFreed", bytesFreed), + h.L.InfoContext( + ctx, + "Capped collection cleaned up.", + slog.String("db", dbInfo.Name), + slog.String("collection", cInfo.Name), + slog.Any("deleted", deleted), + slog.Int64("bytes_freed", bytesFreed), ) } @@ -364,7 +375,8 @@ func (h *Handler) cleanupCappedCollection(ctx context.Context, db backends.Datab if err != nil { return 0, 0, lazyerrors.Error(err) } - h.L.Debug("cleanupCappedCollection: stats before", zap.Any("stats", statsBefore)) + + h.L.DebugContext(ctx, "cleanupCappedCollection: stats before", slog.Any("stats", statsBefore)) // In order to be more precise w.r.t number of documents getting dropped and to avoid // deleting too many documents unnecessarily, @@ -385,7 +397,7 @@ func (h *Handler) cleanupCappedCollection(ctx context.Context, db backends.Datab return 0, 0, lazyerrors.Error(err) } - h.L.Debug("cleanupCappedCollection: stats after document count reduction", zap.Any("stats", statsAfter)) + h.L.DebugContext(ctx, "cleanupCappedCollection: stats after document count reduction", slog.Any("stats", statsAfter)) docsDeleted += int32(count) bytesFreed += (statsBefore.SizeTotal - statsAfter.SizeTotal) @@ -411,7 +423,7 @@ func (h *Handler) cleanupCappedCollection(ctx context.Context, db backends.Datab return 0, 0, lazyerrors.Error(err) } - h.L.Debug("cleanupCappedCollection: stats after compact", zap.Any("stats", statsAfter)) + h.L.DebugContext(ctx, "cleanupCappedCollection: stats after compact", slog.Any("stats", statsAfter)) bytesFreed += (statsBefore.SizeTotal - statsAfter.SizeTotal) diff --git a/internal/handler/handlerparams/extract_params.go b/internal/handler/handlerparams/extract_params.go index cac6aa9456b3..f247a04d9ae4 100644 --- a/internal/handler/handlerparams/extract_params.go +++ b/internal/handler/handlerparams/extract_params.go @@ -17,12 +17,11 @@ package handlerparams import ( "errors" "fmt" + "log/slog" "reflect" "slices" "strings" - "go.uber.org/zap" - "github.com/FerretDB/FerretDB/internal/handler/handlererrors" "github.com/FerretDB/FerretDB/internal/types" "github.com/FerretDB/FerretDB/internal/util/iterator" @@ -58,7 +57,7 @@ import ( // - `ErrBadValue` when field is out of integer range; // - `ErrBadValue` when field has negative value; // - `ErrInvalidNamespace` - collection name has invalid type. -func ExtractParams(doc *types.Document, command string, value any, l *zap.Logger) error { +func ExtractParams(doc *types.Document, command string, value any, l *slog.Logger) error { rv := reflect.ValueOf(value) if rv.Kind() != reflect.Ptr || rv.IsNil() { panic("value must be a non-nil pointer") @@ -107,7 +106,7 @@ func ExtractParams(doc *types.Document, command string, value any, l *zap.Logger if options.ignored { l.Debug( "ignoring field", - zap.String("command", doc.Command()), zap.String("field", key), zap.Any("value", val), + slog.String("command", doc.Command()), slog.String("field", key), slog.Any("value", val), ) continue @@ -229,7 +228,7 @@ func tagOptionsFromList(optionsList []string) *tagOptions { } // setStructField sets the value of the document field to the structure field. -func setStructField(elem *reflect.Value, o *tagOptions, i int, command, key string, val any, l *zap.Logger) error { +func setStructField(elem *reflect.Value, o *tagOptions, i int, command, key string, val any, l *slog.Logger) error { var err error field := elem.Type().Field(i) diff --git a/internal/handler/handlerparams/extract_params_test.go b/internal/handler/handlerparams/extract_params_test.go index 12c7f6660ee9..20036a9764b2 100644 --- a/internal/handler/handlerparams/extract_params_test.go +++ b/internal/handler/handlerparams/extract_params_test.go @@ -19,10 +19,10 @@ import ( "testing" "github.com/stretchr/testify/require" - "go.uber.org/zap" "github.com/FerretDB/FerretDB/internal/types" "github.com/FerretDB/FerretDB/internal/util/must" + "github.com/FerretDB/FerretDB/internal/util/testutil" ) func TestParse(t *testing.T) { @@ -369,7 +369,7 @@ func TestParse(t *testing.T) { } for name, tt := range tests { t.Run(name, func(t *testing.T) { - err := ExtractParams(tt.doc, tt.command, tt.params, zap.NewNop()) + err := ExtractParams(tt.doc, tt.command, tt.params, testutil.SLogger(t)) if tt.wantErr != "" { require.Regexp(t, regexp.MustCompile(".*"+tt.wantErr), err.Error()) return diff --git a/internal/handler/msg_aggregate.go b/internal/handler/msg_aggregate.go index 4855dfd68839..bf13813c35a1 100644 --- a/internal/handler/msg_aggregate.go +++ b/internal/handler/msg_aggregate.go @@ -18,13 +18,12 @@ import ( "context" "errors" "fmt" + "log/slog" "math" "os" "strings" "time" - "go.uber.org/zap" - "github.com/FerretDB/FerretDB/internal/backends" "github.com/FerretDB/FerretDB/internal/clientconn/conninfo" "github.com/FerretDB/FerretDB/internal/clientconn/cursor" @@ -381,9 +380,13 @@ func (h *Handler) MsgAggregate(connCtx context.Context, msg *wire.OpMsg) (*wire. return nil, handleMaxTimeMSError(err, maxTimeMS, "aggregate") } - h.L.Debug( - "Got first batch", zap.Int64("cursor_id", cursorID), zap.Stringer("type", cursor.Type), - zap.Int("count", len(docs)), zap.Int64("batch_size", batchSize), + h.L.DebugContext( + ctx, + "Got first batch", + slog.Int64("cursor_id", cursorID), + slog.Any("type", cursor.Type), + slog.Int("count", len(docs)), + slog.Int64("batch_size", batchSize), ) firstBatch := types.MakeArray(len(docs)) diff --git a/internal/handler/msg_find.go b/internal/handler/msg_find.go index 790f947ab8fe..13ace3920743 100644 --- a/internal/handler/msg_find.go +++ b/internal/handler/msg_find.go @@ -18,11 +18,10 @@ import ( "context" "errors" "fmt" + "log/slog" "strings" "time" - "go.uber.org/zap" - "github.com/FerretDB/FerretDB/internal/backends" "github.com/FerretDB/FerretDB/internal/clientconn/conninfo" "github.com/FerretDB/FerretDB/internal/clientconn/cursor" @@ -95,7 +94,7 @@ func (h *Handler) MsgFind(connCtx context.Context, msg *wire.OpMsg) (*wire.OpMsg } } - qp, err := h.makeFindQueryParams(params, &cInfo) + qp, err := h.makeFindQueryParams(connCtx, params, &cInfo) if err != nil { return nil, err } @@ -165,10 +164,14 @@ func (h *Handler) MsgFind(connCtx context.Context, msg *wire.OpMsg) (*wire.OpMsg return nil, handleMaxTimeMSError(err, params.MaxTimeMS, "find") } - h.L.Debug( - "Got first batch", zap.Int64("cursor_id", cursorID), zap.Stringer("type", c.Type), - zap.Int("count", len(docs)), zap.Int64("batch_size", params.BatchSize), - zap.Bool("single_batch", params.SingleBatch), + h.L.DebugContext( + ctx, + "Got first batch", + slog.Int64("cursor_id", cursorID), + slog.Any("type", c.Type), + slog.Int("count", len(docs)), + slog.Int64("batch_size", params.BatchSize), + slog.Bool("single_batch", params.SingleBatch), ) if params.SingleBatch || len(docs) < int(params.BatchSize) { @@ -210,7 +213,7 @@ type findCursorData struct { } // makeFindQueryParams creates the backend's query parameters for the find command. -func (h *Handler) makeFindQueryParams(params *common.FindParams, cInfo *backends.CollectionInfo) (*backends.QueryParams, error) { +func (h *Handler) makeFindQueryParams(ctx context.Context, params *common.FindParams, cInfo *backends.CollectionInfo) (*backends.QueryParams, error) { //nolint:lll // for readability qp := &backends.QueryParams{ Comment: params.Comment, } @@ -282,7 +285,9 @@ func (h *Handler) makeFindQueryParams(params *common.FindParams, cInfo *backends qp.Limit = params.Limit } - h.L.Sugar().Debugf("Converted %+v for %+v to %+v.", params, cInfo, qp) + if h.L.Enabled(ctx, slog.LevelDebug) { + h.L.DebugContext(ctx, fmt.Sprintf("Converted %+v for %+v to %+v.", params, cInfo, qp)) + } return qp, nil } diff --git a/internal/handler/msg_getlog.go b/internal/handler/msg_getlog.go index 51ff07d498e3..18bfab499d16 100644 --- a/internal/handler/msg_getlog.go +++ b/internal/handler/msg_getlog.go @@ -18,11 +18,10 @@ import ( "context" "encoding/json" "fmt" + "log/slog" "strings" "time" - "go.uber.org/zap" - "github.com/FerretDB/FerretDB/build/version" "github.com/FerretDB/FerretDB/internal/bson" "github.com/FerretDB/FerretDB/internal/handler/handlererrors" @@ -111,7 +110,7 @@ func (h *Handler) MsgGetLog(connCtx context.Context, msg *wire.OpMsg) (*wire.OpM startupWarnings = append(startupWarnings, "This is debug build. The performance will be affected.") } - if h.L.Level().Enabled(zap.DebugLevel) { + if h.L.Enabled(connCtx, slog.LevelDebug) { startupWarnings = append(startupWarnings, "Debug logging enabled. The security and performance will be affected.") } diff --git a/internal/handler/msg_getmore.go b/internal/handler/msg_getmore.go index bd4cd855dd2b..9f237964b75e 100644 --- a/internal/handler/msg_getmore.go +++ b/internal/handler/msg_getmore.go @@ -18,11 +18,10 @@ import ( "context" "errors" "fmt" + "log/slog" "math" "time" - "go.uber.org/zap" - "github.com/FerretDB/FerretDB/internal/backends" "github.com/FerretDB/FerretDB/internal/clientconn/conninfo" "github.com/FerretDB/FerretDB/internal/clientconn/cursor" @@ -284,8 +283,11 @@ func (h *Handler) makeNextBatch(c *cursor.Cursor, batchSize int64) (*types.Array } h.L.Debug( - "Got next batch", zap.Int64("cursor_id", c.ID), zap.Stringer("type", c.Type), - zap.Int("count", len(docs)), zap.Int64("batch_size", batchSize), + "Got next batch", + slog.Int64("cursor_id", c.ID), + slog.Any("type", c.Type), + slog.Int("count", len(docs)), + slog.Int64("batch_size", batchSize), ) nextBatch := types.MakeArray(len(docs)) diff --git a/internal/handler/msg_listdatabases.go b/internal/handler/msg_listdatabases.go index 3a3928f7533b..ff89e5cca8e4 100644 --- a/internal/handler/msg_listdatabases.go +++ b/internal/handler/msg_listdatabases.go @@ -17,12 +17,11 @@ package handler import ( "context" - "go.uber.org/zap" - "github.com/FerretDB/FerretDB/internal/handler/common" "github.com/FerretDB/FerretDB/internal/handler/handlerparams" "github.com/FerretDB/FerretDB/internal/types" "github.com/FerretDB/FerretDB/internal/util/lazyerrors" + "github.com/FerretDB/FerretDB/internal/util/logging" "github.com/FerretDB/FerretDB/internal/util/must" "github.com/FerretDB/FerretDB/internal/wire" ) @@ -66,13 +65,13 @@ func (h *Handler) MsgListDatabases(connCtx context.Context, msg *wire.OpMsg) (*w for _, dbInfo := range res.Databases { db, err := h.b.Database(dbInfo.Name) if err != nil { - h.L.Warn("Failed to get database", zap.Error(err)) + h.L.WarnContext(connCtx, "Failed to get database", logging.Error(err)) continue } stats, err := db.Stats(connCtx, nil) if err != nil { - h.L.Warn("Failed to get database stats", zap.Error(err)) + h.L.WarnContext(connCtx, "Failed to get database stats", logging.Error(err)) continue } diff --git a/internal/handler/msg_saslcontinue.go b/internal/handler/msg_saslcontinue.go index 8757d473f40b..836c201c6045 100644 --- a/internal/handler/msg_saslcontinue.go +++ b/internal/handler/msg_saslcontinue.go @@ -16,14 +16,14 @@ package handler import ( "context" - - "go.uber.org/zap" + "log/slog" "github.com/FerretDB/FerretDB/internal/clientconn/conninfo" "github.com/FerretDB/FerretDB/internal/handler/common" "github.com/FerretDB/FerretDB/internal/handler/handlererrors" "github.com/FerretDB/FerretDB/internal/types" "github.com/FerretDB/FerretDB/internal/util/lazyerrors" + "github.com/FerretDB/FerretDB/internal/util/logging" "github.com/FerretDB/FerretDB/internal/util/must" "github.com/FerretDB/FerretDB/internal/wire" ) @@ -49,7 +49,7 @@ func (h *Handler) MsgSASLContinue(connCtx context.Context, msg *wire.OpMsg) (*wi _, _, conv, _ := conninfo.Get(connCtx).Auth() if conv == nil { - h.L.Warn("saslContinue: no conversation to continue") + h.L.WarnContext(connCtx, "saslContinue: no conversation to continue") return nil, handlererrors.NewCommandErrorMsgWithArgument( handlererrors.ErrAuthenticationFailed, @@ -60,18 +60,18 @@ func (h *Handler) MsgSASLContinue(connCtx context.Context, msg *wire.OpMsg) (*wi response, err := conv.Step(string(payload)) - fields := []zap.Field{ - zap.String("username", conv.Username()), - zap.Bool("valid", conv.Valid()), - zap.Bool("done", conv.Done()), + attrs := []any{ + slog.String("username", conv.Username()), + slog.Bool("valid", conv.Valid()), + slog.Bool("done", conv.Done()), } if err != nil { - if h.L.Level().Enabled(zap.DebugLevel) { - fields = append(fields, zap.Error(err)) + if h.L.Enabled(connCtx, slog.LevelDebug) { + attrs = append(attrs, logging.Error(err)) } - h.L.Warn("saslContinue: step failed", fields...) + h.L.WarnContext(connCtx, "saslContinue: step failed", attrs...) //nolint:sloglint // attrs is not key-value pairs return nil, handlererrors.NewCommandErrorMsgWithArgument( handlererrors.ErrAuthenticationFailed, @@ -80,7 +80,7 @@ func (h *Handler) MsgSASLContinue(connCtx context.Context, msg *wire.OpMsg) (*wi ) } - h.L.Debug("saslContinue: step succeed", fields...) + h.L.DebugContext(connCtx, "saslContinue: step succeed", attrs...) //nolint:sloglint // attrs is not key-value pairs if conv.Valid() { conninfo.Get(connCtx).SetBypassBackendAuth() diff --git a/internal/handler/msg_saslstart.go b/internal/handler/msg_saslstart.go index 2719e2379d85..aafd452a302f 100644 --- a/internal/handler/msg_saslstart.go +++ b/internal/handler/msg_saslstart.go @@ -20,9 +20,9 @@ import ( "encoding/base64" "errors" "fmt" + "log/slog" "github.com/xdg-go/scram" - "go.uber.org/zap" "github.com/FerretDB/FerretDB/internal/clientconn/conninfo" "github.com/FerretDB/FerretDB/internal/handler/common" @@ -30,6 +30,7 @@ import ( "github.com/FerretDB/FerretDB/internal/types" "github.com/FerretDB/FerretDB/internal/util/iterator" "github.com/FerretDB/FerretDB/internal/util/lazyerrors" + "github.com/FerretDB/FerretDB/internal/util/logging" "github.com/FerretDB/FerretDB/internal/util/must" "github.com/FerretDB/FerretDB/internal/wire" ) @@ -232,7 +233,7 @@ func (h *Handler) scramCredentialLookup(ctx context.Context, dbName, username, m } } - h.L.Warn("scramCredentialLookup: failed", zap.String("user", username)) + h.L.WarnContext(ctx, "scramCredentialLookup: failed", slog.String("user", username)) return nil, handlererrors.NewCommandErrorMsgWithArgument( handlererrors.ErrAuthenticationFailed, @@ -281,23 +282,23 @@ func (h *Handler) saslStartSCRAM(ctx context.Context, dbName, mechanism string, response, err := conv.Step(string(payload)) - fields := []zap.Field{ - zap.String("username", conv.Username()), - zap.Bool("valid", conv.Valid()), - zap.Bool("done", conv.Done()), + attrs := []any{ + slog.String("username", conv.Username()), + slog.Bool("valid", conv.Valid()), + slog.Bool("done", conv.Done()), } if err != nil { - if h.L.Level().Enabled(zap.DebugLevel) { - fields = append(fields, zap.Error(err)) + if h.L.Enabled(ctx, slog.LevelDebug) { + attrs = append(attrs, logging.Error(err)) } - h.L.Warn("saslStartSCRAM: step failed", fields...) + h.L.WarnContext(ctx, "saslStartSCRAM: step failed", attrs...) //nolint:sloglint // attrs is not key-value pairs return "", err } - h.L.Debug("saslStartSCRAM: step succeed", fields...) + h.L.DebugContext(ctx, "saslStartSCRAM: step succeed", attrs...) //nolint:sloglint // attrs is not key-value pairs conninfo.Get(ctx).SetAuth(conv.Username(), "", conv, dbName) diff --git a/internal/handler/registry/hana.go b/internal/handler/registry/hana.go index e7f7c0343cc8..f9dfb7535ff8 100644 --- a/internal/handler/registry/hana.go +++ b/internal/handler/registry/hana.go @@ -20,6 +20,7 @@ import ( "github.com/FerretDB/FerretDB/internal/backends/hana" "github.com/FerretDB/FerretDB/internal/handler" "github.com/FerretDB/FerretDB/internal/util/lazyerrors" + "github.com/FerretDB/FerretDB/internal/util/logging" ) // init registers "hana" handler for Hana when "ferretdb_hana" build tag is provided. @@ -47,7 +48,7 @@ func init() { SetupPassword: opts.SetupPassword, SetupTimeout: opts.SetupTimeout, - L: opts.Logger.Named("hana"), + L: logging.WithName(opts.SLogger, "hana"), ConnMetrics: opts.ConnMetrics, StateProvider: opts.StateProvider, diff --git a/internal/handler/registry/mysql.go b/internal/handler/registry/mysql.go index 6d2636c31ad9..ad198681c131 100644 --- a/internal/handler/registry/mysql.go +++ b/internal/handler/registry/mysql.go @@ -18,6 +18,7 @@ import ( "github.com/FerretDB/FerretDB/internal/backends/mysql" "github.com/FerretDB/FerretDB/internal/handler" "github.com/FerretDB/FerretDB/internal/util/lazyerrors" + "github.com/FerretDB/FerretDB/internal/util/logging" ) // init registers "mysql" handler. @@ -42,7 +43,7 @@ func init() { SetupPassword: opts.SetupPassword, SetupTimeout: opts.SetupTimeout, - L: opts.Logger.Named("mysql"), + L: logging.WithName(opts.SLogger, "mysql"), ConnMetrics: opts.ConnMetrics, StateProvider: opts.StateProvider, diff --git a/internal/handler/registry/postgresql.go b/internal/handler/registry/postgresql.go index 2ee11d2abf2f..6fec2dc82263 100644 --- a/internal/handler/registry/postgresql.go +++ b/internal/handler/registry/postgresql.go @@ -20,6 +20,7 @@ import ( "github.com/FerretDB/FerretDB/internal/backends/postgresql" "github.com/FerretDB/FerretDB/internal/handler" "github.com/FerretDB/FerretDB/internal/util/lazyerrors" + "github.com/FerretDB/FerretDB/internal/util/logging" ) // init registers "postgresql" handler. @@ -45,7 +46,7 @@ func init() { SetupPassword: opts.SetupPassword, SetupTimeout: opts.SetupTimeout, - L: opts.Logger.Named("postgresql"), + L: logging.WithName(opts.SLogger, "postgresql"), ConnMetrics: opts.ConnMetrics, StateProvider: opts.StateProvider, diff --git a/internal/handler/registry/registry.go b/internal/handler/registry/registry.go index 4cf1ec6a8416..d835cfc60a75 100644 --- a/internal/handler/registry/registry.go +++ b/internal/handler/registry/registry.go @@ -17,6 +17,7 @@ package registry import ( "fmt" + "log/slog" "time" "go.uber.org/zap" @@ -43,6 +44,7 @@ var registry = map[string]newHandlerFunc{} type NewHandlerOpts struct { // for all backends Logger *zap.Logger + SLogger *slog.Logger ConnMetrics *connmetrics.ConnMetrics StateProvider *state.Provider TCPHost string diff --git a/internal/handler/registry/sqlite.go b/internal/handler/registry/sqlite.go index eb9ce38433af..aab062e84400 100644 --- a/internal/handler/registry/sqlite.go +++ b/internal/handler/registry/sqlite.go @@ -20,6 +20,7 @@ import ( "github.com/FerretDB/FerretDB/internal/backends/sqlite" "github.com/FerretDB/FerretDB/internal/handler" "github.com/FerretDB/FerretDB/internal/util/lazyerrors" + "github.com/FerretDB/FerretDB/internal/util/logging" ) // init registers "sqlite" handler. @@ -45,7 +46,7 @@ func init() { SetupPassword: opts.SetupPassword, SetupTimeout: opts.SetupTimeout, - L: opts.Logger.Named("sqlite"), + L: logging.WithName(opts.SLogger, "sqlite"), ConnMetrics: opts.ConnMetrics, StateProvider: opts.StateProvider, From 4607329179ac7c0fc032271c509106622e6b2f0f Mon Sep 17 00:00:00 2001 From: Chi Fujii Date: Thu, 18 Jul 2024 11:48:35 +0900 Subject: [PATCH 02/11] avoid using Any --- internal/handler/handler.go | 4 ++-- internal/handler/msg_aggregate.go | 2 +- internal/handler/msg_find.go | 2 +- internal/handler/msg_getmore.go | 2 +- 4 files changed, 5 insertions(+), 5 deletions(-) diff --git a/internal/handler/handler.go b/internal/handler/handler.go index 8faeeda17a23..906fa413c5e3 100644 --- a/internal/handler/handler.go +++ b/internal/handler/handler.go @@ -297,7 +297,7 @@ func (h *Handler) Collect(ch chan<- prometheus.Metric) { // cleanupAllCappedCollections drops the given percent of documents from all capped collections. func (h *Handler) cleanupAllCappedCollections(ctx context.Context) error { - h.L.DebugContext(ctx, "cleanupAllCappedCollections: started", slog.Any("percentage", h.CappedCleanupPercentage)) + h.L.DebugContext(ctx, "cleanupAllCappedCollections: started", slog.Int("percentage", int(h.CappedCleanupPercentage))) start := time.Now() defer func() { @@ -345,7 +345,7 @@ func (h *Handler) cleanupAllCappedCollections(ctx context.Context) error { "Capped collection cleaned up.", slog.String("db", dbInfo.Name), slog.String("collection", cInfo.Name), - slog.Any("deleted", deleted), + slog.Int("deleted", int(deleted)), slog.Int64("bytes_freed", bytesFreed), ) } diff --git a/internal/handler/msg_aggregate.go b/internal/handler/msg_aggregate.go index bf13813c35a1..ab9aec38edd3 100644 --- a/internal/handler/msg_aggregate.go +++ b/internal/handler/msg_aggregate.go @@ -384,7 +384,7 @@ func (h *Handler) MsgAggregate(connCtx context.Context, msg *wire.OpMsg) (*wire. ctx, "Got first batch", slog.Int64("cursor_id", cursorID), - slog.Any("type", cursor.Type), + slog.String("type", cursor.Type.String()), slog.Int("count", len(docs)), slog.Int64("batch_size", batchSize), ) diff --git a/internal/handler/msg_find.go b/internal/handler/msg_find.go index 13ace3920743..8e9cbdf056f0 100644 --- a/internal/handler/msg_find.go +++ b/internal/handler/msg_find.go @@ -168,7 +168,7 @@ func (h *Handler) MsgFind(connCtx context.Context, msg *wire.OpMsg) (*wire.OpMsg ctx, "Got first batch", slog.Int64("cursor_id", cursorID), - slog.Any("type", c.Type), + slog.String("type", c.Type.String()), slog.Int("count", len(docs)), slog.Int64("batch_size", params.BatchSize), slog.Bool("single_batch", params.SingleBatch), diff --git a/internal/handler/msg_getmore.go b/internal/handler/msg_getmore.go index 9f237964b75e..00e9be3d004d 100644 --- a/internal/handler/msg_getmore.go +++ b/internal/handler/msg_getmore.go @@ -285,7 +285,7 @@ func (h *Handler) makeNextBatch(c *cursor.Cursor, batchSize int64) (*types.Array h.L.Debug( "Got next batch", slog.Int64("cursor_id", c.ID), - slog.Any("type", c.Type), + slog.String("type", c.Type.String()), slog.Int("count", len(docs)), slog.Int64("batch_size", batchSize), ) From 4b53f0c4c9a00cf1079afd8daf83be2062ff0d7e Mon Sep 17 00:00:00 2001 From: Chi Fujii Date: Thu, 18 Jul 2024 12:31:56 +0900 Subject: [PATCH 03/11] use slog in debug package --- cmd/envtool/envtool.go | 2 +- cmd/ferretdb/main.go | 6 +++--- cmd/ferretdb/ping.go | 34 +++++++++++++++++-------------- internal/util/debug/debug.go | 33 +++++++++++++++++------------- internal/util/debug/debug_test.go | 2 +- 5 files changed, 43 insertions(+), 34 deletions(-) diff --git a/cmd/envtool/envtool.go b/cmd/envtool/envtool.go index a6ba19b55788..f00eba5fe5f7 100644 --- a/cmd/envtool/envtool.go +++ b/cmd/envtool/envtool.go @@ -255,7 +255,7 @@ func setupMongodbSecured(ctx context.Context, logger *zap.SugaredLogger) error { func setup(ctx context.Context, logger *zap.SugaredLogger) error { h, err := debug.Listen(&debug.ListenOpts{ TCPAddr: "127.0.0.1:8089", - L: logger.Named("debug").Desugar(), + L: logging.WithName(slog.Default(), "debug"), // TODO https://github.com/FerretDB/FerretDB/issues/4013 R: prometheus.DefaultRegisterer, }) if err != nil { diff --git a/cmd/ferretdb/main.go b/cmd/ferretdb/main.go index 915a99fe47c2..ca8d987748c2 100644 --- a/cmd/ferretdb/main.go +++ b/cmd/ferretdb/main.go @@ -225,7 +225,7 @@ func main() { checkFlags(logger) ready := ReadyZ{ - l: logger, + l: slog.Default(), // TODO https://github.com/FerretDB/FerretDB/issues/4013 } ctx, stop := ctxutil.SigTerm(context.Background()) @@ -419,7 +419,7 @@ func run() { go func() { defer wg.Done() - l := logger.Named("debug") + l := logging.WithName(slogger, "debug") ready := ReadyZ{ l: l, } @@ -438,7 +438,7 @@ func run() { Readyz: ready.Probe, }) if err != nil { - l.Sugar().Fatalf("Failed to create debug handler: %s.", err) + l.LogAttrs(ctx, logging.LevelFatal, "Failed to create debug handler", logging.Error(err)) } h.Serve(ctx) diff --git a/cmd/ferretdb/ping.go b/cmd/ferretdb/ping.go index e827daaee7e3..8b833546ba4a 100644 --- a/cmd/ferretdb/ping.go +++ b/cmd/ferretdb/ping.go @@ -16,18 +16,21 @@ package main import ( "context" + "fmt" + "log/slog" "net" "net/url" "go.mongodb.org/mongo-driver/mongo" "go.mongodb.org/mongo-driver/mongo/options" - "go.uber.org/zap" + + "github.com/FerretDB/FerretDB/internal/util/logging" ) // ReadyZ represents the Readiness probe, which is used to run `ping` // command against the FerretDB instance specified by cli flags. type ReadyZ struct { - l *zap.Logger + l *slog.Logger } // Probe executes ping queries to open listeners, and returns true if they succeed. @@ -38,7 +41,7 @@ func (ready *ReadyZ) Probe(ctx context.Context) bool { l := ready.l if cli.Setup.Database == "" { - l.Info("Setup database not specified - skipping ping.") + l.InfoContext(ctx, "Setup database not specified - skipping ping") return true } @@ -47,16 +50,16 @@ func (ready *ReadyZ) Probe(ctx context.Context) bool { if cli.Listen.Addr != "" { host, port, err := net.SplitHostPort(cli.Listen.Addr) if err != nil { - l.Error("Getting host and port failed.", zap.Error(err)) + l.ErrorContext(ctx, "Getting host and port failed", logging.Error(err)) return false } - l.Sugar().Debugf("--listen-addr flag is set. Ping to %s will be performed.", cli.Listen.Addr) + l.DebugContext(ctx, fmt.Sprintf("--listen-addr flag is set. Ping to %s will be performed", cli.Listen.Addr)) if host == "" { host = "127.0.0.1" - l.Sugar().Debugf("Host not specified, defaulting to %s.", host) + l.DebugContext(ctx, fmt.Sprintf("Host not specified, defaulting to %s", host)) } u := &url.URL{ @@ -71,29 +74,30 @@ func (ready *ReadyZ) Probe(ctx context.Context) bool { if cli.Listen.TLS != "" { // TODO https://github.com/FerretDB/FerretDB/issues/4427 - l.Warn("TLS ping is not implemented yet.") + l.WarnContext(ctx, "TLS ping is not implemented yet") } if cli.Listen.Unix != "" { - l.Sugar().Debugf("--listen-unix flag is set. Ping to %s will be performed.", cli.Listen.Unix) + l.DebugContext(ctx, fmt.Sprintf("--listen-addr flag is set. Ping to %s will be performed", cli.Listen.Addr)) urls = append(urls, "mongodb://"+url.PathEscape(cli.Listen.Unix)) } if len(urls) == 0 { - l.Info("Neither --listen-addr nor --listen-unix nor --listen-tls flags were specified - skipping ping.") + l.WarnContext(ctx, "Neither --listen-addr nor --listen-unix nor --listen-tls flags were specified - skipping ping.") return true } for _, u := range urls { - l.Sugar().Debugf("Pinging %s...", u) + l.DebugContext(ctx, fmt.Sprintf("Pinging %s...", u)) - ctx, cancel := context.WithTimeout(ctx, cli.Setup.Timeout) + var cancel func() + ctx, cancel = context.WithTimeout(ctx, cli.Setup.Timeout) defer cancel() client, err := mongo.Connect(ctx, options.Client().ApplyURI(u)) if err != nil { - l.Error("Connection failed.", zap.Error(err)) + l.ErrorContext(ctx, "Connection failed", logging.Error(err)) return false } @@ -101,12 +105,12 @@ func (ready *ReadyZ) Probe(ctx context.Context) bool { // do not leave connection open when ping error causes os.Exit with Fatal if err = client.Disconnect(ctx); err != nil { - l.Error("Disconnect failed.", zap.Error(err)) + l.ErrorContext(ctx, "Disconnect failed", logging.Error(err)) return false } if pingErr != nil { - l.Error("Ping failed.", zap.Error(pingErr)) + l.ErrorContext(ctx, "Ping failed", logging.Error(pingErr)) return false } @@ -115,7 +119,7 @@ func (ready *ReadyZ) Probe(ctx context.Context) bool { u = uri.Redacted() } - l.Sugar().Infof("Ping to %s successful.", u) + l.InfoContext(ctx, fmt.Sprintf("Ping to %s successful", u)) } return true diff --git a/internal/util/debug/debug.go b/internal/util/debug/debug.go index 54d7f8e29910..ff960b65d28e 100644 --- a/internal/util/debug/debug.go +++ b/internal/util/debug/debug.go @@ -22,6 +22,7 @@ import ( _ "expvar" // for metrics "fmt" "log" + "log/slog" "net" "net/http" _ "net/http/pprof" // for profiling @@ -32,11 +33,11 @@ import ( "github.com/arl/statsviz" "github.com/prometheus/client_golang/prometheus" "github.com/prometheus/client_golang/prometheus/promhttp" - "go.uber.org/zap" "golang.org/x/exp/maps" "github.com/FerretDB/FerretDB/internal/util/ctxutil" "github.com/FerretDB/FerretDB/internal/util/lazyerrors" + "github.com/FerretDB/FerretDB/internal/util/logging" "github.com/FerretDB/FerretDB/internal/util/must" ) @@ -70,7 +71,7 @@ type Handler struct { //nolint:vet // for readability type ListenOpts struct { TCPAddr string - L *zap.Logger + L *slog.Logger R prometheus.Registerer Livez Probe Readyz Probe @@ -86,7 +87,9 @@ func Listen(opts *ListenOpts) (*Handler, error) { must.NotBeZero(opts) - stdL := must.NotFail(zap.NewStdLogAt(opts.L, zap.WarnLevel)) + l := opts.L + + stdL := slog.NewLogLogger(l.Handler(), slog.LevelError) http.Handle("/debug/metrics", promhttp.InstrumentMetricHandler( opts.R, promhttp.HandlerFor(prometheus.DefaultGatherer, promhttp.HandlerOpts{ @@ -122,13 +125,13 @@ func Listen(opts *ListenOpts) (*Handler, error) { ctx := req.Context() if !opts.Livez(ctx) { - opts.L.Warn("Livez probe failed") + l.Warn("Livez probe failed") rw.WriteHeader(http.StatusInternalServerError) return } - opts.L.Debug("Livez probe succeeded") + l.Debug("Livez probe succeeded") rw.WriteHeader(http.StatusOK) }), )) @@ -139,20 +142,20 @@ func Listen(opts *ListenOpts) (*Handler, error) { ctx := req.Context() if !opts.Livez(ctx) { - opts.L.Warn("Readyz probe failed - livez probe failed") + l.Warn("Readyz probe failed - livez probe failed") rw.WriteHeader(http.StatusInternalServerError) return } if !opts.Readyz(ctx) { - opts.L.Warn("Readyz probe failed") + l.Warn("Readyz probe failed") rw.WriteHeader(http.StatusInternalServerError) return } - opts.L.Debug("Readyz probe succeeded") + l.Debug("Readyz probe succeeded") rw.WriteHeader(http.StatusOK) }), )) @@ -216,20 +219,22 @@ func (h *Handler) Serve(ctx context.Context) { }, } + l := h.opts.L + root := fmt.Sprintf("http://%s", h.lis.Addr()) - h.opts.L.Sugar().Infof("Starting debug server on %s...", root) + l.InfoContext(ctx, fmt.Sprintf("Starting debug server on %s...", root)) paths := maps.Keys(h.handlers) slices.Sort(paths) for _, path := range paths { - h.opts.L.Sugar().Infof("%s%s - %s", root, path, h.handlers[path]) + l.InfoContext(ctx, fmt.Sprintf("%s%s - %s", root, path, h.handlers[path])) } go func() { if err := s.Serve(h.lis); !errors.Is(err, http.ErrServerClosed) { - h.opts.L.DPanic("Serve exited with unexpected error", zap.Error(err)) + l.LogAttrs(ctx, logging.LevelDPanic, "Serve exited with unexpected error", logging.Error(err)) } }() @@ -240,12 +245,12 @@ func (h *Handler) Serve(ctx context.Context) { defer stopCancel(nil) if err := s.Shutdown(stopCtx); err != nil { - h.opts.L.DPanic("Shutdown exited with unexpected error", zap.Error(err)) + l.LogAttrs(ctx, logging.LevelDPanic, "Shutdown exited with unexpected error", logging.Error(err)) } if err := s.Close(); err != nil { - h.opts.L.DPanic("Close exited with unexpected error", zap.Error(err)) + l.LogAttrs(ctx, logging.LevelDPanic, "Close exited with unexpected error", logging.Error(err)) } - h.opts.L.Sugar().Info("Debug server stopped.") + l.InfoContext(ctx, "Debug server stopped") } diff --git a/internal/util/debug/debug_test.go b/internal/util/debug/debug_test.go index 034500a62c7c..978aeee3c68c 100644 --- a/internal/util/debug/debug_test.go +++ b/internal/util/debug/debug_test.go @@ -43,7 +43,7 @@ func TestProbes(t *testing.T) { h, err := Listen(&ListenOpts{ TCPAddr: "127.0.0.1:0", - L: testutil.Logger(t), + L: testutil.SLogger(t), R: prometheus.NewRegistry(), Livez: func(context.Context) bool { return livez.Load() }, Readyz: func(context.Context) bool { return readyz.Load() }, From 973060e651c14ae81071fb9e5dc54306fbcaad70 Mon Sep 17 00:00:00 2001 From: Chi Fujii Date: Thu, 18 Jul 2024 12:34:25 +0900 Subject: [PATCH 04/11] use slog in debug integration test startup --- integration/setup/startup.go | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/integration/setup/startup.go b/integration/setup/startup.go index 5541cbc9d409..411f6418e0ca 100644 --- a/integration/setup/startup.go +++ b/integration/setup/startup.go @@ -16,6 +16,7 @@ package setup import ( "context" + "log/slog" "os" "runtime" "slices" @@ -58,7 +59,7 @@ 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: zap.L().Named("debug"), + L: logging.WithName(slog.Default(), "debug"), // TODO https://github.com/FerretDB/FerretDB/issues/4013 R: prometheus.DefaultRegisterer, }) if err != nil { From 044a566c14463de173e1e2fb75bd3363bed55fd0 Mon Sep 17 00:00:00 2001 From: Chi Fujii Date: Thu, 18 Jul 2024 12:36:45 +0900 Subject: [PATCH 05/11] Revert "avoid using Any" This reverts commit 4607329179ac7c0fc032271c509106622e6b2f0f. --- internal/handler/handler.go | 4 ++-- internal/handler/msg_aggregate.go | 2 +- internal/handler/msg_find.go | 2 +- internal/handler/msg_getmore.go | 2 +- 4 files changed, 5 insertions(+), 5 deletions(-) diff --git a/internal/handler/handler.go b/internal/handler/handler.go index 906fa413c5e3..8faeeda17a23 100644 --- a/internal/handler/handler.go +++ b/internal/handler/handler.go @@ -297,7 +297,7 @@ func (h *Handler) Collect(ch chan<- prometheus.Metric) { // cleanupAllCappedCollections drops the given percent of documents from all capped collections. func (h *Handler) cleanupAllCappedCollections(ctx context.Context) error { - h.L.DebugContext(ctx, "cleanupAllCappedCollections: started", slog.Int("percentage", int(h.CappedCleanupPercentage))) + h.L.DebugContext(ctx, "cleanupAllCappedCollections: started", slog.Any("percentage", h.CappedCleanupPercentage)) start := time.Now() defer func() { @@ -345,7 +345,7 @@ func (h *Handler) cleanupAllCappedCollections(ctx context.Context) error { "Capped collection cleaned up.", slog.String("db", dbInfo.Name), slog.String("collection", cInfo.Name), - slog.Int("deleted", int(deleted)), + slog.Any("deleted", deleted), slog.Int64("bytes_freed", bytesFreed), ) } diff --git a/internal/handler/msg_aggregate.go b/internal/handler/msg_aggregate.go index ab9aec38edd3..bf13813c35a1 100644 --- a/internal/handler/msg_aggregate.go +++ b/internal/handler/msg_aggregate.go @@ -384,7 +384,7 @@ func (h *Handler) MsgAggregate(connCtx context.Context, msg *wire.OpMsg) (*wire. ctx, "Got first batch", slog.Int64("cursor_id", cursorID), - slog.String("type", cursor.Type.String()), + slog.Any("type", cursor.Type), slog.Int("count", len(docs)), slog.Int64("batch_size", batchSize), ) diff --git a/internal/handler/msg_find.go b/internal/handler/msg_find.go index 8e9cbdf056f0..13ace3920743 100644 --- a/internal/handler/msg_find.go +++ b/internal/handler/msg_find.go @@ -168,7 +168,7 @@ func (h *Handler) MsgFind(connCtx context.Context, msg *wire.OpMsg) (*wire.OpMsg ctx, "Got first batch", slog.Int64("cursor_id", cursorID), - slog.String("type", c.Type.String()), + slog.Any("type", c.Type), slog.Int("count", len(docs)), slog.Int64("batch_size", params.BatchSize), slog.Bool("single_batch", params.SingleBatch), diff --git a/internal/handler/msg_getmore.go b/internal/handler/msg_getmore.go index 00e9be3d004d..9f237964b75e 100644 --- a/internal/handler/msg_getmore.go +++ b/internal/handler/msg_getmore.go @@ -285,7 +285,7 @@ func (h *Handler) makeNextBatch(c *cursor.Cursor, batchSize int64) (*types.Array h.L.Debug( "Got next batch", slog.Int64("cursor_id", c.ID), - slog.String("type", c.Type.String()), + slog.Any("type", c.Type), slog.Int("count", len(docs)), slog.Int64("batch_size", batchSize), ) From a48bae6981f96f44c974268368e11b6f92c5aeb7 Mon Sep 17 00:00:00 2001 From: Chi Fujii Date: Thu, 18 Jul 2024 12:36:53 +0900 Subject: [PATCH 06/11] Revert "use slog in handler" This reverts commit 16c05af75cd077f2d211952cd9d4f41f3d21e95a. --- cmd/ferretdb/main.go | 1 - ferretdb/ferretdb.go | 2 - integration/setup/listener.go | 2 - internal/handler/cmd_query.go | 9 ++-- internal/handler/commands.go | 17 ++++--- internal/handler/common/count.go | 4 +- internal/handler/common/delete_params.go | 4 +- internal/handler/common/distinct.go | 5 +- internal/handler/common/explain.go | 4 +- internal/handler/common/find.go | 4 +- internal/handler/common/findandmodify.go | 5 +- internal/handler/common/insert.go | 5 +- internal/handler/common/unimplemented.go | 7 +-- internal/handler/common/update_params.go | 4 +- internal/handler/handler.go | 46 +++++++------------ .../handler/handlerparams/extract_params.go | 9 ++-- .../handlerparams/extract_params_test.go | 4 +- internal/handler/msg_aggregate.go | 13 ++---- internal/handler/msg_find.go | 23 ++++------ internal/handler/msg_getlog.go | 5 +- internal/handler/msg_getmore.go | 10 ++-- internal/handler/msg_listdatabases.go | 7 +-- internal/handler/msg_saslcontinue.go | 22 ++++----- internal/handler/msg_saslstart.go | 21 ++++----- internal/handler/registry/hana.go | 3 +- internal/handler/registry/mysql.go | 3 +- internal/handler/registry/postgresql.go | 3 +- internal/handler/registry/registry.go | 2 - internal/handler/registry/sqlite.go | 3 +- 29 files changed, 110 insertions(+), 137 deletions(-) diff --git a/cmd/ferretdb/main.go b/cmd/ferretdb/main.go index ca8d987748c2..b05b3cacae92 100644 --- a/cmd/ferretdb/main.go +++ b/cmd/ferretdb/main.go @@ -498,7 +498,6 @@ func run() { h, closeBackend, err := registry.NewHandler(cli.Handler, ®istry.NewHandlerOpts{ Logger: logger, - SLogger: slogger, ConnMetrics: metrics.ConnMetrics, StateProvider: stateProvider, TCPHost: cli.Listen.Addr, diff --git a/ferretdb/ferretdb.go b/ferretdb/ferretdb.go index 5032010e4460..32e042df3c59 100644 --- a/ferretdb/ferretdb.go +++ b/ferretdb/ferretdb.go @@ -22,7 +22,6 @@ import ( "context" "errors" "fmt" - "log/slog" "net/url" "sync" @@ -129,7 +128,6 @@ func New(config *Config) (*FerretDB, error) { h, closeBackend, err := registry.NewHandler(config.Handler, ®istry.NewHandlerOpts{ Logger: log, - SLogger: slog.Default(), // TODO https://github.com/FerretDB/FerretDB/issues/4013 ConnMetrics: metrics.ConnMetrics, StateProvider: sp, TCPHost: config.Listener.TCP, diff --git a/integration/setup/listener.go b/integration/setup/listener.go index 3699eb188f2e..b30fe022f149 100644 --- a/integration/setup/listener.go +++ b/integration/setup/listener.go @@ -16,7 +16,6 @@ package setup import ( "context" - "log/slog" "net/url" "os" "path/filepath" @@ -180,7 +179,6 @@ func setupListener(tb testtb.TB, ctx context.Context, logger *zap.Logger, opts * handlerOpts := ®istry.NewHandlerOpts{ Logger: logger, - SLogger: slog.Default(), // TODO https://github.com/FerretDB/FerretDB/issues/4013 ConnMetrics: listenerMetrics.ConnMetrics, StateProvider: sp, diff --git a/internal/handler/cmd_query.go b/internal/handler/cmd_query.go index 927dd02a20e7..b569ccb029a9 100644 --- a/internal/handler/cmd_query.go +++ b/internal/handler/cmd_query.go @@ -19,11 +19,12 @@ import ( "fmt" "strings" + "go.uber.org/zap" + "github.com/FerretDB/FerretDB/internal/handler/common" "github.com/FerretDB/FerretDB/internal/handler/handlererrors" "github.com/FerretDB/FerretDB/internal/types" "github.com/FerretDB/FerretDB/internal/util/lazyerrors" - "github.com/FerretDB/FerretDB/internal/util/logging" "github.com/FerretDB/FerretDB/internal/util/must" "github.com/FerretDB/FerretDB/internal/wire" ) @@ -74,7 +75,7 @@ func (h *Handler) CmdQuery(connCtx context.Context, query *wire.OpQuery) (*wire. dbName, err := common.GetRequiredParam[string](authDoc, "db") if err != nil { - h.L.DebugContext(connCtx, "No `db` in `speculativeAuthenticate`", logging.Error(err)) + h.L.Debug("No `db` in `speculativeAuthenticate`", zap.Error(err)) opReply.SetDocument(reply) @@ -83,7 +84,7 @@ func (h *Handler) CmdQuery(connCtx context.Context, query *wire.OpQuery) (*wire. speculativeAuthenticate, err := h.saslStart(connCtx, dbName, authDoc) if err != nil { - h.L.DebugContext(connCtx, "Speculative authentication failed", logging.Error(err)) + h.L.Debug("Speculative authentication failed", zap.Error(err)) // unsuccessful speculative authentication leave `speculativeAuthenticate` field unset // and let `saslStart` return an error @@ -92,7 +93,7 @@ func (h *Handler) CmdQuery(connCtx context.Context, query *wire.OpQuery) (*wire. return &opReply, nil } - h.L.DebugContext(connCtx, "Speculative authentication passed") + h.L.Debug("Speculative authentication passed") reply.Set("speculativeAuthenticate", speculativeAuthenticate) diff --git a/internal/handler/commands.go b/internal/handler/commands.go index 98a39046b535..c523c54b6bd2 100644 --- a/internal/handler/commands.go +++ b/internal/handler/commands.go @@ -16,7 +16,8 @@ package handler import ( "context" - "log/slog" + + "go.uber.org/zap" "github.com/FerretDB/FerretDB/internal/clientconn/conninfo" "github.com/FerretDB/FerretDB/internal/handler/handlererrors" @@ -294,25 +295,23 @@ func (h *Handler) initCommands() { } // checkSCRAMConversation returns error if SCRAM conversation is not valid. -func checkSCRAMConversation(ctx context.Context, l *slog.Logger) error { +func checkSCRAMConversation(ctx context.Context, l *zap.Logger) error { _, _, conv, _ := conninfo.Get(ctx).Auth() switch { case conv == nil: - l.WarnContext(ctx, "checkSCRAMConversation: no conversation") + l.Warn("checkSCRAMConversation: no conversation") case !conv.Valid(): - l.WarnContext( - ctx, + l.Warn( "checkSCRAMConversation: invalid conversation", - slog.String("username", conv.Username()), slog.Bool("valid", conv.Valid()), slog.Bool("done", conv.Done()), + zap.String("username", conv.Username()), zap.Bool("valid", conv.Valid()), zap.Bool("done", conv.Done()), ) default: - l.DebugContext( - ctx, + l.Debug( "checkSCRAMConversation: passed", - slog.String("username", conv.Username()), slog.Bool("valid", conv.Valid()), slog.Bool("done", conv.Done()), + zap.String("username", conv.Username()), zap.Bool("valid", conv.Valid()), zap.Bool("done", conv.Done()), ) return nil diff --git a/internal/handler/common/count.go b/internal/handler/common/count.go index 7cbdeeef6a05..642faeb14c0c 100644 --- a/internal/handler/common/count.go +++ b/internal/handler/common/count.go @@ -15,7 +15,7 @@ package common import ( - "log/slog" + "go.uber.org/zap" "github.com/FerretDB/FerretDB/internal/handler/handlerparams" "github.com/FerretDB/FerretDB/internal/types" @@ -44,7 +44,7 @@ type CountParams struct { } // GetCountParams returns the parameters for the count command. -func GetCountParams(document *types.Document, l *slog.Logger) (*CountParams, error) { +func GetCountParams(document *types.Document, l *zap.Logger) (*CountParams, error) { var count CountParams err := handlerparams.ExtractParams(document, "count", &count, l) diff --git a/internal/handler/common/delete_params.go b/internal/handler/common/delete_params.go index 36e3d806176f..30e5dfa77eab 100644 --- a/internal/handler/common/delete_params.go +++ b/internal/handler/common/delete_params.go @@ -15,7 +15,7 @@ package common import ( - "log/slog" + "go.uber.org/zap" "github.com/FerretDB/FerretDB/internal/handler/handlerparams" "github.com/FerretDB/FerretDB/internal/types" @@ -55,7 +55,7 @@ type Delete struct { } // GetDeleteParams returns parameters for delete operation. -func GetDeleteParams(document *types.Document, l *slog.Logger) (*DeleteParams, error) { +func GetDeleteParams(document *types.Document, l *zap.Logger) (*DeleteParams, error) { params := DeleteParams{ Ordered: true, } diff --git a/internal/handler/common/distinct.go b/internal/handler/common/distinct.go index e3e1f5435277..66622c73c38c 100644 --- a/internal/handler/common/distinct.go +++ b/internal/handler/common/distinct.go @@ -17,7 +17,8 @@ package common import ( "errors" "fmt" - "log/slog" + + "go.uber.org/zap" "github.com/FerretDB/FerretDB/internal/handler/commonpath" "github.com/FerretDB/FerretDB/internal/handler/handlererrors" @@ -48,7 +49,7 @@ type DistinctParams struct { } // GetDistinctParams returns `distinct` command parameters. -func GetDistinctParams(document *types.Document, l *slog.Logger) (*DistinctParams, error) { +func GetDistinctParams(document *types.Document, l *zap.Logger) (*DistinctParams, error) { var dp DistinctParams err := handlerparams.ExtractParams(document, "distinct", &dp, l) diff --git a/internal/handler/common/explain.go b/internal/handler/common/explain.go index 14b28487741f..857c2b1cbf3f 100644 --- a/internal/handler/common/explain.go +++ b/internal/handler/common/explain.go @@ -15,7 +15,7 @@ package common import ( - "log/slog" + "go.uber.org/zap" "github.com/FerretDB/FerretDB/internal/handler/handlererrors" "github.com/FerretDB/FerretDB/internal/handler/handlerparams" @@ -45,7 +45,7 @@ type ExplainParams struct { } // GetExplainParams returns the parameters for the explain command. -func GetExplainParams(document *types.Document, l *slog.Logger) (*ExplainParams, error) { +func GetExplainParams(document *types.Document, l *zap.Logger) (*ExplainParams, error) { var err error var db, collection string diff --git a/internal/handler/common/find.go b/internal/handler/common/find.go index 4ee10a0d5947..ace9752043bf 100644 --- a/internal/handler/common/find.go +++ b/internal/handler/common/find.go @@ -15,7 +15,7 @@ package common import ( - "log/slog" + "go.uber.org/zap" "github.com/FerretDB/FerretDB/internal/handler/handlererrors" "github.com/FerretDB/FerretDB/internal/handler/handlerparams" @@ -65,7 +65,7 @@ type FindParams struct { } // GetFindParams returns `find` command parameters. -func GetFindParams(doc *types.Document, l *slog.Logger) (*FindParams, error) { +func GetFindParams(doc *types.Document, l *zap.Logger) (*FindParams, error) { params := FindParams{ BatchSize: 101, } diff --git a/internal/handler/common/findandmodify.go b/internal/handler/common/findandmodify.go index 0de40a780977..b11be8ed0765 100644 --- a/internal/handler/common/findandmodify.go +++ b/internal/handler/common/findandmodify.go @@ -16,7 +16,8 @@ package common import ( "fmt" - "log/slog" + + "go.uber.org/zap" "github.com/FerretDB/FerretDB/internal/handler/handlererrors" "github.com/FerretDB/FerretDB/internal/handler/handlerparams" @@ -58,7 +59,7 @@ type FindAndModifyParams struct { } // GetFindAndModifyParams returns `findAndModifyParams` command parameters. -func GetFindAndModifyParams(doc *types.Document, l *slog.Logger) (*FindAndModifyParams, error) { +func GetFindAndModifyParams(doc *types.Document, l *zap.Logger) (*FindAndModifyParams, error) { var params FindAndModifyParams err := handlerparams.ExtractParams(doc, "findAndModify", ¶ms, l) diff --git a/internal/handler/common/insert.go b/internal/handler/common/insert.go index e63bdf770e1c..dcf6c087bab0 100644 --- a/internal/handler/common/insert.go +++ b/internal/handler/common/insert.go @@ -16,7 +16,8 @@ package common import ( "fmt" - "log/slog" + + "go.uber.org/zap" "github.com/FerretDB/FerretDB/internal/handler/handlererrors" "github.com/FerretDB/FerretDB/internal/handler/handlerparams" @@ -44,7 +45,7 @@ type InsertParams struct { } // GetInsertParams returns the parameters for an insert command. -func GetInsertParams(document *types.Document, l *slog.Logger) (*InsertParams, error) { +func GetInsertParams(document *types.Document, l *zap.Logger) (*InsertParams, error) { params := InsertParams{ Ordered: true, } diff --git a/internal/handler/common/unimplemented.go b/internal/handler/common/unimplemented.go index c80f45a7c3cf..153a23ae5ea5 100644 --- a/internal/handler/common/unimplemented.go +++ b/internal/handler/common/unimplemented.go @@ -16,7 +16,8 @@ package common import ( "fmt" - "log/slog" + + "go.uber.org/zap" "github.com/FerretDB/FerretDB/internal/handler/handlererrors" "github.com/FerretDB/FerretDB/internal/types" @@ -59,12 +60,12 @@ func UnimplementedNonDefault(doc *types.Document, field string, isDefault func(v } // Ignored logs a message if doc has any of the given fields. -func Ignored(doc *types.Document, l *slog.Logger, fields ...string) { +func Ignored(doc *types.Document, l *zap.Logger, fields ...string) { for _, field := range fields { if v, err := doc.Get(field); err == nil { l.Debug( "ignoring field", - slog.String("command", doc.Command()), slog.String("field", field), slog.Any("value", v), + zap.String("command", doc.Command()), zap.String("field", field), zap.Any("value", v), ) } } diff --git a/internal/handler/common/update_params.go b/internal/handler/common/update_params.go index dd2c5fde7aec..fc943a50481c 100644 --- a/internal/handler/common/update_params.go +++ b/internal/handler/common/update_params.go @@ -15,7 +15,7 @@ package common import ( - "log/slog" + "go.uber.org/zap" "github.com/FerretDB/FerretDB/internal/handler/handlererrors" "github.com/FerretDB/FerretDB/internal/handler/handlerparams" @@ -84,7 +84,7 @@ type UpdateResult struct { } // GetUpdateParams returns parameters for update command. -func GetUpdateParams(document *types.Document, l *slog.Logger) (*UpdateParams, error) { +func GetUpdateParams(document *types.Document, l *zap.Logger) (*UpdateParams, error) { var params UpdateParams err := handlerparams.ExtractParams(document, "update", ¶ms, l) diff --git a/internal/handler/handler.go b/internal/handler/handler.go index 8faeeda17a23..74b46eb3332e 100644 --- a/internal/handler/handler.go +++ b/internal/handler/handler.go @@ -19,7 +19,6 @@ import ( "context" "errors" "fmt" - "log/slog" "sync" "time" @@ -36,7 +35,6 @@ import ( "github.com/FerretDB/FerretDB/internal/util/ctxutil" "github.com/FerretDB/FerretDB/internal/util/iterator" "github.com/FerretDB/FerretDB/internal/util/lazyerrors" - "github.com/FerretDB/FerretDB/internal/util/logging" "github.com/FerretDB/FerretDB/internal/util/must" "github.com/FerretDB/FerretDB/internal/util/password" "github.com/FerretDB/FerretDB/internal/util/state" @@ -90,7 +88,7 @@ type NewOpts struct { SetupPassword password.Password SetupTimeout time.Duration - L *slog.Logger + L *zap.Logger ConnMetrics *connmetrics.ConnMetrics StateProvider *state.Provider @@ -121,12 +119,12 @@ func New(opts *NewOpts) (*Handler, error) { opts.MaxBsonObjectSizeBytes = types.MaxDocumentLen } - b := oplog.NewBackend(opts.Backend, zap.L().Named("oplog")) + b := oplog.NewBackend(opts.Backend, opts.L.Named("oplog")) h := &Handler{ b: b, NewOpts: opts, - cursors: cursor.NewRegistry(zap.L().Named("cursors")), + cursors: cursor.NewRegistry(opts.L.Named("cursors")), cappedCleanupStop: make(chan struct{}), cleanupCappedCollectionsDocs: prometheus.NewCounterVec( @@ -186,7 +184,7 @@ func (h *Handler) setup() error { ctx = conninfo.Ctx(ctx, info) - l := logging.WithName(h.L, "setup") + l := h.L.Named("setup") var retry int64 @@ -196,7 +194,7 @@ func (h *Handler) setup() error { break } - l.DebugContext(ctx, "Status failed", logging.Error(err)) + l.Debug("Status failed", zap.Error(err)) retry++ ctxutil.SleepWithJitter(ctx, time.Second, retry) @@ -208,16 +206,11 @@ func (h *Handler) setup() error { } if len(res.Databases) > 0 { - l.DebugContext(ctx, "Database already exists") + l.Debug("Database already exists") return nil } - l.InfoContext( - ctx, - "Setting up database and user", - slog.String("database", h.SetupDatabase), - slog.String("username", h.SetupUsername), - ) + l.Info("Setting up database and user", zap.String("database", h.SetupDatabase), zap.String("username", h.SetupUsername)) db, err := h.b.Database(h.SetupDatabase) if err != nil { @@ -252,7 +245,7 @@ func (h *Handler) runCappedCleanup() { return } - h.L.Info("Capped collections cleanup enabled.", slog.Duration("interval", h.CappedCleanupInterval)) + h.L.Info("Capped collections cleanup enabled.", zap.Duration("interval", h.CappedCleanupInterval)) ticker := time.NewTicker(h.CappedCleanupInterval) defer ticker.Stop() @@ -261,7 +254,7 @@ func (h *Handler) runCappedCleanup() { select { case <-ticker.C: if err := h.cleanupAllCappedCollections(context.Background()); err != nil { - h.L.Error("Failed to cleanup capped collections.", logging.Error(err)) + h.L.Error("Failed to cleanup capped collections.", zap.Error(err)) } case <-h.cappedCleanupStop: @@ -297,11 +290,11 @@ func (h *Handler) Collect(ch chan<- prometheus.Metric) { // cleanupAllCappedCollections drops the given percent of documents from all capped collections. func (h *Handler) cleanupAllCappedCollections(ctx context.Context) error { - h.L.DebugContext(ctx, "cleanupAllCappedCollections: started", slog.Any("percentage", h.CappedCleanupPercentage)) + h.L.Debug("cleanupAllCappedCollections: started", zap.Uint8("percentage", h.CappedCleanupPercentage)) start := time.Now() defer func() { - h.L.DebugContext(ctx, "cleanupAllCappedCollections: finished", slog.Duration("duration", time.Since(start))) + h.L.Debug("cleanupAllCappedCollections: finished", zap.Duration("duration", time.Since(start))) }() connInfo := conninfo.New() @@ -340,13 +333,9 @@ func (h *Handler) cleanupAllCappedCollections(ctx context.Context) error { } if deleted > 0 || bytesFreed > 0 { - h.L.InfoContext( - ctx, - "Capped collection cleaned up.", - slog.String("db", dbInfo.Name), - slog.String("collection", cInfo.Name), - slog.Any("deleted", deleted), - slog.Int64("bytes_freed", bytesFreed), + h.L.Info("Capped collection cleaned up.", + zap.String("db", dbInfo.Name), zap.String("collection", cInfo.Name), + zap.Int32("deleted", deleted), zap.Int64("bytesFreed", bytesFreed), ) } @@ -375,8 +364,7 @@ func (h *Handler) cleanupCappedCollection(ctx context.Context, db backends.Datab if err != nil { return 0, 0, lazyerrors.Error(err) } - - h.L.DebugContext(ctx, "cleanupCappedCollection: stats before", slog.Any("stats", statsBefore)) + h.L.Debug("cleanupCappedCollection: stats before", zap.Any("stats", statsBefore)) // In order to be more precise w.r.t number of documents getting dropped and to avoid // deleting too many documents unnecessarily, @@ -397,7 +385,7 @@ func (h *Handler) cleanupCappedCollection(ctx context.Context, db backends.Datab return 0, 0, lazyerrors.Error(err) } - h.L.DebugContext(ctx, "cleanupCappedCollection: stats after document count reduction", slog.Any("stats", statsAfter)) + h.L.Debug("cleanupCappedCollection: stats after document count reduction", zap.Any("stats", statsAfter)) docsDeleted += int32(count) bytesFreed += (statsBefore.SizeTotal - statsAfter.SizeTotal) @@ -423,7 +411,7 @@ func (h *Handler) cleanupCappedCollection(ctx context.Context, db backends.Datab return 0, 0, lazyerrors.Error(err) } - h.L.DebugContext(ctx, "cleanupCappedCollection: stats after compact", slog.Any("stats", statsAfter)) + h.L.Debug("cleanupCappedCollection: stats after compact", zap.Any("stats", statsAfter)) bytesFreed += (statsBefore.SizeTotal - statsAfter.SizeTotal) diff --git a/internal/handler/handlerparams/extract_params.go b/internal/handler/handlerparams/extract_params.go index f247a04d9ae4..cac6aa9456b3 100644 --- a/internal/handler/handlerparams/extract_params.go +++ b/internal/handler/handlerparams/extract_params.go @@ -17,11 +17,12 @@ package handlerparams import ( "errors" "fmt" - "log/slog" "reflect" "slices" "strings" + "go.uber.org/zap" + "github.com/FerretDB/FerretDB/internal/handler/handlererrors" "github.com/FerretDB/FerretDB/internal/types" "github.com/FerretDB/FerretDB/internal/util/iterator" @@ -57,7 +58,7 @@ import ( // - `ErrBadValue` when field is out of integer range; // - `ErrBadValue` when field has negative value; // - `ErrInvalidNamespace` - collection name has invalid type. -func ExtractParams(doc *types.Document, command string, value any, l *slog.Logger) error { +func ExtractParams(doc *types.Document, command string, value any, l *zap.Logger) error { rv := reflect.ValueOf(value) if rv.Kind() != reflect.Ptr || rv.IsNil() { panic("value must be a non-nil pointer") @@ -106,7 +107,7 @@ func ExtractParams(doc *types.Document, command string, value any, l *slog.Logge if options.ignored { l.Debug( "ignoring field", - slog.String("command", doc.Command()), slog.String("field", key), slog.Any("value", val), + zap.String("command", doc.Command()), zap.String("field", key), zap.Any("value", val), ) continue @@ -228,7 +229,7 @@ func tagOptionsFromList(optionsList []string) *tagOptions { } // setStructField sets the value of the document field to the structure field. -func setStructField(elem *reflect.Value, o *tagOptions, i int, command, key string, val any, l *slog.Logger) error { +func setStructField(elem *reflect.Value, o *tagOptions, i int, command, key string, val any, l *zap.Logger) error { var err error field := elem.Type().Field(i) diff --git a/internal/handler/handlerparams/extract_params_test.go b/internal/handler/handlerparams/extract_params_test.go index 20036a9764b2..12c7f6660ee9 100644 --- a/internal/handler/handlerparams/extract_params_test.go +++ b/internal/handler/handlerparams/extract_params_test.go @@ -19,10 +19,10 @@ import ( "testing" "github.com/stretchr/testify/require" + "go.uber.org/zap" "github.com/FerretDB/FerretDB/internal/types" "github.com/FerretDB/FerretDB/internal/util/must" - "github.com/FerretDB/FerretDB/internal/util/testutil" ) func TestParse(t *testing.T) { @@ -369,7 +369,7 @@ func TestParse(t *testing.T) { } for name, tt := range tests { t.Run(name, func(t *testing.T) { - err := ExtractParams(tt.doc, tt.command, tt.params, testutil.SLogger(t)) + err := ExtractParams(tt.doc, tt.command, tt.params, zap.NewNop()) if tt.wantErr != "" { require.Regexp(t, regexp.MustCompile(".*"+tt.wantErr), err.Error()) return diff --git a/internal/handler/msg_aggregate.go b/internal/handler/msg_aggregate.go index bf13813c35a1..4855dfd68839 100644 --- a/internal/handler/msg_aggregate.go +++ b/internal/handler/msg_aggregate.go @@ -18,12 +18,13 @@ import ( "context" "errors" "fmt" - "log/slog" "math" "os" "strings" "time" + "go.uber.org/zap" + "github.com/FerretDB/FerretDB/internal/backends" "github.com/FerretDB/FerretDB/internal/clientconn/conninfo" "github.com/FerretDB/FerretDB/internal/clientconn/cursor" @@ -380,13 +381,9 @@ func (h *Handler) MsgAggregate(connCtx context.Context, msg *wire.OpMsg) (*wire. return nil, handleMaxTimeMSError(err, maxTimeMS, "aggregate") } - h.L.DebugContext( - ctx, - "Got first batch", - slog.Int64("cursor_id", cursorID), - slog.Any("type", cursor.Type), - slog.Int("count", len(docs)), - slog.Int64("batch_size", batchSize), + h.L.Debug( + "Got first batch", zap.Int64("cursor_id", cursorID), zap.Stringer("type", cursor.Type), + zap.Int("count", len(docs)), zap.Int64("batch_size", batchSize), ) firstBatch := types.MakeArray(len(docs)) diff --git a/internal/handler/msg_find.go b/internal/handler/msg_find.go index 13ace3920743..790f947ab8fe 100644 --- a/internal/handler/msg_find.go +++ b/internal/handler/msg_find.go @@ -18,10 +18,11 @@ import ( "context" "errors" "fmt" - "log/slog" "strings" "time" + "go.uber.org/zap" + "github.com/FerretDB/FerretDB/internal/backends" "github.com/FerretDB/FerretDB/internal/clientconn/conninfo" "github.com/FerretDB/FerretDB/internal/clientconn/cursor" @@ -94,7 +95,7 @@ func (h *Handler) MsgFind(connCtx context.Context, msg *wire.OpMsg) (*wire.OpMsg } } - qp, err := h.makeFindQueryParams(connCtx, params, &cInfo) + qp, err := h.makeFindQueryParams(params, &cInfo) if err != nil { return nil, err } @@ -164,14 +165,10 @@ func (h *Handler) MsgFind(connCtx context.Context, msg *wire.OpMsg) (*wire.OpMsg return nil, handleMaxTimeMSError(err, params.MaxTimeMS, "find") } - h.L.DebugContext( - ctx, - "Got first batch", - slog.Int64("cursor_id", cursorID), - slog.Any("type", c.Type), - slog.Int("count", len(docs)), - slog.Int64("batch_size", params.BatchSize), - slog.Bool("single_batch", params.SingleBatch), + h.L.Debug( + "Got first batch", zap.Int64("cursor_id", cursorID), zap.Stringer("type", c.Type), + zap.Int("count", len(docs)), zap.Int64("batch_size", params.BatchSize), + zap.Bool("single_batch", params.SingleBatch), ) if params.SingleBatch || len(docs) < int(params.BatchSize) { @@ -213,7 +210,7 @@ type findCursorData struct { } // makeFindQueryParams creates the backend's query parameters for the find command. -func (h *Handler) makeFindQueryParams(ctx context.Context, params *common.FindParams, cInfo *backends.CollectionInfo) (*backends.QueryParams, error) { //nolint:lll // for readability +func (h *Handler) makeFindQueryParams(params *common.FindParams, cInfo *backends.CollectionInfo) (*backends.QueryParams, error) { qp := &backends.QueryParams{ Comment: params.Comment, } @@ -285,9 +282,7 @@ func (h *Handler) makeFindQueryParams(ctx context.Context, params *common.FindPa qp.Limit = params.Limit } - if h.L.Enabled(ctx, slog.LevelDebug) { - h.L.DebugContext(ctx, fmt.Sprintf("Converted %+v for %+v to %+v.", params, cInfo, qp)) - } + h.L.Sugar().Debugf("Converted %+v for %+v to %+v.", params, cInfo, qp) return qp, nil } diff --git a/internal/handler/msg_getlog.go b/internal/handler/msg_getlog.go index 18bfab499d16..51ff07d498e3 100644 --- a/internal/handler/msg_getlog.go +++ b/internal/handler/msg_getlog.go @@ -18,10 +18,11 @@ import ( "context" "encoding/json" "fmt" - "log/slog" "strings" "time" + "go.uber.org/zap" + "github.com/FerretDB/FerretDB/build/version" "github.com/FerretDB/FerretDB/internal/bson" "github.com/FerretDB/FerretDB/internal/handler/handlererrors" @@ -110,7 +111,7 @@ func (h *Handler) MsgGetLog(connCtx context.Context, msg *wire.OpMsg) (*wire.OpM startupWarnings = append(startupWarnings, "This is debug build. The performance will be affected.") } - if h.L.Enabled(connCtx, slog.LevelDebug) { + if h.L.Level().Enabled(zap.DebugLevel) { startupWarnings = append(startupWarnings, "Debug logging enabled. The security and performance will be affected.") } diff --git a/internal/handler/msg_getmore.go b/internal/handler/msg_getmore.go index 9f237964b75e..bd4cd855dd2b 100644 --- a/internal/handler/msg_getmore.go +++ b/internal/handler/msg_getmore.go @@ -18,10 +18,11 @@ import ( "context" "errors" "fmt" - "log/slog" "math" "time" + "go.uber.org/zap" + "github.com/FerretDB/FerretDB/internal/backends" "github.com/FerretDB/FerretDB/internal/clientconn/conninfo" "github.com/FerretDB/FerretDB/internal/clientconn/cursor" @@ -283,11 +284,8 @@ func (h *Handler) makeNextBatch(c *cursor.Cursor, batchSize int64) (*types.Array } h.L.Debug( - "Got next batch", - slog.Int64("cursor_id", c.ID), - slog.Any("type", c.Type), - slog.Int("count", len(docs)), - slog.Int64("batch_size", batchSize), + "Got next batch", zap.Int64("cursor_id", c.ID), zap.Stringer("type", c.Type), + zap.Int("count", len(docs)), zap.Int64("batch_size", batchSize), ) nextBatch := types.MakeArray(len(docs)) diff --git a/internal/handler/msg_listdatabases.go b/internal/handler/msg_listdatabases.go index ff89e5cca8e4..3a3928f7533b 100644 --- a/internal/handler/msg_listdatabases.go +++ b/internal/handler/msg_listdatabases.go @@ -17,11 +17,12 @@ package handler import ( "context" + "go.uber.org/zap" + "github.com/FerretDB/FerretDB/internal/handler/common" "github.com/FerretDB/FerretDB/internal/handler/handlerparams" "github.com/FerretDB/FerretDB/internal/types" "github.com/FerretDB/FerretDB/internal/util/lazyerrors" - "github.com/FerretDB/FerretDB/internal/util/logging" "github.com/FerretDB/FerretDB/internal/util/must" "github.com/FerretDB/FerretDB/internal/wire" ) @@ -65,13 +66,13 @@ func (h *Handler) MsgListDatabases(connCtx context.Context, msg *wire.OpMsg) (*w for _, dbInfo := range res.Databases { db, err := h.b.Database(dbInfo.Name) if err != nil { - h.L.WarnContext(connCtx, "Failed to get database", logging.Error(err)) + h.L.Warn("Failed to get database", zap.Error(err)) continue } stats, err := db.Stats(connCtx, nil) if err != nil { - h.L.WarnContext(connCtx, "Failed to get database stats", logging.Error(err)) + h.L.Warn("Failed to get database stats", zap.Error(err)) continue } diff --git a/internal/handler/msg_saslcontinue.go b/internal/handler/msg_saslcontinue.go index 836c201c6045..8757d473f40b 100644 --- a/internal/handler/msg_saslcontinue.go +++ b/internal/handler/msg_saslcontinue.go @@ -16,14 +16,14 @@ package handler import ( "context" - "log/slog" + + "go.uber.org/zap" "github.com/FerretDB/FerretDB/internal/clientconn/conninfo" "github.com/FerretDB/FerretDB/internal/handler/common" "github.com/FerretDB/FerretDB/internal/handler/handlererrors" "github.com/FerretDB/FerretDB/internal/types" "github.com/FerretDB/FerretDB/internal/util/lazyerrors" - "github.com/FerretDB/FerretDB/internal/util/logging" "github.com/FerretDB/FerretDB/internal/util/must" "github.com/FerretDB/FerretDB/internal/wire" ) @@ -49,7 +49,7 @@ func (h *Handler) MsgSASLContinue(connCtx context.Context, msg *wire.OpMsg) (*wi _, _, conv, _ := conninfo.Get(connCtx).Auth() if conv == nil { - h.L.WarnContext(connCtx, "saslContinue: no conversation to continue") + h.L.Warn("saslContinue: no conversation to continue") return nil, handlererrors.NewCommandErrorMsgWithArgument( handlererrors.ErrAuthenticationFailed, @@ -60,18 +60,18 @@ func (h *Handler) MsgSASLContinue(connCtx context.Context, msg *wire.OpMsg) (*wi response, err := conv.Step(string(payload)) - attrs := []any{ - slog.String("username", conv.Username()), - slog.Bool("valid", conv.Valid()), - slog.Bool("done", conv.Done()), + fields := []zap.Field{ + zap.String("username", conv.Username()), + zap.Bool("valid", conv.Valid()), + zap.Bool("done", conv.Done()), } if err != nil { - if h.L.Enabled(connCtx, slog.LevelDebug) { - attrs = append(attrs, logging.Error(err)) + if h.L.Level().Enabled(zap.DebugLevel) { + fields = append(fields, zap.Error(err)) } - h.L.WarnContext(connCtx, "saslContinue: step failed", attrs...) //nolint:sloglint // attrs is not key-value pairs + h.L.Warn("saslContinue: step failed", fields...) return nil, handlererrors.NewCommandErrorMsgWithArgument( handlererrors.ErrAuthenticationFailed, @@ -80,7 +80,7 @@ func (h *Handler) MsgSASLContinue(connCtx context.Context, msg *wire.OpMsg) (*wi ) } - h.L.DebugContext(connCtx, "saslContinue: step succeed", attrs...) //nolint:sloglint // attrs is not key-value pairs + h.L.Debug("saslContinue: step succeed", fields...) if conv.Valid() { conninfo.Get(connCtx).SetBypassBackendAuth() diff --git a/internal/handler/msg_saslstart.go b/internal/handler/msg_saslstart.go index aafd452a302f..2719e2379d85 100644 --- a/internal/handler/msg_saslstart.go +++ b/internal/handler/msg_saslstart.go @@ -20,9 +20,9 @@ import ( "encoding/base64" "errors" "fmt" - "log/slog" "github.com/xdg-go/scram" + "go.uber.org/zap" "github.com/FerretDB/FerretDB/internal/clientconn/conninfo" "github.com/FerretDB/FerretDB/internal/handler/common" @@ -30,7 +30,6 @@ import ( "github.com/FerretDB/FerretDB/internal/types" "github.com/FerretDB/FerretDB/internal/util/iterator" "github.com/FerretDB/FerretDB/internal/util/lazyerrors" - "github.com/FerretDB/FerretDB/internal/util/logging" "github.com/FerretDB/FerretDB/internal/util/must" "github.com/FerretDB/FerretDB/internal/wire" ) @@ -233,7 +232,7 @@ func (h *Handler) scramCredentialLookup(ctx context.Context, dbName, username, m } } - h.L.WarnContext(ctx, "scramCredentialLookup: failed", slog.String("user", username)) + h.L.Warn("scramCredentialLookup: failed", zap.String("user", username)) return nil, handlererrors.NewCommandErrorMsgWithArgument( handlererrors.ErrAuthenticationFailed, @@ -282,23 +281,23 @@ func (h *Handler) saslStartSCRAM(ctx context.Context, dbName, mechanism string, response, err := conv.Step(string(payload)) - attrs := []any{ - slog.String("username", conv.Username()), - slog.Bool("valid", conv.Valid()), - slog.Bool("done", conv.Done()), + fields := []zap.Field{ + zap.String("username", conv.Username()), + zap.Bool("valid", conv.Valid()), + zap.Bool("done", conv.Done()), } if err != nil { - if h.L.Enabled(ctx, slog.LevelDebug) { - attrs = append(attrs, logging.Error(err)) + if h.L.Level().Enabled(zap.DebugLevel) { + fields = append(fields, zap.Error(err)) } - h.L.WarnContext(ctx, "saslStartSCRAM: step failed", attrs...) //nolint:sloglint // attrs is not key-value pairs + h.L.Warn("saslStartSCRAM: step failed", fields...) return "", err } - h.L.DebugContext(ctx, "saslStartSCRAM: step succeed", attrs...) //nolint:sloglint // attrs is not key-value pairs + h.L.Debug("saslStartSCRAM: step succeed", fields...) conninfo.Get(ctx).SetAuth(conv.Username(), "", conv, dbName) diff --git a/internal/handler/registry/hana.go b/internal/handler/registry/hana.go index f9dfb7535ff8..e7f7c0343cc8 100644 --- a/internal/handler/registry/hana.go +++ b/internal/handler/registry/hana.go @@ -20,7 +20,6 @@ import ( "github.com/FerretDB/FerretDB/internal/backends/hana" "github.com/FerretDB/FerretDB/internal/handler" "github.com/FerretDB/FerretDB/internal/util/lazyerrors" - "github.com/FerretDB/FerretDB/internal/util/logging" ) // init registers "hana" handler for Hana when "ferretdb_hana" build tag is provided. @@ -48,7 +47,7 @@ func init() { SetupPassword: opts.SetupPassword, SetupTimeout: opts.SetupTimeout, - L: logging.WithName(opts.SLogger, "hana"), + L: opts.Logger.Named("hana"), ConnMetrics: opts.ConnMetrics, StateProvider: opts.StateProvider, diff --git a/internal/handler/registry/mysql.go b/internal/handler/registry/mysql.go index ad198681c131..6d2636c31ad9 100644 --- a/internal/handler/registry/mysql.go +++ b/internal/handler/registry/mysql.go @@ -18,7 +18,6 @@ import ( "github.com/FerretDB/FerretDB/internal/backends/mysql" "github.com/FerretDB/FerretDB/internal/handler" "github.com/FerretDB/FerretDB/internal/util/lazyerrors" - "github.com/FerretDB/FerretDB/internal/util/logging" ) // init registers "mysql" handler. @@ -43,7 +42,7 @@ func init() { SetupPassword: opts.SetupPassword, SetupTimeout: opts.SetupTimeout, - L: logging.WithName(opts.SLogger, "mysql"), + L: opts.Logger.Named("mysql"), ConnMetrics: opts.ConnMetrics, StateProvider: opts.StateProvider, diff --git a/internal/handler/registry/postgresql.go b/internal/handler/registry/postgresql.go index bcbf7f59d5b3..994f922c598e 100644 --- a/internal/handler/registry/postgresql.go +++ b/internal/handler/registry/postgresql.go @@ -20,7 +20,6 @@ import ( "github.com/FerretDB/FerretDB/internal/backends/postgresql" "github.com/FerretDB/FerretDB/internal/handler" "github.com/FerretDB/FerretDB/internal/util/lazyerrors" - "github.com/FerretDB/FerretDB/internal/util/logging" ) // init registers "postgresql" handler. @@ -46,7 +45,7 @@ func init() { SetupPassword: opts.SetupPassword, SetupTimeout: opts.SetupTimeout, - L: logging.WithName(opts.SLogger, "postgresql"), + L: opts.Logger.Named("postgresql"), ConnMetrics: opts.ConnMetrics, StateProvider: opts.StateProvider, diff --git a/internal/handler/registry/registry.go b/internal/handler/registry/registry.go index d835cfc60a75..4cf1ec6a8416 100644 --- a/internal/handler/registry/registry.go +++ b/internal/handler/registry/registry.go @@ -17,7 +17,6 @@ package registry import ( "fmt" - "log/slog" "time" "go.uber.org/zap" @@ -44,7 +43,6 @@ var registry = map[string]newHandlerFunc{} type NewHandlerOpts struct { // for all backends Logger *zap.Logger - SLogger *slog.Logger ConnMetrics *connmetrics.ConnMetrics StateProvider *state.Provider TCPHost string diff --git a/internal/handler/registry/sqlite.go b/internal/handler/registry/sqlite.go index 04912d25c997..ed21c791d1d8 100644 --- a/internal/handler/registry/sqlite.go +++ b/internal/handler/registry/sqlite.go @@ -20,7 +20,6 @@ import ( "github.com/FerretDB/FerretDB/internal/backends/sqlite" "github.com/FerretDB/FerretDB/internal/handler" "github.com/FerretDB/FerretDB/internal/util/lazyerrors" - "github.com/FerretDB/FerretDB/internal/util/logging" ) // init registers "sqlite" handler. @@ -46,7 +45,7 @@ func init() { SetupPassword: opts.SetupPassword, SetupTimeout: opts.SetupTimeout, - L: logging.WithName(opts.SLogger, "sqlite"), + L: opts.Logger.Named("sqlite"), ConnMetrics: opts.ConnMetrics, StateProvider: opts.StateProvider, From 6c03fefe85040772de8233d6344f784eba2bd789 Mon Sep 17 00:00:00 2001 From: Chi Fujii Date: Thu, 18 Jul 2024 12:40:52 +0900 Subject: [PATCH 07/11] fix mistaken commit --- ferretdb/ferretdb.go | 2 ++ integration/setup/listener.go | 2 ++ internal/handler/registry/postgresql.go | 1 + internal/handler/registry/registry.go | 2 ++ internal/handler/registry/sqlite.go | 1 + 5 files changed, 8 insertions(+) diff --git a/ferretdb/ferretdb.go b/ferretdb/ferretdb.go index 32e042df3c59..5032010e4460 100644 --- a/ferretdb/ferretdb.go +++ b/ferretdb/ferretdb.go @@ -22,6 +22,7 @@ import ( "context" "errors" "fmt" + "log/slog" "net/url" "sync" @@ -128,6 +129,7 @@ func New(config *Config) (*FerretDB, error) { h, closeBackend, err := registry.NewHandler(config.Handler, ®istry.NewHandlerOpts{ Logger: log, + SLogger: slog.Default(), // TODO https://github.com/FerretDB/FerretDB/issues/4013 ConnMetrics: metrics.ConnMetrics, StateProvider: sp, TCPHost: config.Listener.TCP, diff --git a/integration/setup/listener.go b/integration/setup/listener.go index b30fe022f149..3699eb188f2e 100644 --- a/integration/setup/listener.go +++ b/integration/setup/listener.go @@ -16,6 +16,7 @@ package setup import ( "context" + "log/slog" "net/url" "os" "path/filepath" @@ -179,6 +180,7 @@ func setupListener(tb testtb.TB, ctx context.Context, logger *zap.Logger, opts * handlerOpts := ®istry.NewHandlerOpts{ Logger: logger, + SLogger: slog.Default(), // TODO https://github.com/FerretDB/FerretDB/issues/4013 ConnMetrics: listenerMetrics.ConnMetrics, StateProvider: sp, diff --git a/internal/handler/registry/postgresql.go b/internal/handler/registry/postgresql.go index 994f922c598e..487d312f0785 100644 --- a/internal/handler/registry/postgresql.go +++ b/internal/handler/registry/postgresql.go @@ -20,6 +20,7 @@ import ( "github.com/FerretDB/FerretDB/internal/backends/postgresql" "github.com/FerretDB/FerretDB/internal/handler" "github.com/FerretDB/FerretDB/internal/util/lazyerrors" + "github.com/FerretDB/FerretDB/internal/util/logging" ) // init registers "postgresql" handler. diff --git a/internal/handler/registry/registry.go b/internal/handler/registry/registry.go index 4cf1ec6a8416..d835cfc60a75 100644 --- a/internal/handler/registry/registry.go +++ b/internal/handler/registry/registry.go @@ -17,6 +17,7 @@ package registry import ( "fmt" + "log/slog" "time" "go.uber.org/zap" @@ -43,6 +44,7 @@ var registry = map[string]newHandlerFunc{} type NewHandlerOpts struct { // for all backends Logger *zap.Logger + SLogger *slog.Logger ConnMetrics *connmetrics.ConnMetrics StateProvider *state.Provider TCPHost string diff --git a/internal/handler/registry/sqlite.go b/internal/handler/registry/sqlite.go index ed21c791d1d8..5c2119c7d9b6 100644 --- a/internal/handler/registry/sqlite.go +++ b/internal/handler/registry/sqlite.go @@ -20,6 +20,7 @@ import ( "github.com/FerretDB/FerretDB/internal/backends/sqlite" "github.com/FerretDB/FerretDB/internal/handler" "github.com/FerretDB/FerretDB/internal/util/lazyerrors" + "github.com/FerretDB/FerretDB/internal/util/logging" ) // init registers "sqlite" handler. From c8782ee7cc2cfdca383055c52453ec9bd0444beb Mon Sep 17 00:00:00 2001 From: Chi Fujii Date: Thu, 18 Jul 2024 12:48:30 +0900 Subject: [PATCH 08/11] fix log format --- cmd/ferretdb/ping.go | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/cmd/ferretdb/ping.go b/cmd/ferretdb/ping.go index 8b833546ba4a..b5a36733548c 100644 --- a/cmd/ferretdb/ping.go +++ b/cmd/ferretdb/ping.go @@ -78,18 +78,18 @@ func (ready *ReadyZ) Probe(ctx context.Context) bool { } if cli.Listen.Unix != "" { - l.DebugContext(ctx, fmt.Sprintf("--listen-addr flag is set. Ping to %s will be performed", cli.Listen.Addr)) + l.DebugContext(ctx, fmt.Sprintf("--listen-unix flag is set. Ping to %s will be performed", cli.Listen.Addr)) urls = append(urls, "mongodb://"+url.PathEscape(cli.Listen.Unix)) } if len(urls) == 0 { - l.WarnContext(ctx, "Neither --listen-addr nor --listen-unix nor --listen-tls flags were specified - skipping ping.") + l.WarnContext(ctx, "Neither --listen-addr nor --listen-unix nor --listen-tls flags were specified - skipping ping") return true } for _, u := range urls { - l.DebugContext(ctx, fmt.Sprintf("Pinging %s...", u)) + l.DebugContext(ctx, fmt.Sprintf("Pinging %s", u)) var cancel func() ctx, cancel = context.WithTimeout(ctx, cli.Setup.Timeout) From 47c863fffda852e691a21296d93bd555913d9639 Mon Sep 17 00:00:00 2001 From: Chi Fujii Date: Thu, 18 Jul 2024 12:52:54 +0900 Subject: [PATCH 09/11] fix --- cmd/ferretdb/ping.go | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/cmd/ferretdb/ping.go b/cmd/ferretdb/ping.go index b5a36733548c..c0a3b2d6a9a8 100644 --- a/cmd/ferretdb/ping.go +++ b/cmd/ferretdb/ping.go @@ -78,7 +78,7 @@ func (ready *ReadyZ) Probe(ctx context.Context) bool { } if cli.Listen.Unix != "" { - l.DebugContext(ctx, fmt.Sprintf("--listen-unix flag is set. Ping to %s will be performed", cli.Listen.Addr)) + l.DebugContext(ctx, fmt.Sprintf("--listen-unix flag is set. Ping to %s will be performed", cli.Listen.Unix)) urls = append(urls, "mongodb://"+url.PathEscape(cli.Listen.Unix)) } @@ -93,6 +93,7 @@ func (ready *ReadyZ) Probe(ctx context.Context) bool { var cancel func() ctx, cancel = context.WithTimeout(ctx, cli.Setup.Timeout) + defer cancel() client, err := mongo.Connect(ctx, options.Client().ApplyURI(u)) From bd1ab3119edafa54d54dd95fbda3582592eb1696 Mon Sep 17 00:00:00 2001 From: Chi Fujii Date: Thu, 18 Jul 2024 12:54:41 +0900 Subject: [PATCH 10/11] use correct log level --- cmd/ferretdb/ping.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/cmd/ferretdb/ping.go b/cmd/ferretdb/ping.go index c0a3b2d6a9a8..89438e69cafe 100644 --- a/cmd/ferretdb/ping.go +++ b/cmd/ferretdb/ping.go @@ -84,7 +84,7 @@ func (ready *ReadyZ) Probe(ctx context.Context) bool { } if len(urls) == 0 { - l.WarnContext(ctx, "Neither --listen-addr nor --listen-unix nor --listen-tls flags were specified - skipping ping") + l.InfoContext(ctx, "Neither --listen-addr nor --listen-unix nor --listen-tls flags were specified - skipping ping") return true } From 2ad9fef3bc6998c4b8b1fafea53ad9ef70bd2777 Mon Sep 17 00:00:00 2001 From: Chi Fujii Date: Thu, 18 Jul 2024 14:29:10 +0900 Subject: [PATCH 11/11] undo --- cmd/ferretdb/main.go | 1 + 1 file changed, 1 insertion(+) diff --git a/cmd/ferretdb/main.go b/cmd/ferretdb/main.go index b05b3cacae92..ca8d987748c2 100644 --- a/cmd/ferretdb/main.go +++ b/cmd/ferretdb/main.go @@ -498,6 +498,7 @@ func run() { h, closeBackend, err := registry.NewHandler(cli.Handler, ®istry.NewHandlerOpts{ Logger: logger, + SLogger: slogger, ConnMetrics: metrics.ConnMetrics, StateProvider: stateProvider, TCPHost: cli.Listen.Addr,