-
Type:
Build Failure
-
Resolution: Done
-
Priority:
Unknown
-
None
-
Affects Version/s: None
-
Component/s: None
-
None
-
None
-
Python Drivers
-
None
-
None
-
None
-
None
-
None
-
None
Name of Failure:
test.test_connection_logging.TestConnectionLoggingConnectionPoolOptions.test_waitQueueTimeoutMS_should_be_included_in_connection_pool_created_message_when_specified
Link to task:
Context of when and why the failure occurred:
Known flaky test. The root cause here is that Pool events are published before the corresponding logs are. In the synchronous API, this can cause the following ordering issue in tests:
1. Test calls wait_until to poll for the event being published
2. Pool publishes the event
3. Before the log can be published, the thread running wait_until preempts the Pool's thread and sees that the event has been published. This causes the test to run its assertions, which fail since the log has not been emitted.
Stack trace:
[2026/05/06 08:50:19.626] FAILURE: AssertionError: 2 != 1 : expected [{'level': 'debug', 'component': 'connection', 'data': {'message': 'Connection pool created', 'serverHost': {'$$type': 'string'}, 'serverPort': {'$$type': ['int', 'long']}, 'waitQueueTimeoutMS': 10000}}, {'level': 'debug', 'component': 'connection', 'data': {'message': 'Connection pool ready', 'serverHost': {'$$type': 'string'}, 'serverPort': {'$$type': ['int', 'long']}}}] but got [{'level': 'debug', 'component': 'connection', 'data': {'message': 'Connection pool created', 'clientId': ObjectId('69fb61c657b07497d93cd9fa'), 'serverHost': 'localhost', 'serverPort': 27017, 'waitQueueTimeoutMS': 10000.0}}] ()
[2026/05/06 08:50:19.626] self = <test.test_connection_logging.TestConnectionLoggingConnectionPoolOptions testMethod=test_waitQueueTimeoutMS_should_be_included_in_connection_pool_created_message_when_specified>
[2026/05/06 08:50:19.626] def test_case(self):
[2026/05/06 08:50:19.626] > self.run_scenario(spec)
[2026/05/06 08:50:19.626] test/unified_format.py:1538:
[2026/05/06 08:50:19.626] _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
[2026/05/06 08:50:19.626] test/unified_format.py:1473: in run_scenario
[2026/05/06 08:50:19.626] self._run_scenario(spec, uri)
[2026/05/06 08:50:19.626] test/unified_format.py:1512: in _run_scenario
[2026/05/06 08:50:19.626] self.check_log_messages(spec["operations"], expect_log_messages)
[2026/05/06 08:50:19.626] test/unified_format.py:1416: in check_log_messages
[2026/05/06 08:50:19.626] self.assertEqual(
[2026/05/06 08:50:19.626] E AssertionError: 2 != 1 : expected [{'level': 'debug', 'component': 'connection', 'data': {'message': 'Connection pool created', 'serverHost': {'$$type': 'string'}, 'serverPort': {'$$type': ['int', 'long']}, 'waitQueueTimeoutMS': 10000}}, {'level': 'debug', 'component': 'connection', 'data': {'message': 'Connection pool ready', 'serverHost': {'$$type': 'string'}, 'serverPort': {'$$type': ['int', 'long']}}}] but got [{'level': 'debug', 'component': 'connection', 'data': {'message': 'Connection pool created', 'clientId': ObjectId('69fb61c657b07497d93cd9fa'), 'serverHost': 'localhost', 'serverPort': 27017, 'waitQueueTimeoutMS': 10000.0}}]