fix(toolkit-lib): throttled final event poll fails a successful deploy

packages/@aws-cdk/toolkit-lib/docs/message-registry.md

@@ -120,6 +120,7 @@ Please let us know by [opening an issue](https://github.com/aws/aws-cdk-cli/issu
 | `CDK_TOOLKIT_W5400` | Hotswap disclosure message | `warn` | n/a |
 | `CDK_TOOLKIT_E5001` | No stacks found | `error` | n/a |
 | `CDK_TOOLKIT_E5500` | Stack Monitoring error | `error` | {@link ErrorPayload} |
+| `CDK_TOOLKIT_W5500` | Stack events could not be read; the reported event log may be incomplete | `warn` | {@link ErrorPayload} |
 | `CDK_TOOLKIT_I6000` | Provides rollback times | `info` | {@link Duration} |
 | `CDK_TOOLKIT_I6100` | Stack rollback progress | `info` | {@link StackRollbackProgress} |
 | `CDK_TOOLKIT_E6001` | No stacks found | `error` | n/a |

packages/@aws-cdk/toolkit-lib/lib/api/io/private/messages.ts

@@ -348,6 +348,11 @@ export const IO = {
     description: 'Stack Monitoring error',
     interface: 'ErrorPayload',
   }),
+  CDK_TOOLKIT_W5500: make.warn<ErrorPayload>({
+    code: 'CDK_TOOLKIT_W5500',
+    description: 'Stack events could not be read; the reported event log may be incomplete',
+    interface: 'ErrorPayload',
+  }),
 
   // 6: Rollback (6xxx)
   CDK_TOOLKIT_I6000: make.info<Duration>({

packages/@aws-cdk/toolkit-lib/lib/api/stack-events/stack-activity-monitor.ts

@@ -220,7 +220,6 @@ export class StackActivityMonitor {
     try {
       this.readPromise = this.readNewEvents(this.monitorId);
       await this.readPromise;
-      this.readPromise = undefined;
 
       // We might have been stop()ped while the network call was in progress.
       if (!this.monitorId) {
@@ -231,6 +230,9 @@ export class StackActivityMonitor {
         util.format('Error occurred while monitoring stack: %s', e),
         { error: e as any },
       ));
+    } finally {
+      // Clear on both paths, so `readPromise` only ever holds a read that is still in flight.
+      this.readPromise = undefined;
     }
     this.scheduleNextTick();
   }
@@ -287,11 +289,23 @@ export class StackActivityMonitor {
     // the moment we were sure we weren't going to get any new events anymore
     // so we need to do a new one anyway. Need to wait for this one though
     // because our state is single-threaded.
-    if (this.readPromise) {
+    try {
       await this.readPromise;
+    } catch {
+      // A failure of the in-flight poll has already been reported by tick().
     }
 
-    await this.readNewEvents(monitorId);
+    // Reading events only completes the event log shown to the user; it cannot change
+    // whether the monitored operation succeeded. Warn that the log may be short instead
+    // of letting the failure propagate out of stop().
+    try {
+      await this.readNewEvents(monitorId);
+    } catch (e) {
+      await this.ioHelper.notify(IO.CDK_TOOLKIT_W5500.msg(
+        util.format('Error occurred during final stack event poll, event log may be incomplete: %s', e),
+        { error: e as any },
+      ));
+    }
   }
 
   /**

packages/@aws-cdk/toolkit-lib/test/api/deployments/cloudformation-deployments.test.ts

@@ -1102,6 +1102,26 @@ test('rollback stack allows rolling back from UPDATE_FAILED', async () => {
   expect(mockCloudFormationClient).toHaveReceivedCommand(RollbackStackCommand);
 });
 
+test('rollback stack is not failed by a throttled stack event poll', async () => {
+  // GIVEN - reading stack events fails throughout, including the final poll in monitor.stop()
+  givenStacks({
+    '*': { template: {}, stackStatus: 'UPDATE_FAILED' },
+  });
+  mockCloudFormationClient.on(DescribeStackEventsCommand).rejects(
+    Object.assign(new Error('Rate exceeded'), { name: 'Throttling' }),
+  );
+
+  // WHEN
+  const response = await deployments.rollbackStack({
+    stack: testStack({ stackName: 'boop' }),
+    validateBootstrapStackVersion: false,
+  });
+
+  // THEN - the rollback succeeded, and the final poll failure was only reported
+  expect(response).toMatchObject({ success: true });
+  ioHost.expectMessage({ level: 'warn', containing: 'Error occurred during final stack event poll' });
+});
+
 test('rollback stack allows continue rollback from UPDATE_ROLLBACK_FAILED', async () => {
   // GIVEN
   givenStacks({

packages/@aws-cdk/toolkit-lib/test/api/deployments/deploy-stack-event-poll-failures.test.ts

@@ -0,0 +1,117 @@
+import type { CloudFormationStackArtifact } from '@aws-cdk/cloud-assembly-api';
+import { deployStack, destroyStack } from '../../../lib/api/deployments/deploy-stack';
+import type { DeployStackOptions as DeployStackApiOptions } from '../../../lib/api/deployments/deploy-stack';
+import { CloudFormationStackDiagnoser } from '../../../lib/api/diagnosing/stack-diagnoser';
+import { NoBootstrapStackEnvironmentResources } from '../../../lib/api/environment';
+import { StackArtifactSourceTracer } from '../../../lib/api/source-tracing/private/stack-source-tracing';
+import { testStack } from '../../_helpers/assembly';
+import { FakeCloudFormation } from '../../_helpers/fake-aws/fake-cloudformation';
+import { advanceTime } from '../../_helpers/fake-time';
+import {
+  mockCloudFormationClient,
+  mockResolvedEnvironment,
+  MockSdk,
+  MockSdkProvider,
+  restoreSdkMocksToDefault,
+} from '../../_helpers/mock-sdk';
+import { TestIoHost } from '../../_helpers/test-io-host';
+
+const ioHost = new TestIoHost();
+const ioHelper = ioHost.asHelper('deploy');
+
+const FAKE_STACK = testStack({
+  stackName: 'withouterrors',
+  template: {
+    Resources: {
+      MyResource: {
+        Type: 'Test::Resource::Type',
+        Properties: {
+          Bar: 'Bar',
+        },
+      },
+    },
+  },
+});
+
+let sdk: MockSdk;
+let sdkProvider: MockSdkProvider;
+const fakeCfn = new FakeCloudFormation();
+
+beforeEach(() => {
+  fakeCfn.reset();
+  ioHost.clear();
+
+  sdkProvider = new MockSdkProvider();
+  sdk = new MockSdk();
+
+  restoreSdkMocksToDefault();
+  fakeCfn.installUsingAwsMock(mockCloudFormationClient);
+
+  jest.useFakeTimers();
+});
+
+afterEach(() => {
+  jest.useRealTimers();
+  jest.restoreAllMocks();
+});
+
+function standardDeployStackArguments(stack: CloudFormationStackArtifact = FAKE_STACK): DeployStackApiOptions {
+  const resolvedEnvironment = mockResolvedEnvironment();
+  return {
+    stack,
+    sdk,
+    sdkProvider,
+    resolvedEnvironment,
+    envResources: new NoBootstrapStackEnvironmentResources(resolvedEnvironment, sdk, ioHelper),
+    diagnoser: new CloudFormationStackDiagnoser({
+      sdk,
+      sourceTracer: new StackArtifactSourceTracer(stack),
+      ioHelper,
+      topLevelStackHierarchicalId: stack.hierarchicalId,
+    }),
+  };
+}
+
+/**
+ * Throttle every stack event read, leaving the rest of the CloudFormation API working
+ */
+function throttleStackEventReads() {
+  const realClient = sdk.cloudFormation();
+  jest.spyOn(sdk, 'cloudFormation').mockReturnValue({
+    ...realClient,
+    describeStackEvents: () => Promise.reject(Object.assign(new Error('Rate exceeded'), { name: 'Throttling' })),
+  });
+}
+
+describe.each(['change-set', 'direct'] as const)('a successful %s deployment', (method) => {
+  test('is not failed by a throttled stack event poll', async () => {
+    // GIVEN - reading stack events fails throughout, including the final poll in monitor.stop()
+    throttleStackEventReads();
+
+    // WHEN
+    const result = await advanceTime(deployStack({
+      ...standardDeployStackArguments(),
+      deploymentMethod: { method },
+    }, ioHelper));
+
+    // THEN - the deployment succeeded, and the final poll failure was only reported
+    expect(result).toMatchObject({ type: 'did-deploy-stack' });
+    ioHost.expectMessage({ level: 'warn', containing: 'Error occurred during final stack event poll' });
+  });
+});
+
+test('a successful destroy is not failed by a throttled stack event poll', async () => {
+  // GIVEN
+  fakeCfn.createStackSync({ StackName: 'withouterrors' });
+  throttleStackEventReads();
+
+  // WHEN
+  const result = await advanceTime(destroyStack({
+    stack: FAKE_STACK,
+    sdk,
+  }, ioHelper));
+
+  // THEN
+  expect(result.stackArn).toBeDefined();
+  ioHost.expectMessage({ level: 'warn', containing: 'Error occurred during final stack event poll' });
+});

packages/@aws-cdk/toolkit-lib/test/api/stack-events/stack-activity-monitor.test.ts

@@ -112,6 +112,48 @@ describe('stack monitor event ordering and pagination', () => {
   });
 });
 
+describe('stack monitor, failures while reading events', () => {
+  test('a failing final poll is reported but does not fail stop()', async () => {
+    mockCloudFormationClient.on(DescribeStackEventsCommand).rejects(throttlingError());
+
+    await eventually(() => expect(mockCloudFormationClient).toHaveReceivedCommand(DescribeStackEventsCommand), 2);
+
+    // The final poll only completes the event log, so its failure must not surface to the caller
+    await expect(monitor.stop()).resolves.toBeUndefined();
+    expect(ioHost.notify).toHaveBeenCalledWith(expect.objectContaining({
+      code: 'CDK_TOOLKIT_W5500',
+      message: expect.stringContaining('event log may be incomplete: Throttling: Rate exceeded'),
+    }));
+    expect(ioHost.notify).toHaveBeenCalledWith(expectStop());
+  });
+
+  test('a poll that fails while stop() waits for it does not fail stop() either', async () => {
+    // GIVEN - a poll that is still in flight when the monitor is stopped
+    let failFirstPoll: (error: Error) => void;
+    const firstPoll = new Promise((_, reject) => {
+      failFirstPoll = reject;
+    });
+    let polls = 0;
+    mockCloudFormationClient.on(DescribeStackEventsCommand).callsFake(() => {
+      polls += 1;
+      return polls === 1 ? firstPoll : { StackEvents: [event(101)] };
+    });
+    await eventually(() => expect(mockCloudFormationClient).toHaveReceivedCommandTimes(DescribeStackEventsCommand, 1), 2);
+
+    // WHEN
+    const stopped = monitor.stop();
+    failFirstPoll!(throttlingError());
+
+    // THEN - the failure is reported by the tick that started the poll, and the final poll still runs
+    await expect(stopped).resolves.toBeUndefined();
+    expect(ioHost.notify).toHaveBeenCalledWith(expect.objectContaining({
+      code: 'CDK_TOOLKIT_E5500',
+      message: expect.stringContaining('Error occurred while monitoring stack: Throttling: Rate exceeded'),
+    }));
+    expect(ioHost.notify).toHaveBeenCalledWith(expectEvent(101));
+  });
+});
+
 describe('stack monitor, collecting errors from events', () => {
   test('return errors from the root stack', async () => {
     mockCloudFormationClient.on(DescribeStackEventsCommand).resolvesOnce({
@@ -294,6 +336,10 @@ function errorEvent(nr: number, props?: Parameters<typeof addErrorToStackEvent>[
   return addErrorToStackEvent(event(nr), props);
 }
 
+function throttlingError(): Error {
+  return Object.assign(new Error('Rate exceeded'), { name: 'Throttling' });
+}
+
 function addErrorToStackEvent(
   eventToUpdate: StackEvent,
   props: {