PYTHON-5168 Use logging for client background task errors (#2166)

Author: ShaneHarvey

pymongo/asynchronous/mongo_client.py

@@ -88,7 +88,7 @@
     _async_create_lock,
     _release_locks,
 )
-from pymongo.logger import _CLIENT_LOGGER, _log_or_warn
+from pymongo.logger import _CLIENT_LOGGER, _log_client_error, _log_or_warn
 from pymongo.message import _CursorAddress, _GetMore, _Query
 from pymongo.monitoring import ConnectionClosedReason
 from pymongo.operations import (
@@ -2049,7 +2049,7 @@ async def _process_kill_cursors(self) -> None:
                     # can be caught in _process_periodic_tasks
                     raise
                 else:
-                    helpers_shared._handle_exception()
+                    _log_client_error()
 
         # Don't re-open topology if it's closed and there's no pending cursors.
         if address_to_cursor_ids:
@@ -2061,7 +2061,7 @@ async def _process_kill_cursors(self) -> None:
                     if isinstance(exc, InvalidOperation) and self._topology._closed:
                         raise
                     else:
-                        helpers_shared._handle_exception()
+                        _log_client_error()
 
     # This method is run periodically by a background thread.
     async def _process_periodic_tasks(self) -> None:
@@ -2075,7 +2075,7 @@ async def _process_periodic_tasks(self) -> None:
             if isinstance(exc, InvalidOperation) and self._topology._closed:
                 return
             else:
-                helpers_shared._handle_exception()
+                _log_client_error()
 
     def _return_server_session(
         self, server_session: Union[_ServerSession, _EmptyServerSession]

pymongo/logger.py

@@ -96,6 +96,14 @@ class _SDAMStatusMessage(str, enum.Enum):
 }
 
 
+def _log_client_error() -> None:
+    # This is called from a daemon thread so check for None to account for interpreter shutdown.
+    logger = _CLIENT_LOGGER
+    if logger:
+        # logger.exception includes the full traceback.
+        logger.exception("MongoClient background task encountered an error:")
+
+
 def _debug_log(logger: logging.Logger, **fields: Any) -> None:
     logger.debug(LogMessage(**fields))
 

pymongo/synchronous/mongo_client.py

@@ -80,7 +80,7 @@
     _create_lock,
     _release_locks,
 )
-from pymongo.logger import _CLIENT_LOGGER, _log_or_warn
+from pymongo.logger import _CLIENT_LOGGER, _log_client_error, _log_or_warn
 from pymongo.message import _CursorAddress, _GetMore, _Query
 from pymongo.monitoring import ConnectionClosedReason
 from pymongo.operations import (
@@ -2043,7 +2043,7 @@ def _process_kill_cursors(self) -> None:
                     # can be caught in _process_periodic_tasks
                     raise
                 else:
-                    helpers_shared._handle_exception()
+                    _log_client_error()
 
         # Don't re-open topology if it's closed and there's no pending cursors.
         if address_to_cursor_ids:
@@ -2055,7 +2055,7 @@ def _process_kill_cursors(self) -> None:
                     if isinstance(exc, InvalidOperation) and self._topology._closed:
                         raise
                     else:
-                        helpers_shared._handle_exception()
+                        _log_client_error()
 
     # This method is run periodically by a background thread.
     def _process_periodic_tasks(self) -> None:
@@ -2069,7 +2069,7 @@ def _process_periodic_tasks(self) -> None:
             if isinstance(exc, InvalidOperation) and self._topology._closed:
                 return
             else:
-                helpers_shared._handle_exception()
+                _log_client_error()
 
     def _return_server_session(
         self, server_session: Union[_ServerSession, _EmptyServerSession]

test/asynchronous/test_client.py

@@ -1790,6 +1790,29 @@ async def stall_connect(*args, **kwargs):
             # Each ping command should not take more than 2 seconds
             self.assertLess(total, 2)
 
+    async def test_background_connections_log_on_error(self):
+        with self.assertLogs("pymongo.client", level="ERROR") as cm:
+            client = await self.async_rs_or_single_client(minPoolSize=1)
+            # Create a single connection in the pool.
+            await client.admin.command("ping")
+
+            # Cause new connections to fail.
+            pool = await async_get_pool(client)
+
+            async def fail_connect(*args, **kwargs):
+                raise Exception("failed to connect")
+
+            pool.connect = fail_connect
+            # Un-patch Pool.connect to break the cyclic reference.
+            self.addCleanup(delattr, pool, "connect")
+
+            await pool.reset_without_pause()
+
+            await async_wait_until(
+                lambda: "failed to connect" in "".join(cm.output), "start creating connections"
+            )
+            self.assertIn("MongoClient background task encountered an error", "".join(cm.output))
+
     @async_client_context.require_replica_set
     async def test_direct_connection(self):
         # direct_connection=True should result in Single topology.

test/test_client.py

@@ -1747,6 +1747,29 @@ def stall_connect(*args, **kwargs):
             # Each ping command should not take more than 2 seconds
             self.assertLess(total, 2)
 
+    def test_background_connections_log_on_error(self):
+        with self.assertLogs("pymongo.client", level="ERROR") as cm:
+            client = self.rs_or_single_client(minPoolSize=1)
+            # Create a single connection in the pool.
+            client.admin.command("ping")
+
+            # Cause new connections to fail.
+            pool = get_pool(client)
+
+            def fail_connect(*args, **kwargs):
+                raise Exception("failed to connect")
+
+            pool.connect = fail_connect
+            # Un-patch Pool.connect to break the cyclic reference.
+            self.addCleanup(delattr, pool, "connect")
+
+            pool.reset_without_pause()
+
+            wait_until(
+                lambda: "failed to connect" in "".join(cm.output), "start creating connections"
+            )
+            self.assertIn("MongoClient background task encountered an error", "".join(cm.output))
+
     @client_context.require_replica_set
     def test_direct_connection(self):
         # direct_connection=True should result in Single topology.