diff --git a/packages/@aws-cdk/tmp-toolkit-helpers/src/api/io/payloads/index.ts b/packages/@aws-cdk/tmp-toolkit-helpers/src/api/io/payloads/index.ts index ae8a4d77b..883a8cc5f 100644 --- a/packages/@aws-cdk/tmp-toolkit-helpers/src/api/io/payloads/index.ts +++ b/packages/@aws-cdk/tmp-toolkit-helpers/src/api/io/payloads/index.ts @@ -12,3 +12,4 @@ export * from './progress'; export * from './watch'; export * from './stack-details'; export * from './diff'; +export * from './logs-monitor'; diff --git a/packages/@aws-cdk/tmp-toolkit-helpers/src/api/io/payloads/logs-monitor.ts b/packages/@aws-cdk/tmp-toolkit-helpers/src/api/io/payloads/logs-monitor.ts new file mode 100644 index 000000000..34cb9852f --- /dev/null +++ b/packages/@aws-cdk/tmp-toolkit-helpers/src/api/io/payloads/logs-monitor.ts @@ -0,0 +1,38 @@ + +/** + * Payload when stack monitoring is starting or stopping for a given stack deployment. + */ +export interface CloudWatchLogMonitorControlEvent { + /** + * A unique identifier for a monitor + * + * Use this value to attribute events received for concurrent log monitoring. + */ + readonly monitor: string; + + /** + * The names of monitored log groups + */ + readonly logGroupNames: string[]; +} + +/** + * Represents a CloudWatch Log Event that will be + * printed to the terminal + */ +export interface CloudWatchLogEvent { + /** + * The log event message + */ + readonly message: string; + + /** + * The name of the log group + */ + readonly logGroupName: string; + + /** + * The time at which the event occurred + */ + readonly timestamp: Date; +} diff --git a/packages/@aws-cdk/tmp-toolkit-helpers/src/api/io/private/messages.ts b/packages/@aws-cdk/tmp-toolkit-helpers/src/api/io/private/messages.ts index 41d153270..360af241d 100644 --- a/packages/@aws-cdk/tmp-toolkit-helpers/src/api/io/private/messages.ts +++ b/packages/@aws-cdk/tmp-toolkit-helpers/src/api/io/private/messages.ts @@ -6,6 +6,7 @@ import type { MissingContext, UpdatedContext } from '../payloads/context'; import type { BuildAsset, DeployConfirmationRequest, PublishAsset, StackDeployProgress, SuccessfulDeployStackResult } from '../payloads/deploy'; import type { StackDestroy, StackDestroyProgress } from '../payloads/destroy'; import type { StackDetailsPayload } from '../payloads/list'; +import type { CloudWatchLogEvent, CloudWatchLogMonitorControlEvent } from '../payloads/logs-monitor'; import type { StackRollbackProgress } from '../payloads/rollback'; import type { SdkTrace } from '../payloads/sdk-trace'; import type { StackActivity, StackMonitoringControlEvent } from '../payloads/stack-activity'; @@ -98,6 +99,26 @@ export const IO = { code: 'CDK_TOOLKIT_I5031', description: 'Informs about any log groups that are traced as part of the deployment', }), + CDK_TOOLKIT_I5032: make.debug({ + code: 'CDK_TOOLKIT_I5032', + description: 'Start monitoring log groups', + interface: 'CloudWatchLogMonitorControlEvent', + }), + CDK_TOOLKIT_I5033: make.info({ + code: 'CDK_TOOLKIT_I5033', + description: 'A log event received from Cloud Watch', + interface: 'CloudWatchLogEvent', + }), + CDK_TOOLKIT_I5034: make.debug({ + code: 'CDK_TOOLKIT_I5034', + description: 'Stop monitoring log groups', + interface: 'CloudWatchLogMonitorControlEvent', + }), + CDK_TOOLKIT_E5035: make.error({ + code: 'CDK_TOOLKIT_E5035', + description: 'A log monitoring error', + interface: 'ErrorPayload', + }), CDK_TOOLKIT_I5050: make.confirm({ code: 'CDK_TOOLKIT_I5050', description: 'Confirm rollback during deployment', diff --git a/packages/@aws-cdk/toolkit-lib/docs/message-registry.md b/packages/@aws-cdk/toolkit-lib/docs/message-registry.md index 745b7562a..4c0f070a8 100644 --- a/packages/@aws-cdk/toolkit-lib/docs/message-registry.md +++ b/packages/@aws-cdk/toolkit-lib/docs/message-registry.md @@ -21,6 +21,10 @@ group: Documents | `CDK_TOOLKIT_W5021` | Empty non-existent stack, deployment is skipped | `warn` | n/a | | `CDK_TOOLKIT_W5022` | Empty existing stack, stack will be destroyed | `warn` | n/a | | `CDK_TOOLKIT_I5031` | Informs about any log groups that are traced as part of the deployment | `info` | n/a | +| `CDK_TOOLKIT_I5032` | Start monitoring log groups | `debug` | {@link CloudWatchLogMonitorControlEvent} | +| `CDK_TOOLKIT_I5033` | A log event received from Cloud Watch | `info` | {@link CloudWatchLogEvent} | +| `CDK_TOOLKIT_I5034` | Stop monitoring log groups | `debug` | {@link CloudWatchLogMonitorControlEvent} | +| `CDK_TOOLKIT_E5035` | A log monitoring error | `error` | {@link ErrorPayload} | | `CDK_TOOLKIT_I5050` | Confirm rollback during deployment | `info` | {@link ConfirmationRequest} | | `CDK_TOOLKIT_I5060` | Confirm deploy security sensitive changes | `info` | {@link DeployConfirmationRequest} | | `CDK_TOOLKIT_I5100` | Stack deploy progress | `info` | {@link StackDeployProgress} | diff --git a/packages/@aws-cdk/toolkit-lib/lib/toolkit/toolkit.ts b/packages/@aws-cdk/toolkit-lib/lib/toolkit/toolkit.ts index 1120777eb..1768843f4 100644 --- a/packages/@aws-cdk/toolkit-lib/lib/toolkit/toolkit.ts +++ b/packages/@aws-cdk/toolkit-lib/lib/toolkit/toolkit.ts @@ -519,7 +519,7 @@ export class Toolkit extends CloudAssemblySourceBuilder implements AsyncDisposab } finally { if (options.traceLogs) { // deploy calls that originate from watch will come with their own cloudWatchLogMonitor - const cloudWatchLogMonitor = options.cloudWatchLogMonitor ?? new CloudWatchLogEventMonitor(); + const cloudWatchLogMonitor = options.cloudWatchLogMonitor ?? new CloudWatchLogEventMonitor({ ioHelper }); const foundLogGroupsResult = await findCloudWatchLogGroups(await this.sdkProvider('deploy'), ioHelper, stack); cloudWatchLogMonitor.addLogGroups( foundLogGroupsResult.env, @@ -637,10 +637,10 @@ export class Toolkit extends CloudAssemblySourceBuilder implements AsyncDisposab type LatchState = 'pre-ready' | 'open' | 'deploying' | 'queued'; let latch: LatchState = 'pre-ready'; - const cloudWatchLogMonitor = options.traceLogs ? new CloudWatchLogEventMonitor() : undefined; + const cloudWatchLogMonitor = options.traceLogs ? new CloudWatchLogEventMonitor({ ioHelper }) : undefined; const deployAndWatch = async () => { latch = 'deploying' as LatchState; - cloudWatchLogMonitor?.deactivate(); + await cloudWatchLogMonitor?.deactivate(); await this.invokeDeployFromWatch(assembly, options, cloudWatchLogMonitor); @@ -654,7 +654,7 @@ export class Toolkit extends CloudAssemblySourceBuilder implements AsyncDisposab await this.invokeDeployFromWatch(assembly, options, cloudWatchLogMonitor); } latch = 'open'; - cloudWatchLogMonitor?.activate(); + await cloudWatchLogMonitor?.activate(); }; chokidar diff --git a/packages/aws-cdk/lib/api/logs/find-cloudwatch-logs.ts b/packages/aws-cdk/lib/api/logs/find-cloudwatch-logs.ts index 068f772ab..90372a51b 100644 --- a/packages/aws-cdk/lib/api/logs/find-cloudwatch-logs.ts +++ b/packages/aws-cdk/lib/api/logs/find-cloudwatch-logs.ts @@ -1,7 +1,6 @@ import type { CloudFormationStackArtifact, Environment } from '@aws-cdk/cx-api'; import type { StackResourceSummary } from '@aws-sdk/client-cloudformation'; -import { IoHelper } from '../../../../@aws-cdk/tmp-toolkit-helpers/src/api/io/private'; -import { debug } from '../../logging'; +import { IO, IoHelper } from '../../../../@aws-cdk/tmp-toolkit-helpers/src/api/io/private'; import { formatErrorMessage } from '../../util'; import type { SDK, SdkProvider } from '../aws-auth'; import { EnvironmentAccess } from '../environment'; @@ -47,7 +46,7 @@ export async function findCloudWatchLogGroups( try { sdk = (await new EnvironmentAccess(sdkProvider, DEFAULT_TOOLKIT_STACK_NAME, ioHelper).accessStackForLookup(stackArtifact)).sdk; } catch (e: any) { - debug(`Failed to access SDK environment: ${formatErrorMessage(e)}`); + await ioHelper.notify(IO.DEFAULT_TOOLKIT_DEBUG.msg(`Failed to access SDK environment: ${formatErrorMessage(e)}`)); sdk = (await sdkProvider.forEnvironment(resolvedEnv, Mode.ForReading)).sdk; } diff --git a/packages/aws-cdk/lib/api/logs/logs-monitor.ts b/packages/aws-cdk/lib/api/logs/logs-monitor.ts index b8a0000f4..f5677a20a 100644 --- a/packages/aws-cdk/lib/api/logs/logs-monitor.ts +++ b/packages/aws-cdk/lib/api/logs/logs-monitor.ts @@ -1,40 +1,12 @@ import * as util from 'util'; import * as cxapi from '@aws-cdk/cx-api'; import * as chalk from 'chalk'; -import { info, error } from '../../logging'; +import * as uuid from 'uuid'; +import type { CloudWatchLogEvent } from '../../../../@aws-cdk/tmp-toolkit-helpers/src/api/io'; +import { IO, IoHelper } from '../../../../@aws-cdk/tmp-toolkit-helpers/src/api/io/private'; import { flatten } from '../../util'; import type { SDK } from '../aws-auth'; -/** - * After reading events from all CloudWatch log groups - * how long should we wait to read more events. - * - * If there is some error with reading events (i.e. Throttle) - * then this is also how long we wait until we try again - */ -const SLEEP = 2_000; - -/** - * Represents a CloudWatch Log Event that will be - * printed to the terminal - */ -interface CloudWatchLogEvent { - /** - * The log event message - */ - readonly message: string; - - /** - * The name of the log group - */ - readonly logGroupName: string; - - /** - * The time at which the event occurred - */ - readonly timestamp: Date; -} - /** * Configuration tracking information on the log groups that are * being monitored @@ -54,6 +26,20 @@ interface LogGroupsAccessSettings { readonly logGroupsStartTimes: { [logGroupName: string]: number }; } +export interface CloudWatchLogEventMonitorProps { + /** + * The IoHost used for messaging + */ + readonly ioHelper: IoHelper; + + /** + * The time from which we start reading log messages + * + * @default - now + */ + readonly startTime?: Date; +} + export class CloudWatchLogEventMonitor { /** * Determines which events not to display @@ -65,18 +51,36 @@ export class CloudWatchLogEventMonitor { */ private readonly envsLogGroupsAccessSettings = new Map(); - private active = false; + /** + * After reading events from all CloudWatch log groups + * how long should we wait to read more events. + * + * If there is some error with reading events (i.e. Throttle) + * then this is also how long we wait until we try again + */ + private readonly pollingInterval: number = 2_000; + + public monitorId?: string; + private readonly ioHelper: IoHelper; - constructor(startTime?: Date) { - this.startTime = startTime?.getTime() ?? Date.now(); + constructor(props: CloudWatchLogEventMonitorProps) { + this.startTime = props.startTime?.getTime() ?? Date.now(); + this.ioHelper = props.ioHelper; } /** * resume reading/printing events */ - public activate(): void { - this.active = true; - this.scheduleNextTick(0); + public async activate(): Promise { + this.monitorId = uuid.v4(); + + await this.ioHelper.notify(IO.CDK_TOOLKIT_I5032.msg('Start monitoring log groups', { + monitor: this.monitorId, + logGroupNames: this.logGroupNames(), + })); + + await this.tick(); + this.scheduleNextTick(); } /** @@ -88,9 +92,16 @@ export class CloudWatchLogEventMonitor { * Also resets the start time to be when the new deployment was triggered * and clears the list of tracked log groups */ - public deactivate(): void { - this.active = false; + public async deactivate(): Promise { + const oldMonitorId = this.monitorId!; + this.monitorId = undefined; this.startTime = Date.now(); + + await this.ioHelper.notify(IO.CDK_TOOLKIT_I5034.msg('Stopped monitoring log groups', { + monitor: oldMonitorId, + logGroupNames: this.logGroupNames(), + })); + this.envsLogGroupsAccessSettings.clear(); } @@ -119,27 +130,41 @@ export class CloudWatchLogEventMonitor { }); } - private scheduleNextTick(sleep: number): void { - setTimeout(() => void this.tick(), sleep); + private logGroupNames(): string[] { + return Array.from(this.envsLogGroupsAccessSettings.values()).flatMap((settings) => Object.keys(settings.logGroupsStartTimes)); + } + + private scheduleNextTick(): void { + if (!this.monitorId) { + return; + } + + setTimeout(() => void this.tick(), this.pollingInterval); } private async tick(): Promise { // excluding from codecoverage because this // doesn't always run (depends on timing) - /* istanbul ignore next */ - if (!this.active) { + /* c8 ignore next */ + if (!this.monitorId) { return; } + try { const events = flatten(await this.readNewEvents()); - events.forEach((event) => { - this.print(event); - }); - } catch (e) { - error('Error occurred while monitoring logs: %s', e); + for (const event of events) { + await this.print(event); + } + + // We might have been stop()ped while the network call was in progress. + if (!this.monitorId) { + return; + } + } catch (e: any) { + await this.ioHelper.notify(IO.CDK_TOOLKIT_E5035.msg('Error occurred while monitoring logs: %s', { error: e })); } - this.scheduleNextTick(SLEEP); + this.scheduleNextTick(); } /** @@ -161,15 +186,16 @@ export class CloudWatchLogEventMonitor { /** * Print out a cloudwatch event */ - private print(event: CloudWatchLogEvent): void { - info( + private async print(event: CloudWatchLogEvent): Promise { + await this.ioHelper.notify(IO.CDK_TOOLKIT_I5033.msg( util.format( '[%s] %s %s', chalk.blue(event.logGroupName), chalk.yellow(event.timestamp.toLocaleTimeString()), event.message.trim(), ), - ); + event, + )); } /** diff --git a/packages/aws-cdk/lib/cli/cdk-toolkit.ts b/packages/aws-cdk/lib/cli/cdk-toolkit.ts index aa9a37725..01163f207 100644 --- a/packages/aws-cdk/lib/cli/cdk-toolkit.ts +++ b/packages/aws-cdk/lib/cli/cdk-toolkit.ts @@ -649,6 +649,7 @@ export class CdkToolkit { public async watch(options: WatchOptions) { const rootDir = path.dirname(path.resolve(PROJECT_CONFIG)); + const ioHelper = asIoHelper(this.ioHost, 'watch'); debug("root directory used for 'watch' is: %s", rootDir); const watchSettings: { include?: string | string[]; exclude: string | string[] } | undefined = @@ -697,10 +698,12 @@ export class CdkToolkit { // -------------- -------- 'cdk deploy' done -------------- 'cdk deploy' done -------------- let latch: 'pre-ready' | 'open' | 'deploying' | 'queued' = 'pre-ready'; - const cloudWatchLogMonitor = options.traceLogs ? new CloudWatchLogEventMonitor() : undefined; + const cloudWatchLogMonitor = options.traceLogs ? new CloudWatchLogEventMonitor({ + ioHelper, + }) : undefined; const deployAndWatch = async () => { latch = 'deploying'; - cloudWatchLogMonitor?.deactivate(); + await cloudWatchLogMonitor?.deactivate(); await this.invokeDeployFromWatch(options, cloudWatchLogMonitor); @@ -714,7 +717,7 @@ export class CdkToolkit { await this.invokeDeployFromWatch(options, cloudWatchLogMonitor); } latch = 'open'; - cloudWatchLogMonitor?.activate(); + await cloudWatchLogMonitor?.activate(); }; chokidar diff --git a/packages/aws-cdk/test/api/logs/logs-monitor.test.ts b/packages/aws-cdk/test/api/logs/logs-monitor.test.ts index a6bced66c..b96a9dd41 100644 --- a/packages/aws-cdk/test/api/logs/logs-monitor.test.ts +++ b/packages/aws-cdk/test/api/logs/logs-monitor.test.ts @@ -1,8 +1,9 @@ import { FilterLogEventsCommand, type FilteredLogEvent } from '@aws-sdk/client-cloudwatch-logs'; import { CloudWatchLogEventMonitor } from '../../../lib/api/logs/logs-monitor'; -import { CliIoHost } from '../../../lib/toolkit/cli-io-host'; import { sleep } from '../../util'; import { MockSdk, mockCloudWatchClient } from '../../util/mock-sdk'; +import { TestIoHost } from '../../_helpers/test-io-host'; +import { asIoHelper } from '../../../../@aws-cdk/tmp-toolkit-helpers/src/api/io/private'; // Helper function to strip ANSI codes const stripAnsi = (str: string): string => { @@ -11,23 +12,19 @@ const stripAnsi = (str: string): string => { }; let sdk: MockSdk; -let stderrMock: jest.SpyInstance; let monitor: CloudWatchLogEventMonitor; +let ioHost = new TestIoHost(); beforeEach(() => { - CliIoHost.instance().isCI = false; - monitor = new CloudWatchLogEventMonitor(new Date(T100)); - stderrMock = jest.spyOn(process.stderr, 'write').mockImplementation((chunk: any) => { - // Strip ANSI codes when capturing output - if (typeof chunk === 'string') { - return stripAnsi(chunk) as unknown as boolean; - } - return stripAnsi(chunk.toString()) as unknown as boolean; + monitor = new CloudWatchLogEventMonitor({ + ioHelper: asIoHelper(ioHost, 'deploy'), + startTime: new Date(T100), }); sdk = new MockSdk(); }); afterEach(() => { - stderrMock.mockRestore(); + ioHost.notifySpy.mockReset(); + ioHost.requestSpy.mockReset(); monitor.deactivate(); }); @@ -54,8 +51,8 @@ test('process events', async () => { // THEN const expectedLocaleTimeString = eventDate.toLocaleTimeString(); - expect(stderrMock).toHaveBeenCalledTimes(1); - expect(stripAnsi(stderrMock.mock.calls[0][0])).toContain(`[loggroup] ${expectedLocaleTimeString} message`); + expect(ioHost.notifySpy).toHaveBeenCalledTimes(1); + expect(stripAnsi(ioHost.notifySpy.mock.calls[0][0].message)).toContain(`[loggroup] ${expectedLocaleTimeString} message`); }); test('process truncated events', async () => { @@ -86,9 +83,9 @@ test('process truncated events', async () => { // THEN const expectedLocaleTimeString = eventDate.toLocaleTimeString(); - expect(stderrMock).toHaveBeenCalledTimes(101); - expect(stripAnsi(stderrMock.mock.calls[0][0])).toContain(`[loggroup] ${expectedLocaleTimeString} message0`); - expect(stripAnsi(stderrMock.mock.calls[100][0])).toContain( + expect(ioHost.notifySpy).toHaveBeenCalledTimes(101); + expect(stripAnsi(ioHost.notifySpy.mock.calls[0][0].message)).toContain(`[loggroup] ${expectedLocaleTimeString} message0`); + expect(stripAnsi(ioHost.notifySpy.mock.calls[100][0].message)).toContain( `[loggroup] ${expectedLocaleTimeString} >>> \`watch\` shows only the first 100 log messages - the rest have been truncated...`, ); }); diff --git a/packages/aws-cdk/test/cli/cdk-toolkit.test.ts b/packages/aws-cdk/test/cli/cdk-toolkit.test.ts index f3c911f63..7e8efad33 100644 --- a/packages/aws-cdk/test/cli/cdk-toolkit.test.ts +++ b/packages/aws-cdk/test/cli/cdk-toolkit.test.ts @@ -4,7 +4,7 @@ const fakeChokidarWatcher = { on: mockChokidarWatcherOn, }; const fakeChokidarWatcherOn = { - get readyCallback(): () => void { + get readyCallback(): () => Promise { expect(mockChokidarWatcherOn.mock.calls.length).toBeGreaterThanOrEqual(1); // The call to the first 'watcher.on()' in the production code is the one we actually want here. // This is a pretty fragile, but at least with this helper class, @@ -1137,7 +1137,7 @@ describe('watch', () => { concurrency: 3, hotswap: HotswapMode.HOTSWAP_ONLY, }); - fakeChokidarWatcherOn.readyCallback(); + await fakeChokidarWatcherOn.readyCallback(); expect(cdkDeployMock).toHaveBeenCalledWith(expect.objectContaining({ concurrency: 3 })); }); @@ -1153,7 +1153,7 @@ describe('watch', () => { selector: { patterns: [] }, hotswap: hotswapMode, }); - fakeChokidarWatcherOn.readyCallback(); + await fakeChokidarWatcherOn.readyCallback(); expect(cdkDeployMock).toHaveBeenCalledWith(expect.objectContaining({ hotswap: hotswapMode })); }); @@ -1169,7 +1169,7 @@ describe('watch', () => { selector: { patterns: [] }, hotswap: HotswapMode.HOTSWAP_ONLY, }); - fakeChokidarWatcherOn.readyCallback(); + await fakeChokidarWatcherOn.readyCallback(); expect(cdkDeployMock).toHaveBeenCalledWith(expect.objectContaining({ hotswap: HotswapMode.HOTSWAP_ONLY })); }); @@ -1184,7 +1184,7 @@ describe('watch', () => { selector: { patterns: [] }, hotswap: HotswapMode.FALL_BACK, }); - fakeChokidarWatcherOn.readyCallback(); + await fakeChokidarWatcherOn.readyCallback(); expect(cdkDeployMock).toHaveBeenCalledWith(expect.objectContaining({ hotswap: HotswapMode.FALL_BACK })); }); @@ -1199,7 +1199,7 @@ describe('watch', () => { selector: { patterns: [] }, hotswap: HotswapMode.FULL_DEPLOYMENT, }); - fakeChokidarWatcherOn.readyCallback(); + await fakeChokidarWatcherOn.readyCallback(); expect(cdkDeployMock).toHaveBeenCalledWith(expect.objectContaining({ hotswap: HotswapMode.FULL_DEPLOYMENT })); }); @@ -1226,11 +1226,11 @@ describe('watch', () => { }); describe("when the 'ready' event has already fired", () => { - beforeEach(() => { + beforeEach(async () => { // The ready callback triggers a deployment so each test // that uses this function will see 'cdkDeployMock' called // an additional time. - fakeChokidarWatcherOn.readyCallback(); + await fakeChokidarWatcherOn.readyCallback(); }); test("an initial 'deploy' is triggered, without any file changes", async () => {