Feature (logger): pretty printing logs in local development

[krivachy]

Description of the feature request

Have the ability to pretty print log statements when running lambdas locally. This would make local development nicer.

Problem statement

The logger module always prints out JSON which is required for CloudWatch, but not a nice experience when running a lambda locally. It is hard to parse the JSON that is printed in a single line.

There is no way to override this via Logger options.

Summary of the feature

To solve this, I would propose an overridable logPrinter function that would default to JSON printing. The function would only be invoked if the log level will be outputted. The function would also be invoked after logFormatter has run.

This would allow users of the library to conditionally override the printer when running a lambda locally.

Code examples

The interface could look like this:

interface LogPrintterInterface {
    /**
     * it serializes the log attributes to a string to be printed out.
     *
     * @param {LogAttributesWithMessage} attributes
     * @returns {string}
     */
    printAttributes(attributes: LogAttributesWithMessage): string;
}

Usage could look like this:

const localPrinter = {
    printAttributes: (attributes: LogAttributesWithMessage) => `${attributes.logLevel} ${attributes.message}`
};
const log = new Logger({
  logPrinter: process.env.IS_LOCAL ? localPrinter : undefined
});

Benefits for you and the wider AWS community

This overridable config would allow users of the AWS community to develop various output formats, for example ones that colorize the console output.

Describe alternatives you've considered

Overriding the actually outputting to stdout, but most users of the library would just use the default console.log so overriding printing seemed like a better option.

Additional context

pino is a library that has pluggable prettification via pino-pretty:

const pino = require('pino')
const pretty = require('pino-pretty')
const logger = pino(pretty())

logger.info('hi')

Which then outputs logs that look like this:

Related issues, RFCs

[dreamorosi]

Hi @krivachy, thanks for opening an issue and proposing the feature.

I can see where you are coming from and what is the use case you're suggesting. I haven't formed an opinion on the topic yet though; the comments that follow are aimed at having an open discussion to evaluate options.

On one hand structured logging is one of the key features of this opinionated logger and optimising these libraries to run on AWS Lambda is a key part of our ethos. On the other hand, I think developer experience is also extremely important, and we have received a similar-ish request not so long ago; so we'll have to discuss this a bit more before making a decision.

In the meanwhile, and just to evaluate other options, what about having a behaviour similar to the one that Tracer has, which consists in Powertools Logger being able to detect it's not running on Lambda. In the case of Tracer, when running locally or inside SAM, we simply don't do traces, in the case of Logger we would pretty-print the JSON objects instead of emitting the string only.

I know this option doesn't cover colouring nor allows complete control over the output, but I'm inclined to think that giving such a big escape hatch (bring your own format) would kind of defeat the purpose of what we are trying to achieve, which, in the case of logger, is to foster the usage of best practices around structured logging and such.

[krivachy]

Thanks for your detailed response @dreamorosi. Having this lib a very opinionated logger makes sense.

Building in pretty printing would be a good solution, even if it doesn't support all of the fancy features that other pretty printers.

How would you detect if it's running in a lambda vs. not?

[dreamorosi]

How would you detect if it's running in a lambda vs. not?

The Tracer utility already does this (see here).

It basically consists of some heuristics logic around environment variables. For example, the AWS Lambda execution environment always sets an AWS_EXECUTION_ENV variable (source), while the sam CLI sets a AWS_SAM_LOCAL one when testing locally (source). If any of these variables is present in the environment then we assume that function is running locally.

[aleguern]

Wouldn't it be simpler to ask the client to add a pipe at the end of his command when developing on his local environment ? I come from pino and you can just pretty print your commands with | pino-pretty.

[dreamorosi]

A similar PR was filed for the Python version of Powertools: https://github.com/awslabs/aws-lambda-powertools-python/pull/1548

[saragerion]

We discussed it this internally among maintainers cross-languages and we came to the decision that we will implement a new environment variable that will enable among other things also printing pretty JSON in Logger. This way developers can decide to enable this functionality locally or in their dev environments if they wish.

If env var POWERTOOLS_DEV is present and set to 'true', the following happens:

Logger:

• pretty print JSON enabled

Tracer:

• traces are disabled

[krivachy]

Thanks @saragerion, that would work nicely! Looking forward to having a better local dev experience.

[saragerion]

@krivachy would you be so kind to leave your feedback in this RFC? https://github.com/awslabs/aws-lambda-powertools/issues/86

I'd love to hear your perspective and vision on the matter.

[dreamorosi]

Linking also this PR as reference: https://github.com/awslabs/aws-lambda-powertools-python/pull/1548

[shdq]

Hey, @dreamorosi, thanks for pointing out this issue. I want to work on this feature. I'll dive into the discussion and write a top-level plan here, then we will discuss it.

[dreamorosi]

@shdq great stuff, thanks for the bias for action. Please make sure to also read the RFC and PR that are linked in the last two comments.

That RFC mentions a new environment variable that, when used, influences the behavior of the logger (as well as other utilities). For now let's keep the changes related to logger and pretty-printing which interest this issue.

