DRIVERS-1675 Add log messages and tests to CMAP spec #1324

kmahar · 2022-10-18T21:39:31Z

Please complete the following before merging:

Update changelog.
Make sure there are generated JSON files from the YAML test files.
Test changes in at least one language driver.
Test these changes against all server versions and topologies (including standalone, replica set, sharded clusters, and serverless).

This PR includes the following:

Add log messages to CMAP which match the events defined in CMAP.
Adds JSON/YAML tests for the log messages, utilizing unified format changes made in DRIVERS-1677, DRIVERS-1673: Add general logging specification and command logging #1303.
- As part of this, I rearranged the existing CMAP tests. Those in the proprietary CMAP format have been moved into a new tests/cmap-format directory, and the logging tests live in a tests/logging directory. Additionally, I moved all the content on the CMAP format tests into a new README in tests/cmap-format and edited the top-level README to discuss the different types of CMAP tests. I don't have strong feelings on the naming or particular organization here, so if anyone prefers something else, let me know. This just seemed like a logical enough way to do it.
Adds a description of a client close operation to the unified test format. This is required to be able to test pool close messages. Per a recent conversation with @jmikola I don't believe this warrants a new minor schema version: "Drivers are supposed to raise errors for unsupported operations so I'm not at all concerned about bumping a schema version for it. The reasoning behind schema changes is that drivers might silently ignore new syntax."

The new tests pass in the Rust driver, but there are a few of them I had to skip from connection-pool-options.yml due to options we don't support. So if another driver is able to test these and let me know if they work for you, please let me know:

"maxConnecting should be included in connection pool created message when specified"
"waitQueueTimeoutMS should be included in connection pool created message when specified"
"waitQueueSize should be included in connection pool created message when specified"
"waitQueueMultiple should be included in connection pool created message when specified"

For the latter two I wasn't sure if they were worth including given that the options are deprecated, but at least the .NET driver still supports those options so it seemed they would provide value to them. (cc @BorisDog)

I will leave some comments inline.

kmahar · 2022-10-18T21:40:41Z

source/connection-monitoring-and-pooling/tests/README.rst


-The YAML and JSON files in this directory are platform-independent tests that


this content has been moved unchanged into /tests/cmap-format/README.rst

kmahar · 2022-10-18T21:43:07Z

source/connection-monitoring-and-pooling/tests/logging/connection-logging.yml

+
+runOnRequirements:
+  - topologies:
+    - single # The number of log messages is different for each topology since there is a connection pool per host.


I considered writing per-topology versions of these tests but it didn't seem like the extra coverage would have a ton of value assuming drivers have well-abstracted connection pools that don't care about what topology type they live in. it looks like the existing CMAP integration tests also only instruct drivers to only run them against a single host in whatever topology they are connected to.

source/connection-monitoring-and-pooling/tests/logging/connection-logging.yml

… is closed

source/connection-monitoring-and-pooling/connection-monitoring-and-pooling.rst

source/connection-monitoring-and-pooling/tests/logging/connection-logging.yml

jmikola

Unified changes LGTM although I have one question. Not going to review the CMAP stuff.

jmikola · 2022-10-23T13:09:32Z

source/unified-test-format/unified-test-format.rst

@@ -1634,6 +1634,18 @@ specifications:
 Client operations that require special handling or are not documented by an
 existing specification are described below.

+close


Just to confirm: is this the first PR introducing spec tests with a client.close operation?

Yes, from a search through the specs repo the only other occurrences of the close operation I can find are for cursors and change streams. All of those occurrences are in the load balancer tests.

Indeed, that operation is already documented in Cursor Operations. Thanks for confirming.

FYI @jmikola I made a small addition to the paragraph here to clarify that entities descended from a closed client should also not be used after a close.

BorisDog · 2022-10-26T17:45:42Z

source/connection-monitoring-and-pooling/connection-monitoring-and-pooling.rst

