Bug: Log pollution with the same warning on every warm execution when using injectLambdaContext middleware

[kallependers]

Expected Behavior

No warning logged that the current log level does not match AWS Lambda Advanced Logging Controls minimum log level when injectLambdaContext Middy middleware is used.

Current Behavior

On every warm execution with injectLambdaContext Middy middleware a warning is logged that the current log level does not match AWS Lambda Advanced Logging Controls minimum log level.

Problem:

• injectLambdaContext calls refreshSampleRateCalculation on every execution;
• refreshSampleRateCalculation callsthis.setLogLevel with the #initialLogLevel on every warm call when debug sampling is not enabled;
• #initialLogLevel contains the default value INFO, because AWS Lambda Advanced Logging Controls minimum log level is set (to a higher value than INFO).

Since the following commit 8c8d6b2, because refreshSampleRateCalculation was added to middy.ts.

Code snippet

import { Logger } from '@aws-lambda-powertools/logger';
import middy from '@middy/core';

const logger = new Logger();

export const handler = middy()
  .use(injectLambdaContext(logger))
  .handler(async () => ({}));

Steps to Reproduce

1. Set application log level to WARN (AWS Lambda Advanced Logging Controls | systemLogLevelV2);
2. Set environment variable POWERTOOLS_LOG_LEVEL=WARN;
3. Don't configure any debug sampling;
4. Use injectLambdaContext Middy middleware;
5. From a warm execution (coldStart=false) onwards every time a WARN is logged.

Possible Solution

setInitialLogLevel in Logger.ts assigns the #initialLogLevel regardless if awsLogLevelShortCircuit is true and another check is added (or replaced for the awsLogLevelShortCircuit condition in setInitialLogLevel) if AWS Lambda Advanced Logging Controls is configured and sets the initial log level with this value.

Another solution would be documenting that Powertool's log level should be combined with AWS Lambda's application log level. The downside of this would be possible log pollution coming from libraries that don't use the Powertool logger, but something else (console eg).

Powertools for AWS Lambda (TypeScript) version

V2.16.0 - V2.18.0 (latest currently)

AWS Lambda function runtime

22.x

Packaging format used

npm

Execution logs

{
    "level": "WARN",
    "message": "Current log level (INFO) does not match AWS Lambda Advanced Logging Controls minimum log level (WARN). This can lead to data loss, consider adjusting them.",
    "timestamp": "X",
    "service": "X",
    "cold_start": false,
    "function_arn": "X",
    "function_memory_size": "128",
    "function_name": "X",
    "function_request_id": "X",
    "sampling_rate": 0,
    "xray_trace_id": "X"
}

[boring-cyborg]

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]

Hi @kallependers, thank you for opening this issue and for taking the time to share the detailed report.

I was able to reproduce the issue and as you pointed out, when the we detect that Advanced Logging Controls is enabled we fall back to that, but never store that value. Because of this, even if ApplicationLogLevel.WARN and POWERTOOLS_LOG_LEVEL=WARN are aligned, the Logger thinks there's a mismatch as it uses the default log level (INFO).

I'm working to see if I can fix the bug and will propose a PR, hopefully soon.

We do have a section dedicated to ALC and how it interacts with our logger here, if you think there's any specific improvement we can do there please let us know.

[dreamorosi]

Besides fixing the bug described above, I think we should also address the fact that these warnings should not be spammed.

I'm going to see if I can implement a mechanism to emit this type of warnings only once per execution environment.

[kallependers]

Sounds great! Thanks a lot for the quick response.