Skip to content

fix(logger): POWERTOOLS_LOGGER_LOG_EVENT precedence is respected #1015

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

Merged
merged 5 commits into from
Jul 13, 2022
Merged

fix(logger): POWERTOOLS_LOGGER_LOG_EVENT precedence is respected #1015

Show file tree
Hide file tree
Changes from 2 commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
6c70a0b
fix: POWERTOOLS_LOGGER_LOG_EVENT precedence is respected
dreamorosi Jul 8, 2022
a034a60
fix: decorator logic
dreamorosi Jul 8, 2022
0dd4568
chore: added unit test cases for decorator
dreamorosi Jul 8, 2022
076660c
chore: added e2e test cases
dreamorosi Jul 11, 2022
00f5f73
chore: address review comments
dreamorosi Jul 11, 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
21 changes: 17 additions & 4 deletions packages/logger/src/Logger.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -292,9 +292,8 @@ class Logger extends Utility implements ClassThatLogs {
}

this.addContext(context);
if (options) {
this.logEventIfEnabled(event, options.logEvent);
}
const logEvent = options ? options.hasOwnProperty('logEvent') ? options.logEvent : undefined : undefined;
this.logEventIfEnabled(event, logEvent);

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

/**
* If the log event feature is enabled via env variable, it sets a property that tracks whether
* the event passed to the Lambda function handler should be logged or not.
*
* @private
* @returns {void}
*/
private setLogEvent(): void {
if (this.getEnvVarsService().getLogEvent()) {
this.logEvent = true;
}
}

