Skip to content

Commit 2fcd943

Browse files
jyeminjyemin
committed
Add structured logging support for command logging
* Align command logging messages to specification * Add command logging unified tests JAVA-4752 JAVA-4753
1 parent fcaf87c commit 2fcd943

File tree

28 files changed

+3534
-108
lines changed

28 files changed

+3534
-108
lines changed

‎config/checkstyle/suppressions.xml‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -86,6 +86,7 @@
8686
<suppress checks="ParameterNumber" files="DefaultClusterableServerFactory"/>
8787
<suppress checks="ParameterNumber" files="Operations"/>
8888
<suppress checks="ParameterNumber" files="ChangeStreamDocument"/>
89+
<suppress checks="ParameterNumber" files="StructuredLogger"/>
8990

9091
<!--Legacy code that has not yet been cleaned-->
9192
<suppress checks="FinalClass" files="AggregationOptions"/>

‎config/codenarc/codenarc.xml‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -143,6 +143,7 @@
143143
<exclude name="UnnecessaryObjectReferences"/>
144144
<exclude name="UnnecessaryBigDecimalInstantiation"/>
145145
<exclude name="UnnecessarySetter"/>
146+
<exclude name="UnnecessaryGString"/>
146147
</ruleset-ref>
147148
<ruleset-ref path='rulesets/unused.xml'>
148149
<rule-config name='UnusedObject'>

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

Lines changed: 9 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -30,6 +30,7 @@
3030
import com.mongodb.annotations.NotThreadSafe;
3131
import com.mongodb.connection.AsyncCompletionHandler;
3232
import com.mongodb.connection.ClusterConnectionMode;
33+
import com.mongodb.connection.ClusterId;
3334
import com.mongodb.connection.ConnectionDescription;
3435
import com.mongodb.connection.ConnectionId;
3536
import com.mongodb.connection.ServerConnectionState;
@@ -42,6 +43,7 @@
4243
import com.mongodb.internal.async.SingleResultCallback;
4344
import com.mongodb.internal.diagnostics.logging.Logger;
4445
import com.mongodb.internal.diagnostics.logging.Loggers;
46+
import com.mongodb.internal.logging.StructuredLogger;
4547
import com.mongodb.internal.session.SessionContext;
4648
import com.mongodb.lang.Nullable;
4749
import org.bson.BsonBinaryReader;
@@ -80,6 +82,7 @@
8082
import static com.mongodb.internal.connection.ProtocolHelper.getRecoveryToken;
8183
import static com.mongodb.internal.connection.ProtocolHelper.getSnapshotTimestamp;
8284
import static com.mongodb.internal.connection.ProtocolHelper.isCommandOk;
85+
import static com.mongodb.internal.logging.StructuredLogMessage.Level.DEBUG;
8386
import static java.lang.String.format;
8487
import static java.util.Arrays.asList;
8588

@@ -845,15 +848,19 @@ public void onResult(@Nullable final ByteBuf result, @Nullable final Throwable t
845848
}
846849
}
847850

848-
private static final Logger COMMAND_PROTOCOL_LOGGER = Loggers.getLogger("protocol.command");
851+
private static final StructuredLogger COMMAND_PROTOCOL_LOGGER = new StructuredLogger("protocol.command");
849852

850853
private CommandEventSender createCommandEventSender(final CommandMessage message, final ByteBufferBsonOutput bsonOutput,
851854
final RequestContext requestContext) {
852-
if (opened() && (commandListener != null || COMMAND_PROTOCOL_LOGGER.isDebugEnabled())) {
855+
if (!isMonitoringConnection && opened() && (commandListener != null || COMMAND_PROTOCOL_LOGGER.isRequired(DEBUG, getClusterId()))) {
853856
return new LoggingCommandEventSender(SECURITY_SENSITIVE_COMMANDS, SECURITY_SENSITIVE_HELLO_COMMANDS, description,
854857
commandListener, requestContext, message, bsonOutput, COMMAND_PROTOCOL_LOGGER);
855858
} else {
856859
return new NoOpCommandEventSender();
857860
}
858861
}
862+
863+
private ClusterId getClusterId() {
864+
return description.getConnectionId().getServerId().getClusterId();
865+
}
859866
}

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

