fix(logger): POWERTOOLS_LOGGER_LOG_EVENT precedence is respected #1015

dreamorosi · 2022-07-08T07:10:32Z

Description of your changes

This PR aims at fixing a bug that was identified by @saragerion in the logger. In v0.11.0 we released a feature that allows to log the event parameter of a function handler. This is an opt-in feature that can be enabled by users by either passing a logEvent parameter equal to true in the middleware/decorator or by setting a POWERTOOLS_LOGGER_LOG_EVENT environment variable also equal to true. In the current iteration of the utility only the first method works.

I was able to reproduce the issue in my own tests.

There were two separate issues that contributed to this bug:

When deciding on whether to log the event or not a function named logEventIfEnabled is called. This function takes in account - and gives precedence to - the parameter passed in the middleware/decorator but also checks the value of the logEvent property that is part of the current Logger class. This property is set to false by default (as documented). That same property should be set to true upon class instantiation and as a part of the setOptions lifecycle if the POWERTOOLS_LOGGER_LOG_EVENT env var is present & with a truthy value, but this never happened.

The second issue, perhaps minor or intended (would appreciate feedback if that was the case) was that both middleware and decorator called the logEventIfEnabled function mentioned above only when an options parameter is passed to the middleware/decorator. For example:

Even fixing the logic as described previously, the code below still doesn't work because since the injectLambdaContext doesn't have a second parameter (options), the Logger class never checks if the log event feature was enabled via env var:

process.env.POWERTOOLS_LOGGER_LOG_EVENT = 'true';

export const handler = middy(lambdaHandler)
    .use(injectLambdaContext(logger));

To make it work, developers would have had to pass an empty object (or an object with other configs like clearState):

process.env.POWERTOOLS_LOGGER_LOG_EVENT = 'true';

export const handler = middy(lambdaHandler)
    .use(injectLambdaContext(logger, { }));

// OR
export const handler = middy(lambdaHandler)
    .use(injectLambdaContext(logger, { clearState: true }));

The same applies to the decorator usage.

Since we cannot rely on the presence of other configs (i.e. clearState) we shouldn't force devs to pass an empty object for the env var config to be evaluated.

How to verify this change

See additional unit test cases that were added.

Related issues, RFCs

N/A

PR status

Is this ready for review?: YES
Is it a breaking change?: NO

Checklist

My changes meet the tenets criteria
I have performed a self-review of my own code
I have commented my code where necessary, particularly in areas that should be flagged with a TODO, or hard-to-understand areas
My changes generate no new warnings
The code coverage hasn't decreased
I have added tests that prove my change is effective and works
New and existing unit tests pass locally and in Github Actions
The PR title follows the conventional commit semantics

Breaking change checklist

N/A

By submitting this pull request, I confirm that you can use, modify, copy, and redistribute this contribution, under the terms of your choice.

flochaz

lgtm, minor suggestion , can be ignored

dreamorosi · 2022-07-08T07:36:27Z

packages/logger/src/middleware/middy.ts

-      if (options) {
-        logger.logEventIfEnabled(request.event, options.logEvent);
-      }
+      const logEvent = options ? options.hasOwnProperty('logEvent') ? options.logEvent : undefined : undefined;


@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

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.

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.

github-actions · 2022-07-08T07:29:06Z

📊 Package size report `0.4%↑`

File	Before	After
`aws-lambda-powertools-logger-0.11.1-rc.0.tgz`	`23.8 kB`	^1%↑`24.1 kB`
`logger-bundle.zip`	`24.3 kB`	^0.9%↑`24.5 kB`
Total _{(Includes all files)}	`140.7 kB`	^0.4%↑`141.2 kB`
Tarball size	`139.5 kB`	^0.3%↑`140.0 kB`

Unchanged files

File	Size
`aws-lambda-powertools-commons-0.11.1-rc.0.tgz`	`6.5 kB`
`aws-lambda-powertools-metrics-0.11.1-rc.0.tgz`	`17.5 kB`
`aws-lambda-powertools-tracer-0.11.1-rc.0.tgz`	`21.5 kB`
`commons-bundle.zip`	`7.1 kB`
`metrics-bundle.zip`	`18.1 kB`
`tracer-bundle.zip`	`22.0 kB`

_{🤖 This report was automatically generated by pkg-size-action}
(options hash: 2baf741796e2d268b42eab0a33e346b6)

