From 592929f9344893a9d224e8c064ddb757b9639536 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Rapha=C3=ABl=20Vandon?= Date: Wed, 28 Jun 2023 14:04:21 -0700 Subject: [PATCH 1/3] aws waiter util: log status info with error level on waiter error currently, the status info is not even logged on error, which is not great to debug. Rather than moving the log line above the check on error type, I think it makes sense to log at a different level to help users who'd have onfo logs disabled diagnose. --- airflow/providers/amazon/aws/utils/waiter_with_logging.py | 2 ++ 1 file changed, 2 insertions(+) diff --git a/airflow/providers/amazon/aws/utils/waiter_with_logging.py b/airflow/providers/amazon/aws/utils/waiter_with_logging.py index 5f66b01cd2a78..1e506927a1f43 100644 --- a/airflow/providers/amazon/aws/utils/waiter_with_logging.py +++ b/airflow/providers/amazon/aws/utils/waiter_with_logging.py @@ -71,6 +71,7 @@ def wait( break except WaiterError as error: if "terminal failure" in str(error): + log.error("%s: %s", failure_message, _LazyStatusFormatter(status_args, error.last_response)) raise AirflowException(f"{failure_message}: {error}") log.info("%s: %s", status_message, _LazyStatusFormatter(status_args, error.last_response)) @@ -122,6 +123,7 @@ async def async_wait( break except WaiterError as error: if "terminal failure" in str(error): + log.error("%s: %s", failure_message, _LazyStatusFormatter(status_args, error.last_response)) raise AirflowException(f"{failure_message}: {error}") log.info("%s: %s", status_message, _LazyStatusFormatter(status_args, error.last_response)) From 5200a35183d4e887a5ed0cd67a74ed09a91346e1 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Rapha=C3=ABl=20Vandon?= Date: Wed, 28 Jun 2023 14:58:50 -0700 Subject: [PATCH 2/3] fix tests --- .../amazon/aws/utils/test_waiter_with_logging.py | 16 ++++------------ 1 file changed, 4 insertions(+), 12 deletions(-) diff --git a/tests/providers/amazon/aws/utils/test_waiter_with_logging.py b/tests/providers/amazon/aws/utils/test_waiter_with_logging.py index 03427c2ac529a..e09655ca6822d 100644 --- a/tests/providers/amazon/aws/utils/test_waiter_with_logging.py +++ b/tests/providers/amazon/aws/utils/test_waiter_with_logging.py @@ -136,7 +136,7 @@ def test_wait_max_attempts_exceeded(self, mock_sleep, caplog): }, ) - mock_waiter.wait.call_count == 11 + assert mock_waiter.wait.call_count == 11 mock_sleep.assert_called_with(123) assert ( caplog.record_tuples @@ -165,6 +165,7 @@ def test_wait_with_failure(self, mock_sleep, caplog): last_response=generate_response("Failure"), ) mock_waiter.wait.side_effect = [error, error, error, failure_error] + with pytest.raises(AirflowException) as exc: wait( waiter=mock_waiter, @@ -175,6 +176,7 @@ def test_wait_with_failure(self, mock_sleep, caplog): status_message="test status message", status_args=["Status.State"], ) + assert "test failure message" in str(exc) mock_waiter.wait.assert_called_with( **{"test_arg": "test_value"}, @@ -183,17 +185,7 @@ def test_wait_with_failure(self, mock_sleep, caplog): }, ) assert mock_waiter.wait.call_count == 4 - assert ( - caplog.record_tuples - == [ - ( - "airflow.providers.amazon.aws.utils.waiter_with_logging", - logging.INFO, - "test status message: Pending", - ) - ] - * 3 - ) + assert caplog.messages == ["test status message: Pending"] * 3 + ["test failure message: Failure"] @mock.patch("time.sleep") def test_wait_with_list_response(self, mock_sleep, caplog): From 16c7f65db4ea18d8805b4db9022c59efeb35ad93 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Rapha=C3=ABl=20Vandon?= Date: Thu, 29 Jun 2023 10:29:12 -0700 Subject: [PATCH 3/3] more fixing --- .../providers/amazon/aws/utils/test_waiter_with_logging.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/tests/providers/amazon/aws/utils/test_waiter_with_logging.py b/tests/providers/amazon/aws/utils/test_waiter_with_logging.py index e09655ca6822d..2f753b84f3922 100644 --- a/tests/providers/amazon/aws/utils/test_waiter_with_logging.py +++ b/tests/providers/amazon/aws/utils/test_waiter_with_logging.py @@ -136,7 +136,7 @@ def test_wait_max_attempts_exceeded(self, mock_sleep, caplog): }, ) - assert mock_waiter.wait.call_count == 11 + assert mock_waiter.wait.call_count == 2 mock_sleep.assert_called_with(123) assert ( caplog.record_tuples @@ -271,7 +271,7 @@ def test_wait_with_incorrect_args(self, mock_sleep, caplog): "MaxAttempts": 1, }, ) - mock_waiter.wait.call_count == 3 + assert mock_waiter.wait.call_count == 3 mock_sleep.assert_called_with(123) assert ( caplog.record_tuples @@ -312,7 +312,7 @@ def test_wait_with_multiple_args(self, mock_sleep, caplog): status_message="test status message", status_args=["Clusters[0].Status", "Clusters[0].StatusDetails", "Clusters[0].ClusterName"], ) - mock_waiter.wait.call_count == 3 + assert mock_waiter.wait.call_count == 3 mock_sleep.assert_called_with(123) assert ( caplog.record_tuples