diff --git a/packages/logger/src/middleware/middy.ts b/packages/logger/src/middleware/middy.ts index d0c622aaf..9b0140a76 100644 --- a/packages/logger/src/middleware/middy.ts +++ b/packages/logger/src/middleware/middy.ts @@ -35,9 +35,9 @@ const injectLambdaContext = (target: Logger | Logger[], options?: HandlerOptions const persistentAttributes: LogAttributes[] = []; const injectLambdaContextBefore = async (request: MiddyLikeRequest): Promise => { - loggers.forEach((logger: Logger) => { + loggers.forEach((logger: Logger, index: number) => { if (options && options.clearState === true) { - persistentAttributes.push({ ...logger.getPersistentLogAttributes() }); + persistentAttributes[index] = ({ ...logger.getPersistentLogAttributes() }); } Logger.injectLambdaContextBefore(logger, request.event, request.context, options); }); diff --git a/packages/logger/tests/unit/Logger.test.ts b/packages/logger/tests/unit/Logger.test.ts index ae1bc7417..5c2b3fd95 100644 --- a/packages/logger/tests/unit/Logger.test.ts +++ b/packages/logger/tests/unit/Logger.test.ts @@ -1235,11 +1235,10 @@ describe('Class: Logger', () => { test('it awaits the decorated method correctly', async () => { // Prepare - const injectLambdaContextAfterOrOnErrorMock = jest.fn().mockReturnValue('worked'); - // Temporarily override the cleanup static method so that we can "spy" on it. - // This method is always called after the handler has returned in the decorator - // implementation. - Logger.injectLambdaContextAfterOrOnError = injectLambdaContextAfterOrOnErrorMock; + const injectLambdaContextAfterOrOnErrorSpy = jest.spyOn( + Logger, + 'injectLambdaContextAfterOrOnError' + ); const logger = new Logger({ logLevel: 'DEBUG', }); @@ -1248,7 +1247,7 @@ describe('Class: Logger', () => { @logger.injectLambdaContext() // eslint-disable-next-line @typescript-eslint/ban-ts-comment // @ts-ignore - public async handler(_event: unknown, _context: Context, _callback: Callback): void | Promise { + public async handler(_event: unknown, _context: unknown): Promise { await this.dummyMethod(); logger.info('This is a DEBUG log'); @@ -1259,18 +1258,78 @@ describe('Class: Logger', () => { return; } } - - // Act const lambda = new LambdaFunction(); const handler = lambda.handler.bind(lambda); - await handler({}, context, () => console.log('Lambda invoked!')); + + // Act + await handler({}, context); // Assess expect(consoleSpy).toBeCalledTimes(1); - // Here we assert that the logger.info method is called before the cleanup function that should awlays - // be called after the handler has returned. If logger.info is called after it means the decorator is - // NOT awaiting the handler which would cause the test to fail. - expect(consoleSpy.mock.invocationCallOrder[0]).toBeLessThan(injectLambdaContextAfterOrOnErrorMock.mock.invocationCallOrder[0]); + // Here we assert that the logger.info method is called before the cleanup function that should always + // be called ONLY after the handler has returned. If logger.info is called after the cleanup function + // it means the decorator is NOT awaiting the handler which would cause the test to fail. + expect(consoleSpy.mock.invocationCallOrder[0]) + .toBeLessThan(injectLambdaContextAfterOrOnErrorSpy.mock.invocationCallOrder[0]); + + }); + + test('when logEvent and clearState are both TRUE, and the logger has persistent attributes, any key added in the handler is cleared properly', async () => { + + // Prepare + const logger = new Logger({ + persistentLogAttributes: { + version: '1.0.0', + } + }); + const consoleSpy = jest.spyOn(logger['console'], 'info').mockImplementation(); + class LambdaFunction implements LambdaInterface { + @logger.injectLambdaContext({ clearState: true, logEvent: true }) + // eslint-disable-next-line @typescript-eslint/ban-ts-comment + // @ts-ignore + public async handler(event: { foo: string }, _context: unknown): Promise { + logger.appendKeys({ foo: event.foo }); + + return; + } + } + const lambda = new LambdaFunction(); + const handler = lambda.handler.bind(lambda); + + // Act + await handler({ foo: 'bar' }, {} as Context); + await handler({ foo: 'baz' }, {} as Context); + await handler({ foo: 'biz' }, {} as Context); + await handler({ foo: 'buz' }, {} as Context); + await handler({ foo: 'boz' }, {} as Context); + + expect(consoleSpy).toBeCalledTimes(5); + for (let i = 1; i === 5; i++) { + expect(consoleSpy).toHaveBeenNthCalledWith( + i, + expect.stringContaining('\"message\":\"Lambda invocation event\"'), + ); + expect(consoleSpy).toHaveBeenNthCalledWith( + i, + expect.stringContaining('\"version\":\"1.0.0\"'), + ); + } + expect(consoleSpy).toHaveBeenNthCalledWith( + 2, + expect.not.stringContaining('\"foo\":\"bar\"') + ); + expect(consoleSpy).toHaveBeenNthCalledWith( + 3, + expect.not.stringContaining('\"foo\":\"baz\"') + ); + expect(consoleSpy).toHaveBeenNthCalledWith( + 4, + expect.not.stringContaining('\"foo\":\"biz\"') + ); + expect(consoleSpy).toHaveBeenNthCalledWith( + 5, + expect.not.stringContaining('\"foo\":\"buz\"') + ); }); diff --git a/packages/logger/tests/unit/middleware/middy.test.ts b/packages/logger/tests/unit/middleware/middy.test.ts index ed4abdb26..c12680a1c 100644 --- a/packages/logger/tests/unit/middleware/middy.test.ts +++ b/packages/logger/tests/unit/middleware/middy.test.ts @@ -11,6 +11,7 @@ import { Logger } from './../../../src'; import middy from '@middy/core'; import { PowertoolLogFormatter } from '../../../src/formatter'; import { Console } from 'console'; +import { Context } from 'aws-lambda'; const mockDate = new Date(1466424490000); const dateSpy = jest.spyOn(global, 'Date').mockImplementation(() => mockDate); @@ -354,6 +355,54 @@ describe('Middy middleware', () => { })); }); + test('when logEvent and clearState are both TRUE, and the logger has persistent attributes, any key added in the handler is cleared properly', async () => { + + const logger = new Logger({ + persistentLogAttributes: { + version: '1.0.0', + } + }); + const consoleSpy = jest.spyOn(logger['console'], 'info').mockImplementation(); + const handler = middy(async (event: { foo: string }, _context: Context) => { + logger.appendKeys({ foo: event.foo }); + }).use(injectLambdaContext(logger, { logEvent: true, clearState: true })); + + await handler({ foo: 'bar' }, {} as Context); + await handler({ foo: 'baz' }, {} as Context); + await handler({ foo: 'biz' }, {} as Context); + await handler({ foo: 'buz' }, {} as Context); + await handler({ foo: 'boz' }, {} as Context); + + expect(consoleSpy).toBeCalledTimes(5); + for (let i = 1; i === 5; i++) { + expect(consoleSpy).toHaveBeenNthCalledWith( + i, + expect.stringContaining('\"message\":\"Lambda invocation event\"'), + ); + expect(consoleSpy).toHaveBeenNthCalledWith( + i, + expect.stringContaining('\"version\":\"1.0.0\"'), + ); + } + expect(consoleSpy).toHaveBeenNthCalledWith( + 2, + expect.not.stringContaining('\"foo\":\"bar\"') + ); + expect(consoleSpy).toHaveBeenNthCalledWith( + 3, + expect.not.stringContaining('\"foo\":\"baz\"') + ); + expect(consoleSpy).toHaveBeenNthCalledWith( + 4, + expect.not.stringContaining('\"foo\":\"biz\"') + ); + expect(consoleSpy).toHaveBeenNthCalledWith( + 5, + expect.not.stringContaining('\"foo\":\"buz\"') + ); + + }); + }); });