Events missing from launch output

[dboitnot]

Events missing from launch output

At some point after updating to Sceptre 3 events which appear in the web console are not included in the command output. It seems like if the stack update lasts long enough events will start to appear as they used to. If the stack launch is short then the command simply exits without feedback. This includes launch failures and roll-backs.

Your environment

• Sceptre, version 3.2.0
• Python 3.9.9
• Official Python 3.9.9 Docker image

Steps to reproduce

$ sceptre launch -y <stack>

This has been consistent across several accounts and versions of Sceptre. I've not yet identified which version the problem appears in.

Expected behaviour

After the Updating Stack message we expect to see a number of resource state-change events and end with the final state of the stack.

Actual behaviour

The process completes successfully, but events which appear in the web console are not output at the terminal:

$ sceptre launch -y prod/alb-internal.yaml
[2022-12-11 15:37:23] - prod/alb-internal - Launching Stack
[2022-12-11 15:37:24] - prod/alb-internal - Stack is in the UPDATE_COMPLETE state
[2022-12-11 15:37:24] - prod/alb-internal - Updating Stack
$

[dboitnot]

Digging into the code I suspect this might have something to do with how new events are filtered by timestamp:

sceptre/sceptre/plan/actions.py

Lines 852 to 855 in b73af2f

	new_events = [
	event for event in events
	if event["Timestamp"] > self.most_recent_event_datetime
	]

Where self.most_recent_event_datetime is initialized as:

sceptre/sceptre/plan/actions.py

Lines 787 to 789 in b73af2f

	self.most_recent_event_datetime = (
	datetime.now(tzutc()) - timedelta(seconds=3)
	)

When I comment out the if on line 854 the missing events are displayed (along with all prior events, obviously). Thinking this might be some clock weirdness from being in a container I evaluated the same expression inside and outside the container:

from datetime import datetime, timedelta
from dateutil.tz import tzutc
datetime.now(tzutc()) - timedelta(seconds=3)

I get the same times in both environments. After some more debug output it turns out my clock was 55 seconds ahead of AWS. /face_palm

[dboitnot]

It might be an improvement to initialize most_recent_event_datetime from the timestamp returned in response:

sceptre/sceptre/plan/actions.py

Lines 139 to 143 in b73af2f

	response = self.connection_manager.call(
	service="cloudformation",
	command="update_stack",
	kwargs=update_stack_kwargs
	)

We can extract a datetime from response by:

import email.utils as eut

start_time = datetime(*eut.parsedate(response["ResponseMetadata"]["HTTPHeaders"]["date"])[:6])

Then add an optional arg to _wait_for_completion:

    def _wait_for_completion(self, timeout=0, start_time=None):
        # ...
        self.most_recent_event_datetime = start_time or datetime.now(tzutc()) - timedelta(seconds=3)

This would make the retrieval of events independent of the local clock time.

[zaro0508]

sounds like an idea that's worth considering @dboitnot. Would you be willing to propose this in a PR?

[dboitnot]

Submitted #1275. It's failing on one unit test, though, but I'm not yet sure why.