Added logging specification tests #1740

rozza · 2025-06-16T13:33:55Z

JAVA-4770

rozza · 2025-06-16T13:47:00Z

driver-core/src/main/com/mongodb/internal/connection/SingleServerCluster.java

@@ -58,9 +58,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))


The tests expect the toplogy description changed to connecting & unknown to be logged before the starting the server monitor log message.

Creating the server first meant that they were the wrong way around.

katcharov

LGTM!

driver-core/src/main/com/mongodb/internal/connection/DefaultServerMonitor.java

katcharov · 2025-06-18T22:26:51Z

driver-sync/src/test/functional/com/mongodb/client/unified/EventMatcher.java

@@ -336,7 +336,7 @@ 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(30));


Updated to 15 - I just wanted to ensure that the server monitor through runs at least once. I think it defaults to every 10 seconds.

Changed to 15 to ensure servermonitor runs at least once.

Nit removed

jyemin

Strangely, when I run the tests locally, both the sync and reactive runners consistently fail the standalone-logging: Topology lifecycle test.

java.lang.AssertionError: Expected BSON values to be equal

Assertion Context:

Value Matching Context:
   Key: message
   Expected value:
      BsonString{value='Topology description changed'}
   Actual value:
      BsonString{value='Stopped server monitoring'}

I imagine you're not seeing that?

driver-sync/src/test/functional/com/mongodb/client/unified/UnifiedTestModifications.java

rozza · 2025-06-23T13:28:19Z

@jyemin - I do see it locally. I recall it as the result of a race condition - the test fails before the description is changed.

I'll review again and see if there is a way to reduce the flakyness. As 5 of the 6 failures hit a similar race when heartbeats are expected to fail.

Previous failing Failing heartbeat test showed that multiple heartbeat started calls but no success or failure calls.

When openining a socket that throws an exception the heartbeat started message is created but no heartbeat failed message.

rozza · 2025-06-26T14:27:33Z

Flaky tests fixed and modifications removed.

Final bug I introduced in JAVA-5230 - where opening the connection issues a heartbeat started event but if that errored there wasn't a corresponding heartbeat failed event.

Build looking happier now (I did have to restart some non related failures).

Copilot

Pull Request Overview

This PR implements logging specification tests (JAVA-4770) by updating the unified test framework to support filtering and ignoring specific log messages, and introduces structured logging in cluster and server monitor classes.

Remove skips for logging tests and add ignoreMessages support in assertLogMessageEquality.
Refactor and extend LogMatcher, ContextElement, and unified tests to handle ignored log entries.
Add structured logging methods in DefaultServerMonitor, adjust topology monitoring logs, and update related classes.

Reviewed Changes

Copilot reviewed 13 out of 13 changed files in this pull request and generated 4 comments.

Show a summary per file

File	Description
driver-sync/src/test/functional/com/mongodb/client/unified/UnifiedTestModifications.java	Removed skipJira entries for logging tests
driver-sync/src/test/functional/com/mongodb/client/unified/UnifiedTest.java	Added `ignoreMessages` parameter and updated `assertLogMessageEquality`
driver-sync/src/test/functional/com/mongodb/client/unified/UnifiedServerDiscoveryAndMonitoringTest.java	Filter test data to only `serverMonitoringMode` scenarios
driver-sync/src/test/functional/com/mongodb/client/unified/LogMatcher.java	Support `ignoreMessages`, extract helper methods
driver-sync/src/test/functional/com/mongodb/client/unified/EventMatcher.java	Increased timeout and refined failure message handling
driver-sync/src/test/functional/com/mongodb/client/unified/ContextElement.java	Updated to use `logMessageAsDocument` helper
driver-reactive-streams/src/test/functional/com/mongodb/reactivestreams/client/unified/UnifiedServerDiscoveryAndMonitoringTest.java	Removed stray blank import
driver-core/src/main/com/mongodb/internal/logging/LogMessage.java	Added `AWAITED` enum entry
driver-core/src/main/com/mongodb/internal/connection/SingleServerCluster.java	Reordered `server.set` and `publishDescription`
driver-core/src/main/com/mongodb/internal/connection/LoadBalancedCluster.java	Changed close logging to `logTopologyMonitoringStopping`
driver-core/src/main/com/mongodb/internal/connection/DefaultServerMonitor.java	Introduced structured logging methods and refactored heartbeat logic
driver-core/src/main/com/mongodb/internal/connection/DefaultServer.java	Added unused `StructuredLogger` import and field
driver-core/src/main/com/mongodb/internal/connection/BaseCluster.java	Updated topology monitoring log methods

Comments suppressed due to low confidence (1)

driver-sync/src/test/functional/com/mongodb/client/unified/EventMatcher.java:344

Using the exception message as a resource key may produce unclear failure messages if the key doesn't exist. Consider using a fixed context message or passing the exception message directly to fail().

            fail(context.getMessage(e.getMessage()));

driver-core/src/main/com/mongodb/internal/connection/SingleServerCluster.java

