From 2f0917c55633265e3b64d6beaf26c942938b9926 Mon Sep 17 00:00:00 2001 From: Preston Vasquez Date: Thu, 7 Dec 2023 16:34:16 -0700 Subject: [PATCH] GODRIVER-2943 Re-organize client entity expected log messages (#1366) --- mongo/integration/unified/client_entity.go | 5 +- mongo/integration/unified/context.go | 34 ++++++-- mongo/integration/unified/logger.go | 28 ++++--- .../unified/logger_verification.go | 20 +---- .../unified/logger_verification_test.go | 84 ------------------- .../unified/unified_spec_runner.go | 10 +-- .../unified/logging-replicaset.json | 16 ---- .../unified/logging-replicaset.yml | 7 ++ .../unified/logging-sharded.json | 16 ---- .../unified/logging-sharded.yml | 7 ++ .../unified/logging-standalone.json | 16 ---- .../unified/logging-standalone.yml | 7 ++ x/mongo/driver/topology/server.go | 19 ++++- 13 files changed, 90 insertions(+), 179 deletions(-) delete mode 100644 mongo/integration/unified/logger_verification_test.go diff --git a/mongo/integration/unified/client_entity.go b/mongo/integration/unified/client_entity.go index b31671ade1..aefe5079f1 100644 --- a/mongo/integration/unified/client_entity.go +++ b/mongo/integration/unified/client_entity.go @@ -107,7 +107,10 @@ func newClientEntity(ctx context.Context, em *EntityMap, entityOptions *entityOp } if olm := entityOptions.ObserveLogMessages; olm != nil { - clientLogger := newLogger(olm, expectedLogMessageCount(ctx)) + expectedLogMessagesCount := expectedLogMessagesCount(ctx, entityOptions.ID) + ignoreLogMessages := ignoreLogMessages(ctx, entityOptions.ID) + + clientLogger := newLogger(olm, expectedLogMessagesCount, ignoreLogMessages) wrap := func(str string) options.LogLevel { return options.LogLevel(logger.ParseLevel(str)) diff --git a/mongo/integration/unified/context.go b/mongo/integration/unified/context.go index d97abaf023..10cfd00652 100644 --- a/mongo/integration/unified/context.go +++ b/mongo/integration/unified/context.go @@ -28,8 +28,8 @@ const ( failPointsKey ctxKey = "test-failpoints" // targetedFailPointsKey is used to store a map from a fail point name to the host on which the fail point is set. targetedFailPointsKey ctxKey = "test-targeted-failpoints" - // expectedLogMessageCountKey is used to store the number of log messages expected to be received by the test runner. - expectedLogMessageCountKey ctxKey = "test-expected-log-message-count" + clientLogMessagesKey ctxKey = "test-expected-log-message-count" + ignoreLogMessagesKey ctxKey = "test-ignore-log-message-count" ) // newTestContext creates a new Context derived from ctx with values initialized to store the state required for test @@ -37,14 +37,14 @@ const ( func newTestContext( ctx context.Context, entityMap *EntityMap, - expectedLogMessageCount int, + clientLogMessages []*clientLogMessages, hasOperationalFailPoint bool, ) context.Context { ctx = context.WithValue(ctx, operationalFailPointKey, hasOperationalFailPoint) ctx = context.WithValue(ctx, entitiesKey, entityMap) ctx = context.WithValue(ctx, failPointsKey, make(map[string]*mongo.Client)) ctx = context.WithValue(ctx, targetedFailPointsKey, make(map[string]string)) - ctx = context.WithValue(ctx, expectedLogMessageCountKey, expectedLogMessageCount) + ctx = context.WithValue(ctx, clientLogMessagesKey, clientLogMessages) return ctx } @@ -84,6 +84,28 @@ func entities(ctx context.Context) *EntityMap { return ctx.Value(entitiesKey).(*EntityMap) } -func expectedLogMessageCount(ctx context.Context) int { - return ctx.Value(expectedLogMessageCountKey).(int) +func expectedLogMessagesCount(ctx context.Context, clientID string) int { + messages := ctx.Value(clientLogMessagesKey).([]*clientLogMessages) + + count := 0 + for _, message := range messages { + if message.Client == clientID { + count += len(message.LogMessages) + } + } + + return count +} + +func ignoreLogMessages(ctx context.Context, clientID string) []*logMessage { + messages := ctx.Value(clientLogMessagesKey).([]*clientLogMessages) + + ignoreMessages := []*logMessage{} + for _, message := range messages { + if message.Client == clientID { + ignoreMessages = append(ignoreMessages, message.IgnoreMessages...) + } + } + + return ignoreMessages } diff --git a/mongo/integration/unified/logger.go b/mongo/integration/unified/logger.go index 6d5b7efcdc..eb9379f9e3 100644 --- a/mongo/integration/unified/logger.go +++ b/mongo/integration/unified/logger.go @@ -7,6 +7,7 @@ package unified import ( + "context" "sync" "go.mongodb.org/mongo-driver/internal/logger" @@ -33,19 +34,21 @@ type Logger struct { // orderMu guards the order value, which increments each time the "Info" // method is called. This is necessary since "Info" could be called from // multiple go routines, e.g. SDAM logs. - orderMu sync.RWMutex - logQueue chan orderedLogMessage + orderMu sync.RWMutex + logQueue chan orderedLogMessage + ignoreMessages []*logMessage } -func newLogger(olm *observeLogMessages, bufSize int) *Logger { +func newLogger(olm *observeLogMessages, bufSize int, ignoreMessages []*logMessage) *Logger { if olm == nil { return nil } return &Logger{ - lastOrder: 1, - logQueue: make(chan orderedLogMessage, bufSize), - bufSize: bufSize, + lastOrder: 1, + logQueue: make(chan orderedLogMessage, bufSize), + bufSize: bufSize, + ignoreMessages: ignoreMessages, } } @@ -65,8 +68,6 @@ func (log *Logger) Info(level int, msg string, args ...interface{}) { return } - defer func() { log.lastOrder++ }() - // Add the Diff back to the level, as there is no need to create a // logging offset. level = level + logger.DiffToInfo @@ -76,12 +77,19 @@ func (log *Logger) Info(level int, msg string, args ...interface{}) { panic(err) } + for _, ignoreMessage := range log.ignoreMessages { + if err := verifyLogMatch(context.Background(), ignoreMessage, logMessage); err == nil { + return + } + } + + defer func() { log.lastOrder++ }() + // Send the log message to the "orderedLogMessage" channel for // validation. log.logQueue <- orderedLogMessage{ order: log.lastOrder + 1, - logMessage: logMessage, - } + logMessage: logMessage} // If the order has reached the buffer size, then close the channel. if log.lastOrder == log.bufSize { diff --git a/mongo/integration/unified/logger_verification.go b/mongo/integration/unified/logger_verification.go index 2b8e4e9d11..ec4b78abc0 100644 --- a/mongo/integration/unified/logger_verification.go +++ b/mongo/integration/unified/logger_verification.go @@ -79,17 +79,6 @@ type clientLogMessages struct { LogMessages []*logMessage `bson:"messages"` } -// ignore checks to see if the message is in the "IgnoreMessages" slice. -func (clm clientLogMessages) ignore(ctx context.Context, msg *logMessage) bool { - for _, ignoreMessage := range clm.IgnoreMessages { - if err := verifyLogMatch(ctx, ignoreMessage, msg); err == nil { - return true - } - } - - return false -} - // logMessageValidator defines the expectation for log messages across all // clients. type logMessageValidator struct { @@ -191,8 +180,7 @@ type logQueues struct { } // partitionLogQueue will partition the expected logs into "unordered" and -// "ordered" log channels. This function will also remove any logs in the -// "ignoreMessages" list for a client. +// "ordered" log channels. func partitionLogQueue(ctx context.Context, exp *clientLogMessages) logQueues { orderedLogCh := make(chan *logMessage, len(exp.LogMessages)) unorderedLogCh := make(chan *logMessage, len(exp.LogMessages)) @@ -241,12 +229,6 @@ func matchOrderedLogs(ctx context.Context, logs logQueues) <-chan error { defer close(errs) for actual := range logs.ordered { - // Ignore logs that are in the "IngoreMessages" slice of - // the expected results. - if logs.expected.ignore(ctx, actual) { - continue - } - expected := expLogMessages[0] if expected == nil { continue diff --git a/mongo/integration/unified/logger_verification_test.go b/mongo/integration/unified/logger_verification_test.go deleted file mode 100644 index 5defb8d1c0..0000000000 --- a/mongo/integration/unified/logger_verification_test.go +++ /dev/null @@ -1,84 +0,0 @@ -// 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 unified - -import ( - "context" - "testing" - - "go.mongodb.org/mongo-driver/internal/assert" - "go.mongodb.org/mongo-driver/internal/logger" - "go.mongodb.org/mongo-driver/internal/require" -) - -func newTestLogMessage(t *testing.T, level int, msg string, args ...interface{}) *logMessage { - t.Helper() - - message, err := newLogMessage(level, msg, args...) - require.NoError(t, err, "failed to create test log message") - - return message -} - -func TestClientLogMessagesIgnore(t *testing.T) { - t.Parallel() - - tests := []struct { - name string - clm clientLogMessages - message *logMessage - want bool - }{ - { - name: "empty", - clm: clientLogMessages{}, - message: &logMessage{}, - want: false, - }, - { - name: "no match", - clm: clientLogMessages{ - IgnoreMessages: []*logMessage{ - newTestLogMessage(t, int(logger.LevelDebug), logger.CommandFailed), - }, - }, - message: newTestLogMessage(t, int(logger.LevelInfo), logger.CommandFailed), - want: false, - }, - { - name: "match", - clm: clientLogMessages{ - IgnoreMessages: []*logMessage{ - newTestLogMessage(t, int(logger.LevelDebug), logger.CommandStarted), - }, - }, - message: newTestLogMessage(t, int(logger.LevelDebug), logger.CommandStarted), - want: true, - }, - { - name: "match subset", - clm: clientLogMessages{ - IgnoreMessages: []*logMessage{ - newTestLogMessage(t, int(logger.LevelDebug), logger.CommandStarted), - }, - }, - message: newTestLogMessage(t, int(logger.LevelDebug), logger.CommandStarted, "extrakey", 1), - want: true, - }, - } - - for _, test := range tests { - test := test // capture the range variable - - t.Run(test.name, func(t *testing.T) { - t.Parallel() - - got := test.clm.ignore(context.Background(), test.message) - assert.Equal(t, test.want, got, "clientLogMessages.ignore() result") - }) - } -} diff --git a/mongo/integration/unified/unified_spec_runner.go b/mongo/integration/unified/unified_spec_runner.go index 7b92d07204..4422606a4a 100644 --- a/mongo/integration/unified/unified_spec_runner.go +++ b/mongo/integration/unified/unified_spec_runner.go @@ -30,8 +30,6 @@ var ( // TODO(GODRIVER-2843): Fix and unskip these test cases. "Find operation with snapshot": "Test fails frequently. See GODRIVER-2843", "Write commands with snapshot session do not affect snapshot reads": "Test fails frequently. See GODRIVER-2843", - // TODO(GODRIVER-2943): Fix and unskip this test case. - "Topology lifecycle": "Test times out. See GODRIVER-2943", } logMessageValidatorTimeout = 10 * time.Millisecond @@ -223,13 +221,7 @@ func (tc *TestCase) Run(ls LoggerSkipper) error { return fmt.Errorf("schema version %q not supported: %v", tc.schemaVersion, err) } - // Count the number of expected log messages over all clients. - var expectedLogCount int - for _, clientLog := range tc.ExpectLogMessages { - expectedLogCount += len(clientLog.LogMessages) - } - - testCtx := newTestContext(context.Background(), tc.entities, expectedLogCount, tc.setsFailPoint()) + testCtx := newTestContext(context.Background(), tc.entities, tc.ExpectLogMessages, tc.setsFailPoint()) defer func() { // If anything fails while doing test cleanup, we only log the error because the actual test may have already diff --git a/testdata/server-discovery-and-monitoring/unified/logging-replicaset.json b/testdata/server-discovery-and-monitoring/unified/logging-replicaset.json index e6738225cd..8522c14e19 100644 --- a/testdata/server-discovery-and-monitoring/unified/logging-replicaset.json +++ b/testdata/server-discovery-and-monitoring/unified/logging-replicaset.json @@ -220,22 +220,6 @@ } } }, - { - "level": "debug", - "component": "topology", - "data": { - "message": "Topology description changed", - "topologyId": { - "$$exists": true - }, - "previousDescription": { - "$$exists": true - }, - "newDescription": { - "$$exists": true - } - } - }, { "level": "debug", "component": "topology", diff --git a/testdata/server-discovery-and-monitoring/unified/logging-replicaset.yml b/testdata/server-discovery-and-monitoring/unified/logging-replicaset.yml index 4644dc1355..176c4e5e18 100644 --- a/testdata/server-discovery-and-monitoring/unified/logging-replicaset.yml +++ b/testdata/server-discovery-and-monitoring/unified/logging-replicaset.yml @@ -109,6 +109,13 @@ tests: topologyId: { $$exists: true } serverHost: { $$type: string } serverPort: { $$type: [int, long] } + # TODO(GODRIVER-2967): The following log message has been removed from + # the JSON analogue because it assumes that + # "TopologyDescriptionChangedEvent" should occur when a topolgoy is + # closed. This behavior is not clearly defined anywhere and some + # drivers support and some don't. + # + # Need to sync whenever GODRIVER-2967 is unblocked. - level: debug component: topology data: diff --git a/testdata/server-discovery-and-monitoring/unified/logging-sharded.json b/testdata/server-discovery-and-monitoring/unified/logging-sharded.json index 61b27f5be0..33e7ec4bfe 100644 --- a/testdata/server-discovery-and-monitoring/unified/logging-sharded.json +++ b/testdata/server-discovery-and-monitoring/unified/logging-sharded.json @@ -187,22 +187,6 @@ } } }, - { - "level": "debug", - "component": "topology", - "data": { - "message": "Topology description changed", - "topologyId": { - "$$exists": true - }, - "previousDescription": { - "$$exists": true - }, - "newDescription": { - "$$exists": true - } - } - }, { "level": "debug", "component": "topology", diff --git a/testdata/server-discovery-and-monitoring/unified/logging-sharded.yml b/testdata/server-discovery-and-monitoring/unified/logging-sharded.yml index 34cd3611e2..f175ce0f90 100644 --- a/testdata/server-discovery-and-monitoring/unified/logging-sharded.yml +++ b/testdata/server-discovery-and-monitoring/unified/logging-sharded.yml @@ -97,6 +97,13 @@ tests: topologyId: { $$exists: true } serverHost: { $$type: string } serverPort: { $$type: [int, long] } + # TODO(GODRIVER-2967): The following log message has been removed from + # the JSON analogue because it assumes that + # "TopologyDescriptionChangedEvent" should occur when a topolgoy is + # closed. This behavior is not clearly defined anywhere and some + # drivers support and some don't. + # + # Need to sync whenever GODRIVER-2967 is unblocked. - level: debug component: topology data: diff --git a/testdata/server-discovery-and-monitoring/unified/logging-standalone.json b/testdata/server-discovery-and-monitoring/unified/logging-standalone.json index 1ee6dbe899..f27d651afc 100644 --- a/testdata/server-discovery-and-monitoring/unified/logging-standalone.json +++ b/testdata/server-discovery-and-monitoring/unified/logging-standalone.json @@ -162,22 +162,6 @@ } } }, - { - "level": "debug", - "component": "topology", - "data": { - "message": "Topology description changed", - "topologyId": { - "$$exists": true - }, - "previousDescription": { - "$$exists": true - }, - "newDescription": { - "$$exists": true - } - } - }, { "level": "debug", "component": "topology", diff --git a/testdata/server-discovery-and-monitoring/unified/logging-standalone.yml b/testdata/server-discovery-and-monitoring/unified/logging-standalone.yml index 95c2676d44..0b378cd2fc 100644 --- a/testdata/server-discovery-and-monitoring/unified/logging-standalone.yml +++ b/testdata/server-discovery-and-monitoring/unified/logging-standalone.yml @@ -84,6 +84,13 @@ tests: topologyId: { $$exists: true } serverHost: { $$type: string } serverPort: { $$type: [int, long] } + # TODO(GODRIVER-2967): The following log message has been removed from + # the JSON analogue because it assumes that + # "TopologyDescriptionChangedEvent" should occur when a topolgoy is + # closed. This behavior is not clearly defined anywhere and some + # drivers support and some don't. + # + # Need to sync whenever GODRIVER-2967 is unblocked. - level: debug component: topology data: diff --git a/x/mongo/driver/topology/server.go b/x/mongo/driver/topology/server.go index 3e93e0319e..41f93a7df2 100644 --- a/x/mongo/driver/topology/server.go +++ b/x/mongo/driver/topology/server.go @@ -15,6 +15,7 @@ import ( "sync/atomic" "time" + "go.mongodb.org/mongo-driver/bson" "go.mongodb.org/mongo-driver/bson/primitive" "go.mongodb.org/mongo-driver/event" "go.mongodb.org/mongo-driver/internal/driverutil" @@ -1055,10 +1056,24 @@ func (s *Server) publishServerHeartbeatSucceededEvent(connectionID string, } if mustLogServerMessage(s) { - logServerMessage(s, logger.TopologyServerHeartbeatStarted, + descRaw, _ := bson.Marshal(struct { + description.Server `bson:",inline"` + Ok int32 + }{ + Server: desc, + Ok: func() int32 { + if desc.LastError != nil { + return 0 + } + + return 1 + }(), + }) + + logServerMessage(s, logger.TopologyServerHeartbeatSucceeded, logger.KeyAwaited, await, logger.KeyDurationMS, duration.Milliseconds(), - logger.KeyReply, desc) + logger.KeyReply, bson.Raw(descRaw).String()) } }