From cca1ab590e62991f3932b4fefa4341794c7e5db5 Mon Sep 17 00:00:00 2001 From: Momo Kornher Date: Mon, 17 Mar 2025 10:08:02 +0000 Subject: [PATCH 1/3] fix(toolkit-lib): deployment total time includes stray output --- .../src/api/io/private/span.ts | 22 +++++++------------ 1 file changed, 8 insertions(+), 14 deletions(-) diff --git a/packages/@aws-cdk/tmp-toolkit-helpers/src/api/io/private/span.ts b/packages/@aws-cdk/tmp-toolkit-helpers/src/api/io/private/span.ts index e93f2b707..f5ff28395 100644 --- a/packages/@aws-cdk/tmp-toolkit-helpers/src/api/io/private/span.ts +++ b/packages/@aws-cdk/tmp-toolkit-helpers/src/api/io/private/span.ts @@ -114,15 +114,15 @@ export class SpanMaker { return this.ioHelper.notify(withSpanId(spanId, msg)); }; - const startMsg = second ? first : 'Starting %s ...'; + const startMsg = second ? first : `Starting ${this.definition.name} ...`; const startPayload = second ?? first; await notify(this.definition.start.msg( - util.format(startMsg, this.definition.name), + startMsg, startPayload, )); - const timingMsg = '\n✨ %s time: %ds\n'; + const timingMsgTemplate = '\n✨ %s time: %ds\n'; const time = () => { const elapsedTime = new Date().getTime() - startTime; return { @@ -132,13 +132,7 @@ export class SpanMaker { }; return { - elapsedTime: async (msg?: ActionLessMessage): Promise => { - if (msg) { - await notify({ - ...msg, - data: msg.data, - }); - } + elapsedTime: async (): Promise => { return time(); }, @@ -148,8 +142,8 @@ export class SpanMaker { timing: async(maker: IoMessageMaker, message?: string): Promise => { const duration = time(); - const endMsg = message ? message : timingMsg; - await notify(maker.msg(util.format(endMsg, this.definition.name, duration.asSec), { + const timingMsg = message ? message : util.format(timingMsgTemplate, this.definition.name, duration.asSec); + await notify(maker.msg(timingMsg, { duration: duration.asMs, })); return duration; @@ -157,11 +151,11 @@ export class SpanMaker { end: async (a: any, b?: ForceEmpty>): Promise => { const duration = time(); - const endMsg = b ? a : timingMsg; + const endMsg = b ? a : util.format(timingMsgTemplate, this.definition.name, duration.asSec); const endPayload = b ?? a; await notify(this.definition.end.msg( - util.format(endMsg, this.definition.name, duration.asSec), { + endMsg, { duration: duration.asMs, ...endPayload, } as E)); From 79e9949feee53b5a324dcdcc28a52cf66174e392 Mon Sep 17 00:00:00 2001 From: Momo Kornher Date: Mon, 17 Mar 2025 18:10:10 +0000 Subject: [PATCH 2/3] test and further fixes --- .../src/api/io/private/span.ts | 31 ++- .../test/api/io/span.test.ts | 218 ++++++++++++++++++ 2 files changed, 243 insertions(+), 6 deletions(-) create mode 100644 packages/@aws-cdk/tmp-toolkit-helpers/test/api/io/span.test.ts diff --git a/packages/@aws-cdk/tmp-toolkit-helpers/src/api/io/private/span.ts b/packages/@aws-cdk/tmp-toolkit-helpers/src/api/io/private/span.ts index f5ff28395..5dd1b275d 100644 --- a/packages/@aws-cdk/tmp-toolkit-helpers/src/api/io/private/span.ts +++ b/packages/@aws-cdk/tmp-toolkit-helpers/src/api/io/private/span.ts @@ -106,7 +106,7 @@ export class SpanMaker { */ public async begin(payload: VoidWhenEmpty): Promise>; public async begin(message: string, payload: S): Promise>; - public async begin(first: any, second?: S): Promise> { + public async begin(a: any, b?: S): Promise> { const spanId = uuid.v4(); const startTime = new Date().getTime(); @@ -114,8 +114,9 @@ export class SpanMaker { return this.ioHelper.notify(withSpanId(spanId, msg)); }; - const startMsg = second ? first : `Starting ${this.definition.name} ...`; - const startPayload = second ?? first; + const startInput = parseArgs(a, b); + const startMsg = startInput.message ?? `Starting ${this.definition.name} ...`; + const startPayload = startInput.payload; await notify(this.definition.start.msg( startMsg, @@ -149,10 +150,12 @@ export class SpanMaker { return duration; }, - end: async (a: any, b?: ForceEmpty>): Promise => { + end: async (x: any, y?: ForceEmpty>): Promise => { const duration = time(); - const endMsg = b ? a : util.format(timingMsgTemplate, this.definition.name, duration.asSec); - const endPayload = b ?? a; + + const endInput = parseArgs>>(x, y); + const endMsg = endInput.message ?? util.format(timingMsgTemplate, this.definition.name, duration.asSec); + const endPayload = endInput.payload; await notify(this.definition.end.msg( endMsg, { @@ -166,6 +169,22 @@ export class SpanMaker { } } +function parseArgs(first: any, second?: S): { message: string | undefined; payload: S } { + const firstIsMessage = typeof first === 'string'; + + // When the first argument is a string or we have a second argument, then the first arg is the message + const message = (firstIsMessage || second) ? first : undefined; + + // When the first argument is a string or we have a second argument, + // then the second arg is the payload, otherwise the first arg is the payload + const payload = firstIsMessage ? second : (second ?? first); + + return { + message, + payload, + }; +} + function withSpanId(span: string, message: ActionLessMessage): ActionLessMessage { return { ...message, diff --git a/packages/@aws-cdk/tmp-toolkit-helpers/test/api/io/span.test.ts b/packages/@aws-cdk/tmp-toolkit-helpers/test/api/io/span.test.ts new file mode 100644 index 000000000..4d19b9559 --- /dev/null +++ b/packages/@aws-cdk/tmp-toolkit-helpers/test/api/io/span.test.ts @@ -0,0 +1,218 @@ +/* eslint-disable @typescript-eslint/unbound-method */ +import type { IoHelper, SpanDefinition } from '../../../src/api/io/private'; +import { SpanMaker } from '../../../src/api/io/private'; +import * as maker from '../../../src/api/io/private/message-maker'; + +describe('SpanMaker', () => { + let ioHelper: jest.Mocked; + + beforeEach(() => { + ioHelper = { + notify: jest.fn(), + } as any; + }); + + test('begin creates span with unique id and sends start message', async () => { + // GIVEN + const definition: SpanDefinition<{}, { duration: number }> = { + name: 'Test Span', + start: maker.info<{}>({ + code: 'CDK_TOOLKIT_I1234', + description: 'test', + interface: 'stuff', + }), + end: maker.info<{ duration: number }>({ + code: 'CDK_TOOLKIT_I1234', + description: 'test', + interface: 'stuff', + }), + }; + const spanMaker = new SpanMaker(ioHelper, definition); + + // WHEN + await spanMaker.begin('Test span', {}); + + // THEN + expect(ioHelper.notify).toHaveBeenCalledTimes(1); + const notifyCall = ioHelper.notify.mock.calls[0][0]; + expect(notifyCall.message).toBe('Test span'); + expect(notifyCall.span).toBeDefined(); // UUID should be set + }); + + test('end returns elapsed time and sends end message', async () => { + // GIVEN + const definition: SpanDefinition<{}, { duration: number }> = { + name: 'Test Span', + start: maker.info<{}>({ + code: 'CDK_TOOLKIT_I1234', + description: 'Starting span', + interface: 'stuff', + }), + end: maker.info<{ duration: number }>({ + code: 'CDK_TOOLKIT_I1234', + description: 'Ending span', + interface: 'stuff', + }), + }; + const spanMaker = new SpanMaker(ioHelper, definition); + + // WHEN + const messageSpan = await spanMaker.begin('Test span', {}); + const result = await messageSpan.end(); + + // THEN + expect(result.asMs).toBeGreaterThanOrEqual(0); + expect(ioHelper.notify).toHaveBeenCalledTimes(2); + const endCall = ioHelper.notify.mock.calls[1][0] as any; + expect(endCall.message).toContain('Test Span time'); + expect(endCall.span).toBeDefined(); + expect(endCall.data.duration).toBeGreaterThanOrEqual(0); + }); + + test('intermediate messages are sent with same span id', async () => { + // GIVEN + const definition: SpanDefinition<{}, { duration: number }> = { + name: 'Test Span', + start: maker.info<{}>({ + code: 'CDK_TOOLKIT_I1234', + description: 'Starting span', + interface: 'stuff', + }), + end: maker.info<{ duration: number }>({ + code: 'CDK_TOOLKIT_I1234', + description: 'Ending span', + interface: 'stuff', + }), + }; + const spanMaker = new SpanMaker(ioHelper, definition); + + // WHEN + const messageSpan = await spanMaker.begin('Test span', {}); + await messageSpan.notify({ + message: 'Intermediate message', + code: 'CDK_TOOLKIT_I1234', + time: new Date(), + level: 'error', + data: undefined, + }); + await messageSpan.end(); + + // THEN + expect(ioHelper.notify).toHaveBeenCalledTimes(3); + const spanId = ioHelper.notify.mock.calls[0][0].span; + expect(ioHelper.notify.mock.calls[1][0].span).toBe(spanId); + expect(ioHelper.notify.mock.calls[2][0].span).toBe(spanId); + }); + + test('end with payload overrides default elapsed time payload', async () => { + // GIVEN + const definition: SpanDefinition<{}, { customField: string; duration: number }> = { + name: 'Test Span', + start: maker.info<{}>({ + code: 'CDK_TOOLKIT_I1234', + description: 'Starting span', + interface: 'stuff', + }), + end: maker.info<{ customField: string; duration: number }>({ + code: 'CDK_TOOLKIT_I1234', + description: 'Ending span', + interface: 'stuff', + }), + }; + const spanMaker = new SpanMaker(ioHelper, definition); + + // WHEN + const messageSpan = await spanMaker.begin('Test span', {}); + const result = await messageSpan.end({ customField: 'test value' }); + + // THEN + expect(result).toEqual({ asMs: expect.any(Number), asSec: expect.any(Number) }); + const endCall = ioHelper.notify.mock.calls[1][0]; + expect(endCall.data).toEqual(expect.objectContaining({ customField: 'test value' })); + }); + + test('begin with payload includes payload in start message', async () => { + // GIVEN + const definition: SpanDefinition<{ startField: string }, { duration: number }> = { + name: 'Test Span', + start: maker.info<{ startField: string }>({ + code: 'CDK_TOOLKIT_I1234', + description: 'Starting span', + interface: 'stuff', + }), + end: maker.info<{ duration: number }>({ + code: 'CDK_TOOLKIT_I1234', + description: 'Ending span', + interface: 'stuff', + }), + }; + const spanMaker = new SpanMaker(ioHelper, definition); + + // WHEN + await spanMaker.begin('Test span', { startField: 'test value' }); + + // THEN + const startCall = ioHelper.notify.mock.calls[0][0]; + expect(startCall.data).toEqual({ startField: 'test value' }); + }); + + test('endWithMessage allows custom end message', async () => { + // GIVEN + const definition: SpanDefinition<{}, { duration: number }> = { + name: 'Test Span', + start: maker.info<{}>({ + code: 'CDK_TOOLKIT_I1234', + description: 'Starting span', + interface: 'stuff', + }), + end: maker.info<{ duration: number }>({ + code: 'CDK_TOOLKIT_I1234', + description: 'Ending span', + interface: 'stuff', + }), + }; + const spanMaker = new SpanMaker(ioHelper, definition); + + // WHEN + const messageSpan =await spanMaker.begin('Test span', {}); + await messageSpan.end('Custom end message'); + + // THEN + const endCall = ioHelper.notify.mock.calls[1][0]; + expect(endCall.message).toBe('Custom end message'); + }); + + test('timing sends timing message with elapsed time', async () => { + // GIVEN + const definition: SpanDefinition<{}, { duration: number }> = { + name: 'Test Span', + start: maker.info<{}>({ + code: 'CDK_TOOLKIT_I1234', + description: 'Starting span', + interface: 'stuff', + }), + end: maker.info<{ duration: number }>({ + code: 'CDK_TOOLKIT_I1234', + description: 'Ending span', + interface: 'stuff', + }), + }; + const spanMaker = new SpanMaker(ioHelper, definition); + + // WHEN + const messageSpan = await spanMaker.begin('Test span', {}); + const elapsedTime = await messageSpan.timing(maker.info({ + code: 'CDK_TOOLKIT_I1234', + description: 'Timing message', + interface: 'stuff', + }), 'Custom timing message'); + + // THEN + expect(elapsedTime.asMs).toBeGreaterThanOrEqual(0); + expect(ioHelper.notify).toHaveBeenCalledTimes(2); + const timingCall = ioHelper.notify.mock.calls[1][0] as any; + expect(timingCall.message).toBe('Custom timing message'); + expect(timingCall.span).toBeDefined(); + expect(timingCall.data.duration).toBeGreaterThanOrEqual(0); + }); +}); From 835338a0776e0c9f90a1923d912f8a35f87c1e5e Mon Sep 17 00:00:00 2001 From: Momo Kornher Date: Tue, 18 Mar 2025 09:51:41 +0000 Subject: [PATCH 3/3] Update packages/@aws-cdk/tmp-toolkit-helpers/src/api/io/private/span.ts --- .../@aws-cdk/tmp-toolkit-helpers/src/api/io/private/span.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/packages/@aws-cdk/tmp-toolkit-helpers/src/api/io/private/span.ts b/packages/@aws-cdk/tmp-toolkit-helpers/src/api/io/private/span.ts index 5dd1b275d..5aaa05afa 100644 --- a/packages/@aws-cdk/tmp-toolkit-helpers/src/api/io/private/span.ts +++ b/packages/@aws-cdk/tmp-toolkit-helpers/src/api/io/private/span.ts @@ -177,7 +177,7 @@ function parseArgs(first: any, second?: S): { message: string // When the first argument is a string or we have a second argument, // then the second arg is the payload, otherwise the first arg is the payload - const payload = firstIsMessage ? second : (second ?? first); + const payload = (firstIsMessage || second) ? second : first; return { message,