driver-core/src/main/com/mongodb/internal/connection/DefaultServer.java

driver-core/src/main/com/mongodb/internal/connection/LoadBalancedCluster.java

Copilot · 2025-06-26T14:29:32Z

driver-core/src/main/com/mongodb/internal/connection/DefaultServerMonitor.java

@@ -295,6 +311,34 @@ private ServerDescription lookupServerDescription(final ServerDescription curren
            }
        }

+        private ServerDescription openNewConnectionAndGetInitialDescription(final boolean shouldStreamResponses) {


[nitpick] The new openNewConnectionAndGetInitialDescription method duplicates logic from lookupServerDescription. Consider refactoring shared parts to reduce duplication.

rozza requested a review from Copilot June 16, 2025 13:33

This comment was marked as resolved.

Sign in to view

rozza force-pushed the JAVA-4770 branch from bdc1af3 to 0c73982 Compare June 16, 2025 13:37

Added logging specification tests

8e94d55

JAVA-4770

rozza force-pushed the JAVA-4770 branch from b6a084d to 8e94d55 Compare June 16, 2025 13:43

rozza requested a review from Copilot June 16, 2025 13:44

This comment was marked as outdated.

Sign in to view

rozza commented Jun 16, 2025

View reviewed changes

rozza added 2 commits June 16, 2025 16:11

Retry flaky / racy failing heartbeat tests

cde8e0b

Provide reason for the retry

0b57fd8

rozza requested review from a team and katcharov and removed request for a team June 16, 2025 15:56

Bump timeout for server monitor events

1513156

rozza marked this pull request as ready for review June 17, 2025 13:45

rozza requested a review from a team as a code owner June 17, 2025 13:45

Merge branch 'main' into JAVA-4770

bc4e53c

katcharov approved these changes Jun 18, 2025

View reviewed changes

rozza added 2 commits June 19, 2025 16:58

Update EventMatcher.java

17d20d1

Changed to 15 to ensure servermonitor runs at least once.

Update DefaultServerMonitor.java

c381586

Nit removed

jyemin self-requested a review June 19, 2025 22:48

jyemin reviewed Jun 19, 2025

View reviewed changes

driver-sync/src/test/functional/com/mongodb/client/unified/UnifiedTestModifications.java Outdated Show resolved Hide resolved

rozza added 6 commits June 24, 2025 13:07

Log messages before publishing events

4212fcd

Temp remove flaky tests to see outcome

9f5a5a8

Output all seen events when timing out

31cc6f2

Propogate the error message

963a9e9

Added more debugging.

158c072

Previous failing Failing heartbeat test showed that multiple heartbeat started calls but no success or failure calls.

Fix heartbeat bug and remove debugging logic

cd7e726

When openining a socket that throws an exception the heartbeat started message is created but no heartbeat failed message.

rozza marked this pull request as draft June 25, 2025 18:01

Fix time reporting for heartbeats

e7dfa0c

rozza force-pushed the JAVA-4770 branch from 3a8a1c2 to e7dfa0c Compare June 26, 2025 13:50

rozza marked this pull request as ready for review June 26, 2025 14:24

rozza requested review from katcharov, jyemin and Copilot June 26, 2025 14:27

Copilot AI reviewed Jun 26, 2025

View reviewed changes

PR fixes

bec47fd

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Added logging specification tests #1740

Added logging specification tests #1740

Uh oh!

rozza commented Jun 16, 2025

Uh oh!

This comment was marked as resolved.

Uh oh!

This comment was marked as outdated.

Uh oh!

rozza Jun 16, 2025 •

edited

Loading

Uh oh!

katcharov left a comment

Uh oh!

Uh oh!

katcharov Jun 18, 2025

Uh oh!

rozza Jun 19, 2025

Uh oh!

jyemin left a comment

Uh oh!

Uh oh!

rozza commented Jun 23, 2025

Uh oh!

rozza commented Jun 26, 2025

Uh oh!

Copilot AI left a comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Copilot AI Jun 26, 2025

Uh oh!

Uh oh!

Added logging specification tests #1740

Are you sure you want to change the base?

Added logging specification tests #1740

Uh oh!

Conversation

rozza commented Jun 16, 2025

Uh oh!

This comment was marked as resolved.

Uh oh!

This comment was marked as outdated.

Uh oh!

rozza Jun 16, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

katcharov left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

katcharov Jun 18, 2025

Choose a reason for hiding this comment

Uh oh!

rozza Jun 19, 2025

Choose a reason for hiding this comment

Uh oh!

jyemin left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

rozza commented Jun 23, 2025

Uh oh!

rozza commented Jun 26, 2025

Uh oh!

Copilot AI left a comment

Choose a reason for hiding this comment

Pull Request Overview

Reviewed Changes

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Copilot AI Jun 26, 2025

Choose a reason for hiding this comment

Uh oh!

Uh oh!

rozza Jun 16, 2025 •

edited

Loading