Bug: Injecting Lambda context into logger causing exception

[Thomas-McKanna]

Expected Behaviour

Should be able to write a Lambda handler like this:

@logger.inject_lambda_context(correlation_id_path=correlation_paths.API_GATEWAY_HTTP, log_event=True)
@tracer.capture_lambda_handler
def lambda_handler(request: dict, context: LambdaContext) -> dict:
    return app.resolve(request, context)

Current Behaviour

502 errors are being returned by API endpoint pointing to Lambda function. Error log is:

[ERROR] AttributeError: 'NoneType' object has no attribute 'append_keys'
Traceback (most recent call last):
  File "/var/task/aws_lambda_powertools/logging/logger.py", line 455, in decorate
    self.append_keys(cold_start=cold_start, **lambda_context.__dict__)
  File "/var/task/aws_lambda_powertools/logging/logger.py", line 603, in append_keys
    self.registered_formatter.append_keys(**additional_keys)

I suspect this error is due to a recent change, as things were working for me yesterday. Removing the @logger.inject_lambda_context decorator removed the error.

The code does not work in version 2.38.0, but does work in version 2.37.0 and earlier.

Code snippet

@logger.inject_lambda_context(correlation_id_path=correlation_paths.API_GATEWAY_HTTP, log_event=True)
@tracer.capture_lambda_handler
def lambda_handler(request: dict, context: LambdaContext) -> dict:
    return app.resolve(request, context)

Possible Solution

No response

Steps to Reproduce

Make minimalistic Lambda Powertools event handler.

Powertools for AWS Lambda (Python) version

latest

AWS Lambda function runtime

3.10

Packaging format used

Lambda Layers

Debugging logs

No response

[leandrodamascena]

Hey @Thomas-McKanna, can you please confirm the Powertools version you are using?

Thanks

[leandrodamascena]

Ah, I saw that you mentioned the version in the issue: 2.38.0.

I'm using this code and this is working as expected in 2.38.0 version. Can you check my code and see if I'm missing something?

CODE

import requests
from requests import Response

from aws_lambda_powertools import Logger, Tracer
from aws_lambda_powertools.event_handler import APIGatewayRestResolver
from aws_lambda_powertools.logging import correlation_paths
from aws_lambda_powertools.utilities.typing import LambdaContext

tracer = Tracer()
logger = Logger()
app = APIGatewayRestResolver()


@app.get("/hello")
@tracer.capture_method
def get_todos():
    todos: Response = requests.get("https://jsonplaceholder.typicode.com/todos")
    todos.raise_for_status()

    # for brevity, we'll limit to the first 10 only
    return {"todos": todos.json()[:10]}


# You can continue to use other utilities just as before
@logger.inject_lambda_context(correlation_id_path=correlation_paths.API_GATEWAY_HTTP, log_event=True)
@tracer.capture_lambda_handler
def lambda_handler(event: dict, context: LambdaContext) -> dict:
    return app.resolve(event, context)

OUTPUT

