Feature request: include error own properties in logged errors

[everett1992]

Expected Behaviour

I expect powertools to log all enumerable properties on an error. It's common to include a code, and extra information about an error. For example, node's fs errors include code, syscall and path. I'd like powertools to log

{
        "name": "Error",
        "location": "",
        "message": "ENOENT: no such file or directory, open 'not a file'",
        "stack": "Error: ENOENT: no such file or directory, open 'not a file'"
        "errno": -2,
        "code": "ENOENT",
        "syscall": "open",
        "path": "not a file"
}

If you log a regular object or classs it's properties will be logged, but if the class extends Error only stack, message, location, name, and cause will be logged.

Current Behaviour

logger does not log any of the errors enumerable properties

Code snippet

import fs from 'fs/promises'

import { Logger } from '@aws-lambda-powertools/logger'

class MyData {
  constructor(public readonly field: string) { }
}
class MyError extends Error {
  constructor(public readonly field: string) {
    super(field)
  }
}


const logger = new Logger();

// node's built in errors include code, syscall and other properties
// powertools doesn't include these when printing the error object.
await fs.readFile("not a file").catch(err => {
  logger.error("fs error", {
    bare: err,
    spread: { ...err },
    json: JSON.parse(JSON.stringify(err)),
  })
})

const myError = new MyError("field");
logger.error("fs error", {
  bare: myError,
  spread: { ...myError },
  json: JSON.parse(JSON.stringify(myError)),
})

const myData = new MyData("field");
logger.error("fs error", {
  bare: myData,
  spread: { ...myData },
  json: JSON.parse(JSON.stringify(myData)),
})

Logging an error thrown by node's built in fs module, see that bare, which is how most people would log an error, is missing errno, code, syscall, and path metadata.
spread, and json include the metadata, but not the stack trace, message, or location. spread and json show that these are enumerable properties on the object.

{
    "level": "ERROR",
    "message": "fs error",
    "service": "service_undefined",
    "timestamp": "2024-03-07T00:04:23.697Z",
    "bare": {
        "name": "Error",
        "location": "",
        "message": "ENOENT: no such file or directory, open 'not a file'",
        "stack": "Error: ENOENT: no such file or directory, open 'not a file'"
    },
    "spread": {
        "errno": -2,
        "code": "ENOENT",
        "syscall": "open",
        "path": "not a file"
    },
    "json": {
        "errno": -2,
        "code": "ENOENT",
        "syscall": "open",
        "path": "not a file"
    }
}

Here's a simple custom error and it has the same problem.

{
    "level": "ERROR",
    "message": "fs error",
    "service": "service_undefined",
    "timestamp": "2024-03-07T00:04:23.699Z",
    "bare": {
        "name": "Error",
        "location": "test.ts:27",
        "message": "field",
        "stack": "Error: field\n    at <anonymous> (test.ts:27:17)"
    },
    "spread": {
        "field": "field"
    },
    "json": {
        "field": "field"
    }
}

This is logging a normal class that doesn't extend Error and you can see that bare includes the properties I would expect.

{
    "level": "ERROR",
    "message": "fs error",
    "service": "service_undefined",
    "timestamp": "2024-03-07T00:04:23.701Z",
    "bare": {
        "field": "field"
    },
    "spread": {
        "field": "field"
    },
    "json": {
        "field": "field"
    }
}

Steps to Reproduce

The script included above reproduces with powertools 1.18.1 or 2.0.2 on node 20.

Possible Solution

Include enumerable properties by spreading the err object.

Powertools for AWS Lambda (TypeScript) version

2.0.2, 1.18.1

AWS Lambda function runtime

20.x

Packaging format used

npm

Execution logs

See above.

[dreamorosi]

Hi @everett1992, thanks for opening the issue.

The format that you described as a bug aligns with the one we specify in the docs.

We purposefully standardize the format of an error whenever encountering one during the parsing and normalize the structure to a common denominator.

With this in mind, the behavior you're seeing is not a bug.

