Add structured log messages to CMAP. #1114

vbabanin · 2023-05-06T00:30:59Z

This pull request adds changes to logging in accordance with CMAP specification. The purpose of these changes is to introduce structured logging to the connection component, providing a uniform logging format across all drivers.

Additionally, this pull request removes unnecessary logging that is not widely used and therefore not necessary to maintain. This will help to simplify the codebase.

Furthermore, conditional logging statements have been improved for better readability. A special formatting approach has been introduced, allowing the omission of log sentences enclosed in conditionals when the corresponding value is null.

JAVA-4771
JAVA-4962
JAVA-4946

JAVA-4771

vbabanin · 2023-05-06T01:48:29Z

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

@@ -497,7 +506,24 @@ private void initClient(final BsonDocument entity, final String id,
        MongoClientSettings clientSettings = clientSettingsBuilder.build();

        if (entity.containsKey("observeLogMessages")) {
-            putEntity(id + "-logging-interceptor", new TestLoggingInterceptor(clientSettings.getApplicationName()), clientLoggingInterceptors);


This change below has been added in accordance with the spec observeLogMessages

JAVA-4771

stIncMale · 2023-05-09T21:29:45Z

The PR implements the spec changes from mongodb/specifications@d268119. As far as I understand, there are some changes in this commits that are either not reflected, or should be reflected differently in the PR:

The directory source/connection-monitoring-and-pooling/tests/connection-monitoring-and-pooling/ was renamed to source/connection-monitoring-and-pooling/tests/cmap-format/, which means we need to rename driver-core/src/test/resources/connection-monitoring-and-pooling/ to driver-core/src/test/resources/connection-monitoring-and-pooling-cmap-format/.
We need to replace all the .rst and .json files in the new driver directory driver-core/src/test/resources/connection-monitoring-and-pooling-cmap-format/ with those from source/connection-monitoring-and-pooling/tests/cmap-format/. Note that the link is to d268119c9d4354f60e59d2e798c3cb3ee5323a29.
2.1. We need to update the corresponding test runner AbstractConnectionPoolTest to search for tests from the new place.
The directory source/connection-monitoring-and-pooling/tests/logging/ was created, and it contains unified tests, which means we need to create driver-core/src/test/resources/unified-test-format/connection-monitoring-and-pooling-logging/.
We need to copy all the .json files from source/connection-monitoring-and-pooling/tests/logging/ to driver-core/src/test/resources/unified-test-format/connection-monitoring-and-pooling-logging/. Note that the link is to d268119c9d4354f60e59d2e798c3cb3ee5323a29.
4.1. We need to update the corresponding test runner ConnectionPoolLoggingTest to search for tests from the new place.

stIncMale

I have not reviewed DefaultConnectionPool. Will wait until the new formatting approach is implemented.

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

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

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

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

stIncMale

I have not reviewed DefaultConnectionPool. Will wait until the new formatting approach is implemented.

vbabanin · 2023-05-10T01:10:20Z

The PR implements the spec changes from mongodb/specifications@d268119. As far as I understand, there are some changes in this commits that are either not reflected, or should be reflected differently in the PR:

The directory source/connection-monitoring-and-pooling/tests/connection-monitoring-and-pooling/ was renamed to source/connection-monitoring-and-pooling/tests/cmap-format/, which means we need to rename driver-core/src/test/resources/connection-monitoring-and-pooling/ to driver-core/src/test/resources/connection-monitoring-and-pooling-cmap-format/.

We need to replace all the .rst and .json files in the new driver directory driver-core/src/test/resources/connection-monitoring-and-pooling-cmap-format/ with those from source/connection-monitoring-and-pooling/tests/cmap-format/. Note that the link is to d268119c9d4354f60e59d2e798c3cb3ee5323a29.
2.1. We need to update the corresponding test runner AbstractConnectionPoolTest to search for tests from the new place.

The directory source/connection-monitoring-and-pooling/tests/logging/ was created, and it contains unified tests, which means we need to create driver-core/src/test/resources/unified-test-format/connection-monitoring-and-pooling-logging/.

We need to copy all the .json files from source/connection-monitoring-and-pooling/tests/logging/ to driver-core/src/test/resources/unified-test-format/connection-monitoring-and-pooling-logging/. Note that the link is to d268119c9d4354f60e59d2e798c3cb3ee5323a29.
4.1. We need to update the corresponding test runner ConnectionPoolLoggingTest to search for tests from the new place.

That makes sense. We can create a subfolder for the tests in our driver as in the spec repo source/connection-monitoring-and-pooling/tests/logging/

The location for this subfolder would be:
driver-core/src/test/resources/unified-test-format/connection-monitoring-and-pooling/logging
As more unified tests are added to CMAP, we can categorize them into separate subfolders under the same CMAP umbrella, based on the type of tests, for better organization. What do you think?

stIncMale · 2023-05-10T01:18:21Z

The location for this subfolder would be:
driver-core/src/test/resources/unified-test-format/connection-monitoring-and-pooling/logging

As more unified tests are added to CMAP, we can categorize them into separate subfolders under the same CMAP umbrella, based on the type of tests, for better organization. What do you think?

The current naming schema is confusing / does not seem to exist: sometimes we use subfolders, as in

driver-core/src/test/resources/server-discovery-and-monitoring/errors
driver-core/src/test/resources/server-discovery-and-monitoring/rs

and sometimes we use plain structure with suffixes, as in

driver-core/src/test/resources/client-side-encryption-corpus
driver-core/src/test/resources/client-side-encryption-data

So yeah, this PR can use subfolders as they seem much better than suffixes.

…d messages. 1. Add LogMessage abstraction over StructuredLogMessage and UnstructuredLogMessage to move interpolation logic to StructuredLogger and lazily construct messages. 2. Move repetitive log keys to an enum to improve code readability and maintainability. JAVA-4771 JAVA-4962

vbabanin · 2023-05-12T02:05:52Z

driver-core/src/test/unit/com/mongodb/internal/logging/LogMessageTest.java

+       String format =  "Command \"{}\" succeeded in {} ms using a connection with driver-generated ID {}" +
+                "[ and server-generated ID {}] to {}:{}[ with service ID {}]. The requestID is {} and the " +
+                "operation ID is {}. Command reply: {}]";
+        return Stream.of(


You can see almost all the cases interpolation currently can handle

vbabanin · 2023-05-12T18:02:07Z

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

+/**
+ * <p>This class is not part of the public API and may be removed or changed at any time</p>
+ */
+public final class LogMessage {


GitHub shows changes as if this is a new class, but actually that is renamed StructuredLogMessage class to LogMessage.

The reason for this change is that by design and specification, StructuredLogMessage only allows non-null entry values. However, we also need to preserve null values when interpolating a message to indicate which parts should be omitted.

To capture all entries, both null and non-null, new wrapper class (LogMessage) was introduced that allows to contain all entries with their corresponding values. Additionally, StructuredLogMessage is an inner class of LogMessage, so that LogMessage can be converted to StructuredLogMessage using the toStructuredLogMessage method, which creates a null-free structured log message.

To handle message interpolation, UnstructuredLogMessage inner class class is introduced as well, which triggers interpolation logic lazily. Our Logger captures LogMessage and internally converts it to either an unstructured or structured log message.

At this time, we only emit unstructured logs to the user.

JAVA-4771 JAVA-4962

vbabanin · 2023-05-15T21:25:46Z

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

+         * @return the interpolated string with the values from the entries collection filled in the placeholders.
+         * @throws NoSuchElementException – if the iteration has no more elements.
+         */
+        public String interpolate() {


@katcharov this is interpolation logic we discussed. You are welcome to review

stIncMale · 2023-05-15T22:09:22Z

Since this PR also implements JAVA-4962, let's add it to the PR description.

stIncMale · 2023-05-15T23:23:48Z

I noticed that the connection-pool-options.json as you took it also contains the complete implementation of JAVA-4946. So let's add this ticket to the PR description, and close it with the others when the PR is merged.

vbabanin · 2023-05-15T23:34:40Z

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

@@ -473,10 +495,36 @@ private void connectionCreated(final ConnectionPoolListener connectionPoolListen
     */
    private void connectionClosed(final ConnectionPoolListener connectionPoolListener, final ConnectionId connectionId,
                                  final ConnectionClosedEvent.Reason reason) {
+        ClusterId clusterId = serverId.getClusterId();
+        if (STRUCTURED_LOGGER.isRequired(DEBUG, clusterId)) {
+            String errorReason = "There was a socket exception raised by this connection";


No explicit exception is thrown to provide a comprehensive explanation of the error. However, according to the specification, it is mandatory to supply an error description when the reason for closure is an ERROR. Please refer to the specification available at Spec.

In the getReasonForClosing method, there is a check if (connection.isClosed()) which returns an ERROR type. Consequently, a corresponding check was implemented in the getReasonStringForClosing method to elaborate in more detail on the cause of the connection closure. Therefore, the error message was derived from the getReasonStringForClosing.

driver-core/src/test/unit/com/mongodb/internal/connection/AbstractConnectionPoolTest.java

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

driver-core/src/test/unit/com/mongodb/internal/logging/LogMessageTest.java

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

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

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

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

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

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

vbabanin · 2023-05-17T07:07:13Z

Additional tests will be added. Converted to draft

- Update LoggingInterceptor to accept LogMessage for capturing both structured and unstructured log messages during testing. - Remove redundant methods. JAVA-4771 JAVA-4962

stIncMale

It'd be great to introduce a new type for message ID constants (a enum appears to be the best choice) instead of using String literals.

I approved, but static checks need to pass before merging.

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

driver-core/src/test/unit/com/mongodb/logging/TestLoggingInterceptor.java

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

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

StructuredLogMessage is an inner class, but does not use its embedded reference to the object which created it. This reference makes the instances of the class larger, and may keep the reference to the creator object alive longer than necessary. JAVA-4771 JAVA-4962

JAVA-4771 JAVA-4962

jyemin

LGTM!

vbabanin added 6 commits May 5, 2023 16:27

Add structured log messages to CMAP.

776a505

JAVA-4771

Make Utility class final.

8f43213

JAVA-4771

Add handling for observeLogMessages.

faeb3fd

JAVA-4771

Remove unused imports.

6a8367b

JAVA-4771

Fix checkstyle warnings.

44c1570

JAVA-4771

Remove redundant variables.

2ad63a2

JAVA-4771

vbabanin commented May 6, 2023

View reviewed changes

vbabanin requested review from stIncMale and jyemin May 6, 2023 01:51

vbabanin added 6 commits May 5, 2023 18:54

Remove redundant variables.

fe94cee

JAVA-4771

Move the logging message closer to where event occurs.

38cb1ee

JAVA-4771

Extract lambda to a named method.

2305822

JAVA-4771

Create method for adding entries to simplify a code structure.

8282eb8

JAVA-4771

Fix checkstyle warnings.

8fb29af

JAVA-4771

Fix checkstyle warnings.

a60bcf3

JAVA-4771

vbabanin marked this pull request as ready for review May 8, 2023 15:28

vbabanin added 2 commits May 8, 2023 16:01

Add reactive streams tests.

e8c8a0e

JAVA-4771

Add missing variable.

db0b30b

JAVA-4771

stIncMale requested changes May 10, 2023

View reviewed changes

vbabanin self-assigned this May 10, 2023

vbabanin commented May 12, 2023

View reviewed changes

vbabanin requested a review from stIncMale May 12, 2023 18:02

vbabanin added 2 commits May 12, 2023 11:43

Fix checkstyle warnings.

d32271a

JAVA-4771 JAVA-4962

Remove redundant message variables.

57f883d

JAVA-4771 JAVA-4962

vbabanin added 2 commits May 12, 2023 12:51

Fix checkstyle issues.

f8c6429

JAVA-4771 JAVA-4962

Fix checkstyle issues.

adac818

JAVA-4771 JAVA-4962

vbabanin commented May 15, 2023

View reviewed changes

stIncMale requested changes May 16, 2023

View reviewed changes

vbabanin marked this pull request as draft May 17, 2023 07:06

Add tests for unstructured connection pool logging.

1c9ce27

- Update LoggingInterceptor to accept LogMessage for capturing both structured and unstructured log messages during testing. - Remove redundant methods. JAVA-4771 JAVA-4962

vbabanin requested a review from stIncMale May 17, 2023 22:39

vbabanin marked this pull request as ready for review May 17, 2023 22:40

stIncMale approved these changes May 17, 2023

View reviewed changes

jyemin requested changes May 18, 2023

View reviewed changes

vbabanin added 2 commits May 17, 2023 17:42

Fix SpotBugs issue.

902a3ae

StructuredLogMessage is an inner class, but does not use its embedded reference to the object which created it. This reference makes the instances of the class larger, and may keep the reference to the creator object alive longer than necessary. JAVA-4771 JAVA-4962

Refactor logEventMessage to support prefix and suffix mutators.

bbe2023

JAVA-4771 JAVA-4962

vbabanin requested a review from jyemin May 18, 2023 20:35

jyemin approved these changes May 18, 2023

View reviewed changes

vbabanin merged commit 14dd356 into mongodb:master May 19, 2023
41 checks passed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add structured log messages to CMAP. #1114

Add structured log messages to CMAP. #1114

vbabanin commented May 6, 2023 •

edited

vbabanin May 6, 2023 •

edited

stIncMale commented May 9, 2023 •

edited

stIncMale left a comment

stIncMale left a comment

vbabanin commented May 10, 2023 •

edited

stIncMale commented May 10, 2023 •

edited

vbabanin May 12, 2023

vbabanin May 12, 2023 •

edited

vbabanin May 15, 2023

stIncMale commented May 15, 2023

stIncMale commented May 15, 2023

vbabanin May 15, 2023

vbabanin commented May 17, 2023

stIncMale left a comment •

edited

jyemin left a comment

Add structured log messages to CMAP. #1114

Add structured log messages to CMAP. #1114

Conversation

vbabanin commented May 6, 2023 • edited

vbabanin May 6, 2023 • edited

Choose a reason for hiding this comment

stIncMale commented May 9, 2023 • edited

stIncMale left a comment

Choose a reason for hiding this comment

stIncMale left a comment

Choose a reason for hiding this comment

vbabanin commented May 10, 2023 • edited

stIncMale commented May 10, 2023 • edited

vbabanin May 12, 2023

Choose a reason for hiding this comment

vbabanin May 12, 2023 • edited

Choose a reason for hiding this comment

vbabanin May 15, 2023

Choose a reason for hiding this comment

stIncMale commented May 15, 2023

stIncMale commented May 15, 2023

vbabanin May 15, 2023

Choose a reason for hiding this comment

vbabanin commented May 17, 2023

stIncMale left a comment • edited

Choose a reason for hiding this comment

jyemin left a comment

Choose a reason for hiding this comment

vbabanin commented May 6, 2023 •

edited

vbabanin May 6, 2023 •

edited

stIncMale commented May 9, 2023 •

edited

vbabanin commented May 10, 2023 •

edited

stIncMale commented May 10, 2023 •

edited

vbabanin May 12, 2023 •

edited

stIncMale left a comment •

edited