diff --git a/samcli/commands/_utils/table_print.py b/samcli/commands/_utils/table_print.py index c2587c4491..de63af29a6 100644 --- a/samcli/commands/_utils/table_print.py +++ b/samcli/commands/_utils/table_print.py @@ -11,7 +11,9 @@ MIN_OFFSET = 20 -def pprint_column_names(format_string, format_kwargs, margin=None, table_header=None, color="yellow"): +def pprint_column_names( + format_string, format_kwargs, margin=None, table_header=None, color="yellow", display_sleep=False +): """ :param format_string: format string to be used that has the strings, minimum width to be replaced @@ -19,6 +21,7 @@ def pprint_column_names(format_string, format_kwargs, margin=None, table_header= :param margin: margin that is to be reduced from column width for columnar text. :param table_header: Supplied table header :param color: color supplied for table headers and column names. + :param display_sleep: flag to format table_header to include deployer's client_sleep :return: boilerplate table string """ @@ -59,7 +62,7 @@ def pprint_wrap(func): def wrap(*args, **kwargs): # The table is setup with the column names, format_string contains the column names. if table_header: - click.secho("\n" + table_header) + click.secho("\n" + table_header.format(args[0].client_sleep) if display_sleep else table_header) click.secho("-" * usable_width, fg=color) click.secho(format_string.format(*format_args, **format_kwargs), fg=color) click.secho("-" * usable_width, fg=color) diff --git a/samcli/lib/deploy/deployer.py b/samcli/lib/deploy/deployer.py index 6170232e36..f3cbadfa49 100644 --- a/samcli/lib/deploy/deployer.py +++ b/samcli/lib/deploy/deployer.py @@ -17,7 +17,7 @@ import sys import math -from collections import OrderedDict +from collections import OrderedDict, deque import logging import time from datetime import datetime @@ -53,7 +53,7 @@ } ) -DESCRIBE_STACK_EVENTS_TABLE_HEADER_NAME = "CloudFormation events from stack operations" +DESCRIBE_STACK_EVENTS_TABLE_HEADER_NAME = "CloudFormation events from stack operations (refresh every {} seconds)" DESCRIBE_CHANGESET_FORMAT_STRING = "{Operation:<{0}} {LogicalResourceId:<{1}} {ResourceType:<{2}} {Replacement:<{3}}" DESCRIBE_CHANGESET_DEFAULT_ARGS = OrderedDict( @@ -360,6 +360,7 @@ def get_last_event_time(self, stack_name): format_string=DESCRIBE_STACK_EVENTS_FORMAT_STRING, format_kwargs=DESCRIBE_STACK_EVENTS_DEFAULT_ARGS, table_header=DESCRIBE_STACK_EVENTS_TABLE_HEADER_NAME, + display_sleep=True, ) def describe_stack_events(self, stack_name, time_stamp_marker, **kwargs): """ @@ -377,45 +378,50 @@ def describe_stack_events(self, stack_name, time_stamp_marker, **kwargs): try: # Only sleep if there have been no retry_attempts time.sleep(0 if retry_attempts else self.client_sleep) - describe_stacks_resp = self._client.describe_stacks(StackName=stack_name) paginator = self._client.get_paginator("describe_stack_events") response_iterator = paginator.paginate(StackName=stack_name) - stack_status = describe_stacks_resp["Stacks"][0]["StackStatus"] - latest_time_stamp_marker = time_stamp_marker + new_events = deque() # event buffer for event_items in response_iterator: for event in event_items["StackEvents"]: - if event["EventId"] not in events and utc_to_timestamp(event["Timestamp"]) > time_stamp_marker: - events.add(event["EventId"]) - latest_time_stamp_marker = max( - latest_time_stamp_marker, utc_to_timestamp(event["Timestamp"]) - ) - row_color = self.deploy_color.get_stack_events_status_color(status=event["ResourceStatus"]) - pprint_columns( - columns=[ - event["ResourceStatus"], - event["ResourceType"], - event["LogicalResourceId"], - event.get("ResourceStatusReason", "-"), - ], - width=kwargs["width"], - margin=kwargs["margin"], - format_string=DESCRIBE_STACK_EVENTS_FORMAT_STRING, - format_args=kwargs["format_args"], - columns_dict=DESCRIBE_STACK_EVENTS_DEFAULT_ARGS.copy(), - color=row_color, - ) - # Skip already shown old event entries - elif utc_to_timestamp(event["Timestamp"]) <= time_stamp_marker: - time_stamp_marker = latest_time_stamp_marker + # Skip already shown old event entries or former deployments + if utc_to_timestamp(event["Timestamp"]) <= time_stamp_marker: break - else: # go to next loop if not break from inside loop - time_stamp_marker = latest_time_stamp_marker # update marker if all events are new + if event["EventId"] not in events: + events.add(event["EventId"]) + # Events are in reverse chronological order + # Pushing in front reverse the order to display older events first + new_events.appendleft(event) + else: # go to next loop (page of events) if not break from inside loop continue break # reached here only if break from inner loop! - if self._check_stack_not_in_progress(stack_status): - stack_change_in_progress = False - break + # Override timestamp marker with latest event (last in deque) + if len(new_events) > 0: + time_stamp_marker = utc_to_timestamp(new_events[-1]["Timestamp"]) + + for new_event in new_events: + row_color = self.deploy_color.get_stack_events_status_color(status=new_event["ResourceStatus"]) + pprint_columns( + columns=[ + new_event["ResourceStatus"], + new_event["ResourceType"], + new_event["LogicalResourceId"], + new_event.get("ResourceStatusReason", "-"), + ], + width=kwargs["width"], + margin=kwargs["margin"], + format_string=DESCRIBE_STACK_EVENTS_FORMAT_STRING, + format_args=kwargs["format_args"], + columns_dict=DESCRIBE_STACK_EVENTS_DEFAULT_ARGS.copy(), + color=row_color, + ) + # Skip events from another consecutive deployment triggered during sleep by another process + if self._is_root_stack_event(new_event) and self._check_stack_not_in_progress( + new_event["ResourceStatus"] + ): + stack_change_in_progress = False + break + # Reset retry attempts if iteration is a success to use client_sleep again retry_attempts = 0 except botocore.exceptions.ClientError as ex: @@ -426,6 +432,14 @@ def describe_stack_events(self, stack_name, time_stamp_marker, **kwargs): # Sleep in exponential backoff mode time.sleep(math.pow(self.backoff, retry_attempts)) + @staticmethod + def _is_root_stack_event(event: Dict) -> bool: + return bool( + event["ResourceType"] == "AWS::CloudFormation::Stack" + and event["StackName"] == event["LogicalResourceId"] + and event["PhysicalResourceId"] == event["StackId"] + ) + @staticmethod def _check_stack_not_in_progress(status: str) -> bool: return "IN_PROGRESS" not in status diff --git a/tests/unit/lib/deploy/test_deployer.py b/tests/unit/lib/deploy/test_deployer.py index 6f8895646a..4c2f2e2b31 100644 --- a/tests/unit/lib/deploy/test_deployer.py +++ b/tests/unit/lib/deploy/test_deployer.py @@ -1,8 +1,10 @@ from logging import captureWarnings +from operator import inv +from typing import Container, Iterable, Union import uuid import time import math -from datetime import datetime, timedelta +from datetime import datetime, timedelta, timezone from unittest import TestCase from unittest.mock import patch, MagicMock, ANY, call @@ -47,7 +49,17 @@ def wait(self, StackName, WaiterConfig): return -class TestDeployer(TestCase): +class CustomTestCase(TestCase): + def assertListSubset(self, l1: Iterable, l2: Union[Iterable, Container], msg=None) -> None: + """ + Assert l2 contains all items in l1. + Just like calling self.assertIn(l1[x], l2) in a loop. + """ + for x in l1: + self.assertIn(x, l2, msg) + + +class TestDeployer(CustomTestCase): def setUp(self): self.session = MagicMock() self.cloudformation_client = self.session.client("cloudformation") @@ -376,26 +388,45 @@ def test_get_last_event_time_unknown_last_time(self): self.assertEqual(last_stack_event_timestamp.second, current_timestamp.second) @patch("time.sleep") - def test_describe_stack_events(self, patched_time): - current_timestamp = datetime.utcnow() + @patch("samcli.lib.deploy.deployer.pprint_columns") + def test_describe_stack_events_chronological_order(self, patched_pprint_columns, patched_time): + start_timestamp = datetime(2022, 1, 1, 16, 42, 0, 0, timezone.utc) - self.deployer._client.describe_stacks = MagicMock( - side_effect=[ - {"Stacks": [{"StackStatus": "CREATE_IN_PROGRESS"}]}, - {"Stacks": [{"StackStatus": "CREATE_IN_PROGRESS"}]}, - {"Stacks": [{"StackStatus": "CREATE_COMPLETE_CLEANUP_IN_PROGRESS"}]}, - {"Stacks": [{"StackStatus": "CREATE_COMPLETE"}]}, - ] - ) self.deployer._client.get_paginator = MagicMock( return_value=MockPaginator( + # describe_stack_events is in reverse chronological order [ { "StackEvents": [ { + "StackId": "arn:aws:cloudformation:region:accountId:stack/test/uuid", "EventId": str(uuid.uuid4()), - "Timestamp": current_timestamp, - "ResourceStatus": "CREATE_IN_PROGRESS", + "StackName": "test", + "LogicalResourceId": "test", + "PhysicalResourceId": "arn:aws:cloudformation:region:accountId:stack/test/uuid", + "ResourceType": "AWS::CloudFormation::Stack", + "Timestamp": start_timestamp + timedelta(seconds=3), + "ResourceStatus": "CREATE_COMPLETE", + } + ] + }, + { + "StackEvents": [ + { + "EventId": str(uuid.uuid4()), + "Timestamp": start_timestamp + timedelta(seconds=2), + "ResourceStatus": "CREATE_COMPLETE", + "ResourceType": "kms", + "LogicalResourceId": "mykms", + } + ] + }, + { + "StackEvents": [ + { + "EventId": str(uuid.uuid4()), + "Timestamp": start_timestamp + timedelta(seconds=1), + "ResourceStatus": "CREATE_COMPLETE", "ResourceType": "s3", "LogicalResourceId": "mybucket", } @@ -405,7 +436,7 @@ def test_describe_stack_events(self, patched_time): "StackEvents": [ { "EventId": str(uuid.uuid4()), - "Timestamp": current_timestamp, + "Timestamp": start_timestamp, "ResourceStatus": "CREATE_IN_PROGRESS", "ResourceType": "kms", "LogicalResourceId": "mykms", @@ -416,72 +447,199 @@ def test_describe_stack_events(self, patched_time): "StackEvents": [ { "EventId": str(uuid.uuid4()), - "Timestamp": current_timestamp, - "ResourceStatus": "CREATE_COMPLETE", + "Timestamp": start_timestamp, + "ResourceStatus": "CREATE_IN_PROGRESS", "ResourceType": "s3", "LogicalResourceId": "mybucket", } ] }, + ] + ) + ) + + self.deployer.describe_stack_events("test", utc_to_timestamp(start_timestamp) - 1) + self.assertEqual(patched_pprint_columns.call_count, 5) + self.assertListSubset( + ["CREATE_IN_PROGRESS", "s3", "mybucket"], patched_pprint_columns.call_args_list[0][1]["columns"] + ) + self.assertListSubset( + ["CREATE_IN_PROGRESS", "kms", "mykms"], patched_pprint_columns.call_args_list[1][1]["columns"] + ) + self.assertListSubset( + ["CREATE_COMPLETE", "s3", "mybucket"], patched_pprint_columns.call_args_list[2][1]["columns"] + ) + self.assertListSubset( + ["CREATE_COMPLETE", "kms", "mykms"], patched_pprint_columns.call_args_list[3][1]["columns"] + ) + self.assertListSubset( + ["CREATE_COMPLETE", "AWS::CloudFormation::Stack", "test"], + patched_pprint_columns.call_args_list[4][1]["columns"], + ) + + @patch("time.sleep") + @patch("samcli.lib.deploy.deployer.pprint_columns") + def test_describe_stack_events_chronological_order_with_previous_event(self, patched_pprint_columns, patched_time): + start_timestamp = datetime(2022, 1, 1, 16, 42, 0, 0, timezone.utc) + last_event_timestamp = start_timestamp - timedelta(hours=6) + + self.deployer._client.get_paginator = MagicMock( + return_value=MockPaginator( + # describe_stack_events is in reverse chronological order + [ { "StackEvents": [ { + "StackId": "arn:aws:cloudformation:region:accountId:stack/test/uuid", "EventId": str(uuid.uuid4()), - "Timestamp": current_timestamp, - "ResourceStatus": "CREATE_COMPLETE", + "StackName": "test", + "LogicalResourceId": "test", + "PhysicalResourceId": "arn:aws:cloudformation:region:accountId:stack/test/uuid", + "ResourceType": "AWS::CloudFormation::Stack", + "Timestamp": start_timestamp + timedelta(seconds=3), + "ResourceStatus": "UPDATE_COMPLETE", + } + ] + }, + { + "StackEvents": [ + { + "EventId": str(uuid.uuid4()), + "Timestamp": start_timestamp + timedelta(seconds=2), + "ResourceStatus": "UPDATE_COMPLETE", + "ResourceType": "kms", + "LogicalResourceId": "mykms", + } + ] + }, + { + "StackEvents": [ + { + "EventId": str(uuid.uuid4()), + "Timestamp": start_timestamp + timedelta(seconds=1), + "ResourceStatus": "UPDATE_COMPLETE", + "ResourceType": "s3", + "LogicalResourceId": "mybucket", + } + ] + }, + { + "StackEvents": [ + { + "EventId": str(uuid.uuid4()), + "Timestamp": start_timestamp, + "ResourceStatus": "UPDATE_IN_PROGRESS", "ResourceType": "kms", "LogicalResourceId": "mykms", } ] }, + { + "StackEvents": [ + { + "EventId": str(uuid.uuid4()), + "Timestamp": start_timestamp, + "ResourceStatus": "UPDATE_IN_PROGRESS", + "ResourceType": "s3", + "LogicalResourceId": "mybucket", + } + ] + }, + # Last event (from a former deployment) + { + "StackEvents": [ + { + "StackId": "arn:aws:cloudformation:region:accountId:stack/test/uuid", + "EventId": str(uuid.uuid4()), + "StackName": "test", + "LogicalResourceId": "test", + "PhysicalResourceId": "arn:aws:cloudformation:region:accountId:stack/test/uuid", + "ResourceType": "AWS::CloudFormation::Stack", + "Timestamp": last_event_timestamp, + "ResourceStatus": "CREATE_COMPLETE", + } + ] + }, ] ) ) - self.deployer.describe_stack_events("test", time.time() - 1) + self.deployer.describe_stack_events("test", utc_to_timestamp(last_event_timestamp)) + self.assertEqual(patched_pprint_columns.call_count, 5) + self.assertListSubset( + ["UPDATE_IN_PROGRESS", "s3", "mybucket"], patched_pprint_columns.call_args_list[0][1]["columns"] + ) + self.assertListSubset( + ["UPDATE_IN_PROGRESS", "kms", "mykms"], patched_pprint_columns.call_args_list[1][1]["columns"] + ) + self.assertListSubset( + ["UPDATE_COMPLETE", "s3", "mybucket"], patched_pprint_columns.call_args_list[2][1]["columns"] + ) + self.assertListSubset( + ["UPDATE_COMPLETE", "kms", "mykms"], patched_pprint_columns.call_args_list[3][1]["columns"] + ) + self.assertListSubset( + ["UPDATE_COMPLETE", "AWS::CloudFormation::Stack", "test"], + patched_pprint_columns.call_args_list[4][1]["columns"], + ) @patch("time.sleep") @patch("samcli.lib.deploy.deployer.pprint_columns") def test_describe_stack_events_skip_old_event(self, patched_pprint_columns, patched_time): - current_timestamp = datetime.utcnow() + start_timestamp = datetime(2022, 1, 1, 16, 42, 0, 0, timezone.utc) + last_event_timestamp = start_timestamp - timedelta(hours=6) - self.deployer._client.describe_stacks = MagicMock( - side_effect=[ - {"Stacks": [{"StackStatus": "CREATE_IN_PROGRESS"}]}, - {"Stacks": [{"StackStatus": "CREATE_IN_PROGRESS"}]}, - {"Stacks": [{"StackStatus": "CREATE_COMPLETE_CLEANUP_IN_PROGRESS"}]}, - {"Stacks": [{"StackStatus": "CREATE_COMPLETE"}]}, - ] - ) sample_events = [ + # old deployment { "StackEvents": [ { + "StackId": "arn:aws:cloudformation:region:accountId:stack/test/uuid", "EventId": str(uuid.uuid4()), - "Timestamp": current_timestamp, + "StackName": "test", + "LogicalResourceId": "test", + "PhysicalResourceId": "arn:aws:cloudformation:region:accountId:stack/test/uuid", + "ResourceType": "AWS::CloudFormation::Stack", + "Timestamp": last_event_timestamp - timedelta(seconds=10), "ResourceStatus": "CREATE_IN_PROGRESS", - "ResourceType": "s3", - "LogicalResourceId": "mybucket", } ] }, { "StackEvents": [ { + "StackId": "arn:aws:cloudformation:region:accountId:stack/test/uuid", "EventId": str(uuid.uuid4()), - "Timestamp": current_timestamp + timedelta(seconds=10), - "ResourceStatus": "CREATE_IN_PROGRESS", - "ResourceType": "kms", - "LogicalResourceId": "mykms", + "StackName": "test", + "LogicalResourceId": "test", + "PhysicalResourceId": "arn:aws:cloudformation:region:accountId:stack/test/uuid", + "ResourceType": "AWS::CloudFormation::Stack", + "Timestamp": last_event_timestamp, + "ResourceStatus": "CREATE_COMPLETE", } ] }, + # new deployment { "StackEvents": [ { + "StackId": "arn:aws:cloudformation:region:accountId:stack/test/uuid", "EventId": str(uuid.uuid4()), - "Timestamp": current_timestamp + timedelta(seconds=20), - "ResourceStatus": "CREATE_COMPLETE", + "StackName": "test", + "LogicalResourceId": "test", + "PhysicalResourceId": "arn:aws:cloudformation:region:accountId:stack/test/uuid", + "ResourceType": "AWS::CloudFormation::Stack", + "Timestamp": start_timestamp, + "ResourceStatus": "UPDATE_IN_PROGRESS", + } + ] + }, + { + "StackEvents": [ + { + "EventId": str(uuid.uuid4()), + "Timestamp": start_timestamp + timedelta(seconds=10), + "ResourceStatus": "UPDATE_IN_PROGRESS", "ResourceType": "s3", "LogicalResourceId": "mybucket", } @@ -491,10 +649,24 @@ def test_describe_stack_events_skip_old_event(self, patched_pprint_columns, patc "StackEvents": [ { "EventId": str(uuid.uuid4()), - "Timestamp": current_timestamp + timedelta(seconds=30), - "ResourceStatus": "CREATE_COMPLETE", - "ResourceType": "kms", - "LogicalResourceId": "mykms", + "Timestamp": start_timestamp + timedelta(seconds=20), + "ResourceStatus": "UPDATE_COMPLETE", + "ResourceType": "s3", + "LogicalResourceId": "mybucket", + } + ] + }, + { + "StackEvents": [ + { + "StackId": "arn:aws:cloudformation:region:accountId:stack/test/uuid", + "EventId": str(uuid.uuid4()), + "StackName": "test", + "LogicalResourceId": "test", + "PhysicalResourceId": "arn:aws:cloudformation:region:accountId:stack/test/uuid", + "ResourceType": "AWS::CloudFormation::Stack", + "Timestamp": start_timestamp + timedelta(seconds=30), + "ResourceStatus": "UPDATE_COMPLETE", } ] }, @@ -502,95 +674,97 @@ def test_describe_stack_events_skip_old_event(self, patched_pprint_columns, patc invalid_event = {"StackEvents": [{}]} # if deployer() loop read this, KeyError would raise self.deployer._client.get_paginator = MagicMock( side_effect=[ - MockPaginator([sample_events[0]]), + MockPaginator([sample_events[0], invalid_event]), MockPaginator([sample_events[1], sample_events[0], invalid_event]), MockPaginator([sample_events[2], sample_events[1], invalid_event]), MockPaginator([sample_events[3], sample_events[2], invalid_event]), + MockPaginator([sample_events[4], sample_events[3], invalid_event]), + MockPaginator([sample_events[5], sample_events[4], invalid_event]), ] ) - self.deployer.describe_stack_events("test", time.time() - 1) + self.deployer.describe_stack_events("test", utc_to_timestamp(last_event_timestamp)) self.assertEqual(patched_pprint_columns.call_count, 4) - - @patch("samcli.lib.deploy.deployer.math") - @patch("time.sleep") - def test_describe_stack_events_exceptions(self, patched_time, patched_math): - - self.deployer._client.describe_stacks = MagicMock( - side_effect=[ - ClientError( - error_response={"Error": {"Message": "Rate Exceeded"}}, operation_name="describe_stack_events" - ), - ClientError( - error_response={"Error": {"Message": "Rate Exceeded"}}, operation_name="describe_stack_events" - ), - ClientError( - error_response={"Error": {"Message": "Rate Exceeded"}}, operation_name="describe_stack_events" - ), - ClientError( - error_response={"Error": {"Message": "Rate Exceeded"}}, operation_name="describe_stack_events" - ), - ] + self.assertListSubset( + ["UPDATE_IN_PROGRESS", "AWS::CloudFormation::Stack", "test"], + patched_pprint_columns.call_args_list[0][1]["columns"], + ) + self.assertListSubset( + ["UPDATE_COMPLETE", "AWS::CloudFormation::Stack", "test"], + patched_pprint_columns.call_args_list[3][1]["columns"], ) - # No exception raised, we return with a log message, this is because, - # the changeset is still getting executed, but displaying them is getting throttled. - self.deployer.describe_stack_events("test", time.time()) - self.assertEqual(patched_math.pow.call_count, 3) - self.assertEqual(patched_math.pow.call_args_list, [call(2, 1), call(2, 2), call(2, 3)]) - @patch("samcli.lib.deploy.deployer.math") @patch("time.sleep") - def test_describe_stack_events_resume_after_exceptions(self, patched_time, patched_math): - current_timestamp = datetime.utcnow() - - self.deployer._client.describe_stacks = MagicMock( - side_effect=[ - ClientError( - error_response={"Error": {"Message": "Rate Exceeded"}}, operation_name="describe_stack_events" - ), - ClientError( - error_response={"Error": {"Message": "Rate Exceeded"}}, operation_name="describe_stack_events" - ), - ClientError( - error_response={"Error": {"Message": "Rate Exceeded"}}, operation_name="describe_stack_events" - ), - {"Stacks": [{"StackStatus": "CREATE_IN_PROGRESS"}]}, - {"Stacks": [{"StackStatus": "CREATE_IN_PROGRESS"}]}, - {"Stacks": [{"StackStatus": "CREATE_COMPLETE_CLEANUP_IN_PROGRESS"}]}, - {"Stacks": [{"StackStatus": "CREATE_COMPLETE"}]}, - ] - ) + @patch("samcli.lib.deploy.deployer.pprint_columns") + def test_describe_stack_events_stop_at_first_not_in_progress(self, patched_pprint_columns, patched_time): + start_timestamp = datetime(2022, 1, 1, 16, 42, 0, 0, timezone.utc) self.deployer._client.get_paginator = MagicMock( return_value=MockPaginator( + # describe_stack_events is in reverse chronological order [ { "StackEvents": [ { + "StackId": "arn:aws:cloudformation:region:accountId:stack/test/uuid", "EventId": str(uuid.uuid4()), - "Timestamp": current_timestamp, - "ResourceStatus": "CREATE_IN_PROGRESS", + "StackName": "test", + "LogicalResourceId": "test", + "PhysicalResourceId": "arn:aws:cloudformation:region:accountId:stack/test/uuid", + "ResourceType": "AWS::CloudFormation::Stack", + "Timestamp": start_timestamp + timedelta(seconds=33), + "ResourceStatus": "UPDATE_COMLPETE", + }, + ] + }, + { + "StackEvents": [ + { + "EventId": str(uuid.uuid4()), + "Timestamp": start_timestamp + timedelta(seconds=32), + "ResourceStatus": "UPDATE_COMPLETE", "ResourceType": "s3", "LogicalResourceId": "mybucket", - } + }, + { + "EventId": str(uuid.uuid4()), + "Timestamp": start_timestamp + timedelta(seconds=31), + "ResourceStatus": "UPDATE_IN_PROGRESS", + "ResourceType": "s3", + "LogicalResourceId": "mybucket", + }, ] }, { "StackEvents": [ { + "StackId": "arn:aws:cloudformation:region:accountId:stack/test/uuid", "EventId": str(uuid.uuid4()), - "Timestamp": current_timestamp, - "ResourceStatus": "CREATE_IN_PROGRESS", - "ResourceType": "kms", - "LogicalResourceId": "mykms", - } + "StackName": "test", + "LogicalResourceId": "test", + "PhysicalResourceId": "arn:aws:cloudformation:region:accountId:stack/test/uuid", + "ResourceType": "AWS::CloudFormation::Stack", + "Timestamp": start_timestamp + timedelta(seconds=30), + "ResourceStatus": "UPDATE_IN_PROGRESS", + }, + { + # This event should stop the loop and ignore above events + "StackId": "arn:aws:cloudformation:region:accountId:stack/test/uuid", + "EventId": str(uuid.uuid4()), + "StackName": "test", + "LogicalResourceId": "test", + "PhysicalResourceId": "arn:aws:cloudformation:region:accountId:stack/test/uuid", + "ResourceType": "AWS::CloudFormation::Stack", + "Timestamp": start_timestamp + timedelta(seconds=3), + "ResourceStatus": "CREATE_COMPLETE", + }, ] }, { "StackEvents": [ { "EventId": str(uuid.uuid4()), - "Timestamp": current_timestamp, + "Timestamp": start_timestamp + timedelta(seconds=1), "ResourceStatus": "CREATE_COMPLETE", "ResourceType": "s3", "LogicalResourceId": "mybucket", @@ -601,10 +775,10 @@ def test_describe_stack_events_resume_after_exceptions(self, patched_time, patch "StackEvents": [ { "EventId": str(uuid.uuid4()), - "Timestamp": current_timestamp, - "ResourceStatus": "CREATE_COMPLETE", - "ResourceType": "kms", - "LogicalResourceId": "mykms", + "Timestamp": start_timestamp, + "ResourceStatus": "CREATE_IN_PROGRESS", + "ResourceType": "s3", + "LogicalResourceId": "mybucket", } ] }, @@ -612,73 +786,194 @@ def test_describe_stack_events_resume_after_exceptions(self, patched_time, patch ) ) + self.deployer.describe_stack_events("test", utc_to_timestamp(start_timestamp) - 1) + self.assertEqual(patched_pprint_columns.call_count, 3) + self.assertListSubset( + ["CREATE_IN_PROGRESS", "s3", "mybucket"], patched_pprint_columns.call_args_list[0][1]["columns"] + ) + self.assertListSubset( + ["CREATE_COMPLETE", "s3", "mybucket"], patched_pprint_columns.call_args_list[1][1]["columns"] + ) + self.assertListSubset( + ["CREATE_COMPLETE", "AWS::CloudFormation::Stack", "test"], + patched_pprint_columns.call_args_list[2][1]["columns"], + ) + + @patch("samcli.lib.deploy.deployer.math") + @patch("time.sleep") + def test_describe_stack_events_exceptions(self, patched_time, patched_math): + + self.deployer._client.get_paginator = MagicMock( + side_effect=[ + ClientError( + error_response={"Error": {"Message": "Rate Exceeded"}}, operation_name="describe_stack_events" + ), + ClientError( + error_response={"Error": {"Message": "Rate Exceeded"}}, operation_name="describe_stack_events" + ), + ClientError( + error_response={"Error": {"Message": "Rate Exceeded"}}, operation_name="describe_stack_events" + ), + ClientError( + error_response={"Error": {"Message": "Rate Exceeded"}}, operation_name="describe_stack_events" + ), + ] + ) + # No exception raised, we return with a log message, this is because, + # the changeset is still getting executed, but displaying them is getting throttled. self.deployer.describe_stack_events("test", time.time()) self.assertEqual(patched_math.pow.call_count, 3) self.assertEqual(patched_math.pow.call_args_list, [call(2, 1), call(2, 2), call(2, 3)]) - @patch("samcli.lib.deploy.deployer.math.pow", wraps=math.pow) + @patch("samcli.lib.deploy.deployer.math") @patch("time.sleep") - def test_describe_stack_events_reset_retry_on_success_after_exceptions(self, patched_time, patched_pow): - current_timestamp = datetime.utcnow() + def test_describe_stack_events_resume_after_exceptions(self, patched_time, patched_math): + start_timestamp = datetime(2022, 1, 1, 16, 42, 0, 0, timezone.utc) - self.deployer._client.describe_stacks = MagicMock( + self.deployer._client.get_paginator = MagicMock( side_effect=[ - {"Stacks": [{"StackStatus": "CREATE_IN_PROGRESS"}]}, ClientError( error_response={"Error": {"Message": "Rate Exceeded"}}, operation_name="describe_stack_events" ), ClientError( error_response={"Error": {"Message": "Rate Exceeded"}}, operation_name="describe_stack_events" ), - {"Stacks": [{"StackStatus": "CREATE_IN_PROGRESS"}]}, ClientError( error_response={"Error": {"Message": "Rate Exceeded"}}, operation_name="describe_stack_events" ), - {"Stacks": [{"StackStatus": "CREATE_COMPLETE"}]}, + MockPaginator( + [ + { + "StackEvents": [ + { + "StackId": "arn:aws:cloudformation:region:accountId:stack/test/uuid", + "EventId": str(uuid.uuid4()), + "StackName": "test", + "LogicalResourceId": "test", + "PhysicalResourceId": "arn:aws:cloudformation:region:accountId:stack/test/uuid", + "ResourceType": "AWS::CloudFormation::Stack", + "Timestamp": start_timestamp, + "ResourceStatus": "CREATE_COMPLETE", + }, + { + "EventId": str(uuid.uuid4()), + "Timestamp": start_timestamp, + "ResourceStatus": "CREATE_COMPLETE", + "ResourceType": "kms", + "LogicalResourceId": "mykms", + }, + ] + }, + { + "StackEvents": [ + { + "EventId": str(uuid.uuid4()), + "Timestamp": start_timestamp, + "ResourceStatus": "CREATE_COMPLETE", + "ResourceType": "s3", + "LogicalResourceId": "mybucket", + } + ] + }, + { + "StackEvents": [ + { + "EventId": str(uuid.uuid4()), + "Timestamp": start_timestamp, + "ResourceStatus": "CREATE_IN_PROGRESS", + "ResourceType": "kms", + "LogicalResourceId": "mykms", + } + ] + }, + { + "StackEvents": [ + { + "EventId": str(uuid.uuid4()), + "Timestamp": start_timestamp, + "ResourceStatus": "CREATE_IN_PROGRESS", + "ResourceType": "s3", + "LogicalResourceId": "mybucket", + } + ] + }, + ] + ), ] ) + self.deployer.describe_stack_events("test", utc_to_timestamp(start_timestamp) - 1) + self.assertEqual(patched_math.pow.call_count, 3) + self.assertEqual(patched_math.pow.call_args_list, [call(2, 1), call(2, 2), call(2, 3)]) + + @patch("samcli.lib.deploy.deployer.math.pow", wraps=math.pow) + @patch("time.sleep") + def test_describe_stack_events_reset_retry_on_success_after_exceptions(self, patched_time, patched_pow): + start_timestamp = datetime(2022, 1, 1, 16, 42, 0, 0, timezone.utc) + self.deployer._client.get_paginator = MagicMock( - return_value=MockPaginator( - [ - { - "StackEvents": [ - { - "EventId": str(uuid.uuid4()), - "Timestamp": current_timestamp, - "ResourceStatus": "CREATE_IN_PROGRESS", - "ResourceType": "s3", - "LogicalResourceId": "mybucket", - } - ] - }, - { - "StackEvents": [ - { - "EventId": str(uuid.uuid4()), - "Timestamp": current_timestamp, - "ResourceStatus": "CREATE_IN_PROGRESS", - "ResourceType": "kms", - "LogicalResourceId": "mykms", - } - ] - }, - { - "StackEvents": [ - { - "EventId": str(uuid.uuid4()), - "Timestamp": current_timestamp, - "ResourceStatus": "CREATE_COMPLETE", - "ResourceType": "s3", - "LogicalResourceId": "mybucket", - } - ] - }, - ] - ) + side_effect=[ + MockPaginator( + [ + { + "StackEvents": [ + { + "EventId": str(uuid.uuid4()), + "Timestamp": start_timestamp, + "ResourceStatus": "CREATE_IN_PROGRESS", + "ResourceType": "s3", + "LogicalResourceId": "mybucket", + }, + ] + }, + ] + ), + ClientError( + error_response={"Error": {"Message": "Rate Exceeded"}}, operation_name="describe_stack_events" + ), + ClientError( + error_response={"Error": {"Message": "Rate Exceeded"}}, operation_name="describe_stack_events" + ), + MockPaginator( + [ + { + "StackEvents": [ + { + "EventId": str(uuid.uuid4()), + "Timestamp": start_timestamp + timedelta(seconds=10), + "ResourceStatus": "CREATE_COMPLETE", + "ResourceType": "s3", + "LogicalResourceId": "mybucket", + } + ] + }, + ] + ), + ClientError( + error_response={"Error": {"Message": "Rate Exceeded"}}, operation_name="describe_stack_events" + ), + MockPaginator( + [ + { + "StackEvents": [ + { + "StackId": "arn:aws:cloudformation:region:accountId:stack/test/uuid", + "EventId": str(uuid.uuid4()), + "StackName": "test", + "LogicalResourceId": "test", + "PhysicalResourceId": "arn:aws:cloudformation:region:accountId:stack/test/uuid", + "ResourceType": "AWS::CloudFormation::Stack", + "Timestamp": start_timestamp + timedelta(seconds=20), + "ResourceStatus": "CREATE_COMPLETE", + }, + ] + }, + ] + ), + ] ) - self.deployer.describe_stack_events("test", time.time()) + self.deployer.describe_stack_events("test", utc_to_timestamp(start_timestamp) - 1) # There are 2 sleep call for exceptions (backoff + regular one at 0) self.assertEqual(patched_time.call_count, 9)