Log when a request is retried due to an OSError.

susodapop · susodapop · commit 38411a8c0ed8 · 2022-08-04T10:20:39.000-05:00
Emit warnings for unexpected OSError codes

Signed-off-by: Jesse Whitehouse &lt;jesse@whitehouse.dev&gt;
diff --git a/src/databricks/sql/thrift_backend.py b/src/databricks/sql/thrift_backend.py
@@ -1,4 +1,5 @@
 from decimal import Decimal
+import errno
 import logging
 import math
 import time
@@ -304,6 +305,27 @@ def attempt_request(attempt):
                 gos_name = TCLIServiceClient.GetOperationStatus.__name__
                 if method.__name__ == gos_name:
                     retry_delay = bound_retry_delay(attempt, self._retry_delay_default)
+
+                    # fmt: off
+                    # The built-in errno package encapsulates OSError codes, which are OS-specific.
+                    # log.info for errors we believe are not unusual or unexpected. log.warn for
+                    # for others like EEXIST, EBADF, ERANGE which are not expected in this context.
+                                            # | Debian | Darwin |
+                    info_errs = [           # |--------|--------|         
+                        errno.ESHUTDOWN,    # |   32   |   32   |
+                        errno.EAFNOSUPPORT, # |   97   |   47   |
+                        errno.ECONNRESET,   # |   104  |   54   |
+                        errno.ETIMEDOUT,    # |   110  |   60   |
+                    ]
+
+                    # fmt: on
+                    log_string = (
+                        f"{gos_name} failed with code {err.errno} and will attempt to retry"
+                    )
+                    if err.errno in info_errs:
+                        logger.info(log_string)
+                    else:
+                        logger.warning(log_string)
             except Exception as err:
                 error = err
                 retry_delay = extract_retry_delay(attempt)
diff --git a/tests/unit/test_thrift_backend.py b/tests/unit/test_thrift_backend.py
@@ -975,13 +975,14 @@ def test_handle_execute_response_sets_active_op_handle(self):
     def test_make_request_will_retry_GetOperationStatus(
             self, mock_retry_policy, mock_GetOperationStatus, t_transport_class):
        
-        import thrift
+        import thrift, errno
         from databricks.sql.thrift_api.TCLIService.TCLIService import Client
         from databricks.sql.exc import RequestError
         from databricks.sql.utils import NoRetryReason
 
-        mock_GetOperationStatus.__name__ = "GetOperationStatus"
-        mock_GetOperationStatus.side_effect = TimeoutError(110)
+        this_gos_name = "GetOperationStatus"
+        mock_GetOperationStatus.__name__ = this_gos_name
+        mock_GetOperationStatus.side_effect = OSError(errno.ETIMEDOUT, "Connection timed out")
 
         protocol = thrift.protocol.TBinaryProtocol.TBinaryProtocol(t_transport_class)
         client = Client(protocol)
@@ -998,13 +999,30 @@ def test_make_request_will_retry_GetOperationStatus(
             443,
             "path", [],
             _retry_stop_after_attempts_count=EXPECTED_RETRIES,
-            _retry_delay_default=0.1)
+            _retry_delay_default=1)
+
 
         with self.assertRaises(RequestError) as cm:
             thrift_backend.make_request(client.GetOperationStatus, req)
 
         self.assertEqual(NoRetryReason.OUT_OF_ATTEMPTS.value, cm.exception.context["no-retry-reason"])
-        self.assertEqual(f'{EXPECTED_RETRIES}/{EXPECTED_RETRIES}', cm.exception.context["attempt"])    
+        self.assertEqual(f'{EXPECTED_RETRIES}/{EXPECTED_RETRIES}', cm.exception.context["attempt"])
+
+        # Unusual OSError code
+        mock_GetOperationStatus.side_effect = OSError(errno.EEXIST, "File does not exist")  
+
+        with self.assertLogs("databricks.sql.thrift_backend", level=logging.WARNING) as cm:
+            with self.assertRaises(RequestError):
+                thrift_backend.make_request(client.GetOperationStatus, req)
+
+        # There should be two warning log messages: one for each retry
+        self.assertEqual(len(cm.output), EXPECTED_RETRIES)
+        
+        # The warnings should be identical
+        self.assertEqual(cm.output[1], cm.output[0])
+        
+        # The warnings should include this text
+        self.assertIn(f"{this_gos_name} failed with code {errno.EEXIST} and will attempt to retry", cm.output[0])
     
     
     @patch("thrift.transport.THttpClient.THttpClient")
