PYTHON-3472 - Add log messages to SDAM spec #1771

NoahStapp · 2024-08-05T18:58:58Z

No description provided.

Jibola

Overall LGTM!

Left non-blocking comments.

pymongo/logger.py

Jibola · 2024-08-07T15:20:11Z

test/discovery_and_monitoring/rs/compatible.json

@@ -16,7 +16,7 @@
              "b:27017"
            ],
            "minWireVersion": 0,
-            "maxWireVersion": 21
+            "maxWireVersion": 6


Guessing this is just a spec requirement change?

Jibola · 2024-08-07T15:32:43Z

test/unified_format.py

@@ -1804,14 +1818,28 @@ def check_events(self, spec):
            else:
                assert server_connection_id is None

+    def process_ignore_messages(self, ignore_logs, actual_logs):
+        final_logs = []
+        for log in actual_logs:


NIT: Thoughts on this potential optimization?

actual_log_messages = {actual_log["data"]["message"] for actual_log in actual_logs}
return list(filter(lambda log: log["data"]["message"] not in actual_log_messages))

I like this optimization but it does deviate from the spec's statement that "Matching rules used to match messages in ignoreMessages are identical to match rules used for messages matching". Is this a case where we need to stick closely to the spec, or can we do this much simpler way of matching?

Good point. I'll say let's not then.

The self.match_evaluator.match_result() function could be added in, but we lose readability so we'll keep it as is.

test/unified_format.py

Co-authored-by: Jib <Jibzade@gmail.com>

ShaneHarvey · 2024-08-08T18:45:12Z

pymongo/asynchronous/monitor.py

        if self._publish:
            assert self._listeners is not None
-            sd = self._server_description
            # XXX: "awaited" could be incorrectly set to True in the rare case
            # the pool checkout closes and recreates a connection.


This comment should move along with the awaited var.

ShaneHarvey · 2024-08-08T18:50:51Z

pymongo/synchronous/monitor.py

+                    serverHost=address[0],
+                    serverPort=address[1],
+                    awaited=awaited,
+                    durationMS=round_trip_time,


Here and elsewhere: round_trip_time is a float in seconds, but durationMS should be in milliseconds.

Still need to make this change in the other locations where durationMS is passed.

ShaneHarvey · 2024-08-08T23:06:11Z

pymongo/asynchronous/monitor.py

+                    serverHost=address[0],
+                    serverPort=address[1],
+                    awaited=awaited,
+                    durationMS=duration,


durationMS needs to be in ms here too.

ShaneHarvey · 2024-08-08T23:06:59Z

pymongo/asynchronous/monitor.py

            self._listeners.publish_server_heartbeat_started(address, awaited)

        if self._cancel_context and self._cancel_context.cancelled:
            await self._reset_connection()
        async with self._pool.checkout() as conn:
+            if _SDAM_LOGGER.isEnabledFor(logging.DEBUG):


Shouldn't this happen at the same point where publish_server_heartbeat_started is called?

In theory yes. However, we need a connection for the required logging information, and checking out the connection before publishing the heartbeat has a lot of side effects for other tests.

I would expect driverConnectionId to be None on the initial started event. Does the spec not expect that?

No such allowance is made: https://github.com/mongodb/specifications/blob/master/source/server-discovery-and-monitoring/server-discovery-and-monitoring-logging-and-monitoring.md#server-heartbeat-started-log-message.

Hmm this was intended to be fixed in DRIVERS-2677. Let's go forward with the current approach for now since the spec is ambiguous.

Jibola · 2024-08-09T20:31:57Z

test/unified_format.py

@@ -1804,14 +1818,28 @@ def check_events(self, spec):
            else:
                assert server_connection_id is None

+    def process_ignore_messages(self, ignore_logs, actual_logs):
+        final_logs = []
+        for log in actual_logs:


Good point. I'll say let's not then.

The self.match_evaluator.match_result() function could be added in, but we lose readability so we'll keep it as is.

ShaneHarvey · 2024-08-27T22:50:57Z