Lines changed: 99 additions & 58 deletions
Original file line numberDiff line numberDiff line change
@@ -18,9 +18,12 @@
1818

1919
import com.mongodb.MongoCommandException;
2020
import com.mongodb.RequestContext;
21+
import com.mongodb.connection.ClusterId;
2122
import com.mongodb.connection.ConnectionDescription;
2223
import com.mongodb.event.CommandListener;
23-
import com.mongodb.internal.diagnostics.logging.Logger;
24+
import com.mongodb.internal.logging.StructuredLogMessage;
25+
import com.mongodb.internal.logging.StructuredLogMessage.Entry;
26+
import com.mongodb.internal.logging.StructuredLogger;
2427
import com.mongodb.lang.Nullable;
2528
import org.bson.BsonDocument;
2629
import org.bson.BsonInt32;
@@ -29,23 +32,28 @@
2932
import org.bson.json.JsonMode;
3033
import org.bson.json.JsonWriter;
3134
import org.bson.json.JsonWriterSettings;
35+
import org.bson.types.ObjectId;
3236

3337
import java.io.StringWriter;
38+
import java.util.ArrayList;
39+
import java.util.List;
3440
import java.util.Set;
3541

3642
import static com.mongodb.assertions.Assertions.assertNotNull;
3743
import static com.mongodb.internal.connection.ProtocolHelper.sendCommandFailedEvent;
3844
import static com.mongodb.internal.connection.ProtocolHelper.sendCommandStartedEvent;
3945
import static com.mongodb.internal.connection.ProtocolHelper.sendCommandSucceededEvent;
40-
import static java.lang.String.format;
46+
import static com.mongodb.internal.logging.StructuredLogMessage.Component.COMMAND;
47+
import static com.mongodb.internal.logging.StructuredLogMessage.Level.DEBUG;
4148

