PYTHON-3926 Add more information to connection errors and timeouts #1375

NoahStapp · 2023-09-14T21:40:02Z

No description provided.

Jibola · 2023-09-18T13:48:25Z

pymongo/common.py

+    if "socketTimeout" in details:
+        result += f" socketTimeout: {details['socketTimeout']}ms,"
+    if "timeout" in details:
+        result += f" timeout: {details['timeout']}ms,"
+    if "connectTimeout" in details:
+        result += f" connectTimeout: {details['connectTimeout']}ms,"


NIT:

Suggested change

if "socketTimeout" in details:

result += f" socketTimeout: {details['socketTimeout']}ms,"

if "timeout" in details:

result += f" timeout: {details['timeout']}ms,"

if "connectTimeout" in details:

result += f" connectTimeout: {details['connectTimeout']}ms,"

for timeout in ["socketTimeout", "timeout", "connectTimeout"]:

if timeout in details:

result += f" {timeout}: {details[timeout]}ms,"

Jibola

Overall, this looks great and I love how concise an improvement it is!

Left some commentary, but only one blocking comment around topology

pymongo/common.py

pymongo/pool.py

NoahStapp · 2023-09-18T16:06:20Z

I just noticed that this doesn't cover the Connection socket timeouts like

mongo-python-driver/pymongo/pool.py

Line 956 in db526f7

self._raise_connection_failure(error)

and

mongo-python-driver/pymongo/pool.py

Line 972 in db526f7

self._raise_connection_failure(error)

and

mongo-python-driver/pymongo/pool.py

Line 982 in db526f7

self._raise_connection_failure(error)

We already have socket_timeout and connect_timeout in the Connection's PoolOptions, thoughts on adding timeout there as well? That will allow us to use those values without need for a MongoClientErrorHandler. toplogy may require more extensive refactoring if we want to include that always as well.

ShaneHarvey · 2023-09-19T19:29:09Z

pymongo/common.py

+    timeout = client.options.timeout
+    socket_timeout = client.options.pool_options.socket_timeout
+    connect_timeout = client.options.pool_options.connect_timeout
+    topology = client.topology_description.server_descriptions()


This should be client.topology_description which is what we include in ServerSelectionTimeoutError:

mongo-python-driver/pymongo/topology.py

Line 259 in 6f4e617

f"{self._error_message(selector)}, Timeout: {timeout}s, Topology Description: {self.description!r}"

ShaneHarvey · 2023-09-19T19:31:21Z

pymongo/common.py

+    connect_timeout = client.options.pool_options.connect_timeout
+    topology = client.topology_description.server_descriptions()
+    if timeout:
+        details["timeout"] = timeout * 1000


Would it make more sense to add _csot.get_timeout() here? That would reflect the last CSOT timeout that was set.

ShaneHarvey · 2023-09-19T19:31:49Z

pymongo/pool.py

@@ -391,13 +396,14 @@ def _raise_connection_failure(
    if msg_prefix:
        msg = msg_prefix + msg
    if isinstance(error, socket.timeout):
-        raise NetworkTimeout(msg) from error
+        print(f"DETAILS: {details}")


errant print here.

ShaneHarvey · 2023-09-19T19:35:19Z

pymongo/pool.py

+                timeout_details = None
+                if handler:
+                    timeout_details = _get_timeout_details(handler.client)
+                _raise_connection_failure(self.address, error, details=timeout_details)


Hmm is there a central place we could catch and re-raise these exceptions (rather than sprinkling format_timeout_details in various places)?

Ideally we'd be able to access the _MongoClientErrorHandler whenever we catch a timeout exception. Are there existing limitations to our internal network interfaces that prevent us from passing an instance of the handler around more widely? That would allow us to add details to far more timeout errors as well as centralize the logic required.

Following up @ShaneHarvey

I believe we do already wrap all operations with _MongoClientErrorHandler. Does that answer your question?

_MongoClientErrorHandler is only wrapped around _checkout and _run_operation in MongoClient, are those the only two operations relevant for this issue? If so, we could maybe move the logic in format_timeout_details into the error handler itself to centralize the processing.

Answered in Zoom but summarizing here:
Yes that's true but it's better we add the info at the point the exception is raised to ensure that event publishing and (soon) command logging also include the same info. If we catch and reraise the exception in _MongoClientErrorHandler then the events/logs will see a different error message than the user.

ShaneHarvey

Could you add a few tests for this behavior (asserting the error message includes the expected timeout info)?

ShaneHarvey · 2023-10-17T21:56:20Z

pymongo/pool.py

+    if timeout:
+        details["timeout"] = timeout * 1000
+    if socket_timeout:
+        details["socketTimeout"] = socket_timeout * 1000


Suggest socketTimeoutMS to match the URI option name.

ShaneHarvey · 2023-10-17T21:56:34Z

pymongo/pool.py

+    if socket_timeout:
+        details["socketTimeout"] = socket_timeout * 1000
+    if connect_timeout:
+        details["connectTimeout"] = connect_timeout * 1000


Suggest connectTimeoutMS to match the URI option name.

ShaneHarvey · 2023-10-17T22:00:52Z

pymongo/pool.py

+    socket_timeout = options.socket_timeout
+    connect_timeout = options.connect_timeout
+    if timeout:
+        details["timeout"] = timeout * 1000


I suspect "timeout" will be confusing to users. Perhaps "operation timeout"? Also if _csot.get_timeout is enabled then should we avoid adding socketTimeoutMS here since CSOT overrides socketTimeoutMS?

I went with operationTimeoutMS. Agreed, if CSOT is present then socketTimeoutMS should not be displayed.

ShaneHarvey · 2023-10-20T19:30:39Z

pymongo/pool.py

@@ -1549,7 +1586,8 @@ def connect(self, handler: Optional[_MongoClientErrorHandler] = None) -> Connect
                )

            if isinstance(error, (IOError, OSError, SSLError)):
