diff --git a/.golangci.yml b/.golangci.yml index b5080d143113..fc6dc5e5e2db 100644 --- a/.golangci.yml +++ b/.golangci.yml @@ -28,6 +28,11 @@ 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 @@ -35,6 +40,7 @@ linters-settings: - "!**/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" diff --git a/internal/handler/msg_getlog.go b/internal/handler/msg_getlog.go index 25ee42ebf047..7e04624a5cca 100644 --- a/internal/handler/msg_getlog.go +++ b/internal/handler/msg_getlog.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), )) diff --git a/internal/util/logging/buffer.go b/internal/util/logging/buffer.go index 836bb6de2c6d..7582b4e9441a 100644 --- a/internal/util/logging/buffer.go +++ b/internal/util/logging/buffer.go @@ -22,80 +22,80 @@ import ( "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.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 diff --git a/internal/util/logging/buffer_test.go b/internal/util/logging/buffer_test.go index 638d1d1980dd..3887477d1e0c 100644 --- a/internal/util/logging/buffer_test.go +++ b/internal/util/logging/buffer_test.go @@ -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 { diff --git a/internal/util/logging/handler_test.go b/internal/util/logging/handler_test.go new file mode 100644 index 000000000000..359aa560670f --- /dev/null +++ b/internal/util/logging/handler_test.go @@ -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")) +} diff --git a/internal/util/logging/logging.go b/internal/util/logging/logging.go index 65139005e497..bcfbee4934f4 100644 --- a/internal/util/logging/logging.go +++ b/internal/util/logging/logging.go @@ -52,6 +52,12 @@ func GoError(err error) slog.Attr { 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)