From 03cd539b52fe485d4ecc58a69550530eed371979 Mon Sep 17 00:00:00 2001 From: Sara Gerion Date: Wed, 10 Aug 2022 00:03:17 +0200 Subject: [PATCH 1/4] chore(logger): removed unused var --- packages/logger/src/Logger.ts | 45 +++++++++------ packages/logger/src/middleware/middy.ts | 21 +++---- packages/logger/tests/unit/Logger.test.ts | 49 ++++++++++++++++ .../tests/unit/middleware/middy.test.ts | 56 +++++++++++++++++++ 4 files changed, 141 insertions(+), 30 deletions(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index f6e05cdf63..6d6138d99b 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -275,8 +275,6 @@ class Logger extends Utility implements ClassThatLogs { * @returns {HandlerMethodDecorator} */ public injectLambdaContext(options?: HandlerOptions): HandlerMethodDecorator { - const isClearStateEnabled = options && options.clearState === true; - return (target, _propertyKey, descriptor) => { /** * The descriptor.value is the method this decorator decorates, it cannot be undefined. @@ -286,23 +284,16 @@ class Logger extends Utility implements ClassThatLogs { descriptor.value = (event, context, callback) => { - let initialPersistentAttributes: LogAttributes = {}; - if (isClearStateEnabled) { - initialPersistentAttributes = { ...this.getPersistentLogAttributes() }; - } - - this.addContext(context); - let shouldLogEvent = undefined; - if ( options && options.hasOwnProperty('logEvent') ) { - shouldLogEvent = options.logEvent; - } - this.logEventIfEnabled(event, shouldLogEvent); + const initialPersistentAttributes = Logger.injectLambdaContextBefore(this, event, context, options); /* eslint-disable @typescript-eslint/no-non-null-assertion */ - const result = originalMethod!.apply(target, [ event, context, callback ]); - - if (isClearStateEnabled) { - this.setPersistentLogAttributes(initialPersistentAttributes); + let result: unknown; + try { + result = originalMethod!.apply(target, [ event, context, callback ]); + } catch (error) { + throw error; + } finally { + Logger.injectLambdaContextAfterOrOnError(this, initialPersistentAttributes, options); } return result; @@ -310,6 +301,26 @@ class Logger extends Utility implements ClassThatLogs { }; } + public static injectLambdaContextAfterOrOnError(logger: Logger, initialPersistentAttributes: LogAttributes = {}, options?: HandlerOptions): void { + if (options && options.clearState === true) { + logger.setPersistentLogAttributes(initialPersistentAttributes); + } + } + + public static injectLambdaContextBefore(logger: Logger, event: unknown, context: Context, options?: HandlerOptions): LogAttributes | undefined { + logger.addContext(context); + + let shouldLogEvent = undefined; + if (options && options.hasOwnProperty('logEvent')) { + shouldLogEvent = options.logEvent; + } + logger.logEventIfEnabled(event, shouldLogEvent); + + if (options && options.clearState === true) { + return { ...logger.getPersistentLogAttributes() }; + } + } + /** * Logs a Lambda invocation event, if it *should*. * diff --git a/packages/logger/src/middleware/middy.ts b/packages/logger/src/middleware/middy.ts index 6800686d18..a011500f52 100644 --- a/packages/logger/src/middleware/middy.ts +++ b/packages/logger/src/middleware/middy.ts @@ -1,4 +1,4 @@ -import type { Logger } from '../Logger'; +import { Logger } from '../Logger'; import type middy from '@middy/core'; import { HandlerOptions, LogAttributes } from '../types'; @@ -30,34 +30,29 @@ import { HandlerOptions, LogAttributes } from '../types'; const injectLambdaContext = (target: Logger | Logger[], options?: HandlerOptions): middy.MiddlewareObj => { const loggers = target instanceof Array ? target : [target]; - const persistentAttributes: LogAttributes[] = []; + const persistentAttributes: (LogAttributes | undefined)[] = []; const injectLambdaContextBefore = async (request: middy.Request): Promise => { loggers.forEach((logger: Logger) => { - logger.addContext(request.context); + const initialPersistentAttributes = Logger.injectLambdaContextBefore(logger, request.event, request.context, options); if (options && options.clearState === true) { - persistentAttributes.push({ ...logger.getPersistentLogAttributes() }); + persistentAttributes.push(initialPersistentAttributes); } - - let shouldLogEvent = undefined; - if ( options && options.hasOwnProperty('logEvent') ) { - shouldLogEvent = options.logEvent; - } - logger.logEventIfEnabled(request.event, shouldLogEvent); }); }; - const injectLambdaContextAfter = async (): Promise => { + const injectLambdaContextAfterOrOnError = async (): Promise => { if (options && options.clearState === true) { loggers.forEach((logger: Logger, index: number) => { - logger.setPersistentLogAttributes(persistentAttributes[index]); + Logger.injectLambdaContextAfterOrOnError(logger, persistentAttributes[index], options); }); } }; return { before: injectLambdaContextBefore, - after: injectLambdaContextAfter + after: injectLambdaContextAfterOrOnError, + onError: injectLambdaContextAfterOrOnError }; }; diff --git a/packages/logger/tests/unit/Logger.test.ts b/packages/logger/tests/unit/Logger.test.ts index 88b628453e..fb5e1c4cd6 100644 --- a/packages/logger/tests/unit/Logger.test.ts +++ b/packages/logger/tests/unit/Logger.test.ts @@ -982,6 +982,55 @@ describe('Class: Logger', () => { }); + test('when used as decorator with the clear state flag enabled and the handler throws, the persistent log attributes added in the handler are removed after the handler\'s code is executed', async () => { + + // Prepare + const logger = new Logger({ + logLevel: 'DEBUG', + persistentLogAttributes: { + foo: 'bar', + biz: 'baz' + } + }); + + type CustomEvent = { user_id: string }; + + class LambdaFunction implements LambdaInterface { + + @logger.injectLambdaContext({ clearState: true }) + // eslint-disable-next-line @typescript-eslint/ban-ts-comment + // @ts-ignore + public handler(event: CustomEvent, _context: Context, _callback: Callback): void | Promise { + // Only add these persistent for the scope of this lambda handler + logger.appendKeys({ + details: { user_id: event['user_id'] } + }); + logger.debug('This is a DEBUG log with the user_id'); + logger.debug('This is another DEBUG log with the user_id'); + + throw new Error('Unexpected error occurred!'); + } + } + + const persistentAttribs = { ...logger.getPersistentLogAttributes() }; + + // Act + try { + await new LambdaFunction().handler({ user_id: '123456' }, dummyContext, () => console.log('Lambda invoked!')); + } catch (error) { + // Do nothing + } + const persistentAttribsAfterInvocation = { ...logger.getPersistentLogAttributes() }; + + // Assess + expect(persistentAttribs).toEqual({ + foo: 'bar', + biz: 'baz' + }); + expect(persistentAttribsAfterInvocation).toEqual(persistentAttribs); + + }); + test('when used as decorator with the log event flag enabled, it logs the event', async () => { // Prepare diff --git a/packages/logger/tests/unit/middleware/middy.test.ts b/packages/logger/tests/unit/middleware/middy.test.ts index d6eb08b0f6..30e12a2900 100644 --- a/packages/logger/tests/unit/middleware/middy.test.ts +++ b/packages/logger/tests/unit/middleware/middy.test.ts @@ -207,6 +207,62 @@ describe('Middy middleware', () => { }); + test('when enabled and the handler throws, the persistent log attributes added within the handler scope are removed after the invocation ends', async () => { + + // Prepare + const logger = new Logger({ + logLevel: 'DEBUG', + persistentLogAttributes: { + foo: 'bar', + biz: 'baz' + } + }); + const context = { + callbackWaitsForEmptyEventLoop: true, + functionVersion: '$LATEST', + functionName: 'foo-bar-function', + memoryLimitInMB: '128', + logGroupName: '/aws/lambda/foo-bar-function', + logStreamName: '2021/03/09/[$LATEST]abcdef123456abcdef123456abcdef123456', + invokedFunctionArn: 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', + awsRequestId: 'abcdef123456abcdef123456', + getRemainingTimeInMillis: () => 1234, + done: () => console.log('Done!'), + fail: () => console.log('Failed!'), + succeed: () => console.log('Succeeded!'), + }; + + const lambdaHandler = (event: { user_id: string }): void => { + // Only add these persistent for the scope of this lambda handler + logger.appendKeys({ + details: { user_id: event['user_id'] } + }); + logger.debug('This is a DEBUG log with the user_id'); + logger.debug('This is another DEBUG log with the user_id'); + + throw new Error('Unexpected error occurred!'); + }; + + const handler = middy(lambdaHandler).use(injectLambdaContext(logger, { clearState: true })); + const persistentAttribs = { ...logger.getPersistentLogAttributes() }; + + // Act + try { + await handler({ user_id: '123456' }, context, () => console.log('Lambda invoked!')); + } catch (error) { + // Do nothing + } + const persistentAttribsAfterInvocation = { ...logger.getPersistentLogAttributes() }; + + // Assess + expect(persistentAttribs).toEqual({ + foo: 'bar', + biz: 'baz' + }); + expect(persistentAttribsAfterInvocation).toEqual(persistentAttribs); + + }); + }); describe('Feature: log event', () => { From b1a1182aafe8746aea626acf708e1cc0527ac0bd Mon Sep 17 00:00:00 2001 From: Sara Gerion Date: Wed, 10 Aug 2022 11:44:30 +0200 Subject: [PATCH 2/4] test(logger): expect lambda handler to throw in unit tests for clear state functionality --- packages/logger/tests/unit/Logger.test.ts | 13 +++++-------- .../logger/tests/unit/middleware/middy.test.ts | 16 +++++++--------- 2 files changed, 12 insertions(+), 17 deletions(-) diff --git a/packages/logger/tests/unit/Logger.test.ts b/packages/logger/tests/unit/Logger.test.ts index fb5e1c4cd6..43cf6fc0c1 100644 --- a/packages/logger/tests/unit/Logger.test.ts +++ b/packages/logger/tests/unit/Logger.test.ts @@ -982,7 +982,7 @@ describe('Class: Logger', () => { }); - test('when used as decorator with the clear state flag enabled and the handler throws, the persistent log attributes added in the handler are removed after the handler\'s code is executed', async () => { + test('when used as decorator with the clear state flag enabled and the handler throws an error, the persistent log attributes added in the handler are removed after the handler\'s code is executed', async () => { // Prepare const logger = new Logger({ @@ -1014,15 +1014,12 @@ describe('Class: Logger', () => { const persistentAttribs = { ...logger.getPersistentLogAttributes() }; - // Act - try { + // Act & Assess + const executeLambdaHandler = async (): Promise => { await new LambdaFunction().handler({ user_id: '123456' }, dummyContext, () => console.log('Lambda invoked!')); - } catch (error) { - // Do nothing - } + }; + await expect(executeLambdaHandler()).rejects.toThrow('Unexpected error occurred!'); const persistentAttribsAfterInvocation = { ...logger.getPersistentLogAttributes() }; - - // Assess expect(persistentAttribs).toEqual({ foo: 'bar', biz: 'baz' diff --git a/packages/logger/tests/unit/middleware/middy.test.ts b/packages/logger/tests/unit/middleware/middy.test.ts index 30e12a2900..f1c0a88fa0 100644 --- a/packages/logger/tests/unit/middleware/middy.test.ts +++ b/packages/logger/tests/unit/middleware/middy.test.ts @@ -10,6 +10,7 @@ import { Logger } from './../../../src'; import middy from '@middy/core'; import { PowertoolLogFormatter } from '../../../src/formatter'; import { Console } from 'console'; +import { context as dummyContext } from '../../../../../tests/resources/contexts/hello-world'; const mockDate = new Date(1466424490000); const dateSpy = jest.spyOn(global, 'Date').mockImplementation(() => mockDate as unknown as string); @@ -207,7 +208,7 @@ describe('Middy middleware', () => { }); - test('when enabled and the handler throws, the persistent log attributes added within the handler scope are removed after the invocation ends', async () => { + test('when enabled and the handler throws an error, the persistent log attributes added within the handler scope are removed after the invocation ends', async () => { // Prepare const logger = new Logger({ @@ -243,18 +244,15 @@ describe('Middy middleware', () => { throw new Error('Unexpected error occurred!'); }; - const handler = middy(lambdaHandler).use(injectLambdaContext(logger, { clearState: true })); const persistentAttribs = { ...logger.getPersistentLogAttributes() }; + const handler = middy(lambdaHandler).use(injectLambdaContext(logger, { clearState: true })); - // Act - try { + // Act & Assess + const executeLambdaHandler = async (): Promise => { await handler({ user_id: '123456' }, context, () => console.log('Lambda invoked!')); - } catch (error) { - // Do nothing - } + }; + await expect(executeLambdaHandler()).rejects.toThrow('Unexpected error occurred!'); const persistentAttribsAfterInvocation = { ...logger.getPersistentLogAttributes() }; - - // Assess expect(persistentAttribs).toEqual({ foo: 'bar', biz: 'baz' From 7d1bd7ce4b4f149f3d3851bcf8d9a0f3e10424c6 Mon Sep 17 00:00:00 2001 From: Sara Gerion Date: Wed, 10 Aug 2022 12:20:33 +0200 Subject: [PATCH 3/4] chore(logger): fix linting --- packages/logger/tests/unit/middleware/middy.test.ts | 1 - 1 file changed, 1 deletion(-) diff --git a/packages/logger/tests/unit/middleware/middy.test.ts b/packages/logger/tests/unit/middleware/middy.test.ts index f1c0a88fa0..e734e61e61 100644 --- a/packages/logger/tests/unit/middleware/middy.test.ts +++ b/packages/logger/tests/unit/middleware/middy.test.ts @@ -10,7 +10,6 @@ import { Logger } from './../../../src'; import middy from '@middy/core'; import { PowertoolLogFormatter } from '../../../src/formatter'; import { Console } from 'console'; -import { context as dummyContext } from '../../../../../tests/resources/contexts/hello-world'; const mockDate = new Date(1466424490000); const dateSpy = jest.spyOn(global, 'Date').mockImplementation(() => mockDate as unknown as string); From 99c33e459ca6ed63f714cc68726a11cfc0636a6a Mon Sep 17 00:00:00 2001 From: Sara Gerion Date: Wed, 10 Aug 2022 14:53:20 +0200 Subject: [PATCH 4/4] test(logger): improve readability of injectLambdaContextBefore & injectLambdaContextAfterOrOnError function behaviour - separation of concerns --- packages/logger/src/Logger.ts | 15 ++++++++------- packages/logger/src/middleware/middy.ts | 6 +++--- 2 files changed, 11 insertions(+), 10 deletions(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 6d6138d99b..ece63b3bd5 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -284,7 +284,12 @@ class Logger extends Utility implements ClassThatLogs { descriptor.value = (event, context, callback) => { - const initialPersistentAttributes = Logger.injectLambdaContextBefore(this, event, context, options); + let initialPersistentAttributes = {}; + if (options && options.clearState === true) { + initialPersistentAttributes = { ...this.getPersistentLogAttributes() }; + } + + Logger.injectLambdaContextBefore(this, event, context, options); /* eslint-disable @typescript-eslint/no-non-null-assertion */ let result: unknown; @@ -301,13 +306,13 @@ class Logger extends Utility implements ClassThatLogs { }; } - public static injectLambdaContextAfterOrOnError(logger: Logger, initialPersistentAttributes: LogAttributes = {}, options?: HandlerOptions): void { + public static injectLambdaContextAfterOrOnError(logger: Logger, initialPersistentAttributes: LogAttributes, options?: HandlerOptions): void { if (options && options.clearState === true) { logger.setPersistentLogAttributes(initialPersistentAttributes); } } - public static injectLambdaContextBefore(logger: Logger, event: unknown, context: Context, options?: HandlerOptions): LogAttributes | undefined { + public static injectLambdaContextBefore(logger: Logger, event: unknown, context: Context, options?: HandlerOptions): void { logger.addContext(context); let shouldLogEvent = undefined; @@ -315,10 +320,6 @@ class Logger extends Utility implements ClassThatLogs { shouldLogEvent = options.logEvent; } logger.logEventIfEnabled(event, shouldLogEvent); - - if (options && options.clearState === true) { - return { ...logger.getPersistentLogAttributes() }; - } } /** diff --git a/packages/logger/src/middleware/middy.ts b/packages/logger/src/middleware/middy.ts index a011500f52..85466c5de1 100644 --- a/packages/logger/src/middleware/middy.ts +++ b/packages/logger/src/middleware/middy.ts @@ -30,14 +30,14 @@ import { HandlerOptions, LogAttributes } from '../types'; const injectLambdaContext = (target: Logger | Logger[], options?: HandlerOptions): middy.MiddlewareObj => { const loggers = target instanceof Array ? target : [target]; - const persistentAttributes: (LogAttributes | undefined)[] = []; + const persistentAttributes: LogAttributes[] = []; const injectLambdaContextBefore = async (request: middy.Request): Promise => { loggers.forEach((logger: Logger) => { - const initialPersistentAttributes = Logger.injectLambdaContextBefore(logger, request.event, request.context, options); if (options && options.clearState === true) { - persistentAttributes.push(initialPersistentAttributes); + persistentAttributes.push({ ...logger.getPersistentLogAttributes() }); } + Logger.injectLambdaContextBefore(logger, request.event, request.context, options); }); };