4249
class LoggingCommandEventSender implements CommandEventSender {
4350
private static final int MAX_COMMAND_DOCUMENT_LENGTH_TO_LOG = 1000;
51+
private static final double NANOS_PER_MILLI = 1_000_000.0d;
4452

4553
private final ConnectionDescription description;
4654
@Nullable private final CommandListener commandListener;
4755
private final RequestContext requestContext;
48-
private final Logger logger;
56+
private final StructuredLogger logger;
4957
private final long startTimeNanos;
5058
private final CommandMessage message;
5159
private final String commandName;
@@ -55,7 +63,7 @@ class LoggingCommandEventSender implements CommandEventSender {
5563
LoggingCommandEventSender(final Set<String> securitySensitiveCommands, final Set<String> securitySensitiveHelloCommands,
5664
final ConnectionDescription description,
5765
@Nullable final CommandListener commandListener, final RequestContext requestContext, final CommandMessage message,
58-
final ByteBufferBsonOutput bsonOutput, final Logger logger) {
66+
final ByteBufferBsonOutput bsonOutput, final StructuredLogger logger) {
5967
this.description = description;
6068
this.commandListener = commandListener;
6169
this.requestContext = requestContext;
@@ -71,12 +79,17 @@ class LoggingCommandEventSender implements CommandEventSender {
7179
@Override
7280
public void sendStartedEvent() {
7381
if (loggingRequired()) {
74-
String commandString = redactionRequired ? format("{\"%s\": ...", commandName) : getTruncatedJsonCommand();
75-
// TODO: log RequestContext?
76-
logger.debug(
77-
format("Sending command '%s' with request id %d to database %s on connection [%s] to server %s",
78-
commandString, message.getId(),
79-
message.getNamespace().getDatabaseName(), description.getConnectionId(), description.getServerAddress()));
82+
List<Entry> entries = new ArrayList<>();
83+
StringBuilder builder = new StringBuilder("Command \"%s\" started on database %s");
84+
entries.add(new Entry("commandName", commandName));
85+
entries.add(new Entry("databaseName", message.getNamespace().getDatabaseName()));
86+
87+
appendCommonLogFragment(entries, builder);
88+
89+
builder.append(" Command: %s");
90+
entries.add(new Entry("command", redactionRequired ? "{}" : getTruncatedJsonCommand(commandDocument)));
91+
92+
logger.log(new StructuredLogMessage(COMMAND, DEBUG, "Command started", getClusterId(), entries), builder.toString());
8093
}
8194

8295
if (eventRequired()) {
@@ -91,38 +104,27 @@ public void sendStartedEvent() {
91104
commandDocument = null;
92105
}
93106

94-
private String getTruncatedJsonCommand() {
95-
StringWriter writer = new StringWriter();
96-
97-
try (BsonReader bsonReader = commandDocument.asBsonReader()) {
98-
JsonWriter jsonWriter = new JsonWriter(writer,
99-
JsonWriterSettings.builder().outputMode(JsonMode.RELAXED).maxLength(MAX_COMMAND_DOCUMENT_LENGTH_TO_LOG).build());
100-
101-
jsonWriter.pipe(bsonReader);
102-
103-
if (jsonWriter.isTruncated()) {
104-
writer.append(" ...");
105-
}
106-
107-
return writer.toString();
108-
}
109-
}
110107

111108
@Override
112109
public void sendFailedEvent(final Throwable t) {
113110
Throwable commandEventException = t;
114111
if (t instanceof MongoCommandException && redactionRequired) {
115-
commandEventException = new MongoCommandException(new BsonDocument(), description.getServerAddress());
112+
MongoCommandException originalCommandException = (MongoCommandException) t;
113+
commandEventException = new MongoCommandException(new BsonDocument(), originalCommandException.getServerAddress());
114+
commandEventException.setStackTrace(t.getStackTrace());
116115
}
117116
long elapsedTimeNanos = System.nanoTime() - startTimeNanos;
118117

119118
if (loggingRequired()) {
120-
logger.debug(
121-
format("Execution of command with request id %d failed to complete successfully in %s ms on connection [%s] "
122-
+ "to server %s",
123-
message.getId(), getElapsedTimeFormattedInMilliseconds(elapsedTimeNanos), description.getConnectionId(),
124-
description.getServerAddress()),
125-
commandEventException);
119+
List<Entry> entries = new ArrayList<>();
120+
StringBuilder builder = new StringBuilder("Command \"%s\" failed in %.2f ms");
121+
entries.add(new Entry("commandName", commandName));
122+
entries.add(new Entry("durationMS", elapsedTimeNanos / NANOS_PER_MILLI));
123+
124+
appendCommonLogFragment(entries, builder);
125+
126+
logger.log(new StructuredLogMessage(COMMAND, DEBUG, "Command failed", getClusterId(), commandEventException, entries),
127+
builder.toString());
126128
}
127129

128130
if (eventRequired()) {
@@ -133,53 +135,92 @@ public void sendFailedEvent(final Throwable t) {
133135

134136
@Override
135137
public void sendSucceededEvent(final ResponseBuffers responseBuffers) {
136-
long elapsedTimeNanos = System.nanoTime() - startTimeNanos;
137-
138-
if (loggingRequired()) {
139-
logger.debug(
140-
format("Execution of command with request id %d completed successfully in %s ms on connection [%s] to server %s",
141-
message.getId(), getElapsedTimeFormattedInMilliseconds(elapsedTimeNanos), description.getConnectionId(),
142-
description.getServerAddress()));
143-
}
144-
145-
if (eventRequired()) {
146-
BsonDocument responseDocumentForEvent = redactionRequired
147-
? new BsonDocument()
148-
: responseBuffers.getResponseDocument(message.getId(), new RawBsonDocumentCodec());
149-
sendCommandSucceededEvent(message, commandName, responseDocumentForEvent, description,
150-
elapsedTimeNanos, commandListener, requestContext);
151-
}
138+
sendSucceededEvent(responseBuffers.getResponseDocument(message.getId(), new RawBsonDocumentCodec()));
152139
}
153140

154141
@Override
155142
public void sendSucceededEventForOneWayCommand() {
143+
sendSucceededEvent(new BsonDocument("ok", new BsonInt32(1)));
144+
}
145+
146+
private void sendSucceededEvent(final BsonDocument reply) {
156147
long elapsedTimeNanos = System.nanoTime() - startTimeNanos;
157148

158149
if (loggingRequired()) {
159-
logger.debug(
160-
format("Execution of one-way command with request id %d completed successfully in %s ms on connection [%s] "
161-
+ "to server %s",
162-
message.getId(), getElapsedTimeFormattedInMilliseconds(elapsedTimeNanos), description.getConnectionId(),
163-
description.getServerAddress()));
150+
List<Entry> entries = new ArrayList<>();
151+
StringBuilder builder = new StringBuilder("Command \"%s\" succeeded in %.2f ms");
152+
entries.add(new Entry("commandName", commandName));
153+
entries.add(new Entry("durationMS", elapsedTimeNanos / NANOS_PER_MILLI));
154+
155+
appendCommonLogFragment(entries, builder);
156+
157+
builder.append(" Command reply: %s");
158+
BsonDocument responseDocumentForEvent = redactionRequired ? new BsonDocument() : reply;
159+
String replyString = redactionRequired ? "{}" : getTruncatedJsonCommand(responseDocumentForEvent);
160+
entries.add(new Entry("reply", replyString));
161+
162+
logger.log(new StructuredLogMessage(COMMAND, DEBUG, "Command succeeded", getClusterId(), entries),
163+
builder.toString());
164164
}
165165

166166
if (eventRequired()) {
167-
BsonDocument responseDocumentForEvent = new BsonDocument("ok", new BsonInt32(1));
167+
BsonDocument responseDocumentForEvent = redactionRequired ? new BsonDocument() : reply;
168168
sendCommandSucceededEvent(message, commandName, responseDocumentForEvent, description,
169169
elapsedTimeNanos, commandListener, requestContext);
170170
}
171171
}
172172

173173
private boolean loggingRequired() {
174-
return logger.isDebugEnabled();
174+
return logger.isRequired(DEBUG, getClusterId());
175+
}
176+
177+
178+
private ClusterId getClusterId() {
179+
return description.getConnectionId().getServerId().getClusterId();
175180
}
176181

177182
private boolean eventRequired() {
178183
return commandListener != null;
179184
}
180185

181-
private String getElapsedTimeFormattedInMilliseconds(final long elapsedTimeNanos) {
182-
return DecimalFormatHelper.format("#0.00", elapsedTimeNanos / 1000000.0);
186+
private void appendCommonLogFragment(final List<Entry> entries, final StringBuilder builder) {
187+
builder.append(" using a connection with driver-generated ID %d");
188+
entries.add(new Entry("driverConnectionId", description.getConnectionId().getLocalValue()));
189+
190+
Integer connectionServerValue = description.getConnectionId().getServerValue();
191+
if (connectionServerValue != null) {
192+
builder.append(" and server-generated ID %d");
193+
entries.add(new Entry("serverConnectionId", connectionServerValue));
194+
}
195+
196+
builder.append(" to %s:%s");
197+
entries.add(new Entry("serverHost", description.getServerAddress().getHost()));
198+
entries.add(new Entry("serverPort", description.getServerAddress().getPort()));
199+
200+
ObjectId descriptionServiceId = description.getServiceId();
201+
if (descriptionServiceId != null) {
202+
builder.append(" with service ID %s");
203+
entries.add(new Entry("serviceId", descriptionServiceId));
204+
}
205+
206+
builder.append(". The request ID is %s.");
207+
entries.add(new Entry("requestId", message.getId()));
183208
}
184209

210+
private static String getTruncatedJsonCommand(final BsonDocument commandDocument) {
211+
StringWriter writer = new StringWriter();
212+
213+
try (BsonReader bsonReader = commandDocument.asBsonReader()) {
214+
JsonWriter jsonWriter = new JsonWriter(writer,
215+
JsonWriterSettings.builder().outputMode(JsonMode.RELAXED).maxLength(MAX_COMMAND_DOCUMENT_LENGTH_TO_LOG).build());
216+
217+
jsonWriter.pipe(bsonReader);
218+
219+
if (jsonWriter.isTruncated()) {
220+
writer.append(" ...");
221+
}
222+
223+
return writer.toString();
224+
}
225+
}
185226
}

0 commit comments

Comments
 (0)