SG-38959 improvements

docs/cookbook/usage_tips.rst

@@ -236,26 +236,38 @@ automatically set whenever an entity is created or updated.
 Logging Messages from the API
 *****************************
 
-The API uses standard python logging but does not define a handler.
+The library uses the standard Python logging module under the logger name
+``shotgun_api3``. Developers are free to configure logging handlers as they see
+fit in their applications.
 
 To see the logging output in stdout, define a streamhandler in your script::
 
     import logging
-    import shotgun_api3 as shotgun
-    logging.basicConfig(level=logging.DEBUG)
+    logging.basicConfig()
+
+    import shotgun_api3
+
+    sg_log = logging.getLogger("shotgun_api3")
+    sg_log.setLevel(logging.DEBUG)
+
 
 To write logging output from the Flow Production Tracking API to a file, define a file handler in your script::
 
     import logging
-    import shotgun_api3 as shotgun
-    logging.basicConfig(level=logging.DEBUG, filename='/path/to/your/log')
+    logging.basicConfig(filename="/path/to/your/log")
+
+    import shotgun_api3
+
+    sg_log = logging.getLogger("shotgun_api3")
+    sg_log.setLevel(logging.DEBUG)
+
 
 To suppress the logging output from the API in a script which uses logging, set the level of the
 Flow Production Tracking logger to a higher level::
 
     import logging
     import shotgun_api3 as shotgun
-    sg_log = logging.getLogger('shotgun_api3')
+    sg_log = logging.getLogger("shotgun_api3")
     sg_log.setLevel(logging.ERROR)
 
 *************

shotgun_api3/shotgun.py

@@ -360,7 +360,9 @@ def __init__(self, sg):
         :param sg: Shotgun connection.
         """
         self._sg = sg
+
         self.max_rpc_attempts = 3
+
         # rpc_attempt_interval stores the number of milliseconds to wait between
         # request retries.  By default, this will be 3000 milliseconds. You can
         # override this by setting this property on the config like so:
@@ -372,11 +374,15 @@ def __init__(self, sg):
         # In the case that the environment variable is already set, setting the
         # property on the config will override it.
         self.rpc_attempt_interval = 3000
-        # From http://docs.python.org/2.6/library/httplib.html:
+
+        # From https://docs.python.org/3.9/library/http.client.html:
         # If the optional timeout parameter is given, blocking operations
         # (like connection attempts) will timeout after that many seconds
         # (if it is not given, the global default timeout setting is used)
         self.timeout_secs = None
+
+        self.http_error_codes_to_retry = [502, 503, 504]  # Should we add 500 ??
+
         self.api_ver = "api3"
         self.convert_datetimes_to_utc = True
         self._records_per_page = None
@@ -460,8 +466,6 @@ class Shotgun(object):
     )
 
     _MULTIPART_UPLOAD_CHUNK_SIZE = 20000000
-    MAX_ATTEMPTS = 3  # Retries on failure
-    BACKOFF = 0.75  # Seconds to wait before retry, times the attempt number
 
     def __init__(
         self,
@@ -470,6 +474,7 @@ def __init__(
         api_key=None,
         convert_datetimes_to_utc=True,
         http_proxy=None,
+        http_error_codes_to_retry: None | list[int] = None,
         connect=True,
         ca_certs=None,
         login=None,
@@ -616,6 +621,28 @@ def __init__(
                 "got '%s'." % self.config.rpc_attempt_interval
             )
 
+        # Handle new config  parameter for retry on HTTP
+        config_value = os.environ.get("SHOTGUN_API_HTTP_ERROR_CODES_TO_RETRY")
+        if config_value:
+            values = config_value.strip()
+            # TODO how to pass an empty list to say we don't want to retry any errors?
+            adding_mode = False
+            if values.startswith("+"):
+                # If starts with a + that means we hadd the codes to the existing list
+                # Otherwise, we start with an empty list
+                adding_mode = True
+                values = values[1:].strip()
+
+            # TODO check if int all
+            codes = [int(code.strip()) for code in values.split(",")]
+
+            if not adding_mode:
+                self.config.http_error_codes_to_retry = []
+
+            self.config.http_error_codes_to_retry.extend(codes)
+        elif http_error_codes_to_retry is not None:
+            self.config.http_error_codes_to_retry = http_error_codes_to_retry
+
         global SHOTGUN_API_DISABLE_ENTITY_OPTIMIZATION
         if (
             os.environ.get("SHOTGUN_API_DISABLE_ENTITY_OPTIMIZATION", "0")
@@ -3637,8 +3664,16 @@ def _call_rpc(self, method, params, include_auth_params=True, first=False):
         if self.config.localized is True:
             req_headers["locale"] = "auto"
 
-        attempt = 1
-        while attempt <= self.MAX_ATTEMPTS:
+        max_rpc_attempts = self.config.max_rpc_attempts
+        rpc_attempt_interval = self.config.rpc_attempt_interval / 1000.0
+
+        attempt = 0
+        while attempt < max_rpc_attempts:
+            if attempt:
+                time.sleep(attempt * rpc_attempt_interval)
+
+            attempt += 1
+
             http_status, resp_headers, body = self._make_call(
                 "POST",
                 self.config.api_path,
@@ -3656,10 +3691,15 @@ def _call_rpc(self, method, params, include_auth_params=True, first=False):
                 # We've seen some rare instances of PTR returning 502 for issues that
                 # appear to be caused by something internal to PTR. We're going to
                 # allow for limited retries for those specifically.
-                if attempt != self.MAX_ATTEMPTS and e.errcode in [502, 504]:
-                    LOG.debug("Got a 502 or 504 response. Waiting and retrying...")
-                    time.sleep(float(attempt) * self.BACKOFF)
-                    attempt += 1
+                if (
+                    attempt < max_rpc_attempts
+                    and e.errcode in self.config.http_error_codes_to_retry
+                ):
+                    # TODO  if status[0] == 503:
+                    # errmsg = "Flow Production Tracking is currently down for maintenance or too busy to reply. Please try again later."
+                    LOG.debug(
+                        f"Got a {e.errcode} HTTP response. Waiting and retrying..."
+                    )
                     continue
                 elif e.errcode == 403:
                     # 403 is returned with custom error page when api access is blocked
@@ -3795,6 +3835,9 @@ def _make_call(self, verb, path, body, headers):
         rpc_attempt_interval = self.config.rpc_attempt_interval / 1000.0
 
         while attempt < max_rpc_attempts:
+            if attempt:
+                time.sleep(attempt * rpc_attempt_interval)
+
             attempt += 1
             try:
                 return self._http_request(verb, path, body, req_headers)
@@ -3814,6 +3857,7 @@ def _make_call(self, verb, path, body, headers):
                 if attempt == max_rpc_attempts:
                     LOG.debug("Request failed.  Giving up after %d attempts." % attempt)
                     raise
+                # TODO create only one attempt for SSL errors.
             except Exception as e:
                 self._close_connection()
                 LOG.debug(f"Request failed.  Reason: {e}", exc_info=True)
@@ -3823,7 +3867,6 @@ def _make_call(self, verb, path, body, headers):
                 "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):
         """
