From ea2c6720731ba470b7ac446263bb919431d7f5c8 Mon Sep 17 00:00:00 2001 From: Andrea Amorosi Date: Fri, 8 Apr 2022 15:07:03 +0000 Subject: [PATCH 1/5] fix: moved to stdout, unit tests wip --- packages/logger/src/Logger.ts | 5 +- packages/logger/tests/unit/Logger.test.ts | 77 +++++++++---------- packages/logger/tests/unit/helpers.test.ts | 4 + .../tests/unit/middleware/middy.test.ts | 13 +++- 4 files changed, 56 insertions(+), 43 deletions(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index fd0540a36c..523bed85a4 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -1,3 +1,4 @@ +import { Console } from 'console'; import type { Context } from 'aws-lambda'; import { Utility } from '@aws-lambda-powertools/commons'; import { LogFormatterInterface, PowertoolLogFormatter } from './formatter'; @@ -107,6 +108,8 @@ import type { */ class Logger extends Utility implements ClassThatLogs { + private console = new Console({ stdout: process.stdout, stderr: process.stderr }); + private customConfigService?: ConfigServiceInterface; private static readonly defaultLogLevel: LogLevel = 'INFO'; @@ -448,7 +451,7 @@ class Logger extends Utility implements ClassThatLogs { const consoleMethod = logLevel.toLowerCase() as keyof ClassThatLogs; - console[consoleMethod](JSON.stringify(log.getAttributes(), this.removeCircularDependencies())); + this.console[consoleMethod](JSON.stringify(log.getAttributes(), this.removeCircularDependencies())); } /** diff --git a/packages/logger/tests/unit/Logger.test.ts b/packages/logger/tests/unit/Logger.test.ts index f6481c7499..ac05ac905d 100644 --- a/packages/logger/tests/unit/Logger.test.ts +++ b/packages/logger/tests/unit/Logger.test.ts @@ -14,24 +14,16 @@ import { EnvironmentVariablesService } from '../../src/config'; import { PowertoolLogFormatter } from '../../src/formatter'; import { ClassThatLogs } from '../../src/types'; import { Context } from 'aws-lambda'; +import { Console } from 'console'; const mockDate = new Date(1466424490000); const dateSpy = jest.spyOn(global, 'Date').mockImplementation(() => mockDate as unknown as string); - -const consoleSpy = { - 'debug': jest.spyOn(console, 'debug').mockImplementation(), - 'info': jest.spyOn(console, 'info').mockImplementation(), - 'warn': jest.spyOn(console, 'warn').mockImplementation(), - 'error': jest.spyOn(console, 'error').mockImplementation(), -}; +const stdoutSpy = jest.spyOn(process.stdout, 'write').mockImplementation(() => true); describe('Class: Logger', () => { beforeEach(() => { - consoleSpy['debug'].mockClear(); - consoleSpy['info'].mockClear(); - consoleSpy['warn'].mockClear(); - consoleSpy['error'].mockClear(); + stdoutSpy.mockClear(); dateSpy.mockClear(); }); @@ -70,9 +62,9 @@ describe('Class: Logger', () => { } // Assess - expect(console[methodOfLogger]).toBeCalledTimes(debugPrints ? 1 : 0); + expect(stdoutSpy).toBeCalledTimes(debugPrints ? 1 : 0); if (debugPrints) { - expect(console[methodOfLogger]).toHaveBeenNthCalledWith(1, JSON.stringify({ + expect(stdoutSpy).toHaveBeenNthCalledWith(1, JSON.stringify({ level: methodOfLogger.toUpperCase(), message: 'foo', service: 'hello-world', @@ -96,9 +88,9 @@ describe('Class: Logger', () => { } // Assess - expect(console[methodOfLogger]).toBeCalledTimes(infoPrints ? 1 : 0); + expect(stdoutSpy).toBeCalledTimes(infoPrints ? 1 : 0); if (infoPrints) { - expect(console[methodOfLogger]).toHaveBeenNthCalledWith(1, JSON.stringify({ + expect(stdoutSpy).toHaveBeenNthCalledWith(1, JSON.stringify({ level: methodOfLogger.toUpperCase(), message: 'foo', service: 'hello-world', @@ -122,9 +114,9 @@ describe('Class: Logger', () => { } // Assess - expect(console[methodOfLogger]).toBeCalledTimes(warnPrints ? 1 : 0); + expect(stdoutSpy).toBeCalledTimes(warnPrints ? 1 : 0); if (warnPrints) { - expect(console[methodOfLogger]).toHaveBeenNthCalledWith(1, JSON.stringify({ + expect(stdoutSpy).toHaveBeenNthCalledWith(1, JSON.stringify({ level: methodOfLogger.toUpperCase(), message: 'foo', service: 'hello-world', @@ -148,9 +140,9 @@ describe('Class: Logger', () => { } // Assess - expect(console[methodOfLogger]).toBeCalledTimes(errorPrints ? 1 : 0); + expect(stdoutSpy).toBeCalledTimes(errorPrints ? 1 : 0); if (errorPrints) { - expect(console[methodOfLogger]).toHaveBeenNthCalledWith(1, JSON.stringify({ + expect(stdoutSpy).toHaveBeenNthCalledWith(1, JSON.stringify({ level: methodOfLogger.toUpperCase(), message: 'foo', service: 'hello-world', @@ -181,7 +173,7 @@ describe('Class: Logger', () => { } // Assess - expect(console[methodOfLogger]).toBeCalledTimes(method === 'error' ? 1 : 0); + expect(stdoutSpy).toBeCalledTimes(method === 'error' ? 1 : 0); }); test('when the Logger\'s log level is higher and the current Lambda invocation IS sampled for logging, it DOES print to stdout', () => { @@ -198,8 +190,8 @@ describe('Class: Logger', () => { } // Assess - expect(console[methodOfLogger]).toBeCalledTimes(1); - expect(console[methodOfLogger]).toHaveBeenNthCalledWith(1, JSON.stringify({ + expect(stdoutSpy).toBeCalledTimes(1); + expect(stdoutSpy).toHaveBeenNthCalledWith(1, JSON.stringify({ level: method.toUpperCase(), message: 'foo', sampling_rate: 1, @@ -226,8 +218,8 @@ describe('Class: Logger', () => { } // Assess - expect(console[methodOfLogger]).toBeCalledTimes(1); - expect(console[methodOfLogger]).toHaveBeenNthCalledWith(1, JSON.stringify({ + expect(stdoutSpy).toBeCalledTimes(1); + expect(stdoutSpy).toHaveBeenNthCalledWith(1, JSON.stringify({ level: method.toUpperCase(), message: 'foo', service: 'hello-world', @@ -250,8 +242,8 @@ describe('Class: Logger', () => { } // Assess - expect(console[methodOfLogger]).toBeCalledTimes(1); - expect(console[methodOfLogger]).toHaveBeenNthCalledWith(1, JSON.stringify({ + expect(stdoutSpy).toBeCalledTimes(1); + expect(stdoutSpy).toHaveBeenNthCalledWith(1, JSON.stringify({ cold_start: true, function_arn: 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', function_memory_size: 128, @@ -292,14 +284,14 @@ describe('Class: Logger', () => { } // Assess - expect(console[methodOfConsole]).toHaveBeenNthCalledWith(1, JSON.stringify({ + expect(stdoutSpy).toHaveBeenNthCalledWith(1, JSON.stringify({ level: method.toUpperCase(), message: 'A log item without extra parameters', service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: 'abcdef123456abcdef123456abcdef123456', })); - expect(console[methodOfConsole]).toHaveBeenNthCalledWith(2, JSON.stringify({ + expect(stdoutSpy).toHaveBeenNthCalledWith(2, JSON.stringify({ level: method.toUpperCase(), message: 'A log item with a string as first parameter, and an object as second parameter', service: 'hello-world', @@ -307,7 +299,7 @@ describe('Class: Logger', () => { xray_trace_id: 'abcdef123456abcdef123456abcdef123456', extra: 'parameter', })); - expect(console[methodOfConsole]).toHaveBeenNthCalledWith(3, JSON.stringify({ + expect(stdoutSpy).toHaveBeenNthCalledWith(3, JSON.stringify({ level: method.toUpperCase(), message: 'A log item with a string as first parameter, and objects as other parameters', service: 'hello-world', @@ -316,7 +308,7 @@ describe('Class: Logger', () => { parameterOne: 'foo', parameterTwo: 'bar', })); - expect(console[methodOfConsole]).toHaveBeenNthCalledWith(4, JSON.stringify({ + expect(stdoutSpy).toHaveBeenNthCalledWith(4, JSON.stringify({ level: method.toUpperCase(), message: 'A log item with an object as first parameters', service: 'hello-world', @@ -324,7 +316,7 @@ describe('Class: Logger', () => { xray_trace_id: 'abcdef123456abcdef123456abcdef123456', extra: 'parameter', })); - const parameterCallNumber5 = JSON.parse(consoleSpy[methodOfConsole].mock.calls[4][0]); + const parameterCallNumber5 = JSON.parse(stdoutSpy.mock.calls[4][0] as string); expect(parameterCallNumber5).toEqual(expect.objectContaining( { level: method.toUpperCase(), message: 'A log item with a string as first parameter, and an error as second parameter', @@ -338,7 +330,7 @@ describe('Class: Logger', () => { stack: expect.stringMatching(/Logger.test.ts:[0-9]+:[0-9]+/), }, })); - const parameterCallNumber6 = JSON.parse(consoleSpy[methodOfConsole].mock.calls[5][0]); + const parameterCallNumber6 = JSON.parse(stdoutSpy.mock.calls[5][0] as string); expect(parameterCallNumber6).toEqual(expect.objectContaining({ level: method.toUpperCase(), message: 'A log item with a string as first parameter, and an error with custom key as second parameter', @@ -352,7 +344,7 @@ describe('Class: Logger', () => { stack: expect.stringMatching(/Logger.test.ts:[0-9]+:[0-9]+/), }, })); - expect(console[methodOfConsole]).toHaveBeenNthCalledWith(7, JSON.stringify({ + expect(stdoutSpy).toHaveBeenNthCalledWith(7, JSON.stringify({ level: method.toUpperCase(), message: 'A log item with a string as first parameter, and a string as second parameter', service: 'hello-world', @@ -385,8 +377,8 @@ describe('Class: Logger', () => { } // Assess - expect(console[methodOfConsole]).toBeCalledTimes(1); - expect(console[methodOfConsole]).toHaveBeenNthCalledWith(1, JSON.stringify({ + expect(stdoutSpy).toBeCalledTimes(1); + expect(stdoutSpy).toHaveBeenNthCalledWith(1, JSON.stringify({ level: method.toUpperCase(), message: 'foo', service: 'hello-world', @@ -428,7 +420,7 @@ describe('Class: Logger', () => { // Assess expect(result).toBe('All good!'); - expect(console[methodOfConsole]).toHaveBeenNthCalledWith(1, JSON.stringify({ + expect(stdoutSpy).toHaveBeenNthCalledWith(1, JSON.stringify({ level: method.toUpperCase(), message: 'A log with a circular reference', service: 'hello-world', @@ -471,6 +463,7 @@ describe('Class: Logger', () => { // Assess expect(logger).toEqual({ + console: expect.any(Console), coldStart: false, // This is now false because the `coldStart` attribute has been already accessed once by the `addContext` method customConfigService: undefined, envVarsService: expect.any(EnvironmentVariablesService), @@ -723,15 +716,17 @@ describe('Class: Logger', () => { // Assess expect(actualResult).toEqual(expectedReturnValue); - expect(console['info']).toBeCalledTimes(2); - expect(console['info']).toHaveBeenNthCalledWith(1, JSON.stringify({ + expect(stdoutSpy).toBeCalledTimes(2); + const actualCall1 = stdoutSpy.mock.calls[0][0]; + expect(actualCall1).toEqual(JSON.stringify({ level: 'INFO', message: 'An INFO log without context!', service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: 'abcdef123456abcdef123456abcdef123456', })); - expect(console['info']).toHaveBeenNthCalledWith(2, JSON.stringify({ + const actualCall2 = stdoutSpy.mock.calls[0][1]; + expect(actualCall2).toEqual(JSON.stringify({ cold_start: true, function_arn: 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', function_memory_size: 128, @@ -804,6 +799,7 @@ describe('Class: Logger', () => { expect(parentLogger === childLoggerWithErrorLogLevel).toBe(false); expect(parentLogger).toEqual({ + console: expect.any(Console), coldStart: true, customConfigService: undefined, envVarsService: expect.any(EnvironmentVariablesService), @@ -827,6 +823,7 @@ describe('Class: Logger', () => { }); expect(childLoggerWithPermanentAttributes).toEqual({ + console: expect.any(Console), coldStart: true, customConfigService: undefined, envVarsService: expect.any(EnvironmentVariablesService), @@ -852,6 +849,7 @@ describe('Class: Logger', () => { }); expect(childLoggerWithSampleRateEnabled).toEqual({ + console: expect.any(Console), coldStart: true, customConfigService: undefined, envVarsService: expect.any(EnvironmentVariablesService), @@ -875,6 +873,7 @@ describe('Class: Logger', () => { }); expect(childLoggerWithErrorLogLevel).toEqual({ + console: expect.any(Console), coldStart: true, customConfigService: undefined, envVarsService: expect.any(EnvironmentVariablesService), diff --git a/packages/logger/tests/unit/helpers.test.ts b/packages/logger/tests/unit/helpers.test.ts index 9d3525d343..eea86b4c0c 100644 --- a/packages/logger/tests/unit/helpers.test.ts +++ b/packages/logger/tests/unit/helpers.test.ts @@ -4,6 +4,7 @@ * @group unit/logger/all */ +import { Console } from 'console'; import { ConfigServiceInterface, EnvironmentVariablesService } from '../../src/config'; import { LogFormatter, PowertoolLogFormatter } from '../../src/formatter'; import { LoggerOptions } from '../../src/types'; @@ -78,6 +79,7 @@ describe('Helper: createLogger function', () => { envVarsService: expect.any(EnvironmentVariablesService), logFormatter: expect.any(PowertoolLogFormatter), logLevel: 'WARN', + console: expect.any(Console), logLevelThresholds: { DEBUG: 8, ERROR: 20, @@ -117,6 +119,7 @@ describe('Helper: createLogger function', () => { envVarsService: expect.any(EnvironmentVariablesService), logFormatter: expect.any(PowertoolLogFormatter), logLevel: 'INFO', + console: expect.any(Console), logLevelThresholds: { DEBUG: 8, ERROR: 20, @@ -240,6 +243,7 @@ describe('Helper: createLogger function', () => { envVarsService: expect.any(EnvironmentVariablesService), logFormatter: expect.any(PowertoolLogFormatter), logLevel: 'INFO', + console: expect.any(Console), logLevelThresholds: { DEBUG: 8, ERROR: 20, diff --git a/packages/logger/tests/unit/middleware/middy.test.ts b/packages/logger/tests/unit/middleware/middy.test.ts index 1993bf288f..979a5a5462 100644 --- a/packages/logger/tests/unit/middleware/middy.test.ts +++ b/packages/logger/tests/unit/middleware/middy.test.ts @@ -9,6 +9,7 @@ import { injectLambdaContext } from '../../../src/middleware/middy'; import { Logger } from './../../../src'; import middy from '@middy/core'; import { PowertoolLogFormatter } from '../../../src/formatter'; +import { Console } from 'console'; describe('Middy middleware', () => { @@ -16,8 +17,7 @@ describe('Middy middleware', () => { beforeEach(() => { jest.resetModules(); - // eslint-disable-next-line @typescript-eslint/no-empty-function - jest.spyOn(console, 'log').mockImplementation(() => {}); + jest.spyOn(process.stdout, 'write').mockImplementation(() => null as unknown as boolean); process.env = { ...ENVIRONMENT_VARIABLES }; }); @@ -120,6 +120,8 @@ describe('Middy middleware', () => { // Assess const expectation = expect.objectContaining({ + logsSampled: false, + persistentLogAttributes: {}, powertoolLogData: { sampleRateValue: undefined, awsRegion: 'eu-west-1', @@ -135,8 +137,13 @@ describe('Middy middleware', () => { serviceName: 'hello-world', xRayTraceId: 'abcdef123456abcdef123456abcdef123456', }, + envVarsService: expect.any(EnvironmentVariablesService), + customConfigService: undefined, + logLevel: 'DEBUG', + logFormatter: expect.any(PowertoolLogFormatter), + console: expect.any(Console), }); - expect(logger).toEqual(anotherLogger); + expect(logger).toEqual(expectation); expect(anotherLogger).toEqual(expectation); }); From 5e413ff06ca2a5f8344102ac1b4ddd8b1a528305 Mon Sep 17 00:00:00 2001 From: Andrea Amorosi Date: Wed, 13 Apr 2022 16:06:44 +0000 Subject: [PATCH 2/5] feat: adapted e2e tests - passing --- .../commons/tests/utils/InvocationLogs.ts | 47 ++++++++----------- .../tests/e2e/basicFeatures.middy.test.ts | 16 +++---- .../tests/e2e/childLogger.manual.test.ts | 16 +++---- .../tests/e2e/sampleRate.decorator.test.ts | 14 +++--- 4 files changed, 43 insertions(+), 50 deletions(-) diff --git a/packages/commons/tests/utils/InvocationLogs.ts b/packages/commons/tests/utils/InvocationLogs.ts index f220581090..47c7ca33ac 100644 --- a/packages/commons/tests/utils/InvocationLogs.ts +++ b/packages/commons/tests/utils/InvocationLogs.ts @@ -8,13 +8,17 @@ export enum LEVEL { ERROR = 'ERROR', } -export type FunctionLog = { - timestamp: string - invocationId: string - logLevel: LEVEL - // eslint-disable-next-line @typescript-eslint/no-explicit-any - logObject: {[key: string]: any} +export type ErrorField = { + name: string + message: string + stack: string }; + +export type FunctionLog = { + level: LEVEL + error: ErrorField +} & { [key: string]: unknown }; + export class InvocationLogs { public static LEVEL = LEVEL; @@ -33,7 +37,7 @@ export class InvocationLogs { * ] * See https://docs.aws.amazon.com/lambda/latest/dg/nodejs-logging.html for details */ - private logs: string[]; + private logs: string[]; public constructor(logResult: string) { const rawLog = Buffer.from(logResult, 'base64').toString('utf-8').trim(); @@ -43,48 +47,37 @@ export class InvocationLogs { /** * Find all functional logs whether it contains a given text * @param text - * @param log level to filter + * @param levelToFilter level to filter * @returns */ public doesAnyFunctionLogsContains(text: string, levelToFilter?: LEVEL): boolean { const filteredLogs = this.getFunctionLogs(levelToFilter) .filter(log => log.includes(text)); - + return filteredLogs.length > 0; } /** * Return only logs from function, exclude START, END, and REPORT generated by Lambda service - * @param log level to filter + * @param levelToFilter level to filter * @returns Array of function logs */ public getFunctionLogs(levelToFilter?: LEVEL): string[] { let filteredLogs = this.logs.slice(1, -2); if (levelToFilter) { - filteredLogs = filteredLogs.filter(log => log.split('\t')[2] == levelToFilter); - } - + filteredLogs = filteredLogs.filter((log) => JSON.parse(log).level == levelToFilter); + } + return filteredLogs; } /** - * Each of log message contains 4 elements, separted by tabs - * 1. Timestamp (e.g. 2022-01-27T16:04:39.323Z ) - * 2. Invocation id (e.g. tafb6de1a-48f8-4fbb-ad72-23a4f0c2924c) - * 3. Log level (e.g. INFO) - * 4. Log object (e.g. {\"cold_start\":true, ..}) - * @param message + * Each of log message contains a JSON with the structured Log object (e.g. {\"cold_start\":true, ..}) + * @param log */ public static parseFunctionLog(log: string): FunctionLog { - const elements = log.split('\t'); - - return { - timestamp: elements[0], - invocationId: elements[1], - logLevel: elements[2], - logObject: JSON.parse(elements[3]), - }; + return JSON.parse(log); } } \ No newline at end of file diff --git a/packages/logger/tests/e2e/basicFeatures.middy.test.ts b/packages/logger/tests/e2e/basicFeatures.middy.test.ts index bbf31c228b..140f08eef9 100644 --- a/packages/logger/tests/e2e/basicFeatures.middy.test.ts +++ b/packages/logger/tests/e2e/basicFeatures.middy.test.ts @@ -10,7 +10,7 @@ import path from 'path'; import { randomUUID } from 'crypto'; import { App, Stack } from 'aws-cdk-lib'; -import { +import { createStackWithLambdaFunction, generateUniqueName, invokeFunction, @@ -18,7 +18,7 @@ import { } from '../../../commons/tests/utils/e2eUtils'; import { InvocationLogs } from '../../../commons/tests/utils/InvocationLogs'; import { deployStack, destroyStack } from '../../../commons/tests/utils/cdk-cli'; -import { +import { RESOURCE_NAME_PREFIX, STACK_OUTPUT_LOG_GROUP, SETUP_TIMEOUT, @@ -67,8 +67,8 @@ describe(`logger E2E tests basic functionalities (middy) for runtime: ${runtime} UUID: uuid, // Text to be used by Logger in the Lambda function - PERSISTENT_KEY, - PERSISTENT_VALUE, + PERSISTENT_KEY, + PERSISTENT_VALUE, SINGLE_LOG_ITEM_KEY, SINGLE_LOG_ITEM_VALUE, ERROR_MSG, @@ -84,7 +84,7 @@ describe(`logger E2E tests basic functionalities (middy) for runtime: ${runtime} invocationLogs = await invokeFunction(functionName, 2, 'SEQUENTIAL'); console.log('logGroupName', logGroupName); - + }, SETUP_TIMEOUT); describe('Log level filtering', () => { @@ -148,7 +148,7 @@ describe(`logger E2E tests basic functionalities (middy) for runtime: ${runtime} it('should log additional keys and value only once', async () => { const logMessages = invocationLogs[0].getFunctionLogs() .filter(message => message.includes(`"${SINGLE_LOG_ITEM_KEY}":"${SINGLE_LOG_ITEM_VALUE}"`)); - + expect(logMessages).toHaveLength(1); }, TEST_CASE_TIMEOUT); }); @@ -157,10 +157,10 @@ describe(`logger E2E tests basic functionalities (middy) for runtime: ${runtime} it('should log additional keys and value only once', async () => { const logMessages = invocationLogs[0].getFunctionLogs(LEVEL.ERROR) .filter(message => message.includes(ERROR_MSG)); - + expect(logMessages).toHaveLength(1); - const { logObject } = InvocationLogs.parseFunctionLog(logMessages[0]); + const logObject = InvocationLogs.parseFunctionLog(logMessages[0]); const errorObj = logObject.error; expect(errorObj.name).toBe('Error'); diff --git a/packages/logger/tests/e2e/childLogger.manual.test.ts b/packages/logger/tests/e2e/childLogger.manual.test.ts index 8f821663c6..8c2c1e5c02 100644 --- a/packages/logger/tests/e2e/childLogger.manual.test.ts +++ b/packages/logger/tests/e2e/childLogger.manual.test.ts @@ -10,7 +10,7 @@ import path from 'path'; import { randomUUID } from 'crypto'; import { App, Stack } from 'aws-cdk-lib'; -import { +import { createStackWithLambdaFunction, generateUniqueName, invokeFunction, @@ -18,14 +18,14 @@ import { } from '../../../commons/tests/utils/e2eUtils'; import { InvocationLogs } from '../../../commons/tests/utils/InvocationLogs'; import { deployStack, destroyStack } from '../../../commons/tests/utils/cdk-cli'; -import { +import { RESOURCE_NAME_PREFIX, STACK_OUTPUT_LOG_GROUP, SETUP_TIMEOUT, TEST_CASE_TIMEOUT, TEARDOWN_TIMEOUT } from './constants'; - + const runtime: string = process.env.RUNTIME || 'nodejs14x'; if (!isValidRuntimeKey(runtime)) { @@ -54,7 +54,7 @@ describe(`logger E2E tests child logger functionalities (manual) for runtime: ${ let invocationLogs: InvocationLogs[]; beforeAll(async () => { - + // Create and deploy a stack with AWS CDK stack = createStackWithLambdaFunction({ app: integTestApp, @@ -67,8 +67,8 @@ describe(`logger E2E tests child logger functionalities (manual) for runtime: ${ UUID: uuid, // Text to be used by Logger in the Lambda function - PARENT_PERSISTENT_KEY, - PARENT_PERSISTENT_VALUE, + PARENT_PERSISTENT_KEY, + PARENT_PERSISTENT_VALUE, PARENT_LOG_MSG, CHILD_LOG_MSG, CHILD_LOG_LEVEL, @@ -83,7 +83,7 @@ describe(`logger E2E tests child logger functionalities (manual) for runtime: ${ invocationLogs = await invokeFunction(functionName, 1); console.log('logGroupName', logGroupName); - + }, SETUP_TIMEOUT); const getAllChildLogs = (): string[] => invocationLogs[0].getFunctionLogs() @@ -111,7 +111,7 @@ describe(`logger E2E tests child logger functionalities (manual) for runtime: ${ // Only parent has injected context. const allChildLogs = getAllChildLogs(); - for ( const log of allChildLogs ) { + for (const log of allChildLogs) { expect(log).not.toContain('function_arn'); expect(log).not.toContain('function_memory_size'); expect(log).not.toContain('function_name'); diff --git a/packages/logger/tests/e2e/sampleRate.decorator.test.ts b/packages/logger/tests/e2e/sampleRate.decorator.test.ts index ac0b2e83dc..8ccd18e73f 100644 --- a/packages/logger/tests/e2e/sampleRate.decorator.test.ts +++ b/packages/logger/tests/e2e/sampleRate.decorator.test.ts @@ -10,7 +10,7 @@ import path from 'path'; import { randomUUID } from 'crypto'; import { App, Stack } from 'aws-cdk-lib'; -import { +import { createStackWithLambdaFunction, generateUniqueName, invokeFunction, @@ -18,7 +18,7 @@ import { } from '../../../commons/tests/utils/e2eUtils'; import { InvocationLogs } from '../../../commons/tests/utils/InvocationLogs'; import { deployStack, destroyStack } from '../../../commons/tests/utils/cdk-cli'; -import { +import { RESOURCE_NAME_PREFIX, STACK_OUTPUT_LOG_GROUP, SETUP_TIMEOUT, @@ -53,7 +53,7 @@ describe(`logger E2E tests sample rate and injectLambdaContext() for runtime: ${ let invocationLogs: InvocationLogs[]; beforeAll(async () => { - + // Create and deploy a stack with AWS CDK stack = createStackWithLambdaFunction({ app: integTestApp, @@ -66,7 +66,7 @@ describe(`logger E2E tests sample rate and injectLambdaContext() for runtime: ${ UUID: uuid, // Parameter(s) to be used by Logger in the Lambda function - LOG_MSG, + LOG_MSG, SAMPLE_RATE, }, logGroupOutputKey: STACK_OUTPUT_LOG_GROUP, @@ -78,7 +78,7 @@ describe(`logger E2E tests sample rate and injectLambdaContext() for runtime: ${ invocationLogs = await invokeFunction(functionName, 20); console.log('logGroupName', logGroupName); - + }, SETUP_TIMEOUT); describe('Enabling sample rate', () => { @@ -105,7 +105,7 @@ describe(`logger E2E tests sample rate and injectLambdaContext() for runtime: ${ // Given that we set rate to 0.5. The chance that we get all invocations sampled (or not sampled) is less than 0.5^20 expect(countSampled).toBeGreaterThan(0); expect(countNotSampled).toBeGreaterThan(0); - + }, TEST_CASE_TIMEOUT); }); @@ -113,7 +113,7 @@ describe(`logger E2E tests sample rate and injectLambdaContext() for runtime: ${ it('should inject Lambda context into the log', async () => { const logMessages = invocationLogs[0].getFunctionLogs(LEVEL.ERROR); - for ( const log of logMessages ) { + for (const log of logMessages) { expect(log).toContain('function_arn'); expect(log).toContain('function_memory_size'); expect(log).toContain('function_name'); From aab56b496f6ed4dbed410a3b20860e8560c819f5 Mon Sep 17 00:00:00 2001 From: Andrea Amorosi Date: Wed, 13 Apr 2022 16:45:58 +0000 Subject: [PATCH 3/5] feat: wrote unit tests --- packages/logger/src/Logger.ts | 12 +- packages/logger/tests/unit/Logger.test.ts | 139 ++++++++++++---------- 2 files changed, 79 insertions(+), 72 deletions(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 523bed85a4..9ad4a563cc 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -257,7 +257,7 @@ class Logger extends Utility implements ClassThatLogs { descriptor.value = (event, context, callback) => { this.addContext(context); - return originalMethod?.apply(target, [ event, context, callback ]); + return originalMethod?.apply(target, [event, context, callback]); }; }; } @@ -368,7 +368,7 @@ class Logger extends Utility implements ClassThatLogs { * @returns {EnvironmentVariablesService} */ private getEnvVarsService(): EnvironmentVariablesService { - return this.envVarsService; + return this.envVarsService; } /** @@ -379,7 +379,7 @@ class Logger extends Utility implements ClassThatLogs { * @returns {LogFormatterInterface} */ private getLogFormatter(): LogFormatterInterface { - return this.logFormatter; + return this.logFormatter; } /** @@ -389,7 +389,7 @@ class Logger extends Utility implements ClassThatLogs { * @returns {LogLevel} */ private getLogLevel(): LogLevel { - return this.logLevel; + return this.logLevel; } /** @@ -400,7 +400,7 @@ class Logger extends Utility implements ClassThatLogs { * @returns {LogAttributes} */ private getPersistentLogAttributes(): LogAttributes { - return this.persistentLogAttributes; + return this.persistentLogAttributes; } /** @@ -425,7 +425,7 @@ class Logger extends Utility implements ClassThatLogs { this.setSampleRateValue(); } - return this.powertoolLogData?.sampleRateValue; + return this.powertoolLogData?.sampleRateValue; } /** diff --git a/packages/logger/tests/unit/Logger.test.ts b/packages/logger/tests/unit/Logger.test.ts index ac05ac905d..c0d0fc49fc 100644 --- a/packages/logger/tests/unit/Logger.test.ts +++ b/packages/logger/tests/unit/Logger.test.ts @@ -18,20 +18,18 @@ import { Console } from 'console'; const mockDate = new Date(1466424490000); const dateSpy = jest.spyOn(global, 'Date').mockImplementation(() => mockDate as unknown as string); -const stdoutSpy = jest.spyOn(process.stdout, 'write').mockImplementation(() => true); describe('Class: Logger', () => { beforeEach(() => { - stdoutSpy.mockClear(); dateSpy.mockClear(); }); describe.each([ - [ 'debug', 'DOES', true, 'DOES NOT', false, 'DOES NOT', false, 'DOES NOT', false ], - [ 'info', 'DOES', true, 'DOES', true, 'DOES NOT', false, 'DOES NOT', false ], - [ 'warn', 'DOES', true, 'DOES', true, 'DOES', true, 'DOES NOT', false ], - [ 'error', 'DOES', true, 'DOES', true, 'DOES', true, 'DOES', true ], + ['debug', 'DOES', true, 'DOES NOT', false, 'DOES NOT', false, 'DOES NOT', false], + ['info', 'DOES', true, 'DOES', true, 'DOES NOT', false, 'DOES NOT', false], + ['warn', 'DOES', true, 'DOES', true, 'DOES', true, 'DOES NOT', false], + ['error', 'DOES', true, 'DOES', true, 'DOES', true, 'DOES', true], ])( 'Method: %p', ( @@ -49,12 +47,13 @@ describe('Class: Logger', () => { describe('Feature: log level', () => { const methodOfLogger = method as keyof ClassThatLogs; - test('when the Logger\'s log level is DEBUG, it '+ debugAction + ' print to stdout', () => { + test('when the Logger\'s log level is DEBUG, it ' + debugAction + ' print to stdout', () => { // Prepare - const logger: ClassThatLogs = createLogger({ + const logger: Logger = createLogger({ logLevel: 'DEBUG', }); + const consoleSpy = jest.spyOn(logger['console'], methodOfLogger).mockImplementation(); // Act if (logger[methodOfLogger]) { @@ -62,9 +61,9 @@ describe('Class: Logger', () => { } // Assess - expect(stdoutSpy).toBeCalledTimes(debugPrints ? 1 : 0); + expect(consoleSpy).toBeCalledTimes(debugPrints ? 1 : 0); if (debugPrints) { - expect(stdoutSpy).toHaveBeenNthCalledWith(1, JSON.stringify({ + expect(consoleSpy).toHaveBeenNthCalledWith(1, JSON.stringify({ level: methodOfLogger.toUpperCase(), message: 'foo', service: 'hello-world', @@ -75,12 +74,13 @@ describe('Class: Logger', () => { }); - test('when the Logger\'s log level is INFO, it '+ infoAction + ' print to stdout', () => { + test('when the Logger\'s log level is INFO, it ' + infoAction + ' print to stdout', () => { // Prepare - const logger: ClassThatLogs = createLogger({ + const logger: Logger = createLogger({ logLevel: 'INFO', }); + const consoleSpy = jest.spyOn(logger['console'], methodOfLogger).mockImplementation(); // Act if (logger[methodOfLogger]) { @@ -88,9 +88,9 @@ describe('Class: Logger', () => { } // Assess - expect(stdoutSpy).toBeCalledTimes(infoPrints ? 1 : 0); + expect(consoleSpy).toBeCalledTimes(infoPrints ? 1 : 0); if (infoPrints) { - expect(stdoutSpy).toHaveBeenNthCalledWith(1, JSON.stringify({ + expect(consoleSpy).toHaveBeenNthCalledWith(1, JSON.stringify({ level: methodOfLogger.toUpperCase(), message: 'foo', service: 'hello-world', @@ -101,12 +101,13 @@ describe('Class: Logger', () => { }); - test('when the Logger\'s log level is WARN, it '+ warnAction + ' print to stdout', () => { + test('when the Logger\'s log level is WARN, it ' + warnAction + ' print to stdout', () => { // Prepare - const logger: ClassThatLogs = createLogger({ + const logger: Logger = createLogger({ logLevel: 'WARN', }); + const consoleSpy = jest.spyOn(logger['console'], methodOfLogger).mockImplementation(); // Act if (logger[methodOfLogger]) { @@ -114,9 +115,9 @@ describe('Class: Logger', () => { } // Assess - expect(stdoutSpy).toBeCalledTimes(warnPrints ? 1 : 0); + expect(consoleSpy).toBeCalledTimes(warnPrints ? 1 : 0); if (warnPrints) { - expect(stdoutSpy).toHaveBeenNthCalledWith(1, JSON.stringify({ + expect(consoleSpy).toHaveBeenNthCalledWith(1, JSON.stringify({ level: methodOfLogger.toUpperCase(), message: 'foo', service: 'hello-world', @@ -127,12 +128,13 @@ describe('Class: Logger', () => { }); - test('when the Logger\'s log level is ERROR, it '+ errorAction + ' print to stdout', () => { + test('when the Logger\'s log level is ERROR, it ' + errorAction + ' print to stdout', () => { // Prepare - const logger: ClassThatLogs = createLogger({ + const logger: Logger = createLogger({ logLevel: 'ERROR', }); + const consoleSpy = jest.spyOn(logger['console'], methodOfLogger).mockImplementation(); // Act if (logger[methodOfLogger]) { @@ -140,9 +142,9 @@ describe('Class: Logger', () => { } // Assess - expect(stdoutSpy).toBeCalledTimes(errorPrints ? 1 : 0); + expect(consoleSpy).toBeCalledTimes(errorPrints ? 1 : 0); if (errorPrints) { - expect(stdoutSpy).toHaveBeenNthCalledWith(1, JSON.stringify({ + expect(consoleSpy).toHaveBeenNthCalledWith(1, JSON.stringify({ level: methodOfLogger.toUpperCase(), message: 'foo', service: 'hello-world', @@ -162,10 +164,11 @@ describe('Class: Logger', () => { test('when the Logger\'s log level is higher and the current Lambda invocation IS NOT sampled for logging, it DOES NOT print to stdout', () => { // Prepare - const logger: ClassThatLogs = createLogger({ + const logger: Logger = createLogger({ logLevel: 'ERROR', sampleRateValue: 0, }); + const consoleSpy = jest.spyOn(logger['console'], methodOfLogger).mockImplementation(); // Act if (logger[methodOfLogger]) { @@ -173,16 +176,17 @@ describe('Class: Logger', () => { } // Assess - expect(stdoutSpy).toBeCalledTimes(method === 'error' ? 1 : 0); + expect(consoleSpy).toBeCalledTimes(method === 'error' ? 1 : 0); }); test('when the Logger\'s log level is higher and the current Lambda invocation IS sampled for logging, it DOES print to stdout', () => { // Prepare - const logger: ClassThatLogs = createLogger({ + const logger: Logger = createLogger({ logLevel: 'ERROR', sampleRateValue: 1, }); + const consoleSpy = jest.spyOn(logger['console'], methodOfLogger).mockImplementation(); // Act if (logger[methodOfLogger]) { @@ -190,8 +194,8 @@ describe('Class: Logger', () => { } // Assess - expect(stdoutSpy).toBeCalledTimes(1); - expect(stdoutSpy).toHaveBeenNthCalledWith(1, JSON.stringify({ + expect(consoleSpy).toBeCalledTimes(1); + expect(consoleSpy).toHaveBeenNthCalledWith(1, JSON.stringify({ level: method.toUpperCase(), message: 'foo', sampling_rate: 1, @@ -207,10 +211,11 @@ describe('Class: Logger', () => { const methodOfLogger = method as keyof ClassThatLogs; - test('when the Lambda context is not captured and a string is passed as log message, it should print a valid '+ method.toUpperCase() + ' log', () => { + test('when the Lambda context is not captured and a string is passed as log message, it should print a valid ' + method.toUpperCase() + ' log', () => { // Prepare - const logger: ClassThatLogs = createLogger(); + const logger: Logger = createLogger(); + const consoleSpy = jest.spyOn(logger['console'], methodOfLogger).mockImplementation(); // Act if (logger[methodOfLogger]) { @@ -218,8 +223,8 @@ describe('Class: Logger', () => { } // Assess - expect(stdoutSpy).toBeCalledTimes(1); - expect(stdoutSpy).toHaveBeenNthCalledWith(1, JSON.stringify({ + expect(consoleSpy).toBeCalledTimes(1); + expect(consoleSpy).toHaveBeenNthCalledWith(1, JSON.stringify({ level: method.toUpperCase(), message: 'foo', service: 'hello-world', @@ -228,13 +233,14 @@ describe('Class: Logger', () => { })); }); - test('when the Lambda context is captured, it returns a valid '+ method.toUpperCase() + ' log', () => { + test('when the Lambda context is captured, it returns a valid ' + method.toUpperCase() + ' log', () => { // Prepare - const logger: ClassThatLogs & { addContext: (context: Context) => void } = createLogger({ + const logger: Logger & { addContext: (context: Context) => void } = createLogger({ logLevel: 'DEBUG', }); logger.addContext(dummyContext); + const consoleSpy = jest.spyOn(logger['console'], methodOfLogger).mockImplementation(); // Act if (logger[methodOfLogger]) { @@ -242,8 +248,8 @@ describe('Class: Logger', () => { } // Assess - expect(stdoutSpy).toBeCalledTimes(1); - expect(stdoutSpy).toHaveBeenNthCalledWith(1, JSON.stringify({ + expect(consoleSpy).toBeCalledTimes(1); + expect(consoleSpy).toHaveBeenNthCalledWith(1, JSON.stringify({ cold_start: true, function_arn: 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', function_memory_size: 128, @@ -263,35 +269,35 @@ describe('Class: Logger', () => { describe('Feature: ephemeral log attributes', () => { const methodOfLogger = method as keyof ClassThatLogs; - const methodOfConsole = methodOfLogger; test('when added, they should appear in that log item only', () => { // Prepare - const logger: ClassThatLogs = createLogger({ + const logger: Logger = createLogger({ logLevel: 'DEBUG', }); + const consoleSpy = jest.spyOn(logger['console'], methodOfLogger).mockImplementation(); // Act if (logger[methodOfLogger]) { logger[methodOfLogger]('A log item without extra parameters'); logger[methodOfLogger]('A log item with a string as first parameter, and an object as second parameter', { extra: 'parameter' }); logger[methodOfLogger]('A log item with a string as first parameter, and objects as other parameters', { parameterOne: 'foo' }, { parameterTwo: 'bar' }); - logger[methodOfLogger]( { message: 'A log item with an object as first parameters', extra: 'parameter' }); - logger[methodOfLogger]('A log item with a string as first parameter, and an error as second parameter', new Error('Something happened!') ); + logger[methodOfLogger]({ message: 'A log item with an object as first parameters', extra: 'parameter' }); + logger[methodOfLogger]('A log item with a string as first parameter, and an error as second parameter', new Error('Something happened!')); logger[methodOfLogger]('A log item with a string as first parameter, and an error with custom key as second parameter', { myCustomErrorKey: new Error('Something happened!') }); logger[methodOfLogger]('A log item with a string as first parameter, and a string as second parameter', 'parameter'); } // Assess - expect(stdoutSpy).toHaveBeenNthCalledWith(1, JSON.stringify({ + expect(consoleSpy).toHaveBeenNthCalledWith(1, JSON.stringify({ level: method.toUpperCase(), message: 'A log item without extra parameters', service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: 'abcdef123456abcdef123456abcdef123456', })); - expect(stdoutSpy).toHaveBeenNthCalledWith(2, JSON.stringify({ + expect(consoleSpy).toHaveBeenNthCalledWith(2, JSON.stringify({ level: method.toUpperCase(), message: 'A log item with a string as first parameter, and an object as second parameter', service: 'hello-world', @@ -299,7 +305,7 @@ describe('Class: Logger', () => { xray_trace_id: 'abcdef123456abcdef123456abcdef123456', extra: 'parameter', })); - expect(stdoutSpy).toHaveBeenNthCalledWith(3, JSON.stringify({ + expect(consoleSpy).toHaveBeenNthCalledWith(3, JSON.stringify({ level: method.toUpperCase(), message: 'A log item with a string as first parameter, and objects as other parameters', service: 'hello-world', @@ -308,7 +314,7 @@ describe('Class: Logger', () => { parameterOne: 'foo', parameterTwo: 'bar', })); - expect(stdoutSpy).toHaveBeenNthCalledWith(4, JSON.stringify({ + expect(consoleSpy).toHaveBeenNthCalledWith(4, JSON.stringify({ level: method.toUpperCase(), message: 'A log item with an object as first parameters', service: 'hello-world', @@ -316,8 +322,8 @@ describe('Class: Logger', () => { xray_trace_id: 'abcdef123456abcdef123456abcdef123456', extra: 'parameter', })); - const parameterCallNumber5 = JSON.parse(stdoutSpy.mock.calls[4][0] as string); - expect(parameterCallNumber5).toEqual(expect.objectContaining( { + const parameterCallNumber5 = JSON.parse(consoleSpy.mock.calls[4][0]); + expect(parameterCallNumber5).toEqual(expect.objectContaining({ level: method.toUpperCase(), message: 'A log item with a string as first parameter, and an error as second parameter', service: 'hello-world', @@ -330,7 +336,7 @@ describe('Class: Logger', () => { stack: expect.stringMatching(/Logger.test.ts:[0-9]+:[0-9]+/), }, })); - const parameterCallNumber6 = JSON.parse(stdoutSpy.mock.calls[5][0] as string); + const parameterCallNumber6 = JSON.parse(consoleSpy.mock.calls[5][0] as string); expect(parameterCallNumber6).toEqual(expect.objectContaining({ level: method.toUpperCase(), message: 'A log item with a string as first parameter, and an error with custom key as second parameter', @@ -344,7 +350,7 @@ describe('Class: Logger', () => { stack: expect.stringMatching(/Logger.test.ts:[0-9]+:[0-9]+/), }, })); - expect(stdoutSpy).toHaveBeenNthCalledWith(7, JSON.stringify({ + expect(consoleSpy).toHaveBeenNthCalledWith(7, JSON.stringify({ level: method.toUpperCase(), message: 'A log item with a string as first parameter, and a string as second parameter', service: 'hello-world', @@ -358,18 +364,18 @@ describe('Class: Logger', () => { describe('Feature: persistent log attributes', () => { const methodOfLogger = method as keyof ClassThatLogs; - const methodOfConsole = methodOfLogger; test('when persistent log attributes are added to the Logger instance, they should appear in all logs printed by the instance', () => { // Prepare - const logger: ClassThatLogs = createLogger({ + const logger: Logger = createLogger({ logLevel: 'DEBUG', persistentLogAttributes: { aws_account_id: '123456789012', aws_region: 'eu-west-1', }, }); + const consoleSpy = jest.spyOn(logger['console'], methodOfLogger).mockImplementation(); // Act if (logger[methodOfLogger]) { @@ -377,8 +383,8 @@ describe('Class: Logger', () => { } // Assess - expect(stdoutSpy).toBeCalledTimes(1); - expect(stdoutSpy).toHaveBeenNthCalledWith(1, JSON.stringify({ + expect(consoleSpy).toBeCalledTimes(1); + expect(consoleSpy).toHaveBeenNthCalledWith(1, JSON.stringify({ level: method.toUpperCase(), message: 'foo', service: 'hello-world', @@ -394,14 +400,14 @@ describe('Class: Logger', () => { describe('Feature: handle safely unexpected errors', () => { const methodOfLogger = method as keyof ClassThatLogs; - const methodOfConsole = methodOfLogger; test('when a logged item references itself, the logger ignores the keys that cause a circular reference', () => { // Prepare - const logger: ClassThatLogs = createLogger({ + const logger: Logger = createLogger({ logLevel: 'DEBUG', }); + const consoleSpy = jest.spyOn(logger['console'], methodOfLogger).mockImplementation(); const circularObject = { foo: 'bar', self: {}, @@ -420,7 +426,7 @@ describe('Class: Logger', () => { // Assess expect(result).toBe('All good!'); - expect(stdoutSpy).toHaveBeenNthCalledWith(1, JSON.stringify({ + expect(consoleSpy).toHaveBeenNthCalledWith(1, JSON.stringify({ level: method.toUpperCase(), message: 'A log with a circular reference', service: 'hello-world', @@ -607,13 +613,14 @@ describe('Class: Logger', () => { beforeEach(() => { // eslint-disable-next-line @typescript-eslint/no-empty-function - jest.spyOn(console, 'log').mockImplementation(() => {}); + jest.spyOn(console, 'log').mockImplementation(() => { }); }); test('when used as decorator, it returns a function with the correct scope of the decorated class', async () => { // Prepare const logger = new Logger(); + const consoleSpy = jest.spyOn(logger['console'], 'info').mockImplementation(); class LambdaFunction implements LambdaInterface { @logger.injectLambdaContext() @@ -623,7 +630,7 @@ describe('Class: Logger', () => { this.myClassMethod(); } - private myClassMethod (): void { + private myClassMethod(): void { logger.info('This is an INFO log with some context'); } @@ -633,8 +640,8 @@ describe('Class: Logger', () => { await new LambdaFunction().handler(dummyEvent, dummyContext, () => console.log('Lambda invoked!')); // Assess - expect(console['info']).toBeCalledTimes(1); - expect(console['info']).toHaveBeenNthCalledWith(1, JSON.stringify({ + expect(consoleSpy).toBeCalledTimes(1); + expect(consoleSpy).toHaveBeenNthCalledWith(1, JSON.stringify({ cold_start: true, function_arn: 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', function_memory_size: 128, @@ -653,6 +660,7 @@ describe('Class: Logger', () => { // Prepare const logger = new Logger(); + const consoleSpy = jest.spyOn(logger['console'], 'info').mockImplementation(); class LambdaFunction implements LambdaInterface { @logger.injectLambdaContext() @@ -669,15 +677,15 @@ describe('Class: Logger', () => { // Assess - expect(console['info']).toBeCalledTimes(2); - expect(console['info']).toHaveBeenNthCalledWith(1, JSON.stringify({ + expect(consoleSpy).toBeCalledTimes(2); + expect(consoleSpy).toHaveBeenNthCalledWith(1, JSON.stringify({ level: 'INFO', message: 'An INFO log without context!', service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: 'abcdef123456abcdef123456abcdef123456', })); - expect(console['info']).toHaveBeenNthCalledWith(2, JSON.stringify({ + expect(consoleSpy).toHaveBeenNthCalledWith(2, JSON.stringify({ cold_start: true, function_arn: 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', function_memory_size: 128, @@ -697,6 +705,7 @@ describe('Class: Logger', () => { // Prepare const expectedReturnValue = 'Lambda invoked!'; const logger = new Logger(); + const consoleSpy = jest.spyOn(logger['console'], 'info').mockImplementation(); class LambdaFunction implements LambdaInterface { @logger.injectLambdaContext() @@ -716,17 +725,15 @@ describe('Class: Logger', () => { // Assess expect(actualResult).toEqual(expectedReturnValue); - expect(stdoutSpy).toBeCalledTimes(2); - const actualCall1 = stdoutSpy.mock.calls[0][0]; - expect(actualCall1).toEqual(JSON.stringify({ + expect(consoleSpy).toBeCalledTimes(2); + expect(consoleSpy).toHaveBeenNthCalledWith(1, JSON.stringify({ level: 'INFO', message: 'An INFO log without context!', service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: 'abcdef123456abcdef123456abcdef123456', })); - const actualCall2 = stdoutSpy.mock.calls[0][1]; - expect(actualCall2).toEqual(JSON.stringify({ + expect(consoleSpy).toHaveBeenNthCalledWith(2, JSON.stringify({ cold_start: true, function_arn: 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', function_memory_size: 128, From bcd964bfc0cc9c62db46dfa7adf6e60547b7623e Mon Sep 17 00:00:00 2001 From: Andrea Amorosi Date: Wed, 13 Apr 2022 16:51:46 +0000 Subject: [PATCH 4/5] lint + cleanup --- packages/commons/tests/utils/InvocationLogs.ts | 7 +++---- packages/logger/src/Logger.ts | 12 ++++++------ packages/logger/tests/unit/Logger.test.ts | 8 ++++---- 3 files changed, 13 insertions(+), 14 deletions(-) diff --git a/packages/commons/tests/utils/InvocationLogs.ts b/packages/commons/tests/utils/InvocationLogs.ts index 47c7ca33ac..22e1334007 100644 --- a/packages/commons/tests/utils/InvocationLogs.ts +++ b/packages/commons/tests/utils/InvocationLogs.ts @@ -26,12 +26,11 @@ export class InvocationLogs { * Array of logs from invocation. * * The first element is START, and the last two elements are END, and REPORT. - * In each log, each content is separated by '\t' * [ * 'START RequestId: c6af9ac6-7b61-11e6-9a41-93e812345678 Version: $LATEST', - * '2022-01-27T16:04:39.323Z\tc6af9ac6-7b61-11e6-9a41-93e812345678\tINFO\t{"cold_start":true,"function_arn":"arn:aws:lambda:eu-west-1:561912387782:function:loggerMiddyStandardFeatures-c555a2ec-1121-4586-9c04-185ab36ea34c","function_memory_size":128,"function_name":"loggerMiddyStandardFeatures-c555a2ec-1121-4586-9c04-185ab36ea34c","function_request_id":"7f586697-238a-4c3b-9250-a5f057c1119c","level":"INFO","message":"This is an INFO log with some context and persistent key","service":"logger-e2e-testing","timestamp":"2022-01-27T16:04:39.323Z","persistentKey":"works"}', - * '2022-01-27T16:04:39.323Z\tc6af9ac6-7b61-11e6-9a41-93e812345678\tINFO\t{"cold_start":true,"function_arn":"arn:aws:lambda:eu-west-1:561912387782:function:loggerMiddyStandardFeatures-c555a2ec-1121-4586-9c04-185ab36ea34c","function_memory_size":128,"function_name":"loggerMiddyStandardFeatures-c555a2ec-1121-4586-9c04-185ab36ea34c","function_request_id":"7f586697-238a-4c3b-9250-a5f057c1119c","level":"INFO","message":"This is an INFO log with some context","service":"logger-e2e-testing","timestamp":"2022-01-27T16:04:39.323Z","persistentKey":"works","additionalKey":"additionalValue"}', - * '2022-01-27T16:04:39.323Z\tc6af9ac6-7b61-11e6-9a41-93e812345678\tERROR\t{"cold_start":true,"function_arn":"arn:aws:lambda:eu-west-1:561912387782:function:loggerMiddyStandardFeatures-c555a2ec-1121-4586-9c04-185ab36ea34c","function_memory_size":128,"function_name":"loggerMiddyStandardFeatures-c555a2ec-1121-4586-9c04-185ab36ea34c","function_request_id":"7f586697-238a-4c3b-9250-a5f057c1119c","level":"ERROR","message":"There was an error","service":"logger-e2e-testing","timestamp":"2022-01-27T16:04:39.323Z","persistentKey":"works","error":{"name":"Error","location":"/var/task/index.js:2778","message":"you cannot prevent this","stack":"Error: you cannot prevent this\\n at testFunction (/var/task/index.js:2778:11)\\n at runRequest (/var/task/index.js:2314:36)"}}', + * '{"cold_start":true,"function_arn":"arn:aws:lambda:eu-west-1:561912387782:function:loggerMiddyStandardFeatures-c555a2ec-1121-4586-9c04-185ab36ea34c","function_memory_size":128,"function_name":"loggerMiddyStandardFeatures-c555a2ec-1121-4586-9c04-185ab36ea34c","function_request_id":"7f586697-238a-4c3b-9250-a5f057c1119c","level":"INFO","message":"This is an INFO log with some context and persistent key","service":"logger-e2e-testing","timestamp":"2022-01-27T16:04:39.323Z","persistentKey":"works"}', + * '{"cold_start":true,"function_arn":"arn:aws:lambda:eu-west-1:561912387782:function:loggerMiddyStandardFeatures-c555a2ec-1121-4586-9c04-185ab36ea34c","function_memory_size":128,"function_name":"loggerMiddyStandardFeatures-c555a2ec-1121-4586-9c04-185ab36ea34c","function_request_id":"7f586697-238a-4c3b-9250-a5f057c1119c","level":"INFO","message":"This is an INFO log with some context","service":"logger-e2e-testing","timestamp":"2022-01-27T16:04:39.323Z","persistentKey":"works","additionalKey":"additionalValue"}', + * '{"cold_start":true,"function_arn":"arn:aws:lambda:eu-west-1:561912387782:function:loggerMiddyStandardFeatures-c555a2ec-1121-4586-9c04-185ab36ea34c","function_memory_size":128,"function_name":"loggerMiddyStandardFeatures-c555a2ec-1121-4586-9c04-185ab36ea34c","function_request_id":"7f586697-238a-4c3b-9250-a5f057c1119c","level":"ERROR","message":"There was an error","service":"logger-e2e-testing","timestamp":"2022-01-27T16:04:39.323Z","persistentKey":"works","error":{"name":"Error","location":"/var/task/index.js:2778","message":"you cannot prevent this","stack":"Error: you cannot prevent this\\n at testFunction (/var/task/index.js:2778:11)\\n at runRequest (/var/task/index.js:2314:36)"}}', * 'END RequestId: c6af9ac6-7b61-11e6-9a41-93e812345678', * 'REPORT RequestId: c6af9ac6-7b61-11e6-9a41-93e812345678\tDuration: 2.16 ms\tBilled Duration: 3 ms\tMemory Size: 128 MB\tMax Memory Used: 57 MB\t', * ] diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 9ad4a563cc..523bed85a4 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -257,7 +257,7 @@ class Logger extends Utility implements ClassThatLogs { descriptor.value = (event, context, callback) => { this.addContext(context); - return originalMethod?.apply(target, [event, context, callback]); + return originalMethod?.apply(target, [ event, context, callback ]); }; }; } @@ -368,7 +368,7 @@ class Logger extends Utility implements ClassThatLogs { * @returns {EnvironmentVariablesService} */ private getEnvVarsService(): EnvironmentVariablesService { - return this.envVarsService; + return this.envVarsService; } /** @@ -379,7 +379,7 @@ class Logger extends Utility implements ClassThatLogs { * @returns {LogFormatterInterface} */ private getLogFormatter(): LogFormatterInterface { - return this.logFormatter; + return this.logFormatter; } /** @@ -389,7 +389,7 @@ class Logger extends Utility implements ClassThatLogs { * @returns {LogLevel} */ private getLogLevel(): LogLevel { - return this.logLevel; + return this.logLevel; } /** @@ -400,7 +400,7 @@ class Logger extends Utility implements ClassThatLogs { * @returns {LogAttributes} */ private getPersistentLogAttributes(): LogAttributes { - return this.persistentLogAttributes; + return this.persistentLogAttributes; } /** @@ -425,7 +425,7 @@ class Logger extends Utility implements ClassThatLogs { this.setSampleRateValue(); } - return this.powertoolLogData?.sampleRateValue; + return this.powertoolLogData?.sampleRateValue; } /** diff --git a/packages/logger/tests/unit/Logger.test.ts b/packages/logger/tests/unit/Logger.test.ts index c0d0fc49fc..a6d5b034ac 100644 --- a/packages/logger/tests/unit/Logger.test.ts +++ b/packages/logger/tests/unit/Logger.test.ts @@ -26,10 +26,10 @@ describe('Class: Logger', () => { }); describe.each([ - ['debug', 'DOES', true, 'DOES NOT', false, 'DOES NOT', false, 'DOES NOT', false], - ['info', 'DOES', true, 'DOES', true, 'DOES NOT', false, 'DOES NOT', false], - ['warn', 'DOES', true, 'DOES', true, 'DOES', true, 'DOES NOT', false], - ['error', 'DOES', true, 'DOES', true, 'DOES', true, 'DOES', true], + [ 'debug', 'DOES', true, 'DOES NOT', false, 'DOES NOT', false, 'DOES NOT', false ], + [ 'info', 'DOES', true, 'DOES', true, 'DOES NOT', false, 'DOES NOT', false ], + [ 'warn', 'DOES', true, 'DOES', true, 'DOES', true, 'DOES NOT', false ], + [ 'error', 'DOES', true, 'DOES', true, 'DOES', true, 'DOES', true ], ])( 'Method: %p', ( From 349b1d2bdb042ef03121e479d76e9b9f21609af4 Mon Sep 17 00:00:00 2001 From: Andrea Amorosi Date: Wed, 13 Apr 2022 17:07:36 +0000 Subject: [PATCH 5/5] chore: updated commons unit tests --- .../commons/tests/unit/InvocationLogs.test.ts | 24 +++++++------------ 1 file changed, 8 insertions(+), 16 deletions(-) diff --git a/packages/commons/tests/unit/InvocationLogs.test.ts b/packages/commons/tests/unit/InvocationLogs.test.ts index 1ef5e33cc2..e0617c8ebe 100644 --- a/packages/commons/tests/unit/InvocationLogs.test.ts +++ b/packages/commons/tests/unit/InvocationLogs.test.ts @@ -8,10 +8,10 @@ import { InvocationLogs, LEVEL } from '../utils/InvocationLogs'; const exampleLogs = `START RequestId: c6af9ac6-7b61-11e6-9a41-93e812345678 Version: $LATEST -2022-01-27T16:04:39.323Z\tc6af9ac6-7b61-11e6-9a41-93e812345678\tDEBUG\t{"cold_start":true,"function_arn":"arn:aws:lambda:eu-west-1:561912387782:function:loggerMiddyStandardFeatures-c555a2ec-1121-4586-9c04-185ab36ea34c","function_memory_size":128,"function_name":"loggerMiddyStandardFeatures-c555a2ec-1121-4586-9c04-185ab36ea34c","function_request_id":"7f586697-238a-4c3b-9250-a5f057c1119c","level":"DEBUG","message":"This is a DEBUG log but contains the word INFO some context and persistent key","service":"logger-e2e-testing","timestamp":"2022-01-27T16:04:39.323Z","persistentKey":"works"} -2022-01-27T16:04:39.323Z\tc6af9ac6-7b61-11e6-9a41-93e812345678\tINFO\t{"cold_start":true,"function_arn":"arn:aws:lambda:eu-west-1:561912387782:function:loggerMiddyStandardFeatures-c555a2ec-1121-4586-9c04-185ab36ea34c","function_memory_size":128,"function_name":"loggerMiddyStandardFeatures-c555a2ec-1121-4586-9c04-185ab36ea34c","function_request_id":"7f586697-238a-4c3b-9250-a5f057c1119c","level":"INFO","message":"This is an INFO log with some context","service":"logger-e2e-testing","timestamp":"2022-01-27T16:04:39.323Z","persistentKey":"works","additionalKey":"additionalValue"} -2022-01-27T16:04:39.323Z\tc6af9ac6-7b61-11e6-9a41-93e812345678\tINFO\t{"cold_start":true,"function_arn":"arn:aws:lambda:eu-west-1:561912387782:function:loggerMiddyStandardFeatures-c555a2ec-1121-4586-9c04-185ab36ea34c","function_memory_size":128,"function_name":"loggerMiddyStandardFeatures-c555a2ec-1121-4586-9c04-185ab36ea34c","function_request_id":"7f586697-238a-4c3b-9250-a5f057c1119c","level":"INFO","message":"This is a second INFO log with some context","service":"logger-e2e-testing","timestamp":"2022-01-27T16:04:39.323Z","persistentKey":"works","additionalKey":"additionalValue"} -2022-01-27T16:04:39.323Z\tc6af9ac6-7b61-11e6-9a41-93e812345678\tERROR\t{"cold_start":true,"function_arn":"arn:aws:lambda:eu-west-1:561912387782:function:loggerMiddyStandardFeatures-c555a2ec-1121-4586-9c04-185ab36ea34c","function_memory_size":128,"function_name":"loggerMiddyStandardFeatures-c555a2ec-1121-4586-9c04-185ab36ea34c","function_request_id":"7f586697-238a-4c3b-9250-a5f057c1119c","level":"ERROR","message":"There was an error","service":"logger-e2e-testing","timestamp":"2022-01-27T16:04:39.323Z","persistentKey":"works","error":{"name":"Error","location":"/var/task/index.js:2778","message":"you cannot prevent this","stack":"Error: you cannot prevent this\\n at testFunction (/var/task/index.js:2778:11)\\n at runRequest (/var/task/index.js:2314:36)"}} +{"cold_start":true,"function_arn":"arn:aws:lambda:eu-west-1:561912387782:function:loggerMiddyStandardFeatures-c555a2ec-1121-4586-9c04-185ab36ea34c","function_memory_size":128,"function_name":"loggerMiddyStandardFeatures-c555a2ec-1121-4586-9c04-185ab36ea34c","function_request_id":"7f586697-238a-4c3b-9250-a5f057c1119c","level":"DEBUG","message":"This is a DEBUG log but contains the word INFO some context and persistent key","service":"logger-e2e-testing","timestamp":"2022-01-27T16:04:39.323Z","persistentKey":"works"} +{"cold_start":true,"function_arn":"arn:aws:lambda:eu-west-1:561912387782:function:loggerMiddyStandardFeatures-c555a2ec-1121-4586-9c04-185ab36ea34c","function_memory_size":128,"function_name":"loggerMiddyStandardFeatures-c555a2ec-1121-4586-9c04-185ab36ea34c","function_request_id":"7f586697-238a-4c3b-9250-a5f057c1119c","level":"INFO","message":"This is an INFO log with some context","service":"logger-e2e-testing","timestamp":"2022-01-27T16:04:39.323Z","persistentKey":"works","additionalKey":"additionalValue"} +{"cold_start":true,"function_arn":"arn:aws:lambda:eu-west-1:561912387782:function:loggerMiddyStandardFeatures-c555a2ec-1121-4586-9c04-185ab36ea34c","function_memory_size":128,"function_name":"loggerMiddyStandardFeatures-c555a2ec-1121-4586-9c04-185ab36ea34c","function_request_id":"7f586697-238a-4c3b-9250-a5f057c1119c","level":"INFO","message":"This is a second INFO log with some context","service":"logger-e2e-testing","timestamp":"2022-01-27T16:04:39.323Z","persistentKey":"works","additionalKey":"additionalValue"} +{"cold_start":true,"function_arn":"arn:aws:lambda:eu-west-1:561912387782:function:loggerMiddyStandardFeatures-c555a2ec-1121-4586-9c04-185ab36ea34c","function_memory_size":128,"function_name":"loggerMiddyStandardFeatures-c555a2ec-1121-4586-9c04-185ab36ea34c","function_request_id":"7f586697-238a-4c3b-9250-a5f057c1119c","level":"ERROR","message":"There was an error","service":"logger-e2e-testing","timestamp":"2022-01-27T16:04:39.323Z","persistentKey":"works","error":{"name":"Error","location":"/var/task/index.js:2778","message":"you cannot prevent this","stack":"Error: you cannot prevent this\\n at testFunction (/var/task/index.js:2778:11)\\n at runRequest (/var/task/index.js:2314:36)"}} END RequestId: c6af9ac6-7b61-11e6-9a41-93e812345678 REPORT RequestId: c6af9ac6-7b61-11e6-9a41-93e812345678\tDuration: 2.16 ms\tBilled Duration: 3 ms\tMemory Size: 128 MB\tMax Memory Used: 57 MB\t`; @@ -104,13 +104,10 @@ describe('getFunctionLogs()', () => { describe('parseFunctionLog()', () => { test('it should return object with the correct values based on the given log', () => { - const rawLogStr = '2022-01-27T16:04:39.323Z\tc6af9ac6-7b61-11e6-9a41-93e812345678\tDEBUG\t{"cold_start":true,"function_arn":"arn:aws:lambda:eu-west-1:561912387782:function:loggerMiddyStandardFeatures-c555a2ec-1121-4586-9c04-185ab36ea34c","function_memory_size":128,"function_name":"loggerMiddyStandardFeatures-c555a2ec-1121-4586-9c04-185ab36ea34c","function_request_id":"7f586697-238a-4c3b-9250-a5f057c1119c","level":"DEBUG","message":"This is a DEBUG log but contains the word INFO some context and persistent key","service":"logger-e2e-testing","timestamp":"2022-01-27T16:04:39.323Z","persistentKey":"works"}'; + const rawLogStr = '{"cold_start":true,"function_arn":"arn:aws:lambda:eu-west-1:561912387782:function:loggerMiddyStandardFeatures-c555a2ec-1121-4586-9c04-185ab36ea34c","function_memory_size":128,"function_name":"loggerMiddyStandardFeatures-c555a2ec-1121-4586-9c04-185ab36ea34c","function_request_id":"7f586697-238a-4c3b-9250-a5f057c1119c","level":"DEBUG","message":"This is a DEBUG log but contains the word INFO some context and persistent key","service":"logger-e2e-testing","timestamp":"2022-01-27T16:04:39.323Z","persistentKey":"works"}'; const logObj = InvocationLogs.parseFunctionLog(rawLogStr); - expect(logObj.timestamp).toBe('2022-01-27T16:04:39.323Z'); - expect(logObj.invocationId).toBe('c6af9ac6-7b61-11e6-9a41-93e812345678'); - expect(logObj.logLevel).toBe(LEVEL.DEBUG); - expect(logObj.logObject).toStrictEqual({ + expect(logObj).toStrictEqual({ cold_start: true, function_arn: 'arn:aws:lambda:eu-west-1:561912387782:function:loggerMiddyStandardFeatures-c555a2ec-1121-4586-9c04-185ab36ea34c', function_memory_size: 128, @@ -125,14 +122,9 @@ describe('parseFunctionLog()', () => { }); test('it should throw an error if receive incorrect formatted raw log string', () => { - const noTabString = 'no-tab-character'; + const notJSONstring = 'not-json-string'; expect(() => { - InvocationLogs.parseFunctionLog(noTabString); - }).toThrow(Error); - - const missSomeElements = '2022-01-27T16:04:39.323Z\tc6af9ac6-7b61-11e6-9a41-93e812345678\tDEBUG\t'; - expect(() => { - InvocationLogs.parseFunctionLog(missSomeElements); + InvocationLogs.parseFunctionLog(notJSONstring); }).toThrow(Error); }); }); \ No newline at end of file