Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

fix(logger): change logging to use stdout #748

Merged
merged 5 commits into from
Apr 14, 2022
Merged

fix(logger): change logging to use stdout #748

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
ea2c672
fix: moved to stdout, unit tests wip
dreamorosi Apr 8, 2022
5e413ff
feat: adapted e2e tests - passing
dreamorosi Apr 13, 2022
aab56b4
feat: wrote unit tests
dreamorosi Apr 13, 2022
bcd964b
lint + cleanup
dreamorosi Apr 13, 2022
349b1d2
chore: updated commons unit tests
dreamorosi Apr 13, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
24 changes: 8 additions & 16 deletions packages/commons/tests/unit/InvocationLogs.test.ts
View file
Open in desktop
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
Open in desktop
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
Open in desktop
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
Open in desktop
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
Open in desktop
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