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.

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

Bug: Exception instead of warning when log level doesn't match AWS log level #2269

Closed
deffer opened this issue Mar 25, 2024 · 5 comments · Fixed by #2277
Closed

Bug: Exception instead of warning when log level doesn't match AWS log level #2269

deffer opened this issue Mar 25, 2024 · 5 comments · Fixed by #2277
Assignees
Labels
bug Something isn't working completed This item is complete and has been merged/shipped logger This item relates to the Logger Utility

Comments

@deffer
Copy link

deffer commented Mar 25, 2024

Expected Behaviour

Expect a following warning when the Application log level of AWS Lambda configuration is set to INFO while powertools level is set to DEBUG (via logLevel attribute of the ConstructorOptions)

Current log level (%s) does not match AWS Lambda Advanced Logging Controls minimum log level (%s). This can lead to data loss, consider adjusting them.

Current Behaviour

Lambda is failing with the following error:

{
    "timestamp": "2024-03-25T01:07:01.251Z",
    "level": "ERROR",
    "message": {
        "errorType": "TypeError",
        "errorMessage": "Cannot read properties of undefined (reading 'formatAttributes')",
        "stackTrace": [
            "TypeError: Cannot read properties of undefined (reading 'formatAttributes')",
            "    at Logger.createAndPopulateLogItem (file:///var/task/node_modules/@aws-lambda-powertools/logger/lib/esm/Logger.js:518:47)",
            "    at Logger.processLogItem (file:///var/task/node_modules/@aws-lambda-powertools/logger/lib/esm/Logger.js:651:42)",
            "    at Logger.warn (file:///var/task/node_modules/@aws-lambda-powertools/logger/lib/esm/Logger.js:437:14)",
            "    at Logger.awsLogLevelShortCircuit (file:///var/task/node_modules/@aws-lambda-powertools/logger/lib/esm/Logger.js:480:22)",
            "    at Logger.setInitialLogLevel (file:///var/task/node_modules/@aws-lambda-powertools/logger/lib/esm/Logger.js:709:18)",
            "    at Logger.setOptions (file:///var/task/node_modules/@aws-lambda-powertools/logger/lib/esm/Logger.js:806:14)",
            "    at new Logger (file:///var/task/node_modules/@aws-lambda-powertools/logger/lib/esm/Logger.js:134:14)",
            "    at file:///var/task/index.js:10:16",
            "    at ModuleJob.run (node:internal/modules/esm/module_job:218:25)",
            "    at async ModuleLoader.import (node:internal/modules/esm/loader:329:24)"
        ]
    }
}

Code snippet

Use the following constructor options in the Lambda, while Application log level of the Lambda Logging configuration is set to INFO (along with Log Format set to JSON).

Instantiate the logger outside of the handler function:

import { Logger } from '@aws-lambda-powertools/logger';
const logger = new Logger({
	logLevel: 'DEBUG', 
	serviceName: 'MyService',
	environment: 'test'
});

