From 0ef38f5ff3f58a2d78d9605dfdf8112747483336 Mon Sep 17 00:00:00 2001 From: Alexey Palazhchenko Date: Tue, 9 Jul 2024 12:29:23 +0400 Subject: [PATCH 01/11] Document logging --- CONTRIBUTING.md | 37 ++++++++++++--------- cmd/ferretdb/main.go | 6 +++- internal/handler/msg_getlog.go | 4 +++ internal/handler/msg_saslcontinue.go | 1 + internal/handler/msg_saslstart.go | 1 + internal/util/logging/buffer.go | 2 +- website/docs/configuration/observability.md | 7 +++- 7 files changed, 40 insertions(+), 18 deletions(-) diff --git a/CONTRIBUTING.md b/CONTRIBUTING.md index a85e7c78d2d0..590a68ad97ba 100644 --- a/CONTRIBUTING.md +++ b/CONTRIBUTING.md @@ -236,27 +236,32 @@ please improve it as you work on it. Our code follows most of the standard Go conventions, documented on [CodeReviewComments wiki page](https://go.dev/wiki/CodeReviewComments) and some other pages such as [Spelling](https://go.dev/wiki/Spelling). -Some of our idiosyncrasies: +Some of our idiosyncrasies are documented below. 1. We use type switches over BSON types in many places in our code. The order of `case`s follows this order: https://pkg.go.dev/github.com/FerretDB/FerretDB/internal/types#hdr-Mapping It may seem random, but it is only pseudo-random and follows BSON spec: https://bsonspec.org/spec.html 2. We generally pass and return `struct`s by pointers. There are some exceptions like `types.Path` that have value semantics, but when in doubt – use pointers. -3. Log messages should not end with punctuation. - Log field names use `snake_case`. -4. Code comments: - - All top-level declarations, even unexported, should have documentation comments. - - In documentation comments do not describe the name in terms of the name itself (`// Registry is a registry of …`). - Use other words instead; often, they could add additional information and make reading more pleasant (`// Registry stores …`). - - In code comments, in general, do not describe _what_ the code does: it should be clear from the code itself - (and when it doesn't and the code is tricky, simplify it instead). - Instead, describe _why_ the code does that if it is not clear from the surrounding context, names, etc. - There is no need to add comments just because there are no comments if everything is already clear without them. - - For code comments, write either - sentence fragments (do not start it with a capital letter, do not end it with a dot, use the simplified grammar) for short notes - or full sentences (do start them with capital letters, do end them with dots, do check their grammar) when a longer (2+ sentences) - explanation is needed (and the code could not be simplified). + +#### Comments conventions + +1. All top-level declarations, even unexported, should have documentation comments. +2. In documentation comments do not describe the name in terms of the name itself (`// Registry is a registry of …`). + Use other words instead; often, they could add additional information and make reading more pleasant (`// Registry stores …`). +3. In code comments, in general, do not describe _what_ the code does: it should be clear from the code itself + (and when it doesn't and the code is tricky, simplify it instead). + Instead, describe _why_ the code does that if it is not clear from the surrounding context, names, etc. + There is no need to add comments just because there are no comments if everything is already clear without them. +4. For code comments, write either + sentence fragments (do not start it with a capital letter, do not end it with a dot, use the simplified grammar) for short notes + or full sentences (do start them with capital letters, do end them with dots, do check their grammar) when a longer (2+ sentences) + explanation is needed (and the code could not be simplified). + +#### Logging conventions + +1. Log messages should not end with punctuation. +2. Log field names use `snake_case`. #### Integration tests conventions @@ -288,6 +293,8 @@ const doubleMaxPrec = float64(1<<53 - 1) // 9007199254740991.0: largest doubl #### Integration tests naming guidelines + + 1. Test names should include the name of the command being tested. For instance, `TestDistinct` for testing the distinct command. 2. Compatibility tests should have `Compat` in the name, following the command. diff --git a/cmd/ferretdb/main.go b/cmd/ferretdb/main.go index 621ab6838344..8a1774938c5e 100644 --- a/cmd/ferretdb/main.go +++ b/cmd/ferretdb/main.go @@ -369,7 +369,11 @@ func run() { logger.Info("Starting FerretDB "+info.Version+"...", startupFields...) if debugbuild.Enabled { - logger.Info("This is debug build. The performance will be affected.") + logger.Info("This is a debug build. The performance will be affected.") + } + + if logger.Level().Enabled(zap.DebugLevel) { + logger.Info("Debug logging enabled. The performance will be affected.") } checkFlags(logger) diff --git a/internal/handler/msg_getlog.go b/internal/handler/msg_getlog.go index 7e04624a5cca..4914f8ec68cc 100644 --- a/internal/handler/msg_getlog.go +++ b/internal/handler/msg_getlog.go @@ -106,6 +106,10 @@ func (h *Handler) MsgGetLog(ctx context.Context, msg *wire.OpMsg) (*wire.OpMsg, startupWarnings = append(startupWarnings, "This is debug build. The performance will be affected.") } + if h.L.Level().Enabled(zap.DebugLevel) { + startupWarnings = append(startupWarnings, "Debug logging enabled. The performance will be affected.") + } + switch { case state.Telemetry == nil: startupWarnings = append( diff --git a/internal/handler/msg_saslcontinue.go b/internal/handler/msg_saslcontinue.go index 90d60bf99e1e..5d11244f5c83 100644 --- a/internal/handler/msg_saslcontinue.go +++ b/internal/handler/msg_saslcontinue.go @@ -65,6 +65,7 @@ func (h *Handler) MsgSASLContinue(ctx context.Context, msg *wire.OpMsg) (*wire.O } if err != nil { + // FIXME if h.L.Level().Enabled(zap.DebugLevel) { fields = append(fields, zap.Error(err)) } diff --git a/internal/handler/msg_saslstart.go b/internal/handler/msg_saslstart.go index 0287fda72817..343f840d03fa 100644 --- a/internal/handler/msg_saslstart.go +++ b/internal/handler/msg_saslstart.go @@ -286,6 +286,7 @@ func (h *Handler) saslStartSCRAM(ctx context.Context, dbName, mechanism string, } if err != nil { + // FIXME if h.L.Level().Enabled(zap.DebugLevel) { fields = append(fields, zap.Error(err)) } diff --git a/internal/util/logging/buffer.go b/internal/util/logging/buffer.go index 7582b4e9441a..044173638bff 100644 --- a/internal/util/logging/buffer.go +++ b/internal/util/logging/buffer.go @@ -68,7 +68,7 @@ func (cb *circularBuffer) get(minLevel zapcore.Level) []*zapcore.Entry { for n := range l { i := (cb.index + n) % l - if r := cb.records[i]; r != nil && r.Level >= minLevel { + if r := cb.records[i]; r != nil && minLevel.Enabled(r.Level) { res = append(res, cb.records[i]) } } diff --git a/website/docs/configuration/observability.md b/website/docs/configuration/observability.md index a055411efa24..8a31126101bc 100644 --- a/website/docs/configuration/observability.md +++ b/website/docs/configuration/observability.md @@ -9,7 +9,12 @@ description: Observability The log level and format can be adjusted by [configuration flags](flags.md#miscellaneous). -Please note that the structured log format is not stable yet; field names and formatting of values might change in minor releases. +:::note + + + +Structured log format is not stable yet; field names and formatting of values might change in minor releases. +::: ### Docker logs From 7807f941a5679dd533e2e649e769edcb3b6f22c9 Mon Sep 17 00:00:00 2001 From: Alexey Palazhchenko Date: Tue, 9 Jul 2024 18:40:52 +0400 Subject: [PATCH 02/11] Update docs --- cmd/ferretdb/main.go | 2 +- internal/clientconn/conn.go | 2 +- internal/handler/msg_getlog.go | 2 +- internal/util/logging/console_handler.go | 2 ++ website/docs/configuration/observability.md | 30 ++++++++++++++++++++- 5 files changed, 34 insertions(+), 4 deletions(-) diff --git a/cmd/ferretdb/main.go b/cmd/ferretdb/main.go index 8a1774938c5e..de9054827f62 100644 --- a/cmd/ferretdb/main.go +++ b/cmd/ferretdb/main.go @@ -373,7 +373,7 @@ func run() { } if logger.Level().Enabled(zap.DebugLevel) { - logger.Info("Debug logging enabled. The performance will be affected.") + logger.Info("Debug logging enabled. The security and performance will be affected.") } checkFlags(logger) diff --git a/internal/clientconn/conn.go b/internal/clientconn/conn.go index 51db7c2b8261..9a49652586e1 100644 --- a/internal/clientconn/conn.go +++ b/internal/clientconn/conn.go @@ -295,7 +295,7 @@ func (c *conn) run(ctx context.Context) (err error) { // diffLogLevel provides the level of logging for the diff between the "normal" and "proxy" responses. // It is set to the highest level of logging used to log response. - var diffLogLevel zapcore.Level + diffLogLevel := zap.DebugLevel // send request to proxy first (unless we are in normal mode) // because FerretDB's handling could modify reqBody's documents, diff --git a/internal/handler/msg_getlog.go b/internal/handler/msg_getlog.go index 4914f8ec68cc..a3204e47d7ca 100644 --- a/internal/handler/msg_getlog.go +++ b/internal/handler/msg_getlog.go @@ -107,7 +107,7 @@ func (h *Handler) MsgGetLog(ctx context.Context, msg *wire.OpMsg) (*wire.OpMsg, } if h.L.Level().Enabled(zap.DebugLevel) { - startupWarnings = append(startupWarnings, "Debug logging enabled. The performance will be affected.") + startupWarnings = append(startupWarnings, "Debug logging enabled. The security and erformance will be affected.") } switch { diff --git a/internal/util/logging/console_handler.go b/internal/util/logging/console_handler.go index cab71da45ff2..1fe5aac86e89 100644 --- a/internal/util/logging/console_handler.go +++ b/internal/util/logging/console_handler.go @@ -40,6 +40,8 @@ const timeLayout = "2006-01-02T15:04:05.000Z0700" // // See https://golang.org/s/slog-handler-guide. // +// TODO https://github.com/FerretDB/FerretDB/issues/4438 +// //nolint:vet // for readability type consoleHandler struct { opts *NewHandlerOpts diff --git a/website/docs/configuration/observability.md b/website/docs/configuration/observability.md index 8a31126101bc..f7707fc02df8 100644 --- a/website/docs/configuration/observability.md +++ b/website/docs/configuration/observability.md @@ -7,7 +7,35 @@ description: Observability ## Logging -The log level and format can be adjusted by [configuration flags](flags.md#miscellaneous). +FerretDB provides the following structured log formats: + + + +- `console` is a human-readable format with optional colors; +- `text` is machine-readable [logfmt](https://brandur.org/logfmt)-like format + (powered by [Go's `slog.TextHandler`](https://pkg.go.dev/log/slog#TextHandler)); +- `json` if machine-readable JSON format + (powered by [Go's `slog.JSONHandler`](https://pkg.go.dev/log/slog#JSONHandler)). + +There are four logging levels: + + + +- `error` is used for errors that can't be handled gracefully + and typically result in client connection being closed; +- `warn` is used for errors that can be handled gracefully + and typically result in an error being returned to the client (without closing the connection); +- `info` is used for various information messages; +- `debug` should only be used for debugging. + +:::caution +`debug`-level messages include complete query and response bodies, authentication credentials, and other sensitive information. +Both the performance of FerretDB and the security of your environment will be affected when `debug` logging is enabled. +::: + +The default level is `info`, except for [debug builds](https://pkg.go.dev/github.com/FerretDB/FerretDB/build/version#hdr-Debug_builds) that default to `debug`. + +The format and level can be adjusted by [configuration flags](flags.md#miscellaneous). :::note From 35dfabdc5261a24cafd8eabc23a9cc473a37acc4 Mon Sep 17 00:00:00 2001 From: Alexey Palazhchenko Date: Tue, 9 Jul 2024 21:39:26 +0400 Subject: [PATCH 03/11] Ignore `$readPreferences` for `insert` --- internal/handler/common/insert.go | 15 ++++++++------- 1 file changed, 8 insertions(+), 7 deletions(-) diff --git a/internal/handler/common/insert.go b/internal/handler/common/insert.go index d731f5107685..dcf6c087bab0 100644 --- a/internal/handler/common/insert.go +++ b/internal/handler/common/insert.go @@ -34,13 +34,14 @@ type InsertParams struct { Collection string `ferretdb:"insert,collection"` Ordered bool `ferretdb:"ordered,opt"` - MaxTimeMS int64 `ferretdb:"maxTimeMS,ignored"` - WriteConcern any `ferretdb:"writeConcern,ignored"` - BypassDocumentValidation bool `ferretdb:"bypassDocumentValidation,ignored"` - Comment string `ferretdb:"comment,ignored"` - LSID any `ferretdb:"lsid,ignored"` - TxnNumber int64 `ferretdb:"txnNumber,ignored"` - ClusterTime any `ferretdb:"$clusterTime,ignored"` + MaxTimeMS int64 `ferretdb:"maxTimeMS,ignored"` + WriteConcern any `ferretdb:"writeConcern,ignored"` + BypassDocumentValidation bool `ferretdb:"bypassDocumentValidation,ignored"` + Comment string `ferretdb:"comment,ignored"` + LSID any `ferretdb:"lsid,ignored"` + TxnNumber int64 `ferretdb:"txnNumber,ignored"` + ClusterTime any `ferretdb:"$clusterTime,ignored"` + ReadPreference *types.Document `ferretdb:"$readPreference,ignored"` } // GetInsertParams returns the parameters for an insert command. From 5507c67e348aebafd66f4adab2f749c6754fa73f Mon Sep 17 00:00:00 2001 From: Alexey Palazhchenko Date: Tue, 9 Jul 2024 21:51:19 +0400 Subject: [PATCH 04/11] Update docs --- CONTRIBUTING.md | 8 +++++++- website/docs/configuration/observability.md | 3 ++- 2 files changed, 9 insertions(+), 2 deletions(-) diff --git a/CONTRIBUTING.md b/CONTRIBUTING.md index 590a68ad97ba..a8128ad70d14 100644 --- a/CONTRIBUTING.md +++ b/CONTRIBUTING.md @@ -260,8 +260,14 @@ Some of our idiosyncrasies are documented below. #### Logging conventions +(See also our user documentation for notes about logging levels, logging sensitive information, etc.) + 1. Log messages should not end with punctuation. -2. Log field names use `snake_case`. +2. Log field names should use `snake_case`. +3. Whatever sensitive information can be logged should be checked by calling `.Enabled(LevelDebug)` on the appropriate logger, + not by directly comparing levels with `<` / `>` operators. + The same check for `LevelDebug` should be applied if additional sensitive fields should be added + to the log message on a different level. #### Integration tests conventions diff --git a/website/docs/configuration/observability.md b/website/docs/configuration/observability.md index f7707fc02df8..5f9e1d3de501 100644 --- a/website/docs/configuration/observability.md +++ b/website/docs/configuration/observability.md @@ -29,7 +29,8 @@ There are four logging levels: - `debug` should only be used for debugging. :::caution -`debug`-level messages include complete query and response bodies, authentication credentials, and other sensitive information. +`debug`-level messages include complete query and response bodies, full error messages, authentication credentials, +and other sensitive information. Both the performance of FerretDB and the security of your environment will be affected when `debug` logging is enabled. ::: From a6a28811f64536d756289fc40aca1bef6057abf0 Mon Sep 17 00:00:00 2001 From: Alexey Palazhchenko Date: Tue, 9 Jul 2024 21:53:01 +0400 Subject: [PATCH 05/11] Update logs --- internal/clientconn/listener.go | 6 +++--- internal/handler/msg_saslcontinue.go | 1 - internal/handler/msg_saslstart.go | 1 - internal/util/debug/debug.go | 2 +- internal/util/observability/observability.go | 4 ++-- 5 files changed, 6 insertions(+), 8 deletions(-) diff --git a/internal/clientconn/listener.go b/internal/clientconn/listener.go index ec46b2507308..c43af0a07d96 100644 --- a/internal/clientconn/listener.go +++ b/internal/clientconn/listener.go @@ -102,7 +102,7 @@ func Listen(opts *NewListenerOpts) (*Listener, error) { } close(l.tcpListenerReady) - ll.Sugar().Infof("Listening on TCP %s ...", l.TCPAddr()) + ll.Sugar().Infof("Listening on TCP %s...", l.TCPAddr()) } if l.Unix != "" { @@ -111,7 +111,7 @@ func Listen(opts *NewListenerOpts) (*Listener, error) { } close(l.unixListenerReady) - ll.Sugar().Infof("Listening on Unix %s ...", l.UnixAddr()) + ll.Sugar().Infof("Listening on Unix %s...", l.UnixAddr()) } if l.TLS != "" { @@ -126,7 +126,7 @@ func Listen(opts *NewListenerOpts) (*Listener, error) { } close(l.tlsListenerReady) - ll.Sugar().Infof("Listening on TLS %s ...", l.TLSAddr()) + ll.Sugar().Infof("Listening on TLS %s...", l.TLSAddr()) } return l, nil diff --git a/internal/handler/msg_saslcontinue.go b/internal/handler/msg_saslcontinue.go index 5d11244f5c83..90d60bf99e1e 100644 --- a/internal/handler/msg_saslcontinue.go +++ b/internal/handler/msg_saslcontinue.go @@ -65,7 +65,6 @@ func (h *Handler) MsgSASLContinue(ctx context.Context, msg *wire.OpMsg) (*wire.O } if err != nil { - // FIXME if h.L.Level().Enabled(zap.DebugLevel) { fields = append(fields, zap.Error(err)) } diff --git a/internal/handler/msg_saslstart.go b/internal/handler/msg_saslstart.go index 343f840d03fa..0287fda72817 100644 --- a/internal/handler/msg_saslstart.go +++ b/internal/handler/msg_saslstart.go @@ -286,7 +286,6 @@ func (h *Handler) saslStartSCRAM(ctx context.Context, dbName, mechanism string, } if err != nil { - // FIXME if h.L.Level().Enabled(zap.DebugLevel) { fields = append(fields, zap.Error(err)) } diff --git a/internal/util/debug/debug.go b/internal/util/debug/debug.go index eca1c61e1a05..54d7f8e29910 100644 --- a/internal/util/debug/debug.go +++ b/internal/util/debug/debug.go @@ -218,7 +218,7 @@ func (h *Handler) Serve(ctx context.Context) { root := fmt.Sprintf("http://%s", h.lis.Addr()) - h.opts.L.Sugar().Infof("Starting debug server on %s ...", root) + h.opts.L.Sugar().Infof("Starting debug server on %s...", root) paths := maps.Keys(h.handlers) slices.Sort(paths) diff --git a/internal/util/observability/observability.go b/internal/util/observability/observability.go index b7e18535a729..2644521872a0 100644 --- a/internal/util/observability/observability.go +++ b/internal/util/observability/observability.go @@ -85,6 +85,8 @@ func NewOtelTracer(opts *OtelTracerOpts) (*OtelTracer, error) { otel.SetTracerProvider(tp) + opts.Logger.Info("Starting OTLP tracer...") + return &OtelTracer{ l: opts.Logger, tp: tp, @@ -93,8 +95,6 @@ func NewOtelTracer(opts *OtelTracerOpts) (*OtelTracer, error) { // Run runs OTLP tracer until ctx is canceled. func (ot *OtelTracer) Run(ctx context.Context) { - ot.l.Info("OTLP tracer started successfully.") - <-ctx.Done() // ctx is already canceled, but we want to inherit its values From 0a5bf150c81a9ec3ce423381be875599bb0d9eb3 Mon Sep 17 00:00:00 2001 From: Alexey Palazhchenko Date: Tue, 9 Jul 2024 21:58:05 +0400 Subject: [PATCH 06/11] Fix typo --- internal/handler/msg_getlog.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/internal/handler/msg_getlog.go b/internal/handler/msg_getlog.go index a3204e47d7ca..0a32e7702f1f 100644 --- a/internal/handler/msg_getlog.go +++ b/internal/handler/msg_getlog.go @@ -107,7 +107,7 @@ func (h *Handler) MsgGetLog(ctx context.Context, msg *wire.OpMsg) (*wire.OpMsg, } if h.L.Level().Enabled(zap.DebugLevel) { - startupWarnings = append(startupWarnings, "Debug logging enabled. The security and erformance will be affected.") + startupWarnings = append(startupWarnings, "Debug logging enabled. The security and performance will be affected.") } switch { From 5cc1aa3639ff4f3027b3a4f7200561ad0febd1e0 Mon Sep 17 00:00:00 2001 From: Alexey Palazhchenko Date: Wed, 10 Jul 2024 08:41:25 +0400 Subject: [PATCH 07/11] Use logger's level in `getLog` --- internal/handler/msg_getlog.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/internal/handler/msg_getlog.go b/internal/handler/msg_getlog.go index 0a32e7702f1f..673e058065ec 100644 --- a/internal/handler/msg_getlog.go +++ b/internal/handler/msg_getlog.go @@ -75,7 +75,7 @@ func (h *Handler) MsgGetLog(ctx context.Context, msg *wire.OpMsg) (*wire.OpMsg, )) case "global": - log, err := logging.RecentEntries.GetArray(zap.DebugLevel) + log, err := logging.RecentEntries.GetArray(h.L.Level()) if err != nil { return nil, lazyerrors.Error(err) } From 17634f0278a17cc88fc9a4142b6ebb1012649a62 Mon Sep 17 00:00:00 2001 From: Alexey Palazhchenko Date: Wed, 10 Jul 2024 09:37:43 +0400 Subject: [PATCH 08/11] Simplify level handling --- .golangci.yml | 13 --- internal/handler/msg_getlog.go | 11 +- internal/util/logging/buffer.go | 20 ++-- internal/util/logging/buffer_test.go | 149 ++++++++++----------------- internal/util/logging/zap.go | 6 +- 5 files changed, 79 insertions(+), 120 deletions(-) diff --git a/.golangci.yml b/.golangci.yml index fc6dc5e5e2db..55b3c59e320d 100644 --- a/.golangci.yml +++ b/.golangci.yml @@ -33,19 +33,6 @@ linters-settings: - "**/internal/util/logging/*.go" deny: - pkg: github.com/FerretDB/FerretDB/internal/types - bson: - files: - - $all - - "!**/internal/backends/user.go" - - "!**/internal/bson/*_test.go" - - "!**/internal/driver/*.go" - - "!**/internal/handler/users/*.go" - - "!**/internal/util/logging/*.go" - - "!**/internal/util/password/*.go" - - "!**/internal/util/testutil/*.go" - - "!**/internal/wire/*.go" - deny: - - pkg: github.com/FerretDB/FerretDB/internal/bson bsonproto: files: - $all diff --git a/internal/handler/msg_getlog.go b/internal/handler/msg_getlog.go index 673e058065ec..308c3fd9ddbe 100644 --- a/internal/handler/msg_getlog.go +++ b/internal/handler/msg_getlog.go @@ -24,6 +24,7 @@ import ( "go.uber.org/zap" "github.com/FerretDB/FerretDB/build/version" + "github.com/FerretDB/FerretDB/internal/bson" "github.com/FerretDB/FerretDB/internal/handler/handlererrors" "github.com/FerretDB/FerretDB/internal/handler/handlerparams" "github.com/FerretDB/FerretDB/internal/types" @@ -75,13 +76,15 @@ func (h *Handler) MsgGetLog(ctx context.Context, msg *wire.OpMsg) (*wire.OpMsg, )) case "global": - log, err := logging.RecentEntries.GetArray(h.L.Level()) - if err != nil { + var res *bson.Array + + if res, err = logging.RecentEntries.GetArray(); err != nil { return nil, lazyerrors.Error(err) } + resDoc = must.NotFail(types.NewDocument( - "log", must.NotFail(log.Convert()), - "totalLinesWritten", int64(log.Len()), + "log", must.NotFail(res.Convert()), + "totalLinesWritten", int64(res.Len()), "ok", float64(1), )) diff --git a/internal/util/logging/buffer.go b/internal/util/logging/buffer.go index 044173638bff..6f75fd058821 100644 --- a/internal/util/logging/buffer.go +++ b/internal/util/logging/buffer.go @@ -48,28 +48,28 @@ func NewCircularBuffer(size int) *circularBuffer { } } -// append adds an entry in circularBuffer. -func (cb *circularBuffer) append(record *zapcore.Entry) { +// add adds an entry in circularBuffer. +func (cb *circularBuffer) add(record zapcore.Entry) { cb.mu.Lock() defer cb.mu.Unlock() - cb.records[cb.index] = record + cb.records[cb.index] = &record cb.index = (cb.index + 1) % len(cb.records) } -// get returns entries from circularBuffer with level at minLevel or above. -func (cb *circularBuffer) get(minLevel zapcore.Level) []*zapcore.Entry { +// get returns entries from circularBuffer. +func (cb *circularBuffer) get() []zapcore.Entry { cb.mu.RLock() defer cb.mu.RUnlock() l := len(cb.records) - res := make([]*zapcore.Entry, 0, l) + res := make([]zapcore.Entry, 0, l) for n := range l { i := (cb.index + n) % l - if r := cb.records[i]; r != nil && minLevel.Enabled(r.Level) { - res = append(res, cb.records[i]) + if r := cb.records[i]; r != nil { + res = append(res, *r) } } @@ -77,8 +77,8 @@ func (cb *circularBuffer) get(minLevel zapcore.Level) []*zapcore.Entry { } // GetArray is a version of Get that returns an array as expected by mongosh. -func (cb *circularBuffer) GetArray(minLevel zapcore.Level) (*bson.Array, error) { - records := cb.get(minLevel) +func (cb *circularBuffer) GetArray() (*bson.Array, error) { + records := cb.get() res := bson.MakeArray(len(records)) for _, r := range records { diff --git a/internal/util/logging/buffer_test.go b/internal/util/logging/buffer_test.go index 3887477d1e0c..db4a6c3fb0ec 100644 --- a/internal/util/logging/buffer_test.go +++ b/internal/util/logging/buffer_test.go @@ -15,7 +15,6 @@ package logging import ( - "fmt" "testing" "time" @@ -24,105 +23,71 @@ import ( "go.uber.org/zap/zapcore" ) -func TestCircularBuffer(t *testing.T) { - for name, tc := range map[string]struct { - size int - msgPanic string - }{ - "PanicNegativSize": { - size: -2, - msgPanic: "buffer size must be at least 1, but -2 provided", - }, - "PanicZeroSize": { - size: 0, - msgPanic: "buffer size must be at least 1, but 0 provided", - }, - } { - t.Run(name, func(t *testing.T) { - assert.PanicsWithValue(t, tc.msgPanic, func() { NewCircularBuffer(tc.size) }) - }) - } +func TestCircularBufferHook(t *testing.T) { + RecentEntries = NewCircularBuffer(2) + + Setup(zap.InfoLevel, "console", "") - cb := NewCircularBuffer(2) - for n, tc := range []struct { - inLog zapcore.Entry + for _, tc := range []struct { //nolint:vet // for readability + msg string + level zapcore.Level expected []zapcore.Entry - }{{ - inLog: zapcore.Entry{ - Level: 1, - Time: time.Date(2022, 12, 31, 11, 59, 1, 0, time.UTC), - Message: "message 1", + }{ + { + msg: "message 1", + level: zap.WarnLevel, + expected: []zapcore.Entry{{ + Level: zap.WarnLevel, + Message: "message 1", + }}, }, - expected: []zapcore.Entry{{ - Level: 1, - Time: time.Date(2022, 12, 31, 11, 59, 1, 0, time.UTC), - Message: "message 1", - }}, - }, { - inLog: zapcore.Entry{ - Level: 2, - Time: time.Date(2022, 12, 31, 11, 59, 2, 0, time.UTC), - Message: "message 2", + { + msg: "message 2", + level: zap.ErrorLevel, + expected: []zapcore.Entry{{ + Level: zap.WarnLevel, + Message: "message 1", + }, { + Level: zap.ErrorLevel, + Message: "message 2", + }}, }, - expected: []zapcore.Entry{{ - Level: 1, - Time: time.Date(2022, 12, 31, 11, 59, 1, 0, time.UTC), - Message: "message 1", - }, { - Level: 2, - Time: time.Date(2022, 12, 31, 11, 59, 2, 0, time.UTC), - Message: "message 2", - }}, - }, { - inLog: zapcore.Entry{ - Level: 3, - Time: time.Date(2022, 12, 31, 11, 59, 3, 0, time.UTC), - Message: "message 3", + { + msg: "debug not added", + level: zap.DebugLevel, + expected: []zapcore.Entry{{ + Level: zap.WarnLevel, + Message: "message 1", + }, { + Level: zap.ErrorLevel, + Message: "message 2", + }}, }, - expected: []zapcore.Entry{{ - Level: 2, - Time: time.Date(2022, 12, 31, 11, 59, 2, 0, time.UTC), - Message: "message 2", - }, { - Level: 3, - Time: time.Date(2022, 12, 31, 11, 59, 3, 0, time.UTC), - Message: "message 3", - }}, - }} { - t.Run(fmt.Sprintf("AppendGet_%d", n), func(t *testing.T) { - cb.append(&tc.inLog) - actual := cb.get(zap.DebugLevel) - for i, exp := range tc.expected { - assert.Equal(t, exp, *actual[i]) - } - }) - } + { + msg: "message 3", + level: zap.InfoLevel, + expected: []zapcore.Entry{{ + Level: zap.ErrorLevel, + Message: "message 2", + }, { + Level: zap.InfoLevel, + Message: "message 3", + }}, + }, + } { + t.Run(tc.msg, func(t *testing.T) { + zap.L().Log(tc.level, tc.msg) - Setup(zap.DebugLevel, "console", "") - logger := zap.L() + actual := RecentEntries.get() - for n, tc := range []struct { - addMsg string - expected []string - }{{ - addMsg: "Test message 1", - expected: []string{"Test message 1"}, - }, { - addMsg: "Test message 2", - expected: []string{"Test message 1", "Test message 2"}, - }, { - addMsg: "Test message 3", - expected: []string{"Test message 1", "Test message 2", "Test message 3"}, - }, { - addMsg: "Test message 4", - expected: []string{"Test message 1", "Test message 2", "Test message 3", "Test message 4"}, - }} { - t.Run(fmt.Sprintf("Intercept_%d", n), func(t *testing.T) { - logger.Info(tc.addMsg) - actual := RecentEntries.get(zap.DebugLevel) - for i, exp := range tc.expected { - assert.Equal(t, exp, actual[i].Message) + for i, a := range actual { + a.Time = time.Time{} + a.Caller = zapcore.EntryCaller{} + a.Stack = "" + actual[i] = a } + + assert.Equal(t, tc.expected, actual) }) } } diff --git a/internal/util/logging/zap.go b/internal/util/logging/zap.go index 3b18c1798ce9..8c322d1e5488 100644 --- a/internal/util/logging/zap.go +++ b/internal/util/logging/zap.go @@ -94,7 +94,11 @@ func Setup(level zapcore.Level, encoding, uuid string) { // WithHooks returns a logger with recent entries hooks. func WithHooks(logger *zap.Logger) *zap.Logger { return logger.WithOptions(zap.Hooks(func(entry zapcore.Entry) error { - RecentEntries.append(&entry) + // Zap documentation says this: + // Entries are pooled, so any functions that accept them MUST be careful not to + // retain references to them. + // So we store the value, not pointer. + RecentEntries.add(entry) return nil })) } From 5f79f4d2bb401e2060ceb3bcb2736740cb406b3e Mon Sep 17 00:00:00 2001 From: Alexey Palazhchenko Date: Wed, 10 Jul 2024 09:38:55 +0400 Subject: [PATCH 09/11] Comment --- internal/util/logging/zap.go | 3 +++ 1 file changed, 3 insertions(+) diff --git a/internal/util/logging/zap.go b/internal/util/logging/zap.go index 8c322d1e5488..9dab8eb9baee 100644 --- a/internal/util/logging/zap.go +++ b/internal/util/logging/zap.go @@ -94,11 +94,14 @@ func Setup(level zapcore.Level, encoding, uuid string) { // WithHooks returns a logger with recent entries hooks. func WithHooks(logger *zap.Logger) *zap.Logger { return logger.WithOptions(zap.Hooks(func(entry zapcore.Entry) error { + // Hook is called when entry is being written out; no need to compare logger's and entry's levels. + // Zap documentation says this: // Entries are pooled, so any functions that accept them MUST be careful not to // retain references to them. // So we store the value, not pointer. RecentEntries.add(entry) + return nil })) } From f2cbf1126e388468b5e43ddd503931f535b5f60b Mon Sep 17 00:00:00 2001 From: Alexey Palazhchenko Date: Wed, 10 Jul 2024 10:02:05 +0400 Subject: [PATCH 10/11] Update docs --- website/docs/configuration/observability.md | 34 ++++++++++++--------- 1 file changed, 19 insertions(+), 15 deletions(-) diff --git a/website/docs/configuration/observability.md b/website/docs/configuration/observability.md index 5f9e1d3de501..c97fb34bddc3 100644 --- a/website/docs/configuration/observability.md +++ b/website/docs/configuration/observability.md @@ -7,7 +7,17 @@ description: Observability ## Logging -FerretDB provides the following structured log formats: +FerretDB writes structured logs to the standard error (`stderr`) stream. +The most recent entries are also available via `getLog` command. + +:::note + + + +Structured log format is not stable yet; field names and formatting of values might change in minor releases. +::: + +FerretDB provides the following log formats: @@ -28,23 +38,21 @@ There are four logging levels: - `info` is used for various information messages; - `debug` should only be used for debugging. +The default level is `info`, except for [debug builds](https://pkg.go.dev/github.com/FerretDB/FerretDB/build/version#hdr-Debug_builds) that default to `debug`. + :::caution `debug`-level messages include complete query and response bodies, full error messages, authentication credentials, and other sensitive information. -Both the performance of FerretDB and the security of your environment will be affected when `debug` logging is enabled. -::: -The default level is `info`, except for [debug builds](https://pkg.go.dev/github.com/FerretDB/FerretDB/build/version#hdr-Debug_builds) that default to `debug`. +Since logs are often retained by the infrastructure +(and FerretDB itself makes recent entries available via the `getLog` command), +that poses a security risk. +Additionally, writing out a significantly larger number of log messages affects FerretDB performance. +For those reasons, the `debug` level should not be enabled in production environments. +::: The format and level can be adjusted by [configuration flags](flags.md#miscellaneous). -:::note - - - -Structured log format is not stable yet; field names and formatting of values might change in minor releases. -::: - ### Docker logs If Docker was launched with [our quick local setup with Docker Compose](../quickstart-guide/docker.md#postgresql-setup-with-docker-compose), @@ -66,10 +74,6 @@ CONTAINER ID IMAGE COMMAND CREATED $ docker logs my-ferretdb ``` -### Binary executable logs - -FerretDB writes logs to the standard error (`stderr`) stream. - ## Debug handler FerretDB exposes various HTTP endpoints with the debug handler on `http://127.0.0.1:8088/debug/` by default. From 0f7ce58150f0ac5b6d93ab0f063b193235511d98 Mon Sep 17 00:00:00 2001 From: Alexey Palazhchenko Date: Wed, 10 Jul 2024 10:13:09 +0400 Subject: [PATCH 11/11] Port tiny thing from another PR --- Taskfile.yml | 2 +- integration/Taskfile.yml | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/Taskfile.yml b/Taskfile.yml index 00e9f308bf2f..44148b98fccd 100644 --- a/Taskfile.yml +++ b/Taskfile.yml @@ -494,7 +494,7 @@ tasks: security-govulncheck: cmds: - - bin/govulncheck{{exeExt}} -test ./... + - bin/govulncheck{{exeExt}} -test -show=verbose,color ./... - bin/task{{exeExt}} -d integration integration-security security-trivy: diff --git a/integration/Taskfile.yml b/integration/Taskfile.yml index 38f756bfcd17..3d04547426fb 100644 --- a/integration/Taskfile.yml +++ b/integration/Taskfile.yml @@ -40,7 +40,7 @@ tasks: integration-security: cmds: - - ../bin/govulncheck{{exeExt}} -test ./... + - ../bin/govulncheck{{exeExt}} -test -show=verbose,color ./... bench-postgresql: desc: "Run benchmarks for `postgresql` backend"