Add stub for named slog logger helper

FerretDB · AlekSi · Jul 9, 2024 · Jul 8, 2024 · Jul 9, 2024 · Jul 9, 2024
commit 45a841dd8c40754b42f0708bfb9867c26de109f5
@@ -28,13 +28,19 @@ 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
+      types:
+        files:
+          - "**/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"

@@ -80,7 +80,7 @@ func (h *Handler) MsgGetLog(ctx context.Context, msg *wire.OpMsg) (*wire.OpMsg,
 			return nil, lazyerrors.Error(err)
 		}
 		resDoc = must.NotFail(types.NewDocument(
-			"log", log,
+			"log", must.NotFail(log.Convert()),
 			"totalLinesWritten", int64(log.Len()),
 			"ok", float64(1),
 		))

@@ -22,80 +22,80 @@
 
 	"go.uber.org/zap/zapcore"
 
-	"github.com/FerretDB/FerretDB/internal/types"
+	"github.com/FerretDB/FerretDB/internal/bson"
 	"github.com/FerretDB/FerretDB/internal/util/lazyerrors"
 )
 
-// RecentEntries implements zap logging entries interception
+// RecentEntries implements log records interception
 // and stores the last 1024 entries in circular buffer in memory.
 var RecentEntries = NewCircularBuffer(1024)
 
 // circularBuffer is a storage of log records in memory.
 type circularBuffer struct {
-	mu    sync.RWMutex
-	log   []*zapcore.Entry
-	index int64
+	mu      sync.RWMutex
+	records []*zapcore.Entry
+	index   int
 }
 
