test(common,logger,metrics): run e2e tests for metrics in both Node runtimes

packages/commons/jest.config.js

@@ -19,6 +19,12 @@ module.exports = {
   'testEnvironment': 'node',
   'coveragePathIgnorePatterns': [
     '/node_modules/',
+    /** 
+    * e2eUtils.ts contains helper methods that simplify several calls to CDK and SDK interface.
+    * Unit testing it is mostly mocking the CDK/SDK functions. It will be brittle and yield little value.
+    * In addition, the file is used for every E2E test run, so its correctness is verified for every PR. 
+    */
+    '/src/tests/e2e/e2eUtils.ts',
   ],
   'coverageThreshold': {
     'global': {

packages/commons/src/index.ts

@@ -1,4 +1,5 @@
 export * from './utils/lambda';
 export * from './Utility';
+export * from './tests/e2e';
 export * as ContextExamples from './tests/resources/contexts';
 export * as Events from './tests/resources/events';

packages/logger/tests/helpers/InvocationLogs.ts → packages/commons/src/tests/e2e/InvocationLogs.ts

@@ -41,28 +41,28 @@ export class InvocationLogs {
   }
 
   /**
-   * Find all functional logs whether it contains a given key
-   * @param key 
+   * Find all functional logs whether it contains a given text
+   * @param text 
    * @param log level to filter
    * @returns 
    */
-  public doesAnyFunctionLogsContains(key: string, levelToFilter?: LEVEL): boolean {
+  public doesAnyFunctionLogsContains(text: string, levelToFilter?: LEVEL): boolean {
     const filteredLogs = this.getFunctionLogs(levelToFilter)
-      .filter(log => log.includes(key));
+      .filter(log => log.includes(text));
 
     return filteredLogs.length > 0;
   }
 
   /**
-   * Return only logs from function, excude START, END, and REPORT generated by Lambda service
+   * Return only logs from function, exclude START, END, and REPORT generated by Lambda service
    * @param log 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.includes(levelToFilter.toString()));
+      filteredLogs = filteredLogs.filter(log => log.split('\t')[2] == levelToFilter);
     } 
 
     return filteredLogs;

packages/logger/tests/helpers/e2eUtils.ts → packages/commons/src/tests/e2e/e2eUtils.ts

@@ -1,19 +1,24 @@
+/* istanbul ignore file */
+
 // Copyright Amazon.com, Inc. or its affiliates. All Rights Reserved.
 // SPDX-License-Identifier: MIT-0
 
+/** 
+ * E2E utils is used by e2e tests. They are helper function that calls either CDK or SDK
+ * to interact with services. 
+*/
 import { CloudFormationStackArtifact } from '@aws-cdk/cx-api';
 import { SdkProvider } from 'aws-cdk/lib/api/aws-auth';
 import { CloudFormationDeployments } from 'aws-cdk/lib/api/cloudformation-deployments';
 import { App, CfnOutput, Stack } from '@aws-cdk/core';
 import * as lambda from '@aws-cdk/aws-lambda-nodejs';
-import { Runtime } from '@aws-cdk/aws-lambda';
+import { Runtime, Tracing } from '@aws-cdk/aws-lambda';
 import * as AWS from 'aws-sdk';
 
 import { InvocationLogs } from './InvocationLogs';
 
 const lambdaClient = new AWS.Lambda();
 
-const NAME_PREFIX = 'Logger-E2E';
 const testRuntimeKeys = [ 'nodejs12x', 'nodejs14x' ];
 export type TestRuntimesKey = typeof testRuntimeKeys[number];
 const TEST_RUNTIMES: Record<TestRuntimesKey, Runtime> = {
@@ -26,8 +31,9 @@ export type StackWithLambdaFunctionOptions = {
   stackName: string
   functionName: string
   functionEntry: string
+  tracing?: Tracing
   environment: {[key: string]: string}
-  logGroupOutputKey: string
+  logGroupOutputKey?: string
   runtime: string
 };
 
@@ -39,19 +45,22 @@ export const createStackWithLambdaFunction = (params: StackWithLambdaFunctionOpt
   const testFunction = new lambda.NodejsFunction(stack, `testFunction`, {
     functionName: params.functionName,
     entry: params.functionEntry,
+    tracing: params.tracing,
     environment: params.environment,
     runtime: TEST_RUNTIMES[params.runtime as TestRuntimesKey],
   });
 
-  new CfnOutput(stack, params.logGroupOutputKey, {
-    value: testFunction.logGroup.logGroupName,
-  });
+  if (params.logGroupOutputKey) {
+    new CfnOutput(stack, params.logGroupOutputKey, {
+      value: testFunction.logGroup.logGroupName,
+    });
+  }
 
   return stack;
 };
 
-export const generateUniqueName = (uuid: string, runtime: string, testName: string): string => 
-  `${NAME_PREFIX}-${runtime}-${testName}-${uuid}`.substring(0, 64);
+export const generateUniqueName = (name_prefix: string, uuid: string, runtime: string, testName: string): string => 
+  `${name_prefix}-${runtime}-${testName}-${uuid}`.substring(0, 64);
 
 export const deployStack = async (stackArtifact: CloudFormationStackArtifact ): Promise<{[name:string]: string}> => {
   const sdkProvider = await SdkProvider.withAwsCliCompatibleDefaults({

packages/commons/src/tests/e2e/index.ts

@@ -0,0 +1,2 @@
+export * from './e2eUtils';
+export * from './InvocationLogs';

packages/commons/tests/unit/InvocationLogs.test.ts

@@ -0,0 +1,138 @@
+/**
+ * Test InvocationLogs class
+ * 
+ * @group unit/commons/invocationLogs
+ * 
+ */
+
+import { InvocationLogs, LEVEL } from '../../src';
+
+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)"}}
+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`;
+
+describe('Constructor', () => {
+  test('it should parse base64 text correctly', () => {
+    const invocationLogs = new InvocationLogs(Buffer.from(exampleLogs).toString('base64'));
+    expect(invocationLogs.getFunctionLogs(LEVEL.DEBUG).length).toBe(1);
+    expect(invocationLogs.getFunctionLogs(LEVEL.INFO).length).toBe(2);
+    expect(invocationLogs.getFunctionLogs(LEVEL.ERROR).length).toBe(1);
+  });
+
+});
+
+describe('doesAnyFunctionLogsContains()', () => {
+  let invocationLogs: InvocationLogs;
+
+  beforeEach(() => {
+    invocationLogs = new InvocationLogs(Buffer.from(exampleLogs).toString('base64'));
+  });
+  test('it should return true if the text appear in any logs', () => {
+    const phraseInMessage = 'This is';
+    expect(invocationLogs.doesAnyFunctionLogsContains(phraseInMessage)).toBe(true);
+
+  });
+  test('it should return false if the text does not appear in any logs', () => {
+    const phraseNotInMessage = 'A quick brown fox jumps over the lazy dog';
+    expect(invocationLogs.doesAnyFunctionLogsContains(phraseNotInMessage)).toBe(false);
+  });
+
+  test('it should return true for key in the log', () => {
+    const keyInLog = 'error';
+    expect(invocationLogs.doesAnyFunctionLogsContains(keyInLog)).toBe(true);
+  });
+
+  test('it should return true for a text in an error key', () => {
+    const textInError = '/var/task/index.js:2778';
+    expect(invocationLogs.doesAnyFunctionLogsContains(textInError)).toBe(true);
+  });
+  test('it should return false for the text that appears only on the ', () => {
+    const textInStartLine = 'Version: $LATEST';
+    const textInEndLine = 'END RequestId';
+    const textInReportLine = 'Billed Duration';
+    expect(invocationLogs.doesAnyFunctionLogsContains(textInStartLine)).toBe(false);
+    expect(invocationLogs.doesAnyFunctionLogsContains(textInEndLine)).toBe(false);
+    expect(invocationLogs.doesAnyFunctionLogsContains(textInReportLine)).toBe(false);
+  });
+
+  test('it should apply filter log based on the given level', () => {
+    const debugLogHasWordINFO = invocationLogs.doesAnyFunctionLogsContains('INFO', LEVEL.DEBUG);
+    expect(debugLogHasWordINFO).toBe(true);
+
+    const infoLogHasWordINFO = invocationLogs.doesAnyFunctionLogsContains('INFO', LEVEL.INFO);
+    expect(infoLogHasWordINFO).toBe(true);
+
+    const errorLogHasWordINFO = invocationLogs.doesAnyFunctionLogsContains('INFO', LEVEL.ERROR);
+    expect(errorLogHasWordINFO).toBe(false);
+
+  });
+});
+
+describe('getFunctionLogs()', () => {
+  let invocationLogs: InvocationLogs;
+
+  beforeEach(() => {
+    invocationLogs = new InvocationLogs(Buffer.from(exampleLogs).toString('base64'));
+  });
+
+  test('it should retrive logs of the given level only', () => {
+    const infoLogs = invocationLogs.getFunctionLogs(LEVEL.INFO);
+    expect(infoLogs.length).toBe(2);
+    expect(infoLogs[0].includes('INFO')).toBe(true);
+    expect(infoLogs[1].includes('INFO')).toBe(true);
+    expect(infoLogs[0].includes('ERROR')).toBe(false);
+    expect(infoLogs[1].includes('ERROR')).toBe(false);
+
+    const errorLogs = invocationLogs.getFunctionLogs(LEVEL.ERROR);
+    expect(errorLogs.length).toBe(1);
+    expect(errorLogs[0].includes('INFO')).toBe(false);
+    expect(errorLogs[0].includes('ERROR')).toBe(true);
+  });
+
+  test('it should NOT return logs generated by Lambda service (e.g. START, END, and REPORT)', () => {
+    const errorLogs = invocationLogs.getFunctionLogs(LEVEL.ERROR);
+    expect(errorLogs.length).toBe(1);
+    expect(errorLogs[0].includes('START')).toBe(false);
+    expect(errorLogs[0].includes('END')).toBe(false);
+    expect(errorLogs[0].includes('REPORT')).toBe(false);
+  });
+});
+
+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 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({
+      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',
+    });
+  });
+
+  test('it should throw an error if receive incorrect formatted raw log string', () => {
+    const noTabString = 'no-tab-character';
+    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);
+    }).toThrow(Error);
+  });
+});

packages/logger/tests/e2e/basicFeatures.middy.test.ts

@@ -10,8 +10,22 @@
 import path from 'path';
 import { randomUUID } from 'crypto';
 import { App, Stack } from '@aws-cdk/core';
-import { createStackWithLambdaFunction, deployStack, destroyStack, generateUniqueName, invokeFunction, isValidRuntimeKey } from '../helpers/e2eUtils';
-import { InvocationLogs } from '../helpers/InvocationLogs';
+import { 
+  createStackWithLambdaFunction,
+  deployStack,
+  destroyStack,
+  generateUniqueName,
+  InvocationLogs,
+  invokeFunction,
+  isValidRuntimeKey
+} from '@aws-lambda-powertools/commons';
+import { 
+  RESOURCE_NAME_PREFIX,
+  STACK_OUTPUT_LOG_GROUP,
+  SETUP_TIMEOUT,
+  TEST_CASE_TIMEOUT,
+  TEARDOWN_TIMEOUT
+} from './constants';
 
 const runtime: string = process.env.RUNTIME || 'nodejs14x';
 
@@ -20,14 +34,10 @@ if (!isValidRuntimeKey(runtime)) {
 }
 
 const LEVEL = InvocationLogs.LEVEL;
-const TEST_CASE_TIMEOUT = 20000; // 20 seconds
-const SETUP_TIMEOUT = 300000; // 300 seconds
-const TEARDOWN_TIMEOUT = 200000; 
-const STACK_OUTPUT_LOG_GROUP = 'LogGroupName';
 
 const uuid = randomUUID();
-const stackName = generateUniqueName(uuid, runtime, 'BasicFeatures-Middy');
-const functionName = generateUniqueName(uuid, runtime, 'BasicFeatures-Middy');
+const stackName = generateUniqueName(RESOURCE_NAME_PREFIX, uuid, runtime, 'BasicFeatures-Middy');
+const functionName = generateUniqueName(RESOURCE_NAME_PREFIX, uuid, runtime, 'BasicFeatures-Middy');
 const lambdaFunctionCodeFile = 'basicFeatures.middy.test.FunctionCode.ts';
 
 // Text to be used by Logger in the Lambda function

packages/logger/tests/e2e/childLogger.manual.test.ts

@@ -10,8 +10,22 @@
 import path from 'path';
 import { randomUUID } from 'crypto';
 import { App, Stack } from '@aws-cdk/core';
-import { createStackWithLambdaFunction, deployStack, destroyStack, generateUniqueName, invokeFunction, isValidRuntimeKey } from '../helpers/e2eUtils';
-import { InvocationLogs } from '../helpers/InvocationLogs';
+import {
+  createStackWithLambdaFunction,
+  deployStack,
+  destroyStack,
+  generateUniqueName,
+  InvocationLogs,
+  invokeFunction,
+  isValidRuntimeKey,
+} from '@aws-lambda-powertools/commons';
+import {
+  RESOURCE_NAME_PREFIX,
+  STACK_OUTPUT_LOG_GROUP,
+  SETUP_TIMEOUT,
+  TEST_CASE_TIMEOUT,
+  TEARDOWN_TIMEOUT
+} from './constants';
 
 const runtime: string = process.env.RUNTIME || 'nodejs14x';
 
@@ -20,14 +34,10 @@ if (!isValidRuntimeKey(runtime)) {
 }
 
 const LEVEL = InvocationLogs.LEVEL;
-const TEST_CASE_TIMEOUT = 20000; // 20 seconds
-const SETUP_TIMEOUT = 300000; // 300 seconds
-const TEARDOWN_TIMEOUT = 200000; 
-const STACK_OUTPUT_LOG_GROUP = 'LogGroupName';
 
 const uuid = randomUUID();
-const stackName = generateUniqueName(uuid, runtime, 'ChildLogger-Manual');
-const functionName = generateUniqueName(uuid, runtime, 'ChildLogger-Manual');
+const stackName = generateUniqueName(RESOURCE_NAME_PREFIX, uuid, runtime, 'ChildLogger-Manual');
+const functionName = generateUniqueName(RESOURCE_NAME_PREFIX, uuid, runtime, 'ChildLogger-Manual');
 const lambdaFunctionCodeFile = 'childLogger.manual.test.FunctionCode.ts';
 
 // Parameters to be used by Logger in the Lambda function

packages/logger/tests/e2e/constants.ts

@@ -0,0 +1,5 @@
+export const RESOURCE_NAME_PREFIX = 'Logger-E2E';
+export const TEST_CASE_TIMEOUT = 20_000; // 20 seconds
+export const SETUP_TIMEOUT = 300_000; // 300 seconds
+export const TEARDOWN_TIMEOUT = 200_000; 
+export const STACK_OUTPUT_LOG_GROUP = 'LogGroupName';