PYTHON-4557 - Add log message for retried commands (mongodb#2248)

Author: NoahStapp

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, _EventListeners
 from pymongo.operations import (
@@ -2686,6 +2692,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
@@ -2728,6 +2735,7 @@ async def run(self) -> T:
                             raise
                         self._retrying = True
                         self._last_error = exc
+                        self._attempt_number += 1
                     else:
                         raise
 
@@ -2749,6 +2757,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:
@@ -2827,6 +2836,14 @@ 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}",
+                        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 @@ 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}",
+                    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
 
 

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, _EventListeners
 from pymongo.operations import (
@@ -2672,6 +2678,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
@@ -2714,6 +2721,7 @@ def run(self) -> T:
                             raise
                         self._retrying = True
                         self._last_error = exc
+                        self._attempt_number += 1
                     else:
                         raise
 
@@ -2735,6 +2743,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:
@@ -2813,6 +2822,14 @@ 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}",
+                        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 @@ 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}",
+                    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
 
 

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,22 @@ 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()
+        ]
+        print(retry_messages)
+        self.assertEqual(len(retry_messages), 1)
+
 
 if __name__ == "__main__":
     unittest.main()

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 @@ 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()
+        ]
+        print(retry_messages)
+        self.assertEqual(len(retry_messages), 1)
+
 
 if __name__ == "__main__":
     unittest.main()