Skip to content

Commit 1cbb4db

Browse files
dreamorosidreamorosi
authored
fix(logger): POWERTOOLS_LOGGER_LOG_EVENT precedence is respected (#1015)
* fix: POWERTOOLS_LOGGER_LOG_EVENT precedence is respected * fix: decorator logic * chore: added unit test cases for decorator * chore: added e2e test cases * chore: address review comments
1 parent f4bc324 commit 1cbb4db

File tree

6 files changed

+371
-37
lines changed

6 files changed

+371
-37
lines changed

Diff for: ‎packages/logger/src/Logger.ts

+19-3
Original file line numberDiff line numberDiff line change
@@ -292,9 +292,11 @@ class Logger extends Utility implements ClassThatLogs {
292292
}
293293

294294
this.addContext(context);
295-
if (options) {
296-
this.logEventIfEnabled(event, options.logEvent);
295+
let shouldLogEvent = undefined;
296+
if ( options && options.hasOwnProperty('logEvent') ) {
297+
shouldLogEvent = options.logEvent;
297298
}
299+
this.logEventIfEnabled(event, shouldLogEvent);
298300

299301
/* eslint-disable @typescript-eslint/no-non-null-assertion */
300302
const result = originalMethod!.apply(target, [ event, context, callback ]);
@@ -636,6 +638,19 @@ class Logger extends Utility implements ClassThatLogs {
636638
this.envVarsService = new EnvironmentVariablesService();
637639
}
638640

641+
/**
642+
* If the log event feature is enabled via env variable, it sets a property that tracks whether
643+
* the event passed to the Lambda function handler should be logged or not.
644+
*
645+
* @private
646+
* @returns {void}
647+
*/
648+
private setLogEvent(): void {
649+
if (this.getEnvVarsService().getLogEvent()) {
650+
this.logEvent = true;
651+
}
652+
}
653+
639654
/**
640655
* It sets the log formatter instance, in charge of giving a custom format
641656
* to the structured logs
@@ -716,7 +731,8 @@ class Logger extends Utility implements ClassThatLogs {
716731
this.setLogsSampled();
717732
this.setLogFormatter(logFormatter);
718733
this.setPowertoolLogData(serviceName, environment);
719-
734+
this.setLogEvent();
735+
720736
this.addPersistentLogAttributes(persistentLogAttributes);
721737

722738
return this;

Diff for: ‎packages/logger/src/middleware/middy.ts

+5-2
Original file line numberDiff line numberDiff line change
@@ -38,9 +38,12 @@ const injectLambdaContext = (target: Logger | Logger[], options?: HandlerOptions
3838
if (options && options.clearState === true) {
3939
persistentAttributes.push({ ...logger.getPersistentLogAttributes() });
4040
}
41-
if (options) {
42-
logger.logEventIfEnabled(request.event, options.logEvent);
41+
42+
let shouldLogEvent = undefined;
43+
if ( options && options.hasOwnProperty('logEvent') ) {
44+
shouldLogEvent = options.logEvent;
4345
}
46+
logger.logEventIfEnabled(request.event, shouldLogEvent);
4447
});
4548
};
4649

Diff for: ‎packages/logger/tests/e2e/logEventEnvVarSetting.middy.test.FunctionCode.ts

+16
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,16 @@
1+
import { injectLambdaContext, Logger } from '../../src';
2+
import { Context } from 'aws-lambda';
3+
import middy from '@middy/core';
4+
5+
type LambdaEvent = {
6+
invocation: number
7+
};
8+
9+
const logger = new Logger();
10+
11+
const testFunction = async (event: LambdaEvent, context: Context): Promise<{requestId: string}> => ({
12+
requestId: context.awsRequestId,
13+
});
14+
15+
export const handler = middy(testFunction)
16+
.use(injectLambdaContext(logger));

Diff for: ‎packages/logger/tests/e2e/logEventEnvVarSetting.middy.test.ts

+110
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,110 @@
1+
// Copyright Amazon.com, Inc. or its affiliates. All Rights Reserved.
2+
// SPDX-License-Identifier: MIT-0
3+
4+
/**
5+
* Test logger basic features
6+
*
7+
* @group e2e/logger/logEventEnvVarSetting
8+
*/
9+
10+
import path from 'path';
11+
import { App, Stack } from 'aws-cdk-lib';
12+
import { v4 } from 'uuid';
13+
import {
14+
createStackWithLambdaFunction,
15+
generateUniqueName,
16+
invokeFunction,
17+
isValidRuntimeKey
18+
} from '../../../commons/tests/utils/e2eUtils';
19+
import { InvocationLogs } from '../../../commons/tests/utils/InvocationLogs';
20+
import { deployStack, destroyStack } from '../../../commons/tests/utils/cdk-cli';
21+
import {
22+
RESOURCE_NAME_PREFIX,
23+
STACK_OUTPUT_LOG_GROUP,
24+
SETUP_TIMEOUT,
25+
TEST_CASE_TIMEOUT,
26+
TEARDOWN_TIMEOUT
27+
} from './constants';
28+
29+
const runtime: string = process.env.RUNTIME || 'nodejs16x';
30+
31+
if (!isValidRuntimeKey(runtime)) {
32+
throw new Error(`Invalid runtime key value: ${runtime}`);
33+
}
34+
35+
const uuid = v4();
36+
const stackName = generateUniqueName(RESOURCE_NAME_PREFIX, uuid, runtime, 'LogEventEnvVarSetting-Middy');
37+
const functionName = generateUniqueName(RESOURCE_NAME_PREFIX, uuid, runtime, 'LogEventEnvVarSetting-Middy');
38+
const lambdaFunctionCodeFile = 'logEventEnvVarSetting.middy.test.FunctionCode.ts';
39+
40+
const integTestApp = new App();
41+
let logGroupName: string; // We do not know it until deployment
42+
let stack: Stack;
43+
44+
describe(`logger E2E tests log event via env var setting (middy) for runtime: ${runtime}`, () => {
45+
46+
let invocationLogs: InvocationLogs[];
47+
48+
beforeAll(async () => {
49+
// Create and deploy a stack with AWS CDK
50+
stack = createStackWithLambdaFunction({
51+
app: integTestApp,
52+
stackName: stackName,
53+
functionName: functionName,
54+
functionEntry: path.join(__dirname, lambdaFunctionCodeFile),
55+
environment: {
56+
LOG_LEVEL: 'INFO',
57+
POWERTOOLS_SERVICE_NAME: 'logger-e2e-testing',
58+
UUID: uuid,
59+
60+
// Enabling the logger to log events via env var
61+
POWERTOOLS_LOGGER_LOG_EVENT: 'true',
62+
},
63+
logGroupOutputKey: STACK_OUTPUT_LOG_GROUP,
64+
runtime: runtime,
65+
});
66+
67+
const result = await deployStack(integTestApp, stack);
68+
logGroupName = result.outputs[STACK_OUTPUT_LOG_GROUP];
69+
70+
// Invoke the function twice (one for cold start, another for warm start)
71+
invocationLogs = await invokeFunction(functionName, 2, 'SEQUENTIAL');
72+
73+
console.log('logGroupName', logGroupName);
74+
75+
}, SETUP_TIMEOUT);
76+
77+
describe('Log event', () => {
78+
79+
it('should log the event at both invocations', async () => {
80+
const firstInvocationMessages = invocationLogs[0].getAllFunctionLogs();
81+
let eventLoggedInFirstInvocation = false;
82+
for (const message of firstInvocationMessages) {
83+
if (message.includes(`event`)) {
84+
eventLoggedInFirstInvocation = true;
85+
expect(message).toContain(`"event":{"invocation":0}`);
86+
}
87+
}
88+
89+
const secondInvocationMessages = invocationLogs[1].getAllFunctionLogs();
90+
let eventLoggedInSecondInvocation = false;
91+
for (const message of secondInvocationMessages) {
92+
if (message.includes(`event`)) {
93+
eventLoggedInSecondInvocation = true;
94+
expect(message).toContain(`"event":{"invocation":1}`);
95+
}
96+
}
97+
98+
expect(eventLoggedInFirstInvocation).toBe(true);
99+
expect(eventLoggedInSecondInvocation).toBe(true);
100+
101+
}, TEST_CASE_TIMEOUT);
102+
103+
});
104+
105+
afterAll(async () => {
106+
if (!process.env.DISABLE_TEARDOWN) {
107+
await destroyStack(integTestApp, stack);
108+
}
109+
}, TEARDOWN_TIMEOUT);
110+
});

Diff for: ‎packages/logger/tests/unit/Logger.test.ts

+87
Original file line numberDiff line numberDiff line change
@@ -982,6 +982,93 @@ describe('Class: Logger', () => {
982982

983983
});
984984

985+
test('when used as decorator with the log event flag enabled, it logs the event', async () => {
986+
987+
// Prepare
988+
const logger = new Logger({
989+
logLevel: 'DEBUG',
990+
});
991+
const consoleSpy = jest.spyOn(logger['console'], 'info').mockImplementation();
992+
993+
type CustomEvent = { user_id: string };
994+
995+
class LambdaFunction implements LambdaInterface {
996+
997+
@logger.injectLambdaContext({ logEvent: true })
998+
// eslint-disable-next-line @typescript-eslint/ban-ts-comment
999+
// @ts-ignore
1000+
public handler<TResult>(_event: CustomEvent, _context: Context, _callback: Callback<TResult>): void | Promise<TResult> {
1001+
return;
1002+
}
1003+
}
1004+
1005+
// Act
1006+
await new LambdaFunction().handler({ user_id: '123456' }, dummyContext, () => console.log('Lambda invoked!'));
1007+
1008+
// Assess
1009+
expect(consoleSpy).toBeCalledTimes(1);
1010+
expect(consoleSpy).toHaveBeenNthCalledWith(1, JSON.stringify({
1011+
cold_start: true,
1012+
function_arn: 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function',
1013+
function_memory_size: 128,
1014+
function_name: 'foo-bar-function',
1015+
function_request_id: 'c6af9ac6-7b61-11e6-9a41-93e812345678',
1016+
level: 'INFO',
1017+
message: 'Lambda invocation event',
1018+
service: 'hello-world',
1019+
timestamp: '2016-06-20T12:08:10.000Z',
1020+
xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793',
1021+
event: {
1022+
user_id: '123456'
1023+
}
1024+
}));
1025+
1026+
});
1027+
1028+
test('when used as decorator without options, but POWERTOOLS_LOGGER_LOG_EVENT env var is set to true, it logs the event', async () => {
1029+
1030+
// Prepare
1031+
process.env.POWERTOOLS_LOGGER_LOG_EVENT = 'true';
1032+
const logger = new Logger({
1033+
logLevel: 'DEBUG',
1034+
});
1035+
const consoleSpy = jest.spyOn(logger['console'], 'info').mockImplementation();
1036+
1037+
type CustomEvent = { user_id: string };
1038+
1039+
class LambdaFunction implements LambdaInterface {
1040+
1041+
@logger.injectLambdaContext()
1042+
// eslint-disable-next-line @typescript-eslint/ban-ts-comment
1043+
// @ts-ignore
1044+
public handler<TResult>(_event: CustomEvent, _context: Context, _callback: Callback<TResult>): void | Promise<TResult> {
1045+
return;
1046+
}
1047+
}
1048+
1049+
// Act
1050+
await new LambdaFunction().handler({ user_id: '123456' }, dummyContext, () => console.log('Lambda invoked!'));
1051+
1052+
// Assess
1053+
expect(consoleSpy).toBeCalledTimes(1);
1054+
expect(consoleSpy).toHaveBeenNthCalledWith(1, JSON.stringify({
1055+
cold_start: true,
1056+
function_arn: 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function',
1057+
function_memory_size: 128,
1058+
function_name: 'foo-bar-function',
1059+
function_request_id: 'c6af9ac6-7b61-11e6-9a41-93e812345678',
1060+
level: 'INFO',
1061+
message: 'Lambda invocation event',
1062+
service: 'hello-world',
1063+
timestamp: '2016-06-20T12:08:10.000Z',
1064+
xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793',
1065+
event: {
1066+
user_id: '123456'
1067+
}
1068+
}));
1069+
1070+
});
1071+
9851072
});
9861073

9871074
describe('Method: refreshSampleRateCalculation', () => {

0 commit comments

Comments
 (0)