export const handler = async (event: LambdaEvent, context: Context ...

Steps to Reproduce

  1. Create a Node.js 20.x lambda. In the Configuration -> Monitoring and operations tool, set Log Format set to JSON and Application log level to INFO
  2. In the Lambda code instantiate the logger outside of the handler function:
import { Logger } from '@aws-lambda-powertools/logger';
const logger = new Logger({
	logLevel: 'DEBUG', 
	serviceName: 'MyService',
	environment: 'test'
});
  1. Test the function my passing any object. The instantiation of the logger will fail with the following error
{
    "timestamp": "2024-03-25T01:07:01.251Z",
    "level": "ERROR",
    "message": {
        "errorType": "TypeError",
        "errorMessage": "Cannot read properties of undefined (reading 'formatAttributes')",
        "stackTrace": [
            "TypeError: Cannot read properties of undefined (reading 'formatAttributes')",
            "    at Logger.createAndPopulateLogItem (file:///var/task/node_modules/@aws-lambda-powertools/logger/lib/esm/Logger.js:518:47)",
            "    at Logger.processLogItem (file:///var/task/node_modules/@aws-lambda-powertools/logger/lib/esm/Logger.js:651:42)",
            "    at Logger.warn (file:///var/task/node_modules/@aws-lambda-powertools/logger/lib/esm/Logger.js:437:14)",
            "    at Logger.awsLogLevelShortCircuit (file:///var/task/node_modules/@aws-lambda-powertools/logger/lib/esm/Logger.js:480:22)",
            "    at Logger.setInitialLogLevel (file:///var/task/node_modules/@aws-lambda-powertools/logger/lib/esm/Logger.js:709:18)",
            "    at Logger.setOptions (file:///var/task/node_modules/@aws-lambda-powertools/logger/lib/esm/Logger.js:806:14)",
            "    at new Logger (file:///var/task/node_modules/@aws-lambda-powertools/logger/lib/esm/Logger.js:134:14)",
            "    at file:///var/task/index.js:10:16",
            "    at ModuleJob.run (node:internal/modules/esm/module_job:218:25)",
            "    at async ModuleLoader.import (node:internal/modules/esm/loader:329:24)"
        ]
    }
}

Possible Solution

In the private setOptions(...) method of the Logger, change the order of the initialization of initiaLogLevel and the logFormatter to make sure logFormatter is initialized before invoking this.setInitialLogLevel(logLevel);

    this.setInitialLogLevel(logLevel);
    this.setLogFormatter(logFormatter);  // move up

Reason:
The Logger's method awsLogLevelShortCircuit, which is invoked during the construction of the Logger with options, attempts to log a warning about mismatched log levels using this.warn(). The warn() method relies on the logFormatter been set, which has not happened yet.

Powertools for AWS Lambda (TypeScript) version

latest

AWS Lambda function runtime

20.x

Packaging format used

npm

Execution logs

No response

@deffer deffer added triage This item has not been triaged by a maintainer, please wait bug Something isn't working labels Mar 25, 2024
Copy link

boring-cyborg bot commented Mar 25, 2024

Thanks for opening your first issue here! We'll come back to you as soon as we can.
In the meantime, check out the #typescript channel on our Powertools for AWS Lambda Discord: Invite link

@dreamorosi dreamorosi self-assigned this Mar 25, 2024
@dreamorosi dreamorosi added logger This item relates to the Logger Utility confirmed The scope is clear, ready for implementation and removed triage This item has not been triaged by a maintainer, please wait labels Mar 25, 2024
@dreamorosi
Copy link
Contributor

Hi @deffer, thank you so much for opening this issue.

I was able to reproduce the behavior you described and identify a gap in our tests.

I'll be working on a fix and will open a PR as soon as I have it, together with some new tests.

@dreamorosi dreamorosi linked a pull request Mar 25, 2024 that will close this issue
9 tasks
@dreamorosi
Copy link
Contributor

I have opened a PR that should fix the issue.

Instead of swapping the order of the methods during the setup phase I have modified the init logic so that the order of these actions shouldn't matter. I have also added a test case that matches the "steps to reproduce" indicated above.

Copy link
Contributor

⚠️ COMMENT VISIBILITY WARNING ⚠️

This issue is now closed. Please be mindful that future comments are hard for our team to see.

If you need more assistance, please either tag a team member or open a new issue that references this one.

If you wish to keep having a conversation with other community members under this issue feel free to do so.

@github-actions github-actions bot added pending-release This item has been merged and will be released soon and removed confirmed The scope is clear, ready for implementation labels Mar 27, 2024
Copy link
Contributor

This is now released under v2.0.4 version!

@github-actions github-actions bot added completed This item is complete and has been merged/shipped and removed pending-release This item has been merged and will be released soon labels Apr 10, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working completed This item is complete and has been merged/shipped logger This item relates to the Logger Utility
Projects
Status: Coming soon
Development

Successfully merging a pull request may close this issue.

2 participants