dreamorosi · 2022-07-08T07:36:27Z

packages/logger/src/middleware/middy.ts

-      if (options) {
-        logger.logEventIfEnabled(request.event, options.logEvent);
-      }
+      const logEvent = options ? options.hasOwnProperty('logEvent') ? options.logEvent : undefined : undefined;


@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

dreamorosi · 2022-07-11T08:33:29Z

@saragerion: a comment on the e2e test I added like you asked.

Before this PR we had 3 stacks for e2e tests & Logger:

middy (many features being tested, including the logEvent via middleware config)
manual (child logger)
decorator (sample rate).

Each stack defines one single Lambda function with some env vars and some params in the constructor / middleware.

In order to test this case the function would need the following configs:

LOG_LEVEL=INFO or more verbose
logEvent param not present in the middleware/decorator
POWERTOOLS_LOGGER_LOG_EVENT env var set on the function

I have considered adding this test case to the middleware one but this is not possible because the function passes the logEvent=true param in the middleware.

Likewise I have also considered adding it to the decorator one but this is also not compatible as that function/stack sets log level equal to ERROR to test sampling and the log event feature logs using INFO, so the log would never appear.

In order to add this I had to add a new and dedicated stack + function.

Considering that the feature in itself is already being tested in the e2e (via middleware param) and that this PR introduces unit test cases that specifically target this behaviour (env variable but not middleware/decorator param), are we okay with having a new stack / function that makes the e2e tests longer?

This is not a big issue but I wanted to point this out & document it as it kind of breaks the neat organization of the test cases we had in the logger.

github-actions · 2022-07-11T08:37:08Z

📊 Package size report `0.4%↑`

File	Before	After
`aws-lambda-powertools-logger-0.11.1-rc.0.tgz`	`23.8 kB`	^1%↑`24.1 kB`
`logger-bundle.zip`	`24.3 kB`	^0.9%↑`24.5 kB`
Total _{(Includes all files)}	`141.0 kB`	^0.4%↑`141.5 kB`
Tarball size	`139.8 kB`	^0.3%↑`140.3 kB`

Unchanged files

File	Size
`aws-lambda-powertools-commons-0.11.1-rc.0.tgz`	`6.5 kB`
`aws-lambda-powertools-metrics-0.11.1-rc.0.tgz`	`17.5 kB`
`aws-lambda-powertools-tracer-0.11.1-rc.0.tgz`	`21.5 kB`
`commons-bundle.zip`	`7.1 kB`
`metrics-bundle.zip`	`18.1 kB`
`tracer-bundle.zip`	`22.1 kB`

_{🤖 This report was automatically generated by pkg-size-action}
(options hash: c072cc3ae0dffc1c5b055f78e99260a2)

dreamorosi · 2022-07-11T08:52:08Z

e2e test passing:

https://github.com/awslabs/aws-lambda-powertools-typescript/runs/7278953119?check_suite_focus=true

packages/logger/src/Logger.ts

ijemmy · 2022-07-11T12:07:23Z

packages/logger/tests/e2e/logEventEnvVarSetting.middy.test.FunctionCode.ts

@@ -0,0 +1,16 @@
+import { injectLambdaContext, Logger } from '../../src';


(nit) missing Copyright header?

None of the functions in that group of e2e tests has the copyright header, should I add it?

packages/logger/src/middleware/middy.ts

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

packages/logger/tests/unit/middleware/middy.test.ts

approved by mistake

github-actions · 2022-07-11T14:55:53Z

📊 Package size report `0.4%↑`

File	Before	After
`aws-lambda-powertools-logger-0.11.1-rc.0.tgz`	`23.8 kB`	^1%↑`24.1 kB`
`logger-bundle.zip`	`24.3 kB`	^1%↑`24.6 kB`
Total _{(Includes all files)}	`141.0 kB`	^0.4%↑`141.6 kB`
Tarball size	`139.8 kB`	^0.4%↑`140.4 kB`

Unchanged files

File	Size
`aws-lambda-powertools-commons-0.11.1-rc.0.tgz`	`6.5 kB`
`aws-lambda-powertools-metrics-0.11.1-rc.0.tgz`	`17.5 kB`
`aws-lambda-powertools-tracer-0.11.1-rc.0.tgz`	`21.5 kB`
`commons-bundle.zip`	`7.1 kB`
`metrics-bundle.zip`	`18.1 kB`
`tracer-bundle.zip`	`22.1 kB`

