SG-34910 Fixup SSLEOFError exception (#346)

* Minor fixup to make sure the attempt log shows up in any cases

* Add missing log

* Fixup close the connection and attempt a new request in case of SSLEOFError

* Remove deprecated code since the ssl module was introduced in Python 2.6

* Add a test for _make_call retry

Author: julien-lang

shotgun_api3/shotgun.py

@@ -42,6 +42,7 @@
 import os
 import re
 import copy
+import ssl
 import stat                                # used for attachment upload
 import sys
 import time
@@ -111,14 +112,6 @@ def _is_mimetypes_broken():
 have a self-signed internal certificate that isn't included in our certificate bundle, you may
 not require the added security provided by enforcing this.
 """
-try:
-    import ssl
-except ImportError as e:
-    if "SHOTGUN_FORCE_CERTIFICATE_VALIDATION" in os.environ:
-        raise ImportError("%s. SHOTGUN_FORCE_CERTIFICATE_VALIDATION environment variable prevents "
-                          "disabling SSL certificate validation." % e)
-    LOG.debug("ssl not found, disabling certificate validation")
-    NO_SSL_VALIDATION = True
 
 # ----------------------------------------------------------------------------
 # Version
@@ -3577,6 +3570,22 @@ def _make_call(self, verb, path, body, headers):
             attempt += 1
             try:
                 return self._http_request(verb, path, body, req_headers)
+            except ssl.SSLEOFError as e:
+                # SG-34910 - EOF occurred in violation of protocol (_ssl.c:2426)
+                # This issue seems to be related to proxy and keep alive.
+                # It looks like, sometimes, the proxy drops the connection on
+                # the TCP/TLS level despites the keep-alive. So we need to close
+                # the connection and make a new attempt.
+                LOG.debug("SSLEOFError: {}".format(e))
+                self._close_connection()
+                if attempt == max_rpc_attempts:
+                    LOG.debug("Request failed.  Giving up after %d attempts." % attempt)
+                    raise
+                # This is the exact same block as the "except Exception" bellow.
+                # We need to do it here because the next except will match it
+                # otherwise and will not re-attempt.
+                # When we drop support of Python 2 and we will probably drop the
+                # next except, we might want to remove this except too.
             except ssl_error_classes as e:
                 # Test whether the exception is due to the fact that this is an older version of
                 # Python that cannot validate certificates encrypted with SHA-2. If it is, then
@@ -3608,17 +3617,19 @@ def _make_call(self, verb, path, body, headers):
 
                 self._close_connection()
                 if attempt == max_rpc_attempts:
+                    LOG.debug("Request failed.  Giving up after %d attempts." % attempt)
                     raise
             except Exception:
                 self._close_connection()
                 if attempt == max_rpc_attempts:
                     LOG.debug("Request failed.  Giving up after %d attempts." % attempt)
                     raise
-                LOG.debug(
-                    "Request failed, attempt %d of %d.  Retrying in %.2f seconds..." %
-                    (attempt, max_rpc_attempts, rpc_attempt_interval)
-                )
-                time.sleep(rpc_attempt_interval)
+
+            LOG.debug(
+                "Request failed, attempt %d of %d.  Retrying in %.2f seconds..." %
+                (attempt, max_rpc_attempts, rpc_attempt_interval)
+            )
+            time.sleep(rpc_attempt_interval)
 
     def _http_request(self, verb, path, body, headers):
         """

tests/test_api.py

@@ -18,7 +18,9 @@
 import datetime
 import sys
 import os
+from . import mock
 from .mock import patch, MagicMock
+import ssl
 import time
 import types
 import uuid
@@ -1900,6 +1902,100 @@ def test_status_not_200(self, mock_request):
         mock_request.return_value = (response, {})
         self.assertRaises(shotgun_api3.ProtocolError, self.sg.find_one, 'Shot', [])
 
+    @patch('shotgun_api3.shotgun.Http.request')
+    def test_make_call_retry(self, mock_request):
+        response = MagicMock(name="response mock", spec=dict)
+        response.status = 200
+        response.reason = 'reason'
+        mock_request.return_value = (response, {})
+
+        bak_rpc_attempt_interval = self.sg.config.rpc_attempt_interval
+        self.sg.config.rpc_attempt_interval = 0
+        try:
+            # First: make the request raise a consistent exception
+            mock_request.side_effect = Exception("not working")
+            with self.assertLogs(
+                'shotgun_api3', level='DEBUG'
+            ) as cm1, self.assertRaises(
+                Exception
+            ) as cm2:
+                self.sg.info()
+
+            self.assertEqual(cm2.exception.args[0], "not working")
+            log_content = "\n".join(cm1.output)
+            for i in [1,2]:
+                self.assertIn(
+                    f"Request failed, attempt {i} of 3.  Retrying",
+                    log_content,
+                )
+            self.assertIn(
+                "Request failed.  Giving up after 3 attempts.",
+                log_content,
+            )
+
+            # Then, make the exception happening only once and prove the
+            # retry works
+            def my_side_effect(*args, **kwargs):
+                try:
+                    if my_side_effect.counter<1:
+                        raise Exception("not working")
+
+                    return mock.DEFAULT
+                finally:
+                    my_side_effect.counter += 1
+
+            my_side_effect.counter = 0
+            mock_request.side_effect = my_side_effect
+            with self.assertLogs('shotgun_api3', level='DEBUG') as cm:
+                self.assertIsInstance(
+                    self.sg.info(),
+                    dict,
+                )
+
+            log_content = "\n".join(cm.output)
+            self.assertIn(
+                "Request failed, attempt 1 of 3.  Retrying",
+                log_content,
+            )
+            self.assertNotIn(
+                "Request failed, attempt 2 of 3.  Retrying",
+                log_content,
+            )
+
+            # Last: raise a SSLEOFError exception - SG-34910
+            def my_side_effect2(*args, **kwargs):
+                try:
+                    if my_side_effect2.counter<1:
+                        raise ssl.SSLEOFError(
+                            "EOF occurred in violation of protocol (_ssl.c:2426)"
+                        )
+
+                    return mock.DEFAULT
+                finally:
+                    my_side_effect2.counter += 1
+
+            my_side_effect2.counter = 0
+            mock_request.side_effect = my_side_effect2
+
+            with self.assertLogs('shotgun_api3', level='DEBUG') as cm:
+                self.assertIsInstance(
+                    self.sg.info(),
+                    dict,
+                )
+
+            log_content = "\n".join(cm.output)
+            self.assertIn("SSLEOFError", log_content)
+            self.assertIn(
+                "Request failed, attempt 1 of 3.  Retrying",
+                log_content,
+            )
+            self.assertNotIn(
+                "Request failed, attempt 2 of 3.  Retrying",
+                log_content,
+            )
+        finally:
+            self.sg.config.rpc_attempt_interval = bak_rpc_attempt_interval
+
     @patch('shotgun_api3.shotgun.Http.request')
     def test_sha2_error(self, mock_request):
         # Simulate the exception raised with SHA-2 errors