Logger clear_state flip removing structure keys

[alexanderluiscampino]

Using the clear_state argument in the logger decorator for lambda handlers is destroying the default structured keys.

What were you trying to accomplish?
Just trying to get some lambda logs with custom keys, which ideally would be cleaned up after each warm call, such that those custom key values do not trickle to the next invocation.

Expected Behavior

Using the clear_state argument should not remove the default structured keys. Those should remain fixed. Only custom keys should be removed upon new invocation.

Current Behavior

Currently, default structured keys are being removed from the get-go.

Steps to Reproduce (for bugs)

First, this:

from aws_lambda_powertools import logging
from aws_lambda_powertools.utilities.typing import LambdaContext


logger = logging.Logger()

@logger.inject_lambda_context(clear_state=False)
def lambda_handler(event: dict, context: LambdaContext):
    logger.info("HEREEE")

Output:

{
    "level": "INFO",
    "location": "lambda_handler:21",
    "message": "HEREEE",
    "timestamp": "2022-03-29 17:53:56,985+0000",
    "service": "service_undefined",
    "cold_start": true,
    "function_name": "alex-test-layers",
    "function_memory_size": "1024",
    "function_arn": "arn:aws:lambda:us-west-2:111111111111:function:alex-test-layers",
    "function_request_id": "a1453466-2abe-4a55-ad9e-640e745f4133",
    "xray_trace_id": "1-624347b4-589b3226782e49797249edb1"
}

Now this clear_state=True

from aws_lambda_powertools import logging
from aws_lambda_powertools.utilities.typing import LambdaContext


logger = logging.Logger()

@logger.inject_lambda_context(clear_state=True)
def lambda_handler(event: dict, context: LambdaContext):
    logger.info("HEREEE")

Output:

{
    "message": "HEREEE",
    "service": "service_undefined",
    "cold_start": true,
    "function_name": "alex-test-layers",
    "function_memory_size": "1024",
    "function_arn": "arn:aws:lambda:us-west-2:111111111111:function:alex-test-layers",
    "function_request_id": "e3cf7717-88ea-43dc-b80c-57754bc6b8c9",
    "xray_trace_id": "1-62435f24-54e5827e68d838640494dca4"
}

Environment

• Powertools version used: aws-lambda-powertools==1.25.5
• Packaging format (Layers, PyPi): Layers
• AWS Lambda function runtime: Python 3.8
• Debugging logs: Above.

[heitorlessa]

Thank you @alexanderluiscampino for filing a high quality bug reporting -- We'll look into this week and release a patch release once as soon as we can.

Thank you

[heitorlessa]

Reproduced and found the regression was introduced in 1.25.3 when fixing a custom formatter. Tests were insufficient for clear_state=True hence we didn't catch it -- working on better tests and will make a release by EOD the latest.

[github-actions]

This is now released under 1.25.6 version!

[heitorlessa]

Thanks to your super high quality bug report we managed to reproduce and improved tests as part of the fix - the latest version 1.25.6 has this fix now. Lambda Layers upcoming version 16 will take a few hours to be available in multiple AWS commercial regions.

[eliasbrange]

@heitorlessa, I'm seeing some problems which I'm guess is connected to this as well. I've been trying to change the default location format by doing: logger = Logger(location="...") and I'm also running with clear_state=True. And now, the call to _build_default_keys() resets it back to "%(funcName)s:%(lineno)d".

Saw in the contribution guide that external contributions are de-prioritized for now, so will not create a PR. But something like the following could perhaps work?

Switch the following from

https://github.com/awslabs/aws-lambda-powertools-python/blob/f24332d76d1ecb42c33f1e34607ac458f670d8c3/aws_lambda_powertools/logging/formatter.py#L130-L131

to

self.keys_combined = {**self._build_default_keys(), **kwargs} 
self.log_format.update(**self.keys_combined) 

and switch

https://github.com/awslabs/aws-lambda-powertools-python/blob/f24332d76d1ecb42c33f1e34607ac458f670d8c3/aws_lambda_powertools/logging/formatter.py#L188-L190

to

def clear_state(self):
    self.log_format = dict.fromkeys(self.log_record_order)
    self.log_format.update(**self.keys_combined)

[heitorlessa]

Edit: wording as I reopened the issue. Will try to reproduce tomorrow morning before shift starts

Hey @eliasbrange! For bugs we can reproduce, we welcome the PRs ;)

This seemed like an easy fix for custom formatters at first, but it continues to cause edge cases that our tests were not covering clear_state well enough - my apologies.

I'm with customers until Thursday evening, but if you could make a PR with tests, I'll gladly accept it (and enrich if necessary)

Thank you 🙏