Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

DRIVERS-1677, DRIVERS-1673: Add general logging specification and command logging #1303

Merged
merged 45 commits into from
Oct 14, 2022
Merged
Show file tree
Hide file tree
Changes from 13 commits
Commits
Show all changes
45 commits
Select commit Hold shift + click to select a range
195f581
DRIVERS-1204 add general spec, unified format changes, and command lo…
kmahar Sep 1, 2022
2359fbc
use $$matchAsDocument for matching empty documents
kmahar Sep 9, 2022
8bea9ab
fix link
kmahar Sep 9, 2022
5484c94
Apply suggestions from code review
kmahar Sep 14, 2022
998adcb
Apply suggestions from code review
kmahar Sep 14, 2022
2d406d7
make driverConnectionId optional and split out testing for it
kmahar Sep 13, 2022
3027e01
move tests up out of /unified subdirectories
kmahar Sep 13, 2022
4114394
clarify length in prose tests
kmahar Sep 13, 2022
6e0356a
add type assertions to tests
kmahar Sep 13, 2022
a628829
drivers must omit null values from messages
kmahar Sep 14, 2022
968d937
unstuctured -> unstructured
kmahar Sep 14, 2022
60ec05e
MUST -> SHOULD for unstructured message forms; pull out common values…
kmahar Sep 14, 2022
09e0316
address comments on unified test format
kmahar Sep 14, 2022
68f1dd0
address comments on general spec
kmahar Sep 15, 2022
b8d48eb
fix rst
kmahar Sep 15, 2022
be019e5
fix operationId test
kmahar Sep 15, 2022
001e6d2
fix object in operationId test
kmahar Sep 15, 2022
08275c7
add tests for no handshake and no heartbeat messages being emitted
kmahar Sep 16, 2022
cf77d2c
only run heartbeat test on non-LB topology; reorder ops
kmahar Sep 16, 2022
dc15477
update rationale for not requiring structured logging
kmahar Sep 16, 2022
e8b39be
update prose test to reflect it applies to any driver with a max leng…
kmahar Sep 16, 2022
b161034
fix emphasis
kmahar Sep 16, 2022
1afc10f
schema version should be 1.12
kmahar Sep 27, 2022
b441824
Merge branch 'master' into DRIVERS-1204/logging-spec
kmahar Sep 27, 2022
e998fed
bump test file schema versions
kmahar Sep 27, 2022
45b9d8b
add interruptInUseConnections to schema v1.12
kmahar Sep 27, 2022
8c01044
update command logging tests README
kmahar Oct 5, 2022
4a94ad0
reword
kmahar Oct 5, 2022
2f41ac7
make clear that drivers should do "naive" truncation of JSON, and add…
kmahar Oct 7, 2022
830c568
drivers must match exact names/casing for structured log messages
kmahar Oct 10, 2022
5bacb00
events -> messages, clarify that messages MUST be an exact match
kmahar Oct 11, 2022
3a22c27
bump schema versions in invalid tests
kmahar Oct 11, 2022
5b0224b
update redacton rules and unifited format support for testing for red…
kmahar Oct 11, 2022
e2c7209
update failureIsRedacted language slightly
kmahar Oct 11, 2022
0434dd8
Merge branch 'master' into DRIVERS-1204/logging-spec
kmahar Oct 11, 2022
2f5256e
back to a single boolean; fix typos
kmahar Oct 12, 2022
73a0b3c
Merge remote-tracking branch 'origin' into DRIVERS-1204/logging-spec
kmahar Oct 12, 2022
7174ad7
address jmikola comments
kmahar Oct 13, 2022
bc6cdf6
schema version 1.12 -> 1.13
kmahar Oct 14, 2022
13e9593
Merge remote-tracking branch 'origin' into DRIVERS-1204/logging-spec
kmahar Oct 14, 2022
cfd852a
fix changelog date
kmahar Oct 14, 2022
042f20c
bump schema version in unified tests makefile
kmahar Oct 14, 2022
7a63673
update CLAM spec name in makefile
kmahar Oct 14, 2022
9358d08
consistent driver connection ID type in events
kmahar Oct 14, 2022
91464fa
address @BorisDog comments
kmahar Oct 14, 2022
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -5,8 +5,7 @@
Command Logging and Monitoring
==============================

:Title: Command Logging and Monitoring
:Status: Approved
:Status: Accepted
:Minimum Server Version: 2.4

.. contents::
Expand Down Expand Up @@ -149,10 +148,28 @@ the architecture needs of each driver.
Security
--------

