Document logging changes (#4510)

FerretDB · Aug 2, 2024 · d9e77a8 · d9e77a8
1 parent efe2130
commit d9e77a8
Show file tree

Hide file tree

Showing 12 changed files with 73 additions and 30 deletions.
diff --git a/.github/workflows/cleanup.yml b/.github/workflows/cleanup.yml
@@ -22,8 +22,8 @@ jobs:
       - name: Checkout code
         uses: actions/checkout@v4
         with:
-          fetch-depth: 0
-          lfs: true
+          fetch-depth: 0 # for `git describe` to work
+          lfs: false # LFS is used only by website
 
       - name: Setup Go
         uses: FerretDB/github-actions/setup-go@main

diff --git a/.github/workflows/debug.yml b/.github/workflows/debug.yml
@@ -39,8 +39,8 @@ jobs:
       - name: Checkout code
         uses: actions/checkout@v4
         with:
-          fetch-depth: 0
-          lfs: false
+          fetch-depth: 0 # for `git describe` to work
+          lfs: false # LFS is used only by website
 
       - name: Debug git status
         run: git status

diff --git a/.github/workflows/go.yml b/.github/workflows/go.yml
@@ -316,6 +316,7 @@ jobs:
           ssh-key: ${{ secrets.FUZZ_CORPUS_DEPLOY_KEY }}
           path: fuzz-corpus
           fetch-depth: 0 # for commit and push to work
+          lfs: false # LFS is used only by website
 
       - name: Setup corpus
         run: bin/task fuzz-corpus

diff --git a/.github/workflows/packages.yml b/.github/workflows/packages.yml
@@ -74,8 +74,8 @@ jobs:
         if: github.event_name == 'pull_request_target'
         uses: actions/checkout@v4
         with:
-          fetch-depth: 0
-          lfs: false
+          fetch-depth: 0 # for `git describe` to work
+          lfs: false # LFS is used only by website
           ref: ${{ github.event.pull_request.head.sha }}
 
       # for version.txt on push tags; see https://github.com/actions/checkout/issues/290

diff --git a/.golangci.yml b/.golangci.yml
@@ -28,6 +28,14 @@ linters-settings:
             desc: use `github.com/jackc/pgx/v5` package instead
           - pkg: github.com/jackc/pgx/v4
             desc: use `github.com/jackc/pgx/v5` package instead
+
+      ferretdb-in-tools:
+        files:
+          - "**/tools/**/*.go"
+        deny:
+          - pkg: github.com/FerretDB/FerretDB/internal/
+            desc: tools should not import FerretDB code
+
       types:
         files:
           - "**/internal/util/logging/*.go"

diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -2,6 +2,15 @@
 
 <!-- markdownlint-disable MD024 MD034 -->
 
+## [v1.24.0](https://github.com/FerretDB/FerretDB/releases/tag/v1.24.0) (TBD)
+
+### What's Changed
+
+#### Embeddable package
+
+As communicated in the previous release, this version renames the `SLogger` field to `Logger`,
+finishing the migration from [`zap`](https://github.com/uber-go/zap) to [`slog`](https://pkg.go.dev/log/slog).
+
 ## [v1.23.0](https://github.com/FerretDB/FerretDB/releases/tag/v1.23.0) (2024-07-25)
 
 ### What's Changed

diff --git a/CONTRIBUTING.md b/CONTRIBUTING.md
@@ -262,12 +262,12 @@ Some of our idiosyncrasies are documented below.
 
 (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,
+1. Log messages should contain a single sentence; use a semicolon if you must.
+2. Log messages should not have leading/trailing spaces or end with punctuation.
+3. Log field names should use `snake_case`.
+4. Whatever sensitive information can be logged should be checked by calling `.Enabled(slog.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.
+   The same check should be applied if additional sensitive fields should be added to the log message on a different level.
 
 #### Integration tests conventions
 

diff --git a/ferretdb/ferretdb_test.go b/ferretdb/ferretdb_test.go
@@ -173,7 +173,7 @@ func TestEmbedded(t *testing.T) {
 		},
 		Logger:        testutil.Logger(t),
 		Handler:       "postgresql",
-		PostgreSQLURL: testutil.TestPostgreSQLURI(t, ctx, "postgres://username@127.0.0.1:5432/ferretdb?search_path="),
+		PostgreSQLURL: testutil.TestPostgreSQLURI(t, ctx, ""),
 	})
 	require.NoError(t, err)
 

diff --git a/internal/types/logging_test.go b/internal/types/logging_test.go
@@ -44,22 +44,25 @@ func TestLogging(t *testing.T) {
 
 	var cbuf, tbuf, jbuf bytes.Buffer
 	clog := slog.New(logging.NewHandler(&cbuf, &logging.NewHandlerOpts{
-		Base:         "console",
-		RemoveTime:   true,
-		RemoveLevel:  true,
-		RemoveSource: true,
+		Base:          "console",
+		RemoveTime:    true,
+		RemoveLevel:   true,
+		RemoveSource:  true,
+		CheckMessages: true,
 	}))
 	tlog := slog.New(logging.NewHandler(&tbuf, &logging.NewHandlerOpts{
-		Base:         "text",
-		RemoveTime:   true,
-		RemoveLevel:  true,
-		RemoveSource: true,
+		Base:          "text",
+		RemoveTime:    true,
+		RemoveLevel:   true,
+		RemoveSource:  true,
+		CheckMessages: true,
 	}))
 	jlog := slog.New(logging.NewHandler(&jbuf, &logging.NewHandlerOpts{
-		Base:         "json",
-		RemoveTime:   true,
-		RemoveLevel:  true,
-		RemoveSource: true,
+		Base:          "json",
+		RemoveTime:    true,
+		RemoveLevel:   true,
+		RemoveSource:  true,
+		CheckMessages: true,
 	}))
 
 	for _, tc := range []struct {

diff --git a/internal/util/logging/buffer_test.go b/internal/util/logging/buffer_test.go
@@ -27,8 +27,9 @@ func TestCircularBufferHandler(t *testing.T) {
 	RecentEntries = NewCircularBuffer(2)
 
 	opts := &NewHandlerOpts{
-		Base:  "console",
-		Level: slog.LevelInfo,
+		Base:          "console",
+		Level:         slog.LevelInfo,
+		CheckMessages: true,
 	}
 	Setup(opts, "")
 

diff --git a/internal/util/logging/handler.go b/internal/util/logging/handler.go
@@ -21,6 +21,7 @@ import (
 	"log/slog"
 	"os"
 	"path/filepath"
+	"strings"
 
 	"github.com/FerretDB/FerretDB/internal/util/debugbuild"
 	"github.com/FerretDB/FerretDB/internal/util/must"
@@ -31,10 +32,12 @@ import (
 //     (DPanic/ERROR+1 panics in debug builds, Panic/ERROR+2 always panics, Fatal/ERROR+3 exits with a non-zero status);
 //   - shorter source locations;
 //   - removal of time, level, and source attributes;
+//   - message checks for leading/trailing spaces and ending punctuation;
 //   - collecting recent log entries for `getLog` command.
 type Handler struct {
-	base slog.Handler
-	out  io.Writer
+	base          slog.Handler
+	out           io.Writer
+	checkMessages bool
 }
 
 // NewHandlerOpts represents [NewHandler] options.
@@ -46,6 +49,13 @@ type NewHandlerOpts struct {
 	RemoveTime   bool
 	RemoveLevel  bool
 	RemoveSource bool
+
+	// When set, causes handler to panic on messages with leading/trailing spaces or ending punctuation.
+	// It must not be set unconditionally because we don't control messages from third-party packages.
+	//
+	// But we can enable it in our tests and when [debugbuild.Enabled] is true.
+	// TODO https://github.com/FerretDB/FerretDB/issues/4511
+	CheckMessages bool
 }
 
 // shortPath returns shorter path for the given path.
@@ -148,6 +158,16 @@ func (h *Handler) Handle(ctx context.Context, r slog.Record) error {
 		must.NoError(err)
 	}
 
+	if h.checkMessages {
+		if strings.TrimSpace(r.Message) != r.Message {
+			panic(fmt.Sprintf("message %q has leading/trailing spaces", r.Message))
+		}
+
+		if strings.TrimRight(r.Message, ".?!") != r.Message {
+			panic(fmt.Sprintf("message %q ends with punctuation", r.Message))
+		}
+	}
+
 	RecentEntries.add(&r)
 
 	if r.Level < LevelDPanic {

diff --git a/internal/util/logging/handler_test.go b/internal/util/logging/handler_test.go
@@ -56,8 +56,9 @@ func TestHandler(t *testing.T) {
 
 			var buf bytes.Buffer
 			var h slog.Handler = NewHandler(&buf, &NewHandlerOpts{
-				Base:  base,
-				Level: slog.LevelInfo,
+				Base:          base,
+				Level:         slog.LevelInfo,
+				CheckMessages: true,
 			})
 
 			h = h.WithGroup("g2")