From 6ce31b6b5d5cdeec6a709a1f3665c2501f818d4a Mon Sep 17 00:00:00 2001 From: Noah Stapp Date: Mon, 31 Mar 2025 16:05:48 -0400 Subject: [PATCH 1/5] PYTHON-4557 - Add log message for retried commands --- pymongo/asynchronous/mongo_client.py | 21 ++++++++++++++++++++- pymongo/synchronous/mongo_client.py | 21 ++++++++++++++++++++- test/asynchronous/test_logger.py | 17 ++++++++++++++++- test/test_logger.py | 17 ++++++++++++++++- 4 files changed, 72 insertions(+), 4 deletions(-) diff --git a/pymongo/asynchronous/mongo_client.py b/pymongo/asynchronous/mongo_client.py index 16753420c0..20cec6031b 100644 --- a/pymongo/asynchronous/mongo_client.py +++ b/pymongo/asynchronous/mongo_client.py @@ -89,7 +89,13 @@ _async_create_lock, _release_locks, ) -from pymongo.logger import _CLIENT_LOGGER, _log_client_error, _log_or_warn +from pymongo.logger import ( + _CLIENT_LOGGER, + _COMMAND_LOGGER, + _debug_log, + _log_client_error, + _log_or_warn, +) from pymongo.message import _CursorAddress, _GetMore, _Query from pymongo.monitoring import ConnectionClosedReason from pymongo.operations import ( @@ -2684,6 +2690,7 @@ def __init__( self._deprioritized_servers: list[Server] = [] self._operation = operation self._operation_id = operation_id + self._attempt_number = 0 async def run(self) -> T: """Runs the supplied func() and attempts a retry @@ -2726,6 +2733,7 @@ async def run(self) -> T: raise self._retrying = True self._last_error = exc + self._attempt_number += 1 else: raise @@ -2747,6 +2755,7 @@ async def run(self) -> T: raise self._last_error from exc else: raise + self._attempt_number += 1 if self._bulk: self._bulk.retrying = True else: @@ -2825,6 +2834,11 @@ async def _write(self) -> T: # not support sessions raise the last error. self._check_last_error() self._retryable = False + if self._retrying: + _debug_log( + _COMMAND_LOGGER, + message=f"Retrying write attempt number {self._attempt_number}", + ) return await self._func(self._session, conn, self._retryable) # type: ignore except PyMongoError as exc: if not self._retryable: @@ -2846,6 +2860,11 @@ async def _read(self) -> T: ): if self._retrying and not self._retryable: self._check_last_error() + if self._retrying: + _debug_log( + _COMMAND_LOGGER, + message=f"Retrying read attempt number {self._attempt_number}", + ) return await self._func(self._session, self._server, conn, read_pref) # type: ignore diff --git a/pymongo/synchronous/mongo_client.py b/pymongo/synchronous/mongo_client.py index 2d8d6d730b..10d615fe8d 100644 --- a/pymongo/synchronous/mongo_client.py +++ b/pymongo/synchronous/mongo_client.py @@ -81,7 +81,13 @@ _create_lock, _release_locks, ) -from pymongo.logger import _CLIENT_LOGGER, _log_client_error, _log_or_warn +from pymongo.logger import ( + _CLIENT_LOGGER, + _COMMAND_LOGGER, + _debug_log, + _log_client_error, + _log_or_warn, +) from pymongo.message import _CursorAddress, _GetMore, _Query from pymongo.monitoring import ConnectionClosedReason from pymongo.operations import ( @@ -2670,6 +2676,7 @@ def __init__( self._deprioritized_servers: list[Server] = [] self._operation = operation self._operation_id = operation_id + self._attempt_number = 0 def run(self) -> T: """Runs the supplied func() and attempts a retry @@ -2712,6 +2719,7 @@ def run(self) -> T: raise self._retrying = True self._last_error = exc + self._attempt_number += 1 else: raise @@ -2733,6 +2741,7 @@ def run(self) -> T: raise self._last_error from exc else: raise + self._attempt_number += 1 if self._bulk: self._bulk.retrying = True else: @@ -2811,6 +2820,11 @@ def _write(self) -> T: # not support sessions raise the last error. self._check_last_error() self._retryable = False + if self._retrying: + _debug_log( + _COMMAND_LOGGER, + message=f"Retrying write attempt number {self._attempt_number}", + ) return self._func(self._session, conn, self._retryable) # type: ignore except PyMongoError as exc: if not self._retryable: @@ -2832,6 +2846,11 @@ def _read(self) -> T: ): if self._retrying and not self._retryable: self._check_last_error() + if self._retrying: + _debug_log( + _COMMAND_LOGGER, + message=f"Retrying read attempt number {self._attempt_number}", + ) return self._func(self._session, self._server, conn, read_pref) # type: ignore diff --git a/test/asynchronous/test_logger.py b/test/asynchronous/test_logger.py index a2e8b35c5f..7bd0e5daf9 100644 --- a/test/asynchronous/test_logger.py +++ b/test/asynchronous/test_logger.py @@ -15,7 +15,7 @@ import os from test import unittest -from test.asynchronous import AsyncIntegrationTest +from test.asynchronous import AsyncIntegrationTest, async_client_context from unittest.mock import patch from bson import json_util @@ -97,6 +97,21 @@ async def test_logging_without_listeners(self): await c.db.test.insert_one({"x": "1"}) self.assertGreater(len(cm.records), 0) + @async_client_context.require_failCommand_fail_point + async def test_logging_retry_read_attempts(self): + await self.db.test.insert_one({"x": "1"}) + + async with self.fail_point( + {"mode": {"times": 1}, "data": {"failCommands": ["find"], "closeConnection": True}} + ): + with self.assertLogs("pymongo.command", level="DEBUG") as cm: + await self.db.test.find_one({"x": "1"}) + + retry_messages = [ + r.getMessage() for r in cm.records if "Retrying read attempt" in r.getMessage() + ] + self.assertEqual(len(retry_messages), 1) + if __name__ == "__main__": unittest.main() diff --git a/test/test_logger.py b/test/test_logger.py index b3c8e6d176..5368d248d2 100644 --- a/test/test_logger.py +++ b/test/test_logger.py @@ -14,7 +14,7 @@ from __future__ import annotations import os -from test import IntegrationTest, unittest +from test import IntegrationTest, client_context, unittest from unittest.mock import patch from bson import json_util @@ -96,6 +96,21 @@ def test_logging_without_listeners(self): c.db.test.insert_one({"x": "1"}) self.assertGreater(len(cm.records), 0) + @client_context.require_failCommand_fail_point + def test_logging_retry_read_attempts(self): + self.db.test.insert_one({"x": "1"}) + + with self.fail_point( + {"mode": {"times": 1}, "data": {"failCommands": ["find"], "closeConnection": True}} + ): + with self.assertLogs("pymongo.command", level="DEBUG") as cm: + self.db.test.find_one({"x": "1"}) + + retry_messages = [ + r.getMessage() for r in cm.records if "Retrying read attempt" in r.getMessage() + ] + self.assertEqual(len(retry_messages), 1) + if __name__ == "__main__": unittest.main() From 0b6c4fb85abc01ce40454996fb7f856d6b741e02 Mon Sep 17 00:00:00 2001 From: Noah Stapp Date: Tue, 1 Apr 2025 09:10:42 -0400 Subject: [PATCH 2/5] Add operation name and ID to message --- pymongo/asynchronous/mongo_client.py | 4 ++-- pymongo/synchronous/mongo_client.py | 4 ++-- test/asynchronous/test_logger.py | 1 + test/test_logger.py | 1 + 4 files changed, 6 insertions(+), 4 deletions(-) diff --git a/pymongo/asynchronous/mongo_client.py b/pymongo/asynchronous/mongo_client.py index 20cec6031b..8f56fd7974 100644 --- a/pymongo/asynchronous/mongo_client.py +++ b/pymongo/asynchronous/mongo_client.py @@ -2837,7 +2837,7 @@ async def _write(self) -> T: if self._retrying: _debug_log( _COMMAND_LOGGER, - message=f"Retrying write attempt number {self._attempt_number}", + message=f"Retrying write attempt number {self._attempt_number} for operation `{self._operation}` with id {self._operation_id}", ) return await self._func(self._session, conn, self._retryable) # type: ignore except PyMongoError as exc: @@ -2863,7 +2863,7 @@ async def _read(self) -> T: if self._retrying: _debug_log( _COMMAND_LOGGER, - message=f"Retrying read attempt number {self._attempt_number}", + message=f"Retrying read attempt number {self._attempt_number} for operation `{self._operation}` with id {self._operation_id}", ) return await self._func(self._session, self._server, conn, read_pref) # type: ignore diff --git a/pymongo/synchronous/mongo_client.py b/pymongo/synchronous/mongo_client.py index 10d615fe8d..38b3b4d65c 100644 --- a/pymongo/synchronous/mongo_client.py +++ b/pymongo/synchronous/mongo_client.py @@ -2823,7 +2823,7 @@ def _write(self) -> T: if self._retrying: _debug_log( _COMMAND_LOGGER, - message=f"Retrying write attempt number {self._attempt_number}", + message=f"Retrying write attempt number {self._attempt_number} for operation `{self._operation}` with id {self._operation_id}", ) return self._func(self._session, conn, self._retryable) # type: ignore except PyMongoError as exc: @@ -2849,7 +2849,7 @@ def _read(self) -> T: if self._retrying: _debug_log( _COMMAND_LOGGER, - message=f"Retrying read attempt number {self._attempt_number}", + message=f"Retrying read attempt number {self._attempt_number} for operation `{self._operation}` with id {self._operation_id}", ) return self._func(self._session, self._server, conn, read_pref) # type: ignore diff --git a/test/asynchronous/test_logger.py b/test/asynchronous/test_logger.py index 7bd0e5daf9..92c29e1117 100644 --- a/test/asynchronous/test_logger.py +++ b/test/asynchronous/test_logger.py @@ -110,6 +110,7 @@ async def test_logging_retry_read_attempts(self): retry_messages = [ r.getMessage() for r in cm.records if "Retrying read attempt" in r.getMessage() ] + print(retry_messages) self.assertEqual(len(retry_messages), 1) diff --git a/test/test_logger.py b/test/test_logger.py index 5368d248d2..398f768c9d 100644 --- a/test/test_logger.py +++ b/test/test_logger.py @@ -109,6 +109,7 @@ def test_logging_retry_read_attempts(self): retry_messages = [ r.getMessage() for r in cm.records if "Retrying read attempt" in r.getMessage() ] + print(retry_messages) self.assertEqual(len(retry_messages), 1) From ffb3ebbd33ee299cf562d4367d26f294dbff1e69 Mon Sep 17 00:00:00 2001 From: Noah Stapp Date: Tue, 1 Apr 2025 13:21:53 -0400 Subject: [PATCH 3/5] Use logging format --- pymongo/asynchronous/mongo_client.py | 10 ++++++++-- pymongo/synchronous/mongo_client.py | 10 ++++++++-- 2 files changed, 16 insertions(+), 4 deletions(-) diff --git a/pymongo/asynchronous/mongo_client.py b/pymongo/asynchronous/mongo_client.py index 8f56fd7974..a775b702a3 100644 --- a/pymongo/asynchronous/mongo_client.py +++ b/pymongo/asynchronous/mongo_client.py @@ -2837,7 +2837,10 @@ async def _write(self) -> T: if self._retrying: _debug_log( _COMMAND_LOGGER, - message=f"Retrying write attempt number {self._attempt_number} for operation `{self._operation}` with id {self._operation_id}", + message=f"Retrying write attempt number {self._attempt_number}", + clientId=self._client.client_id, + commandName=self._operation, + operationId=self._operation_id, ) return await self._func(self._session, conn, self._retryable) # type: ignore except PyMongoError as exc: @@ -2863,7 +2866,10 @@ async def _read(self) -> T: if self._retrying: _debug_log( _COMMAND_LOGGER, - message=f"Retrying read attempt number {self._attempt_number} for operation `{self._operation}` with id {self._operation_id}", + message=f"Retrying read attempt number {self._attempt_number}", + clientId=self._client.client_id, + commandName=self._operation, + operationId=self._operation_id, ) return await self._func(self._session, self._server, conn, read_pref) # type: ignore diff --git a/pymongo/synchronous/mongo_client.py b/pymongo/synchronous/mongo_client.py index 38b3b4d65c..531863d035 100644 --- a/pymongo/synchronous/mongo_client.py +++ b/pymongo/synchronous/mongo_client.py @@ -2823,7 +2823,10 @@ def _write(self) -> T: if self._retrying: _debug_log( _COMMAND_LOGGER, - message=f"Retrying write attempt number {self._attempt_number} for operation `{self._operation}` with id {self._operation_id}", + message=f"Retrying write attempt number {self._attempt_number}", + clientId=self._client.client_id, + commandName=self._operation, + operationId=self._operation_id, ) return self._func(self._session, conn, self._retryable) # type: ignore except PyMongoError as exc: @@ -2849,7 +2852,10 @@ def _read(self) -> T: if self._retrying: _debug_log( _COMMAND_LOGGER, - message=f"Retrying read attempt number {self._attempt_number} for operation `{self._operation}` with id {self._operation_id}", + message=f"Retrying read attempt number {self._attempt_number}", + clientId=self._client.client_id, + commandName=self._operation, + operationId=self._operation_id, ) return self._func(self._session, self._server, conn, read_pref) # type: ignore From c10ed805fcffd828206bf97ff9a97b64945ac70e Mon Sep 17 00:00:00 2001 From: Noah Stapp Date: Tue, 1 Apr 2025 16:10:23 -0400 Subject: [PATCH 4/5] Fix clientId --- pymongo/asynchronous/mongo_client.py | 2 +- pymongo/synchronous/mongo_client.py | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/pymongo/asynchronous/mongo_client.py b/pymongo/asynchronous/mongo_client.py index fefa9f4e6e..a0ff8741a5 100644 --- a/pymongo/asynchronous/mongo_client.py +++ b/pymongo/asynchronous/mongo_client.py @@ -2869,7 +2869,7 @@ async def _read(self) -> T: _debug_log( _COMMAND_LOGGER, message=f"Retrying read attempt number {self._attempt_number}", - clientId=self._client.client_id, + clientId=self._client._topology_settings._topology_id, commandName=self._operation, operationId=self._operation_id, ) diff --git a/pymongo/synchronous/mongo_client.py b/pymongo/synchronous/mongo_client.py index 66140f3533..a674bfb667 100644 --- a/pymongo/synchronous/mongo_client.py +++ b/pymongo/synchronous/mongo_client.py @@ -2855,7 +2855,7 @@ def _read(self) -> T: _debug_log( _COMMAND_LOGGER, message=f"Retrying read attempt number {self._attempt_number}", - clientId=self._client.client_id, + clientId=self._client._topology_settings._topology_id, commandName=self._operation, operationId=self._operation_id, ) From 9fffc9ee21e950de1222643f67272c67d5cf1ca7 Mon Sep 17 00:00:00 2001 From: Noah Stapp Date: Thu, 3 Apr 2025 15:12:31 -0400 Subject: [PATCH 5/5] Add write log test, use errorCode for fail points --- pymongo/asynchronous/mongo_client.py | 2 +- pymongo/synchronous/mongo_client.py | 2 +- test/asynchronous/test_logger.py | 31 ++++++++++++++++++++++++++-- test/test_logger.py | 31 ++++++++++++++++++++++++++-- 4 files changed, 60 insertions(+), 6 deletions(-) diff --git a/pymongo/asynchronous/mongo_client.py b/pymongo/asynchronous/mongo_client.py index a0ff8741a5..7c8f7180bd 100644 --- a/pymongo/asynchronous/mongo_client.py +++ b/pymongo/asynchronous/mongo_client.py @@ -2840,7 +2840,7 @@ async def _write(self) -> T: _debug_log( _COMMAND_LOGGER, message=f"Retrying write attempt number {self._attempt_number}", - clientId=self._client.client_id, + clientId=self._client._topology_settings._topology_id, commandName=self._operation, operationId=self._operation_id, ) diff --git a/pymongo/synchronous/mongo_client.py b/pymongo/synchronous/mongo_client.py index a674bfb667..14fdefcb6f 100644 --- a/pymongo/synchronous/mongo_client.py +++ b/pymongo/synchronous/mongo_client.py @@ -2826,7 +2826,7 @@ def _write(self) -> T: _debug_log( _COMMAND_LOGGER, message=f"Retrying write attempt number {self._attempt_number}", - clientId=self._client.client_id, + clientId=self._client._topology_settings._topology_id, commandName=self._operation, operationId=self._operation_id, ) diff --git a/test/asynchronous/test_logger.py b/test/asynchronous/test_logger.py index 92c29e1117..d024735fd8 100644 --- a/test/asynchronous/test_logger.py +++ b/test/asynchronous/test_logger.py @@ -102,7 +102,14 @@ async def test_logging_retry_read_attempts(self): await self.db.test.insert_one({"x": "1"}) async with self.fail_point( - {"mode": {"times": 1}, "data": {"failCommands": ["find"], "closeConnection": True}} + { + "mode": {"times": 1}, + "data": { + "failCommands": ["find"], + "errorCode": 10107, + "errorLabels": ["RetryableWriteError"], + }, + } ): with self.assertLogs("pymongo.command", level="DEBUG") as cm: await self.db.test.find_one({"x": "1"}) @@ -110,7 +117,27 @@ async def test_logging_retry_read_attempts(self): retry_messages = [ r.getMessage() for r in cm.records if "Retrying read attempt" in r.getMessage() ] - print(retry_messages) + self.assertEqual(len(retry_messages), 1) + + @async_client_context.require_failCommand_fail_point + @async_client_context.require_retryable_writes + async def test_logging_retry_write_attempts(self): + async with self.fail_point( + { + "mode": {"times": 1}, + "data": { + "errorCode": 10107, + "errorLabels": ["RetryableWriteError"], + "failCommands": ["insert"], + }, + } + ): + with self.assertLogs("pymongo.command", level="DEBUG") as cm: + await self.db.test.insert_one({"x": "1"}) + + retry_messages = [ + r.getMessage() for r in cm.records if "Retrying write attempt" in r.getMessage() + ] self.assertEqual(len(retry_messages), 1) diff --git a/test/test_logger.py b/test/test_logger.py index 398f768c9d..a7d97927fa 100644 --- a/test/test_logger.py +++ b/test/test_logger.py @@ -101,7 +101,14 @@ def test_logging_retry_read_attempts(self): self.db.test.insert_one({"x": "1"}) with self.fail_point( - {"mode": {"times": 1}, "data": {"failCommands": ["find"], "closeConnection": True}} + { + "mode": {"times": 1}, + "data": { + "failCommands": ["find"], + "errorCode": 10107, + "errorLabels": ["RetryableWriteError"], + }, + } ): with self.assertLogs("pymongo.command", level="DEBUG") as cm: self.db.test.find_one({"x": "1"}) @@ -109,7 +116,27 @@ def test_logging_retry_read_attempts(self): retry_messages = [ r.getMessage() for r in cm.records if "Retrying read attempt" in r.getMessage() ] - print(retry_messages) + self.assertEqual(len(retry_messages), 1) + + @client_context.require_failCommand_fail_point + @client_context.require_retryable_writes + def test_logging_retry_write_attempts(self): + with self.fail_point( + { + "mode": {"times": 1}, + "data": { + "errorCode": 10107, + "errorLabels": ["RetryableWriteError"], + "failCommands": ["insert"], + }, + } + ): + with self.assertLogs("pymongo.command", level="DEBUG") as cm: + self.db.test.insert_one({"x": "1"}) + + retry_messages = [ + r.getMessage() for r in cm.records if "Retrying write attempt" in r.getMessage() + ] self.assertEqual(len(retry_messages), 1)