diff --git a/internal/bson2/array.go b/internal/bson2/array.go index 156c812fbfa8..cb582089cb06 100644 --- a/internal/bson2/array.go +++ b/internal/bson2/array.go @@ -148,7 +148,12 @@ func (arr *Array) LogValue() slog.Value { // somewhat similar (but not identical) to JSON or Go syntax. // It may change over time. func (arr *Array) LogMessage() string { - return logMessage(arr) + return logMessage(arr, logMaxFlowLength, "", 1) +} + +// LogMessageBlock is a variant of [Array.LogMessage] that never uses a flow style. +func (arr *Array) LogMessageBlock() string { + return logMessage(arr, 0, "", 1) } // check interfaces diff --git a/internal/bson2/document.go b/internal/bson2/document.go index 84e962f06bac..6f33d318c7e1 100644 --- a/internal/bson2/document.go +++ b/internal/bson2/document.go @@ -182,7 +182,12 @@ func (doc *Document) LogValue() slog.Value { // somewhat similar (but not identical) to JSON or Go syntax. // It may change over time. func (doc *Document) LogMessage() string { - return logMessage(doc) + return logMessage(doc, logMaxFlowLength, "", 1) +} + +// LogMessageBlock is a variant of [Document.LogMessage] that never uses a flow style. +func (doc *Document) LogMessageBlock() string { + return logMessage(doc, 0, "", 1) } // check interfaces diff --git a/internal/bson2/logging.go b/internal/bson2/logging.go index 61022698e117..1d8380ba6554 100644 --- a/internal/bson2/logging.go +++ b/internal/bson2/logging.go @@ -25,13 +25,13 @@ import ( "time" ) -// 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 logMaxFlowLength = 80 - // logMaxDepth is the maximum depth of a recursive representation of a BSON value. const logMaxDepth = 20 +// logMaxFlowLength is the maximum length of a flow/inline/compact representation of a BSON value. +// It may be set to 0 to always disable flow representation. +const logMaxFlowLength = 80 + // nanBits is the most common pattern of a NaN float64 value, the same as math.Float64bits(math.NaN()). const nanBits = 0b111111111111000000000000000000000000000000000000000000000000001 @@ -141,12 +141,7 @@ func slogValue(v any, depth int) 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, "", 1) -} - -// logMessageIndent is a variant of [logMessage] with an indentation and depth for recursive calls. -func logMessageIndent(v any, indent string, depth int) string { +func logMessage(v any, maxFlowLength int, indent string, depth int) string { switch v := v.(type) { case *Document: l := len(v.fields) @@ -158,12 +153,12 @@ func logMessageIndent(v any, indent string, depth int) string { return "{...}" } - if logMaxFlowLength > 0 { + if maxFlowLength > 0 { res := "{" for i, f := range v.fields { res += strconv.Quote(f.name) + `: ` - res += logMessageIndent(f.value, "", depth+1) + res += logMessage(f.value, maxFlowLength, "", depth+1) if i != l-1 { res += ", " @@ -172,7 +167,7 @@ func logMessageIndent(v any, indent string, depth int) string { res += `}` - if len(res) < logMaxFlowLength { + if len(res) < maxFlowLength { return res } } @@ -182,7 +177,7 @@ func logMessageIndent(v any, indent string, depth int) string { for _, f := range v.fields { res += indent + " " res += strconv.Quote(f.name) + `: ` - res += logMessageIndent(f.value, indent+" ", depth+1) + ",\n" + res += logMessage(f.value, maxFlowLength, indent+" ", depth+1) + ",\n" } res += indent + `}` @@ -202,11 +197,11 @@ func logMessageIndent(v any, indent string, depth int) string { return "[...]" } - if logMaxFlowLength > 0 { + if maxFlowLength > 0 { res := "[" for i, e := range v.elements { - res += logMessageIndent(e, "", depth+1) + res += logMessage(e, maxFlowLength, "", depth+1) if i != l-1 { res += ", " @@ -215,7 +210,7 @@ func logMessageIndent(v any, indent string, depth int) string { res += `]` - if len(res) < logMaxFlowLength { + if len(res) < maxFlowLength { return res } } @@ -224,7 +219,7 @@ func logMessageIndent(v any, indent string, depth int) string { for _, e := range v.elements { res += indent + " " - res += logMessageIndent(e, indent+" ", depth+1) + ",\n" + res += logMessage(e, maxFlowLength, indent+" ", depth+1) + ",\n" } res += indent + `]` diff --git a/internal/bson2/logging_test.go b/internal/bson2/logging_test.go index 338cdad5c32b..7cdb339bdf79 100644 --- a/internal/bson2/logging_test.go +++ b/internal/bson2/logging_test.go @@ -51,14 +51,15 @@ func TestLogging(t *testing.T) { for _, tc := range []struct { name string - v slog.LogValuer + doc *Document t string j string m string + b string }{ { name: "Numbers", - v: must.NotFail(NewDocument( + doc: must.NotFail(NewDocument( "f64", 42.0, "inf", float64(math.Inf(1)), "neg_inf", float64(math.Inf(-1)), @@ -81,10 +82,21 @@ func TestLogging(t *testing.T) { "i32": 42, "i64": int64(42), }`, + b: ` + { + "f64": 42.0, + "inf": +Inf, + "neg_inf": -Inf, + "zero": 0.0, + "neg_zero": -0.0, + "nan": NaN, + "i32": 42, + "i64": int64(42), + }`, }, { name: "Scalars", - v: must.NotFail(NewDocument( + doc: must.NotFail(NewDocument( "null", Null, "id", ObjectID{0x42}, "bool", true, @@ -99,10 +111,17 @@ func TestLogging(t *testing.T) { "bool": true, "time": 2023-03-06T09:14:42.123Z, }`, + b: ` + { + "null": null, + "id": ObjectID(420000000000000000000000), + "bool": true, + "time": 2023-03-06T09:14:42.123Z, + }`, }, { name: "Composites", - v: must.NotFail(NewDocument( + doc: must.NotFail(NewDocument( "doc", must.NotFail(NewDocument( "foo", "bar", "baz", must.NotFail(NewDocument( @@ -128,10 +147,29 @@ func TestLogging(t *testing.T) { "doc_empty": {}, "array": ["foo", "bar", ["baz", "qux"]], }`, + b: ` + { + "doc": { + "foo": "bar", + "baz": { + "qux": "quux", + }, + }, + "doc_raw": RawDocument<1>, + "doc_empty": {}, + "array": [ + "foo", + "bar", + [ + "baz", + "qux", + ], + ], + }`, }, { name: "Nested", - v: makeNested(false, 20).(*Document), + doc: makeNested(false, 20).(*Document), t: `v.f.0.f.0.f.0.f.0.f.0.f.0.f.0.f.0.f.0.f.0=`, j: `{"v":{"f":{"0":{"f":{"0":{"f":{"0":{"f":{"0":{"f":{"0":{"f":{"0":` + `{"f":{"0":{"f":{"0":{"f":{"0":{"f":{"0":null}}}}}}}}}}}}}}}}}}}}}`, @@ -143,18 +181,64 @@ func TestLogging(t *testing.T) { }, ], }`, + b: ` + { + "f": [ + { + "f": [ + { + "f": [ + { + "f": [ + { + "f": [ + { + "f": [ + { + "f": [ + { + "f": [ + { + "f": [ + { + "f": [ + null, + ], + }, + ], + }, + ], + }, + ], + }, + ], + }, + ], + }, + ], + }, + ], + }, + ], + }, + ], + }`, }, } { t.Run(tc.name, func(t *testing.T) { - tlog.InfoContext(ctx, "", slog.Any("v", tc.v)) + tlog.InfoContext(ctx, "", slog.Any("v", tc.doc)) assert.Equal(t, tc.t+"\n", tbuf.String()) tbuf.Reset() - jlog.InfoContext(ctx, "", slog.Any("v", tc.v)) + jlog.InfoContext(ctx, "", slog.Any("v", tc.doc)) assert.Equal(t, tc.j+"\n", jbuf.String()) jbuf.Reset() - assert.Equal(t, testutil.Unindent(t, tc.m), logMessage(tc.v)) + m := tc.doc.LogMessage() + assert.Equal(t, testutil.Unindent(t, tc.m), m, "actual:\n%s", m) + + b := tc.doc.LogMessageBlock() + assert.Equal(t, testutil.Unindent(t, tc.b), b, "actual:\n%s", b) }) } } diff --git a/internal/bson2/raw_array.go b/internal/bson2/raw_array.go index 569527b97825..f66468a1df39 100644 --- a/internal/bson2/raw_array.go +++ b/internal/bson2/raw_array.go @@ -91,14 +91,19 @@ func (raw RawArray) decode(mode decodeMode) (*Array, error) { } // LogValue implements slog.LogValuer interface. -func (doc RawArray) LogValue() slog.Value { - return slogValue(doc, 1) +func (raw RawArray) LogValue() slog.Value { + return slogValue(raw, 1) } // LogMessage returns a representation as a string. // It may change over time. -func (doc RawArray) LogMessage() string { - return logMessage(doc) +func (raw RawArray) LogMessage() string { + return logMessage(raw, logMaxFlowLength, "", 1) +} + +// LogMessageBlock is a variant of [RawArray.LogMessage] that never uses a flow style. +func (raw RawArray) LogMessageBlock() string { + return logMessage(raw, 0, "", 1) } // check interfaces diff --git a/internal/bson2/raw_document.go b/internal/bson2/raw_document.go index 37d479e8bb01..60cba1f0db16 100644 --- a/internal/bson2/raw_document.go +++ b/internal/bson2/raw_document.go @@ -162,14 +162,19 @@ func (raw RawDocument) decode(mode decodeMode) (*Document, error) { } // LogValue implements slog.LogValuer interface. -func (doc RawDocument) LogValue() slog.Value { - return slogValue(doc, 1) +func (raw RawDocument) LogValue() slog.Value { + return slogValue(raw, 1) } // LogMessage returns a representation as a string. // It may change over time. -func (doc RawDocument) LogMessage() string { - return logMessage(doc) +func (raw RawDocument) LogMessage() string { + return logMessage(raw, logMaxFlowLength, "", 1) +} + +// LogMessageBlock is a variant of [RawDocument.LogMessage] that never uses a flow style. +func (raw RawDocument) LogMessageBlock() string { + return logMessage(raw, 0, "", 1) } // check interfaces diff --git a/internal/clientconn/conn.go b/internal/clientconn/conn.go index 7385debfdf46..98cd6333671d 100644 --- a/internal/clientconn/conn.go +++ b/internal/clientconn/conn.go @@ -344,11 +344,11 @@ func (c *conn) run(ctx context.Context) (err error) { var resBodyString, proxyBodyString string if resBody != nil { - resBodyString = resBody.String() + resBodyString = resBody.StringBlock() } if proxyBody != nil { - proxyBodyString = proxyBody.String() + proxyBodyString = proxyBody.StringBlock() } var diffBody string diff --git a/internal/wire/msg_body.go b/internal/wire/msg_body.go index 56cf637a3a83..80693fc986df 100644 --- a/internal/wire/msg_body.go +++ b/internal/wire/msg_body.go @@ -40,6 +40,9 @@ type MsgBody interface { encoding.BinaryMarshaler fmt.Stringer + + // StringBlock returns an indented string representation for logging. + StringBlock() string } // ErrZeroRead is returned when zero bytes was read from connection, diff --git a/internal/wire/op_msg.go b/internal/wire/op_msg.go index 4bf7b1da2562..a479a772d767 100644 --- a/internal/wire/op_msg.go +++ b/internal/wire/op_msg.go @@ -421,8 +421,8 @@ func (msg *OpMsg) MarshalBinary() ([]byte, error) { return b, nil } -// String returns a string representation for logging. -func (msg *OpMsg) String() string { +// logMessage returns a string representation for logging. +func (msg *OpMsg) logMessage(block bool) string { if msg == nil { return "" } @@ -471,9 +471,23 @@ func (msg *OpMsg) String() string { must.NoError(m.Add("Sections", sections)) + if block { + return m.LogMessageBlock() + } + return m.LogMessage() } +// String returns a string representation for logging. +func (msg *OpMsg) String() string { + return msg.logMessage(false) +} + +// StringBlock returns an indented string representation for logging. +func (msg *OpMsg) StringBlock() string { + return msg.logMessage(true) +} + // check interfaces var ( _ MsgBody = (*OpMsg)(nil) diff --git a/internal/wire/op_query.go b/internal/wire/op_query.go index 07a28d63a9af..4fe69b7f21bc 100644 --- a/internal/wire/op_query.go +++ b/internal/wire/op_query.go @@ -151,8 +151,8 @@ func (query *OpQuery) ReturnFieldsSelector() *types.Document { return must.NotFail(query.returnFieldsSelector.Convert()) } -// String returns a string representation for logging. -func (query *OpQuery) String() string { +// logMessage returns a string representation for logging. +func (query *OpQuery) logMessage(block bool) string { if query == nil { return "" } @@ -180,9 +180,23 @@ func (query *OpQuery) String() string { } } + if block { + return m.LogMessageBlock() + } + return m.LogMessage() } +// String returns a string representation for logging. +func (query *OpQuery) String() string { + return query.logMessage(false) +} + +// StringBlock returns an indented string representation for logging. +func (query *OpQuery) StringBlock() string { + return query.logMessage(true) +} + // check interfaces var ( _ MsgBody = (*OpQuery)(nil) diff --git a/internal/wire/op_reply.go b/internal/wire/op_reply.go index 62864e07faac..8538f940dd58 100644 --- a/internal/wire/op_reply.go +++ b/internal/wire/op_reply.go @@ -122,8 +122,8 @@ func (reply *OpReply) SetDocument(doc *types.Document) { reply.document = must.NotFail(d.Encode()) } -// String returns a string representation for logging. -func (reply *OpReply) String() string { +// logMessage returns a string representation for logging. +func (reply *OpReply) logMessage(block bool) string { if reply == nil { return "" } @@ -147,9 +147,23 @@ func (reply *OpReply) String() string { } } + if block { + return m.LogMessageBlock() + } + return m.LogMessage() } +// String returns a string representation for logging. +func (reply *OpReply) String() string { + return reply.logMessage(false) +} + +// StringBlock returns an indented string representation for logging. +func (reply *OpReply) StringBlock() string { + return reply.logMessage(true) +} + // check interfaces var ( _ MsgBody = (*OpReply)(nil) diff --git a/internal/wire/wire_test.go b/internal/wire/wire_test.go index d28e31d374ef..6a32d0779194 100644 --- a/internal/wire/wire_test.go +++ b/internal/wire/wire_test.go @@ -120,6 +120,7 @@ func testMessages(t *testing.T, testCases []testCase) { require.NotNil(t, msgBody) assert.NotPanics(t, func() { _ = msgHeader.String() }) assert.Equal(t, testutil.Unindent(t, tc.m), msgBody.String()) + assert.NotPanics(t, func() { _ = msgBody.StringBlock() }) require.NoError(t, msgBody.check()) @@ -208,6 +209,7 @@ func fuzzMessages(f *testing.F, testCases []testCase) { if msgBody.check() != nil { assert.NotPanics(t, func() { _ = msgHeader.String() }) assert.NotPanics(t, func() { _ = msgBody.String() }) + assert.NotPanics(t, func() { _ = msgBody.StringBlock() }) if msg, ok := msgBody.(*OpMsg); ok { assert.NotPanics(t, func() { diff --git a/website/docs/configuration/operation-modes.md b/website/docs/configuration/operation-modes.md index 7d3e5c587044..493d8cbf8f55 100644 --- a/website/docs/configuration/operation-modes.md +++ b/website/docs/configuration/operation-modes.md @@ -35,15 +35,16 @@ Header diff: --- res header +++ proxy header @@ -1 +1 @@ --length: 63, id: 14, response_to: 24, opcode: OP_MSG -+length: 64, id: 229, response_to: 24, opcode: OP_MSG +-length: 63, id: 4, response_to: 13, opcode: OP_MSG ++length: 191, id: 53, response_to: 13, opcode: OP_MSG Body diff: --- res body +++ proxy body -@@ -10,3 +10,3 @@ - ], -- "you": "127.0.0.1:57079", -+ "you": "172.19.0.1:59824", - "ok": { +@@ -7,4 +7,12 @@ + "Document": { +- "you": "127.0.0.1:64795", ++ "you": "192.168.65.1:21365", + "ok": 1.0, + }, ``` diff --git a/website/docs/migration/premigration-testing.md b/website/docs/migration/premigration-testing.md index fce33ba77e90..1cacce64e0a2 100644 --- a/website/docs/migration/premigration-testing.md +++ b/website/docs/migration/premigration-testing.md @@ -121,66 +121,37 @@ Continuing with the same example above, we can further examine the diff output w In the diff output below, however, we have discovered that the query cannot be serviced by our application because the `$first` accumulator operator is not implemented in FerretDB. ```diff -2023-08-29T13:25:09.048+0200 WARN // 127.0.0.1:33522 -> 127.0.0.1:27017 clientconn/conn.go:360 Header diff: +Header diff: --- res header +++ proxy header @@ -1 +1 @@ --length: 140, id: 2, response_to: 156, opcode: OP_MSG -+length: 181, id: 360, response_to: 156, opcode: OP_MSG +-length: 140, id: 8, response_to: 19, opcode: OP_MSG ++length: 306, id: 128, response_to: 19, opcode: OP_MSG Body diff: --- res body +++ proxy body -@@ -7,13 +7,41 @@ - "$k": [ -- "ok", -- "errmsg", -- "code", -- "codeName" -+ "cursor", -+ "ok" - ], +@@ -7,6 +7,25 @@ + "Document": { +- "ok": 0.0, +- "errmsg": "$group accumulator \"$first\" is not implemented yet", +- "code": 238, +- "codeName": "NotImplemented", + "cursor": { -+ "$k": [ -+ "firstBatch", -+ "id", -+ "ns" -+ ], + "firstBatch": [ + { -+ "$k": [ -+ "_id", -+ "firstPost" -+ ], -+ "_id": "Alice", -+ "firstPost": { -+ "$d": 1692527603134 -+ } ++ "_id": "Bob", ++ "firstPost": 2023-08-28T10:33:23.134Z, + }, + { -+ "$k": [ -+ "_id", -+ "firstPost" -+ ], -+ "_id": "Bob", -+ "firstPost": { -+ "$d": 1693218803134 -+ } -+ } ++ "_id": "Alice", ++ "firstPost": 2023-08-20T10:33:23.134Z, ++ }, + ], -+ "id": { -+ "$l": "0" -+ }, -+ "ns": "test.posts" ++ "id": int64(0), ++ "ns": "test.posts", + }, - "ok": { -- "$f": 0 -- }, -- "errmsg": "$group accumulator \"$first\" is not implemented yet", -- "code": 238, -- "codeName": "NotImplemented" -+ "$f": 1 -+ } ++ "ok": 1.0, }, ```