Is this pypy failure related?:

=================================== FAILURES ===================================
_ TestConnectionLoggingConnectionLogging.test_Create_a_client,_run_a_command,_and_close_the_client _

self = <test.test_connection_logging.TestConnectionLoggingConnectionLogging testMethod=test_Create_a_client,_run_a_command,_and_close_the_client>

    def test_case(self):
>       self.run_scenario(spec)

test/unified_format.py:2069: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
test/unified_format.py:2013: in run_scenario
    self._run_scenario(spec, uri)
test/unified_format.py:2043: in _run_scenario
    self.check_log_messages(spec["operations"], expect_log_messages)
test/unified_format.py:1939: in check_log_messages
    formatted_logs = format_logs(cm.records)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

log_list = [<LogRecord: pymongo.topology, 10, /home/runner/work/mongo-python-driver/mongo-python-driver/pymongo/logger.py, 100, "...66cddd96f2b922fd71bcd93c"}, "message": "Connection pool ready", "serverHost": "localhost", "serverPort": 27017}">, ...]

    def format_logs(log_list):
        client_to_log = defaultdict(list)
        for log in log_list:
            if log.module == "ocsp_support":
                continue
>           data = json_util.loads(log.message)
E           AttributeError: 'LogRecord' object has no attribute 'message'

test/unified_format.py:1926: AttributeError
------------------------------ Captured log call -------------------------------
DEBUG    pymongo.topology:logger.py:100 {"topologyId": {"$oid": "66cddd96f2b922fd71bcd93c"}, "driverConnectionId": 1, "serverConnectionId": 901, "serverHost": "localhost", "serverPort": 27017, "awaited": true, "message": "Server heartbeat started"}

NoahStapp · 2024-08-28T12:30:33Z

Is this pypy failure related?:

=================================== FAILURES ===================================
_ TestConnectionLoggingConnectionLogging.test_Create_a_client,_run_a_command,_and_close_the_client _

self = <test.test_connection_logging.TestConnectionLoggingConnectionLogging testMethod=test_Create_a_client,_run_a_command,_and_close_the_client>

    def test_case(self):
>       self.run_scenario(spec)

test/unified_format.py:2069: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
test/unified_format.py:2013: in run_scenario
    self._run_scenario(spec, uri)
test/unified_format.py:2043: in _run_scenario
    self.check_log_messages(spec["operations"], expect_log_messages)
test/unified_format.py:1939: in check_log_messages
    formatted_logs = format_logs(cm.records)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

log_list = [<LogRecord: pymongo.topology, 10, /home/runner/work/mongo-python-driver/mongo-python-driver/pymongo/logger.py, 100, "...66cddd96f2b922fd71bcd93c"}, "message": "Connection pool ready", "serverHost": "localhost", "serverPort": 27017}">, ...]

    def format_logs(log_list):
        client_to_log = defaultdict(list)
        for log in log_list:
            if log.module == "ocsp_support":
                continue
>           data = json_util.loads(log.message)
E           AttributeError: 'LogRecord' object has no attribute 'message'

test/unified_format.py:1926: AttributeError
------------------------------ Captured log call -------------------------------
DEBUG    pymongo.topology:logger.py:100 {"topologyId": {"$oid": "66cddd96f2b922fd71bcd93c"}, "driverConnectionId": 1, "serverConnectionId": 901, "serverHost": "localhost", "serverPort": 27017, "awaited": true, "message": "Server heartbeat started"}

I wouldn't expect it to be related, but it doesn't appear to be failing on other PRs. According to the logging docs, LogRecord.message is set only when the formatter is called. We've seen this exact error before intermittently, but haven't tracked down the underlying cause.

NoahStapp · 2024-08-28T18:48:46Z

Is this pypy failure related?:

=================================== FAILURES ===================================
_ TestConnectionLoggingConnectionLogging.test_Create_a_client,_run_a_command,_and_close_the_client _

self = <test.test_connection_logging.TestConnectionLoggingConnectionLogging testMethod=test_Create_a_client,_run_a_command,_and_close_the_client>

    def test_case(self):
