Feature request: Simplified logger formatter when in AWS SAM Local

[pmarko1711]

Use case

I use aws_lambda_powertools.Logger which works very nicely when looking at logs in Cloudwatch.
Nevertheless, when testing/debugging lambda functions using AWS SAM local invoke, I find the json representation difficult to read and cluttering the console too much.

I know I can swap the logger, or use a custom formatter. But would it not be meaningful to include a simple formatter (instead of the LambdaPowertoolsFormatter that prints out jsons) and use it automatically when not really in Lambda (but e.g. in AWS SAM local invoke) ?

Related issue: #409

Note:

• Strictly speaking this request might breach your tenet 1 ("AWS Lambda only"), but it depends where you place AWS SAM local invoke or development & testing of Lambda functions outside Lambda

Solution/User Experience

• Add a "simple" formatter that would print a single line, without serializing to json
  • optionally with a custom format
• With that, use the existing json formatter only when really in Lambda
  • or alternatively, use the simple one when in AWS SAM Local (and similar, if it can be detected).
  • or make it easy to swap, by e.g. an envvar

Alternative solutions

There exists a solution already and that is to use a custom formatter. 

I opened the issue to consider building this in thinking that it might be beneficial for more users developing and testing Lambda functions.

Acknowledgment

• This feature request meets Lambda Powertools Tenets
• Should this be considered in other Lambda Powertools languages? i.e. Java, TypeScript

[boring-cyborg]

Thanks for opening your first issue here! We'll come back to you as soon as we can.
In the meantime, check out the #python channel on our AWS Lambda Powertools Discord: Invite link

[heitorlessa]

Hey @pmarko1711, thanks a lot for taking the time to help us improve! Would you have the output handy to make it easier to reason the next steps?

I need to spin up a project to test. I can't remember if it's an one line JSON (cost optimization), or indented -- would it be more helpful to have indented JSON when running locally if that's not the case yet?

My initial concern: transparently swapping for a no JSON output could lead to incorrect assumptions how the final output would be when deployed.

Look forward to hearing from you

[heitorlessa]

Example

Demonstrating how it could look like without any code change.

Before

sam local invoke     
Invoking app.lambda_handler (python3.9)
Skip pulling image and use local one: public.ecr.aws/sam/emulation-python3.9:rapid-1.56.1-x86_64.

Mounting /Users/lessa/DEV/pt-issue-1527/.aws-sam/build/HelloWorldFunction as /var/task:ro,delegated inside runtime container
START RequestId: ea90d758-5a78-4777-9c46-2017b472fc08 Version: $LATEST
{"level": "INFO", "location": "lambda_handler:39", "message": "This should appear indented and not compacted into a single line...", "timestamp": "2022-09-26 09:03:38,349+0000", "service": "issue-1527"}
END RequestId: ea90d758-5a78-4777-9c46-2017b472fc08
{"statusCode": 200, "body": "{\"message\": \"hello world\"}"}REPORT RequestId: ea90d758-5a78-4777-9c46-2017b472fc08     Init Duration: 1.39 ms  Duration: 1141.96 msBilled Duration: 1142 ms Memory Size: 128 MB     Max Memory Used: 128 MB

After

> sam local invoke
Invoking app.lambda_handler (python3.9)
Skip pulling image and use local one: public.ecr.aws/sam/emulation-python3.9:rapid-1.56.1-x86_64.

Mounting /Users/lessa/DEV/pt-issue-1527/.aws-sam/build/HelloWorldFunction as /var/task:ro,delegated inside runtime container
START RequestId: 9d9eeaaa-6a1f-4355-ac3a-dc20da33f1c6 Version: $LATEST
{
    "level": "INFO",
    "location": "lambda_handler:39",
    "message": "This should appear indented and not compacted into a single line...",
    "timestamp": "2022-09-26 09:02:05,262+0000",
    "service": "issue-1527"
}
END RequestId: 9d9eeaaa-6a1f-4355-ac3a-dc20da33f1c6
REPORT RequestId: 9d9eeaaa-6a1f-4355-ac3a-dc20da33f1c6  Init Duration: 1.04 ms  Duration: 1120.49 ms    Billed Duration: 1121 ms        Memory Size: 128 MB     Max Memory Used: 128 MB
{"statusCode": 200, "body": "{\"message\": \"hello world\"}"}%

[pmarko1711]

Thanks for coming back to be, @heitorlessa .

Right now the output is in this format:

