Add server selection log messages (#1221)

JAVA-4754

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

@@ -17,15 +17,20 @@
 package com.mongodb.internal.logging;
 
 import com.mongodb.connection.ClusterId;
+import com.mongodb.internal.VisibleForTesting;
 import com.mongodb.lang.Nullable;
 
 import java.util.Collection;
 import java.util.Iterator;
 import java.util.List;
+import java.util.Map;
 import java.util.NoSuchElementException;
 import java.util.stream.Collectors;
+import java.util.stream.Stream;
 
 import static com.mongodb.assertions.Assertions.assertNotNull;
+import static com.mongodb.internal.VisibleForTesting.AccessModifier.PRIVATE;
+import static java.util.function.Function.identity;
 
 /**
  * <p>This class is not part of the public API and may be removed or changed at any time</p>
@@ -41,11 +46,36 @@ public final class LogMessage {
     private final String format;
 
     public enum Component {
-        COMMAND,
-        CONNECTION
+        COMMAND("command"),
+        CONNECTION("connection"),
+        SERVER_SELECTION("serverSelection");
+
+        private static final Map<String, Component> INDEX;
+
+        static {
+            INDEX = Stream.of(Component.values()).collect(Collectors.toMap(Component::getValue, identity()));
+        }
+
+        private final String value;
+
+        Component(final String value) {
+            this.value = value;
+        }
+
+        @VisibleForTesting(otherwise = PRIVATE)
+        public String getValue() {
+            return value;
+        }
+
+        @VisibleForTesting(otherwise = PRIVATE)
+        public static Component of(final String value) {
+            Component result = INDEX.get(value);
+            return assertNotNull(result);
+        }
     }
 
     public enum Level {
+        INFO,
         DEBUG
     }
 
@@ -73,6 +103,10 @@ public enum Name {
             COMMAND_NAME("commandName"),
             REQUEST_ID("requestId"),
             OPERATION_ID("operationId"),
+            /**
+             * Not supported.
+             */
+            OPERATION("operation"),
             SERVICE_ID("serviceId"),
             SERVER_CONNECTION_ID("serverConnectionId"),
             DRIVER_CONNECTION_ID("driverConnectionId"),
@@ -82,11 +116,15 @@ public enum Name {
             COMMAND_CONTENT("command"),
             REASON_DESCRIPTION("reason"),
             ERROR_DESCRIPTION("error"),
+            FAILURE("failure"),
             MAX_IDLE_TIME_MS("maxIdleTimeMS"),
             MIN_POOL_SIZE("minPoolSize"),
             MAX_POOL_SIZE("maxPoolSize"),
             MAX_CONNECTING("maxConnecting"),
-            WAIT_QUEUE_TIMEOUT_MS("waitQueueTimeoutMS");
+            WAIT_QUEUE_TIMEOUT_MS("waitQueueTimeoutMS"),
+            SELECTOR("selector"),
+            TOPOLOGY_DESCRIPTION("topologyDescription"),
+            REMAINING_TIME_MS("remainingTimeMS");
 
             private final String value;
 

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

@@ -24,6 +24,9 @@
 import com.mongodb.lang.Nullable;
 
 import java.util.concurrent.ConcurrentHashMap;
+import java.util.function.BiConsumer;
+import java.util.function.Consumer;
+import java.util.function.Supplier;
 
 import static com.mongodb.internal.VisibleForTesting.AccessModifier.PRIVATE;
 
@@ -68,10 +71,11 @@ public boolean isRequired(final Level level, final ClusterId clusterId) {
             return true;
         }
 
-        //noinspection SwitchStatementWithTooFewBranches
         switch (level) {
             case DEBUG:
                 return logger.isDebugEnabled();
+            case INFO:
+                return logger.isInfoEnabled();
             default:
                 throw new UnsupportedOperationException();
         }
@@ -82,22 +86,32 @@ public void log(final LogMessage logMessage) {
         if (interceptor != null) {
             interceptor.intercept(logMessage);
         }
-        //noinspection SwitchStatementWithTooFewBranches
         switch (logMessage.getLevel()) {
             case DEBUG:
-                if (logger.isDebugEnabled()) {
-                    LogMessage.UnstructuredLogMessage unstructuredLogMessage = logMessage.toUnstructuredLogMessage();
-                    String message = unstructuredLogMessage.interpolate();
-                    Throwable exception = logMessage.getException();
-                    if (exception == null) {
-                        logger.debug(message);
-                    } else {
-                        logger.debug(message, exception);
-                    }
-                }
+                logUnstructured(logMessage, logger::isDebugEnabled, logger::debug, logger::debug);
+                break;
+            case INFO:
+                logUnstructured(logMessage, logger::isInfoEnabled, logger::info, logger::info);
                 break;
             default:
                 throw new UnsupportedOperationException();
         }
     }
+
+    private static void logUnstructured(
+            final LogMessage logMessage,
+            final Supplier<Boolean> loggingEnabled,
+            final Consumer<String> doLog,
+            final BiConsumer<String, Throwable> doLogWithException) {
+        if (loggingEnabled.get()) {
+            LogMessage.UnstructuredLogMessage unstructuredLogMessage = logMessage.toUnstructuredLogMessage();
+            String message = unstructuredLogMessage.interpolate();
+            Throwable exception = logMessage.getException();
+            if (exception == null) {
+                doLog.accept(message);
+            } else {
+                doLogWithException.accept(message, exception);
+            }
+        }
+    }
 }

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

@@ -19,6 +19,7 @@
 import com.mongodb.MongoException;
 import com.mongodb.ReadPreference;
 import com.mongodb.ServerApi;
+import com.mongodb.connection.ClusterDescription;
 import com.mongodb.connection.ServerDescription;
 import com.mongodb.internal.IgnorableRequestContext;
 import com.mongodb.internal.binding.StaticBindingContext;
@@ -29,6 +30,7 @@
 import com.mongodb.internal.selector.ReadPreferenceServerSelector;
 import com.mongodb.internal.validator.NoOpFieldNameValidator;
 import com.mongodb.lang.Nullable;
+import com.mongodb.selector.ServerSelector;
 import com.mongodb.session.ServerSession;
 import org.bson.BsonArray;
 import org.bson.BsonBinary;
@@ -114,24 +116,40 @@ private void endClosedSessions() {
             return;
         }
 
-        List<ServerDescription> primaryPreferred = new ReadPreferenceServerSelector(ReadPreference.primaryPreferred())
+        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());
 
             connection.command("admin",
                     new BsonDocument("endSessions", new BsonArray(identifiers)), new NoOpFieldNameValidator(),

driver-core/src/test/resources/unified-test-format/server-selection/logging/load-balanced.json

@@ -0,0 +1,107 @@
+{
+  "description": "server-selection-logging",
+  "schemaVersion": "1.13",
+  "runOnRequirements": [
+    {
+      "topologies": [
+        "load-balanced"
+      ]
+    }
+  ],
+  "createEntities": [
+    {
+      "client": {
+        "id": "client",
+        "uriOptions": {
+          "heartbeatFrequencyMS": 500
+        },
+        "observeLogMessages": {
+          "serverSelection": "debug"
+        },
+        "observeEvents": [
+          "serverDescriptionChangedEvent"
+        ]
+      }
+    },
+    {
+      "database": {
+        "id": "database",
+        "client": "client",
+        "databaseName": "logging-tests"
+      }
+    },
+    {
+      "collection": {
+        "id": "collection",
+        "database": "database",
+        "collectionName": "server-selection"
+      }
+    }
+  ],
+  "tests": [
+    {
+      "description": "A successful operation - load balanced cluster",
+      "operations": [
+        {
+          "name": "waitForEvent",
+          "object": "testRunner",
+          "arguments": {
+            "client": "client",
+            "event": {
+              "serverDescriptionChangedEvent": {
+                "newDescription": {
+                  "type": "LoadBalancer"
+                }
+              }
+            },
+            "count": 1
+          }
+        },
+        {
+          "name": "insertOne",
+          "object": "collection",
+          "arguments": {
+            "document": {
+              "x": 1
+            }
+          }
+        }
+      ],
+      "expectLogMessages": [
+        {
+          "client": "client",
+          "messages": [
+            {
+              "level": "debug",
+              "component": "serverSelection",
+              "data": {
+                "message": "Server selection started",
+                "selector": {
+                  "$$exists": true
+                },
+                "operation": "insert",
+                "topologyDescription": {
+                  "$$exists": true
+                }
+              }
+            },
+            {
+              "level": "debug",
+              "component": "serverSelection",
+              "data": {
+                "message": "Server selection succeeded",
+                "selector": {
+                  "$$exists": true
+                },
+                "operation": "insert",
+                "topologyDescription": {
+                  "$$exists": true
+                }
+              }
+            }
+          ]
+        }
+      ]
+    }
+  ]
+}