Skip to content

Commit 14dd356

Browse files
vbabaninvbabanin
authored
Add structured log messages to CMAP. (#1114)
- Update LoggingInterceptor to accept LogMessage instances, enabling it to capture both structured and unstructured log messages during testing. 
- Introduce interpolation functionality for unstructured logging to enhance readability of log statements by enabling the dynamic replacement of placeholders with actual values. - Add LogMessage abstraction to preserve null values for conditional message interpolation.

1 parent 64c030f commit 14dd356

File tree

53 files changed

+2046
-325
lines changed

Some content is hidden

Large Commits have some content hidden by default. Use the searchbox below for content that may be hidden.

53 files changed

+2046
-325
lines changed

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

Lines changed: 140 additions & 71 deletions
Large diffs are not rendered by default.

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

Lines changed: 2 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -86,8 +86,7 @@
8686
import static com.mongodb.internal.connection.ProtocolHelper.getRecoveryToken;
8787
import static com.mongodb.internal.connection.ProtocolHelper.getSnapshotTimestamp;
8888
import static com.mongodb.internal.connection.ProtocolHelper.isCommandOk;
89-
import static com.mongodb.internal.logging.StructuredLogMessage.Level.DEBUG;
90-
import static java.lang.String.format;
89+
import static com.mongodb.internal.logging.LogMessage.Level.DEBUG;
9190
import static java.util.Arrays.asList;
9291

9392
/**
@@ -289,9 +288,6 @@ private void initAfterHandshakeFinish(final InternalConnectionInitializationDesc
289288
initialServerDescription = initializationDescription.getServerDescription();
290289
opened.set(true);
291290
sendCompressor = findSendCompressor(description);
292-
if (LOGGER.isDebugEnabled()) {
293-
LOGGER.debug(format("Opened connection [%s] to %s", getId(), serverId.getAddress()));
294-
}
295291
}
296292

297293
private Map<Byte, Compressor> createCompressorMap(final List<MongoCompressor> compressorList) {
@@ -337,13 +333,8 @@ private Compressor createCompressor(final MongoCompressor mongoCompressor) {
337333
@Override
338334
public void close() {
339335
// All but the first call is a no-op
340-
if (!isClosed.getAndSet(true)) {
341-
if (LOGGER.isDebugEnabled()) {
342-
LOGGER.debug(format("Closing connection %s", getId()));
343-
}
344-
if (stream != null) {
336+
if (!isClosed.getAndSet(true) && (stream != null)) {
345337
stream.close();
346-
}
347338
}
348339
}
349340

@@ -655,9 +646,6 @@ public void receiveMessageAsync(final int responseTo, final SingleResultCallback
655646
return;
656647
}
657648

658-
if (LOGGER.isTraceEnabled()) {
659-
LOGGER.trace(format("Start receiving response on %s", getId()));
660-
}
661649
readAsync(MESSAGE_HEADER_LENGTH, new MessageHeaderCallback((result, t) -> {
662650
if (t != null) {
663651
close();

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

Lines changed: 68 additions & 59 deletions
Original file line numberDiff line numberDiff line change
@@ -22,8 +22,8 @@
2222
import com.mongodb.connection.ClusterId;
2323
import com.mongodb.connection.ConnectionDescription;
2424
import com.mongodb.event.CommandListener;
25-
import com.mongodb.internal.logging.StructuredLogMessage;
26-
import com.mongodb.internal.logging.StructuredLogMessage.Entry;
25+
import com.mongodb.internal.logging.LogMessage;
26+
import com.mongodb.internal.logging.LogMessage.Entry;
2727
import com.mongodb.internal.logging.StructuredLogger;
2828
import com.mongodb.lang.Nullable;
2929
import org.bson.BsonDocument;
@@ -33,25 +33,38 @@
3333
import org.bson.json.JsonMode;
3434
import org.bson.json.JsonWriter;
3535
import org.bson.json.JsonWriterSettings;
36-
import org.bson.types.ObjectId;
3736

3837
import java.io.StringWriter;
38+
3939
import java.util.ArrayList;
4040
import java.util.List;
4141
import java.util.Set;
42+
import java.util.function.Consumer;
4243

4344
import static com.mongodb.assertions.Assertions.assertNotNull;
4445
import static com.mongodb.internal.connection.ProtocolHelper.sendCommandFailedEvent;
4546
import static com.mongodb.internal.connection.ProtocolHelper.sendCommandStartedEvent;
4647
import static com.mongodb.internal.connection.ProtocolHelper.sendCommandSucceededEvent;
47-
import static com.mongodb.internal.logging.StructuredLogMessage.Component.COMMAND;
48-
import static com.mongodb.internal.logging.StructuredLogMessage.Level.DEBUG;
48+
import static com.mongodb.internal.logging.LogMessage.Component.COMMAND;
49+
import static com.mongodb.internal.logging.LogMessage.Entry.Name.COMMAND_CONTENT;
50+
import static com.mongodb.internal.logging.LogMessage.Entry.Name.COMMAND_NAME;
51+
import static com.mongodb.internal.logging.LogMessage.Entry.Name.DATABASE_NAME;
52+
import static com.mongodb.internal.logging.LogMessage.Entry.Name.DRIVER_CONNECTION_ID;
53+
import static com.mongodb.internal.logging.LogMessage.Entry.Name.DURATION_MS;
54+
import static com.mongodb.internal.logging.LogMessage.Entry.Name.OPERATION_ID;
55+
import static com.mongodb.internal.logging.LogMessage.Entry.Name.REPLY;
56+
import static com.mongodb.internal.logging.LogMessage.Entry.Name.REQUEST_ID;
57+
import static com.mongodb.internal.logging.LogMessage.Entry.Name.SERVER_CONNECTION_ID;
58+
import static com.mongodb.internal.logging.LogMessage.Entry.Name.SERVER_HOST;
59+
import static com.mongodb.internal.logging.LogMessage.Entry.Name.SERVER_PORT;
60+
import static com.mongodb.internal.logging.LogMessage.Entry.Name.SERVICE_ID;
61+
import static com.mongodb.internal.logging.LogMessage.Level.DEBUG;
4962

5063
class LoggingCommandEventSender implements CommandEventSender {
5164
private static final double NANOS_PER_MILLI = 1_000_000.0d;
52-
5365
private final ConnectionDescription description;
54-
@Nullable private final CommandListener commandListener;
66+
@Nullable
67+
private final CommandListener commandListener;
5568
private final RequestContext requestContext;
5669
private final OperationContext operationContext;
5770
private final StructuredLogger logger;
@@ -84,17 +97,14 @@ class LoggingCommandEventSender implements CommandEventSender {
8497
@Override
8598
public void sendStartedEvent() {
8699
if (loggingRequired()) {
87-
List<Entry> entries = new ArrayList<>();
88-
StringBuilder builder = new StringBuilder("Command \"%s\" started on database %s");
89-
entries.add(new Entry("commandName", commandName));
90-
entries.add(new Entry("databaseName", message.getNamespace().getDatabaseName()));
91-
92-
appendCommonLogFragment(entries, builder);
93-
94-
builder.append(" Command: %s");
95-
entries.add(new Entry("command", redactionRequired ? "{}" : getTruncatedJsonCommand(commandDocument)));
96-
97-
logger.log(new StructuredLogMessage(COMMAND, DEBUG, "Command started", getClusterId(), entries), builder.toString());
100+
String messagePrefix = "Command \"{}\" started on database {}";
101+
String command = redactionRequired ? "{}" : getTruncatedJsonCommand(commandDocument);
102+
103+
logEventMessage(messagePrefix, "Command started", null, entries -> {
104+
entries.add(new Entry(COMMAND_NAME, commandName));
105+
entries.add(new Entry(DATABASE_NAME, message.getNamespace().getDatabaseName()));
106+
},
107+
entries -> entries.add(new Entry(COMMAND_CONTENT, command)));
98108
}
99109

100110
if (eventRequired()) {
@@ -121,15 +131,14 @@ public void sendFailedEvent(final Throwable t) {
121131
long elapsedTimeNanos = System.nanoTime() - startTimeNanos;
122132

123133
if (loggingRequired()) {
124-
List<Entry> entries = new ArrayList<>();
125-
StringBuilder builder = new StringBuilder("Command \"%s\" failed in %.2f ms");
126-
entries.add(new Entry("commandName", commandName));
127-
entries.add(new Entry("durationMS", elapsedTimeNanos / NANOS_PER_MILLI));
128-
129-
appendCommonLogFragment(entries, builder);
130-
131-
logger.log(new StructuredLogMessage(COMMAND, DEBUG, "Command failed", getClusterId(), commandEventException, entries),
132-
builder.toString());
134+
String messagePrefix = "Command \"{}\" failed in {} ms";
135+
136+
logEventMessage(messagePrefix, "Command failed", commandEventException,
137+
entries -> {
138+
entries.add(new Entry(COMMAND_NAME, commandName));
139+
entries.add(new Entry(DURATION_MS, elapsedTimeNanos / NANOS_PER_MILLI));
140+
},
141+
entries -> entries.add(new Entry(COMMAND_CONTENT, null)));
133142
}
134143

135144
if (eventRequired()) {
@@ -152,20 +161,19 @@ private void sendSucceededEvent(final BsonDocument reply) {
152161
long elapsedTimeNanos = System.nanoTime() - startTimeNanos;
153162

154163
if (loggingRequired()) {
155-
List<Entry> entries = new ArrayList<>();
156-
StringBuilder builder = new StringBuilder("Command \"%s\" succeeded in %.2f ms");
157-
entries.add(new Entry("commandName", commandName));
158-
entries.add(new Entry("durationMS", elapsedTimeNanos / NANOS_PER_MILLI));
164+
String format = "Command \"{}\" succeeded in {} ms using a connection with driver-generated ID {}"
165+
+ "[ and server-generated ID {}] to {}:{}[ with service ID {}]. The request ID is {}"
166+
+ " and the operation ID is {}. Command reply: {}";
159167

160-
appendCommonLogFragment(entries, builder);
161-
162-
builder.append(" Command reply: %s");
163168
BsonDocument responseDocumentForEvent = redactionRequired ? new BsonDocument() : reply;
164169
String replyString = redactionRequired ? "{}" : getTruncatedJsonCommand(responseDocumentForEvent);
165-
entries.add(new Entry("reply", replyString));
166170

167-
logger.log(new StructuredLogMessage(COMMAND, DEBUG, "Command succeeded", getClusterId(), entries),
168-
builder.toString());
171+
logEventMessage("Command succeeded", null,
172+
entries -> {
173+
entries.add(new Entry(COMMAND_NAME, commandName));
174+
entries.add(new Entry(DURATION_MS, elapsedTimeNanos / NANOS_PER_MILLI));
175+
},
176+
entries -> entries.add(new Entry(REPLY, replyString)), format);
169177
}
170178

171179
if (eventRequired()) {
@@ -188,29 +196,30 @@ private boolean eventRequired() {
188196
return commandListener != null;
189197
}
190198

191-
private void appendCommonLogFragment(final List<Entry> entries, final StringBuilder builder) {
192-
builder.append(" using a connection with driver-generated ID %d");
193-
entries.add(new Entry("driverConnectionId", description.getConnectionId().getLocalValue()));
194-
195-
Integer connectionServerValue = description.getConnectionId().getServerValue();
196-
if (connectionServerValue != null) {
197-
builder.append(" and server-generated ID %d");
198-
entries.add(new Entry("serverConnectionId", connectionServerValue));
199-
}
200-
201-
builder.append(" to %s:%s");
202-
entries.add(new Entry("serverHost", description.getServerAddress().getHost()));
203-
entries.add(new Entry("serverPort", description.getServerAddress().getPort()));
204-
205-
ObjectId descriptionServiceId = description.getServiceId();
206-
if (descriptionServiceId != null) {
207-
builder.append(" with service ID %s");
208-
entries.add(new Entry("serviceId", descriptionServiceId));
209-
}
199+
private void logEventMessage(final String messagePrefix, final String messageId, @Nullable final Throwable exception,
200+
final Consumer<List<Entry>> prefixEntriesMutator,
201+
final Consumer<List<Entry>> suffixEntriesMutator) {
202+
String format = messagePrefix + " using a connection with driver-generated ID {}"
203+
+ "[ and server-generated ID {}] to {}:{}[ with service ID {}]. The request ID is {}"
204+
+ " and the operation ID is {}.[ Command: {}]";
205+
logEventMessage(messageId, exception, prefixEntriesMutator, suffixEntriesMutator, format);
206+
}
210207

211-
builder.append(". The request ID is %s and the operation ID is %s.");
212-
entries.add(new Entry("requestId", message.getId()));
213-
entries.add(new Entry("operationId", operationContext.getId()));
208+
private void logEventMessage(final String messageId, final @Nullable Throwable exception,
209+
final Consumer<List<Entry>> prefixEntriesMutator,
210+
final Consumer<List<Entry>> suffixEntriesMutator,
211+
final String format) {
212+
List<Entry> entries = new ArrayList<>();
213+
prefixEntriesMutator.accept(entries);
214+
entries.add(new Entry(DRIVER_CONNECTION_ID, description.getConnectionId().getLocalValue()));
215+
entries.add(new Entry(SERVER_CONNECTION_ID, description.getConnectionId().getServerValue()));
216+
entries.add(new Entry(SERVER_HOST, description.getServerAddress().getHost()));
217+
entries.add(new Entry(SERVER_PORT, description.getServerAddress().getPort()));
218+
entries.add(new Entry(SERVICE_ID, description.getServiceId()));
219+
entries.add(new Entry(REQUEST_ID, message.getId()));
220+
entries.add(new Entry(OPERATION_ID, operationContext.getId()));
221+
suffixEntriesMutator.accept(entries);
222+
logger.log(new LogMessage(COMMAND, DEBUG, messageId, getClusterId(), exception, entries, format));
214223
}
215224

216225
private String getTruncatedJsonCommand(final BsonDocument commandDocument) {

‎driver-core/src/main/com/mongodb/internal/event/EventReasonMessageResolver.java

Lines changed: 60 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,60 @@
1+
/*
2+
* Copyright 2008-present MongoDB, Inc.
3+
*
4+
* Licensed under the Apache License, Version 2.0 (the "License");
5+
* you may not use this file except in compliance with the License.
6+
* You may obtain a copy of the License at
7+
*
8+
* http://www.apache.org/licenses/LICENSE-2.0
9+
*
10+
* Unless required by applicable law or agreed to in writing, software
11+
* distributed under the License is distributed on an "AS IS" BASIS,
12+
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13+
* See the License for the specific language governing permissions and
14+
* limitations under the License.
15+
*/
16+
17+
package com.mongodb.internal.event;
18+
19+
import com.mongodb.event.ConnectionCheckOutFailedEvent;
20+
import com.mongodb.event.ConnectionClosedEvent;
21+
22+
/**
23+
* <p>This class is not part of the public API and may be removed or changed at any time</p>
24+
*/
25+
public final class EventReasonMessageResolver {
26+
private static final String MESSAGE_CONNECTION_POOL_WAS_CLOSED = "Connection pool was closed";
27+
private static final String EMPTY_REASON = "";
28+
29+
public static String getMessage(final ConnectionClosedEvent.Reason reason) {
30+
switch (reason) {
31+
case STALE:
32+
return "Connection became stale because the pool was cleared";
33+
case IDLE:
34+
return "Connection has been available but unused for longer than the configured max idle time";
35+
case ERROR:
36+
return "An error occurred while using the connection";
37+
case POOL_CLOSED:
38+
return MESSAGE_CONNECTION_POOL_WAS_CLOSED;
39+
default:
40+
return EMPTY_REASON;
41+
}
42+
}
43+
44+
public static String getMessage(final ConnectionCheckOutFailedEvent.Reason reason) {
45+
switch (reason) {
46+
case TIMEOUT:
47+
return "Wait queue timeout elapsed without a connection becoming available";
48+
case CONNECTION_ERROR:
49+
return "An error occurred while trying to establish a new connection";
50+
case POOL_CLOSED:
51+
return MESSAGE_CONNECTION_POOL_WAS_CLOSED;
52+
default:
53+
return EMPTY_REASON;
54+
}
55+
}
56+
57+
private EventReasonMessageResolver() {
58+
//NOP
59+
}
60+
}

0 commit comments

Comments
 (0)