[CLI] cdk deploy keeps calling describeStackEvents() for ~10 minutes after stack update

[kennu]

AWS CDK cdk deploy keeps calling describeStackEvents() for about 10 minutes after the CloudFormation stack has been successfully updated. It seems that CDK iterates through the entire event history of the stack in 5 second intervals. This makes the cdk deploy command take a very long time.

During the delay AWS CDK appears to be stuck in the "creating CloudFormation changeset" phase. In reality it has already created the changeset and applied it to the CloudFormation stack.

Reproduction Steps

You might need a CloudFormation stack that has a lot of event history to notice that AWS CDK iterates through all of them, causing the long delay.

You can see the describeStackEvents() iteration in debug output by using cdk deploy -v -v -v. It will keep showing entries like this (with different NextToken as it progresses):

[AWS cloudformation 200 5.499s 0 retries] describeStackEvents({
  StackName: 'webcat-registrar-dev',
  NextToken: 'f73Uze7bI/CdCn4qrXZ31hZlkhi5jbWWog...'
}) 

What did you expect to happen?

cdk deploy should finish in about 3 minutes.

What actually happened?

cdk deploy takes 14 minutes to complete.

Environment

• CLI Version : 1.56.0
• Framework Version: 1.56.0
• Node.js Version: v12.18.2
• OS : Linux (Ubuntu in Docker)
• Language (Version): TypeScript 3.9.7

Other

---

This is 🐛 Bug Report

[kennu]

Here is the sequence of debug output that occurs at the time the stack update finishes. After this the describeStackEvents() go on.

Stack webcat-registrar-dev has an ongoing operation in progress and is not stable (UPDATE_IN_PROGRESS)
[AWS cloudformation 200 6.336s 0 retries] describeStackEvents({
  StackName: 'webcat-registrar-dev',
  NextToken: 'xxx'
})
[AWS cloudformation 200 6.115s 0 retries] describeStackEvents({
  StackName: 'webcat-registrar-dev',
  NextToken: 'xxx'
})
[AWS cloudformation 200 5.294s 0 retries] describeStacks({ StackName: 'webcat-registrar-dev' })
Stack webcat-registrar-dev has an ongoing operation in progress and is not stable (UPDATE_IN_PROGRESS)
[AWS cloudformation 200 6.107s 0 retries] describeStackEvents({
  StackName: 'webcat-registrar-dev',
  NextToken: 'xxx'
})
[AWS cloudformation 200 5.29s 0 retries] describeStacks({ StackName: 'webcat-registrar-dev' })
Stack webcat-registrar-dev has an ongoing operation in progress and is not stable (UPDATE_COMPLETE_CLEANUP_IN_PROGRESS)
[AWS cloudformation 200 6.279s 0 retries] describeStackEvents({
  StackName: 'webcat-registrar-dev',
  NextToken: 'xxx'
})
[AWS cloudformation 200 6.309s 0 retries] describeStackEvents({
  StackName: 'webcat-registrar-dev',
  NextToken: 'xxx'
})
[AWS cloudformation 200 5.264s 0 retries] describeStacks({ StackName: 'webcat-registrar-dev' })
[AWS cloudformation 200 5.892s 0 retries] describeStackEvents({
  StackName: 'webcat-registrar-dev',
  NextToken: 'xxx'
})
[AWS cloudformation 200 5.994s 0 retries] describeStackEvents({
  StackName: 'webcat-registrar-dev',
  NextToken: 'xxx'
})
[AWS cloudformation 200 6.231s 0 retries] describeStackEvents({
  StackName: 'webcat-registrar-dev',
  NextToken: 'xxx'
})
[AWS cloudformation 200 6.36s 0 retries] describeStackEvents({
  StackName: 'webcat-registrar-dev',
  NextToken: 'xxx'
})

[shivlaks]

@kennu what's the stack status? does it end with UPDATE_COMPLETE_CLEANUP_IN_PROGRESS or does it transition to UPDATE_COMPLATE and then the cdk continues polling the stack?

at a cursory glance, it looks like the deploy status is not being classified as terminal so the CLI continues polling the stack until a terminal status is reached or it times out and gives up.

[kennu]

I think the stack final status is always UPDATE_COMPLETE. At least it was the last few times when I deployed and took the timings for this issue. Everything looks normal in AWS Console.

[kennu]

To my understanding, this is the recursive step that keeps calling describeStackEvents() forever:

aws-cdk/packages/aws-cdk/lib/api/util/cloudformation/stack-activity-monitor.ts

Line 197 in 16d2a48

// only read next page if all the events we read are new events. otherwise, we can rest.

I'm not quite sure about the logic there, but it seems like it just keeps iterating more and more events in my stack(s).

[rix0rrr]

If it's true that the paging token is not properly retained between polls, that would be pretty bad.

[kennu]

I think that the token is retained, but I just have a lot of events in that stack. So it takes a long time to iterate through all of them.

[kennu]

I double checked by adding a console.log() of every stack event that AWS CDK scans through. It really iterates all the stack events from today all the way back to 2019-04-07 when the stack was created.

Unless I misunderstand something, the whole logic of StackActivityMonitor.readEvents() is flawed. It will always scan through the entire stack event history, which keeps growing forever and making deployments slower and slower.

This is the last entry scanned before cdk deploy completes after 15 minutes of iterating events:

{
  StackId: 'arn:aws:cloudformation:eu-west-1:xxx:stack/webcat-registrar-dev/xxx',
  EventId: 'xxx',
  StackName: 'webcat-registrar-dev',
  LogicalResourceId: 'webcat-registrar-dev',
  PhysicalResourceId: 'arn:aws:cloudformation:eu-west-1:xxx:stack/webcat-registrar-dev/xxx',
  ResourceType: 'AWS::CloudFormation::Stack',
  Timestamp: 2019-04-07T00:12:50.615Z,
  ResourceStatus: 'REVIEW_IN_PROGRESS',
  ResourceStatusReason: 'User Initiated'
}
Stack webcat-registrar-dev has completed updating

[rix0rrr]

Yep. Turns out we are accidentally quadratic!