From 3210b175dd672ad20623d7cc2994594cd7d94991 Mon Sep 17 00:00:00 2001 From: Noah Stapp Date: Wed, 2 Apr 2025 08:29:23 -0400 Subject: [PATCH] PYTHON-4557 - Add log message for retried commands (#2248) --- pymongo/asynchronous/mongo_client.py | 27 ++++++++++++++++++++++++++- pymongo/synchronous/mongo_client.py | 27 ++++++++++++++++++++++++++- test/asynchronous/test_logger.py | 18 +++++++++++++++++- test/test_logger.py | 18 +++++++++++++++++- 4 files changed, 86 insertions(+), 4 deletions(-) diff --git a/pymongo/asynchronous/mongo_client.py b/pymongo/asynchronous/mongo_client.py index 98b8204d9..a0ff8741a 100644 --- a/pymongo/asynchronous/mongo_client.py +++ b/pymongo/asynchronous/mongo_client.py @@ -89,7 +89,13 @@ from pymongo.lock import ( _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, _EventListeners from pymongo.operations import ( @@ -2686,6 +2692,7 @@ class _ClientConnectionRetryable(Generic[T]): 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 @@ -2728,6 +2735,7 @@ class _ClientConnectionRetryable(Generic[T]): raise self._retrying = True self._last_error = exc + self._attempt_number += 1 else: raise @@ -2749,6 +2757,7 @@ class _ClientConnectionRetryable(Generic[T]): raise self._last_error from exc else: raise + self._attempt_number += 1 if self._bulk: self._bulk.retrying = True else: @@ -2827,6 +2836,14 @@ class _ClientConnectionRetryable(Generic[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}", + 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: if not self._retryable: @@ -2848,6 +2865,14 @@ class _ClientConnectionRetryable(Generic[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}", + clientId=self._client._topology_settings._topology_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 170798e9f..a674bfb66 100644 --- a/pymongo/synchronous/mongo_client.py +++ b/pymongo/synchronous/mongo_client.py @@ -81,7 +81,13 @@ from pymongo.lock import ( _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, _EventListeners from pymongo.operations import ( @@ -2672,6 +2678,7 @@ class _ClientConnectionRetryable(Generic[T]): 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 @@ -2714,6 +2721,7 @@ class _ClientConnectionRetryable(Generic[T]): raise self._retrying = True self._last_error = exc + self._attempt_number += 1 else: raise @@ -2735,6 +2743,7 @@ class _ClientConnectionRetryable(Generic[T]): raise self._last_error from exc else: raise + self._attempt_number += 1 if self._bulk: self._bulk.retrying = True else: @@ -2813,6 +2822,14 @@ class _ClientConnectionRetryable(Generic[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}", + 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: if not self._retryable: @@ -2834,6 +2851,14 @@ class _ClientConnectionRetryable(Generic[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}", + clientId=self._client._topology_settings._topology_id, + commandName=self._operation, + operationId=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 a2e8b35c5..92c29e111 100644 --- a/test/asynchronous/test_logger.py +++ b/test/asynchronous/test_logger.py @@ -15,7 +15,7 @@ from __future__ import annotations 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,22 @@ class TestLogger(AsyncIntegrationTest): 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() + ] + print(retry_messages) + self.assertEqual(len(retry_messages), 1) + if __name__ == "__main__": unittest.main() diff --git a/test/test_logger.py b/test/test_logger.py index b3c8e6d17..398f768c9 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,22 @@ class TestLogger(IntegrationTest): 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() + ] + print(retry_messages) + self.assertEqual(len(retry_messages), 1) + if __name__ == "__main__": unittest.main()