-                _raise_connection_failure(self.address, error)
+                details = _get_timeout_details(self.opts)
+                _raise_connection_failure(self.address, error, timeout_details=details)


I see _configured_socket() also calls _raise_connection_failure(). Will this then add timeout_details to the error twice?

Good catch. I'll add a check in _raise_connection_failure to ensure it doesn't add timeout_details if they're already in the message.

ShaneHarvey · 2023-10-20T19:32:05Z

test/test_pooling.py

+
+        with self.assertRaises(Exception) as error:
+            client.db.t.find_one({"$where": delay(2)})
+            self.assertTrue(


This line needs to be de-indented otherwise it never runs.

ShaneHarvey · 2023-10-20T19:32:17Z

test/test_pooling.py

+
+        with self.assertRaises(Exception) as error:
+            client.db.t.find_one({"$where": delay(2)})
+            self.assertTrue("(configured timeouts: socketTimeoutMS: 1.0ms)" in str(error.exception))


ShaneHarvey · 2023-10-20T19:32:53Z

test/test_pooling.py

+        client = rs_or_single_client(timeoutMS=1)
+
+        with self.assertRaises(Exception) as error:
+            client.db.t.find_one({"$where": delay(2)})


We can use pymongo.timeout() where instead of creating a new client.

ShaneHarvey · 2023-10-20T19:34:32Z

pymongo/pool.py

+    socket_timeout = options.socket_timeout
+    connect_timeout = options.connect_timeout
+    if timeout:
+        details["operationTimeoutMS"] = timeout * 1000


Suggest remaining this to "timeoutMS" to match the URI option name. operationTimeoutMS doesn't appear anywhere else so this could be confusing.

Agreed it should match the URI option name. Is timeoutMS generally specific enough for users, or should we consider changing that option name to reflect its functionality better?

ShaneHarvey · 2023-10-20T19:35:30Z

test/test_pooling.py

+
+        with self.assertRaises(Exception) as error:
+            client.db.t.find_one({"$where": delay(2)})
+            self.assertTrue(


ShaneHarvey · 2023-10-20T19:36:31Z

test/test_pooling.py

+            self.assertTrue("(configured timeouts: socketTimeoutMS: 1.0ms)" in str(error.exception))
+
+    def test_connection_timeout_message(self):
+        client = rs_or_single_client("badhost", connectTimeoutMS=1, serverSelectionTimeoutMS=10)


Might need to use a failpoint to fail connection creation, otherwise this will result in a ServerSelectionTimeoutError, not a pool checkout error.

Wouldn't failing connection creation result in a ServerSelectionTimeoutError? In this case we want to have the client successfully select the server and then timeout when it tries to execute a command, correct?

EDIT: Actually for this specific test, I believe we want it to timeout when the client tries to connect to the server but after it's selected it.

ShaneHarvey · 2023-10-20T23:34:11Z

test/test_pooling.py

@@ -411,6 +411,41 @@ def find_one():
        # maxConnecting = unbounded: 30+ connections in ~0.140+ seconds
        print(len(pool.conns))

+    def test_csot_timeout_message(self):
+        with self.assertRaises(Exception) as error:
+            with timeout(0.001):


We'll need to increase this to 500ms to make sure there's enough time to actually run the command (instead of timing out in server selection for example).

ShaneHarvey · 2023-10-20T23:35:21Z

test/test_pooling.py

+        self.assertTrue("(configured timeouts: timeoutMS: 1.0ms" in str(error.exception))
+
+    def test_socket_timeout_message(self):
+        client = rs_or_single_client(socketTimeoutMS=0.01)


___________________ TestPooling.test_socket_timeout_message ____________________ self = <test.test_pooling.TestPooling testMethod=test_socket_timeout_message> def test_socket_timeout_message(self): client = rs_or_single_client(socketTimeoutMS=0.01) > with self.assertRaises(Exception) as error: E AssertionError: Exception not ### raised

Not sure how to explain the above error but could you increase the timeout to 500ms to make sure there's enough time to actually run the command (instead of timing out in server selection for example).

test/test_pooling.py

ShaneHarvey · 2023-10-30T17:57:25Z

test/test_pooling.py

+    def test_csot_timeout_message(self):
+        with self.assertRaises(Exception) as error:
+            with timeout(0.5):
+                self.client.db.t.find_one({"$where": delay(2)})


This is failing because the query ($where) will only be evaluated on non-empty collections. On missing/empty collections the server returns an empty result without executing the query. Same for test_socket_timeout_message below.

ShaneHarvey

Nice tests!

PYTHON-3926 Add more information to connection errors and timeouts

c5c7bfd

NoahStapp requested a review from a team as a code owner September 14, 2023 21:40

NoahStapp requested review from ShaneHarvey and removed request for a team September 14, 2023 21:40

Jibola reviewed Sep 18, 2023

View reviewed changes

Jibola requested changes Sep 18, 2023

View reviewed changes

pymongo/common.py Outdated Show resolved Hide resolved

pymongo/pool.py Outdated Show resolved Hide resolved

Streamline control flow + check for topology in formatting

85337d3

NoahStapp requested a review from Jibola September 18, 2023 15:55

ShaneHarvey requested changes Sep 19, 2023

View reviewed changes

NoahStapp added 3 commits September 22, 2023 12:36

Use CSOT timeouts

f481741

Remove errant print

c318e1f

Remove topology + consolidate handling into _raise_connection_failure

cdce419

NoahStapp requested a review from ShaneHarvey October 12, 2023 22:16

ShaneHarvey requested changes Oct 17, 2023

View reviewed changes

Address review comments

f30ea47

NoahStapp requested a review from ShaneHarvey October 17, 2023 23:22

ShaneHarvey requested changes Oct 20, 2023

View reviewed changes

Fix tests

9c28636

NoahStapp requested a review from ShaneHarvey October 20, 2023 21:32

NoahStapp added 4 commits October 20, 2023 14:41

Add annotation for failCommand

ac1b47e

Update test timeouts

be1dd5e

More test timeout updates

c9d0c7b

More test timeout updates

cd82e39

ShaneHarvey requested changes Oct 20, 2023

View reviewed changes

NoahStapp added 2 commits October 20, 2023 16:56

Raise test timeouts to 500ms

90eab27

Use failpoints for all connection error tests

a5daa28

ShaneHarvey requested changes Oct 30, 2023

View reviewed changes

NoahStapp added 2 commits October 30, 2023 11:32

Insert a document before doing timeout tests

d10d28a

Update minimum server version for test_connection_timeout_message

a3445be

NoahStapp requested a review from ShaneHarvey October 30, 2023 20:45

ShaneHarvey approved these changes Oct 30, 2023

View reviewed changes

NoahStapp merged commit 06653c9 into mongodb:master Oct 30, 2023
9 checks passed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

PYTHON-3926 Add more information to connection errors and timeouts #1375

PYTHON-3926 Add more information to connection errors and timeouts #1375

NoahStapp commented Sep 14, 2023

Jibola Sep 18, 2023

Jibola left a comment

NoahStapp commented Sep 18, 2023 •

edited

Loading

ShaneHarvey Sep 19, 2023

ShaneHarvey Sep 19, 2023

ShaneHarvey Sep 19, 2023

ShaneHarvey Sep 19, 2023

NoahStapp Sep 22, 2023 •

edited

Loading

NoahStapp Oct 10, 2023

ShaneHarvey Oct 11, 2023

NoahStapp Oct 12, 2023

ShaneHarvey Oct 12, 2023

ShaneHarvey left a comment

ShaneHarvey Oct 17, 2023

ShaneHarvey Oct 17, 2023

ShaneHarvey Oct 17, 2023

NoahStapp Oct 17, 2023

ShaneHarvey Oct 20, 2023

NoahStapp Oct 20, 2023

ShaneHarvey Oct 20, 2023

ShaneHarvey Oct 20, 2023

ShaneHarvey Oct 20, 2023

ShaneHarvey Oct 20, 2023

NoahStapp Oct 20, 2023

ShaneHarvey Oct 20, 2023

ShaneHarvey Oct 20, 2023

NoahStapp Oct 20, 2023 •

edited

Loading

ShaneHarvey Oct 20, 2023

ShaneHarvey Oct 20, 2023

ShaneHarvey Oct 30, 2023

ShaneHarvey left a comment

PYTHON-3926 Add more information to connection errors and timeouts #1375

PYTHON-3926 Add more information to connection errors and timeouts #1375

Conversation

NoahStapp commented Sep 14, 2023

Choose a reason for hiding this comment

Jibola left a comment

Choose a reason for hiding this comment

NoahStapp commented Sep 18, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

NoahStapp Sep 22, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ShaneHarvey left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

NoahStapp Oct 20, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ShaneHarvey left a comment

Choose a reason for hiding this comment

NoahStapp commented Sep 18, 2023 •

edited

Loading

NoahStapp Sep 22, 2023 •

edited

Loading

NoahStapp Oct 20, 2023 •

edited

Loading