// Copyright (C) MongoDB, Inc. 2023-present. // // 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 package logger import ( "bytes" "encoding/json" "fmt" "os" "reflect" "strings" "sync" "testing" "gitea.psichedelico.com/go/bson" "gitea.psichedelico.com/go/bson/internal/assert" "gitea.psichedelico.com/go/bson/x/bsonx/bsoncore" ) type mockLogSink struct{} func (mockLogSink) Info(int, string, ...interface{}) {} func (mockLogSink) Error(error, string, ...interface{}) {} func BenchmarkLoggerWithLargeDocuments(b *testing.B) { // Define the large document test cases testCases := []struct { name string create func() bson.D }{ { name: "LargeStrings", create: func() bson.D { return createLargeStringsDocument(10) }, }, { name: "MassiveArrays", create: func() bson.D { return createMassiveArraysDocument(100000) }, }, { name: "VeryVoluminousDocument", create: func() bson.D { return createVoluminousDocument(100000) }, }, } for _, tc := range testCases { tc := tc b.Run(tc.name, func(b *testing.B) { // Run benchmark with logging and truncation enabled b.Run("LoggingWithTruncation", func(b *testing.B) { logger, err := New(mockLogSink{}, 0, map[Component]Level{ ComponentCommand: LevelDebug, }) if err != nil { b.Fatal(err) } bs, err := bson.Marshal(tc.create()) if err != nil { b.Fatal(err) } b.ResetTimer() for i := 0; i < b.N; i++ { logger.Print(LevelInfo, ComponentCommand, FormatDocument(bs, 1024), "foo", "bar", "baz") } }) // Run benchmark with logging enabled without truncation b.Run("LoggingWithoutTruncation", func(b *testing.B) { logger, err := New(mockLogSink{}, 0, map[Component]Level{ ComponentCommand: LevelDebug, }) if err != nil { b.Fatal(err) } bs, err := bson.Marshal(tc.create()) if err != nil { b.Fatal(err) } b.ResetTimer() for i := 0; i < b.N; i++ { msg := bsoncore.Document(bs).String() logger.Print(LevelInfo, ComponentCommand, msg, "foo", "bar", "baz") } }) // Run benchmark without logging or truncation b.Run("WithoutLoggingOrTruncation", func(b *testing.B) { bs, err := bson.Marshal(tc.create()) if err != nil { b.Fatal(err) } b.ResetTimer() for i := 0; i < b.N; i++ { _ = bsoncore.Document(bs).String() } }) }) } } // Helper functions to create large documents func createVoluminousDocument(numKeys int) bson.D { d := make(bson.D, numKeys) for i := 0; i < numKeys; i++ { d = append(d, bson.E{Key: fmt.Sprintf("key%d", i), Value: "value"}) } return d } func createLargeStringsDocument(sizeMB int) bson.D { largeString := strings.Repeat("a", sizeMB*1024*1024) return bson.D{ {Key: "largeString1", Value: largeString}, {Key: "largeString2", Value: largeString}, {Key: "largeString3", Value: largeString}, {Key: "largeString4", Value: largeString}, } } func createMassiveArraysDocument(arraySize int) bson.D { massiveArray := make([]string, arraySize) for i := 0; i < arraySize; i++ { massiveArray[i] = "value" } return bson.D{ {Key: "massiveArray1", Value: massiveArray}, {Key: "massiveArray2", Value: massiveArray}, {Key: "massiveArray3", Value: massiveArray}, {Key: "massiveArray4", Value: massiveArray}, } } func BenchmarkLogger(b *testing.B) { b.ReportAllocs() b.ResetTimer() b.Run("Print", func(b *testing.B) { b.ReportAllocs() b.ResetTimer() logger, err := New(mockLogSink{}, 0, map[Component]Level{ ComponentCommand: LevelDebug, }) if err != nil { b.Fatal(err) } b.RunParallel(func(pb *testing.PB) { for pb.Next() { logger.Print(LevelInfo, ComponentCommand, "foo", "bar", "baz") } }) }) } func mockKeyValues(length int) (KeyValues, map[string]interface{}) { keysAndValues := KeyValues{} m := map[string]interface{}{} for i := 0; i < length; i++ { keyName := fmt.Sprintf("key%d", i) valueName := fmt.Sprintf("value%d", i) keysAndValues.Add(keyName, valueName) m[keyName] = valueName } return keysAndValues, m } func BenchmarkIOSinkInfo(b *testing.B) { keysAndValues, _ := mockKeyValues(10) b.ReportAllocs() b.ResetTimer() sink := NewIOSink(bytes.NewBuffer(nil)) b.RunParallel(func(pb *testing.PB) { for pb.Next() { sink.Info(0, "foo", keysAndValues...) } }) } func TestIOSinkInfo(t *testing.T) { t.Parallel() const threshold = 1000 mockKeyValues, kvmap := mockKeyValues(10) buf := new(bytes.Buffer) sink := NewIOSink(buf) wg := sync.WaitGroup{} wg.Add(threshold) for i := 0; i < threshold; i++ { go func() { defer wg.Done() sink.Info(0, "foo", mockKeyValues...) }() } wg.Wait() dec := json.NewDecoder(buf) for dec.More() { var m map[string]interface{} if err := dec.Decode(&m); err != nil { t.Fatalf("error unmarshaling JSON: %v", err) } delete(m, KeyTimestamp) delete(m, KeyMessage) if !reflect.DeepEqual(m, kvmap) { t.Fatalf("expected %v, got %v", kvmap, m) } } } func TestSelectMaxDocumentLength(t *testing.T) { for _, tcase := range []struct { name string arg uint expected uint env map[string]string }{ { name: "default", arg: 0, expected: DefaultMaxDocumentLength, }, { name: "non-zero", arg: 100, expected: 100, }, { name: "valid env", arg: 0, expected: 100, env: map[string]string{ maxDocumentLengthEnvVar: "100", }, }, { name: "invalid env", arg: 0, expected: DefaultMaxDocumentLength, env: map[string]string{ maxDocumentLengthEnvVar: "foo", }, }, } { tcase := tcase t.Run(tcase.name, func(t *testing.T) { for k, v := range tcase.env { t.Setenv(k, v) } actual := selectMaxDocumentLength(tcase.arg) if actual != tcase.expected { t.Errorf("expected %d, got %d", tcase.expected, actual) } }) } } func TestSelectLogSink(t *testing.T) { for _, tcase := range []struct { name string arg LogSink expected LogSink env map[string]string }{ { name: "default", arg: nil, expected: NewIOSink(os.Stderr), }, { name: "non-nil", arg: mockLogSink{}, expected: mockLogSink{}, }, { name: "stdout", arg: nil, expected: NewIOSink(os.Stdout), env: map[string]string{ logSinkPathEnvVar: logSinkPathStdout, }, }, { name: "stderr", arg: nil, expected: NewIOSink(os.Stderr), env: map[string]string{ logSinkPathEnvVar: logSinkPathStderr, }, }, } { tcase := tcase t.Run(tcase.name, func(t *testing.T) { for k, v := range tcase.env { t.Setenv(k, v) } actual, _, _ := selectLogSink(tcase.arg) if !reflect.DeepEqual(actual, tcase.expected) { t.Errorf("expected %+v, got %+v", tcase.expected, actual) } }) } } func TestSelectedComponentLevels(t *testing.T) { for _, tcase := range []struct { name string arg map[Component]Level expected map[Component]Level env map[string]string }{ { name: "default", arg: nil, expected: map[Component]Level{ ComponentCommand: LevelOff, ComponentTopology: LevelOff, ComponentServerSelection: LevelOff, ComponentConnection: LevelOff, }, }, { name: "non-nil", arg: map[Component]Level{ ComponentCommand: LevelDebug, }, expected: map[Component]Level{ ComponentCommand: LevelDebug, ComponentTopology: LevelOff, ComponentServerSelection: LevelOff, ComponentConnection: LevelOff, }, }, { name: "valid env", arg: nil, expected: map[Component]Level{ ComponentCommand: LevelDebug, ComponentTopology: LevelInfo, ComponentServerSelection: LevelOff, ComponentConnection: LevelOff, }, env: map[string]string{ mongoDBLogCommandEnvVar: levelLiteralDebug, mongoDBLogTopologyEnvVar: levelLiteralInfo, }, }, { name: "invalid env", arg: nil, expected: map[Component]Level{ ComponentCommand: LevelOff, ComponentTopology: LevelOff, ComponentServerSelection: LevelOff, ComponentConnection: LevelOff, }, env: map[string]string{ mongoDBLogCommandEnvVar: "foo", mongoDBLogTopologyEnvVar: "bar", }, }, } { tcase := tcase t.Run(tcase.name, func(t *testing.T) { for k, v := range tcase.env { t.Setenv(k, v) } actual := selectComponentLevels(tcase.arg) for k, v := range tcase.expected { if actual[k] != v { t.Errorf("expected %d, got %d", v, actual[k]) } } }) } } func TestLogger_LevelComponentEnabled(t *testing.T) { t.Parallel() tests := []struct { name string logger Logger level Level component Component want bool }{ { name: "zero", logger: Logger{}, level: LevelOff, component: ComponentCommand, want: false, }, { name: "empty", logger: Logger{ ComponentLevels: map[Component]Level{}, }, level: LevelOff, component: ComponentCommand, want: false, // LevelOff should never be considered enabled. }, { name: "one level below", logger: Logger{ ComponentLevels: map[Component]Level{ ComponentCommand: LevelDebug, }, }, level: LevelInfo, component: ComponentCommand, want: true, }, { name: "equal levels", logger: Logger{ ComponentLevels: map[Component]Level{ ComponentCommand: LevelDebug, }, }, level: LevelDebug, component: ComponentCommand, want: true, }, { name: "one level above", logger: Logger{ ComponentLevels: map[Component]Level{ ComponentCommand: LevelInfo, }, }, level: LevelDebug, component: ComponentCommand, want: false, }, { name: "component mismatch", logger: Logger{ ComponentLevels: map[Component]Level{ ComponentCommand: LevelDebug, }, }, level: LevelDebug, component: ComponentTopology, want: false, }, { name: "component all enables with topology", logger: Logger{ ComponentLevels: map[Component]Level{ ComponentAll: LevelDebug, }, }, level: LevelDebug, component: ComponentTopology, want: true, }, { name: "component all enables with server selection", logger: Logger{ ComponentLevels: map[Component]Level{ ComponentAll: LevelDebug, }, }, level: LevelDebug, component: ComponentServerSelection, want: true, }, { name: "component all enables with connection", logger: Logger{ ComponentLevels: map[Component]Level{ ComponentAll: LevelDebug, }, }, level: LevelDebug, component: ComponentConnection, want: true, }, { name: "component all enables with command", logger: Logger{ ComponentLevels: map[Component]Level{ ComponentAll: LevelDebug, }, }, level: LevelDebug, component: ComponentCommand, want: true, }, { name: "component all enables with all", logger: Logger{ ComponentLevels: map[Component]Level{ ComponentAll: LevelDebug, }, }, level: LevelDebug, component: ComponentAll, want: true, }, { name: "component all does not enable with lower level", logger: Logger{ ComponentLevels: map[Component]Level{ ComponentAll: LevelInfo, }, }, level: LevelDebug, component: ComponentCommand, want: false, }, { name: "component all has a lower log level than command", logger: Logger{ ComponentLevels: map[Component]Level{ ComponentAll: LevelInfo, ComponentCommand: LevelDebug, }, }, level: LevelDebug, component: ComponentCommand, want: true, }, { name: "component all has a higher log level than command", logger: Logger{ ComponentLevels: map[Component]Level{ ComponentAll: LevelDebug, ComponentCommand: LevelInfo, }, }, level: LevelDebug, component: ComponentCommand, want: true, }, } for _, tcase := range tests { tcase := tcase // Capture the range variable. t.Run(tcase.name, func(t *testing.T) { t.Parallel() got := tcase.logger.LevelComponentEnabled(tcase.level, tcase.component) assert.Equal(t, tcase.want, got, "unexpected result for LevelComponentEnabled") }) } }