Feature request: POWERTOOLS_DEV=1 should pretty print stack traces

[everett1992]

Use case

import { Logger } from '@aws-lambda-powertools/logger'
const err = new Error('message')
console.log(err)
new Logger().error("err", err)

Compare native node formatting, with clear new line and indentation, to powertools

POWERTOOLS_DEV=1 node test.mjs
Error: message
    at file://test.mjs:2:13
    at ModuleJob.run (node:internal/modules/esm/module_job:193:25)
    at async Promise.all (index 0)
    at async ESMLoader.import (node:internal/modules/esm/loader:530:24)
    at async loadESM (node:internal/process/esm_loader:91:5)
    at async handleMainPromise (node:internal/modules/run_main:65:12)

{
    "level": "ERROR",
    "message": "err",
    "service": "service_undefined",
    "timestamp": "2023-03-09T19:29:41.087Z",
    "error": {
        "name": "Error",
        "location": "node:internal/modules/esm/module_job:193",
        "message": "message",
        "stack": "Error: message\n    at file://test.mjs:2:13\n    at ModuleJob.run (node:internal/modules/esm/module_job:193:25)\n    at async Promise.all (index 0)\n    at async ESMLoader.import (node:internal/modules/esm/loader:530:24)\n    at async loadESM (node:internal/process/esm_loader:91:5)\n    at async handleMainPromise (node:internal/modules/run_main:65:12)"
    }
}

Solution/User Experience

Powertools should print the stack trace similarly to native node.

Alternative solutions

I understand that may not be possible with JSON output. As an alternative powertools could provide a non-json, terminal-focused, formatter for development.

Im not sure if that meets the tenents

> AWS Lambda only. We optimise for AWS Lambda function environments and supported runtimes only. Utilities might work with web frameworks and non-Lambda environments, though they are not officially supported.

Acknowledgment

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

Future readers

Please react with 👍 and your use case to help us understand customer demand.

[dreamorosi]

Hi @everett1992, thank you for taking the time to open this issue.

As a developer I see the value of having a clearly readable stack trace, and I agree that the one currently being output doesn't fit this description.

With that said, I'm not sure whether it's possible to apply multi-line formatting to JSON values and as you already touched, removing the JSON structure would go against the main value proposition of the utility and tenets.

I need to actually test this and dive deeper into the current implementation, but I think we could evaluate the option of breaking the lines of the stack traces into an array of strings, which once pretty-printed would look like this:

{
    "level": "ERROR",
    "message": "err",
    "service": "service_undefined",
    "timestamp": "2023-03-09T19:29:41.087Z",
    "error": {
        "name": "Error",
        "location": "node:internal/modules/esm/module_job:193",
        "message": "message",
        "stack": [
            "Error: message",
            "at file://test.mjs:2:13",
            "at ModuleJob.run (node:internal/modules/esm/module_job:193:25)",
            "at async Promise.all (index 0)",
            "at async ESMLoader.import (node:internal/modules/esm/loader:530:24)",
            "at async loadESM (node:internal/process/esm_loader:91:5)",
            "at async handleMainPromise (node:internal/modules/run_main:65:12)"
        ]
    }
}

This type of behavior would be enabled only when POWERTOOLS_DEV is set to true | 1 like your proposal.

I realize that this is not exactly what you proposed, but I think it could be a reasonable middle ground that can provide a good readability while maintaining the ethos of the utility.

What do you/people think?

[everett1992]

Totally acceptable solution to me, tho it does change the schema of the json record, and would change how logs are stored in cloudwatch if POWERTOOLS_DEV=1 was used in lambda.

What about the option to log with a terminal friendly format in development?

[dreamorosi]

Hi Caleb, I see your point and the and I'm still on the fence about this.

I would like to gather some additional feedback from the community about the feature to understand how many people use the logger library locally.

Let's keep this open and revisit this sometime soon.

[quintinchris]

definitely +1 this feature. i work with a relatively large team of developers that run and test api gateways and lambdas locally (now utilizing the powertools logger), and it would be a huge benefit to have the logs be pretty printed when running locally.

