Skip to content

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

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 7 commits into from
Mar 5, 2025
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
8 changes: 4 additions & 4 deletions pymongo/asynchronous/mongo_client.py
Original file line number Diff line number Diff line change
Expand Up @@ -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 (
Expand Down Expand Up @@ -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:
Expand All @@ -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:
Expand All @@ -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]
Expand Down
8 changes: 8 additions & 0 deletions pymongo/logger.py
Original file line number Diff line number Diff line change
Expand Up @@ -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:")
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is this method supposed to also print the actual exception?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

logger.exception already includes the full traceback (see the PR description for an example).

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can you add a short comment saying that here for clarity?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done.



def _debug_log(logger: logging.Logger, **fields: Any) -> None:
logger.debug(LogMessage(**fields))

Expand Down
8 changes: 4 additions & 4 deletions pymongo/synchronous/mongo_client.py
Original file line number Diff line number Diff line change
Expand Up @@ -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 (
Expand Down Expand Up @@ -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:
Expand All @@ -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:
Expand All @@ -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]
Expand Down
23 changes: 23 additions & 0 deletions test/asynchronous/test_client.py
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down
23 changes: 23 additions & 0 deletions test/test_client.py
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down
Loading