+subscriber if it is convenient to do so.
+
+The types used in the structured message definitions below are demonstrative, and drivers MAY use similar types instead so long as the information
+is present (e.g. a double instead of an integer, or a string instead of an integer if the structured logging framework does not support numeric types.)


nit: period at the end of the sentence?

moved period out of the parentheses

BorisDog · 2022-10-26T18:50:47Z

source/connection-monitoring-and-pooling/tests/logging/connection-logging.yml

+              message: "Connection checkout failed"
+              serverHost: { $$type: string }
+              serverPort: { $$type: [int, long] }
+              reason: "An error occurred while trying to establish a connection"


This probably should be "An error occurred while trying to establish a new connection" ?

yes good catch, I accidentally omitted the "new" here and in Rust impl. fixed.

…tations from tests

kmahar · 2022-11-01T17:44:29Z

FYI: It came up in driver-devs that Ruby does not close the connection pool when a client is closed. I was thinking about how these tests would work (or not work) for Ruby and I noticed all of the connection-pool-options tests were unnecessarily closing the client and expecting a corresponding log message so I have removed those. I think Ruby will just have to skip the one test that does need the close and write some prose test to cover that log message.

BorisDog

LGTM (minor comment)

BorisDog · 2022-11-01T18:58:00Z

source/connection-monitoring-and-pooling/tests/logging/connection-logging.yml

+              serverHost: { $$type: string }
+              serverPort: { $$type: [int, long] }
+
+  # This test exists to probide coverage of checkout failed and pool cleared events.


typo: provide

thanks, fixed.

patrickfreed · 2022-11-01T21:46:12Z

source/connection-monitoring-and-pooling/connection-monitoring-and-pooling.rst

+
+The unstructured form SHOULD be as follows, using the values defined in the structured format above to fill in placeholders as appropriate:
+
+  Connection checked out with driver-generated ID {{driverConnectionId}} to {{serverHost}}:{{serverPort}}


This is kind of a grammar nit, but I think this message reads a bit easier if the "with id" and "to <address>" phrases came before the verb here, since they're describing "Connection". If you drop the "with" part, the issue is a bit more obvious (e.g. "Connection checked out to a:12345" doesn't quite make sense).

Something like "Connection to a:12345 with driver-generated ID checked out" reads a bit better to me. The drawback with that is "Connection" and "checked out" are now separate, though I'm not sure if that's an issue or not. A more dramatic shift that doesn't have either problem could be something like "Connection checked out (driver-generated ID=1, destination=a:12345)".

WDYT?

yeah I was having a hard time figuring out how to write the english for some of these and it shows here 😅

re-reading this I had a couple thoughts:

I feel like the host/port should come before the ID as it feels more important given that IDs are only unique per-pool/endpoint

maybe "for" would be a better word than to?

I do think keeping the "Connection checked out" part together and at the start of the message is useful so that if you are skimming you can easily see what the message is about from the start of it.

given these WDYT of either of the following:

Connection checked out for endpoint a:12345 with driver-generated ID 123

Connection checked out: endpoint=a:12345, driver-generated ID=123.

(borrowing "endpoint" terminology from elsewhere in CMAP)

I kinda like 2. It's consistent and pretty easy to parse visually (and programatically in case a given language can't do structured logs).

"endpoint" is spec language-y though, I'm not sure if it ends up in our API or docs that often. What about just using "address" like the events do?

cool, I updated to the second one (but with address instead of endpoint) and updated some of the other log messages to make the format/phrasing more consistent

source/connection-monitoring-and-pooling/connection-monitoring-and-pooling.rst

patrickfreed

LGTM!

BorisDog

LGTM

kmahar added 2 commits October 18, 2022 15:07

DRIVERS-1675 Add log messages and tests to CMAP spec

3596215

restrict test using failCommand to 4.0+

c3a6104

kmahar commented Oct 18, 2022