/**
* It sets the log formatter instance, in charge of giving a custom format
* to the structured logs
Expand Down Expand Up @@ -716,7 +728,8 @@ class Logger extends Utility implements ClassThatLogs {
this.setLogsSampled();
this.setLogFormatter(logFormatter);
this.setPowertoolLogData(serviceName, environment);

this.setLogEvent();

this.addPersistentLogAttributes(persistentLogAttributes);

return this;
Expand Down
5 changes: 2 additions & 3 deletions packages/logger/src/middleware/middy.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -38,9 +38,8 @@ const injectLambdaContext = (target: Logger | Logger[], options?: HandlerOptions
if (options && options.clearState === true) {
persistentAttributes.push({ ...logger.getPersistentLogAttributes() });
}
if (options) {
logger.logEventIfEnabled(request.event, options.logEvent);
}
const logEvent = options ? options.hasOwnProperty('logEvent') ? options.logEvent : undefined : undefined;
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@flochaz: I haven't purposefully used that notation because we must support Node.js 12.x and that would break it, see this other PR from @ijemmy where he had to remove them all to make the build pass: #925

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is Node 12 support actually needed? Active support for it ended over a year and a half ago and even extended security support for it ended 2 months ago. It's now officially past EOL.

That said, I don't have insight into how many Node12 Lambdas are still running, so maybe supporting existing functions makes it worthwhile.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hello @bilalq, yes.

For the time being we are committed to support Node.js 12.x since AWS Lambda still supports that runtime.

So far, and aside from these minor changes in some lines, it hasn't been a blocker for us, so we still see value in allowing those customers who might have not migrated to newer and actively maintained runtimes to use the Powertools utilities.

logger.logEventIfEnabled(request.event, logEvent);
});
};

Expand Down
153 changes: 122 additions & 31 deletions packages/logger/tests/unit/middleware/middy.test.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -153,6 +153,64 @@ describe('Middy middleware', () => {
});

});

});

describe('Feature: clear state', () => {

test('when enabled, the persistent log attributes added in the handler are removed after the handler\'s code is executed', async () => {

// Prepare
const logger = new Logger({
logLevel: 'DEBUG',
persistentLogAttributes: {
foo: 'bar',
biz: 'baz'
}
});
const context = {
callbackWaitsForEmptyEventLoop: true,
functionVersion: '$LATEST',
functionName: 'foo-bar-function',
memoryLimitInMB: '128',
logGroupName: '/aws/lambda/foo-bar-function',
logStreamName: '2021/03/09/[$LATEST]abcdef123456abcdef123456abcdef123456',
invokedFunctionArn: 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function',
awsRequestId: 'abcdef123456abcdef123456',
getRemainingTimeInMillis: () => 1234,
done: () => console.log('Done!'),
fail: () => console.log('Failed!'),
succeed: () => console.log('Succeeded!'),
};

const lambdaHandler = (event: { user_id: string }): void => {
// Only add these persistent for the scope of this lambda handler
logger.appendKeys({
details: { user_id: event['user_id'] }
});
logger.debug('This is a DEBUG log with the user_id');
logger.debug('This is another DEBUG log with the user_id');
};
const handler = middy(lambdaHandler).use(injectLambdaContext(logger, { clearState: true }));
const persistentAttribs = { ...logger.getPersistentLogAttributes() };

// Act
await handler({ user_id: '123456' }, context, () => console.log('Lambda invoked!'));
const persistentAttribsAfterInvocation = { ...logger.getPersistentLogAttributes() };

// Assess
expect(persistentAttribs).toEqual({
foo: 'bar',
biz: 'baz'
});
expect(persistentAttribsAfterInvocation).toEqual(persistentAttribs);

});

});

describe('Feature: log event', () => {

test('when a logger is passed with option logEvent set to true, it logs the event', async () => {

// Prepare
Expand Down Expand Up @@ -203,7 +261,7 @@ describe('Middy middleware', () => {

});

test('when a logger is passed with option logEvent set to true, it logs the event', async () => {
test('when a logger is passed with option logEvent set to true, while also having a custom configService, it logs the event', async () => {

// Prepare
const configService: ConfigServiceInterface = {
Expand All @@ -227,7 +285,6 @@ describe('Middy middleware', () => {
},

};
// Prepare

const logger = new Logger({
customConfigService: configService,
Expand Down Expand Up @@ -278,20 +335,19 @@ describe('Middy middleware', () => {

});

});

describe('Feature: clear state', () => {

test('when enabled, the persistent log attributes added in the handler are removed after the handler\'s code is executed', async () => {
test('when a logger is passed without options, but POWERTOOLS_LOGGER_LOG_EVENT env var is set to true, it logs the event', async () => {

// Prepare
const logger = new Logger({
logLevel: 'DEBUG',
persistentLogAttributes: {
foo: 'bar',
biz: 'baz'
}
});
process.env.POWERTOOLS_LOGGER_LOG_EVENT = 'true';
const logger = new Logger();
const consoleSpy = jest.spyOn(logger['console'], 'info').mockImplementation();
const lambdaHandler = (): void => {
logger.info('This is an INFO log with some context');
};
const handler = middy(lambdaHandler).use(injectLambdaContext(logger));
const event = { foo: 'bar' };
const getRandomInt = (): number => Math.floor(Math.random() * 1000000000);
const awsRequestId = getRandomInt().toString();
const context = {
callbackWaitsForEmptyEventLoop: true,
functionVersion: '$LATEST',
Expand All @@ -300,34 +356,69 @@ describe('Middy middleware', () => {
logGroupName: '/aws/lambda/foo-bar-function',
logStreamName: '2021/03/09/[$LATEST]abcdef123456abcdef123456abcdef123456',
invokedFunctionArn: 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function',
awsRequestId: 'abcdef123456abcdef123456',
awsRequestId: awsRequestId,
getRemainingTimeInMillis: () => 1234,
done: () => console.log('Done!'),
fail: () => console.log('Failed!'),
succeed: () => console.log('Succeeded!'),
};

const lambdaHandler = (event: { user_id: string }): void => {
// Only add these persistent for the scope of this lambda handler
logger.appendKeys({
details: { user_id: event['user_id'] }
});
logger.debug('This is a DEBUG log with the user_id');
logger.debug('This is another DEBUG log with the user_id');
// Act
await handler(event, context, () => console.log('Lambda invoked!'));

// Assess
expect(consoleSpy).toBeCalledTimes(2);
expect(consoleSpy).toHaveBeenNthCalledWith(1, JSON.stringify({
cold_start: true,
function_arn: 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function',
function_memory_size: 128,
function_name: 'foo-bar-function',
function_request_id: awsRequestId,
level: 'INFO',
message: 'Lambda invocation event',
service: 'hello-world',
timestamp: '2016-06-20T12:08:10.000Z',
xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793',
event: {
foo: 'bar'
}
}));

});

test('when a logger is passed with option logEvent set to false, but POWERTOOLS_LOGGER_LOG_EVENT env var is set to true, it does not log the event', async () => {

// Prepare
process.env.POWERTOOLS_LOGGER_LOG_EVENT = 'true';
const logger = new Logger();
const consoleSpy = jest.spyOn(logger['console'], 'info').mockImplementation();
const lambdaHandler = (): void => {
logger.info('This is an INFO log with some context');
};
const handler = middy(lambdaHandler).use(injectLambdaContext(logger, { logEvent: false }));
const event = { foo: 'bar' };
const getRandomInt = (): number => Math.floor(Math.random() * 1000000000);
const awsRequestId = getRandomInt().toString();
const context = {
callbackWaitsForEmptyEventLoop: true,
functionVersion: '$LATEST',
functionName: 'foo-bar-function',
memoryLimitInMB: '128',
logGroupName: '/aws/lambda/foo-bar-function',
logStreamName: '2021/03/09/[$LATEST]abcdef123456abcdef123456abcdef123456',
invokedFunctionArn: 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function',
awsRequestId: awsRequestId,
getRemainingTimeInMillis: () => 1234,
done: () => console.log('Done!'),
fail: () => console.log('Failed!'),
succeed: () => console.log('Succeeded!'),
};
const handler = middy(lambdaHandler).use(injectLambdaContext(logger, { clearState: true }));
const persistentAttribs = { ...logger.getPersistentLogAttributes() };

// Act
await handler({ user_id: '123456' }, context, () => console.log('Lambda invoked!'));
const persistentAttribsAfterInvocation = { ...logger.getPersistentLogAttributes() };
await handler(event, context, () => console.log('Lambda invoked!'));

// Assess
expect(persistentAttribs).toEqual({
foo: 'bar',
biz: 'baz'
});
expect(persistentAttribsAfterInvocation).toEqual(persistentAttribs);
expect(consoleSpy).toBeCalledTimes(1);

});

Expand Down