Skip to content

Commit 2f0917c

Browse files
prestonvasquezprestonvasquez
authored
GODRIVER-2943 Re-organize client entity expected log messages (#1366)
1 parent d05853f commit 2f0917c

13 files changed

+90
-179
lines changed

‎mongo/integration/unified/client_entity.go

Lines changed: 4 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -107,7 +107,10 @@ func newClientEntity(ctx context.Context, em *EntityMap, entityOptions *entityOp
107107
}
108108

109109
if olm := entityOptions.ObserveLogMessages; olm != nil {
110-
clientLogger := newLogger(olm, expectedLogMessageCount(ctx))
110+
expectedLogMessagesCount := expectedLogMessagesCount(ctx, entityOptions.ID)
111+
ignoreLogMessages := ignoreLogMessages(ctx, entityOptions.ID)
112+
113+
clientLogger := newLogger(olm, expectedLogMessagesCount, ignoreLogMessages)
111114

112115
wrap := func(str string) options.LogLevel {
113116
return options.LogLevel(logger.ParseLevel(str))

‎mongo/integration/unified/context.go

Lines changed: 28 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -28,23 +28,23 @@ const (
2828
failPointsKey ctxKey = "test-failpoints"
2929
// targetedFailPointsKey is used to store a map from a fail point name to the host on which the fail point is set.
3030
targetedFailPointsKey ctxKey = "test-targeted-failpoints"
31-
// expectedLogMessageCountKey is used to store the number of log messages expected to be received by the test runner.
32-
expectedLogMessageCountKey ctxKey = "test-expected-log-message-count"
31+
clientLogMessagesKey ctxKey = "test-expected-log-message-count"
32+
ignoreLogMessagesKey ctxKey = "test-ignore-log-message-count"
3333
)
3434

3535
// newTestContext creates a new Context derived from ctx with values initialized to store the state required for test
3636
// execution.
3737
func newTestContext(
3838
ctx context.Context,
3939
entityMap *EntityMap,
40-
expectedLogMessageCount int,
40+
clientLogMessages []*clientLogMessages,
4141
hasOperationalFailPoint bool,
4242
) context.Context {
4343
ctx = context.WithValue(ctx, operationalFailPointKey, hasOperationalFailPoint)
4444
ctx = context.WithValue(ctx, entitiesKey, entityMap)
4545
ctx = context.WithValue(ctx, failPointsKey, make(map[string]*mongo.Client))
4646
ctx = context.WithValue(ctx, targetedFailPointsKey, make(map[string]string))
47-
ctx = context.WithValue(ctx, expectedLogMessageCountKey, expectedLogMessageCount)
47+
ctx = context.WithValue(ctx, clientLogMessagesKey, clientLogMessages)
4848
return ctx
4949
}
5050

@@ -84,6 +84,28 @@ func entities(ctx context.Context) *EntityMap {
8484
return ctx.Value(entitiesKey).(*EntityMap)
8585
}
8686

87-
func expectedLogMessageCount(ctx context.Context) int {
88-
return ctx.Value(expectedLogMessageCountKey).(int)
87+
func expectedLogMessagesCount(ctx context.Context, clientID string) int {
88+
messages := ctx.Value(clientLogMessagesKey).([]*clientLogMessages)
89+
90+
count := 0
91+
for _, message := range messages {
92+
if message.Client == clientID {
93+
count += len(message.LogMessages)
94+
}
95+
}
96+
97+
return count
98+
}
99+
100+
func ignoreLogMessages(ctx context.Context, clientID string) []*logMessage {
101+
messages := ctx.Value(clientLogMessagesKey).([]*clientLogMessages)
102+
103+
ignoreMessages := []*logMessage{}
104+
for _, message := range messages {
105+
if message.Client == clientID {
106+
ignoreMessages = append(ignoreMessages, message.IgnoreMessages...)
107+
}
108+
}
109+
110+
return ignoreMessages
89111
}

‎mongo/integration/unified/logger.go

Lines changed: 18 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -7,6 +7,7 @@
77
package unified
88

99
import (
10+
"context"
1011
"sync"
1112

1213
"go.mongodb.org/mongo-driver/internal/logger"
@@ -33,19 +34,21 @@ type Logger struct {
3334
// orderMu guards the order value, which increments each time the "Info"
3435
// method is called. This is necessary since "Info" could be called from
3536
// multiple go routines, e.g. SDAM logs.
36-
orderMu sync.RWMutex
37-
logQueue chan orderedLogMessage
37+
orderMu sync.RWMutex
38+
logQueue chan orderedLogMessage
39+
ignoreMessages []*logMessage
3840
}
3941

40-
func newLogger(olm *observeLogMessages, bufSize int) *Logger {
42+
func newLogger(olm *observeLogMessages, bufSize int, ignoreMessages []*logMessage) *Logger {
4143
if olm == nil {
4244
return nil
4345
}
4446

4547
return &Logger{
46-
lastOrder: 1,
47-
logQueue: make(chan orderedLogMessage, bufSize),
48-
bufSize: bufSize,
48+
lastOrder: 1,
49+
logQueue: make(chan orderedLogMessage, bufSize),
50+
bufSize: bufSize,
51+
ignoreMessages: ignoreMessages,
4952
}
5053
}
5154

@@ -65,8 +68,6 @@ func (log *Logger) Info(level int, msg string, args ...interface{}) {
6568
return
6669
}
6770

68-
defer func() { log.lastOrder++ }()
69-
7071
// Add the Diff back to the level, as there is no need to create a
7172
// logging offset.
7273
level = level + logger.DiffToInfo
@@ -76,12 +77,19 @@ func (log *Logger) Info(level int, msg string, args ...interface{}) {
7677
panic(err)
7778
}
7879

80+
for _, ignoreMessage := range log.ignoreMessages {
81+
if err := verifyLogMatch(context.Background(), ignoreMessage, logMessage); err == nil {
82+
return
83+
}
84+
}
85+
86+
defer func() { log.lastOrder++ }()
87+
7988
// Send the log message to the "orderedLogMessage" channel for
8089
// validation.
8190
log.logQueue <- orderedLogMessage{
8291
order: log.lastOrder + 1,
83-
logMessage: logMessage,
84-
}
92+
logMessage: logMessage}
8593

8694
// If the order has reached the buffer size, then close the channel.
8795
if log.lastOrder == log.bufSize {

‎mongo/integration/unified/logger_verification.go

Lines changed: 1 addition & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -79,17 +79,6 @@ type clientLogMessages struct {
7979
LogMessages []*logMessage `bson:"messages"`
8080
}
8181

82-
// ignore checks to see if the message is in the "IgnoreMessages" slice.
83-
func (clm clientLogMessages) ignore(ctx context.Context, msg *logMessage) bool {
84-
for _, ignoreMessage := range clm.IgnoreMessages {
85-
if err := verifyLogMatch(ctx, ignoreMessage, msg); err == nil {
86-
return true
87-
}
88-
}
89-
90-
return false
91-
}
92-
9382
// logMessageValidator defines the expectation for log messages across all
9483
// clients.
9584
type logMessageValidator struct {
@@ -191,8 +180,7 @@ type logQueues struct {
191180
}
192181

193182
// partitionLogQueue will partition the expected logs into "unordered" and
194-
// "ordered" log channels. This function will also remove any logs in the
195-
// "ignoreMessages" list for a client.
183+
// "ordered" log channels.
196184
func partitionLogQueue(ctx context.Context, exp *clientLogMessages) logQueues {
197185
orderedLogCh := make(chan *logMessage, len(exp.LogMessages))
198186
unorderedLogCh := make(chan *logMessage, len(exp.LogMessages))
@@ -241,12 +229,6 @@ func matchOrderedLogs(ctx context.Context, logs logQueues) <-chan error {
241229
defer close(errs)
242230

243231
for actual := range logs.ordered {
244-
// Ignore logs that are in the "IngoreMessages" slice of
245-
// the expected results.
246-
if logs.expected.ignore(ctx, actual) {
247-
continue
248-
}
249-
250232
expected := expLogMessages[0]
251233
if expected == nil {
252234
continue

‎mongo/integration/unified/logger_verification_test.go

Lines changed: 0 additions & 84 deletions
This file was deleted.

‎mongo/integration/unified/unified_spec_runner.go

Lines changed: 1 addition & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -30,8 +30,6 @@ var (
3030
// TODO(GODRIVER-2843): Fix and unskip these test cases.
3131
"Find operation with snapshot": "Test fails frequently. See GODRIVER-2843",
3232
"Write commands with snapshot session do not affect snapshot reads": "Test fails frequently. See GODRIVER-2843",
33-
// TODO(GODRIVER-2943): Fix and unskip this test case.
34-
"Topology lifecycle": "Test times out. See GODRIVER-2943",
3533
}
3634

3735
logMessageValidatorTimeout = 10 * time.Millisecond
@@ -223,13 +221,7 @@ func (tc *TestCase) Run(ls LoggerSkipper) error {
223221
return fmt.Errorf("schema version %q not supported: %v", tc.schemaVersion, err)
224222
}
225223

226-
// Count the number of expected log messages over all clients.
227-
var expectedLogCount int
228-
for _, clientLog := range tc.ExpectLogMessages {
229-
expectedLogCount += len(clientLog.LogMessages)
230-
}
231-
232-
testCtx := newTestContext(context.Background(), tc.entities, expectedLogCount, tc.setsFailPoint())
224+
testCtx := newTestContext(context.Background(), tc.entities, tc.ExpectLogMessages, tc.setsFailPoint())
233225

234226
defer func() {
235227
// If anything fails while doing test cleanup, we only log the error because the actual test may have already

‎testdata/server-discovery-and-monitoring/unified/logging-replicaset.json

Lines changed: 0 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -220,22 +220,6 @@
220220
}
221221
}
222222
},
223-
{
224-
"level": "debug",
225-
"component": "topology",
226-
"data": {
227-
"message": "Topology description changed",
228-
"topologyId": {
229-
"$$exists": true
230-
},
231-
"previousDescription": {
232-
"$$exists": true
233-
},
234-
"newDescription": {
235-
"$$exists": true
236-
}
237-
}
238-
},
239223
{
240224
"level": "debug",
241225
"component": "topology",

‎testdata/server-discovery-and-monitoring/unified/logging-replicaset.yml

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -109,6 +109,13 @@ tests:
109109
topologyId: { $$exists: true }
110110
serverHost: { $$type: string }
111111
serverPort: { $$type: [int, long] }
112+
# TODO(GODRIVER-2967): The following log message has been removed from
113+
# the JSON analogue because it assumes that
114+
# "TopologyDescriptionChangedEvent" should occur when a topolgoy is
115+
# closed. This behavior is not clearly defined anywhere and some
116+
# drivers support and some don't.
117+
#
118+
# Need to sync whenever GODRIVER-2967 is unblocked.
112119
- level: debug
113120
component: topology
114121
data:

‎testdata/server-discovery-and-monitoring/unified/logging-sharded.json

Lines changed: 0 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -187,22 +187,6 @@
187187
}
188188
}
189189
},
190-
{
191-
"level": "debug",
192-
"component": "topology",
193-
"data": {
194-
"message": "Topology description changed",
195-
"topologyId": {
196-
"$$exists": true
197-
},
198-
"previousDescription": {
199-
"$$exists": true
200-
},
201-
"newDescription": {
202-
"$$exists": true
203-
}
204-
}
205-
},
206190
{
207191
"level": "debug",
208192
"component": "topology",

‎testdata/server-discovery-and-monitoring/unified/logging-sharded.yml

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -97,6 +97,13 @@ tests:
9797
topologyId: { $$exists: true }
9898
serverHost: { $$type: string }
9999
serverPort: { $$type: [int, long] }
100+
# TODO(GODRIVER-2967): The following log message has been removed from
101+
# the JSON analogue because it assumes that
102+
# "TopologyDescriptionChangedEvent" should occur when a topolgoy is
103+
# closed. This behavior is not clearly defined anywhere and some
104+
# drivers support and some don't.
105+
#
106+
# Need to sync whenever GODRIVER-2967 is unblocked.
100107
- level: debug
101108
component: topology
102109
data:

‎testdata/server-discovery-and-monitoring/unified/logging-standalone.json

Lines changed: 0 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -162,22 +162,6 @@
162162
}
163163
}
164164
},
165-
{
166-
"level": "debug",
167-
"component": "topology",
168-
"data": {
169-
"message": "Topology description changed",
170-
"topologyId": {
171-
"$$exists": true
172-
},
173-
"previousDescription": {
174-
"$$exists": true
175-
},
176-
"newDescription": {
177-
"$$exists": true
178-
}
179-
}
180-
},
181165
{
182166
"level": "debug",
183167
"component": "topology",

‎testdata/server-discovery-and-monitoring/unified/logging-standalone.yml

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -84,6 +84,13 @@ tests:
8484
topologyId: { $$exists: true }
8585
serverHost: { $$type: string }
8686
serverPort: { $$type: [int, long] }
87+
# TODO(GODRIVER-2967): The following log message has been removed from
88+
# the JSON analogue because it assumes that
89+
# "TopologyDescriptionChangedEvent" should occur when a topolgoy is
90+
# closed. This behavior is not clearly defined anywhere and some
91+
# drivers support and some don't.
92+
#
93+
# Need to sync whenever GODRIVER-2967 is unblocked.
8794
- level: debug
8895
component: topology
8996
data:

0 commit comments

Comments
 (0)