GODRIVER-2572 Add log messages to Server selection spec #1325

prestonvasquez · 2023-07-18T23:46:08Z

Summary

Define structured log messages for server selection.

Add an explicit test to ensure that no extra server selection events are observed for session support in accordance with DRIVERS-2530.

This PR implements changes required as part of GODRIVER-2466 , specifically recording type-specific data for the expectedSdamEvent, referenced here.

Background & Motivation

prestonvasquez · 2023-07-26T19:11:18Z

mongo/integration/unified/client_entity.go

@@ -528,38 +549,40 @@ func setClientOptionsFromURIOptions(clientOpts *options.ClientOptions, uriOpts b
 	var wcSet bool

 	for key, value := range uriOpts {
-		switch key {
+		switch strings.ToLower(key) {


Suggest using case insensitive matching. The motivation for this is that the "failCommand" specifications indicate that the application name field in spec tests should be "appName". However, there doesn't seem to be consistency in the unified spec tests, often "appname" is used, especially in logging. This update will ensure more consistent behavior.

internal/logger/component.go

mongo/integration/unified/event.go

x/mongo/driver/operation.go

mongo/description/server_selector.go

matthewdale · 2023-08-08T06:14:26Z

mongo/description/server_selector.go

+
+// String returns the JSON string representation of the serverSelectorInfo.
+func (sss serverSelectorInfo) String() string {
+	bytes, _ := json.Marshal(sss)


I'm concerned that the nested JSON created here will be difficult to use when output by a structured logger. Is there another format we can use to combine multiple points of info that works better when nested in JSON? Or maybe only produce JSON when the output is unstructured?

Could you elaborate on what you mean by this: "difficult to use when output by a structured logger" ? The output is the type of selector, associated data, and the child selectors (which is only relevant in the composite case). Here is an example:

{ "Type": "compositeSelector", "Selectors": [ { "Type": "writeSelector" }, { "Type": "latencySelector" } ] }

We could omit child selectors. I would argue that, in the context of logging, more information is better.

My concern is actually that the server selector information is a string containing escaped JSON, rather than a JSON object. Consider the example:

{ "message": "Server selection started", "operation": "find", "operationId": 1, "selector": "{\"Type\":\"compositeSelector\",\"Selectors\":[{\"Type\":\"readPrefSelector\",\"Data\":\"primary\"},{\"Type\":\"latencySelector\"}]}", "timestamp": 1692071928112600000, "topologyDescription": "Type: Unknown, Servers: [{ Addr: localhost:27017, Type: Unknown, State: Connected, Average RTT: 0s, Min RTT: 0s }, { Addr: localhost:27018, Type: Unknown, State: Connected, Average RTT: 0s, Min RTT: 0s }, { Addr: localhost:27019, Type: Unknown, State: Connected, Average RTT: 0s, Min RTT: 0s }, ]" }

That selector information would be more usable and readable as a JSON object.

The specifications require this field to be a string. This representation seems reasonable to me. However, if you want to unescape the string we can build this data directly, similar to what we do with the Server.

Since the spec requires it to be a string, the escaped JSON seems like a reasonable solution.

matthewdale · 2023-08-08T21:55:32Z

x/mongo/driver/operation.go

+		if startedInfo.cmdName != op.Name {
+			op.Name = startedInfo.cmdName
+		}


Is there a way we can prevent this inconsistency from ever happening? Does the command name ever depend on server info, or is it constant?

AFAICT command name is constant and is sourced from the command document when creating a wire message. Technically, these two values should never differ. However, one is sourced from the command function and the other from a field on the operation struct. Since their source differs, it is seems best to make this check.

Sounds good.

mongo/collection.go

mongo/description/server_selector.go

matthewdale · 2023-08-14T18:58:47Z

mongo/integration/unified/client_entity.go

+	observedEvents                      map[monitoringEventType]struct{}
+	storedEvents                        map[monitoringEventType][]string
+	eventsCount                         map[monitoringEventType]int32
+	serverDescriptionChangedEventsCount map[serverDescriptionChangedEvent]int32

-	eventsCountLock sync.RWMutex
+	eventsCountLock                         sync.RWMutex
+	serverDescriptionChangedEventsCountLock sync.RWMutex


Can we use sync.Map for any of these to simplify the locking logic?

There also seems to be significant overlap in the recorded data. Is it possible to store all of the observed events and then calculate the required counts and other stats on-demand?

The documentation for sync.Map states that it's intended use includes the following:

when the entry for a given key is only ever written once but read many times, as in caches that only grow.

This is not the case for any of these observation sets, as like-keys are written to as many times as an event being measured might occur.

mongo/integration/unified/event.go

x/mongo/driver/topology/topology.go

github-actions · 2023-08-14T21:37:36Z

API Change Report

./x/mongo/driver

compatible changes

Operation.Name: added

x/mongo/driver/topology/topology.go

matthewdale · 2023-08-15T05:25:56Z

mongo/description/server_selector.go

+
+// String returns the JSON string representation of the serverSelectorInfo.
+func (sss serverSelectorInfo) String() string {
+	bytes, _ := json.Marshal(sss)


My concern is actually that the server selector information is a string containing escaped JSON, rather than a JSON object. Consider the example:

{ "message": "Server selection started", "operation": "find", "operationId": 1, "selector": "{\"Type\":\"compositeSelector\",\"Selectors\":[{\"Type\":\"readPrefSelector\",\"Data\":\"primary\"},{\"Type\":\"latencySelector\"}]}", "timestamp": 1692071928112600000, "topologyDescription": "Type: Unknown, Servers: [{ Addr: localhost:27017, Type: Unknown, State: Connected, Average RTT: 0s, Min RTT: 0s }, { Addr: localhost:27018, Type: Unknown, State: Connected, Average RTT: 0s, Min RTT: 0s }, { Addr: localhost:27019, Type: Unknown, State: Connected, Average RTT: 0s, Min RTT: 0s }, ]" }

That selector information would be more usable and readable as a JSON object.

matthewdale

Looks good 👍

matthewdale · 2023-08-17T15:09:27Z

mongo/description/server_selector.go

+
+// String returns the JSON string representation of the serverSelectorInfo.
+func (sss serverSelectorInfo) String() string {
+	bytes, _ := json.Marshal(sss)


Since the spec requires it to be a string, the escaped JSON seems like a reasonable solution.

matthewdale · 2023-08-17T15:12:17Z

x/mongo/driver/operation.go

+		if startedInfo.cmdName != op.Name {
+			op.Name = startedInfo.cmdName
+		}


Sounds good.

prestonvasquez added 30 commits June 2, 2023 17:20

update windows distro to vsCurrent-latest

7b46fe0

Merge branch 'master' of github.com:mongodb/mongo-go-driver

7bde5ae

GODRIVER-2742 set implementation

f7abd3c

GODRIVER-2743 Add CompareUint32Ptr function

92cb1bf

GODRIVER-2585 Initialize SDAM logging

4c95947

GODRIVER-2585 initialize heartbeat logging

faca1cc

GODRIVER-2585 merge master

d7005b5

GODRIVER-2585 Add remaining SDAM logging USTs

5f4f342

GODRIVER-2585 Seperate server and topology component structs

9a9122d

GODRIER-2585 Revert changes to the internal logger

a0dfef3

GODRIVER-2585 Extend reduced HB frequency logic to operational clients

c0c767f

GODRIVER-2585 Clean up comments

85dbb56

Merge branch 'master' into GODRIVER-2585

2f73b7c

GODRIVER-2585 Remove empty space from comment

1c05011

GODRIVER-2585 Fix static analysis failures

4d75016

GODRIVER-2585 add missing licenses

d8eaf6c

Merge branch 'master' into GODRIVER-2742

27d61c0

GODRIVER-2742 Add mongodcryptd process runner

a7d6685

GODRIVER-2742 Use internal compare function in server desc equal

66bec31

GODRIVER-2742 fix failures with session timout selection

4299250

GODRIVER-2742 Fix topology test failures

af250a1

GODRIVER-2742 More test failure fixes

5848ad5

GODRIVER-2742 Convert mongocryptd prose test to mtest

a333d3e

GODRIVER-2742 Use mtest and fix typos

0696575

GODRIVER-2742 update mtest usage

dcb8380

GODRIVER-2585 Add component tests

bdd4e8c

GODRIVER-2585 Add missing licenses

8d4cd4c

GODRIVER-2585 Add comment to Print ack the message duplication

02b7657

Merge branch 'GODRIVER-2742' into GODRIVER-2572

8d91a00

GODRIVER-2572 Add UST

e291f7c

GODRIVER-2572 Remove uint32 comparison logic

ebf07b4

prestonvasquez commented Jul 26, 2023

View reviewed changes

GODRIVER-2572 Clean up comments

0fd270a

prestonvasquez marked this pull request as ready for review July 26, 2023 19:56

prestonvasquez requested a review from a team as a code owner July 26, 2023 19:56

prestonvasquez requested review from matthewdale, qingyang-hu and blink1073 and removed request for a team July 26, 2023 19:56

GODRIVER-2572 Resolve merge conflicts

eaad735

qingyang-hu approved these changes Aug 3, 2023

View reviewed changes

blink1073 approved these changes Aug 4, 2023

View reviewed changes

GODRIVER-2572 Fix static analysis errors

2a1771b

matthewdale reviewed Aug 8, 2023

View reviewed changes

prestonvasquez added 4 commits August 8, 2023 14:00

GODRIVER-2572 PR requests

a474c8c

GODRIVER-2572 Resolve misaligned server selectors

2bc53da

GODRIVER-2572 Fix static analysis errors

adf86c7

GODRIVER-2572 Add licenses

cb497c0

prestonvasquez requested a review from matthewdale August 9, 2023 18:38

matthewdale reviewed Aug 14, 2023

View reviewed changes

GODRIVER-2572 Clean up code per review

3da9902

prestonvasquez requested a review from matthewdale August 14, 2023 20:58

GODRIVER-2572 Resolve merge conflict

79894b8

matthewdale reviewed Aug 15, 2023

View reviewed changes

GODRIVER-2572 Update topology options to default load empty log options

906d534

prestonvasquez requested a review from matthewdale August 15, 2023 17:24

GODRIVER-2572 Add correct options to log constructor

ffbfe15

matthewdale approved these changes Aug 17, 2023

View reviewed changes

prestonvasquez merged commit 4bd1c27 into mongodb:master Aug 17, 2023
16 of 21 checks passed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

GODRIVER-2572 Add log messages to Server selection spec #1325

GODRIVER-2572 Add log messages to Server selection spec #1325

prestonvasquez commented Jul 18, 2023 •

edited

Loading

prestonvasquez Jul 26, 2023 •

edited

Loading

matthewdale Aug 8, 2023

prestonvasquez Aug 8, 2023 •

edited

Loading

matthewdale Aug 15, 2023

prestonvasquez Aug 15, 2023

matthewdale Aug 17, 2023

matthewdale Aug 8, 2023

prestonvasquez Aug 14, 2023

matthewdale Aug 17, 2023

matthewdale Aug 14, 2023

prestonvasquez Aug 14, 2023 •

edited

Loading

github-actions bot commented Aug 14, 2023 •

edited

Loading

matthewdale Aug 15, 2023

matthewdale left a comment

matthewdale Aug 17, 2023

matthewdale Aug 17, 2023

GODRIVER-2572 Add log messages to Server selection spec #1325

GODRIVER-2572 Add log messages to Server selection spec #1325

Conversation

prestonvasquez commented Jul 18, 2023 • edited Loading

Summary

Background & Motivation

prestonvasquez Jul 26, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

prestonvasquez Aug 8, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

prestonvasquez Aug 14, 2023 • edited Loading

Choose a reason for hiding this comment

github-actions bot commented Aug 14, 2023 • edited Loading

API Change Report

./x/mongo/driver

compatible changes

Choose a reason for hiding this comment

matthewdale left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

prestonvasquez commented Jul 18, 2023 •

edited

Loading

prestonvasquez Jul 26, 2023 •

edited

Loading

prestonvasquez Aug 8, 2023 •

edited

Loading

prestonvasquez Aug 14, 2023 •

edited

Loading

github-actions bot commented Aug 14, 2023 •

edited

Loading