>       self.run_scenario(spec)

test/unified_format.py:2069: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
test/unified_format.py:2013: in run_scenario
    self._run_scenario(spec, uri)
test/unified_format.py:2043: in _run_scenario
    self.check_log_messages(spec["operations"], expect_log_messages)
test/unified_format.py:1939: in check_log_messages
    formatted_logs = format_logs(cm.records)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

log_list = [<LogRecord: pymongo.topology, 10, /home/runner/work/mongo-python-driver/mongo-python-driver/pymongo/logger.py, 100, "...66cddd96f2b922fd71bcd93c"}, "message": "Connection pool ready", "serverHost": "localhost", "serverPort": 27017}">, ...]

    def format_logs(log_list):
        client_to_log = defaultdict(list)
        for log in log_list:
            if log.module == "ocsp_support":
                continue
>           data = json_util.loads(log.message)
E           AttributeError: 'LogRecord' object has no attribute 'message'

test/unified_format.py:1926: AttributeError
------------------------------ Captured log call -------------------------------
DEBUG    pymongo.topology:logger.py:100 {"topologyId": {"$oid": "66cddd96f2b922fd71bcd93c"}, "driverConnectionId": 1, "serverConnectionId": 901, "serverHost": "localhost", "serverPort": 27017, "awaited": true, "message": "Server heartbeat started"}

I wouldn't expect it to be related, but it doesn't appear to be failing on other PRs. According to the logging docs, LogRecord.message is set only when the formatter is called. We've seen this exact error before intermittently, but haven't tracked down the underlying cause.

I cannot reproduce this locally. Will keep an eye on it, and if it continues failing I'll open a ticket to investigate.

NoahStapp added 4 commits August 5, 2024 11:32

PYTHON-3472 - Add log messages to SDAM spec

13ec1fd

Merge with master

0e4ba42

Fix order of publishing

9425dc4

Fix SDAM logging comment

de5743a

mongodb-drivers-pr-bot bot requested a review from Jibola August 5, 2024 19:05

Fix NotPrimaryReplicaSet bug

2439c8b

Jibola previously approved these changes Aug 7, 2024

View reviewed changes

NoahStapp dismissed Jibola’s stale review via 4f69f28 August 7, 2024 17:16

NoahStapp and others added 4 commits August 7, 2024 10:16

Update test/unified_format.py

4f69f28

Co-authored-by: Jib <Jibzade@gmail.com>

Update pymongo/logger.py

7ccf98d

Co-authored-by: Jib <Jibzade@gmail.com>

linting

ab5e14e

Revert pop optimization

e3eb985

NoahStapp requested a review from Jibola August 8, 2024 16:03

ShaneHarvey requested changes Aug 8, 2024

View reviewed changes

Address review

294977c

NoahStapp requested a review from ShaneHarvey August 8, 2024 20:49

ShaneHarvey requested changes Aug 8, 2024

View reviewed changes

Fix durationMS

2b93d00

Jibola approved these changes Aug 9, 2024

View reviewed changes

NoahStapp requested a review from ShaneHarvey August 26, 2024 13:38

ShaneHarvey approved these changes Aug 28, 2024

View reviewed changes

NoahStapp merged commit c6967ab into mongodb:master Aug 28, 2024
30 of 34 checks passed

NoahStapp deleted the PYTHON-3472 branch August 28, 2024 18:48

PYTHON-3472 - Add log messages to SDAM spec #1771

PYTHON-3472 - Add log messages to SDAM spec #1771

Uh oh!

Conversation

NoahStapp commented Aug 5, 2024

Uh oh!

Jibola left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

ShaneHarvey Aug 12, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

ShaneHarvey commented Aug 27, 2024

Uh oh!

NoahStapp commented Aug 28, 2024

Uh oh!

NoahStapp commented Aug 28, 2024

Uh oh!

Uh oh!

Uh oh!

ShaneHarvey Aug 12, 2024 •

edited

Loading