Added logging specification tests (#1740)

rozza · web-flow · commit df6888d4f047 · 2025-07-03T12:26:42.000+01:00
Fixed issue when openining a socket that throws an exception the heartbeat started message was created but no heartbeat failed message. JAVA-4770
diff --git a/driver-core/src/main/com/mongodb/internal/connection/BaseCluster.java b/driver-core/src/main/com/mongodb/internal/connection/BaseCluster.java
@@ -120,12 +120,12 @@ abstract class BaseCluster implements Cluster {
         this.settings = notNull("settings", settings);
         this.serverFactory = notNull("serverFactory", serverFactory);
         this.clusterListener = singleClusterListener(settings);
-        ClusterOpeningEvent clusterOpeningEvent = new ClusterOpeningEvent(clusterId);
-        this.clusterListener.clusterOpening(clusterOpeningEvent);
-        logTopologyOpening(clusterId, clusterOpeningEvent);
         this.description = new ClusterDescription(settings.getMode(), UNKNOWN, emptyList(),
                 settings, serverFactory.getSettings());
         this.clientMetadata = clientMetadata;
+        logTopologyMonitoringStarting(clusterId);
+        ClusterOpeningEvent clusterOpeningEvent = new ClusterOpeningEvent(clusterId);
+        clusterListener.clusterOpening(clusterOpeningEvent);
     }
 
     @Override
@@ -229,9 +229,9 @@ public void close() {
             phase.get().countDown();
             fireChangeEvent(new ClusterDescription(settings.getMode(), UNKNOWN, emptyList(), settings, serverFactory.getSettings()),
                     description);
+            logTopologyMonitoringStopping(clusterId);
             ClusterClosedEvent clusterClosedEvent = new ClusterClosedEvent(clusterId);
             clusterListener.clusterClosed(clusterClosedEvent);
-            logTopologyClosedEvent(clusterId, clusterClosedEvent);
             stopWaitQueueHandler();
         }
     }
@@ -259,8 +259,8 @@ protected void updateDescription(final ClusterDescription newDescription) {
     protected void fireChangeEvent(final ClusterDescription newDescription, final ClusterDescription previousDescription) {
         if (!wouldDescriptionsGenerateEquivalentEvents(newDescription, previousDescription)) {
             ClusterDescriptionChangedEvent changedEvent = new ClusterDescriptionChangedEvent(getClusterId(), newDescription, previousDescription);
-            clusterListener.clusterDescriptionChanged(changedEvent);
             logTopologyDescriptionChanged(getClusterId(),  changedEvent);
+            clusterListener.clusterDescriptionChanged(changedEvent);
         }
     }
 
@@ -642,9 +642,7 @@ static void logServerSelectionSucceeded(
         }
     }
 