Some commands and replies will contain sensitive data and in order to not risk the leaking of this
data to external sources or logs their commands AND replies AND corresponding error messages/exceptions
MUST be redacted from the events and log messages. The value MUST be replaced with an empty BSON document.
The list is as follows:
Some commands and replies will contain sensitive data relating to authentication.

In order to not risk leaking this data to external sources or logs, for these commands:

- The "command" field in ``CommandStartedEvent`` and "command started" log messages MUST
be replaced with an empty BSON document.
- The "reply" field in ``CommandSucceededEvent`` and "command succeeded" log messages MUST
be replaced with an empty BSON document.
- If the error is a server-side error, the "failure" field in ``CommandFailedEvent`` and
"command failed" log messages MUST have all fields besides the following redacted:

- ``code``
- ``codeName``
- ``errorLabels``

The exact implementation of redaction is flexible depending on the type the driver uses
to represent a failure in these events and log messages. For example, a driver could choose
to set all properties besides these on an error object to null. Alternatively, a driver
that uses strings to represent failures could replace relevant portions of the string with
"REDACTED".

The list of sensitive commands is as follows:

.. list-table::
:header-rows: 1
Expand Down Expand Up @@ -513,52 +530,26 @@ See the README in the test directory for requirements and guidance.
Changelog
=========

16 SEP 2015:
- Removed ``limit`` from find test with options to support 3.2.
- Changed find test read preference to ``primaryPreferred``.

1 OCT 2015:
- Changed find test with a kill cursors to not run on server versions greater than 3.0
- Added a find test with no kill cursors command which only runs on 3.1 and higher.
- Added notes on which tests should run based on server versions.

19 OCT 2015:
- Changed batchSize in the 3.2 find tests to expect the remaining value.

31 OCT 2015:
- Changed find test on 3.1 and higher to ignore being run on sharded clusters.

22 NOV 2015:
- Specify how to merge OP_MSG document sequences into command-started events.

29 MAR 2016:
- Added note on guarantee of the request ids.

2 NOV 2016:
- Added clause for not upconverting commands larger than maxBsonSize.

16 APR 2018:
- Made inclusion of BSON serialization/deserialization in command durations
to be optional.

12 FEB 2020:
- Added legacy hello ``speculativeAuthenticate`` to the list of values that should be redacted.

15 APR 2021:
- Added ``serviceId`` field to events.

5 MAY 2021:
- Updated to use hello and legacy hello.

30 AUG 2021:
- Added ``serverConnectionId`` field to ``CommandStartedEvent``, ``CommandSucceededEvent`` and
``CommandFailedEvent``.

18 MAY 2022:
- Converted legacy tests to the unified test format.

2 SEPTEMBER 2022:
- Remove material that only applies to MongoDB versions < 3.6.

7 SEPTEMBER 2022:
- Add command logging information and tests.
:2015-09-16: Removed ``limit`` from find test with options to support 3.2.
Changed find test read preference to ``primaryPreferred``.
:2015-10-01: Changed find test with a kill cursors to not run on server versions
greater than 3.0. Added a find test with no kill cursors command
which only runs on 3.1 and higher. Added notes on which tests
should run based on server versions.
:2015-10-19: Changed batchSize in the 3.2 find tests to expect the remaining value.
:2015-10-31: Changed find test on 3.1 and higher to ignore being run on sharded clusters.
:2015-11-22: Specify how to merge OP_MSG document sequences into command-started events.
:2016-03-29: Added note on guarantee of the request ids.
:2016-11-02: Added clause for not upconverting commands larger than maxBsonSize.
:2018-04-16: Made inclusion of BSON serialization/deserialization in command
durations to be optional.
:2020-02-12: Added legacy hello ``speculativeAuthenticate`` to the list of
values that should be redacted.
:2021-04-15: Added ``serviceId`` field to events.
:2021-05-05: Updated to use hello and legacy hello.
:2021-08-30: Added ``serverConnectionId`` field to ``CommandStartedEvent``,
``CommandSucceededEvent`` and ``CommandFailedEvent``.
:2022-05-18: Converted legacy tests to the unified test format.
:2022-09-02: Remove material that only applies to MongoDB versions < 3.6.
:2022-10-05: Remove spec front matter and reformat changelog.
:2022-10-11: Add command logging information and tests.
11 changes: 7 additions & 4 deletions source/command-logging-and-monitoring/tests/README.rst
Original file line number Diff line number Diff line change
Expand Up @@ -15,11 +15,14 @@ Testing
Automated Tests
^^^^^^^^^^^^^^^
There are tests in the `Unified Test Format <../../unified-test-format/unified-test-format.rst>`__ for both logging and
monitoring in `/logging </logging>`_ and `/monitoring </monitoring>`_, respectively.

