Lambda context data is excluded when using custom formatter and flag clear_state on inject_lambda_context

[jacobdarrossi]

When we use a custom formatter, inject_lambda_context with clear_state=True stopped having effect

Expected Behavior

The keys appended should be removed in clear_state=True and the context data should be kept. The custom Formatter should not impact this behavior

Current Behavior

When we use a custom formatter to obfuscate sensitive data in our logs, the flag clear_state=True stopped having effect, the context data is no longer logged and the keys appended was not removed in next hot execution. If clear_state is removed, the context data is logged normally

Steps to Reproduce (for bugs)

1. Create a Formatter than override json_serializer_function
2. Create a Logger object with this formatter
3. Use the decorator inject_lambda_function(clear_state=True)
4. Check the execution logs

Environment

• Powertools version used: 1.25.1
• Packaging format (Layers, PyPi): Layer
• AWS Lambda function runtime: python 3.8

[boring-cyborg]

Thanks for opening your first issue here! We'll come back to you as soon as we can.

[heitorlessa]

Thanks a lot for reporting this @jacobdarrossi - it sounds like an issue on our side, if all you're doing is overriding that method.

We'll look into it on Monday as soon as we can, and make a patch release if we manage to reproduce it.

[heitorlessa]

Forgot to ask, could you provide before/after log outputs too?

That will speed up reproducing it on our side, or quickly detecting whether that's intended behaviour.

Thank you!!

[jacobdarrossi]

Thanks for replying so fast.
This is a simple example with logging enabled.

First block of logs, with Formatter.
The second without the Formatter.
I hope this is what you need.

Code:

from aws_lambda_powertools.logging.logger import Logger, set_package_logger
from aws_lambda_powertools.logging.formatter import LambdaPowertoolsFormatter
from dataclasses import dataclass
import json

set_package_logger()

class LambdaContext:
    function_name: str = "test"
    memory_limit_in_mb: int = 128
    invoked_function_arn: str = "arn:aws:lambda:eu-west-1:123456789:function:test"
    aws_request_id: str = "52fdfc07-2182-154f-163f-5f0f9a621d72"

class MyFormatter(LambdaPowertoolsFormatter):
    def __init__(self):
        super().__init__(json_serializer=self.json_serializer_function)

    def json_serializer_function(self, obj):
        return json.dumps(obj, default=str, separators=(",", ":"))

# logger = Logger(service="TEST", logger_formatter=MyFormatter())  # To test with formatter
logger = Logger(service="TEST")  # To test without formatter

@logger.inject_lambda_context(clear_state=True)
def lambda_handler(event, context):
    logger.info(f"Execution {event} start!")
    logger.append_keys(key=f"{event} appended")
    logger.info(f"Executing {event}")
    logger.info(f"Execution {event} end!")

lambda_handler(1, LambdaContext())
lambda_handler(2, LambdaContext())

Logs with formatter:

2022-02-27 14:15:28,161 aws_lambda_powertools.logging.logger [DEBUG] Adding filter in root logger to suppress child logger records to bubble up
2022-02-27 14:15:28,161 aws_lambda_powertools.logging.logger [DEBUG] Marking logger TEST as preconfigured
2022-02-27 14:15:28,161 aws_lambda_powertools.logging.logger [DEBUG] Decorator called with parameters
{"level":"INFO","location":"lambda_handler:26","message":"Execution 1 start!","timestamp":"2022-02-27 14:15:28,161-0300"}
{"level":"INFO","location":"lambda_handler:28","message":"Executing 1","timestamp":"2022-02-27 14:15:28,161-0300","key":"1 appended"}
{"level":"INFO","location":"lambda_handler:29","message":"Execution 1 end!","timestamp":"2022-02-27 14:15:28,161-0300","key":"1 appended"}
{"level":"INFO","location":"lambda_handler:26","message":"Execution 2 start!","timestamp":"2022-02-27 14:15:28,161-0300","key":"1 appended"}
{"level":"INFO","location":"lambda_handler:28","message":"Executing 2","timestamp":"2022-02-27 14:15:28,161-0300","key":"2 appended"}
{"level":"INFO","location":"lambda_handler:29","message":"Execution 2 end!","timestamp":"2022-02-27 14:15:28,161-0300","key":"2 appended"}

Logs without formatter:

2022-02-27 14:20:29,946 aws_lambda_powertools.logging.logger [DEBUG] Marking logger TEST as preconfigured
2022-02-27 14:20:29,946 aws_lambda_powertools.logging.logger [DEBUG] Decorator called with parameters
{"level":"INFO","location":"lambda_handler:26","message":"Execution 1 start!","timestamp":"2022-02-27 14:20:29,946-0300","service":"TEST","cold_start":true,"function_name":"test","function_memory_size":128,"function_arn":"arn:aws:lambda:eu-west-1:123456789:function:test","function_request_id":"52fdfc07-2182-154f-163f-5f0f9a621d72"}
{"level":"INFO","location":"lambda_handler:28","message":"Executing 1","timestamp":"2022-02-27 14:20:29,946-0300","service":"TEST","cold_start":true,"function_name":"test","function_memory_size":128,"function_arn":"arn:aws:lambda:eu-west-1:123456789:function:test","function_request_id":"52fdfc07-2182-154f-163f-5f0f9a621d72","key":"1 appended"}
{"level":"INFO","location":"lambda_handler:29","message":"Execution 1 end!","timestamp":"2022-02-27 14:20:29,946-0300","service":"TEST","cold_start":true,"function_name":"test","function_memory_size":128,"function_arn":"arn:aws:lambda:eu-west-1:123456789:function:test","function_request_id":"52fdfc07-2182-154f-163f-5f0f9a621d72","key":"1 appended"}
{"level":"INFO","location":"lambda_handler:26","message":"Execution 2 start!","timestamp":"2022-02-27 14:20:29,946-0300","service":"TEST","cold_start":false,"function_name":"test","function_memory_size":128,"function_arn":"arn:aws:lambda:eu-west-1:123456789:function:test","function_request_id":"52fdfc07-2182-154f-163f-5f0f9a621d72"}
{"level":"INFO","location":"lambda_handler:28","message":"Executing 2","timestamp":"2022-02-27 14:20:29,946-0300","service":"TEST","cold_start":false,"function_name":"test","function_memory_size":128,"function_arn":"arn:aws:lambda:eu-west-1:123456789:function:test","function_request_id":"52fdfc07-2182-154f-163f-5f0f9a621d72","key":"2 appended"}
{"level":"INFO","location":"lambda_handler:29","message":"Execution 2 end!","timestamp":"2022-02-27 14:20:29,946-0300","service":"TEST","cold_start":false,"function_name":"test","function_memory_size":128,"function_arn":"arn:aws:lambda:eu-west-1:123456789:function:test","function_request_id":"52fdfc07-2182-154f-163f-5f0f9a621d72","key":"2 appended"}

