Add server selection log messages #1221

stIncMale · 2023-10-11T16:29:59Z

The implemented spec changes: mongodb/specifications@c773534.

JAVA-4754

stIncMale · 2023-10-11T16:41:48Z

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

@@ -118,6 +119,7 @@ public final class Entities {
    private final Map<String, TestLoggingInterceptor> clientLoggingInterceptors = new HashMap<>();
    private final Map<String, TestConnectionPoolListener> clientConnectionPoolListeners = new HashMap<>();
    private final Map<String, TestServerListener> clientServerListeners = new HashMap<>();
+    private final Map<String, TestClusterListener> clientClusterListeners = new HashMap<>();


The new code using clientClusterListeners in this PR was written based on the existing code that uses clientServerListeners.

stIncMale · 2023-10-11T16:44:53Z

driver-core/src/test/unit/com/mongodb/internal/connection/TestClusterListener.java

-    private ClusterOpeningEvent clusterOpeningEvent;
-    private ClusterClosedEvent clusterClosingEvent;
-    private final List<ClusterDescriptionChangedEvent> clusterDescriptionChangedEvents = new ArrayList<>();
+public final class TestClusterListener implements ClusterListener {


The changes in TestClusterListener are needed for the spec tests added in this PR.

stIncMale · 2023-10-11T16:50:04Z

driver-core/src/test/unit/com/mongodb/internal/connection/TestServerListener.java

+    public void waitForServerDescriptionChangedEvents(
+            final Predicate<ServerDescriptionChangedEvent> matcher, final int count, final Duration duration)


The signature of this method in TestServerListener was changed to make the method similar to TestClusterListener.waitForClusterDescriptionChangedEvents.

The rest of the changes in TestServerListener is meant to fix concurrency issues in the code, which we had because we previously mistakenly decided that ClusterListener/ServerListener/ServerMonitorListener don't need to care about concurrency (see https://jira.mongodb.org/browse/JAVA-5185).

stIncMale · 2023-10-11T16:54:22Z

driver-core/src/main/com/mongodb/internal/session/ServerSessionPool.java

+        ReadPreference primaryPreferred = ReadPreference.primaryPreferred();
+        List<ServerDescription> primaryPreferredServers = new ReadPreferenceServerSelector(primaryPreferred)
                .select(cluster.getCurrentDescription());
-        if (primaryPreferred.isEmpty()) {
+        if (primaryPreferredServers.isEmpty()) {
+            // Skip doing server selection if we anticipate that no server is readily selectable.
+            // This approach is racy, and it is still possible to become blocked selecting a server
+            // even if `primaryPreferredServers` is not empty.
            return;
        }

        Connection connection = null;
        try {
            StaticBindingContext context = new StaticBindingContext(NoOpSessionContext.INSTANCE, serverApi,
                    IgnorableRequestContext.INSTANCE, new OperationContext());
-            connection = cluster.selectServer(clusterDescription -> {
-                for (ServerDescription cur : clusterDescription.getServerDescriptions()) {
-                    if (cur.getAddress().equals(primaryPreferred.get(0).getAddress())) {
-                        return Collections.singletonList(cur);
-                    }
-                }
-                return Collections.emptyList();
-            }, context.getOperationContext()).getServer().getConnection(context.getOperationContext());
+            connection = cluster.selectServer(
+                    new ServerSelector() {
+                        @Override
+                        public List<ServerDescription> select(final ClusterDescription clusterDescription) {
+                            for (ServerDescription cur : clusterDescription.getServerDescriptions()) {
+                                if (cur.getAddress().equals(primaryPreferredServers.get(0).getAddress())) {
+                                    return Collections.singletonList(cur);
+                                }
+                            }
+                            return Collections.emptyList();
+                        }
+
+                        @Override
+                        public String toString() {
+                            return "ReadPreferenceServerSelector{"
+                                    + "readPreference=" + primaryPreferred
+                                    + '}';
+                        }
+                    },
+                    context.getOperationContext()).getServer().getConnection(context.getOperationContext());


This change is just to implement toString for this custom ServerSelector. Also left a comment explaining the idea behind this custom selector and the issue with it.

stIncMale · 2023-10-11T16:56:03Z

driver-core/src/main/com/mongodb/internal/logging/StructuredLogger.java

-                        logger.debug(message, exception);
-                    }
-                }
+                logUnstructured(logMessage, Logger::isDebugEnabled, Logger::debug, Logger::debug);


The inference magic is strong in this code, when it comes to the last two arguments.

driver-core/src/main/com/mongodb/internal/logging/LogMessage.java

stIncMale · 2023-10-11T17:18:20Z

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

-                    throw createTimeoutException(serverSelector, curDescription);
+                Long remainingTimeNanos = maxWaitTimeNanos == null ? null : maxWaitTimeNanos - (curTimeNanos - startTimeNanos);
+
+                if (remainingTimeNanos != null && remainingTimeNanos <= 0) {


Note how now remainingTimeNanos <= 0 is used, while previously curTimeNanos - startTimeNanos > maxWaitTimeNanos was used, which was equivalent to remainingTimeNanos < 0. The reason we must use <= instead of < is that when maxWaitTimeNanos is 0, we must not wait (as per the getServerSelectionTimeout docs), and <= 0 makes sure we don't wait, while < is not guaranteed to give us that behavior.

The Javadoc says:

A value of 0 means that it will timeout immediately if no server is available. A negative value means to wait indefinitely.

The spec only says:

A serverSelectionTimeoutMS of zero MAY have special meaning in some drivers; zero's meaning is not defined in this spec, but all drivers SHOULD document the meaning of zero.

So this looks good to me.

JAVA-4754

stIncMale · 2023-10-12T20:20:55Z

driver-core/src/main/com/mongodb/internal/logging/LogMessage.java

+            /**
+             * Not supported.
+             */
+            OPERATION("operation"),


The final decision on whether to support operation and to what extent will be done in https://jira.mongodb.org/browse/JAVA-5197.

…/browse/JAVA-5189 JAVA-4754

vbabanin

Looks good! Just a couple of questions and suggestions. Additionally, could you please confirm if manual testing was performed for unstructured logging? 

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

driver-core/src/main/com/mongodb/internal/logging/StructuredLogger.java

driver-core/src/main/com/mongodb/internal/logging/LogMessage.java

JAVA-4754

stIncMale · 2023-10-21T05:04:40Z

Additionally, could you please confirm if manual testing was performed for unstructured logging?

Yes, I've just done that.

katcharov

Looking good, just a question.

We might run into rebasing issues with CSOT that would require an understanding of this task, even without refactoring, but I don't see a way around that.

katcharov · 2023-10-23T20:10:46Z

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


            long startTimeNanos = System.nanoTime();
            long curTimeNanos = startTimeNanos;
-            long maxWaitTimeNanos = getMaxWaitTimeNanos();
+            Long maxWaitTimeNanos = getMaxWaitTimeNanos();


Does this method and related code need to be refactored in order to accomplish the logging spec changes? Note that much of this has been refactored already in the CSOT branch. It seems that we only need to either add methods that log messages, or remove existing logs.

remainingTimeNanos has to be computed and logged, unless it's infinite. This required changing the code.

This PR also fixes a bug in the code that works with the timeout. See Add server selection log messages #1221 (comment) for the details.

Creating exceptions and logging them is related, which means that the line throwIfIncompatible(curDescription); needed to be changed.

Note that much of this has been refactored already in the CSOT branch.

I won't be surprised if merging this code from master with CSOT will effectively require reintroducing the spec changes in the selectServer methods (not from scratch, though, as the methods that create exceptions and the methods that log them and other messages don't need changes)

jyemin · 2023-10-31T21:23:18Z

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

-                    throw createTimeoutException(serverSelector, curDescription);
+                Long remainingTimeNanos = maxWaitTimeNanos == null ? null : maxWaitTimeNanos - (curTimeNanos - startTimeNanos);
+
+                if (remainingTimeNanos != null && remainingTimeNanos <= 0) {


The Javadoc says:

A value of 0 means that it will timeout immediately if no server is available. A negative value means to wait indefinitely.

The spec only says:

A serverSelectionTimeoutMS of zero MAY have special meaning in some drivers; zero's meaning is not defined in this spec, but all drivers SHOULD document the meaning of zero.

So this looks good to me.

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

JAVA-4754

jyemin

One optional change request.

jyemin · 2023-11-01T12:53:18Z

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

+                    // This hardcoded message guarantees that the `FAILURE` entry for `MongoTimeoutException` does not include
+                    // any information that is specified via other entries, e.g., `SELECTOR` and `TOPOLOGY_DESCRIPTION`.
+                    // The logging spec requires us to avoid such duplication of information.
+                    ? MongoTimeoutException.class.getName() + ": Timed out while waiting for a suitable server"


Including the class name seems unnecessary in this context. But if you have a good reason for it, I'm ok if it stays.

The other branch (failure.toString()) includes it, so I mimicked it for consistency.

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

stIncMale added 4 commits October 10, 2023 14:32

Add unified tests

14b3b1a

JAVA-4754

Add ServerSelectionLoggingTest, implement schema-1.14.json

cbf661a

JAVA-4754

Implement server selection logging

51c1220

JAVA-4754

Do fixes

f2dc65e

JAVA-4754

stIncMale self-assigned this Oct 11, 2023

stIncMale commented Oct 11, 2023

View reviewed changes

driver-core/src/main/com/mongodb/internal/logging/LogMessage.java Outdated Show resolved Hide resolved

stIncMale commented Oct 11, 2023

View reviewed changes

stIncMale added 2 commits October 11, 2023 14:38

Do fixes

b1292b9

JAVA-4754

Do fixes

f4a4013

JAVA-4754

stIncMale commented Oct 12, 2023

View reviewed changes

stIncMale marked this pull request as ready for review October 12, 2023 20:22

stIncMale requested review from katcharov and vbabanin October 12, 2023 20:22

Update locking to match the decision made in https://jira.mongodb.org…

ed34386

…/browse/JAVA-5189 JAVA-4754

vbabanin requested changes Oct 19, 2023

View reviewed changes

driver-core/src/main/com/mongodb/internal/connection/BaseCluster.java Show resolved Hide resolved

driver-core/src/main/com/mongodb/internal/logging/StructuredLogger.java Outdated Show resolved Hide resolved

vbabanin requested changes Oct 19, 2023

View reviewed changes

driver-core/src/main/com/mongodb/internal/logging/LogMessage.java Outdated Show resolved Hide resolved

Address review concerns

e09930f

JAVA-4754

stIncMale requested a review from vbabanin October 19, 2023 17:45

vbabanin approved these changes Oct 21, 2023

View reviewed changes

katcharov requested changes Oct 23, 2023

View reviewed changes

stIncMale requested a review from katcharov October 25, 2023 18:24

jyemin requested review from jyemin and removed request for katcharov October 27, 2023 13:03

jyemin requested changes Oct 31, 2023

View reviewed changes

Partially restore the MongoTimeoutException message

7998d1a

JAVA-4754

stIncMale requested a review from jyemin November 1, 2023 06:29

Fix BaseClusterSpecification

ef5cd3a

JAVA-4754

jyemin approved these changes Nov 1, 2023

View reviewed changes

stIncMale merged commit d375cd4 into mongodb:master Nov 1, 2023
56 checks passed

stIncMale deleted the JAVA-4754 branch November 1, 2023 16:11

stIncMale mentioned this pull request Nov 2, 2023

Make ServerSelectionLoggingTest pass when run against a load balanced cluster, or when using Unix domain socket #1243

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add server selection log messages #1221

Add server selection log messages #1221

stIncMale commented Oct 11, 2023 •

edited

stIncMale Oct 11, 2023

stIncMale Oct 11, 2023

stIncMale Oct 11, 2023

stIncMale Oct 11, 2023

stIncMale Oct 11, 2023

stIncMale Oct 11, 2023

jyemin Oct 31, 2023

stIncMale Oct 12, 2023

vbabanin left a comment

stIncMale commented Oct 21, 2023

katcharov left a comment

katcharov Oct 23, 2023 •

edited

stIncMale Oct 23, 2023 •

edited

stIncMale Oct 23, 2023 •

edited

jyemin Oct 31, 2023

jyemin left a comment

jyemin Nov 1, 2023

stIncMale Nov 1, 2023

		public void waitForServerDescriptionChangedEvents(
		final Predicate<ServerDescriptionChangedEvent> matcher, final int count, final Duration duration)

Add server selection log messages #1221

Add server selection log messages #1221

Conversation

stIncMale commented Oct 11, 2023 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

vbabanin left a comment

Choose a reason for hiding this comment

stIncMale commented Oct 21, 2023

katcharov left a comment

Choose a reason for hiding this comment

katcharov Oct 23, 2023 • edited

Choose a reason for hiding this comment

stIncMale Oct 23, 2023 • edited

Choose a reason for hiding this comment

stIncMale Oct 23, 2023 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jyemin left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

stIncMale commented Oct 11, 2023 •

edited

katcharov Oct 23, 2023 •

edited

stIncMale Oct 23, 2023 •

edited

stIncMale Oct 23, 2023 •

edited