-// NewCircularBuffer creates a circular buffer for log entries in memory.
-func NewCircularBuffer(size int64) *circularBuffer {
+// NewCircularBuffer creates a circular buffer for log records in memory.
+func NewCircularBuffer(size int) *circularBuffer {
 	if size < 1 {
 		panic(fmt.Sprintf("buffer size must be at least 1, but %d provided", size))
 	}
 
 	return &circularBuffer{
-		log: make([]*zapcore.Entry, size),
+		records: make([]*zapcore.Entry, size),
 	}
 }
 
 // append adds an entry in circularBuffer.
-func (l *circularBuffer) append(entry *zapcore.Entry) {
-	l.mu.Lock()
-	defer l.mu.Unlock()
+func (cb *circularBuffer) append(record *zapcore.Entry) { // cb
+	cb.mu.Lock()
+	defer cb.mu.Unlock()
 
-	l.log[l.index] = entry
-	l.index = (l.index + 1) % int64(len(l.log))
+	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 (l *circularBuffer) get(minLevel zapcore.Level) []*zapcore.Entry {
-	l.mu.RLock()
-	defer l.mu.RUnlock()
+func (cb *circularBuffer) get(minLevel zapcore.Level) []*zapcore.Entry {
+	cb.mu.RLock()
+	defer cb.mu.RUnlock()
 
-	n := len(l.log)
-	entries := make([]*zapcore.Entry, 0, n)
-	for i := int64(0); i < int64(len(l.log)); i++ {
-		k := (i + l.index) % int64(len(l.log))
+	l := len(cb.records)
+	res := make([]*zapcore.Entry, 0, l)
 
-		if l.log[k] != nil && l.log[k].Level >= minLevel {
-			entries = append(entries, l.log[k])
+	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])
 		}
 	}
 
-	return entries
+	return res
 }
 
 // GetArray is a version of Get that returns an array as expected by mongosh.
-func (l *circularBuffer) GetArray(minLevel zapcore.Level) (*types.Array, error) {
-	entries := l.get(minLevel)
-	res := types.MakeArray(len(entries))
+func (cb *circularBuffer) GetArray(minLevel zapcore.Level) (*bson.Array, error) {
+	records := cb.get(minLevel)
+	res := bson.MakeArray(len(records))
 
-	for _, e := range entries {
+	for _, r := range records {
 		b, err := json.Marshal(map[string]any{
 			"t": map[string]time.Time{
-				"$date": e.Time,
+				"$date": r.Time,
 			},
-			"l":   e.Level,
-			"ln":  e.LoggerName,
-			"msg": e.Message,
-			"c":   e.Caller,
-			"s":   e.Stack,
+			"l":   r.Level,
+			"msg": r.Message,
 		})
 		if err != nil {
 			return nil, lazyerrors.Error(err)
 		}
 
-		res.Append(string(b))
+		if err = res.Add(string(b)); err != nil {
+			return nil, lazyerrors.Error(err)
+		}
 	}
 
 	return res, nil

@@ -26,7 +26,7 @@ import (
 
 func TestCircularBuffer(t *testing.T) {
 	for name, tc := range map[string]struct {
-		size     int64
+		size     int
 		msgPanic string
 	}{
 		"PanicNegativSize": {
@@ -38,71 +38,60 @@ func TestCircularBuffer(t *testing.T) {
 			msgPanic: "buffer size must be at least 1, but 0 provided",
 		},
 	} {
-		name, tc := name, tc
 		t.Run(name, func(t *testing.T) {
 			assert.PanicsWithValue(t, tc.msgPanic, func() { NewCircularBuffer(tc.size) })
 		})
 	}
 
-	logram := NewCircularBuffer(2)
+	cb := NewCircularBuffer(2)
 	for n, tc := range []struct {
 		inLog    zapcore.Entry
 		expected []zapcore.Entry
 	}{{
 		inLog: zapcore.Entry{
-			Level:      1,
-			Time:       time.Date(2022, 12, 31, 11, 59, 1, 0, time.UTC),
-			LoggerName: "logger_1",
-			Message:    "message 1",
+			Level:   1,
+			Time:    time.Date(2022, 12, 31, 11, 59, 1, 0, time.UTC),
+			Message: "message 1",
 		},
 		expected: []zapcore.Entry{{
-			Level:      1,
-			Time:       time.Date(2022, 12, 31, 11, 59, 1, 0, time.UTC),
-			LoggerName: "logger_1",
-			Message:    "message 1",
+			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),
-			LoggerName: "logger_2",
-			Message:    "message 2",
+			Level:   2,
+			Time:    time.Date(2022, 12, 31, 11, 59, 2, 0, time.UTC),
+			Message: "message 2",
 		},
 		expected: []zapcore.Entry{{
-			Level:      1,
-			Time:       time.Date(2022, 12, 31, 11, 59, 1, 0, time.UTC),
-			LoggerName: "logger_1",
-			Message:    "message 1",
+			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),
-			LoggerName: "logger_2",
-			Message:    "message 2",
+			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),
-			LoggerName: "logger_3",
-			Message:    "message 3",
+			Level:   3,
+			Time:    time.Date(2022, 12, 31, 11, 59, 3, 0, time.UTC),
+			Message: "message 3",
 		},
 		expected: []zapcore.Entry{{
-			Level:      2,
-			Time:       time.Date(2022, 12, 31, 11, 59, 2, 0, time.UTC),
-			LoggerName: "logger_2",
-			Message:    "message 2",
+			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),
-			LoggerName: "logger_3",
-			Message:    "message 3",
+			Level:   3,
+			Time:    time.Date(2022, 12, 31, 11, 59, 3, 0, time.UTC),
+			Message: "message 3",
 		}},
 	}} {
-		name := fmt.Sprintf("AppendGet_%d", n)
-		tc := tc
-		t.Run(name, func(t *testing.T) {
-			logram.append(&tc.inLog)
-			actual := logram.get(zap.DebugLevel)
+		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])
 			}
@@ -128,9 +117,7 @@ func TestCircularBuffer(t *testing.T) {
 		addMsg:   "Test message 4",
 		expected: []string{"Test message 1", "Test message 2", "Test message 3", "Test message 4"},
 	}} {
-		name := fmt.Sprintf("ZapHooks_%d", n)
-		tc := tc
-		t.Run(name, func(t *testing.T) {
+		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 {

@@ -0,0 +1,85 @@
+// Copyright 2021 FerretDB Inc.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+package logging
+
+import (
+	"bytes"
+	"context"
+	"encoding/hex"
+	"log/slog"
+	"runtime"
+	"testing"
+	"time"
+
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+)
+
+func TestHandler(t *testing.T) {
+	t.Parallel()
+
+	ctx := context.Background()
+	pc, _, _, _ := runtime.Caller(0)
+	r := slog.NewRecord(time.Date(2024, 5, 31, 9, 26, 42, 0, time.UTC), slog.LevelInfo, "multi\nline\nmessage\n\n", pc)
+
+	r.AddAttrs(slog.Group("g1", slog.Int("k1", 42), slog.Duration("k2", 7*time.Second)))
+	r.AddAttrs(slog.Group("g4", slog.Group("g5")))
+	r.AddAttrs(slog.String("k3", "s"))
+	r.AddAttrs(slog.String("k3", "dup"))
+
+	for base, expected := range map[string]string{
+		"console": `2024-05-31T09:26:42.000Z	INFO	logging/handler_test.go:34	` +
+			"multi\nline\nmessage\n\n\t" +
+			`{"g2":{"g1":{"k1":42,"k2":7000000000},"g3":{"s":"a"},"i":1,"k3":"dup"}}` + "\n",
+		"text": `time=2024-05-31T09:26:42.000Z level=INFO source=logging/handler_test.go:34 ` +
+			`msg="multi\nline\nmessage\n\n" ` +
+			`g2.i=1 g2.g3.s=a g2.g1.k1=42 g2.g1.k2=7s g2.k3=s g2.k3=dup` + "\n",
+		"json": `{"time":"2024-05-31T09:26:42Z","level":"INFO","source":` +
+			`{"function":"github.com/FerretDB/FerretDB/internal/util/logging.TestHandler",` +
+			`"file":"logging/handler_test.go","line":34},"msg":"multi\nline\nmessage\n\n"` +
+			`,"g2":{"i":1,"g3":{"s":"a"},"g1":{"k1":42,"k2":7000000000},"k3":"s","k3":"dup"}}` + "\n",
+	} {
+		t.Run(base, func(t *testing.T) {
+			t.Parallel()
+
+			var buf bytes.Buffer
+			var h slog.Handler = NewHandler(&buf, &NewHandlerOpts{
+				Base:  base,
+				Level: slog.LevelInfo,
+			})
+
+			h = h.WithGroup("g2")
+			h = h.WithAttrs([]slog.Attr{
+				slog.Int("i", 1),
+			})
+			h = h.WithAttrs([]slog.Attr{
+				slog.Group("g3", slog.String("s", "a")),
+			})
+
+			require.NoError(t, h.Handle(ctx, r))
+
+			assert.Equal(t, expected, buf.String(), "actual:\n%s", hex.Dump(buf.Bytes()))
+		})
+	}
+}
+
+func TestShortPath(t *testing.T) {
+	t.Parallel()
+
+	assert.Equal(t, "file.go", shortPath("/file.go"))
+	assert.Equal(t, "dir1/file.go", shortPath("/dir1/file.go"))
+	assert.Equal(t, "dir2/file.go", shortPath("/dir1/dir2/file.go"))
+	assert.Equal(t, "dir3/file.go", shortPath("/dir1/dir2/dir3/file.go"))
+}
@@ -52,6 +52,12 @@
 	return slog.String("error", fmt.Sprintf("%#v", err))
 }
 
+// Named returns a logger with name segment added to existing name.
+func Named(l *slog.Logger, name string) *slog.Logger {
+	// TODO https://github.com/FerretDB/FerretDB/issues/4431
+	return l
+}
+
 // setupSlog initializes slog logging with given options and UUID.
 func setupSlog(opts *NewHandlerOpts, uuid string) {
 	must.NotBeZero(opts)