diff --git a/packages/commons/tests/utils/InvocationLogs.ts b/packages/commons/tests/utils/InvocationLogs.ts index 730e6f8e87..fd2b9f3e4c 100644 --- a/packages/commons/tests/utils/InvocationLogs.ts +++ b/packages/commons/tests/utils/InvocationLogs.ts @@ -69,28 +69,30 @@ export class InvocationLogs { * @returns {number} index of the log that contains END RequestId */ public static getEndLogIndex(logs: string[]): number { - return logs.findIndex((log) => log.includes('END RequestId')); + return logs.findIndex((log) => log.startsWith('END RequestId')); } /** - * Return only logs from function, exclude START, END, REPORT, and XRay log generated by Lambda service - * @param levelToFilter level to filter - * @returns Array of function logs + * Return only logs from function, exclude START, END, REPORT, + * and X-Ray log generated by the Lambda service. + * + * @param {LEVEL} [levelToFilter] - Level to filter the logs + * @returns Array of function logs, filtered by level if provided */ public getFunctionLogs(levelToFilter?: LEVEL): string[] { + const startLogIndex = InvocationLogs.getStartLogIndex(this.logs); const endLogIndex = InvocationLogs.getEndLogIndex(this.logs); - let filteredLogs = this.logs.slice(1, endLogIndex); + let filteredLogs = this.logs.slice(startLogIndex + 1, endLogIndex); if (levelToFilter) { filteredLogs = filteredLogs.filter((log) => { try { - const parsedLog = JSON.parse(log); - if (parsedLog.level == levelToFilter) return parsedLog; - else return; + const parsedLog = InvocationLogs.parseFunctionLog(log); + + return parsedLog.level == levelToFilter; } catch (error) { // If log is not from structured logging : such as metrics one. - if (log.split('\t')[2] == levelToFilter) return log; - else return; + return log.split('\t')[2] == levelToFilter; } }); } @@ -98,6 +100,10 @@ export class InvocationLogs { return filteredLogs; } + public static getStartLogIndex(logs: string[]): number { + return logs.findIndex((log) => log.startsWith('START RequestId')); + } + /** * Each of log message contains a JSON with the structured Log object (e.g. {\"cold_start\":true, ..}) * @param log diff --git a/packages/logger/tests/e2e/basicFeatures.middy.test.FunctionCode.ts b/packages/logger/tests/e2e/basicFeatures.middy.test.FunctionCode.ts index c434a7892a..116424e395 100644 --- a/packages/logger/tests/e2e/basicFeatures.middy.test.FunctionCode.ts +++ b/packages/logger/tests/e2e/basicFeatures.middy.test.FunctionCode.ts @@ -1,73 +1,66 @@ import { injectLambdaContext, Logger } from '../../src'; import { Context, APIGatewayAuthorizerResult } from 'aws-lambda'; +import { TestEvent, TestOutput } from '../helpers/types'; import middy from '@middy/core'; -const PERSISTENT_KEY = process.env.PERSISTENT_KEY; -const PERSISTENT_KEY_FIRST_INVOCATION_ONLY = process.env.PERSISTENT_KEY_FIRST_INVOCATION_ONLY; -const PERSISTENT_VALUE = process.env.PERSISTENT_VALUE; -const REMOVABLE_KEY = process.env.REMOVABLE_KEY; -const REMOVABLE_VALUE = process.env.REMOVABLE_VALUE; +const PERSISTENT_KEY = process.env.PERSISTENT_KEY || 'persistentKey'; +const PERSISTENT_VALUE = process.env.PERSISTENT_VALUE || 'persistentValue'; +const REMOVABLE_KEY = process.env.REMOVABLE_KEY || 'removableKey'; +const REMOVABLE_VALUE = process.env.REMOVABLE_VALUE || 'remvovableValue'; const ERROR_MSG = process.env.ERROR_MSG || 'error'; -const SINGLE_LOG_ITEM_KEY = process.env.SINGLE_LOG_ITEM_KEY; -const SINGLE_LOG_ITEM_VALUE = process.env.SINGLE_LOG_ITEM_VALUE; -const ARBITRARY_OBJECT_KEY = process.env.ARBITRARY_OBJECT_KEY; -const ARBITRARY_OBJECT_DATA = process.env.ARBITRARY_OBJECT_DATA; - -type LambdaEvent = { - invocation: number -}; +const RUNTIME_ADDED_KEY = process.env.RUNTIME_ADDED_KEY || 'runtimeAddedKey'; +const SINGLE_LOG_ITEM_KEY = process.env.SINGLE_LOG_ITEM_KEY || 'keyForSingleLogItem'; +const SINGLE_LOG_ITEM_VALUE = process.env.SINGLE_LOG_ITEM_VALUE || 'valueForSingleLogItem'; +const ARBITRARY_OBJECT_KEY = process.env.ARBITRARY_OBJECT_KEY || 'keyForArbitraryObject'; +const ARBITRARY_OBJECT_DATA = process.env.ARBITRARY_OBJECT_DATA || 'arbitrary object data'; const logger = new Logger({ persistentLogAttributes: { - [PERSISTENT_KEY]: PERSISTENT_VALUE, - [REMOVABLE_KEY]: REMOVABLE_VALUE, + [PERSISTENT_KEY]: PERSISTENT_VALUE, // This key-value pair will be added to every log + [REMOVABLE_KEY]: REMOVABLE_VALUE, // This other one will be removed at runtime and not displayed in any log }, }); -const testFunction = async (event: LambdaEvent, context: Context): Promise<{requestId: string}> => { - // Test feature 1: Log level filtering - // Test feature 2: Context data - // Test feature 3: Add and remove persistent additional log keys and value - // Test feature 4: X-Ray Trace ID injection - logger.removeKeys([REMOVABLE_KEY]); - - const specialValue = event.invocation; - if (specialValue === 0) { - logger.appendKeys({ - [PERSISTENT_KEY_FIRST_INVOCATION_ONLY]: specialValue - }); - } - +const testFunction = async (event: TestEvent, context: Context): TestOutput => { + // Test feature 1: Context data injection (all logs should have the same context data) + // Test feature 2: Event log (this log should have the event data) + // Test feature 3: Log level filtering (log level is set to INFO) logger.debug('##### This should not appear'); - logger.info('This is an INFO log with context and persistent key'); + + // Test feature 4: Add and remove persistent additional log keys and value + logger.removeKeys([REMOVABLE_KEY]); // This key should not appear in any log (except the event log) + logger.appendKeys({ // This key-value pair should appear in every log (except the event log) + [RUNTIME_ADDED_KEY]: event.invocation, + }); // Test feature 5: One-time additional log keys and values logger.info('This is an one-time log with an additional key-value', { [SINGLE_LOG_ITEM_KEY]: SINGLE_LOG_ITEM_VALUE, }); - // Test feature 6: Logging an error object + // Test feature 6: Error logging try { throw new Error(ERROR_MSG); } catch (e) { logger.error(ERROR_MSG, e as Error); } - // Test feature 7: Logging an arbitrary object + // Test feature 7: Arbitrary object logging const obj: APIGatewayAuthorizerResult = { principalId: ARBITRARY_OBJECT_DATA, policyDocument: { - Version: 'Version' + ARBITRARY_OBJECT_DATA, + Version: 'Version 1', Statement: [{ - Effect: 'Effect' + ARBITRARY_OBJECT_DATA, - Action: 'Action' + ARBITRARY_OBJECT_DATA, - Resource: 'Resource' + ARBITRARY_OBJECT_DATA + Effect: 'Allow', + Action: 'geo:*', + Resource: '*', }] } }; - logger.info('A log entry with an object', { [ARBITRARY_OBJECT_KEY]: obj }); + // Test feature 8: X-Ray Trace ID injection (all logs should have the same X-Ray Trace ID) + return { requestId: context.awsRequestId, }; diff --git a/packages/logger/tests/e2e/basicFeatures.middy.test.ts b/packages/logger/tests/e2e/basicFeatures.middy.test.ts index d12583b84a..04757def04 100644 --- a/packages/logger/tests/e2e/basicFeatures.middy.test.ts +++ b/packages/logger/tests/e2e/basicFeatures.middy.test.ts @@ -1,12 +1,8 @@ -// Copyright Amazon.com, Inc. or its affiliates. All Rights Reserved. -// SPDX-License-Identifier: MIT-0 - /** * Test logger basic features * * @group e2e/logger/basicFeatures */ - import path from 'path'; import { App, Stack } from 'aws-cdk-lib'; import { APIGatewayAuthorizerResult } from 'aws-lambda'; @@ -24,7 +20,8 @@ import { STACK_OUTPUT_LOG_GROUP, SETUP_TIMEOUT, TEST_CASE_TIMEOUT, - TEARDOWN_TIMEOUT + TEARDOWN_TIMEOUT, + XRAY_TRACE_ID_REGEX, } from './constants'; const runtime: string = process.env.RUNTIME || 'nodejs18x'; @@ -40,17 +37,19 @@ const stackName = generateUniqueName(RESOURCE_NAME_PREFIX, uuid, runtime, 'Basic const functionName = generateUniqueName(RESOURCE_NAME_PREFIX, uuid, runtime, 'BasicFeatures-Middy'); const lambdaFunctionCodeFile = 'basicFeatures.middy.test.FunctionCode.ts'; +const invocationCount = 3; + // Text to be used by Logger in the Lambda function const PERSISTENT_KEY = 'persistentKey'; -const PERSISTENT_KEY_FIRST_INVOCATION_ONLY = 'specialKey'; -const PERSISTENT_VALUE = `a persistent value that will be put in every log ${uuid}`; +const RUNTIME_ADDED_KEY = 'invocation'; +const PERSISTENT_VALUE = uuid; const REMOVABLE_KEY = 'removableKey'; -const REMOVABLE_VALUE = `a persistent value that will be removed and not displayed in any log ${uuid}`; -const SINGLE_LOG_ITEM_KEY = `keyForSingleLogItem${uuid}`; -const SINGLE_LOG_ITEM_VALUE = `a value for a single log item${uuid}`; -const ERROR_MSG = `error-${uuid}`; -const ARBITRARY_OBJECT_KEY = `keyForArbitraryObject${uuid}`; -const ARBITRARY_OBJECT_DATA = `arbitrary object data ${uuid}`; +const REMOVABLE_VALUE = 'removedValue'; +const SINGLE_LOG_ITEM_KEY = 'singleKey'; +const SINGLE_LOG_ITEM_VALUE = 'singleValue'; +const ERROR_MSG = 'error'; +const ARBITRARY_OBJECT_KEY = 'arbitraryObjectKey'; +const ARBITRARY_OBJECT_DATA = 'arbitraryObjectData'; const integTestApp = new App(); let logGroupName: string; // We do not know it until deployment @@ -74,8 +73,8 @@ describe(`logger E2E tests basic functionalities (middy) for runtime: ${runtime} // Text to be used by Logger in the Lambda function PERSISTENT_KEY, - PERSISTENT_KEY_FIRST_INVOCATION_ONLY, PERSISTENT_VALUE, + RUNTIME_ADDED_KEY, REMOVABLE_KEY, REMOVABLE_VALUE, SINGLE_LOG_ITEM_KEY, @@ -91,171 +90,261 @@ describe(`logger E2E tests basic functionalities (middy) for runtime: ${runtime} const result = await deployStack(integTestApp, stack); logGroupName = result.outputs[STACK_OUTPUT_LOG_GROUP]; - // Invoke the function twice (one for cold start, another for warm start) - invocationLogs = await invokeFunction(functionName, 2, 'SEQUENTIAL'); + // Invoke the function three time (one for cold start, then two for warm start) + invocationLogs = await invokeFunction(functionName, invocationCount, 'SEQUENTIAL'); console.log('logGroupName', logGroupName); }, SETUP_TIMEOUT); describe('Log level filtering', () => { + it('should filter log based on LOG_LEVEL (INFO) environment variable in Lambda', async () => { - const debugLogs = invocationLogs[0].getFunctionLogs(LEVEL.DEBUG); - expect(debugLogs.length).toBe(0); + + for (let i = 0; i < invocationCount; i++) { + // Get log messages of the invocation and filter by level + const debugLogs = invocationLogs[i].getFunctionLogs(LEVEL.DEBUG); + // Check that no log message below INFO level is logged + expect(debugLogs.length).toBe(0); + } + }, TEST_CASE_TIMEOUT); }); describe('Context data', () => { - it('should log context information of the function', async () => { - const logMessages = invocationLogs[0].getFunctionLogs(); - - for (const message of logMessages) { - expect(message).toContain('function_arn'); - expect(message).toContain('function_memory_size'); - expect(message).toContain('function_name'); - expect(message).toContain('function_request_id'); - expect(message).toContain('timestamp'); - } - }, TEST_CASE_TIMEOUT); - it('should include cold start equal to TRUE only on the first invocation', async () => { - const coldStartLogMessages = invocationLogs[0].getFunctionLogs(LEVEL.INFO); - for (const message of coldStartLogMessages) { - expect(message).toContain(`"cold_start":true`); + it('should inject context info in each log', async () => { + + for (let i = 0; i < invocationCount; i++) { + // Get log messages of the invocation + const logMessages = invocationLogs[i].getFunctionLogs(); + // Check that the context is logged on every log + for (const message of logMessages) { + const log = InvocationLogs.parseFunctionLog(message); + expect(log).toHaveProperty('function_arn'); + expect(log).toHaveProperty('function_memory_size'); + expect(log).toHaveProperty('function_name'); + expect(log).toHaveProperty('function_request_id'); + expect(log).toHaveProperty('timestamp'); + } } - const normalLogMessages = invocationLogs[1].getFunctionLogs(LEVEL.INFO); - for (const message of normalLogMessages) { - expect(message).not.toContain(`"cold_start":true`); - } }, TEST_CASE_TIMEOUT); - it('should log context information in every log', async () => { - const logMessages = invocationLogs[0].getFunctionLogs(); - - for (const message of logMessages) { - expect(message).toContain('function_arn'); - expect(message).toContain('function_memory_size'); - expect(message).toContain('function_name'); - expect(message).toContain('function_request_id'); - expect(message).toContain('timestamp'); + it('should include coldStart equal to TRUE only on the first invocation, FALSE otherwise', async () => { + + for (let i = 0; i < invocationCount; i++) { + // Get log messages of the invocation + const logMessages = invocationLogs[i].getFunctionLogs(); + // Check that cold start is logged correctly on every log + for (const message of logMessages) { + const log = InvocationLogs.parseFunctionLog(message); + if (i === 0) { + expect(log.cold_start).toBe(true); + } else { + expect(log.cold_start).toBe(false); + } + } } + }, TEST_CASE_TIMEOUT); + }); describe('Log event', () => { - it('should log the event on the first invocation', async () => { - const firstInvocationMessages = invocationLogs[0].getAllFunctionLogs(); - let eventLoggedInFirstInvocation = false; - for (const message of firstInvocationMessages) { - if (message.includes(`event`)) { - eventLoggedInFirstInvocation = true; - expect(message).toContain(`"event":{"invocation":0}`); + it('should log the event as the first log of each invocation only', async () => { + + for (let i = 0; i < invocationCount; i++) { + // Get log messages of the invocation + const logMessages = invocationLogs[i].getFunctionLogs(); + + for (const [ index, message ] of logMessages.entries()) { + const log = InvocationLogs.parseFunctionLog(message); + // Check that the event is logged on the first log + if (index === 0) { + expect(log).toHaveProperty('event'); + expect(log.event).toStrictEqual( + expect.objectContaining({ invocation: i }) + ); + // Check that the event is not logged again on the rest of the logs + } else { + expect(log).not.toHaveProperty('event'); + } } } - const secondInvocationMessages = invocationLogs[1].getAllFunctionLogs(); - let eventLoggedInSecondInvocation = false; - for (const message of secondInvocationMessages) { - if (message.includes(`event`)) { - eventLoggedInSecondInvocation = true; - expect(message).toContain(`"event":{"invocation":1}`); - } - } - - expect(eventLoggedInFirstInvocation).toBe(true); - expect(eventLoggedInSecondInvocation).toBe(true); - }, TEST_CASE_TIMEOUT); }); describe('Persistent additional log keys and values', () => { + it('should contain persistent value in every log', async () => { - const logMessages = invocationLogs[0].getFunctionLogs(); - for (const message of logMessages) { - expect(message).toContain(`"${PERSISTENT_KEY}":"${PERSISTENT_VALUE}"`); + for (let i = 0; i < invocationCount; i++) { + // Get log messages of the invocation + const logMessages = invocationLogs[i].getFunctionLogs(); + + for (const message of logMessages) { + const log = InvocationLogs.parseFunctionLog(message); + // Check that the persistent key is present in every log + expect(log).toHaveProperty(PERSISTENT_KEY); + expect(log[PERSISTENT_KEY]).toBe(PERSISTENT_VALUE); + } } + }, TEST_CASE_TIMEOUT); it('should not contain persistent keys that were removed on runtime', async () => { - const logMessages = invocationLogs[0].getFunctionLogs(); - for (const message of logMessages) { - expect(message).not.toContain(`"${REMOVABLE_KEY}":"${REMOVABLE_VALUE}"`); + for (let i = 0; i < invocationCount; i++) { + // Get log messages of the invocation + const logMessages = invocationLogs[i].getFunctionLogs(); + + for (const [ index, message ] of logMessages.entries()) { + const log = InvocationLogs.parseFunctionLog(message); + // Check that at the time of logging the event, which happens before the handler, + // the key was still present + if (index === 0) { + expect(log).toHaveProperty(REMOVABLE_KEY); + expect(log[REMOVABLE_KEY]).toBe(REMOVABLE_VALUE); + // Check that all other logs that happen at runtime do not contain the key + } else { + expect(log).not.toHaveProperty(REMOVABLE_KEY); + } + } } + }, TEST_CASE_TIMEOUT); - it('with clear state enabled, should not persist keys across invocations', async () => { - const firstInvocationMessages = invocationLogs[0].getFunctionLogs(); - for (const message of firstInvocationMessages) { - expect(message).toContain(`"${PERSISTENT_KEY_FIRST_INVOCATION_ONLY}":0`); + it('should not leak any persistent keys added runtime since clearState is enabled', async () => { + + for (let i = 0; i < invocationCount; i++) { + // Get log messages of the invocation + const logMessages = invocationLogs[i].getFunctionLogs(); + + for (const [ index, message ] of logMessages.entries()) { + const log = InvocationLogs.parseFunctionLog(message); + // Check that at the time of logging the event, which happens before the handler, + // the key is NOT present + if (index === 0) { + expect(log).not.toHaveProperty(RUNTIME_ADDED_KEY); + } else { + // Check that all other logs that happen at runtime do contain the key + expect(log).toHaveProperty(RUNTIME_ADDED_KEY); + // Check that the value is the same for all logs (it should be the index of the invocation) + expect(log[RUNTIME_ADDED_KEY]).toEqual(i); + } + } } - const secondInvocationMessages = invocationLogs[1].getFunctionLogs(); - for (const message of secondInvocationMessages) { - expect(message).not.toContain(`"${PERSISTENT_KEY_FIRST_INVOCATION_ONLY}":0`); - } }, TEST_CASE_TIMEOUT); }); - describe('X-Ray Trace ID injection', () => { - it('should inject & parse X-Ray Trace ID into every log', async () => { - const logMessages = invocationLogs[0].getFunctionLogs(); + describe('One-time additional log keys and values', () => { + + it('should log additional keys and value only once', async () => { - for (const message of logMessages) { - expect(message).toContain('xray_trace_id'); + for (let i = 0; i < invocationCount; i++) { + // Get log messages of the invocation + const logMessages = invocationLogs[i].getFunctionLogs(); + // Check that the additional log is logged only once + const logMessagesWithAdditionalLog = logMessages.filter( + log => log.includes(SINGLE_LOG_ITEM_KEY) + ); + expect(logMessagesWithAdditionalLog).toHaveLength(1); + // Check that the additional log is logged correctly + const parsedLog = InvocationLogs + .parseFunctionLog(logMessagesWithAdditionalLog[0]); + expect(parsedLog[SINGLE_LOG_ITEM_KEY]).toBe(SINGLE_LOG_ITEM_VALUE); } + }, TEST_CASE_TIMEOUT); + }); - describe('One-time additional log keys and values', () => { - 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}"`)); + describe('Error logging', () => { + + it('should log error only once', async () => { + + for (let i = 0; i < invocationCount; i++) { + // Get log messages of the invocation filtered by error level + const logMessages = invocationLogs[i].getFunctionLogs(LEVEL.ERROR); + + // Check that the error is logged only once + expect(logMessages).toHaveLength(1); + + // Check that the error is logged correctly + const errorLog = InvocationLogs.parseFunctionLog(logMessages[0]); + expect(errorLog).toHaveProperty('error'); + expect(errorLog.error).toStrictEqual( + expect.objectContaining({ + location: expect.any(String), + name: 'Error', + message: ERROR_MSG, + stack: expect.anything() + }) + ); + + } - expect(logMessages).toHaveLength(1); }, TEST_CASE_TIMEOUT); + }); + + describe('Arbitrary object logging', () => { + it('should log additional arbitrary object only once', async () => { - const logMessages = invocationLogs[0].getFunctionLogs() - .filter(message => message.includes(ARBITRARY_OBJECT_DATA)); - - expect(logMessages).toHaveLength(1); - - const logObject = InvocationLogs.parseFunctionLog(logMessages[0]); - expect(logObject).toHaveProperty(ARBITRARY_OBJECT_KEY); - const arbitrary = logObject[ARBITRARY_OBJECT_KEY] as APIGatewayAuthorizerResult; - expect(arbitrary.principalId).toBe(ARBITRARY_OBJECT_DATA); - expect(arbitrary.policyDocument).toEqual(expect.objectContaining( - { - Version: 'Version' + ARBITRARY_OBJECT_DATA, - Statement: [{ - Effect: 'Effect' + ARBITRARY_OBJECT_DATA, - Action: 'Action' + ARBITRARY_OBJECT_DATA, - Resource: 'Resource' + ARBITRARY_OBJECT_DATA - }] - } - )); + + for (let i = 0; i < invocationCount; i++) { + // Get log messages of the invocation + const logMessages = invocationLogs[i].getFunctionLogs(); + // Get the log messages that contains the arbitrary object + const filteredLogs = logMessages + .filter(log => log.includes(ARBITRARY_OBJECT_DATA)); + // Check that the arbitrary object is logged only once + expect(filteredLogs).toHaveLength(1); + const logObject = InvocationLogs.parseFunctionLog(filteredLogs[0]); + // Check that the arbitrary object is logged correctly + expect(logObject).toHaveProperty(ARBITRARY_OBJECT_KEY); + const arbitrary = logObject[ARBITRARY_OBJECT_KEY] as APIGatewayAuthorizerResult; + expect(arbitrary.principalId).toBe(ARBITRARY_OBJECT_DATA); + expect(arbitrary.policyDocument).toEqual(expect.objectContaining( + { + Version: 'Version 1', + Statement: [{ + Effect: 'Allow', + Action: 'geo:*', + Resource: '*' + }] + } + )); + } + }, TEST_CASE_TIMEOUT); }); - describe('Logging an error object', () => { - it('should log error only once', async () => { - const logMessages = invocationLogs[0].getFunctionLogs(LEVEL.ERROR) - .filter(message => message.includes(ERROR_MSG)); - - expect(logMessages).toHaveLength(1); + describe('X-Ray Trace ID injection', () => { - const logObject = InvocationLogs.parseFunctionLog(logMessages[0]); - const errorObj = logObject.error; + it('should inject & parse the X-Ray Trace ID of the current invocation into every log', async () => { + + for (let i = 0; i < invocationCount; i++) { + // Get log messages of the invocation + const logMessages = invocationLogs[i].getFunctionLogs(); + + // Check that the X-Ray Trace ID is logged on every log + const traceIds: string[] = []; + for (const message of logMessages) { + const log = InvocationLogs.parseFunctionLog(message); + expect(log).toHaveProperty('xray_trace_id'); + expect(log.xray_trace_id).toMatch(XRAY_TRACE_ID_REGEX); + traceIds.push(log.xray_trace_id as string); + } + } - expect(errorObj.name).toBe('Error'); - expect(errorObj.message).toBe(ERROR_MSG); - expect(errorObj.stack).toBeDefined(); }, TEST_CASE_TIMEOUT); + }); afterAll(async () => { diff --git a/packages/logger/tests/e2e/childLogger.manual.test.FunctionCode.ts b/packages/logger/tests/e2e/childLogger.manual.test.FunctionCode.ts index a738eb6888..c4e0fd8ec3 100644 --- a/packages/logger/tests/e2e/childLogger.manual.test.FunctionCode.ts +++ b/packages/logger/tests/e2e/childLogger.manual.test.FunctionCode.ts @@ -1,15 +1,17 @@ import { Logger } from '../../src'; -import { APIGatewayProxyEvent, Context } from 'aws-lambda'; +import { Context } from 'aws-lambda'; +import { LogLevel } from '../../src/types'; +import { TestEvent, TestOutput } from '../helpers/types'; -const PARENT_PERSISTENT_KEY = process.env.PARENT_PERSISTENT_KEY; -const PARENT_PERSISTENT_VALUE = process.env.PARENT_PERSISTENT_VALUE; -const PARENT_LOG_MSG = process.env.PARENT_LOG_MSG; -const CHILD_LOG_MSG = process.env.PARENT_LOG_MSG; -const CHILD_LOG_LEVEL = process.env.CHILD_LOG_LEVEL; +const PERSISTENT_KEY = process.env.PERSISTENT_KEY || 'persistentKey'; +const PERSISTENT_VALUE = process.env.ERSISTENT_VALUE || 'persistentValue'; +const PARENT_LOG_MSG = process.env.PARENT_LOG_MSG || 'parent-only-log-msg'; +const CHILD_LOG_MSG = process.env.CHILD_LOG_MSG || 'child-only-log-msg'; +const CHILD_LOG_LEVEL = (process.env.CHILD_LOG_LEVEL || 'warn') as LogLevel; const parentLogger = new Logger({ persistentLogAttributes: { - [PARENT_PERSISTENT_KEY]: PARENT_PERSISTENT_VALUE, + [PERSISTENT_KEY]: PERSISTENT_VALUE, } }); @@ -18,7 +20,7 @@ const childLogger = parentLogger.createChild({ logLevel: CHILD_LOG_LEVEL, }); -export const handler = async (event: APIGatewayProxyEvent, context: Context): Promise<{requestId: string}> => { +export const handler = async (_event: TestEvent, context: Context): TestOutput => { parentLogger.addContext(context); childLogger.info(CHILD_LOG_MSG); diff --git a/packages/logger/tests/e2e/childLogger.manual.test.ts b/packages/logger/tests/e2e/childLogger.manual.test.ts index 5bce0bb4f5..1e11d52b0b 100644 --- a/packages/logger/tests/e2e/childLogger.manual.test.ts +++ b/packages/logger/tests/e2e/childLogger.manual.test.ts @@ -1,12 +1,8 @@ -// Copyright Amazon.com, Inc. or its affiliates. All Rights Reserved. -// SPDX-License-Identifier: MIT-0 - /** * Test logger child logger * * @group e2e/logger/childLogger */ - import path from 'path'; import { App, Stack } from 'aws-cdk-lib'; import { v4 } from 'uuid'; @@ -39,16 +35,19 @@ const stackName = generateUniqueName(RESOURCE_NAME_PREFIX, uuid, runtime, 'Child const functionName = generateUniqueName(RESOURCE_NAME_PREFIX, uuid, runtime, 'ChildLogger-Manual'); const lambdaFunctionCodeFile = 'childLogger.manual.test.FunctionCode.ts'; +const invocationCount = 3; + // Parameters to be used by Logger in the Lambda function -const PARENT_PERSISTENT_KEY = 'persistentKey'; -const PARENT_PERSISTENT_VALUE = `a persistent value that will be put in prent only ${uuid}`; -const PARENT_LOG_MSG = `only PARENT logger will log with this message ${uuid}`; -const CHILD_LOG_MSG = `only CHILD logger will log with this message ${uuid}`; -const CHILD_LOG_LEVEL = LEVEL.ERROR.toString(); +const PERSISTENT_KEY = 'persistentKey'; +const PERSISTENT_VALUE = 'persistentValue'; +const PARENT_LOG_MSG = 'parent-only-log-msg'; +const CHILD_LOG_MSG = 'child-only-log-msg'; +const CHILD_LOG_LEVEL = LEVEL.ERROR; const integTestApp = new App(); let logGroupName: string; // We do not know it until deployment let stack: Stack; + describe(`logger E2E tests child logger functionalities (manual) for runtime: ${runtime}`, () => { let invocationLogs: InvocationLogs[]; @@ -67,8 +66,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, + PERSISTENT_KEY, + PERSISTENT_VALUE, PARENT_LOG_MSG, CHILD_LOG_MSG, CHILD_LOG_LEVEL, @@ -79,55 +78,89 @@ describe(`logger E2E tests child logger functionalities (manual) for runtime: ${ const result = await deployStack(integTestApp, stack); logGroupName = result.outputs[STACK_OUTPUT_LOG_GROUP]; - // Invoke the function once - invocationLogs = await invokeFunction(functionName, 1); + // Invoke the function three time (one for cold start, then two for warm start) + invocationLogs = await invokeFunction(functionName, invocationCount); console.log('logGroupName', logGroupName); }, SETUP_TIMEOUT); - const getAllChildLogs = (): string[] => invocationLogs[0].getFunctionLogs() - .filter(message => message.includes(CHILD_LOG_MSG)); - describe('Child logger', () => { - it('should not log at parent log level', async () => { - // Only parents log will appear at info level - const allInfoLogs = invocationLogs[0].getFunctionLogs(LEVEL.INFO); - const parentInfoLogs = allInfoLogs.filter(message => message.includes(PARENT_LOG_MSG)); - const childInfoLogs = allInfoLogs.filter(message => message.includes(CHILD_LOG_MSG)); - - expect(parentInfoLogs).toHaveLength(allInfoLogs.length); - expect(childInfoLogs).toHaveLength(0); + + it('should not log at same level of parent because of its own logLevel', async () => { + + for (let i = 0; i < invocationCount; i++) { + // Get log messages of the invocation and filter by level + const infoLogs = invocationLogs[i].getFunctionLogs(LEVEL.INFO); + + const parentInfoLogs = infoLogs + .filter(message => message.includes(PARENT_LOG_MSG)); + const childInfoLogs = infoLogs + .filter(message => message.includes(CHILD_LOG_MSG)); + + expect(parentInfoLogs).toHaveLength(infoLogs.length); + expect(childInfoLogs).toHaveLength(0); + } + }, TEST_CASE_TIMEOUT); it('should log only level passed to a child', async () => { - const allChildLogs = getAllChildLogs(); - const errorChildLogs = allChildLogs.filter(message => message.includes(LEVEL.ERROR.toString())); - expect(errorChildLogs).toHaveLength(allChildLogs.length); + for (let i = 0; i < invocationCount; i++) { + // Get log messages of the invocation + const logMessages = invocationLogs[i].getFunctionLogs(); + + // Filter child logs by level + const errorChildLogs = logMessages + .filter( + message => message.includes(LEVEL.ERROR.toString()) && + message.includes(CHILD_LOG_MSG) + ); + + // Check that the child logger only logged once (the other) + // log was filtered out by the child logger because of its logLevel + expect(errorChildLogs).toHaveLength(1); + } + }, TEST_CASE_TIMEOUT); it('should NOT inject context into the child logger', async () => { - // Only parent has injected context. - const allChildLogs = getAllChildLogs(); - - for (const log of allChildLogs) { - expect(log).not.toContain('function_arn'); - expect(log).not.toContain('function_memory_size'); - expect(log).not.toContain('function_name'); - expect(log).not.toContain('function_request_id'); - expect(log).not.toContain('timestamp'); + + for (let i = 0; i < invocationCount; i++) { + // Get log messages of the invocation + const logMessages = invocationLogs[i].getFunctionLogs(); + + // Filter child logs by level + const childLogMessages = logMessages + .filter(message => message.includes(CHILD_LOG_MSG)); + + // Check that the context is not present in any of the child logs + for (const message of childLogMessages) { + const log = InvocationLogs.parseFunctionLog(message); + expect(log).not.toHaveProperty('function_arn'); + expect(log).not.toHaveProperty('function_memory_size'); + expect(log).not.toHaveProperty('function_name'); + expect(log).not.toHaveProperty('function_request_id'); + } } + }, TEST_CASE_TIMEOUT); - it('should NOT have parent logger persistent key/value', async () => { - // Only parent has injected context. - const allChildLogs = getAllChildLogs(); + it('both logger instances should have the same persistent key/value', async () => { + + for (let i = 0; i < invocationCount; i++) { + // Get log messages of the invocation + const logMessages = invocationLogs[i].getFunctionLogs(); - for (const log of allChildLogs) { - expect(log).not.toContain(`"${PARENT_PERSISTENT_KEY}":"${PARENT_PERSISTENT_VALUE}"`); + // Check that all logs have the persistent key/value + for (const message of logMessages) { + const log = InvocationLogs.parseFunctionLog(message); + expect(log).toHaveProperty(PERSISTENT_KEY); + } } + }, TEST_CASE_TIMEOUT); + }); afterAll(async () => { diff --git a/packages/logger/tests/e2e/constants.ts b/packages/logger/tests/e2e/constants.ts index 79eb64e5aa..25c928e0c1 100644 --- a/packages/logger/tests/e2e/constants.ts +++ b/packages/logger/tests/e2e/constants.ts @@ -3,4 +3,5 @@ export const ONE_MINUTE = 60 * 1000; export const TEST_CASE_TIMEOUT = ONE_MINUTE; export const SETUP_TIMEOUT = 5 * ONE_MINUTE; export const TEARDOWN_TIMEOUT = 5 * ONE_MINUTE; -export const STACK_OUTPUT_LOG_GROUP = 'LogGroupName'; \ No newline at end of file +export const STACK_OUTPUT_LOG_GROUP = 'LogGroupName'; +export const XRAY_TRACE_ID_REGEX = /^1-[0-9a-f]{8}-[0-9a-f]{24}$/; \ No newline at end of file diff --git a/packages/logger/tests/e2e/logEventEnvVarSetting.middy.test.FunctionCode.ts b/packages/logger/tests/e2e/logEventEnvVarSetting.middy.test.FunctionCode.ts index 6d412daf06..6fdcd1ec62 100644 --- a/packages/logger/tests/e2e/logEventEnvVarSetting.middy.test.FunctionCode.ts +++ b/packages/logger/tests/e2e/logEventEnvVarSetting.middy.test.FunctionCode.ts @@ -1,16 +1,14 @@ import { injectLambdaContext, Logger } from '../../src'; +import { TestEvent, TestOutput } from '../helpers/types'; import { Context } from 'aws-lambda'; import middy from '@middy/core'; -type LambdaEvent = { - invocation: number -}; - const logger = new Logger(); -const testFunction = async (event: LambdaEvent, context: Context): Promise<{requestId: string}> => ({ +const testFunction = async (_event: TestEvent, context: Context): TestOutput => ({ requestId: context.awsRequestId, }); export const handler = middy(testFunction) - .use(injectLambdaContext(logger)); + // The event should be logged because POWERTOOLS_LOGGER_LOG_EVENT is set to true + .use(injectLambdaContext(logger)); diff --git a/packages/logger/tests/e2e/logEventEnvVarSetting.middy.test.ts b/packages/logger/tests/e2e/logEventEnvVarSetting.middy.test.ts index 147d838c95..fc49c31a8c 100644 --- a/packages/logger/tests/e2e/logEventEnvVarSetting.middy.test.ts +++ b/packages/logger/tests/e2e/logEventEnvVarSetting.middy.test.ts @@ -1,12 +1,8 @@ -// Copyright Amazon.com, Inc. or its affiliates. All Rights Reserved. -// SPDX-License-Identifier: MIT-0 - /** * Test logger basic features * * @group e2e/logger/logEventEnvVarSetting */ - import path from 'path'; import { App, Stack } from 'aws-cdk-lib'; import { v4 } from 'uuid'; @@ -37,6 +33,8 @@ const stackName = generateUniqueName(RESOURCE_NAME_PREFIX, uuid, runtime, 'LogEv const functionName = generateUniqueName(RESOURCE_NAME_PREFIX, uuid, runtime, 'LogEventEnvVarSetting-Middy'); const lambdaFunctionCodeFile = 'logEventEnvVarSetting.middy.test.FunctionCode.ts'; +const invocationCount = 3; + const integTestApp = new App(); let logGroupName: string; // We do not know it until deployment let stack: Stack; @@ -67,8 +65,8 @@ describe(`logger E2E tests log event via env var setting (middy) for runtime: ${ const result = await deployStack(integTestApp, stack); logGroupName = result.outputs[STACK_OUTPUT_LOG_GROUP]; - // Invoke the function twice (one for cold start, another for warm start) - invocationLogs = await invokeFunction(functionName, 2, 'SEQUENTIAL'); + // Invoke the function three time (one for cold start, then two for warm start) + invocationLogs = await invokeFunction(functionName, invocationCount, 'SEQUENTIAL'); console.log('logGroupName', logGroupName); @@ -76,28 +74,27 @@ describe(`logger E2E tests log event via env var setting (middy) for runtime: ${ describe('Log event', () => { - it('should log the event at both invocations', async () => { - const firstInvocationMessages = invocationLogs[0].getAllFunctionLogs(); - let eventLoggedInFirstInvocation = false; - for (const message of firstInvocationMessages) { - if (message.includes(`event`)) { - eventLoggedInFirstInvocation = true; - expect(message).toContain(`"event":{"invocation":0}`); + it('should log the event as the first log of each invocation only', async () => { + + for (let i = 0; i < invocationCount; i++) { + // Get log messages of the invocation + const logMessages = invocationLogs[i].getFunctionLogs(); + + for (const [ index, message ] of logMessages.entries()) { + const log = InvocationLogs.parseFunctionLog(message); + // Check that the event is logged on the first log + if (index === 0) { + expect(log).toHaveProperty('event'); + expect(log.event).toStrictEqual( + expect.objectContaining({ invocation: i }) + ); + // Check that the event is not logged again on the rest of the logs + } else { + expect(log).not.toHaveProperty('event'); + } } } - const secondInvocationMessages = invocationLogs[1].getAllFunctionLogs(); - let eventLoggedInSecondInvocation = false; - for (const message of secondInvocationMessages) { - if (message.includes(`event`)) { - eventLoggedInSecondInvocation = true; - expect(message).toContain(`"event":{"invocation":1}`); - } - } - - expect(eventLoggedInFirstInvocation).toBe(true); - expect(eventLoggedInSecondInvocation).toBe(true); - }, TEST_CASE_TIMEOUT); }); diff --git a/packages/logger/tests/e2e/sampleRate.decorator.test.FunctionCode.ts b/packages/logger/tests/e2e/sampleRate.decorator.test.FunctionCode.ts index 72c13f07b4..ba4b7f8895 100644 --- a/packages/logger/tests/e2e/sampleRate.decorator.test.FunctionCode.ts +++ b/packages/logger/tests/e2e/sampleRate.decorator.test.FunctionCode.ts @@ -1,5 +1,6 @@ import { Logger } from '../../src'; -import { APIGatewayProxyEvent, Context } from 'aws-lambda'; +import { TestEvent, TestOutput } from '../helpers/types'; +import { Context } from 'aws-lambda'; import { LambdaInterface } from '@aws-lambda-powertools/commons'; const SAMPLE_RATE = parseFloat(process.env.SAMPLE_RATE || '0.1'); @@ -20,7 +21,7 @@ class Lambda implements LambdaInterface { @logger.injectLambdaContext() // eslint-disable-next-line @typescript-eslint/ban-ts-comment // @ts-ignore - public async handler(event: APIGatewayProxyEvent, context: Context): Promise<{requestId: string}> { + public async handler(event: TestEvent, context: Context): TestOutput { this.printLogInAllLevels(); return { diff --git a/packages/logger/tests/e2e/sampleRate.decorator.test.ts b/packages/logger/tests/e2e/sampleRate.decorator.test.ts index f803deae79..1955b20f46 100644 --- a/packages/logger/tests/e2e/sampleRate.decorator.test.ts +++ b/packages/logger/tests/e2e/sampleRate.decorator.test.ts @@ -1,12 +1,8 @@ -// Copyright Amazon.com, Inc. or its affiliates. All Rights Reserved. -// SPDX-License-Identifier: MIT-0 - /** * Test logger sample rate feature * * @group e2e/logger/sampleRate */ - import path from 'path'; import { App, Stack } from 'aws-cdk-lib'; import { v4 } from 'uuid'; @@ -39,16 +35,18 @@ const stackName = generateUniqueName(RESOURCE_NAME_PREFIX, uuid, runtime, 'Sampl const functionName = generateUniqueName(RESOURCE_NAME_PREFIX, uuid, runtime, 'SampleRate-Decorator'); const lambdaFunctionCodeFile = 'sampleRate.decorator.test.FunctionCode.ts'; +const invocationCount = 20; + // Parameters to be used by Logger in the Lambda function const LOG_MSG = `Log message ${uuid}`; const SAMPLE_RATE = '0.5'; -const LOG_LEVEL = LEVEL.ERROR.toString(); +const LOG_LEVEL = LEVEL.ERROR; const integTestApp = new App(); let stack: Stack; let logGroupName: string; // We do not know the exact name until deployment -describe(`logger E2E tests sample rate and injectLambdaContext() for runtime: ${runtime}`, () => { +describe(`logger E2E tests sample rate and injectLambdaContext() for runtime: nodejs18x`, () => { let invocationLogs: InvocationLogs[]; @@ -75,7 +73,7 @@ describe(`logger E2E tests sample rate and injectLambdaContext() for runtime: ${ const result = await deployStack(integTestApp, stack); logGroupName = result.outputs[STACK_OUTPUT_LOG_GROUP]; - invocationLogs = await invokeFunction(functionName, 20); + invocationLogs = await invokeFunction(functionName, invocationCount); console.log('logGroupName', logGroupName); @@ -86,23 +84,23 @@ describe(`logger E2E tests sample rate and injectLambdaContext() for runtime: ${ // Fetch log streams from all invocations let countSampled = 0; let countNotSampled = 0; - for (const invocationLog of invocationLogs) { - const logs = invocationLog.getFunctionLogs(); - if (logs.length === 1 && logs[0].includes(LEVEL.ERROR.toString())) { + + for (let i = 0; i < invocationCount; i++) { + // Get log messages of the invocation + const logMessages = invocationLogs[i].getFunctionLogs(); + + if (logMessages.length === 1 && logMessages[0].includes(LEVEL.ERROR)) { countNotSampled++; - } else if (logs.length === 4) { + } else if (logMessages.length === 4) { countSampled++; } else { - // TODO: To be investigate if this is Lambda service's issue. This happens once every 10-20 e2e tests runs. The symptoms I found are: - // 1. Warning and error logs disappear (in sampled case) - // 2. Error log disappears (in non-sampled case) - // I reviewed Logger code but it is not possible that the first case could happen because we use the same "logsSampled" flag. console.error(`Log group ${logGroupName} contains missing log`); throw new Error('Sampled log should have either 1 error log or 4 logs of all levels'); } } - // 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 + // 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); @@ -110,15 +108,21 @@ describe(`logger E2E tests sample rate and injectLambdaContext() for runtime: ${ }); describe('Decorator injectLambdaContext()', () => { - it('should inject Lambda context into the log', async () => { - const logMessages = invocationLogs[0].getFunctionLogs(LEVEL.ERROR); - - for (const log of logMessages) { - expect(log).toContain('function_arn'); - expect(log).toContain('function_memory_size'); - expect(log).toContain('function_name'); - expect(log).toContain('function_request_id'); - expect(log).toContain('timestamp'); + it('should inject Lambda context into every log emitted', async () => { + + for (let i = 0; i < invocationCount; i++) { + // Get log messages of the invocation + const logMessages = invocationLogs[i].getFunctionLogs(LEVEL.ERROR); + + // Check that the context is logged on every log + for (const message of logMessages) { + const log = InvocationLogs.parseFunctionLog(message); + expect(log).toHaveProperty('function_arn'); + expect(log).toHaveProperty('function_memory_size'); + expect(log).toHaveProperty('function_name'); + expect(log).toHaveProperty('function_request_id'); + expect(log).toHaveProperty('timestamp'); + } } }, TEST_CASE_TIMEOUT); diff --git a/packages/logger/tests/helpers/types.ts b/packages/logger/tests/helpers/types.ts new file mode 100644 index 0000000000..8c7b5dcbdf --- /dev/null +++ b/packages/logger/tests/helpers/types.ts @@ -0,0 +1,5 @@ +export type TestEvent = { + invocation: number +}; + +export type TestOutput = Promise<{requestId: string}>; \ No newline at end of file