Skip to content

Commit 0c73982

Browse files
rozzarozza
committed
Added logging specification tests
JAVA-4770
1 parent a20d204 commit 0c73982

File tree

12 files changed

+165
-25
lines changed

12 files changed

+165
-25
lines changed

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

Lines changed: 4 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -118,9 +118,9 @@ abstract class BaseCluster implements Cluster {
118118
this.clusterListener = singleClusterListener(settings);
119119
ClusterOpeningEvent clusterOpeningEvent = new ClusterOpeningEvent(clusterId);
120120
clusterListener.clusterOpening(clusterOpeningEvent);
121-
logTopologyOpening(clusterId, clusterOpeningEvent);
122121
description = new ClusterDescription(settings.getMode(), UNKNOWN, emptyList(),
123122
settings, serverFactory.getSettings());
123+
logTopologyOpening(clusterId);
124124
}
125125

126126
@Override
@@ -221,7 +221,7 @@ public void close() {
221221
description);
222222
ClusterClosedEvent clusterClosedEvent = new ClusterClosedEvent(clusterId);
223223
clusterListener.clusterClosed(clusterClosedEvent);
224-
logTopologyClosedEvent(clusterId, clusterClosedEvent);
224+
logTopologyClosedEvent(clusterId);
225225
stopWaitQueueHandler();
226226
}
227227
}
@@ -632,9 +632,7 @@ static void logServerSelectionSucceeded(
632632
}
633633
}
634634