As per last time, if you have any question please let me know :)

[shdq]

Hey @dreamorosi. I hope you're doing well. I've been working on this feature and have some questions to ask.

According to RFC, the scope of this PR is basically to increase JSON.stringify indentation to 4 if the POWERTOOLS_DEV env variable has truthy (true or 1) value.

I implemented the feature and added tests. It works. I had to introduce this env variable because it wasn't used before. First of all, I have naming questions, I called the constant devModeVariable and the method getDevMode in ConfigService. I hope "devMode" is a readable and self-documented name that aligns with prototyping locally or against a non-production environment.

Second thing, I looked at the python implementation, they use PRETTY_INDENT and COMPACT_INDENT constants. I didn't find any common constants across packages in the codebase of this repo. So for now, I hardcoded a magic number 4 in the printLog() and in a test case which is bad. It's better to put it out somewhere. What do you think is the better place to put a constant for pretty indentation?

Maybe I went too far and added this "dev mode" as an option to the logger options like logLevel, logEvent, etc. It seems logical to add it there. setOptions configures the Logger instance settings that will affect the Logger's behaviour and the content of all logs. It seems like POWERTOOLS_DEV affect the content. It seems appropriate, but I'm not sure. I think it is better to look at the code. Maybe I create a PR and we will continue there?

And the last thing. Should I update the docs and add the same section like this? And also add POWERTOOLS_DEV here.

Let me know. All best, Sergei

[dreamorosi]

Hi @shdq, doing great and happy to hear from you.

Will reply below to each paragraph/topic :)

According to RFC, the scope of this PR is basically to increase JSON.stringify indentation to 4 if the POWERTOOLS_DEV env variable has truthy (true or 1) value.

Correct

I implemented the feature and added tests. It works. I had to introduce this env variable because it wasn't used before. First of all, I have naming questions, I called the constant devModeVariable and the method getDevMode in ConfigService. I hope "devMode" is a readable and self-documented name that aligns with prototyping locally or against a non-production environment.

I think the naming choices are sensible, but I'll be able to give a more definitive answer in the PR review. I trust that if we decide to change the name the impact won't be major. If that's not the case please let me know.

Second thing, I looked at the python implementation, they use PRETTY_INDENT and COMPACT_INDENT constants. I didn't find any common constants across packages in the codebase of this repo. So for now, I hardcoded a magic number 4 in the printLog() and in a test case which is bad. It's better to put it out somewhere. What do you think is the better place to put a constant for pretty indentation?

You're right in that we don't have an equivalent for these variables here. If I remember correctly their implementation the two variables are needed because they somewhat manually configure the indent based on the mode. In our case I think we could be fine with only one for PRETTY_INDENT or any other name that makes sense. In regards to where to put it, I would like to see a first implementation before weighing in.

Maybe I went too far and added this "dev mode" as an option to the logger options like logLevel, logEvent, etc. It seems logical to add it there. setOptions configures the Logger instance settings that will affect the Logger's behaviour and the content of all logs. It seems like POWERTOOLS_DEV affect the content. It seems appropriate, but I'm not sure. I think it is better to look at the code.

I do appreciate the bias for action here. I see where you're coming from and how by reading the setOptions this new setting could be seen as part of that statement. However in this specific case I'd be more inclined towards not having the setting in the constructor.

The reason for not having it there is that we would like customers to use this new POWERTOOLS_DEV setting only in development/test environments. By this logic, the setting was thought to be less intrusive as possible in the sense that customers should be able to run locally the same code they run in production However I'm not sure about exposing the setting - without changes - have logs being pretty-printed. With this in mind, having a constructor property could give the impression that customers have to explicitly enable/disable this in all environments and/or have to modify their code when testing/running locally. So I would leave this as an environment variable only for now.

And the last thing. Should I update the docs and add the same section like this? And also add POWERTOOLS_DEV here.

Yes, ideally if there's a change in the API it should be represented in the docs.

Maybe I create a PR and we will continue there?

Yes, definitely. I see that you've already put a lot of thought into the feature and based on the message above I think you're going in the right direction so I agree that the discussion would be better suited to continue while looking at the code.

Thank you again for the care & consideration you've put in the messages & changes.

[shdq]

The reason for not having it there is that we would like customers to use this new POWERTOOLS_DEV setting only in development/test environments. By this logic, the setting was thought to be less intrusive as possible in the sense that customers should be able to run locally the same code they run in production However I'm not sure about exposing the setting - without changes - have logs being pretty-printed. With this in mind, having a constructor property could give the impression that customers have to explicitly enable/disable this in all environments and/or have to modify their code when testing/running locally. So I would leave this as an environment variable only for now.

The first doubt about this was when other tests failed to pass because of the new config option. Next, when I was describing it here. Now I'm sure. Thank you for the clarification. I will revert the changes tied to the config and open a PR tomorrow.

[github-actions[bot]]

⚠️ COMMENT VISIBILITY WARNING ⚠️

Comments on closed issues 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.