_{🤖 This report was automatically generated by pkg-size-action}
(options hash: cde58c3e67d279f4d39c5d7412331a5c)

* 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

dreamorosi added 2 commits July 8, 2022 08:45

fix: POWERTOOLS_LOGGER_LOG_EVENT precedence is respected

6c70a0b

fix: decorator logic

a034a60

dreamorosi requested review from saragerion, flochaz and ijemmy July 8, 2022 07:10

dreamorosi self-assigned this Jul 8, 2022

github-actions bot added the bug Something isn't working label Jul 8, 2022

dreamorosi added logger This item relates to the Logger Utility fix labels Jul 8, 2022

dreamorosi added this to the production-ready-release milestone Jul 8, 2022

chore: added unit test cases for decorator

0dd4568

flochaz reviewed Jul 8, 2022

View reviewed changes

dreamorosi commented Jul 8, 2022

View reviewed changes

dreamorosi requested a review from flochaz July 8, 2022 07:37

flochaz previously approved these changes Jul 8, 2022

View reviewed changes

chore: added e2e test cases

076660c

dreamorosi dismissed flochaz’s stale review via 076660c July 11, 2022 08:29

dreamorosi requested a review from flochaz July 11, 2022 08:42

ijemmy previously approved these changes Jul 11, 2022

View reviewed changes

chore: address review comments

00f5f73

dreamorosi requested a review from ijemmy July 11, 2022 14:48

ijemmy approved these changes Jul 11, 2022

View reviewed changes

saragerion approved these changes Jul 13, 2022

View reviewed changes

dreamorosi merged commit 1cbb4db into main Jul 13, 2022

dreamorosi deleted the fix/log_event_env_var branch July 13, 2022 14:19

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

fix(logger): POWERTOOLS_LOGGER_LOG_EVENT precedence is respected #1015

fix(logger): POWERTOOLS_LOGGER_LOG_EVENT precedence is respected #1015

dreamorosi commented Jul 8, 2022

flochaz left a comment

dreamorosi Jul 8, 2022

bilalq Jul 9, 2022

dreamorosi Jul 9, 2022

github-actions bot commented Jul 8, 2022 •

edited

Loading

dreamorosi Jul 8, 2022

dreamorosi commented Jul 11, 2022

github-actions bot commented Jul 11, 2022 •

edited

Loading

dreamorosi commented Jul 11, 2022

ijemmy Jul 11, 2022

dreamorosi Jul 11, 2022

github-actions bot commented Jul 11, 2022 •

edited

Loading

		@@ -0,0 +1,16 @@
		import { injectLambdaContext, Logger } from '../../src';

fix(logger): POWERTOOLS_LOGGER_LOG_EVENT precedence is respected #1015

fix(logger): POWERTOOLS_LOGGER_LOG_EVENT precedence is respected #1015

Conversation

dreamorosi commented Jul 8, 2022

Description of your changes

How to verify this change

Related issues, RFCs

PR status

Checklist

Breaking change checklist

flochaz left a comment

Choose a reason for hiding this comment

dreamorosi Jul 8, 2022

Choose a reason for hiding this comment

bilalq Jul 9, 2022

Choose a reason for hiding this comment

dreamorosi Jul 9, 2022

Choose a reason for hiding this comment

github-actions bot commented Jul 8, 2022 • edited Loading

📊 Package size report 0.4%↑

dreamorosi Jul 8, 2022

Choose a reason for hiding this comment

dreamorosi commented Jul 11, 2022

github-actions bot commented Jul 11, 2022 • edited Loading

📊 Package size report 0.4%↑

dreamorosi commented Jul 11, 2022

ijemmy Jul 11, 2022

Choose a reason for hiding this comment

dreamorosi Jul 11, 2022

Choose a reason for hiding this comment

github-actions bot commented Jul 11, 2022 • edited Loading

📊 Package size report 0.4%↑

github-actions bot commented Jul 8, 2022 •

edited

Loading

📊 Package size report `0.4%↑`

github-actions bot commented Jul 11, 2022 •

edited

Loading

📊 Package size report `0.4%↑`

github-actions bot commented Jul 11, 2022 •

edited

Loading

📊 Package size report `0.4%↑`