View reviewed changes

kmahar marked this pull request as ready for review October 18, 2022 23:06

kmahar requested review from a team as code owners October 18, 2022 23:06

kmahar requested review from jmikola, BorisDog, patrickfreed and jyemin and removed request for a team October 18, 2022 23:06

kmahar mentioned this pull request Oct 20, 2022

RUST-1510 Implement connection pool tracing messages mongodb/mongo-rust-driver#766

Merged

add a sentence clarifying a client entity should not be used after it…

cec5975

… is closed

patrickfreed reviewed Oct 21, 2022

View reviewed changes

jmikola approved these changes Oct 23, 2022

View reviewed changes

BorisDog reviewed Oct 27, 2022

View reviewed changes

address review comments

de7361e

kmahar requested review from patrickfreed and BorisDog October 31, 2022 21:54

kmahar added 4 commits October 31, 2022 17:56

Update unified-test-format.rst

a851d91

Merge branch 'master' into DRIVERS-1675/cmap-logging

4417d3a

remove unneeded client close operations and pool closed message expec…

027e988

…tations from tests

update comments

97dc23f

BorisDog approved these changes Nov 1, 2022

View reviewed changes

kmahar mentioned this pull request Nov 1, 2022

minor: regenerate JSON files #1335

Merged

fix typo

67096ae

patrickfreed reviewed Nov 1, 2022

View reviewed changes

add errors to log messages where relevant

bf59603

kmahar requested a review from BorisDog November 3, 2022 21:25

kmahar added 2 commits November 3, 2022 17:25

Merge remote-tracking branch 'origin' into DRIVERS-1675/cmap-logging

54c3468

reword unstructured log messages

9829146

jyemin removed their request for review November 7, 2022 17:35

patrickfreed approved these changes Nov 7, 2022

View reviewed changes

BorisDog approved these changes Nov 8, 2022

View reviewed changes

kmahar merged commit d268119 into master Nov 8, 2022

kmahar deleted the DRIVERS-1675/cmap-logging branch November 8, 2022 20:32

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

DRIVERS-1675 Add log messages and tests to CMAP spec #1324

DRIVERS-1675 Add log messages and tests to CMAP spec #1324

kmahar commented Oct 18, 2022

kmahar Oct 18, 2022 •

edited

Loading

kmahar Oct 18, 2022

jmikola left a comment

jmikola Oct 23, 2022

kmahar Oct 25, 2022

jmikola Oct 28, 2022

kmahar Oct 31, 2022

BorisDog Oct 26, 2022

kmahar Oct 31, 2022

BorisDog Oct 26, 2022

kmahar Oct 31, 2022

kmahar commented Nov 1, 2022

BorisDog left a comment

BorisDog Nov 1, 2022

kmahar Nov 1, 2022

patrickfreed Nov 1, 2022 •

edited

Loading

kmahar Nov 3, 2022

patrickfreed Nov 3, 2022

kmahar Nov 3, 2022

patrickfreed left a comment

BorisDog left a comment


		The YAML and JSON files in this directory are platform-independent tests that


		The unstructured form SHOULD be as follows, using the values defined in the structured format above to fill in placeholders as appropriate:

		Connection checked out with driver-generated ID {{driverConnectionId}} to {{serverHost}}:{{serverPort}}

DRIVERS-1675 Add log messages and tests to CMAP spec #1324

DRIVERS-1675 Add log messages and tests to CMAP spec #1324

Conversation

kmahar commented Oct 18, 2022

kmahar Oct 18, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jmikola left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

kmahar commented Nov 1, 2022

BorisDog left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

patrickfreed Nov 1, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

patrickfreed left a comment

Choose a reason for hiding this comment

BorisDog left a comment

Choose a reason for hiding this comment

kmahar Oct 18, 2022 •

edited

Loading

patrickfreed Nov 1, 2022 •

edited

Loading