Fix deploy with long poll delay events order and stop condition

samcli/commands/_utils/table_print.py

@@ -11,14 +11,17 @@
 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
     :param format_kwargs: dictionary that is supplied to the format_string to format the string
     :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)

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