Repository: aws/aws-sam-cli

Issue:
Bug: deploy with large SAM_CLI_POLL_DELAY has a wrong display (nightly)
### Description:
_Not a breaking bug, more like a display and timing bug_

If we use the feature from my last PR #3500, using `SAM_CLI_POLL_DELAY` with a large delay like a minute, the events retrieved during the poll will be displayed in reverse order (because `describe-stack-events` is in reverse chronological order).

Also during the sleep, the deployment can end and another process could start another deploy so the stack will be `IN_PROGRESS` again and when the first `sam deploy` wakes up it misses the end of the first deployment and will keep running and catch the events of the second deployment.


### Steps to reproduce:
Use [`sam-cli-nightly`](https://github.com/aws/aws-sam-cli/releases/tag/sam-cli-nightly)
`SAM_CLI_POLL_DELAY=60 sam deploy ...`

Check on `cloudformation` that the stack completes and while the first CLI is still running (sleeping)
Run `sam deploy ...` again in another tty.


### Observed result:
Wrong order and display 2 deployments
```
-------------------------------------------------------------------------------------------------------------------------
ResourceStatus                 ResourceType                   LogicalResourceId              ResourceStatusReason
-------------------------------------------------------------------------------------------------------------------------
UPDATE_COMPLETE_CLEANUP_IN_P   AWS::CloudFormation::Stack     my-stack                       -
ROGRESS
UPDATE_COMPLETE                AWS::CloudFormation::Stack     AsyncLambdaApp                 -
UPDATE_IN_PROGRESS             AWS::CloudFormation::Stack     AsyncLambdaApp                 -
UPDATE_COMPLETE                AWS::CloudFormation::Stack     DynamoApp                      -
UPDATE_IN_PROGRESS             AWS::CloudFormation::Stack     DynamoApp                      -
UPDATE_IN_PROGRESS             AWS::CloudFormation::Stack     AsyncLambdaApp                 -
UPDATE_COMPLETE                AWS::CloudFormation::Stack     DynamoApp                      -
UPDATE_IN_PROGRESS             AWS::CloudFormation::Stack     DynamoApp                      -
UPDATE_IN_PROGRESS             AWS::CloudFormation::Stack     my-stack                       User Initiated
UPDATE_COMPLETE                AWS::CloudFormation::Stack     my-stack                       -
UPDATE_COMPLETE                AWS::CloudFormation::Stack     DynamoApp                      -
UPDATE_COMPLETE                AWS::CloudFormation::Stack     AsyncLambdaApp                 -
UPDATE_COMPLETE                AWS::CloudFormation::Stack     my-stack                       -
UPDATE_COMPLETE                AWS::CloudFormation::Stack     DynamoApp                      -
UPDATE_COMPLETE                AWS::CloudFormation::Stack     AsyncLambdaApp                 -
UPDATE_COMPLETE_CLEANUP_IN_P   AWS::CloudFormation::Stack     my-stack                       -
ROGRESS
UPDATE_COMPLETE                AWS::CloudFormation::Stack     AsyncLambdaApp                 -
-------------------------------------------------------------------------------------------------------------------------
```


### Expected result:

```
-------------------------------------------------------------------------------------------------------------------------
ResourceStatus                 ResourceType                   LogicalResourceId              ResourceStatusReason
-------------------------------------------------------------------------------------------------------------------------
UPDATE_IN_PROGRESS             AWS::CloudFormation::Stack     DynamoApp                      -
UPDATE_COMPLETE                AWS::CloudFormation::Stack     DynamoApp                      -
UPDATE_IN_PROGRESS             AWS::CloudFormation::Stack     AsyncLambdaApp                 -
UPDATE_COMPLETE                AWS::CloudFormation::Stack     AsyncLambdaApp                 -
UPDATE_COMPLETE_CLEANUP_IN_P   AWS::CloudFormation::Stack     my-stack                       -
ROGRESS
UPDATE_COMPLETE                AWS::CloudFormation::Stack     DynamoApp                      -
UPDATE_COMPLETE                AWS::CloudFormation::Stack     AsyncLambdaApp                 -
UPDATE_COMPLETE                AWS::CloudFormation::Stack     my-stack                       -
-------------------------------------------------------------------------------------------------------------------------
```


### Additional environment details (Ex: Windows, Mac, Amazon Linux etc)

`[Unstable] Nightly Release v1.50.0.dev202205260901 - 2022-05-26`

---

### Solution

1: In [`describe_stack_events`](https://github.com/aws/aws-sam-cli/blob/aa75d721b1b463e0a4f2717524cfee80e9fac9d2/samcli/lib/deploy/deployer.py#L364) Instead of immediately print events, they should be buffered during pagination loop and reordered to print.

And in the reordered list find if the stack is not in progress to skip other deployments events (explained in https://github.com/aws/aws-sam-cli/issues/3911).
Maybe we could use `EventId` instead of `Timestamp` to have an exact comparison ?

2: Or maybe we could see with the `cloudformation` team if the [`DescribeStackEvents`](https://docs.aws.amazon.com/AWSCloudFormation/latest/APIReference/API_DescribeStackEvents.html) could be improved to pass the order and starting `EventId` or `Timestamp` and it does the ordering/filter for us.
(As the second solution might take some time, I'll go on the first one)

---

@jfuss @moelasmar @mndeveci What do you think about this ? I could work on a PR to get this and https://github.com/aws/aws-sam-cli/issues/3911 done quickly


Discussion:
jfuss: @BourgoisMickael Thanks for the quick response and pushing more fixes!

> Remove DescribeStacks request and rely on first not_in_progress event on the root stack to exit the loop

This seems reasonable. I am trying to figure out if there are any edge cases we introduce here. I assume we initially put this in place for "a reason", though not sure what that would be. So I just want to do some digging on this to see if the commit has any indications.

On the ordering:
I am a little confused. From my understanding it seems like the original ordering is consistent before and after your change, unless I am missing something. The reason we did it from top down, was so that we can stream the printing to console and you can read the changes as they come in. I think this change breaks that (from reading the code). Why do you expect the opposite here? What I am really trying to understand is what happened for the ordering to change, and if that was on us or something else changed.
BourgoisMickael: Because `DesciribeStackEvents` reverse chronological order. So when you poll every 0.5s there will most likely by only one new event for each request and it's printed immediately.

When if a set a delay of 60s, during this time a lot of events will happen, so the `DescribeStackEvents` will return multiple new events with this latests on top, that's wy it needs reordering to print the olddest event first and the latest last
jfuss: @BourgoisMickael I see. So it all has to do with the polling time. Sorry I did not connect those dots initially. 


I hate diffs, makes changes harder to read sometimes. I see what is happening now. There is a while "stack is in progress" do thing going on. Which allows for the streaming. Or at least keeps the same thing we had before in how we "streamed".


Patch:
diff --git a/samcli/commands/_utils/table_print.py b/samcli/commands/_utils/table_print.py
index c2587c44..de63af29 100644
--- a/samcli/commands/_utils/table_print.py
+++ b/samcli/commands/_utils/table_print.py
@@ -11,7 +11,9 @@ import click
 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_column_names(format_string, format_kwargs, margin=None, table_header=
         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 6170232e..f3cbadfa 100644
--- a/samcli/lib/deploy/deployer.py
+++ b/samcli/lib/deploy/deployer.py
@@ -17,7 +17,7 @@ Cloudformation deploy class which also streams events and changeset information
 
 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_DEFAULT_ARGS = OrderedDict(
     }
 )
 
-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 @@ class Deployer:
         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 @@ class Deployer:
             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 @@ class Deployer:
                 # 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


Test patch:
diff --git a/tests/unit/lib/deploy/test_deployer.py b/tests/unit/lib/deploy/test_deployer.py
index 6f889564..4c2f2e2b 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 @@ class MockCreateUpdateWaiter:
         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 @@ class TestDeployer(TestCase):
         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 @@ class TestDeployer(TestCase):
                         "StackEvents": [
                             {
                                 "EventId": str(uuid.uuid4()),
-                                "Timestamp": current_timestamp,
+                                "Timestamp": start_timestamp,
                                 "ResourceStatus": "CREATE_IN_PROGRESS",
                                 "ResourceType": "kms",
                                 "LogicalResourceId": "mykms",
@@ -416,72 +447,199 @@ class TestDeployer(TestCase):
                         "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 @@ class TestDeployer(TestCase):
                 "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 @@ class TestDeployer(TestCase):
         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 @@ class TestDeployer(TestCase):
                         "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 @@ class TestDeployer(TestCase):
             )
         )
 
+        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)