Add structured log messages to CMAP.

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

@@ -86,8 +86,7 @@
 import static com.mongodb.internal.connection.ProtocolHelper.getRecoveryToken;
 import static com.mongodb.internal.connection.ProtocolHelper.getSnapshotTimestamp;
 import static com.mongodb.internal.connection.ProtocolHelper.isCommandOk;
-import static com.mongodb.internal.logging.StructuredLogMessage.Level.DEBUG;
-import static java.lang.String.format;
+import static com.mongodb.internal.logging.LogMessage.Level.DEBUG;
 import static java.util.Arrays.asList;
 
 /**
@@ -289,9 +288,6 @@ private void initAfterHandshakeFinish(final InternalConnectionInitializationDesc
         initialServerDescription = initializationDescription.getServerDescription();
         opened.set(true);
         sendCompressor = findSendCompressor(description);
-        if (LOGGER.isDebugEnabled()) {
-            LOGGER.debug(format("Opened connection [%s] to %s", getId(), serverId.getAddress()));
-        }
     }
 
     private Map<Byte, Compressor> createCompressorMap(final List<MongoCompressor> compressorList) {
@@ -337,13 +333,8 @@ private Compressor createCompressor(final MongoCompressor mongoCompressor) {
     @Override
     public void close() {
         // All but the first call is a no-op
-        if (!isClosed.getAndSet(true)) {
-            if (LOGGER.isDebugEnabled()) {
-                LOGGER.debug(format("Closing connection %s", getId()));
-            }
-            if (stream != null) {
+        if (!isClosed.getAndSet(true) && (stream != null)) {
                 stream.close();
-            }
         }
     }
 
@@ -655,9 +646,6 @@ public void receiveMessageAsync(final int responseTo, final SingleResultCallback
             return;
         }
 
-        if (LOGGER.isTraceEnabled()) {
-            LOGGER.trace(format("Start receiving response on %s", getId()));
-        }
         readAsync(MESSAGE_HEADER_LENGTH, new MessageHeaderCallback((result, t) -> {
             if (t != null) {
                 close();

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

@@ -22,8 +22,8 @@
 import com.mongodb.connection.ClusterId;
 import com.mongodb.connection.ConnectionDescription;
 import com.mongodb.event.CommandListener;
-import com.mongodb.internal.logging.StructuredLogMessage;
-import com.mongodb.internal.logging.StructuredLogMessage.Entry;
+import com.mongodb.internal.logging.LogMessage;
+import com.mongodb.internal.logging.LogMessage.Entry;
 import com.mongodb.internal.logging.StructuredLogger;
 import com.mongodb.lang.Nullable;
 import org.bson.BsonDocument;
@@ -33,25 +33,38 @@
 import org.bson.json.JsonMode;
 import org.bson.json.JsonWriter;
 import org.bson.json.JsonWriterSettings;
-import org.bson.types.ObjectId;
 
 import java.io.StringWriter;
+
 import java.util.ArrayList;
 import java.util.List;
 import java.util.Set;
+import java.util.function.Consumer;
 
 import static com.mongodb.assertions.Assertions.assertNotNull;
 import static com.mongodb.internal.connection.ProtocolHelper.sendCommandFailedEvent;
 import static com.mongodb.internal.connection.ProtocolHelper.sendCommandStartedEvent;
 import static com.mongodb.internal.connection.ProtocolHelper.sendCommandSucceededEvent;
-import static com.mongodb.internal.logging.StructuredLogMessage.Component.COMMAND;
-import static com.mongodb.internal.logging.StructuredLogMessage.Level.DEBUG;
+import static com.mongodb.internal.logging.LogMessage.Component.COMMAND;
+import static com.mongodb.internal.logging.LogMessage.Entry.Name.COMMAND_CONTENT;
+import static com.mongodb.internal.logging.LogMessage.Entry.Name.COMMAND_NAME;
+import static com.mongodb.internal.logging.LogMessage.Entry.Name.DATABASE_NAME;
+import static com.mongodb.internal.logging.LogMessage.Entry.Name.DRIVER_CONNECTION_ID;
+import static com.mongodb.internal.logging.LogMessage.Entry.Name.DURATION_MS;
+import static com.mongodb.internal.logging.LogMessage.Entry.Name.OPERATION_ID;
+import static com.mongodb.internal.logging.LogMessage.Entry.Name.REPLY;
+import static com.mongodb.internal.logging.LogMessage.Entry.Name.REQUEST_ID;
+import static com.mongodb.internal.logging.LogMessage.Entry.Name.SERVER_CONNECTION_ID;
+import static com.mongodb.internal.logging.LogMessage.Entry.Name.SERVER_HOST;
+import static com.mongodb.internal.logging.LogMessage.Entry.Name.SERVER_PORT;
+import static com.mongodb.internal.logging.LogMessage.Entry.Name.SERVICE_ID;
+import static com.mongodb.internal.logging.LogMessage.Level.DEBUG;
 
 class LoggingCommandEventSender implements CommandEventSender {
     private static final double NANOS_PER_MILLI = 1_000_000.0d;
-
     private final ConnectionDescription description;
-    @Nullable private final CommandListener commandListener;
+    @Nullable
+    private final CommandListener commandListener;
     private final RequestContext requestContext;
     private final OperationContext operationContext;
     private final StructuredLogger logger;
@@ -84,17 +97,14 @@ class LoggingCommandEventSender implements CommandEventSender {
     @Override
     public void sendStartedEvent() {
         if (loggingRequired()) {
-            List<Entry> entries = new ArrayList<>();
-            StringBuilder builder = new StringBuilder("Command \"%s\" started on database %s");
-            entries.add(new Entry("commandName", commandName));
-            entries.add(new Entry("databaseName", message.getNamespace().getDatabaseName()));
-
-            appendCommonLogFragment(entries, builder);
-
-            builder.append(" Command: %s");
-            entries.add(new Entry("command", redactionRequired ? "{}" : getTruncatedJsonCommand(commandDocument)));
-
-            logger.log(new StructuredLogMessage(COMMAND, DEBUG, "Command started", getClusterId(), entries), builder.toString());
+            String messagePrefix = "Command \"{}\" started on database {}";
+            String command = redactionRequired ? "{}" : getTruncatedJsonCommand(commandDocument);
+
+            logEventMessage(messagePrefix, "Command started", null, entries -> {
+                        entries.add(new Entry(COMMAND_NAME, commandName));
+                        entries.add(new Entry(DATABASE_NAME, message.getNamespace().getDatabaseName()));
+                    },
+                    entries -> entries.add(new Entry(COMMAND_CONTENT, command)));
         }
 
         if (eventRequired()) {
@@ -121,15 +131,14 @@ public void sendFailedEvent(final Throwable t) {
         long elapsedTimeNanos = System.nanoTime() - startTimeNanos;
 
         if (loggingRequired()) {
-            List<Entry> entries = new ArrayList<>();
-            StringBuilder builder = new StringBuilder("Command \"%s\" failed in %.2f ms");
-            entries.add(new Entry("commandName", commandName));
-            entries.add(new Entry("durationMS", elapsedTimeNanos / NANOS_PER_MILLI));
-
-            appendCommonLogFragment(entries, builder);
-
-            logger.log(new StructuredLogMessage(COMMAND, DEBUG, "Command failed", getClusterId(), commandEventException, entries),
-                    builder.toString());
+            String messagePrefix = "Command \"{}\" failed in {} ms";
+
+            logEventMessage(messagePrefix, "Command failed", commandEventException,
+                    entries -> {
+                        entries.add(new Entry(COMMAND_NAME, commandName));
+                        entries.add(new Entry(DURATION_MS, elapsedTimeNanos / NANOS_PER_MILLI));
+                    },
+                    entries -> entries.add(new Entry(COMMAND_CONTENT, null)));
         }
 
         if (eventRequired()) {
@@ -152,20 +161,19 @@ private void sendSucceededEvent(final BsonDocument reply) {
         long elapsedTimeNanos = System.nanoTime() - startTimeNanos;
 
         if (loggingRequired()) {
-            List<Entry> entries = new ArrayList<>();
-            StringBuilder builder = new StringBuilder("Command \"%s\" succeeded in %.2f ms");
-            entries.add(new Entry("commandName", commandName));
-            entries.add(new Entry("durationMS", elapsedTimeNanos / NANOS_PER_MILLI));
+            String format = "Command \"{}\" succeeded in {} ms using a connection with driver-generated ID {}"
+                    + "[ and server-generated ID {}] to {}:{}[ with service ID {}]. The request ID is {}"
+                    + " and the operation ID is {}. Command reply: {}";
 
-            appendCommonLogFragment(entries, builder);
-
-            builder.append(" Command reply: %s");
             BsonDocument responseDocumentForEvent = redactionRequired ? new BsonDocument() : reply;
             String replyString = redactionRequired ? "{}" : getTruncatedJsonCommand(responseDocumentForEvent);
-            entries.add(new Entry("reply", replyString));
 
-            logger.log(new StructuredLogMessage(COMMAND, DEBUG, "Command succeeded", getClusterId(), entries),
-                    builder.toString());
+            logEventMessage("Command succeeded", null,
+                    entries -> {
+                        entries.add(new Entry(COMMAND_NAME, commandName));
+                        entries.add(new Entry(DURATION_MS, elapsedTimeNanos / NANOS_PER_MILLI));
+                    },
+                    entries -> entries.add(new Entry(REPLY, replyString)), format);
         }
 
         if (eventRequired()) {
@@ -188,29 +196,30 @@ private boolean eventRequired() {
         return commandListener != null;
     }
 
-    private void appendCommonLogFragment(final List<Entry> entries, final StringBuilder builder) {
-        builder.append(" using a connection with driver-generated ID %d");
-        entries.add(new Entry("driverConnectionId", description.getConnectionId().getLocalValue()));
-
-        Integer connectionServerValue = description.getConnectionId().getServerValue();
-        if (connectionServerValue != null) {
-            builder.append(" and server-generated ID %d");
-            entries.add(new Entry("serverConnectionId", connectionServerValue));
-        }
-
-        builder.append(" to %s:%s");
-        entries.add(new Entry("serverHost", description.getServerAddress().getHost()));
-        entries.add(new Entry("serverPort", description.getServerAddress().getPort()));
-
-        ObjectId descriptionServiceId = description.getServiceId();
-        if (descriptionServiceId != null) {
-            builder.append(" with service ID %s");
-            entries.add(new Entry("serviceId", descriptionServiceId));
-        }
+    private void logEventMessage(final String messagePrefix, final String messageId, @Nullable final Throwable exception,
+                                 final Consumer<List<Entry>> prefixEntriesMutator,
+                                 final Consumer<List<Entry>> suffixEntriesMutator) {
+        String format = messagePrefix + " using a connection with driver-generated ID {}"
+                + "[ and server-generated ID {}] to {}:{}[ with service ID {}]. The request ID is {}"
+                + " and the operation ID is {}.[ Command: {}]";
+        logEventMessage(messageId, exception, prefixEntriesMutator, suffixEntriesMutator, format);
+    }
 
-        builder.append(". The request ID is %s and the operation ID is %s.");
-        entries.add(new Entry("requestId", message.getId()));
-        entries.add(new Entry("operationId", operationContext.getId()));
+    private void logEventMessage(final String messageId, final @Nullable Throwable exception,
+                                 final Consumer<List<Entry>> prefixEntriesMutator,
+                                 final Consumer<List<Entry>> suffixEntriesMutator,
+                                 final String format) {
+        List<Entry> entries = new ArrayList<>();
+        prefixEntriesMutator.accept(entries);
+        entries.add(new Entry(DRIVER_CONNECTION_ID, description.getConnectionId().getLocalValue()));
+        entries.add(new Entry(SERVER_CONNECTION_ID, description.getConnectionId().getServerValue()));
+        entries.add(new Entry(SERVER_HOST, description.getServerAddress().getHost()));
+        entries.add(new Entry(SERVER_PORT, description.getServerAddress().getPort()));
+        entries.add(new Entry(SERVICE_ID, description.getServiceId()));
+        entries.add(new Entry(REQUEST_ID, message.getId()));
+        entries.add(new Entry(OPERATION_ID, operationContext.getId()));
+        suffixEntriesMutator.accept(entries);
+        logger.log(new LogMessage(COMMAND, DEBUG, messageId, getClusterId(), exception, entries, format));
     }
 
     private String getTruncatedJsonCommand(final BsonDocument commandDocument) {

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

@@ -0,0 +1,60 @@
+/*
+ * Copyright 2008-present MongoDB, Inc.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *   http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package com.mongodb.internal.event;
+
+import com.mongodb.event.ConnectionCheckOutFailedEvent;
+import com.mongodb.event.ConnectionClosedEvent;
+
+/**
+ * <p>This class is not part of the public API and may be removed or changed at any time</p>
+ */
+public final class EventReasonMessageResolver {
+    private static final String MESSAGE_CONNECTION_POOL_WAS_CLOSED = "Connection pool was closed";
+    private static final String EMPTY_REASON = "";
+
+    public static String getMessage(final ConnectionClosedEvent.Reason reason) {
+        switch (reason) {
+            case STALE:
+                return "Connection became stale because the pool was cleared";
+            case IDLE:
+                return "Connection has been available but unused for longer than the configured max idle time";
+            case ERROR:
+                return "An error occurred while using the connection";
+            case POOL_CLOSED:
+                return MESSAGE_CONNECTION_POOL_WAS_CLOSED;
+            default:
+                return EMPTY_REASON;
+        }
+    }
+
+    public static String getMessage(final ConnectionCheckOutFailedEvent.Reason reason) {
+        switch (reason) {
+            case TIMEOUT:
+                return "Wait queue timeout elapsed without a connection becoming available";
+            case CONNECTION_ERROR:
+                return "An error occurred while trying to establish a new connection";
+            case POOL_CLOSED:
+                return MESSAGE_CONNECTION_POOL_WAS_CLOSED;
+            default:
+                return EMPTY_REASON;
+        }
+    }
+
+    private EventReasonMessageResolver() {
+        //NOP
+    }
+}