-    static void logTopologyOpening(
-            final ClusterId clusterId,
-            final ClusterOpeningEvent clusterOpeningEvent) {
+    static void logTopologyMonitoringStarting(final ClusterId clusterId) {
         if (STRUCTURED_LOGGER.isRequired(DEBUG, clusterId)) {
             STRUCTURED_LOGGER.log(new LogMessage(
                     TOPOLOGY, DEBUG, "Starting topology monitoring", clusterId,
@@ -669,9 +667,7 @@ static void logTopologyDescriptionChanged(
         }
     }
 
-    static void logTopologyClosedEvent(
-            final ClusterId clusterId,
-            final ClusterClosedEvent clusterClosedEvent) {
+    static void logTopologyMonitoringStopping(final ClusterId clusterId) {
         if (STRUCTURED_LOGGER.isRequired(DEBUG, clusterId)) {
             STRUCTURED_LOGGER.log(new LogMessage(
                     TOPOLOGY, DEBUG, "Stopped topology monitoring", clusterId,
diff --git a/driver-core/src/main/com/mongodb/internal/connection/DefaultServer.java b/driver-core/src/main/com/mongodb/internal/connection/DefaultServer.java
@@ -75,7 +75,6 @@ class DefaultServer implements ClusterableServer {
         this.connectionPool = notNull("connectionPool", connectionPool);
 
         this.serverId = serverId;
-
         serverListener.serverOpening(new ServerOpeningEvent(this.serverId));
 
         this.serverMonitor = serverMonitor;
diff --git a/driver-core/src/main/com/mongodb/internal/connection/DefaultServerMonitor.java b/driver-core/src/main/com/mongodb/internal/connection/DefaultServerMonitor.java
diff --git a/driver-core/src/main/com/mongodb/internal/connection/LoadBalancedCluster.java b/driver-core/src/main/com/mongodb/internal/connection/LoadBalancedCluster.java
@@ -63,7 +63,7 @@
 import static com.mongodb.connection.ServerConnectionState.CONNECTING;
 import static com.mongodb.internal.connection.BaseCluster.logServerSelectionStarted;
 import static com.mongodb.internal.connection.BaseCluster.logServerSelectionSucceeded;
-import static com.mongodb.internal.connection.BaseCluster.logTopologyClosedEvent;
+import static com.mongodb.internal.connection.BaseCluster.logTopologyMonitoringStopping;
 import static com.mongodb.internal.event.EventListenerHelper.singleClusterListener;
 import static java.lang.String.format;
 import static java.util.Collections.emptyList;
@@ -281,9 +281,9 @@ public void close() {
             if (localServer != null) {
                 localServer.close();
             }
+            logTopologyMonitoringStopping(clusterId);
             ClusterClosedEvent clusterClosedEvent = new ClusterClosedEvent(clusterId);
             clusterListener.clusterClosed(clusterClosedEvent);
-            logTopologyClosedEvent(clusterId, clusterClosedEvent);
         }
     }
 
diff --git a/driver-core/src/main/com/mongodb/internal/connection/SingleServerCluster.java b/driver-core/src/main/com/mongodb/internal/connection/SingleServerCluster.java
@@ -59,9 +59,9 @@ public SingleServerCluster(final ClusterId clusterId, final ClusterSettings sett
         // synchronized in the constructor because the change listener is re-entrant to this instance.
         // In other words, we are leaking a reference to "this" from the constructor.
         withLock(() -> {
-            server.set(createServer(settings.getHosts().get(0)));
             publishDescription(ServerDescription.builder().state(CONNECTING).address(settings.getHosts().get(0))
                     .build());
+            server.set(createServer(settings.getHosts().get(0)));
         });
     }
 
diff --git a/driver-core/src/main/com/mongodb/internal/logging/LogMessage.java b/driver-core/src/main/com/mongodb/internal/logging/LogMessage.java
@@ -108,6 +108,7 @@ public enum Name {
              * Not supported.
              */
             OPERATION("operation"),
+            AWAITED("awaited"),
             SERVICE_ID("serviceId"),
             SERVER_CONNECTION_ID("serverConnectionId"),
             DRIVER_CONNECTION_ID("driverConnectionId"),
diff --git a/driver-reactive-streams/src/test/functional/com/mongodb/reactivestreams/client/unified/UnifiedServerDiscoveryAndMonitoringTest.java b/driver-reactive-streams/src/test/functional/com/mongodb/reactivestreams/client/unified/UnifiedServerDiscoveryAndMonitoringTest.java
@@ -17,7 +17,6 @@
 package com.mongodb.reactivestreams.client.unified;
 
 import org.junit.jupiter.params.provider.Arguments;
-
 import java.util.Collection;
 
 final class UnifiedServerDiscoveryAndMonitoringTest extends UnifiedReactiveStreamsTest {
diff --git a/driver-sync/src/test/functional/com/mongodb/client/unified/ContextElement.java b/driver-sync/src/test/functional/com/mongodb/client/unified/ContextElement.java
@@ -495,7 +495,7 @@ public String toString() {
                     + new BsonDocument("messages", expectedMessages).toJson(JsonWriterSettings.builder().indent(true).build()) + "\n"
                     + "   actualMessages="
                     + new BsonDocument("messages", new BsonArray(actualMessages.stream()
-                    .map(LogMatcher::asDocument).collect(Collectors.toList())))
+                    .map(LogMatcher::logMessageAsDocument).collect(Collectors.toList())))
                     .toJson(JsonWriterSettings.builder().indent(true).build()) + "\n";
         }
     }
diff --git a/driver-sync/src/test/functional/com/mongodb/client/unified/EventMatcher.java b/driver-sync/src/test/functional/com/mongodb/client/unified/EventMatcher.java
@@ -336,12 +336,12 @@ public <T> void waitForServerMonitorEvents(final String client, final Class<T> e
         BsonDocument expectedEventContents = getEventContents(expectedEvent);
         try {
             serverMonitorListener.waitForEvents(expectedEventType,
-                    event -> serverMonitorEventMatches(expectedEventContents, event, null), count, Duration.ofSeconds(10));
+                    event -> serverMonitorEventMatches(expectedEventContents, event, null), count, Duration.ofSeconds(15));
             context.pop();
         } catch (InterruptedException e) {
             throw new RuntimeException(e);
         } catch (TimeoutException e) {
-            fail(context.getMessage("Timed out waiting for server monitor events"));
+            fail(context.getMessage(e.getMessage()));
         }
     }
 
diff --git a/driver-sync/src/test/functional/com/mongodb/client/unified/LogMatcher.java b/driver-sync/src/test/functional/com/mongodb/client/unified/LogMatcher.java
@@ -33,6 +33,7 @@
 
 import java.util.Collection;
 import java.util.List;
+import java.util.stream.Collectors;
 
 import static org.junit.Assert.assertEquals;
 import static org.junit.Assert.assertTrue;
@@ -47,15 +48,20 @@ final class LogMatcher {
         this.context = context;
     }
 
-    void assertLogMessageEquality(final String client, final boolean ignoreExtraMessages, final BsonArray expectedMessages,
+    void assertLogMessageEquality(final String client, final BsonArray ignoreMessages,
+            final boolean ignoreExtraMessages, final BsonArray expectedMessages,
             final List<LogMessage> actualMessages, final Iterable<Tweak> tweaks) {
         context.push(ContextElement.ofLogMessages(client, expectedMessages, actualMessages));
 
+        List<LogMessage> logMessages = actualMessages.stream()
+                .filter(logMessage -> !ignoreMessages.contains(logMessageAsIgnoreMessageDocument(logMessage)))
+                .collect(Collectors.toList());
+
         if (ignoreExtraMessages) {
             assertTrue(context.getMessage("Number of messages must be greater than or equal to the expected number of messages"),
-                    actualMessages.size() >= expectedMessages.size());
+                    logMessages.size() >= expectedMessages.size());
         } else {
-            assertEquals(context.getMessage("Number of log messages must be the same"), expectedMessages.size(), actualMessages.size());
+            assertEquals(context.getMessage("Number of log messages must be the same"), expectedMessages.size(), logMessages.size());
         }
 
         for (int i = 0; i < expectedMessages.size(); i++) {
@@ -64,14 +70,22 @@ void assertLogMessageEquality(final String client, final boolean ignoreExtraMess
                 expectedMessage = tweak.apply(expectedMessage);
             }
             if (expectedMessage != null) {
-                valueMatcher.assertValuesMatch(expectedMessage, asDocument(actualMessages.get(i)));
+                valueMatcher.assertValuesMatch(expectedMessage, logMessageAsDocument(logMessages.get(i)));
             }
         }
 
         context.pop();
     }
 
-     static BsonDocument asDocument(final LogMessage message) {
+    private static BsonDocument logMessageAsIgnoreMessageDocument(final LogMessage message) {
+        BsonDocument document = new BsonDocument();
+        document.put("level", new BsonString(message.getLevel().name().toLowerCase()));
+        document.put("component", new BsonString(message.getComponent().getValue()));
+        document.put("data", new BsonDocument("message", new BsonString(message.getMessageId())));
+        return document;
+    }
+
+     static BsonDocument logMessageAsDocument(final LogMessage message) {
         BsonDocument document = new BsonDocument();
         document.put("component", new BsonString(message.getComponent().getValue()));
         document.put("level", new BsonString(message.getLevel().name().toLowerCase()));
diff --git a/driver-sync/src/test/functional/com/mongodb/client/unified/UnifiedTest.java b/driver-sync/src/test/functional/com/mongodb/client/unified/UnifiedTest.java
@@ -481,10 +481,11 @@ private void compareLogMessages(final UnifiedTestContext rootContext, final Bson
         for (BsonValue cur : definition.getArray("expectLogMessages")) {
             BsonDocument curLogMessagesForClient = cur.asDocument();
             boolean ignoreExtraMessages = curLogMessagesForClient.getBoolean("ignoreExtraMessages", BsonBoolean.FALSE).getValue();
+            BsonArray ignoreMessages = curLogMessagesForClient.getArray("ignoreMessages", new BsonArray());
             String clientId = curLogMessagesForClient.getString("client").getValue();
             TestLoggingInterceptor loggingInterceptor =
                     entities.getClientLoggingInterceptor(clientId);
-            rootContext.getLogMatcher().assertLogMessageEquality(clientId, ignoreExtraMessages,
+            rootContext.getLogMatcher().assertLogMessageEquality(clientId, ignoreMessages, ignoreExtraMessages,
                     curLogMessagesForClient.getArray("messages"), loggingInterceptor.getMessages(), tweaks);
         }
     }
diff --git a/driver-sync/src/test/functional/com/mongodb/client/unified/UnifiedTestModifications.java b/driver-sync/src/test/functional/com/mongodb/client/unified/UnifiedTestModifications.java
@@ -233,11 +233,6 @@ public static void applyCustomizations(final TestDef def) {
         def.skipJira("https://jira.mongodb.org/browse/JAVA-5230")
                 .test("server-discovery-and-monitoring", "serverMonitoringMode", "connect with serverMonitoringMode=auto >=4.4")
                 .test("server-discovery-and-monitoring", "serverMonitoringMode", "connect with serverMonitoringMode=stream >=4.4");
-        def.skipJira("https://jira.mongodb.org/browse/JAVA-4770")
-                .file("server-discovery-and-monitoring", "standalone-logging")
-                .file("server-discovery-and-monitoring", "replicaset-logging")
-                .file("server-discovery-and-monitoring", "sharded-logging")
-                .file("server-discovery-and-monitoring", "loadbalanced-logging");
         def.skipJira("https://jira.mongodb.org/browse/JAVA-5564")
                 .test("server-discovery-and-monitoring", "serverMonitoringMode", "poll waits after successful heartbeat");
         def.skipJira("https://jira.mongodb.org/browse/JAVA-4536")

Original file line number	Diff line number	Diff line change
`@@ -63,7 +63,7 @@`
`63`	`63`	`import static com.mongodb.connection.ServerConnectionState.CONNECTING;`
`64`	`64`	`import static com.mongodb.internal.connection.BaseCluster.logServerSelectionStarted;`
`65`	`65`	`import static com.mongodb.internal.connection.BaseCluster.logServerSelectionSucceeded;`
`66`		`-import static com.mongodb.internal.connection.BaseCluster.logTopologyClosedEvent;`
	`66`	`+import static com.mongodb.internal.connection.BaseCluster.logTopologyMonitoringStopping;`
`67`	`67`	`import static com.mongodb.internal.event.EventListenerHelper.singleClusterListener;`
`68`	`68`	`import static java.lang.String.format;`
`69`	`69`	`import static java.util.Collections.emptyList;`
`@@ -281,9 +281,9 @@ public void close() {`
`281`	`281`	`if (localServer != null) {`
`282`	`282`	`localServer.close();`
`283`	`283`	`}`
	`284`	`+ logTopologyMonitoringStopping(clusterId);`
`284`	`285`	`ClusterClosedEvent clusterClosedEvent = new ClusterClosedEvent(clusterId);`
`285`	`286`	`clusterListener.clusterClosed(clusterClosedEvent);`
`286`		`- logTopologyClosedEvent(clusterId, clusterClosedEvent);`
`287`	`287`	`}`
`288`	`288`	`}`
`289`	`289`
Original file line number	Diff line number	Diff line change
`@@ -495,7 +495,7 @@ public String toString() {`
`495`	`495`	`+ new BsonDocument("messages", expectedMessages).toJson(JsonWriterSettings.builder().indent(true).build()) + "\n"`
`496`	`496`	`+ " actualMessages="`
`497`	`497`	`+ new BsonDocument("messages", new BsonArray(actualMessages.stream()`
`498`		`- .map(LogMatcher::asDocument).collect(Collectors.toList())))`
	`498`	`+ .map(LogMatcher::logMessageAsDocument).collect(Collectors.toList())))`
`499`	`499`	`.toJson(JsonWriterSettings.builder().indent(true).build()) + "\n";`
`500`	`500`	`}`
`501`	`501`	`}`
Original file line number	Diff line number	Diff line change
`@@ -336,12 +336,12 @@ public <T> void waitForServerMonitorEvents(final String client, final Class<T> e`
`336`	`336`	`BsonDocument expectedEventContents = getEventContents(expectedEvent);`
`337`	`337`	`try {`
`338`	`338`	`serverMonitorListener.waitForEvents(expectedEventType,`
`339`		`- event -> serverMonitorEventMatches(expectedEventContents, event, null), count, Duration.ofSeconds(10));`
	`339`	`+ event -> serverMonitorEventMatches(expectedEventContents, event, null), count, Duration.ofSeconds(15));`
`340`	`340`	`context.pop();`
`341`	`341`	`} catch (InterruptedException e) {`
`342`	`342`	`throw new RuntimeException(e);`
`343`	`343`	`} catch (TimeoutException e) {`
`344`		`- fail(context.getMessage("Timed out waiting for server monitor events"));`
	`344`	`+ fail(context.getMessage(e.getMessage()));`
`345`	`345`	`}`
`346`	`346`	`}`
`347`	`347`