as a suggestion, maybe this should be done automatically if running in a local environment? not sure how many consumers use SAM, but you can check if you're running on SAM local via the AWS_SAM_LOCAL env variable. with this approach there would be no need to change how logs are stored in cloudwatch, as you could be confident this would only occur locally

[dreamorosi]

it would be a huge benefit to have the logs be pretty printed when running locally.

Hi @quintinchris, just to clarify: you can already pretty print logs by setting the POWERTOOLS_DEV environment variable, this issue proposes extending the behavior to stack traces, that are currently logged as they are emitted.

[StianHanssen]

Just adding to this, that also for those using the serverless framework, it is very common to test the lambda locally first via serverless invoke local.

Myself and a colleague had a very similar conversation on the python side of the library. There we came to a nice resolution where there is customizability to have a different local logger, that behaves like a typical local logger (non-json). The thread can be found here: aws-powertools/powertools-lambda-python#409

[ConnorKirk]

I think that splitting the stack string into an array would be the simplest way to solve the immediate problem that the stack trace is not very easy to read. This doesn't quite match the python logger implementation and would leave a small parity gap. It is possible to get parity with python, but would perhaps be overkill.

By default, the Python Powertools Logger serialises the stack trace into an object, notably containing an array of the stack frames. They use some custom logic - _serialise_stacktrace to create the object. This occurs regardless of whether POWERTOOLS_DEV is set. This can be disabled by setting serialize_stacktrace=False in the logger config.

This allows the JSON object to contain the stack trace as an object with an array of frame objects, like this

// https://docs.powertools.aws.dev/lambda/python/latest/core/logger/#stack-trace-logging
{
    "level":"ERROR",
    // ..snipped
    "exception_name":"HTTPError",
    "stack_trace":{
       "type":"HTTPError",
       "value":"500 Server Error: INTERNAL SERVER ERROR for url: http://httpbin.org/status/500",
       "module":"requests.exceptions",
       "frames":[
          {
             "file":"/var/task/app.py",
             "line":14,
             "function":"lambda_handler",
             "statement":"ret.raise_for_status()"
          },
          {
             "file":"/var/task/requests/models.py",
             "line":1021,
             "function":"raise_for_status",
             "statement":"raise HTTPError(http_error_msg, response=self)"
          }
       ]
    }
 }

An analagous implementation in Typescript would be to parse the stack trace string into an array of call site objects.

There isn't a built in method to do this (yet), but there are multiple examples of libraries to do this node-stack-trace, stacktrace.js. (But adding a third party dependency for this is unwarrented)

We could write a basic parser ourselves, but it would add complexity, and doesn't solve the described problem better than just splitting the strings on the newlines.

There is work to standardise the stack spec, which would provide a native way to get the stacktrace as an object. This seems a long time away.. tc-39 proposal-errror-stacks

• Is it acceptable to output an array of strings rather than an array of call site objects?
• Should this be the default behaviour of the logger? Should it be configurable either using POWERTOOLS_DEV or the logger config itself?

[dreamorosi]

Hi @ConnorKirk, thank you for the investigation and assessment.

I am not inclined to adopt some non-standard parsing of the call sites and instead I'd rather keep things simple, at least for this first iteration. The TC39 proposal is promising but as you mentioned is most likely some time away since it recently got to Stage 2 (of 4).

Customers can already/still extend the LogFormatter class and customize how the formatErrror method behaves, so instead of adopting a 3rd party formatting now and potentially migrate to the standard one if/once the TC39 proposal moves to Stage 3.

I've been going back and forth on this for months now, and I have come to the conclusion that for now the only use case for this to be split into an array of strings is during development as this is essentially part of the pretty-print feature (so it should be behind POWERTOOLS_DEV).

When running in production, at least until we're able to create actual frames with the proposal, splitting the stack traces into a list of strings actually makes it harder to parse since you now don't know at which index the issue you're looking for is.

Because of this, and also to make things backwards compatible, I'd say let's add it behind POWERTOOLS_DEV, even if it deviates from the Python implementation. Once the language evolves we'll revisit and hopefully get closer to that feature.

[ConnorKirk]

Makes sense.

If it's ok for you, I intend update the formatError method in LogFormatter.ts to split the string on if dev mode is enabled. I think this achieves the goal.

[dreamorosi]

Sure, go ahead. Thanks!