monitoring in `/logging </logging>`_ and `/monitoring </monitoring>`_, respectively. Drivers MUST run the logging
kmahar marked this conversation as resolved.
Show resolved Hide resolved
tests with their max document length setting (as described in the
`logging specification <../../logging/logging.rst#truncation-of-large-documents>`__) set to a large value e.g. 10,000;
this is necessary in order for the driver to emit the full server reply (and to allow matching against that reply) on
certain MongoDB versions and topologies.

Prose Tests
~~~~~~~~~~~
^^^^^^^^^^^
Drivers MUST implement the following logging prose tests. These tests require the ability to capture log message data in a
structured form as described in the
`Unified Test Format specification <../../unified-test-format/unified-test-format.rst#expectedLogMessage>`__.
Expand All @@ -34,7 +37,7 @@ to support for specifying max document length as discussed in the
2. Construct an array ``docs`` containing the document ``{"x" : "y"}`` repeated 100 times.
3. Insert ``docs`` to a collection via ``insertMany``.
4. Inspect the resulting "command started" log message and assert that the "command" value is a string of length 1000 + (length of trailing ellipsis).
5. Inspect the resulting "command succeeded" log message and assert that the "reply" value is a string of length <= 1000.
5. Inspect the resulting "command succeeded" log message and assert that the "reply" value is a string of length <= 1000 + (length of trailing ellipsis).
6. Run ``find()`` on the collection where the document was inserted.
7. Inspect the resulting "command succeeded" log message and assert that the reply is a string of length 1000 + (length of trailing ellipsis).
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

minor: Is there a value in having the second test, as opposed to a parameterizing the first one?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think the differences in terms of the commands and assertions run are significant enough that it would not save us much text to try to combine them.


Expand Down
Original file line number Diff line number Diff line change
@@ -1,6 +1,6 @@
{
"description": "command-logging",
"schemaVersion": "1.11",
"schemaVersion": "1.12",
"createEntities": [
{
"client": {
Expand Down
Original file line number Diff line number Diff line change
@@ -1,6 +1,6 @@
description: "command-logging"

schemaVersion: "1.11"
schemaVersion: "1.12"

createEntities:
- client:
Expand Down
Original file line number Diff line number Diff line change
@@ -1,6 +1,6 @@
{
"description": "driver-connection-id",
"schemaVersion": "1.11",
"schemaVersion": "1.12",
"createEntities": [
{
"client": {
Expand Down
Original file line number Diff line number Diff line change
@@ -1,7 +1,7 @@
# This is a separate test so that drivers that do not implement CMAP can easily skip it.
description: "driver-connection-id"

schemaVersion: "1.11"
schemaVersion: "1.12"

createEntities:
- client:
Expand Down
Original file line number Diff line number Diff line change
@@ -1,6 +1,6 @@
{
"description": "no-handshake-command-logs",
"schemaVersion": "1.11",
"schemaVersion": "1.12",
"tests": [
{
"description": "Handshake commands should not generate log messages",
Expand Down
Original file line number Diff line number Diff line change
@@ -1,6 +1,6 @@
description: "no-handshake-command-logs"

schemaVersion: "1.11"
schemaVersion: "1.12"

tests:
- description: "Handshake commands should not generate log messages"
Expand Down
Original file line number Diff line number Diff line change
@@ -1,6 +1,6 @@
{
"description": "no-heartbeat-command-logs",
"schemaVersion": "1.11",
"schemaVersion": "1.12",
"runOnRequirements": [
{
"topologies": [
Expand Down
Original file line number Diff line number Diff line change
@@ -1,6 +1,6 @@
description: "no-heartbeat-command-logs"

schemaVersion: "1.11"
schemaVersion: "1.12"

# no heartbeats in load balanced mode.
runOnRequirements:
Expand Down
Original file line number Diff line number Diff line change
@@ -1,6 +1,6 @@
{
"description": "operation-id",
"schemaVersion": "1.11",
"schemaVersion": "1.12",
"createEntities": [
{
"client": {
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -2,7 +2,7 @@
# together bulk writes.
description: "operation-id"

schemaVersion: "1.11"
schemaVersion: "1.12"

createEntities:
- client:
Expand Down
Original file line number Diff line number Diff line change
@@ -1,6 +1,6 @@
{
"description": "pre-42-server-connection-id",
"schemaVersion": "1.11",
"schemaVersion": "1.12",
"runOnRequirements": [
{
"maxServerVersion": "4.0.99"
Expand Down
Original file line number Diff line number Diff line change
@@ -1,6 +1,6 @@
description: "pre-42-server-connection-id"

schemaVersion: "1.11"
schemaVersion: "1.12"

runOnRequirements:
- maxServerVersion: "4.0.99"
Expand Down