2024-05-17 18:00:58 127.0.0.1 - - [17/May/2024 18:00:58] "GET /favicon.ico HTTP/1.1" 403 -
Invoking app.lambda_handler (python3.10)                                                                                                                                                                                                                                                         
Reuse the created warm container for Lambda function 'HelloWorldFunction'                                                                                                                                                                                                                        
Lambda function 'HelloWorldFunction' is already running                                                                                                                                                                                                                                          
START RequestId: ff767f95-8b88-4556-a11b-34d3a0bc43a8 Version: $LATEST
{"level":"INFO","location":"decorate:464","message":{"body":null,"headers":{"Aaaa":"ssss","Accept":"text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.7","Accept-Encoding":"deflate, gzip","Accept-Language":"pt-BR,pt;q=0.9,en-US;q=0.8,en;q=0.7","Cache-Control":"max-age=0","Connection":"keep-alive","Cookie":"ai_user=g4yjv2A7NLpX5f41GKfChv|2024-04-29T13:59:36.588Z","Host":"127.0.0.1:3000","Sec-Ch-Ua":"\"Chromium\";v=\"124\", \"Google Chrome\";v=\"124\", \"Not-A.Brand\";v=\"99\"","Sec-Ch-Ua-Mobile":"?0","Sec-Ch-Ua-Platform":"\"macOS\"","Sec-Fetch-Dest":"document","Sec-Fetch-Mode":"navigate","Sec-Fetch-Site":"none","Sec-Fetch-User":"?1","Upgrade-Insecure-Requests":"1","User-Agent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/124.0.0.0 Safari/537.36","X-Forwarded-Port":"3000","X-Forwarded-Proto":"http"},"httpMethod":"GET","isBase64Encoded":false,"multiValueHeaders":{"Aaaa":["ssss"],"Accept":["text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.7"],"Accept-Encoding":["deflate, gzip"],"Accept-Language":["pt-BR,pt;q=0.9,en-US;q=0.8,en;q=0.7"],"Cache-Control":["max-age=0"],"Connection":["keep-alive"],"Cookie":["ai_user=g4yjv2A7NLpX5f41GKfChv|2024-04-29T13:59:36.588Z"],"Host":["127.0.0.1:3000"],"Sec-Ch-Ua":["\"Chromium\";v=\"124\", \"Google Chrome\";v=\"124\", \"Not-A.Brand\";v=\"99\""],"Sec-Ch-Ua-Mobile":["?0"],"Sec-Ch-Ua-Platform":["\"macOS\""],"Sec-Fetch-Dest":["document"],"Sec-Fetch-Mode":["navigate"],"Sec-Fetch-Site":["none"],"Sec-Fetch-User":["?1"],"Upgrade-Insecure-Requests":["1"],"User-Agent":["Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/124.0.0.0 Safari/537.36"],"X-Forwarded-Port":["3000"],"X-Forwarded-Proto":["http"]},"multiValueQueryStringParameters":null,"path":"/hello","pathParameters":null,"queryStringParameters":null,"requestContext":{"accountId":"123456789012","apiId":"1234567890","domainName":"127.0.0.1:3000","extendedRequestId":null,"httpMethod":"GET","identity":{"accountId":null,"apiKey":null,"caller":null,"cognitoAuthenticationProvider":null,"cognitoAuthenticationType":null,"cognitoIdentityPoolId":null,"sourceIp":"127.0.0.1","user":null,"userAgent":"Custom User Agent String","userArn":null},"path":"/hello","protocol":"HTTP/1.1","requestId":"da64b3a2-8d61-47df-ac64-4f5fce271ac1","requestTime":"17/May/2024:17:00:49 +0000","requestTimeEpoch":1715965249,"resourceId":"123456","resourcePath":"/hello","stage":"Prod"},"resource":"/hello","stageVariables":null},"timestamp":"2024-05-17 17:02:41,596+0000","service":"service_undefined","cold_start":false,"function_name":"HelloWorldFunction","function_memory_size":"128","function_arn":"arn:aws:lambda:us-east-1:012345678912:function:HelloWorldFunction","function_request_id":"fb5c1346-f7b6-44fd-be26-21fec400883c","correlation_id":"da64b3a2-8d61-47df-ac64-4f5fce271ac1"}
END RequestId: fb5c1346-f7b6-44fd-be26-21fec400883c
REPORT RequestId: fb5c1346-f7b6-44fd-be26-21fec400883c	Duration: 269.41 ms	Billed Duration: 270 ms	Memory Size: 128 MB	Max Memory Used: 128 MB	

[Thomas-McKanna]

@leandrodamascena The bug appears in 2.38.0. My code was working up to and including version 2.37.0.

[leandrodamascena]

@leandrodamascena The bug appears in 2.38.0. My code was working up to and including version 2.37.0.

Thanks for sending this. I sent an example that is working for me. Can you validate this and see if I'm doing anything different than you?

[SimonBFrank]

I am also seeing an issue that I think is related. I am getting the following error: AttributeError: 'NoneType' object has no attribute 'clear_state'. This is breaking existing unit-tests when I upgraded from v2.37.0 to v2.38.0. Below is the stack trace.

