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/CONTRIBUTING.md b/CONTRIBUTING.md index a85e7c78d2d0..a8128ad70d14 100644 --- a/CONTRIBUTING.md +++ b/CONTRIBUTING.md @@ -236,27 +236,38 @@ 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 + +(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 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 @@ -288,6 +299,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/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/cmd/ferretdb/main.go b/cmd/ferretdb/main.go index 642959aadc04..36ecd4dca232 100644 --- a/cmd/ferretdb/main.go +++ b/cmd/ferretdb/main.go @@ -382,7 +382,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 security and performance will be affected.") } checkFlags(logger) 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" 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/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_getlog.go b/internal/handler/msg_getlog.go index 7e04624a5cca..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(zap.DebugLevel) - 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), )) @@ -106,6 +109,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 security and performance will be affected.") + } + switch { case state.Telemetry == nil: startupWarnings = append( 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/logging/buffer.go b/internal/util/logging/buffer.go index 7582b4e9441a..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 && r.Level >= minLevel { - 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/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/internal/util/logging/zap.go b/internal/util/logging/zap.go index 3b18c1798ce9..9dab8eb9baee 100644 --- a/internal/util/logging/zap.go +++ b/internal/util/logging/zap.go @@ -94,7 +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 { - RecentEntries.append(&entry) + // 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 })) } 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 diff --git a/website/docs/configuration/observability.md b/website/docs/configuration/observability.md index a055411efa24..c97fb34bddc3 100644 --- a/website/docs/configuration/observability.md +++ b/website/docs/configuration/observability.md @@ -7,9 +7,51 @@ description: Observability ## Logging -The log level and format can be adjusted by [configuration flags](flags.md#miscellaneous). +FerretDB writes structured logs to the standard error (`stderr`) stream. +The most recent entries are also available via `getLog` command. -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. +::: + +FerretDB provides the following 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. + +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. + +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). ### Docker logs @@ -32,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.