@@ -3854,12 +3897,7 @@ def _make_upload_request(self, request, opener):
         Open the given request object, return the
         response, raises URLError on protocol errors.
         """
-        try:
-            result = opener.open(request)
-
-        except urllib.error.HTTPError:
-            raise
-        return result
+        return opener.open(request)
 
     def _parse_http_status(self, status):
         """
@@ -3873,8 +3911,6 @@ def _parse_http_status(self, status):
 
         if status[0] >= 300:
             headers = "HTTP error from server"
-            if status[0] == 503:
-                errmsg = "Flow Production Tracking is currently down for maintenance or too busy to reply. Please try again later."
             raise ProtocolError(self.config.server, error_code, errmsg, headers)
 
         return
@@ -4341,30 +4377,48 @@ def _upload_data_to_storage(self, data, content_type, size, storage_url):
         :param str content_type: Content type of the data stream.
         :param int size: Number of bytes in the data stream.
         :param str storage_url: Target URL for the uploaded file.
-        :returns: upload url.
+        :returns: upload url - NO! Return the AWS object ID.
         :rtype: str
         """
 
-        attempt = 1
-        while attempt <= self.MAX_ATTEMPTS:
+        ## TODO - add unitests for those cases
+        # storage_url = "https://untrusted-root.badssl.com/"
+        # storage_url = "https://wrong.host.badssl.com/"
+        # storage_url = "https://expired.badssl.com/"
+
+        attempt = 0
+        max_rpc_attempts = self.config.max_rpc_attempts
+        rpc_attempt_interval = self.config.rpc_attempt_interval / 1000.0
+
+        while attempt <= max_rpc_attempts:
+            if attempt:
+                time.sleep(attempt * rpc_attempt_interval)
+
+            attempt += 1
+
             try:
                 opener = self._build_opener(urllib.request.HTTPHandler)
 
-                request = urllib.request.Request(storage_url, data=data)
-                request.add_header("Content-Type", content_type)
-                request.add_header("Content-Length", size)
-                request.get_method = lambda: "PUT"
+                request = urllib.request.Request(
+                    storage_url,
+                    method="PUT",
+                    headers={
+                        "Content-Type": content_type,
+                        "Content-Length": size,
+                    },
+                    data=data,
+                )
+
                 result = self._make_upload_request(request, opener)
 
-                LOG.debug("Completed request to %s" % request.get_method())
+                LOG.debug(f"Completed request to {safe_short_url(storage_url)}")
 
             except urllib.error.HTTPError as e:
-                if attempt != self.MAX_ATTEMPTS and e.code in [500, 503]:
-                    LOG.debug("Got a %s response. Waiting and retrying..." % e.code)
-                    time.sleep(float(attempt) * self.BACKOFF)
-                    attempt += 1
-                    continue
-                elif e.code in [500, 503]:
+                if e.code in self.config.http_error_codes_to_retry:
+                    if attempt < max_rpc_attempts:
+                        LOG.debug("Got a %s response. Waiting and retrying..." % e.code)
+                        continue
+
                     raise ShotgunError(
                         "Got a %s response when uploading to %s: %s"
                         % (e.code, storage_url, e)
@@ -4375,9 +4429,20 @@ def _upload_data_to_storage(self, data, content_type, size, storage_url):
                         % (storage_url, e)
                     )
             except urllib.error.URLError as e:
+                if isinstance(e.reason, ssl.SSLError):
+                    ssl_err = e.reason
+
+                    LOG.debug(
+                        f"Received an SSL error during request to {safe_short_url(storage_url)}"
+                    )
+
+                    if isinstance(ssl_err, ssl.SSLCertVerificationError):
+                        LOG.debug(f"SSL certificate error occurred: {ssl_err}")
+                    else:
+                        LOG.debug(f"SSL error occurred: {ssl_err}")
+                    raise
+
                 LOG.debug("Got a '%s' response. Waiting and retrying..." % e)
-                time.sleep(float(attempt) * self.BACKOFF)
-                attempt += 1
                 continue
             else:
                 break
@@ -4474,21 +4539,28 @@ def _send_form(self, url, params):
 
         params.update(self._auth_params())
 
-        attempt = 1
-        while attempt <= self.MAX_ATTEMPTS:
+        max_rpc_attempts = self.config.max_rpc_attempts
+        rpc_attempt_interval = self.config.rpc_attempt_interval / 1000.0
+
+        attempt = 0
+        while attempt < max_rpc_attempts:
+            if attempt:
+                time.sleep(attempt * rpc_attempt_interval)
+
+            attempt += 1
+
             # Perform the request
             try:
                 opener = self._build_opener(FormPostHandler)
                 resp = opener.open(url, params)
                 result = resp.read()
                 # response headers are in str(resp.info()).splitlines()
-            except urllib.error.URLError as e:
-                LOG.debug("Got a %s response. Waiting and retrying..." % e)
-                time.sleep(float(attempt) * self.BACKOFF)
-                attempt += 1
-                continue
             except urllib.error.HTTPError as e:
-                if e.code == 500:
+                if e.code in self.config.http_error_codes_to_retry:
+                    if attempt < max_rpc_attempts:
+                        LOG.debug("Got a %s response. Waiting and retrying..." % e.code)
+                        continue
+
                     raise ShotgunError(
                         "Server encountered an internal error. "
                         "\n%s\n(%s)\n%s\n\n"
@@ -4497,6 +4569,10 @@ def _send_form(self, url, params):
                 else:
                     raise ShotgunError("Unanticipated error occurred %s" % (e))
 
+            except urllib.error.URLError as e:
+                LOG.debug("Got a %s response. Waiting and retrying..." % e)
+                continue
+
             if isinstance(result, bytes):
                 result = result.decode("utf-8")
 
@@ -4684,3 +4760,23 @@ def _get_type_and_id_from_value(value):
         LOG.debug(f"Could not optimize entity value {value}")
 
     return value
+
+
+def safe_short_url(url: str, max_path_length: int = 80) -> str:
+    u = urllib.parse.urlparse(url)
+
+    # If the path is longer than the max_path_length, truncate it in the middle
+    if len(u.path) > max_path_length:
+        half_length = max_path_length // 2
+
+        u = u._replace(
+            path=u.path[: half_length - 3] + "[...]" + u.path[-half_length + 3 :]
+        )
+
+    return urllib.parse.urlunparse(
+        u._replace(
+            netloc=u.hostname,  # Sanitize possible in URL credentials - HTTP Basic Auth
+            query="",  # Sanitize possible in URL credentials - API keys
+            fragment="",
+        )
+    )

tests/test_client.py

@@ -470,6 +470,9 @@ def test_upload_s3_503(self):
             f"Call is repeated up to {self.sg.MAX_ATTEMPTS} times",
         )
 
+    # TODO change attempt num
+    # TODO add 504. in config
+
     def test_upload_s3_500(self):
         """
         Test 500 response is retried when uploading to S3.