Bug: Injecting Lambda context into logger causing exception #4362

Thomas-McKanna · 2024-05-17T16:39:08Z

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

The text was updated successfully, but these errors were encountered:

leandrodamascena · 2024-05-17T16:52:40Z

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

Thanks

leandrodamascena · 2024-05-17T17:04:06Z

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 · 2024-05-17T17:04:07Z

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

leandrodamascena · 2024-05-17T17:18:12Z

@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 · 2024-05-17T17:23:53Z

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 · 2024-05-17T17:27:56Z

@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 · 2024-05-17T17:32:49Z

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 · 2024-05-17T17:36:01Z

@leandrodamascena

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

Thomas-McKanna · 2024-05-17T17:36:55Z

If it helps, I am doing a * import on another module that is also initializing a Logger instance. I wonder if this is related to the issue.

SimonBFrank · 2024-05-17T17:39:17Z

I am seeing this when I am running locally.

leandrodamascena · 2024-05-17T17:48:06Z

I am doing a * import on another module that is also initializing a Logger instance.

Thank you so much @Thomas-McKanna and @SimonBFrank, this is the missing piece. I was able to reproduce this and am debugging to see if I can find a quick solution or revert this PR https://github.com/aws-powertools/powertools-lambda-python/pull/4295/files

validate_log.py

from collections import namedtuple
from aws_lambda_powertools.event_handler import (
    APIGatewayRestResolver,)
from aws_lambda_powertools.logging import correlation_paths
from aws_lambda_powertools.utilities.typing import LambdaContext
from aws_lambda_powertools import Logger

from event import EVENT

from validate_log1 import *

logger = Logger()
app = APIGatewayRestResolver(enable_validation=True)

@app.get("/hello")
def get_todos():
    return {"todos": "OK"}


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


def lambda_context():
    lambda_context = {
        "function_name": "test",
        "memory_limit_in_mb": 128,
        "invoked_function_arn": "arn:aws:lambda:eu-west-1:809313241:function:test",
        "aws_request_id": "52fdfc07-2182-154f-163f-5f0f9a621d72",
    }

    return namedtuple("LambdaContext", lambda_context.keys())(*lambda_context.values())

lambda_handler(EVENT, lambda_context())

validate_log1.py

from aws_lambda_powertools import Logger

logger = Logger()

output

(venv) ➜  bug-log python validate_log.py                          
Traceback (most recent call last):
  File "/Users//DEV/powertools/tmp-testes/bug-log/validate_log.py", line 37, in <module>
    lambda_handler(EVENT, lambda_context())
  File "/Users//DEV/powertools/tmp-testes/bug-log/venv/lib/python3.10/site-packages/aws_lambda_powertools/logging/logger.py", line 455, in decorate
    self.append_keys(cold_start=cold_start, **lambda_context.__dict__)
  File "/Users//DEV/powertools/tmp-testes/bug-log/venv/lib/python3.10/site-packages/aws_lambda_powertools/logging/logger.py", line 603, in append_keys
    self.registered_formatter.append_keys(**additional_keys)
AttributeError: 'NoneType' object has no attribute 'append_keys'

This same code works in version 2.37.0

saravsak · 2024-05-17T18:36:28Z

+1. We saw this happening too. We had to rollback to 2.37 and it seems to work now.

What's weird is that this code segment worked locally, but did not work when deployed to a Lambda.

leandrodamascena · 2024-05-17T18:46:24Z

What's weird is that this code segment worked locally, but did not work when deployed to a Lambda.

Hi @saravsak, just to understand your use case, how many Logger instances are you creating? Do you have any other library that creates a log instance?

leandrodamascena · 2024-05-17T18:46:47Z

I'll rollback this PR to allow us to have more time to test as many scenarios as possible, it looks like we have some use cases that aren't clear and I don't know if the patch I'm going to apply has any side effects.

I will make a patch release 2.38.1 with the code reverted.

Thank you everyone for reporting this and I apologize for any inconveniences.

saravsak · 2024-05-17T18:51:54Z

What's weird is that this code segment worked locally, but did not work when deployed to a Lambda.

Hi @saravsak, just to understand your use case, how many Logger instances are you creating? Do you have any other library that creates a log instance?

Looks like the reason this was working locally was because we were still using 2.37 in our virtualenv whereas our pipeline was installing 2.38 which is why our deployments broke. Roling it back to 2.37 worked.

leandrodamascena · 2024-05-17T19:22:46Z

I'm waiting for the CI to turn green to merge and release a patch release.

#4363

leandrodamascena · 2024-05-17T19:30:13Z

I'm releasing v2.38.1 - https://github.com/aws-powertools/powertools-lambda-python/actions/runs/9133311541

leandrodamascena · 2024-05-17T19:49:54Z

Hello @Thomas-McKanna @SimonBFrank @saravsak @JacobAuthenic v2.38.1 is already available in PyPi, can you please try and give me a feedback?

https://pypi.org/project/aws-lambda-powertools/2.38.1/

github-actions · 2024-05-17T20:04:56Z

This is now released under 2.38.1 version!

SimonBFrank · 2024-05-17T20:21:50Z

v2.38.1 works again for me! Thanks for the help

Thomas-McKanna · 2024-05-17T23:45:55Z

Working for me now also. Thanks!

github-actions · 2024-05-17T23:46:13Z