{"level":"INFO","location":"functionB:615","message":"Soemthing happening here","timestamp":"2022-09-26 09:16:26,735+0000","service":"ABC"}
{"level":"INFO","location":"send_message_to_queue:563","message":"{'MessageAttributes': {'somekey1': {'StringValue': 'ABC', 'DataType': 'String'}}, 'MessageBody': '{\"somekey2\": \"someval2\", \"somekey3\": \"true\"}'}","timestamp":"2022-09-26 09:16:26,733+0000","service":"ABC"}
{"level":"INFO","location":"lambda_handler:98","message":"Something else happening here","timestamp":"2022-09-26 09:16:26,735+0000","service":"ABC"}
{"level":"INFO","location":"_functionB:185","message":"Another thing here","timestamp":"2022-09-26 09:16:26,735+0000","service":"ABC"}
{"level":"INFO","location":"_functionC:401","message":"And finally, this happened","timestamp":"2022-09-26 09:16:26,736+0000","service":"ABC"}

In here it looks quite OK, but imagine these messages to be quite longer and auto-wrapped into multiple rows. It's then not that easy to find and read the actual messages while debugging.

When I submitted the ticket I thought of simply outputting (when in AWS SAM Local) something more condensed, where message would be easier to find (since it'd be normally the last item in each row), e.g.:

2022-09-26 09:16:26,735+0000|INFO|ABC|functionB:615|Soemthing happening here
2022-09-26 09:16:26,733+0000|DEBUG|ABC|send_messages_to_queue:563|{'MessageAttributes': {'somekey1': {'StringValue': 'ABC', 'DataType': 'String'}}, 'MessageBody': '{\"somekey2\": \"someval2\", \"somekey3\": \"true\"}'}
2022-09-26 09:16:26,735+0000|WARNING|ABC|lambda_handler:98|Something else happening here
2022-09-26 09:16:26,735+0000|INFO|ABC|_functionB:185|Another thing here
2022-09-26 09:16:26,736+0000|INFO|ABC|_functionC:401|And finally, this happened

For now I've achieved this by initializing a logger with a custom formatter that conditionally overwrote the inherited serialize() method. So in Lambda I get the jsons, but in AWS SAM Local only a more plain output. I guess that's a bit dirty, but still, see (*) below. I thought of embedding something similar into the LambdaPowertoolsFormatter to do this either automatically or on request. If one went this route, it'd be nice if there was a default, concise format that one could override (something along format parameter of Python's logging).

Nevertheless, your idea of indenting JSON outputs could be sufficient here. Maybe making use of pprint then? Wouldn't however having multi-line messages cause more issues elsewhere? (it seems a bit non-standard)

(*)

import os
from aws_lambda_powertools.logging.formatter import LambdaPowertoolsFormatter

AWS_SAM_LOCAL = os.getenv("AWS_SAM_LOCAL", "false").lower() == "true"

class MyCustomFormatter(LambdaPowertoolsFormatter):
    def serialize(self, log: dict) -> str:
        """Use serialize"""
        if AWS_SAM_LOCAL:
            # https://awslabs.github.io/aws-lambda-powertools-python/latest/core/logger/#standard-structured-keys
            prefix = "|".join(
                [
                    log[k]
                    for k in ["timestamp", "level", "service", "location"]
                    if k in log
                ]
            )
            suffix = f"\n{log['exception']}" if "exception" in log else ""
            return "{}: {}{}".format(prefix, log.get("message", ""), suffix)
        else:
            return super().serialize(log)

logger = Logger(service="ABC", logger_formatter=MyCustomFormatter())

[heitorlessa]

On Mobile so excuse formatting and briefness

For JSON multi-line, stdlib "json" has an indent param which is what I used for this POC - it's a no brainer to enable it for local dev ;-)

pprint however could skew results as you have nested objects (plus multiple conversions).

My main worry about plain text is setting the expectations to customers who would see different results in CloudWatch Logs (or elsewhere) -- we have a distinct set of customers persona (dev, Data engineers, Ops, InfoSec) so we always take that into account.

If JSON multi-line suffices for you, we could make this available in the next release!

I could either guide you where to make changes (formatter.py) so we can credit you in the release notes, or if you don't have the bandwidth I can make it later this week.

Once I get my laptop tomorrow,
I'd like to dig on your good comment on "format" method - I'm all for making it easier for customers... and we use standard logging so that's a plus

[pmarko1711]

Thanks. Ok, and happy to do add it myself so that I get familiar with your contribute process (and can contribute with sthg else in the future)

[pmarko1711]

should it get activated automatically (looking at AWS_SAM_LOCAL) or via a parameter / or a new envvar?

[heitorlessa]

Awesome! Let’s use AWS_SAM_LOCAL - if it’s present use a different indentation (4) otherwise None

…

On Tue, 27 Sep 2022 at 18:17, Peter Marko ***@***.***> wrote: should it get activated automatically (looking at AWS_SAM_LOCAL) or via a parameter / or a new envvar? — Reply to this email directly, view it on GitHub <#1527 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAZPQBCNHPNLFO577H3IQDTWAMMY5ANCNFSM6AAAAAAQRFESSI> . You are receiving this because you were mentioned.Message ID: ***@***.***>

[github-actions]

This is now released under 1.30.0 version!