GODRIVER-2585 Add log messages to SDAM #1305
Conversation
| for _, ignoreMessage := range clm.IgnoreMessages { | ||
| if err := verifyLogMatch(ctx, ignoreMessage, msg); err == nil { | ||
| return true | ||
| } |
There was a problem hiding this comment.
This is a really unfortunate pattern, but I don't think there is a "set" solution that can be implemented here since the "logMessage" struct contains a slice of bytes. From the comparison spec:
Slice, map, and function types are not comparable.
Even though the time complexity is linear, the overall size of the IgnoreMessages should be very minimal.
| @@ -199,3 +211,62 @@ func SerializeConnection(conn Connection, extraKeysAndValues ...interface{}) []i | |||
|
|
|||
| return keysAndValues | |||
| } | |||
|
|
|||
| // Server contains data that all server messages MAY contain. | |||
| type Server struct { | |||
There was a problem hiding this comment.
Even though both "Server" and "Topology" fall under the "ComponentTopology" component, it feels more natural to separate them into two separate message structs since they will ultimately contain non-intersecting fields.
| expectedLogMessageCount int, | ||
| hasOperationalFailPoint bool, | ||
| ) context.Context { | ||
| ctx = context.WithValue(ctx, operationalFailPointKey, hasOperationalFailPoint) |
There was a problem hiding this comment.
Before this ticket we supported reducing heartbeatFrequencyMS at the file-level client, but not the operational-level client. Since the operation does not maintain access to the "TestCase" object, it feels natural to extend the test context to include whether or not the set of operations contains a fail point operation.
| t.Helper() | ||
|
|
||
| message, err := newLogMessage(level, msg, args...) | ||
| require.Nil(t, err, "failed to create test log message: %v", err) |
There was a problem hiding this comment.
Use require.NoError instead.
| require.Nil(t, err, "failed to create test log message: %v", err) | |
| require.NoError(t, err, "failed to create test log message") |
| func TestClientLogMessages(t *testing.T) { | ||
| t.Parallel() | ||
|
|
||
| t.Run("ignore", func(t *testing.T) { |
There was a problem hiding this comment.
Optional: The existing pattern of using one test function for testing a type with a bunch of subtests per function causes some problems:
- Makes running more granular tests more difficult because popular IDE integrations don't allow running individual subtests.
- Makes debugging more granular tests more difficult because popular IDE integrations don't allow debugging individual subtests.
- Increases the probability of unexpected interaction between subtests because they share a scope.
Consider naming this test function something like TestClientLogMessagesIgnore and removing the "ignore" subtest.
| assert.Equal(t, test.want, got, | ||
| "clientLogMessages.ignore() = %v, want: %v", got, test.want) |
There was a problem hiding this comment.
Optional: Printing the values in the message is redundant because assert.Equal will already print them on an assertion failure. Consider removing the redundant values.
| assert.Equal(t, test.want, got, | |
| "clientLogMessages.ignore() = %v, want: %v", got, test.want) | |
| assert.Equal(t, test.want, got, "unexpected clientLogMessages.ignore() result") |
internal/logger/component.go
Outdated
| keysAndValues.Add(KeyServerConnectionID, connID) | ||
| } | ||
|
|
||
| port, err := strconv.ParseInt(srv.ServerPort, 0, 32) |
There was a problem hiding this comment.
Automatically determining the number base (i.e. base 0) may lead to unexpected results when parsing some port numberes (see examples here). It's safer to explicitly specify the expected base.
| port, err := strconv.ParseInt(srv.ServerPort, 0, 32) | |
| port, err := strconv.ParseInt(srv.ServerPort, 10, 32) |
Alternatively, consider using the simpler strconv.Atoi unless you need to specify the base or bit size.
There was a problem hiding this comment.
This makes sense, note that the specifications defined the port to be an integer (e.g. CMAP). The two cases you note that would cause unexpected behavior ("0123", "0999") would result in invalid ports regardless of the base
| type Server struct { | ||
| DriverConnectionID uint64 // Driver's ID for the connection | ||
| TopologyID primitive.ObjectID // Driver's unique ID for this topology | ||
| Message string // Message associated with the topology |
There was a problem hiding this comment.
Including the message here and passing it via the msg field in the LogSink.Info function seems like it will repeat the message twice in logs. Is that intended?
There was a problem hiding this comment.
Yes it will. go-logr/logr's LogSink.Info() method requires a message string:
The log message consists of a constant message attached to the log line. This should generally be a simple description of what's occurring, and should never be a format string. Variable information can then be attached using named values.
And the DBX logging specifications include the messages in the structured data, e.g. here.
The duplication is unfortunate, but I'm not sure there is an obvious way around it. A logrus example:
DEBU[0000] Command started command="{\"insert\": \"test\",\"ordere..." commandName=insert databaseName=test driverConnectionId=1 message="Command started" operationId=0 requestId=11 serverConnectionId=2014 serverHost=localhost serverPort=27018
There was a problem hiding this comment.
I've added a comment to the "Print" method acknowledging this.
There was a problem hiding this comment.
I think we have some latitude to interpret the logging specification as requiring passing the message, but not necessarily requiring it to be passed in the key/value pairs. As long as the "default" structured logger output contains the expected structure and a user can implement the expected logger (e.g. by using a structured logger that puts the log message in the "message" field), that should satisfy the specification requirements.
TLDR: The duplication is fine, but I'd argue it's unnecessary even given the spec requirements.
GODRIVER-2585
Summary
Define log messages for SDAM events.
Background & Motivation
The SDAM logging and monitoring specification defines a set of behaviors in the driver for providing runtime information about server discovery and monitoring (SDAM) in log messages, as well as in events that users can consume programmatically, either directly or by integrating with third-party APM libraries.