⚠️COMMENT VISIBILITY WARNING⚠️

This issue is now closed. Please be mindful that future comments are hard for our team to see.

If you need more assistance, please either tag a team member or open a new issue that references this one.

If you wish to keep having a conversation with other community members under this issue feel free to do so.

heitorlessa · 2024-05-18T01:14:03Z

thank you all for pitching in so quickly, can't thank you enough. We'll create new tests for this use case (functional & end-to-end) to catch regressions like this earlier now.

and thank you @leandrodamascena for working late on Friday night to revert the other bug fix that caused this regression undetected by our tests suite <3

Thomas-McKanna added bug Something isn't working triage Pending triage from maintainers labels May 17, 2024

github-project-automation bot added this to Powertools for AWS Lambda (Python) May 17, 2024

github-project-automation bot moved this to Triage in Powertools for AWS Lambda (Python) May 17, 2024

leandrodamascena self-assigned this May 17, 2024

leandrodamascena removed the triage Pending triage from maintainers label May 17, 2024

leandrodamascena moved this from Triage to Working on it in Powertools for AWS Lambda (Python) May 17, 2024

leandrodamascena added the logger label May 17, 2024

leandrodamascena mentioned this issue May 17, 2024

fix(logger): reverting logger child modification #4363

Merged

7 tasks

github-actions bot added the pending-release Fix or implementation already in dev waiting to be released label May 17, 2024

github-actions bot closed this as completed May 17, 2024

github-actions bot removed the pending-release Fix or implementation already in dev waiting to be released label May 17, 2024

github-project-automation bot moved this from Working on it to Coming soon in Powertools for AWS Lambda (Python) May 17, 2024

leandrodamascena reopened this May 17, 2024

github-project-automation bot moved this from Coming soon to Pending review in Powertools for AWS Lambda (Python) May 17, 2024

Thomas-McKanna closed this as completed May 17, 2024

github-project-automation bot moved this from Pending review to Coming soon in Powertools for AWS Lambda (Python) May 17, 2024

heitorlessa mentioned this issue May 18, 2024

Bug: logger_handler argument is ignored if logging.getLogger() already has a handler. #4277

Closed

heitorlessa moved this from Coming soon to Shipped in Powertools for AWS Lambda (Python) Jun 10, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Bug: Injecting Lambda context into logger causing exception #4362

Bug: Injecting Lambda context into logger causing exception #4362

Thomas-McKanna commented May 17, 2024 •

edited

Loading

leandrodamascena commented May 17, 2024

leandrodamascena commented May 17, 2024

Thomas-McKanna commented May 17, 2024

leandrodamascena commented May 17, 2024

SimonBFrank commented May 17, 2024

Thomas-McKanna commented May 17, 2024

leandrodamascena commented May 17, 2024

Thomas-McKanna commented May 17, 2024

Thomas-McKanna commented May 17, 2024 •

edited

Loading

SimonBFrank commented May 17, 2024

leandrodamascena commented May 17, 2024 •

edited

Loading

saravsak commented May 17, 2024

leandrodamascena commented May 17, 2024

leandrodamascena commented May 17, 2024

saravsak commented May 17, 2024

leandrodamascena commented May 17, 2024 •

edited

Loading

leandrodamascena commented May 17, 2024

leandrodamascena commented May 17, 2024

github-actions bot commented May 17, 2024

SimonBFrank commented May 17, 2024

Thomas-McKanna commented May 17, 2024

github-actions bot commented May 17, 2024

heitorlessa commented May 18, 2024

Bug: Injecting Lambda context into logger causing exception #4362

Bug: Injecting Lambda context into logger causing exception #4362

Comments

Thomas-McKanna commented May 17, 2024 • edited Loading

Expected Behaviour

Current Behaviour

Code snippet

Possible Solution

Steps to Reproduce

Powertools for AWS Lambda (Python) version

AWS Lambda function runtime

Packaging format used

Debugging logs

leandrodamascena commented May 17, 2024

leandrodamascena commented May 17, 2024

CODE

OUTPUT

Thomas-McKanna commented May 17, 2024

leandrodamascena commented May 17, 2024

SimonBFrank commented May 17, 2024

Thomas-McKanna commented May 17, 2024

leandrodamascena commented May 17, 2024

Thomas-McKanna commented May 17, 2024

Thomas-McKanna commented May 17, 2024 • edited Loading

SimonBFrank commented May 17, 2024

leandrodamascena commented May 17, 2024 • edited Loading

validate_log.py

validate_log1.py

output

saravsak commented May 17, 2024

leandrodamascena commented May 17, 2024

leandrodamascena commented May 17, 2024

saravsak commented May 17, 2024

leandrodamascena commented May 17, 2024 • edited Loading

leandrodamascena commented May 17, 2024

leandrodamascena commented May 17, 2024

github-actions bot commented May 17, 2024

SimonBFrank commented May 17, 2024

Thomas-McKanna commented May 17, 2024

github-actions bot commented May 17, 2024

⚠️COMMENT VISIBILITY WARNING⚠️

heitorlessa commented May 18, 2024

Thomas-McKanna commented May 17, 2024 •

edited

Loading

Thomas-McKanna commented May 17, 2024 •

edited

Loading

leandrodamascena commented May 17, 2024 •

edited

Loading

leandrodamascena commented May 17, 2024 •

edited

Loading