635-
static void logTopologyOpening(
636-
final ClusterId clusterId,
637-
final ClusterOpeningEvent clusterOpeningEvent) {
635+
static void logTopologyOpening(final ClusterId clusterId) {
638636
if (STRUCTURED_LOGGER.isRequired(DEBUG, clusterId)) {
639637
STRUCTURED_LOGGER.log(new LogMessage(
640638
TOPOLOGY, DEBUG, "Starting topology monitoring", clusterId,
@@ -659,9 +657,7 @@ static void logTopologyDescriptionChanged(
659657
}
660658
}
661659

662-
static void logTopologyClosedEvent(
663-
final ClusterId clusterId,
664-
final ClusterClosedEvent clusterClosedEvent) {
660+
static void logTopologyClosedEvent(final ClusterId clusterId) {
665661
if (STRUCTURED_LOGGER.isRequired(DEBUG, clusterId)) {
666662
STRUCTURED_LOGGER.log(new LogMessage(
667663
TOPOLOGY, DEBUG, "Stopped topology monitoring", clusterId,

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

Lines changed: 18 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -17,10 +17,28 @@
1717
package com.mongodb.internal.connection;
1818

1919
import com.mongodb.MongoException;
20+
import com.mongodb.connection.ConnectionDescription;
21+
import com.mongodb.connection.ServerId;
22+
import com.mongodb.internal.logging.LogMessage;
23+
import com.mongodb.internal.logging.StructuredLogger;
24+
import org.bson.BsonDocument;
2025

2126
import java.util.List;
2227

28+
import static com.mongodb.internal.logging.LogMessage.Component.TOPOLOGY;
29+
import static com.mongodb.internal.logging.LogMessage.Entry.Name.AWAITED;
30+
import static com.mongodb.internal.logging.LogMessage.Entry.Name.DRIVER_CONNECTION_ID;
31+
import static com.mongodb.internal.logging.LogMessage.Entry.Name.DURATION_MS;
32+
import static com.mongodb.internal.logging.LogMessage.Entry.Name.FAILURE;
33+
import static com.mongodb.internal.logging.LogMessage.Entry.Name.REPLY;
34+
import static com.mongodb.internal.logging.LogMessage.Entry.Name.SERVER_CONNECTION_ID;
35+
import static com.mongodb.internal.logging.LogMessage.Entry.Name.SERVER_HOST;
36+
import static com.mongodb.internal.logging.LogMessage.Entry.Name.SERVER_PORT;
37+
import static com.mongodb.internal.logging.LogMessage.Entry.Name.TOPOLOGY_ID;
38+
import static com.mongodb.internal.logging.LogMessage.Level.DEBUG;
2339
import static java.util.Arrays.asList;
40+
import static java.util.concurrent.TimeUnit.MILLISECONDS;
41+
import static java.util.concurrent.TimeUnit.NANOSECONDS;
2442

2543
/**
2644
* A logical connection to a MongoDB server that supports clustering along with other servers.

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

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -31,6 +31,7 @@
3131
import com.mongodb.internal.connection.SdamServerDescriptionManager.SdamIssue;
3232
import com.mongodb.internal.diagnostics.logging.Logger;
3333
import com.mongodb.internal.diagnostics.logging.Loggers;
34+
import com.mongodb.internal.logging.StructuredLogger;
3435
import com.mongodb.internal.session.SessionContext;
3536
import com.mongodb.lang.Nullable;
3637
import org.bson.BsonDocument;
@@ -48,6 +49,7 @@
4849

4950
class DefaultServer implements ClusterableServer {
5051
private static final Logger LOGGER = Loggers.getLogger("connection");
52+
private static final StructuredLogger STRUCTURED_LOGGER = new StructuredLogger("connection");
5153
private final ServerId serverId;
5254
private final ConnectionPool connectionPool;
5355
private final ClusterConnectionMode clusterConnectionMode;
@@ -75,7 +77,6 @@ class DefaultServer implements ClusterableServer {
7577
this.connectionPool = notNull("connectionPool", connectionPool);
7678

7779
this.serverId = serverId;
78-
7980
serverListener.serverOpening(new ServerOpeningEvent(this.serverId));
8081

8182
this.serverMonitor = serverMonitor;

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

Lines changed: 116 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -22,6 +22,7 @@
2222
import com.mongodb.ServerApi;
2323
import com.mongodb.annotations.ThreadSafe;
2424
import com.mongodb.connection.ClusterConnectionMode;
25+
import com.mongodb.connection.ConnectionDescription;
2526
import com.mongodb.connection.ServerDescription;
2627
import com.mongodb.connection.ServerId;
2728
import com.mongodb.connection.ServerSettings;
@@ -34,6 +35,8 @@
3435
import com.mongodb.internal.diagnostics.logging.Logger;
3536
import com.mongodb.internal.diagnostics.logging.Loggers;
3637
import com.mongodb.internal.inject.Provider;
38+
import com.mongodb.internal.logging.LogMessage;
39+
import com.mongodb.internal.logging.StructuredLogger;
3740
import com.mongodb.internal.validator.NoOpFieldNameValidator;
3841
import com.mongodb.lang.Nullable;
3942
import org.bson.BsonBoolean;
@@ -63,14 +66,27 @@
6366
import static com.mongodb.internal.connection.DescriptionHelper.createServerDescription;
6467
import static com.mongodb.internal.connection.ServerDescriptionHelper.unknownConnectingServerDescription;
6568
import static com.mongodb.internal.event.EventListenerHelper.singleServerMonitorListener;
69+
import static com.mongodb.internal.logging.LogMessage.Component.TOPOLOGY;
70+
import static com.mongodb.internal.logging.LogMessage.Entry.Name.AWAITED;
71+
import static com.mongodb.internal.logging.LogMessage.Entry.Name.DRIVER_CONNECTION_ID;
72+
import static com.mongodb.internal.logging.LogMessage.Entry.Name.DURATION_MS;
73+
import static com.mongodb.internal.logging.LogMessage.Entry.Name.FAILURE;
74+
import static com.mongodb.internal.logging.LogMessage.Entry.Name.REPLY;
75+
import static com.mongodb.internal.logging.LogMessage.Entry.Name.SERVER_CONNECTION_ID;
76+
import static com.mongodb.internal.logging.LogMessage.Entry.Name.SERVER_HOST;
77+
import static com.mongodb.internal.logging.LogMessage.Entry.Name.SERVER_PORT;
78+
import static com.mongodb.internal.logging.LogMessage.Entry.Name.TOPOLOGY_ID;
79+
import static com.mongodb.internal.logging.LogMessage.Level.DEBUG;
6680
import static java.lang.String.format;
81+
import static java.util.Arrays.asList;
6782
import static java.util.concurrent.TimeUnit.MILLISECONDS;
6883
import static java.util.concurrent.TimeUnit.NANOSECONDS;
6984

7085
@ThreadSafe
7186
class DefaultServerMonitor implements ServerMonitor {
7287

7388
private static final Logger LOGGER = Loggers.getLogger("cluster");
89+
private static final StructuredLogger STRUCTURED_LOGGER = new StructuredLogger("cluster");
7490

7591
private final ServerId serverId;
7692
private final ServerMonitorListener serverMonitorListener;
@@ -116,6 +132,7 @@ class DefaultServerMonitor implements ServerMonitor {
116132

117133
@Override
118134
public void start() {
135+
logStartedServerMonitoring(serverId);
119136
monitor.start();
120137
}
121138

@@ -137,6 +154,9 @@ public void connect() {
137154
@SuppressWarnings("try")
138155
public void close() {
139156
withLock(lock, () -> {
157+
if (!isClosed) {
158+
logStoppedServerMonitoring(serverId);
159+
}
140160
isClosed = true;
141161
//noinspection EmptyTryBlock
142162
try (ServerMonitor ignoredAutoClosed = monitor;
@@ -226,6 +246,7 @@ private ServerDescription lookupServerDescription(final ServerDescription curren
226246
alreadyLoggedHeartBeatStarted = true;
227247
currentCheckCancelled = false;
228248
InternalConnection newConnection = internalConnectionFactory.create(serverId);
249+
logHeartbeatStarted(serverId, newConnection.getDescription(), shouldStreamResponses);
229250
serverMonitorListener.serverHearbeatStarted(new ServerHeartbeatStartedEvent(
230251
newConnection.getDescription().getConnectionId(), shouldStreamResponses));
231252
newConnection.open(operationContextFactory.create());
@@ -238,6 +259,7 @@ private ServerDescription lookupServerDescription(final ServerDescription curren
238259
LOGGER.debug(format("Checking status of %s", serverId.getAddress()));
239260
}
240261
if (!alreadyLoggedHeartBeatStarted) {
262+
logHeartbeatStarted(serverId, connection.getDescription(), shouldStreamResponses);
241263
serverMonitorListener.serverHearbeatStarted(new ServerHeartbeatStartedEvent(
242264
connection.getDescription().getConnectionId(), shouldStreamResponses));
243265
}
@@ -269,15 +291,18 @@ private ServerDescription lookupServerDescription(final ServerDescription curren
269291
if (!shouldStreamResponses) {
270292
roundTripTimeSampler.addSample(elapsedTimeNanos);
271293
}
294+
logHeartbeatSucceeded(serverId, connection.getDescription(), shouldStreamResponses, elapsedTimeNanos, helloResult);
272295
serverMonitorListener.serverHeartbeatSucceeded(
273296
new ServerHeartbeatSucceededEvent(connection.getDescription().getConnectionId(), helloResult,
274297
elapsedTimeNanos, shouldStreamResponses));
275298

276299
return createServerDescription(serverId.getAddress(), helloResult, roundTripTimeSampler.getAverage(),
277300
roundTripTimeSampler.getMin());
278301
} catch (Exception e) {
302+
long elapsedTimeNanos = System.nanoTime() - start;
303+
logHeartbeatFailed(serverId, connection.getDescription(), shouldStreamResponses, elapsedTimeNanos, e);
279304
serverMonitorListener.serverHeartbeatFailed(
280-
new ServerHeartbeatFailedEvent(connection.getDescription().getConnectionId(), System.nanoTime() - start,
305+
new ServerHeartbeatFailedEvent(connection.getDescription().getConnectionId(), elapsedTimeNanos,
281306
shouldStreamResponses, e));
282307
throw e;
283308
}
@@ -515,4 +540,94 @@ private void waitForNext() throws InterruptedException {
515540
private String getHandshakeCommandName(final ServerDescription serverDescription) {
516541
return serverDescription.isHelloOk() ? HELLO : LEGACY_HELLO;
517542
}
543+
544+
private static void logHeartbeatStarted(
545+
final ServerId serverId,
546+
final ConnectionDescription connectionDescription,
547+
final boolean awaited) {
548+
if (STRUCTURED_LOGGER.isRequired(DEBUG, serverId.getClusterId())) {
549+
STRUCTURED_LOGGER.log(new LogMessage(
550+
TOPOLOGY, DEBUG, "Server heartbeat started", serverId.getClusterId(),
551+
asList(
552+
new LogMessage.Entry(SERVER_HOST, serverId.getAddress().getHost()),
553+
new LogMessage.Entry(SERVER_PORT, serverId.getAddress().getPort()),
554+
new LogMessage.Entry(DRIVER_CONNECTION_ID, connectionDescription.getConnectionId().getLocalValue()),
555+
new LogMessage.Entry(SERVER_CONNECTION_ID, connectionDescription.getConnectionId().getServerValue()),
556+
new LogMessage.Entry(TOPOLOGY_ID, serverId.getClusterId()),
557+
new LogMessage.Entry(AWAITED, awaited)),
558+
"Heartbeat started for {}:{} on connection with driver-generated ID {} and server-generated ID {} "
559+
+ "in topology with ID {}. Awaited: {}"));
560+
}
561+
}
562+
563+
private static void logHeartbeatSucceeded(
564+
final ServerId serverId,
565+
final ConnectionDescription connectionDescription,
566+
final boolean awaited,
567+
final long elapsedTimeNanos,
568+
final BsonDocument reply) {
569+
if (STRUCTURED_LOGGER.isRequired(DEBUG, serverId.getClusterId())) {
570+
STRUCTURED_LOGGER.log(new LogMessage(
571+
TOPOLOGY, DEBUG, "Server heartbeat succeeded", serverId.getClusterId(),
572+
asList(
573+
new LogMessage.Entry(DURATION_MS, MILLISECONDS.convert(elapsedTimeNanos, NANOSECONDS)),
574+
new LogMessage.Entry(SERVER_HOST, serverId.getAddress().getHost()),
575+
new LogMessage.Entry(SERVER_PORT, serverId.getAddress().getPort()),
576+
new LogMessage.Entry(DRIVER_CONNECTION_ID, connectionDescription.getConnectionId().getLocalValue()),
577+
new LogMessage.Entry(SERVER_CONNECTION_ID, connectionDescription.getConnectionId().getServerValue()),
578+
new LogMessage.Entry(TOPOLOGY_ID, serverId.getClusterId()),
579+
new LogMessage.Entry(AWAITED, awaited),
580+
new LogMessage.Entry(REPLY, reply.toJson())),
581+
"Heartbeat succeeded in {} ms for {}:{} on connection with driver-generated ID {} and server-generated ID {} "
582+
+ "in topology with ID {}. Awaited: {}. Reply: {}"));
583+
}
584+
}
585+
586+
private static void logHeartbeatFailed(
587+
final ServerId serverId,
588+
final ConnectionDescription connectionDescription,
589+
final boolean awaited,
590+
final long elapsedTimeNanos,
591+
final Exception failure) {
592+
if (STRUCTURED_LOGGER.isRequired(DEBUG, serverId.getClusterId())) {
593+
STRUCTURED_LOGGER.log(new LogMessage(
594+
TOPOLOGY, DEBUG, "Server heartbeat failed", serverId.getClusterId(),
595+
asList(
596+
new LogMessage.Entry(DURATION_MS, MILLISECONDS.convert(elapsedTimeNanos, NANOSECONDS)),
597+
new LogMessage.Entry(SERVER_HOST, serverId.getAddress().getHost()),
598+
new LogMessage.Entry(SERVER_PORT, serverId.getAddress().getPort()),
599+
new LogMessage.Entry(DRIVER_CONNECTION_ID, connectionDescription.getConnectionId().getLocalValue()),
600+
new LogMessage.Entry(SERVER_CONNECTION_ID, connectionDescription.getConnectionId().getServerValue()),
601+
new LogMessage.Entry(TOPOLOGY_ID, serverId.getClusterId()),
602+
new LogMessage.Entry(AWAITED, awaited),
603+
new LogMessage.Entry(FAILURE, failure.getMessage())),
604+
"Heartbeat failed in {} ms for {}:{} on connection with driver-generated ID {} and server-generated ID {} "
605+
+ "in topology with ID {}. Awaited: {}. Failure: {}"));
606+
}
607+
}
608+
609+
610+
private static void logStartedServerMonitoring(final ServerId serverId) {
611+
if (STRUCTURED_LOGGER.isRequired(DEBUG, serverId.getClusterId())) {
612+
STRUCTURED_LOGGER.log(new LogMessage(
613+
TOPOLOGY, DEBUG, "Starting server monitoring", serverId.getClusterId(),
614+
asList(
615+
new LogMessage.Entry(SERVER_HOST, serverId.getAddress().getHost()),
616+
new LogMessage.Entry(SERVER_PORT, serverId.getAddress().getPort()),
617+
new LogMessage.Entry(TOPOLOGY_ID, serverId.getClusterId())),
618+
"Starting monitoring for server {}:{} in topology with ID {}"));
619+
}
620+
}
621+
622+
private static void logStoppedServerMonitoring(final ServerId serverId) {
623+
if (STRUCTURED_LOGGER.isRequired(DEBUG, serverId.getClusterId())) {
624+
STRUCTURED_LOGGER.log(new LogMessage(
625+
TOPOLOGY, DEBUG, "Stopped server monitoring", serverId.getClusterId(),
626+
asList(
627+
new LogMessage.Entry(SERVER_HOST, serverId.getAddress().getHost()),
628+
new LogMessage.Entry(SERVER_PORT, serverId.getAddress().getPort()),
629+
new LogMessage.Entry(TOPOLOGY_ID, serverId.getClusterId())),
630+
"Stopped monitoring for server {}:{} in topology with ID {}"));
631+
}
632+
}
518633
}

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

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -275,7 +275,7 @@ public void close() {
275275
}
276276
ClusterClosedEvent clusterClosedEvent = new ClusterClosedEvent(clusterId);
277277
clusterListener.clusterClosed(clusterClosedEvent);
278-
logTopologyClosedEvent(clusterId, clusterClosedEvent);
278+
logTopologyClosedEvent(clusterId);
279279
}
280280
}
281281

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

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -58,9 +58,9 @@ public SingleServerCluster(final ClusterId clusterId, final ClusterSettings sett
5858
// synchronized in the constructor because the change listener is re-entrant to this instance.
5959
// In other words, we are leaking a reference to "this" from the constructor.
6060
withLock(() -> {
61-
server.set(createServer(settings.getHosts().get(0)));
6261
publishDescription(ServerDescription.builder().state(CONNECTING).address(settings.getHosts().get(0))
6362
.build());
63+
server.set(createServer(settings.getHosts().get(0)));
6464
});
6565
}
6666

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

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -108,6 +108,7 @@ public enum Name {
108108
* Not supported.
109109
*/
110110
OPERATION("operation"),
111+
AWAITED("awaited"),
111112
SERVICE_ID("serviceId"),
112113
SERVER_CONNECTION_ID("serverConnectionId"),
113114
DRIVER_CONNECTION_ID("driverConnectionId"),

‎driver-reactive-streams/src/test/functional/com/mongodb/reactivestreams/client/unified/UnifiedServerDiscoveryAndMonitoringTest.java

Lines changed: 0 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -17,7 +17,6 @@
1717
package com.mongodb.reactivestreams.client.unified;
1818

1919
import org.junit.jupiter.params.provider.Arguments;
20-
2120
import java.util.Collection;
2221

2322
final class UnifiedServerDiscoveryAndMonitoringTest extends UnifiedReactiveStreamsTest {

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

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -495,7 +495,7 @@ public String toString() {
495495
+ new BsonDocument("messages", expectedMessages).toJson(JsonWriterSettings.builder().indent(true).build()) + "\n"
496496
+ " actualMessages="
497497
+ new BsonDocument("messages", new BsonArray(actualMessages.stream()
498-
.map(LogMatcher::asDocument).collect(Collectors.toList())))
498+
.map(LogMatcher::logMessageAsDocument).collect(Collectors.toList())))
499499
.toJson(JsonWriterSettings.builder().indent(true).build()) + "\n";
500500
}
501501
}

0 commit comments

Comments
 (0)