[heitorlessa]

Thanks a lot @jacobdarrossi - That doesn't seem right at all. Got side tracked with customer activities, but will be looking into it this week

[ilias-at-adarma]

@heitorlessa Funnily we had the exact same issue days ago, we're also using our own formatter which inherits the LambdaPowertoolsFormatter.

We think the issue is here:

https://github.com/awslabs/aws-lambda-powertools-python/blob/51ff350b25e2025b3baf3e4a64f8ba21632b1aec/aws_lambda_powertools/logging/logger.py#L394

If a formatter already exists it wont be reallocated and defaulted to the standard keys, it will just reuse the existing object.

Feels like the only way to not introduce a breaking change to this is to add a new parameter to pass a formatter factory or meta class that will recreate our own new formatter rather than reuse the existing one.

Something like

formatter = self.logger_formatter_factory(**log_keys) or self.logger_formatter or LambdaPowertoolsFormatter(**log_keys)  # type: ignore 

[heitorlessa]

ugh thanks a lot @ilias-at-adarma! @jacobdarrossi and @ilias-at-adarma, would it be too much of a blocker for you if I start looking at a solution this coming Monday?

I'd like to look into this clear headed, and with enough time to make an emergency release as soon as I get a fix. I can start looking as soon as possible if this can't be worked around (e.g. no clear_state=True).

[jacobdarrossi]

@heitorlessa, no problem. We wait. Thank you very much.

[heitorlessa]

Had my first look into this bug and the more I look the more interesting it becomes. @ilias-at-adarma I like your idea about factory, but I suspect we can solve it by transparently introducing a clear_state method plus a few non-breaking changes - meaning the fix will be automatically applied; no code changes on your side.

It's something I've been meaning to do for ages. Most of it came due to the original implementation that outgrew a tiny library we originally vended. Now it's a good opportunity to further break down structure_logs method (superseded by append/remove_keys) that we intend to deprecate.

With a clear_state, we can also provide better guidance for anyone bringing an entirely new custom formatter (BasePowertoolsFormatter over LambdaPowertoolsFormatter) while allowing them to opt-in for key features such as clear state, key ordering, etc.

Next. I blocked tomorrow morning and a few slots in the afternoon to work on tests for this. My resolve is to have a fix by the end of the week (latest), and send a few implementation ideas here in case I get blocked. Meantime, I'm gonna make a patch release today to introduce non-related fixes elsewhere.

I appreciate your patience while we investigate all trade-offs here.

[heitorlessa]

@jacobdarrossi @ilias-at-adarma we've got a fix - It'll be transparent to you as you're inheriting from LambdaPowertoolsFormatter and not BasePowertoolsFormatter. You can find the implementation details in the PR: #1072

For folks using Logger in non-Lambda environments, where they end up creating an entirely new Logger Formatter to use with Powertools, we decided to use a abstractmethod to ensure they have access to all features as documentation suggests. In this instance, @cakepietoast and I decided this wouldn't be a breaking change as it's documented that it should've worked, and if it wasn't it affects only <1% (extreme edge case).

Next. I'm work on improving the documentation on the edge case, and continue to emphasize LambdaPowertoolsFormatter is best.

If I'm mistaken and you are in fact inheriting from BasePowertoolsFormatter, please shout out and we can reconsider the use of abstractmethod.

Thank you for your patience :)

[ilias-at-adarma]

@heitorlessa, I tested with #1072's branch, works exactly as expected without any change on our side as you said.

We are indeed inheriting from LambdaPowertoolsFormatter where we add a couple of our own keys and formatting but still require the clear state for dynamically added keys within the lambda handler. We also add a handler to the logger which now works nicely as well.

Cheers

[heitorlessa]

Perfect. I'll complete the missing parts and make a release tomorrow

[jacobdarrossi]

@heitorlessa, we also tested it and it works as expected. Let's wait for release. Thanks

[github-actions]

This is now released under 1.25.3 version!

[heitorlessa]

PyPi and SAR App have the fix. Kicking the Lambda Layer update (version 13) across all AWS commercial regions we support - might take a few hours.

cc @am29d

[jacobdarrossi]

@heitorlessa and the whole aws-lambda-powertools team, thank you all

[heitorlessa]

Lambda Layer version 13 is now live on all regions -- Rebuilding docs and it should reflect the latest ARN in a few minutes

arn:aws:lambda:{region}:017000801446:layer:AWSLambdaPowertoolsPython:13