diff --git a/.evergreen/spec-patch/PYTHON-5791.patch b/.evergreen/spec-patch/PYTHON-5791.patch new file mode 100644 index 0000000000..1a078712c9 --- /dev/null +++ b/.evergreen/spec-patch/PYTHON-5791.patch @@ -0,0 +1,94 @@ +PYMONGO DOES NOT YET SEND readConcern.afterClusterTime IN RETRYABLE WRITE RETRIES + +diff --git a/test/transactions-convenient-api/unified/callback-aborts.json b/test/transactions-convenient-api/unified/callback-aborts.json +index 20642871..dc8f7fb5 100644 +--- a/test/transactions-convenient-api/unified/callback-aborts.json ++++ b/test/transactions-convenient-api/unified/callback-aborts.json +@@ -308,10 +308,12 @@ + "lsid": { + "$$sessionLsid": "session0" + }, +- "autocommit": { +- "$$exists": false +- }, + "readConcern": { ++ "afterClusterTime": { ++ "$$exists": true ++ } ++ }, ++ "autocommit": { + "$$exists": false + }, + "startTransaction": { +diff --git a/test/transactions-convenient-api/unified/callback-commits.json b/test/transactions-convenient-api/unified/callback-commits.json +index 06f791e9..edda3864 100644 +--- a/test/transactions-convenient-api/unified/callback-commits.json ++++ b/test/transactions-convenient-api/unified/callback-commits.json +@@ -381,10 +381,12 @@ + "lsid": { + "$$sessionLsid": "session0" + }, +- "autocommit": { +- "$$exists": false +- }, + "readConcern": { ++ "afterClusterTime": { ++ "$$exists": true ++ } ++ }, ++ "autocommit": { + "$$exists": false + }, + "startTransaction": { +diff --git a/test/transactions/unified/commit.json b/test/transactions/unified/commit.json +index ab778d8d..f0339069 100644 +--- a/test/transactions/unified/commit.json ++++ b/test/transactions/unified/commit.json +@@ -1040,7 +1040,9 @@ + ], + "ordered": true, + "readConcern": { +- "$$exists": false ++ "afterClusterTime": { ++ "$$exists": true ++ } + }, + "lsid": { + "$$sessionLsid": "session1" +@@ -1196,7 +1198,9 @@ + ], + "ordered": true, + "readConcern": { +- "$$exists": false ++ "afterClusterTime": { ++ "$$exists": true ++ } + }, + "lsid": { + "$$sessionLsid": "session1" +diff --git a/test/transactions/unified/retryable-writes.json b/test/transactions/unified/retryable-writes.json +index c196e686..21ef22b8 100644 +--- a/test/transactions/unified/retryable-writes.json ++++ b/test/transactions/unified/retryable-writes.json +@@ -217,7 +217,9 @@ + ], + "ordered": true, + "readConcern": { +- "$$exists": false ++ "afterClusterTime": { ++ "$$exists": true ++ } + }, + "lsid": { + "$$sessionLsid": "session0" +@@ -306,7 +308,9 @@ + ], + "ordered": true, + "readConcern": { +- "$$exists": false ++ "afterClusterTime": { ++ "$$exists": true ++ } + }, + "lsid": { + "$$sessionLsid": "session0" diff --git a/.evergreen/spec-patch/permanent/PYTHON-4201.patch b/.evergreen/spec-patch/permanent/PYTHON-4201.patch deleted file mode 100644 index c0b67f202d..0000000000 --- a/.evergreen/spec-patch/permanent/PYTHON-4201.patch +++ /dev/null @@ -1,62 +0,0 @@ -PYMONGO BEHAVES DIFFERENTLY INTENTIONALLY -- WE NEED THIS PATCH -diff --git a/test/server_selection_logging/replica-set.json b/test/server_selection_logging/replica-set.json -index 830b1ea51..5eba784bf 100644 ---- a/test/server_selection_logging/replica-set.json -+++ b/test/server_selection_logging/replica-set.json -@@ -184,7 +184,7 @@ - } - }, - { -- "level": "debug", -+ "level": "info", - "component": "serverSelection", - "data": { - "message": "Waiting for suitable server to become available", -diff --git a/test/server_selection_logging/standalone.json b/test/server_selection_logging/standalone.json -index 830b1ea51..5eba784bf 100644 ---- a/test/server_selection_logging/standalone.json -+++ b/test/server_selection_logging/standalone.json -@@ -191,7 +191,7 @@ - } - }, - { -- "level": "debug", -+ "level": "info", - "component": "serverSelection", - "data": { - "message": "Waiting for suitable server to become available", -diff --git a/test/server_selection_logging/sharded.json b/test/server_selection_logging/sharded.json -index 830b1ea51..5eba784bf 100644 ---- a/test/server_selection_logging/sharded.json -+++ b/test/server_selection_logging/sharded.json -@@ -193,7 +193,7 @@ - } - }, - { -- "level": "debug", -+ "level": "info", - "component": "serverSelection", - "data": { - "message": "Waiting for suitable server to become available", -diff --git a/test/server_selection_logging/sharded.json b/test/server_selection_logging/operation-id.json -index 830b1ea51..5eba784bf 100644 ---- a/test/server_selection_logging/operation-id.json -+++ b/test/server_selection_logging/operation-id.json -@@ -197,7 +197,7 @@ - } - }, - { -- "level": "debug", -+ "level": "info", - "component": "serverSelection", - "data": { - "message": "Waiting for suitable server to become available", -@@ -383,7 +383,7 @@ - } - }, - { -- "level": "debug", -+ "level": "info", - "component": "serverSelection", - "data": { - "message": "Waiting for suitable server to become available", diff --git a/pymongo/asynchronous/command_cursor.py b/pymongo/asynchronous/command_cursor.py index 5a59c67a15..f67c9ad3ec 100644 --- a/pymongo/asynchronous/command_cursor.py +++ b/pymongo/asynchronous/command_cursor.py @@ -172,6 +172,13 @@ async def _send_message(self, operation: _GetMore) -> None: self._killed = True if exc.timeout: self._die_no_lock() + elif self._sock_mgr: + # In load balancer mode the pinned connection must stay checked + # out until cursor.close() is called. _killed is already True + # for cursor-closed errors (set above); for other errors leave + # it False so cursor.close() will send killCursors via the + # pinned connection before releasing it. + pass else: # Return the session and pinned connection, if necessary. await self.close() @@ -179,8 +186,9 @@ async def _send_message(self, operation: _GetMore) -> None: except ConnectionFailure: # Don't send killCursors because the cursor is already closed. self._killed = True - # Return the session and pinned connection, if necessary. - await self.close() + if not self._sock_mgr: + # Return the session and pinned connection, if necessary. + await self.close() raise except Exception: await self.close() diff --git a/pymongo/asynchronous/cursor.py b/pymongo/asynchronous/cursor.py index a60c082ade..310d66964a 100644 --- a/pymongo/asynchronous/cursor.py +++ b/pymongo/asynchronous/cursor.py @@ -993,6 +993,13 @@ async def _send_message(self, operation: Union[_Query, _GetMore]) -> None: self._killed = True if exc.timeout: self._die_no_lock() + elif self._sock_mgr: + # In load balancer mode the pinned connection must stay checked + # out until cursor.close() is called. _killed is already True + # for cursor-closed errors (set above); for other errors leave + # it False so cursor.close() will send killCursors via the + # pinned connection before releasing it. + pass else: await self.close() # If this is a tailable cursor the error is likely @@ -1007,7 +1014,8 @@ async def _send_message(self, operation: Union[_Query, _GetMore]) -> None: raise except ConnectionFailure: self._killed = True - await self.close() + if not self._sock_mgr: + await self.close() raise # Catch KeyboardInterrupt, CancelledError, etc. and cleanup. except BaseException: diff --git a/pymongo/asynchronous/pool.py b/pymongo/asynchronous/pool.py index a5d5b28990..268b935e5d 100644 --- a/pymongo/asynchronous/pool.py +++ b/pymongo/asynchronous/pool.py @@ -623,11 +623,14 @@ async def _raise_connection_failure(self, error: BaseException) -> NoReturn: # KeyboardInterrupt from the start, rather than as an initial # socket.error, so we catch that, close the socket, and reraise it. # - # The connection closed event will be emitted later in checkin. - if self.ready: - reason = None + # For ready connections the closed event is emitted later in checkin. + # For not-ready LB connections, defer the event so that pool.connect()'s + # except block can emit poolClearedEvent first (CMAP spec requirement). + # For not-ready non-LB connections, emit the event immediately as before. + if self.ready or not self.opts.load_balanced: + reason = None if self.ready else ConnectionClosedReason.ERROR else: - reason = ConnectionClosedReason.ERROR + reason = None # deferred to pool.connect()'s except block await self.close_conn(reason) # SSLError from PyOpenSSL inherits directly from Exception. if isinstance(error, (IOError, OSError, *SSLErrors)): @@ -1086,7 +1089,33 @@ async def connect(self, handler: Optional[_MongoClientErrorHandler] = None) -> A self.active_contexts.discard(conn.cancel_context) if not completed_hello: self._handle_connection_error(e) - await conn.close_conn(ConnectionClosedReason.ERROR) + if completed_hello and handler and self.opts.load_balanced: + # LB only: hello succeeded so service_id is known. Run SDAM + # error handling (which clears the pool) before emitting + # connectionClosedEvent as required by the CMAP spec. + await handler.handle(type(e), e) + if self.opts.load_balanced and conn.closed: + # LB: _raise_connection_failure deferred the connectionClosedEvent. + # Emit it now, after any poolClearedEvent emitted above. + if conn.enabled_for_cmap: + assert conn.listeners is not None + conn.listeners.publish_connection_closed( + conn.address, conn.id, ConnectionClosedReason.ERROR + ) + if conn.enabled_for_logging and _CONNECTION_LOGGER.isEnabledFor(logging.DEBUG): + _debug_log( + _CONNECTION_LOGGER, + message=_ConnectionStatusMessage.CONN_CLOSED, + clientId=self._client_id, + serverHost=self.address[0], + serverPort=self.address[1], + driverConnectionId=conn.id, + reason=_verbose_connection_error_reason(ConnectionClosedReason.ERROR), + error=ConnectionClosedReason.ERROR, + ) + else: + # Non-LB: close_conn emits event if not already closed. + await conn.close_conn(ConnectionClosedReason.ERROR) raise if handler: diff --git a/pymongo/asynchronous/topology.py b/pymongo/asynchronous/topology.py index 01e346bfa8..8ccc4b38b9 100644 --- a/pymongo/asynchronous/topology.py +++ b/pymongo/asynchronous/topology.py @@ -54,6 +54,7 @@ _SDAM_LOGGER, _SERVER_SELECTION_LOGGER, _debug_log, + _info_log, _SDAMStatusMessage, _ServerSelectionStatusMessage, ) @@ -361,7 +362,7 @@ async def _select_servers_loop( ) if not logged_waiting: - _debug_log( + _info_log( _SERVER_SELECTION_LOGGER, message=_ServerSelectionStatusMessage.WAITING, selector=selector, diff --git a/pymongo/synchronous/command_cursor.py b/pymongo/synchronous/command_cursor.py index 34f60c6540..61b16d60c7 100644 --- a/pymongo/synchronous/command_cursor.py +++ b/pymongo/synchronous/command_cursor.py @@ -172,6 +172,13 @@ def _send_message(self, operation: _GetMore) -> None: self._killed = True if exc.timeout: self._die_no_lock() + elif self._sock_mgr: + # In load balancer mode the pinned connection must stay checked + # out until cursor.close() is called. _killed is already True + # for cursor-closed errors (set above); for other errors leave + # it False so cursor.close() will send killCursors via the + # pinned connection before releasing it. + pass else: # Return the session and pinned connection, if necessary. self.close() @@ -179,8 +186,9 @@ def _send_message(self, operation: _GetMore) -> None: except ConnectionFailure: # Don't send killCursors because the cursor is already closed. self._killed = True - # Return the session and pinned connection, if necessary. - self.close() + if not self._sock_mgr: + # Return the session and pinned connection, if necessary. + self.close() raise except Exception: self.close() diff --git a/pymongo/synchronous/cursor.py b/pymongo/synchronous/cursor.py index 5a721d8e06..92a9d6739a 100644 --- a/pymongo/synchronous/cursor.py +++ b/pymongo/synchronous/cursor.py @@ -991,6 +991,13 @@ def _send_message(self, operation: Union[_Query, _GetMore]) -> None: self._killed = True if exc.timeout: self._die_no_lock() + elif self._sock_mgr: + # In load balancer mode the pinned connection must stay checked + # out until cursor.close() is called. _killed is already True + # for cursor-closed errors (set above); for other errors leave + # it False so cursor.close() will send killCursors via the + # pinned connection before releasing it. + pass else: self.close() # If this is a tailable cursor the error is likely @@ -1005,7 +1012,8 @@ def _send_message(self, operation: Union[_Query, _GetMore]) -> None: raise except ConnectionFailure: self._killed = True - self.close() + if not self._sock_mgr: + self.close() raise # Catch KeyboardInterrupt, CancelledError, etc. and cleanup. except BaseException: diff --git a/pymongo/synchronous/pool.py b/pymongo/synchronous/pool.py index 25f2d08fe7..afc53eef70 100644 --- a/pymongo/synchronous/pool.py +++ b/pymongo/synchronous/pool.py @@ -621,11 +621,14 @@ def _raise_connection_failure(self, error: BaseException) -> NoReturn: # KeyboardInterrupt from the start, rather than as an initial # socket.error, so we catch that, close the socket, and reraise it. # - # The connection closed event will be emitted later in checkin. - if self.ready: - reason = None + # For ready connections the closed event is emitted later in checkin. + # For not-ready LB connections, defer the event so that pool.connect()'s + # except block can emit poolClearedEvent first (CMAP spec requirement). + # For not-ready non-LB connections, emit the event immediately as before. + if self.ready or not self.opts.load_balanced: + reason = None if self.ready else ConnectionClosedReason.ERROR else: - reason = ConnectionClosedReason.ERROR + reason = None # deferred to pool.connect()'s except block self.close_conn(reason) # SSLError from PyOpenSSL inherits directly from Exception. if isinstance(error, (IOError, OSError, *SSLErrors)): @@ -1082,7 +1085,33 @@ def connect(self, handler: Optional[_MongoClientErrorHandler] = None) -> Connect self.active_contexts.discard(conn.cancel_context) if not completed_hello: self._handle_connection_error(e) - conn.close_conn(ConnectionClosedReason.ERROR) + if completed_hello and handler and self.opts.load_balanced: + # LB only: hello succeeded so service_id is known. Run SDAM + # error handling (which clears the pool) before emitting + # connectionClosedEvent as required by the CMAP spec. + handler.handle(type(e), e) + if self.opts.load_balanced and conn.closed: + # LB: _raise_connection_failure deferred the connectionClosedEvent. + # Emit it now, after any poolClearedEvent emitted above. + if conn.enabled_for_cmap: + assert conn.listeners is not None + conn.listeners.publish_connection_closed( + conn.address, conn.id, ConnectionClosedReason.ERROR + ) + if conn.enabled_for_logging and _CONNECTION_LOGGER.isEnabledFor(logging.DEBUG): + _debug_log( + _CONNECTION_LOGGER, + message=_ConnectionStatusMessage.CONN_CLOSED, + clientId=self._client_id, + serverHost=self.address[0], + serverPort=self.address[1], + driverConnectionId=conn.id, + reason=_verbose_connection_error_reason(ConnectionClosedReason.ERROR), + error=ConnectionClosedReason.ERROR, + ) + else: + # Non-LB: close_conn emits event if not already closed. + conn.close_conn(ConnectionClosedReason.ERROR) raise if handler: diff --git a/pymongo/synchronous/topology.py b/pymongo/synchronous/topology.py index ec1615f0c6..fe9d993317 100644 --- a/pymongo/synchronous/topology.py +++ b/pymongo/synchronous/topology.py @@ -50,6 +50,7 @@ _SDAM_LOGGER, _SERVER_SELECTION_LOGGER, _debug_log, + _info_log, _SDAMStatusMessage, _ServerSelectionStatusMessage, ) @@ -361,7 +362,7 @@ def _select_servers_loop( ) if not logged_waiting: - _debug_log( + _info_log( _SERVER_SELECTION_LOGGER, message=_ServerSelectionStatusMessage.WAITING, selector=selector, diff --git a/test/connection_monitoring/pool-checkout-custom-maxConnecting-is-enforced.json b/test/connection_monitoring/pool-checkout-custom-maxConnecting-is-enforced.json index 6620f82fd9..9a7c0174c5 100644 --- a/test/connection_monitoring/pool-checkout-custom-maxConnecting-is-enforced.json +++ b/test/connection_monitoring/pool-checkout-custom-maxConnecting-is-enforced.json @@ -17,13 +17,15 @@ ], "closeConnection": false, "blockConnection": true, - "blockTimeMS": 500 + "blockTimeMS": 500, + "appName": "PoolCheckoutCustomMaxConnectingIsEnforced" } }, "poolOptions": { "maxConnecting": 1, "maxPoolSize": 2, - "waitQueueTimeoutMS": 5000 + "waitQueueTimeoutMS": 5000, + "appName": "PoolCheckoutCustomMaxConnectingIsEnforced" }, "operations": [ { diff --git a/test/connection_monitoring/pool-checkout-maxConnecting-is-enforced.json b/test/connection_monitoring/pool-checkout-maxConnecting-is-enforced.json index 3a63818bfe..418ec7986f 100644 --- a/test/connection_monitoring/pool-checkout-maxConnecting-is-enforced.json +++ b/test/connection_monitoring/pool-checkout-maxConnecting-is-enforced.json @@ -19,12 +19,14 @@ ], "closeConnection": false, "blockConnection": true, - "blockTimeMS": 800 + "blockTimeMS": 800, + "appName": "PoolCheckoutMaxConnectingIsEnforced" } }, "poolOptions": { "maxPoolSize": 10, - "waitQueueTimeoutMS": 5000 + "waitQueueTimeoutMS": 5000, + "appName": "PoolCheckoutMaxConnectingIsEnforced" }, "operations": [ { diff --git a/test/connection_monitoring/pool-checkout-maxConnecting-timeout.json b/test/connection_monitoring/pool-checkout-maxConnecting-timeout.json index 4d9fda1a68..443104675d 100644 --- a/test/connection_monitoring/pool-checkout-maxConnecting-timeout.json +++ b/test/connection_monitoring/pool-checkout-maxConnecting-timeout.json @@ -19,12 +19,14 @@ ], "closeConnection": false, "blockConnection": true, - "blockTimeMS": 750 + "blockTimeMS": 750, + "appName": "PoolCheckoutMaxConnectingTimeout" } }, "poolOptions": { "maxPoolSize": 10, - "waitQueueTimeoutMS": 50 + "waitQueueTimeoutMS": 50, + "appName": "PoolCheckoutMaxConnectingTimeout" }, "operations": [ { diff --git a/test/connection_monitoring/pool-checkout-minPoolSize-connection-maxConnecting.json b/test/connection_monitoring/pool-checkout-minPoolSize-connection-maxConnecting.json index 3b0d43e877..b53b002805 100644 --- a/test/connection_monitoring/pool-checkout-minPoolSize-connection-maxConnecting.json +++ b/test/connection_monitoring/pool-checkout-minPoolSize-connection-maxConnecting.json @@ -17,13 +17,15 @@ ], "closeConnection": false, "blockConnection": true, - "blockTimeMS": 500 + "blockTimeMS": 500, + "appName": "PoolCheckoutMinPoolSizeConnectionMaxConnecting" } }, "poolOptions": { "minPoolSize": 2, "maxPoolSize": 3, - "waitQueueTimeoutMS": 5000 + "waitQueueTimeoutMS": 5000, + "appName": "PoolCheckoutMinPoolSizeConnectionMaxConnecting" }, "operations": [ { diff --git a/test/connection_monitoring/pool-checkout-returned-connection-maxConnecting.json b/test/connection_monitoring/pool-checkout-returned-connection-maxConnecting.json index 10b526e0c3..0bac21ae64 100644 --- a/test/connection_monitoring/pool-checkout-returned-connection-maxConnecting.json +++ b/test/connection_monitoring/pool-checkout-returned-connection-maxConnecting.json @@ -19,13 +19,15 @@ ], "closeConnection": false, "blockConnection": true, - "blockTimeMS": 750 + "blockTimeMS": 750, + "appName": "PoolCheckoutReturnedConnectionMaxConnecting" } }, "poolOptions": { "maxConnecting": 2, "maxPoolSize": 10, - "waitQueueTimeoutMS": 5000 + "waitQueueTimeoutMS": 5000, + "appName": "PoolCheckoutReturnedConnectionMaxConnecting" }, "operations": [ { diff --git a/test/connection_monitoring/pool-clear-interrupting-pending-connections.json b/test/connection_monitoring/pool-clear-interrupting-pending-connections.json index c1fd746329..a8452d8f84 100644 --- a/test/connection_monitoring/pool-clear-interrupting-pending-connections.json +++ b/test/connection_monitoring/pool-clear-interrupting-pending-connections.json @@ -17,11 +17,13 @@ ], "closeConnection": false, "blockConnection": true, - "blockTimeMS": 10000 + "blockTimeMS": 10000, + "appName": "PoolClearInterruptingPendingConnections" } }, "poolOptions": { - "minPoolSize": 0 + "minPoolSize": 0, + "appName": "PoolClearInterruptingPendingConnections" }, "operations": [ { diff --git a/test/load_balancer/cursors.json b/test/load_balancer/cursors.json index 27aaddd5b6..b11bf2c6fa 100644 --- a/test/load_balancer/cursors.json +++ b/test/load_balancer/cursors.json @@ -385,7 +385,7 @@ ] }, { - "description": "pinned connections are returned after an network error during getMore", + "description": "pinned connections are not returned after an network error during getMore", "operations": [ { "name": "failPoint", @@ -449,7 +449,7 @@ "object": "testRunner", "arguments": { "client": "client0", - "connections": 0 + "connections": 1 } }, { @@ -677,7 +677,7 @@ ] }, { - "description": "pinned connections are returned to the pool after a non-network error on getMore", + "description": "pinned connections are not returned to the pool after a non-network error on getMore", "operations": [ { "name": "failPoint", @@ -733,7 +733,7 @@ "object": "testRunner", "arguments": { "client": "client0", - "connections": 0 + "connections": 1 } }, { diff --git a/test/load_balancer/sdam-error-handling.json b/test/load_balancer/sdam-error-handling.json index 41bc90be7f..2107afe5b3 100644 --- a/test/load_balancer/sdam-error-handling.json +++ b/test/load_balancer/sdam-error-handling.json @@ -372,6 +372,9 @@ { "connectionCreatedEvent": {} }, + { + "poolClearedEvent": {} + }, { "connectionClosedEvent": { "reason": "error" @@ -381,9 +384,6 @@ "connectionCheckOutFailedEvent": { "reason": "connectionError" } - }, - { - "poolClearedEvent": {} } ] } diff --git a/test/server_selection_logging/operation-id.json b/test/server_selection_logging/operation-id.json index ccc2623166..72ebff60d8 100644 --- a/test/server_selection_logging/operation-id.json +++ b/test/server_selection_logging/operation-id.json @@ -197,7 +197,7 @@ } }, { - "level": "debug", + "level": "info", "component": "serverSelection", "data": { "message": "Waiting for suitable server to become available", @@ -383,7 +383,7 @@ } }, { - "level": "debug", + "level": "info", "component": "serverSelection", "data": { "message": "Waiting for suitable server to become available", diff --git a/test/server_selection_logging/replica-set.json b/test/server_selection_logging/replica-set.json index 830b1ea51a..5eba784bf2 100644 --- a/test/server_selection_logging/replica-set.json +++ b/test/server_selection_logging/replica-set.json @@ -184,7 +184,7 @@ } }, { - "level": "debug", + "level": "info", "component": "serverSelection", "data": { "message": "Waiting for suitable server to become available", diff --git a/test/server_selection_logging/sharded.json b/test/server_selection_logging/sharded.json index 346c050f9e..d42fba9100 100644 --- a/test/server_selection_logging/sharded.json +++ b/test/server_selection_logging/sharded.json @@ -193,7 +193,7 @@ } }, { - "level": "debug", + "level": "info", "component": "serverSelection", "data": { "message": "Waiting for suitable server to become available", diff --git a/test/server_selection_logging/standalone.json b/test/server_selection_logging/standalone.json index fa01ad9911..3b3eddd841 100644 --- a/test/server_selection_logging/standalone.json +++ b/test/server_selection_logging/standalone.json @@ -191,7 +191,7 @@ } }, { - "level": "debug", + "level": "info", "component": "serverSelection", "data": { "message": "Waiting for suitable server to become available",