Skip to content

Commit

Permalink
fix(logger): change logging to use stdout (#748)
Browse files Browse the repository at this point in the history 
* fix: moved to stdout, unit tests wip

* feat: adapted e2e tests - passing

* feat: wrote unit tests

* lint + cleanup

* chore: updated commons unit tests
  • Loading branch information
@dreamorosi
dreamorosi authored Apr 14, 2022
1 parent 95d7b6f commit 0781a47
Show file tree
Hide file tree
Showing 9 changed files with 147 additions and 143 deletions.
24 changes: 8 additions & 16 deletions packages/commons/tests/unit/InvocationLogs.test.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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`;

Expand Down Expand Up @@ -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,
Expand All @@ -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);
});
});
54 changes: 23 additions & 31 deletions packages/commons/tests/utils/InvocationLogs.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -8,32 +8,35 @@ 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;

/**
* 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',
* ]
* 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();
Expand All @@ -43,48 +46,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: <LEVEL> elements[2],
logObject: JSON.parse(elements[3]),
};
return JSON.parse(log);
}

}
5 changes: 4 additions & 1 deletion packages/logger/src/Logger.ts
View file
Original file line number Diff line number Diff line change
@@ -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';
Expand Down Expand Up @@ -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';
Expand Down Expand Up @@ -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()));
}

/**
Expand Down
16 changes: 8 additions & 8 deletions packages/logger/tests/e2e/basicFeatures.middy.test.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -10,15 +10,15 @@
import path from 'path';
import { randomUUID } from 'crypto';
import { App, Stack } from 'aws-cdk-lib';
import {
import {
createStackWithLambdaFunction,
generateUniqueName,
invokeFunction,
isValidRuntimeKey
} 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,
Expand Down Expand Up @@ -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,
Expand All @@ -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', () => {
Expand Down Expand Up @@ -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);
});
Expand All @@ -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');
Expand Down
16 changes: 8 additions & 8 deletions packages/logger/tests/e2e/childLogger.manual.test.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -10,22 +10,22 @@
import path from 'path';
import { randomUUID } from 'crypto';
import { App, Stack } from 'aws-cdk-lib';
import {
import {
createStackWithLambdaFunction,
generateUniqueName,
invokeFunction,
isValidRuntimeKey
} 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)) {
Expand Down Expand Up @@ -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,
Expand All @@ -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,
Expand All @@ -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()
Expand Down Expand Up @@ -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');
Expand Down
Loading

0 comments on commit 0781a47

Please sign in to comment.