self = <aws_lambda_powertools.logging.logger.Logger object at 0x10860b9d0>, append = False, formatter_options = {}, keys = {'cold_start': False, 'function_arn': 'AWS-ARN', 'function_memory_size': 512, 'function_name': 'FUNCTION-NAME', ...}
log_keys = {'cold_start': False, 'function_arn': 'AWS-ARN', 'function_memory_size': 512, 'function_name': 'FUNCTION-NAME', ...}, is_logger_preconfigured = True

    def structure_logs(self, append: bool = False, formatter_options: Optional[Dict] = None, **keys) -> None:
        """Sets logging formatting to JSON.
    
        Optionally, it can append keyword arguments
        to an existing logger, so it is available across future log statements.
    
        Last keyword argument and value wins if duplicated.
    
        Parameters
        ----------
        append : bool, optional
            append keys provided to logger formatter, by default False
        formatter_options : dict, optional
            LambdaPowertoolsFormatter options to be propagated, by default {}
        """
        formatter_options = formatter_options or {}
    
        # There are 3 operational modes for this method
        ## 1. Register a Powertools for AWS Lambda (Python) Formatter for the first time
        ## 2. Append new keys to the current logger formatter; deprecated in favour of append_keys
        ## 3. Add new keys and discard existing to the registered formatter
    
        # Mode 1
        log_keys = {**self._default_log_keys, **keys}
        is_logger_preconfigured = getattr(self._logger, LOGGER_ATTRIBUTE_PRECONFIGURED, False)
        if not is_logger_preconfigured:
            formatter = self.logger_formatter or LambdaPowertoolsFormatter(**formatter_options, **log_keys)
            self.registered_handler.setFormatter(formatter)
    
            # when using a custom Powertools for AWS Lambda (Python) Formatter
            # standard and custom keys that are not Powertools for AWS Lambda (Python) Formatter parameters
            # should be appended and custom keys that might happen to be Powertools for AWS Lambda (Python)
            # Formatter parameters should be discarded this prevents adding them as custom keys, for example,
            # `json_default=<callable>` see https://github.com/aws-powertools/powertools-lambda-python/issues/1263
            custom_keys = {k: v for k, v in log_keys.items() if k not in RESERVED_FORMATTER_CUSTOM_KEYS}
            return self.registered_formatter.append_keys(**custom_keys)
    
        # Mode 2 (legacy)
        if append:
            # Maintenance: Add deprecation warning for major version
            return self.append_keys(**keys)
    
        # Mode 3
>       self.registered_formatter.clear_state()
E       AttributeError: 'NoneType' object has no attribute 'clear_state'

[Thomas-McKanna]

@leandrodamascena

I'm doing a line by line comparison right now. It's stumping me. For some, my formatter is None:

powertools-lambda-python/aws_lambda_powertools/logging/logger.py

Lines 697 to 707 in d0293d0

	def registered_formatter(self) -> BasePowertoolsFormatter:
	"""Convenience property to access the first logger formatter"""
	handler = self.registered_handler
	if handler is None:
	raise OrphanedChildLoggerError(
	"Orphan child loggers cannot append nor remove keys until a parent is initialized first. "
	"To solve this issue, you can A) make sure a parent logger is initialized first, or B) move append/remove keys operations to a later stage." # noqa: E501
	"Reference: https://docs.powertools.aws.dev/lambda/python/latest/core/logger/#reusing-logger-across-your-code",
	)
	return cast(BasePowertoolsFormatter, handler.formatter)

I see there is a check that handler is None, but that that the formatter within it is None.

I really am struggling to find a difference in my code. Here is a scrubbed version of what I'm working with, with the endpoints taken out:

import traceback

from aws_lambda_powertools import Logger, Tracer
from aws_lambda_powertools.event_handler import (
    APIGatewayRestResolver,
    Response,
    content_types,
)
from aws_lambda_powertools.event_handler.openapi.params import Path
from aws_lambda_powertools.logging import correlation_paths
from aws_lambda_powertools.shared.types import Annotated
from aws_lambda_powertools.utilities.typing import LambdaContext


tracer = Tracer()
logger = Logger()
app = APIGatewayRestResolver(enable_validation=True)
app.enable_swagger(path="/swagger")

@logger.inject_lambda_context(
    correlation_id_path=correlation_paths.API_GATEWAY_HTTP, log_event=True
)
@tracer.capture_lambda_handler
def lambda_handler(request: dict, context: LambdaContext) -> dict:
    return app.resolve(request, context)

[leandrodamascena]

I suspect we have some regression caused here: https://github.com/aws-powertools/powertools-lambda-python/pull/4295/files.

I appreciate your patience and I'm sorry for some back and forth @Thomas-McKanna and @SimonBFrank, but I need to confirm some information before applying a patch or reverting this PR.

Can you confirm the environment you are running this Lambda in? Is this using AWS? SAM CLI? Serverless framework? Local emulation?

Thanks

[Thomas-McKanna]

@leandrodamascena

I am running in Python 3.10 Lambda environment in AWS, deployed with SAM CLI. I have not tried local emulation.