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.