Skip to content

Commit d375cd4

Browse files
stIncMalestIncMale
authored
Add server selection log messages (#1221)
JAVA-4754
1 parent 73d523c commit d375cd4

File tree

20 files changed

+1573
-146
lines changed

20 files changed

+1573
-146
lines changed

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

Lines changed: 158 additions & 58 deletions
Large diffs are not rendered by default.

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

Lines changed: 41 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -17,15 +17,20 @@
1717
package com.mongodb.internal.logging;
1818

1919
import com.mongodb.connection.ClusterId;
20+
import com.mongodb.internal.VisibleForTesting;
2021
import com.mongodb.lang.Nullable;
2122

2223
import java.util.Collection;
2324
import java.util.Iterator;
2425
import java.util.List;
26+
import java.util.Map;
2527
import java.util.NoSuchElementException;
2628
import java.util.stream.Collectors;
29+
import java.util.stream.Stream;
2730

2831
import static com.mongodb.assertions.Assertions.assertNotNull;
32+
import static com.mongodb.internal.VisibleForTesting.AccessModifier.PRIVATE;
33+
import static java.util.function.Function.identity;
2934

3035
/**
3136
* <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 {
4146
private final String format;
4247

4348
public enum Component {
44-
COMMAND,
45-
CONNECTION
49+
COMMAND("command"),
50+
CONNECTION("connection"),
51+
SERVER_SELECTION("serverSelection");
52+
53+
private static final Map<String, Component> INDEX;
54+
55+
static {
56+
INDEX = Stream.of(Component.values()).collect(Collectors.toMap(Component::getValue, identity()));
57+
}
58+
59+
private final String value;
60+
61+
Component(final String value) {
62+
this.value = value;
63+
}
64+
65+
@VisibleForTesting(otherwise = PRIVATE)
66+
public String getValue() {
67+
return value;
68+
}
69+
70+
@VisibleForTesting(otherwise = PRIVATE)
71+
public static Component of(final String value) {
72+
Component result = INDEX.get(value);
73+
return assertNotNull(result);
74+
}
4675
}
4776

4877
public enum Level {
78+
INFO,
4979
DEBUG
5080
}
5181

@@ -73,6 +103,10 @@ public enum Name {
73103
COMMAND_NAME("commandName"),
74104
REQUEST_ID("requestId"),
75105
OPERATION_ID("operationId"),
106+
/**
107+
* Not supported.
108+
*/
109+
OPERATION("operation"),
76110
SERVICE_ID("serviceId"),
77111
SERVER_CONNECTION_ID("serverConnectionId"),
78112
DRIVER_CONNECTION_ID("driverConnectionId"),
@@ -82,11 +116,15 @@ public enum Name {
82116
COMMAND_CONTENT("command"),
83117
REASON_DESCRIPTION("reason"),
84118
ERROR_DESCRIPTION("error"),
119+
FAILURE("failure"),
85120
MAX_IDLE_TIME_MS("maxIdleTimeMS"),
86121
MIN_POOL_SIZE("minPoolSize"),
87122
MAX_POOL_SIZE("maxPoolSize"),
88123
MAX_CONNECTING("maxConnecting"),
89-
WAIT_QUEUE_TIMEOUT_MS("waitQueueTimeoutMS");
124+
WAIT_QUEUE_TIMEOUT_MS("waitQueueTimeoutMS"),
125+
SELECTOR("selector"),
126+
TOPOLOGY_DESCRIPTION("topologyDescription"),
127+
REMAINING_TIME_MS("remainingTimeMS");
90128

91129
private final String value;
92130

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

Lines changed: 26 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -24,6 +24,9 @@
2424
import com.mongodb.lang.Nullable;
2525

2626
import java.util.concurrent.ConcurrentHashMap;
27+
import java.util.function.BiConsumer;
28+
import java.util.function.Consumer;
29+
import java.util.function.Supplier;
2730

2831
import static com.mongodb.internal.VisibleForTesting.AccessModifier.PRIVATE;
2932

@@ -68,10 +71,11 @@ public boolean isRequired(final Level level, final ClusterId clusterId) {
6871
return true;
6972
}
7073

71-
//noinspection SwitchStatementWithTooFewBranches
7274
switch (level) {
7375
case DEBUG:
7476
return logger.isDebugEnabled();
77+
case INFO:
78+
return logger.isInfoEnabled();
7579
default:
7680
throw new UnsupportedOperationException();
7781
}
@@ -82,22 +86,32 @@ public void log(final LogMessage logMessage) {
8286
if (interceptor != null) {
8387
interceptor.intercept(logMessage);
8488
}
85-
//noinspection SwitchStatementWithTooFewBranches
8689
switch (logMessage.getLevel()) {
8790
case DEBUG:
88-
if (logger.isDebugEnabled()) {
89-
LogMessage.UnstructuredLogMessage unstructuredLogMessage = logMessage.toUnstructuredLogMessage();
90-
String message = unstructuredLogMessage.interpolate();
91-
Throwable exception = logMessage.getException();
92-
if (exception == null) {
93-
logger.debug(message);
94-
} else {
95-
logger.debug(message, exception);
96-
}
97-
}
91+
logUnstructured(logMessage, logger::isDebugEnabled, logger::debug, logger::debug);
92+
break;
93+
case INFO:
94+
logUnstructured(logMessage, logger::isInfoEnabled, logger::info, logger::info);
9895
break;
9996
default:
10097
throw new UnsupportedOperationException();
10198
}
10299
}
100+
101+
private static void logUnstructured(
102+
final LogMessage logMessage,
103+
final Supplier<Boolean> loggingEnabled,
104+
final Consumer<String> doLog,
105+
final BiConsumer<String, Throwable> doLogWithException) {
106+
if (loggingEnabled.get()) {
107+
LogMessage.UnstructuredLogMessage unstructuredLogMessage = logMessage.toUnstructuredLogMessage();
108+
String message = unstructuredLogMessage.interpolate();
109+
Throwable exception = logMessage.getException();
110+
if (exception == null) {
111+
doLog.accept(message);
112+
} else {
113+
doLogWithException.accept(message, exception);
114+
}
115+
}
116+
}
103117
}

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

Lines changed: 28 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -19,6 +19,7 @@
1919
import com.mongodb.MongoException;
2020
import com.mongodb.ReadPreference;
2121
import com.mongodb.ServerApi;
22+
import com.mongodb.connection.ClusterDescription;
2223
import com.mongodb.connection.ServerDescription;
2324
import com.mongodb.internal.IgnorableRequestContext;
2425
import com.mongodb.internal.binding.StaticBindingContext;
@@ -29,6 +30,7 @@
2930
import com.mongodb.internal.selector.ReadPreferenceServerSelector;
3031
import com.mongodb.internal.validator.NoOpFieldNameValidator;
3132
import com.mongodb.lang.Nullable;
33+
import com.mongodb.selector.ServerSelector;
3234
import com.mongodb.session.ServerSession;
3335
import org.bson.BsonArray;
3436
import org.bson.BsonBinary;
@@ -114,24 +116,40 @@ private void endClosedSessions() {
114116
return;
115117
}
116118

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

123129
Connection connection = null;
124130
try {
125131
StaticBindingContext context = new StaticBindingContext(NoOpSessionContext.INSTANCE, serverApi,
126132
IgnorableRequestContext.INSTANCE, new OperationContext());
127-
connection = cluster.selectServer(clusterDescription -> {
128-
for (ServerDescription cur : clusterDescription.getServerDescriptions()) {
129-
if (cur.getAddress().equals(primaryPreferred.get(0).getAddress())) {
130-
return Collections.singletonList(cur);
131-
}
132-
}
133-
return Collections.emptyList();
134-
}, context.getOperationContext()).getServer().getConnection(context.getOperationContext());
133+
connection = cluster.selectServer(
134+
new ServerSelector() {
135+
@Override
136+
public List<ServerDescription> select(final ClusterDescription clusterDescription) {
137+
for (ServerDescription cur : clusterDescription.getServerDescriptions()) {
138+
if (cur.getAddress().equals(primaryPreferredServers.get(0).getAddress())) {
139+
return Collections.singletonList(cur);
140+
}
141+
}
142+
return Collections.emptyList();
143+
}
144+
145+
@Override
146+
public String toString() {
147+
return "ReadPreferenceServerSelector{"
148+
+ "readPreference=" + primaryPreferred
149+
+ '}';
150+
}
151+
},
152+
context.getOperationContext()).getServer().getConnection(context.getOperationContext());
135153

136154
connection.command("admin",
137155
new BsonDocument("endSessions", new BsonArray(identifiers)), new NoOpFieldNameValidator(),

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

Lines changed: 107 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,107 @@
1+
{
2+
"description": "server-selection-logging",
3+
"schemaVersion": "1.13",
4+
"runOnRequirements": [
5+
{
6+
"topologies": [
7+
"load-balanced"
8+
]
9+
}
10+
],
11+
"createEntities": [
12+
{
13+
"client": {
14+
"id": "client",
15+
"uriOptions": {
16+
"heartbeatFrequencyMS": 500
17+
},
18+
"observeLogMessages": {
19+
"serverSelection": "debug"
20+
},
21+
"observeEvents": [
22+
"serverDescriptionChangedEvent"
23+
]
24+
}
25+
},
26+
{
27+
"database": {
28+
"id": "database",
29+
"client": "client",
30+
"databaseName": "logging-tests"
31+
}
32+
},
33+
{
34+
"collection": {
35+
"id": "collection",
36+
"database": "database",
37+
"collectionName": "server-selection"
38+
}
39+
}
40+
],
41+
"tests": [
42+
{
43+
"description": "A successful operation - load balanced cluster",
44+
"operations": [
45+
{
46+
"name": "waitForEvent",
47+
"object": "testRunner",
48+
"arguments": {
49+
"client": "client",
50+
"event": {
51+
"serverDescriptionChangedEvent": {
52+
"newDescription": {
53+
"type": "LoadBalancer"
54+
}
55+
}
56+
},
57+
"count": 1
58+
}
59+
},
60+
{
61+
"name": "insertOne",
62+
"object": "collection",
63+
"arguments": {
64+
"document": {
65+
"x": 1
66+
}
67+
}
68+
}
69+
],
70+
"expectLogMessages": [
71+
{
72+
"client": "client",
73+
"messages": [
74+
{
75+
"level": "debug",
76+
"component": "serverSelection",
77+
"data": {
78+
"message": "Server selection started",
79+
"selector": {
80+
"$$exists": true
81+
},
82+
"operation": "insert",
83+
"topologyDescription": {
84+
"$$exists": true
85+
}
86+
}
87+
},
88+
{
89+
"level": "debug",
90+
"component": "serverSelection",
91+
"data": {
92+
"message": "Server selection succeeded",
93+
"selector": {
94+
"$$exists": true
95+
},
96+
"operation": "insert",
97+
"topologyDescription": {
98+
"$$exists": true
99+
}
100+
}
101+
}
102+
]
103+
}
104+
]
105+
}
106+
]
107+
}

0 commit comments

Comments
 (0)