Fix logging of deeply nested documents (#4167)

Closes #3759.

go.mod

@@ -68,7 +68,7 @@ require (
 	golang.org/x/net v0.21.0 // indirect
 	golang.org/x/sync v0.6.0 // indirect
 	golang.org/x/text v0.14.0 // indirect
-	golang.org/x/tools v0.18.0 // indirect
+	golang.org/x/tools v0.18.0 // indirect; https://github.com/golang/go/issues/66259
 	google.golang.org/genproto/googleapis/api v0.0.0-20240102182953-50ed04b92917 // indirect
 	google.golang.org/genproto/googleapis/rpc v0.0.0-20240102182953-50ed04b92917 // indirect
 	google.golang.org/grpc v1.61.0 // indirect

integration/basic_test.go

@@ -552,58 +552,6 @@ func TestDebugError(t *testing.T) {
 	})
 }
 
-func TestCheckingNestedDocuments(t *testing.T) {
-	t.Skip("https://github.com/FerretDB/FerretDB/issues/3759")
-
-	for name, tc := range map[string]struct {
-		doc any
-		err *mongo.CommandError
-	}{
-		"1ok": {
-			doc: CreateNestedDocument(1),
-		},
-		"10ok": {
-			doc: CreateNestedDocument(10),
-		},
-		"100ok": {
-			doc: CreateNestedDocument(100),
-		},
-		"179ok": {
-			doc: CreateNestedDocument(179),
-		},
-		"180fail": {
-			doc: CreateNestedDocument(180),
-			err: &mongo.CommandError{
-				Message: "bson.Array.ReadFrom (document has exceeded the max supported nesting: 179.",
-			},
-		},
-		"180endedWithDocumentFail": {
-			doc: bson.D{{"v", CreateNestedDocument(179)}},
-			err: &mongo.CommandError{
-				Message: "bson.Document.ReadFrom (document has exceeded the max supported nesting: 179.",
-			},
-		},
-		"1000fail": {
-			doc: CreateNestedDocument(1000),
-			err: &mongo.CommandError{
-				Message: "bson.Document.ReadFrom (document has exceeded the max supported nesting: 179.",
-			},
-		},
-	} {
-		t.Run(name, func(t *testing.T) {
-			ctx, collection := setup.Setup(t)
-
-			_, err := collection.InsertOne(ctx, tc.doc)
-			if tc.err != nil {
-				AssertEqualCommandError(t, *tc.err, err)
-				return
-			}
-
-			require.NoError(t, err)
-		})
-	}
-}
-
 func TestPingCommand(t *testing.T) {
 	t.Parallel()
 

integration/benchmarks_test.go

@@ -54,7 +54,7 @@ func BenchmarkFind(b *testing.B) {
 			b.Run(name, func(b *testing.B) {
 				var firstDocs, docs int
 
-				for i := 0; i < b.N; i++ {
+				for range b.N {
 					cursor, err := s.Collection.Find(s.Ctx, bc.filter)
 					require.NoError(b, err)
 
@@ -112,7 +112,7 @@ func BenchmarkReplaceOne(b *testing.B) {
 		filter := bson.D{{"_id", doc[0].Value}}
 		var res *mongo.UpdateResult
 
-		for i := 0; i < b.N; i++ {
+		for i := range b.N {
 			doc[1].Value = int64(i + 1)
 
 			res, err = collection.ReplaceOne(ctx, filter, doc)
@@ -148,7 +148,7 @@ func BenchmarkInsertMany(b *testing.B) {
 			b.Run(fmt.Sprintf("%s/Batch%d", provider.Name(), batchSize), func(b *testing.B) {
 				b.StopTimer()
 
-				for i := 0; i < b.N; i++ {
+				for range b.N {
 					require.NoError(b, collection.Drop(ctx))
 
 					iter := provider.NewIterator()

integration/go.mod

@@ -68,7 +68,7 @@ require (
 	golang.org/x/sync v0.6.0 // indirect
 	golang.org/x/sys v0.17.0 // indirect
 	golang.org/x/text v0.14.0 // indirect
-	golang.org/x/tools v0.18.0 // indirect
+	golang.org/x/tools v0.18.0 // indirect; https://github.com/golang/go/issues/66259
 	google.golang.org/genproto/googleapis/api v0.0.0-20240102182953-50ed04b92917 // indirect
 	google.golang.org/genproto/googleapis/rpc v0.0.0-20240102182953-50ed04b92917 // indirect
 	google.golang.org/grpc v1.61.0 // indirect

integration/integration.go

@@ -458,29 +458,3 @@ func GenerateDocuments(startID, endID int32) (bson.A, []bson.D) {
 
 	return arr, docs
 }
-
-// CreateNestedDocument creates a mock BSON document that consists of nested arrays and documents.
-// The nesting level is based on integer parameter.
-func CreateNestedDocument(n int) bson.D {
-	return createNestedDocument(n, false).(bson.D)
-}
-
-// createNestedDocument creates the nested n times object that consists of
-// documents and arrays. If the arr is true, the root value will be array.
-//
-// This function should be used only internally.
-// To generate values for tests please use
-// exported CreateNestedDocument function.
-func createNestedDocument(n int, arr bool) any {
-	var child any
-
-	if n > 0 {
-		child = createNestedDocument(n-1, !arr)
-	}
-
-	if arr {
-		return bson.A{child}
-	}
-
-	return bson.D{{"v", child}}
-}

internal/bson/bson_test.go

@@ -228,7 +228,7 @@ func benchmark(b *testing.B, testCases []testCase, newFunc func() bsontype) {
 				b.SetBytes(br.Size())
 				b.ResetTimer()
 
-				for i := 0; i < b.N; i++ {
+				for range b.N {
 					_, seekErr = br.Seek(0, io.SeekStart)
 
 					v = newFunc()

internal/bson2/array.go

@@ -141,7 +141,7 @@ func (arr *Array) Encode() (RawArray, error) {
 
 // LogValue implements slog.LogValuer interface.
 func (arr *Array) LogValue() slog.Value {
-	return slogValue(arr)
+	return slogValue(arr, 1)
 }
 
 // LogMessage returns an indented representation as a string,

internal/bson2/bson2_test.go

@@ -285,6 +285,19 @@ var normalTestCases = []normalTestCase{
 		  "timestamp": [Timestamp(42), Timestamp(0)],
 		}`,
 	},
+	{
+		name: "nested",
+		raw:  testutil.MustParseDumpFile("testdata", "nested.hex"),
+		tdoc: must.NotFail(makeNested(false, 150).(*Document).Convert()),
+		m: `
+		{
+		  "f": [
+		    {
+		      "f": [{"f": [{"f": [{"f": [{"f": [{"f": [{"f": [{"f": [{"f": [{...}]}]}]}]}]}]}]}]}],
+		    },
+		  ],
+		}`,
+	},
 	{
 		name: "float64Doc",
 		raw: RawDocument{

internal/bson2/document.go

@@ -175,7 +175,7 @@ func (doc *Document) Encode() (RawDocument, error) {
 
 // LogValue implements slog.LogValuer interface.
 func (doc *Document) LogValue() slog.Value {
-	return slogValue(doc)
+	return slogValue(doc, 1)
 }
 
 // LogMessage returns an indented representation as a string,

internal/bson2/logging.go

@@ -25,9 +25,12 @@ import (
 	"time"
 )
 
-// flowLimit is the maximum length of a flow/inline/compact representation of a BSON value.
+// logMaxFlowLength is the maximum length of a flow/inline/compact representation of a BSON value.
 // It may be set to 0 to disable flow representation.
-const flowLimit = 80
+const logMaxFlowLength = 80
+
+// logMaxDepth is the maximum depth of a recursive representation of a BSON value.
+const logMaxDepth = 20
 
 // nanBits is the most common pattern of a NaN float64 value, the same as math.Float64bits(math.NaN()).
 const nanBits = 0b111111111111000000000000000000000000000000000000000000000000001
@@ -42,13 +45,17 @@ const nanBits = 0b11111111111100000000000000000000000000000000000000000000000000
 // More information is subsequently lost in handlers output;
 // for example, float64(42), int32(42), and int64(42) values would all look the same
 // (`f64=42 i32=42 i64=42` or `{"f64":42,"i32":42,"i64":42}`).
-func slogValue(v any) slog.Value {
+func slogValue(v any, depth int) slog.Value {
 	switch v := v.(type) {
 	case *Document:
+		if depth > logMaxDepth {
+			return slog.StringValue("Document<...>")
+		}
+
 		var attrs []slog.Attr
 
 		for _, f := range v.fields {
-			attrs = append(attrs, slog.Attr{Key: f.name, Value: slogValue(f.value)})
+			attrs = append(attrs, slog.Attr{Key: f.name, Value: slogValue(f.value, depth+1)})
 		}
 
 		return slog.GroupValue(attrs...)
@@ -61,10 +68,14 @@ func slogValue(v any) slog.Value {
 		return slog.StringValue("RawDocument<" + strconv.Itoa(len(v)) + ">")
 
 	case *Array:
+		if depth > logMaxDepth {
+			return slog.StringValue("Array<...>")
+		}
+
 		var attrs []slog.Attr
 
 		for i, v := range v.elements {
-			attrs = append(attrs, slog.Attr{Key: strconv.Itoa(i), Value: slogValue(v)})
+			attrs = append(attrs, slog.Attr{Key: strconv.Itoa(i), Value: slogValue(v, depth+1)})
 		}
 
 		return slog.GroupValue(attrs...)
@@ -131,24 +142,28 @@ func slogValue(v any) slog.Value {
 // The result is optimized for large values such as full request documents.
 // All information is preserved.
 func logMessage(v any) string {
-	return logMessageIndent(v, "")
+	return logMessageIndent(v, "", 1)
 }
 
-// logMessageIndent is a variant of [logMessage] with an indentation for recursive calls.
-func logMessageIndent(v any, indent string) string {
+// logMessageIndent is a variant of [logMessage] with an indentation and depth for recursive calls.
+func logMessageIndent(v any, indent string, depth int) string {
 	switch v := v.(type) {
 	case *Document:
 		l := len(v.fields)
 		if l == 0 {
 			return "{}"
 		}
 
-		if flowLimit > 0 {
+		if depth > logMaxDepth {
+			return "{...}"
+		}
+
+		if logMaxFlowLength > 0 {
 			res := "{"
 
 			for i, f := range v.fields {
 				res += strconv.Quote(f.name) + `: `
-				res += logMessageIndent(f.value, "")
+				res += logMessageIndent(f.value, "", depth+1)
 
 				if i != l-1 {
 					res += ", "
@@ -157,7 +172,7 @@ func logMessageIndent(v any, indent string) string {
 
 			res += `}`
 
-			if len(res) < flowLimit {
+			if len(res) < logMaxFlowLength {
 				return res
 			}
 		}
@@ -167,7 +182,7 @@ func logMessageIndent(v any, indent string) string {
 		for _, f := range v.fields {
 			res += indent + "  "
 			res += strconv.Quote(f.name) + `: `
-			res += logMessageIndent(f.value, indent+"  ") + ",\n"
+			res += logMessageIndent(f.value, indent+"  ", depth+1) + ",\n"
 		}
 
 		res += indent + `}`
@@ -183,11 +198,15 @@ func logMessageIndent(v any, indent string) string {
 			return "[]"
 		}
 
-		if flowLimit > 0 {
+		if depth > logMaxDepth {
+			return "[...]"
+		}
+
+		if logMaxFlowLength > 0 {
 			res := "["
 
 			for i, e := range v.elements {
-				res += logMessageIndent(e, "")
+				res += logMessageIndent(e, "", depth+1)
 
 				if i != l-1 {
 					res += ", "
@@ -196,7 +215,7 @@ func logMessageIndent(v any, indent string) string {
 
 			res += `]`
 
-			if len(res) < flowLimit {
+			if len(res) < logMaxFlowLength {
 				return res
 			}
 		}
@@ -205,7 +224,7 @@ func logMessageIndent(v any, indent string) string {
 
 		for _, e := range v.elements {
 			res += indent + "  "
-			res += logMessageIndent(e, indent+"  ") + ",\n"
+			res += logMessageIndent(e, indent+"  ", depth+1) + ",\n"
 		}
 
 		res += indent + `]`