Add server selection log messages

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

@@ -22,10 +22,13 @@
 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 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 +44,34 @@ 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;
+ }
+
+ public String getValue() {
+ return value;
+ }
+
+ public static Component of(final String value) {
+ Component result = INDEX.get(value);
+ return assertNotNull(result);
+ }
  }
 
  public enum Level {
+ INFO,
  DEBUG
  }
 
@@ -73,6 +99,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 +112,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,8 @@
 import com.mongodb.lang.Nullable;
 
 import java.util.concurrent.ConcurrentHashMap;
+import java.util.function.BiConsumer;
+import java.util.function.Predicate;
 
 import static com.mongodb.internal.VisibleForTesting.AccessModifier.PRIVATE;
 
@@ -68,10 +70,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 +85,37 @@ 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 void logUnstructured(
+ final LogMessage logMessage,
+ final Predicate<Logger> loggingEnabled,
+ final BiConsumer<Logger, String> doLog,
+ final TriConsumer<Logger, String, Throwable> doLogWithException) {
+ if (loggingEnabled.test(logger)) {
+ LogMessage.UnstructuredLogMessage unstructuredLogMessage = logMessage.toUnstructuredLogMessage();
+ String message = unstructuredLogMessage.interpolate();
+ Throwable exception = logMessage.getException();
+ if (exception == null) {
+ doLog.accept(logger, message);
+ } else {
+ doLogWithException.accept(logger, message, exception);
+ }
+ }
+ }
+
+ @FunctionalInterface
+ private interface TriConsumer<A, B, C> {
+ void accept(A a, B b, C c);
+ }
 }

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
+ }
+ }
+ }
+ ]
+ }
+ ]
+ }
+ ]
+}