Document logging (#4436)

.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

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
 
+<!-- https://github.com/FerretDB/FerretDB/issues/694 -->
+
 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.

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:

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)

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"

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,

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

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(

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)

internal/util/logging/buffer.go

@@ -48,37 +48,37 @@ 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)
 		}
 	}
 
 	return res
 }
 
 // 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 {