How correctly log AWS Lambda event with lambda powertools

[macdrorepo]

I've started using lambda power-tools for lambda. Currently my code looks like:

@event_source(data_class=SNSEvent)
@LOGGER.inject_lambda_context(log_event=True)
def handler(event: SNSEvent, context: LambdaContext) -> None:  # pylint: disable=W0613
    """Lambda function invoked by Image builder SNS topic, putting Image
    builder ami-id in parameter store.
    :param event: SNS message containing Image Builder build results
    :return:
    """
    LOGGER.debug(f"Event: {event}") //logging event
    for record in event.records:
        message = record.sns.message
        LOGGER.info(f"Message: {message}")
        process_sns_event(message)
        return None

In line with comment I want to log what actually is lambda getting at beginning. As for now in cloud watch I'm getting entries like: Event: <aws_lambda_powertools.utilities.data_classes.sns_event.SNSEvent object at 0x7f9bbd36a0> or Event: <generator object SNSEvent.records at 0x7facfb6510> after updating powertools version to latest.

I'm confused what should I do to log just event json. Can any one point me out what should I do? (I'm rather beginner as can seen).

[heitorlessa]

Hey, you don't need that debug statement because you already have "log_event=True".

Are you also not getting the raw Event logged in CloudWatch Logs?

Explanation: The @event_source decorator converts the raw event (Dict) into a Class, so logging the actual event will have the expected output like you're seeing.

Besides "log_event=True" that you're already using it, you can use the property "raw_event" to log the original event from your data class - LOGGER.debug(event.raw_event)

Let us know if you get different results otherwise!

[macdrorepo]

Nope I'm not getting any raw Event. What I can see in logs is:

{
    "level": "INFO",
    "location": "decorate:345",
    "message": "<aws_lambda_powertools.utilities.data_classes.sns_event.SNSEvent object at 0x7fa8c7d670>",
    "timestamp": "2022-12-09 12:13:42,503+0000",
    "service": "name",
    "sampling_rate": 1,
    "cold_start": true,
    "function_name": "name",
    "function_memory_size": "256",
    "function_arn": "arn:aws:lambda:eu-west-2:account:function:name",
    "function_request_id": "34300f77-d195-4cd1-a657-91cf0356574d",
    "xray_trace_id": "1-63932674-55ef07e0084667ec194df927"
}

{
    "level": "DEBUG",
    "location": "handler:27",
    "message": "Event: <generator object SNSEvent.records at 0x7fa7298510>",
    "timestamp": "2022-12-09 12:13:42,503+0000",
    "service": "name",
    "sampling_rate": 1,
    "cold_start": true,
    "function_name": "name",
    "function_memory_size": "256",
    "function_arn": "arn:aws:lambda:eu-west-2:account:function:name",
    "function_request_id": "34300f77-d195-4cd1-a657-91cf0356574d",
    "xray_trace_id": "1-63932674-55ef07e0084667ec194df927"
}

{
    "level": "INFO",
    "location": "handler:31",
    "message": "Message: {\n  string \n}",
    "timestamp": "2022-12-09 12:13:42,503+0000",
    "service": "name",
    "sampling_rate": 1,
    "cold_start": true,
    "function_name": "name",
    "function_memory_size": "256",
    "function_arn": "arn:aws:lambda:eu-west-2:account:function:name",
    "function_request_id": "34300f77-d195-4cd1-a657-91cf0356574d",
    "xray_trace_id": "1-63932674-55ef07e0084667ec194df927"
}

and so on.. rest of the logs

[heitorlessa]

Thanks for the output - that confirms that the event is being serialised earlier not giving the chance to be logged in raw format (when using log_event=True).

Swap the order of the decorator and it should work.

I'll get my laptop later to send a full working snippet

[macdrorepo]

So that would be correct order of decorators?

@LOGGER.inject_lambda_context(log_event=True)
@event_source(data_class=SNSEvent)
def handler(event: SNSEvent, context: LambdaContext) -> None:  # pylint: disable=W0613
    """Lambda function invoked by Image builder SNS topic, putting Image
    builder ami-id in parameter store.

    :param event: SNS message containing Image Builder build results
    :return:
    """
    LOGGER.debug(f"Event: {event.raw_event}")

    for record in event.records:
        message = record.sns.message
        LOGGER.info(f"Message: {message}")

        process_sns_event(message)
        return None

edit: Also that means @LOGGER.inject_lambda_context(log_event=True) must on top of all decorators if I would use more of them?

[heitorlessa]

So that would be correct order of decorators?

That's right!

edit: Also that means @LOGGER.inject_lambda_context(log_event=True) must on top of all decorators if I would use more of them?

No. This is only the case for event_source and parser decorators (or your own in the future) that modify the "event" dictionary in-place.

NOTE: I'll convert this discussion into a documentation issue as we can do better.

If we were to break it down, a mental model for decorators works like this, since the "@" is a syntactic sugar:

1. Modifies the event as dict into a SNS Data Class when called

handler = event_source(handler(event, context))

2. We log the event and extract key info from context. We do not mutate the event nor context.

handler = LOGGER.inject_lambda_context(handler(event, context), log_event=True)

In that order (like you have above), we have:

• Logger_inject_lambda_context will receive the pure event as dictionary, because the event_source function hasn't been called yet.
• Logger does its thing, and call the handler it decorated (Event Source)
• Event_source will call the handler it decorated (actual Lambda Handler), and pass a modified event, a SNS Data class, as the argument for the decorated handler

In one expression, it'd look like this:

handler = LOGGER.inject_lambda_context(
    event_source(
        # SNS data class now
        handler(event, context)
    )
,log_event=True)

Please let me know if we can better explain any of this in more detail.

Event Source Data Class is one of the documentation section we haven't managed to refactor entirely yet, so I truly appreciate you opening this discussion to help us do better (and more quickly).

Thank you!

[macdrorepo]

That's excellent - thank you. Will make adjustments to lambda and try that out.

[heitorlessa]

To close this discussion - I've extended the Logger feature log_event=True to take into account an event wrapped under Parser (Pydantic), and Dataclasses, so it can deserialize it correctly to its original before logging. This should remove the requirement of having the decorator in the right order - I can easily see this causing concerns despite documentation; best to do the right thing as you're explicitly asking to log the event.

Surprisingly, this was meant to work for Event Source Data Classes now that I've got my laptop to look at the code and see the history (that was done ~10 months ago). Nevertheless, it works for any case we support now so it's an improvement ;)

Thanks again!!

[heitorlessa]

Solved in todays release 1.25.0 🎉