All Error instances and derivatives are passed through the formatError() method present in the LogFormatter class.

Using a custom log formatter you can customize the format of the error by overriding the formatError() method to include all the info you need.

Here you have an example of how to use a custom log formatter.

At the moment we only expose the LogFormatter class, this means you'll have to also provide an implementation for the formatAttributes() method which is abstract. If you'd like us to expose the default PowertoolsLogFormatter so that you can use all the default settings while still being able to selectively override some aspects, please let me know and I'll include it in the next release.

[everett1992]

Where is it specified in the docs? I read that section but I don't see any claim that only location, stack, name, and message are logged. The examples may only have those fields, but the errors wouldn't have any extra fields.

I think 'field', or 'code', 'path', 'errno', 'syscall' should be logged along with the location, message, name and stack.

[leandrodamascena]

Hello everybody! I was reading this issue and thought it was important to give my impressions here as we added this same feature in Powertools Python recently.

Firstly, I must say that I agree that Powertools Typescript should add the same capability as Python, that is, in case of exceptions, create a specific field with the entire stack trace to ease discoveries when searching in respective logs. On the other hand, I think that we should not add fields that are not present in all exceptions, as we may incur an increase in the storage of client logs with information that may not be useful for that specific client and that is optional. I was reading the NodeJS errors documentation (https://nodejs.org/api/errors.html#class-systemerror) and saw that fields like address, path, and port are optional. In my opinion, the exception must add the mandatory fields and the customer can customize through a custom log, just as @dreamorosi showed in the example.

As additional context, I personally really like Sentry's exception-catching implementation, and in Python we try to follow the same stack trace format that they implement - of course removing fields that doesn't matter for us.
They don´t log some specific exception fields and you can enrich this by adding additional metadata to scope (custom format in our case).

Example

app.py

import sentry_sdk

sentry_sdk.init(
    dsn="....",
)

try:
    open("leo.txt")
except Exception as e:
    sentry_sdk.capture_exception(e)

log.json - no personal information was disclosed

{
    "event_id": "7b36ed6f32874c249e0574197cb23e43",
    "exception": {
        "values": [
            {
                "type": "FileNotFoundError",
                "value": "[Errno 2] No such file or directory: 'leo.txt'",
                "stacktrace": {
                    "frames": [
                        {
                            "function": "<module>",
                            "module": "__main__",
                            "filename": "leo.py",
                            "abs_path": "/home/leandro/DEVEL-PYTHON/tmp/sentry-error/leo.py",
                            "lineno": 19,
                            "pre_context": [
                                ")",
                                "",
                                "",
                                "",
                                "try:"
                            ],
                            "context_line": "    open(\"leo.txt\")",
                            "post_context": [
                                "except Exception as e:",
                                "    # Alternatively the argument can be omitted",
                                "    sentry_sdk.capture_exception(e)"
                            ],
                            "in_app": true,
                            "vars": {
                                "__annotations__": {},
                                "__builtins__": "<module 'builtins' (built-in)>",
                                "__cached__": "None",
                                "__doc__": "None",
                                "__file__": "'/home/leandro/DEVEL-PYTHON/tmp/sentry-error/leo.py'",
                                "__loader__": "<_frozen_importlib_external.SourceFileLoader object at 0x7f5112e8dc10>",
                                "__name__": "'__main__'",
                                "__package__": "None",
                                "__spec__": "None",
                                "sentry_sdk": "<module 'sentry_sdk' from '/home/leandro/DEVEL-PYTHON/tmp/sentry-error/.venv/lib/python3.9/site-packages/sentry_sdk/__init__.py'>"
                            }
                        }
                    ]
                },
                "mechanism": {
                    "type": "generic",
                    "handled": true,
                    "meta": {
                        "errno": {
                            "number": 2
                        }
                    }
                }
            }
        ]
    }

}

Thank you

[everett1992]

If you'd like us to expose the default PowertoolsLogFormatter so that you can use all the default settings while still being able to selectively override some aspects, please let me know and I'll include it in the next release.

That seems like a good compromise, but this still feels like an important feature or bug.

Here's examples from other loggers, they each include the error's properties.

-- powertools --------------------------------------------
{"level":"ERROR","message":"fs error","sampling_rate":0,"service":"service_undefined","timestamp":"2024-03-12T16:09:17.475Z","err":{"name":"Error","location":"","message":"ENOENT: no such file or directory, open 'not a file'","stack":"Error: ENOENT: no such file or directory, open 'not a file'"}}
-- winston -----------------------------------------------
{"err":{"code":"ENOENT","errno":-2,"path":"not a file","syscall":"open"},"level":"error","message":"fs error"}
-- bunyan ------------------------------------------------
{"name":"bunyan","hostname":"u0ac46b2ab35f52.ant.amazon.com","pid":44989,"level":50,"err":{"errno":-2,"code":"ENOENT","syscall":"open","path":"not a file"},"msg":"fs error","time":"2024-03-12T16:09:17.479Z","v":0}
-- pino --------------------------------------------------
{"level":50,"time":1710259757479,"pid":44989,"hostname":"u0ac46b2ab35f52.ant.amazon.com","err":{"type":"Error","message":"ENOENT: no such file or directory, open 'not a file'","stack":"Error: ENOENT: no such file or directory, open 'not a file'","errno":-2,"code":"ENOENT","syscall":"open","path":"not a file"},"msg":"fs error"}

[dreamorosi]

@heitorlessa would like to hear your opinion on this, thanks.

[bilalq]

This behavior is somewhat surprising. Most problematic however, is how it excludes the cause property of logged errors. https://developer.mozilla.org/en-US/docs/Web/JavaScript/Reference/Global_Objects/Error/cause

These have been standard since Node 16 (with feature flags) and the exclusion really hampers debugging.

A concrete example:

Let's say you're using powertools alongside the secretsmanager middy middleware. If permissions are not set on the KMS key or Secret resource to grant your lambda read/decrypt permissions, middy will throw an error with the following message: Failed to resolve internal values. It's opaque and that's all you'd see in the logs. However, we can see that middy actually sets the error cause property with more details.

Actual log observed (running on a local node process, so some lambda context values are not set):

{
    "cold_start": true,
    "function_memory_size": null,
    "level": "ERROR",
    "message": "example",
    "service": "service_undefined",
    "timestamp": "2024-05-10T09:28:17.412Z",
    "error": {
        "name": "Error",
        "location": "/Users/bilalq/example/node_modules/@middy/util/index.cjs:116",
        "message": "Failed to resolve internal values",
        "stack": "Error: Failed to resolve internal values\n    at getInternal (/Users/bilalq/example/node_modules/@middy/util/index.cjs:116:15)\n    at processTicksAndRejections (node:internal/process/task_queues:95:5)\n    at async secretsManagerMiddlewareBefore (/Users/bilalq/example/node_modules/@middy/secrets-manager/index.cjs:56:26)\n    at async runMiddlewares (/Users/bilalq/example/node_modules/@middy/core/index.cjs:126:21)\n    at async runRequest (/Users/bilalq/example/node_modules/@middy/core/index.cjs:86:9)"
    }
}

The cause property would show that the error was due to CredentialsProviderError and be much more useful.

Can we maybe at least get cause included in error logs?

[dreamorosi]

Hi @bilalq - which version of Logger are you using? We support the cause property unless there's a bug or it's being specified differently than what you linked:

[bilalq]

Ah, that was my mistake. Thanks for pointing it out. It seems that the service I was looking at happened to be on the 1.8.0 version of powertools. The latest version does indeed behave as expected with cause.

[dreamorosi]

Thanks for confirming - and also for reviving this thread.

I just wanted to share that I have not forgotten about this and I am going to try to have a final answer in the next few weeks. Since my initial comment I actually got bit by this myself trying to log a custom error I made and not seeing its properties.

I'm now leaning towards including them but I still want to get the alignment of other Powertools runtimes before moving forward.