Bug: Allow reporting entry logs with custom exception and exception_name

[iago1460]

Expected Behaviour

Due to internal logic exception and exception_name always get overridden.

The following statement should serialize the values provided:

logger.info("Report", extra={"exception": "Oops!  That was not valid", "exception_name": "ValueError" })

logger.append_keys(exception="Oops!  That was not valid", exception_name="ValueError")
logger.info("Report")

and produce an output like:

{
        "level": "INFO",
        "message": "Report",
        "exception": "Oops!  That was not valid",
        "exception_name": "ValueError",
}

Current Behaviour

Due to internal logic these field get overridden with None:

{
        "level": "INFO",
        "message": "Report"
}

Code snippet

from aws_lambda_powertools import Logger

logger = Logger()

logger.info("Report", extra={"exception": "Oops!  That was not valid", "exception_name": "ValueError"})

Possible Solution

Checking if these fields already exist on the formatted_log instead of always calling _extract_log_exception would fix this issue.

Steps to Reproduce

See code snippet section

AWS Lambda Powertools for Python version

latest

AWS Lambda function runtime

3.9

Packaging format used

PyPi

Debugging logs

No response

[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

[leandrodamascena]

Hello @iago1460! Thank you for opening this issue! Indeed, you're right, the code always override this extra information provided (extra={"exception": "Oops! That was not valid", "exception_name": "ValueError" }), because it expects to extract exception and exception_name fields of an exception. Just for context, we have an example explaining how to log an exception. In my opinion, I don't think this is a bug, it's more of an opinionated use for this utility.

On the other hand, we love to hear from our customers about their use cases and needs and I'm very curious to know in which situation adding exception fields in a log with INFO level can be useful. One thing I wondered here was this case where you have a decorator/class to catch all exceptions and log them. We have a utility called middleware_factory and I create code to simulate a hypothetical situation .

from aws_lambda_powertools import Logger
from aws_lambda_powertools.utilities.typing import LambdaContext
from aws_lambda_powertools.middleware_factory import lambda_handler_decorator

logger = Logger()

@lambda_handler_decorator
def catch_all_error(handler, event, context):
    try:
        response = handler(event, context)
    except Exception as exc:
        # Catching all exceptions in a Lambda execution
        exception_type = type(exc).__name__
        exception_value = exc
        #logger.info(f"TYPE - {exception_type}...  ERROR: {exception_value}") 
        logger.info("Report", extra={"exception": exception_value, "exception_name": exception_type })


@catch_all_error # Middleware Factory Function
def lambda_handler(event: dict, context: LambdaContext) -> str:
    print(event.KEYNOEXISTS)

But in my opinion even in this case the exception fields can be automatically logged using the logger.exception level, like the example below

from aws_lambda_powertools import Logger
from aws_lambda_powertools.utilities.typing import LambdaContext
from aws_lambda_powertools.middleware_factory import lambda_handler_decorator

logger = Logger()

@lambda_handler_decorator
def catch_all_error(handler, event, context):
    try:
        response = handler(event, context)
    except Exception as exc:
        # Catching all exceptions in a Lambda execution and logging using logger.exception
        logger.exception("Report")


@catch_all_error # Middleware Factory Function
def lambda_handler(event: dict, context: LambdaContext) -> str:
    print(event.KEYNOEXISTS)

Thank you and let me know if I'm missing something.

[iago1460]

Hi @leandrodamascena, thanks for your detailed explanation. Let me expand our user case in more detail:

import functools
import traceback

from aws_lambda_powertools import Logger
from aws_lambda_powertools.event_handler.exceptions import ServiceError

from st_autosuggest.utils import APIGatewayResolver

summary_logger = Logger(service="execution_summary")
app = APIGatewayResolver()


class ExpectedException(Exception):
    pass


def log_lambda_request(logger=summary_logger):
    def actual_decorator(func):
        @functools.wraps(func)
        def wrapper(event, context):
            try:
                output = func(event, context)
            except Exception:
                logger.exception("Unhandled error")
                raise
            else:
                logger.append_keys(status_code=output["statusCode"])
                logger.info("Request processed")
                return output

        return wrapper

    return actual_decorator


@app.exception_handler(ExpectedException)
def handle_value_error(ex: ExpectedException):
    summary_logger.append_keys(
        exception_name=str(ex.__class__.__name__),
        exception="".join(
            traceback.format_exception(type(ex), ex, ex.__traceback__)
        ),
    )
    raise ServiceError(status_code=503, msg=f"Expected exception happened: {ex}")


@app.get(".+")
def my_view():
    raise ExpectedException()
    # raise ValueError()
    return {'result': 'Test'}


@summary_logger.inject_lambda_context(clear_state=True)
@log_lambda_request()
def lambda_handler(event, context):
    return app.resolve(event, context)

The idea is to log a unique entry per request, to measure some custom metrics, like for example execution time.

The problem we face is that app.exception_handler catches the expected exception but we would like to output it as well as a different error level to distinguish it from an unexpected exception

[leandrodamascena]

Hello @iago1460, thank you very much for the explanation! In fact, it makes sense to check if these keys exist in the logger instance and not try to replace them every time.
Do you have the bandwidth to send a PR with this change? It can be awesome to have your PR approved and given credit to you. Don't worry if you can't, just let me know and I can do this.

BTW, I might suggest you use our Middleware Factory utility. It provides a decorator factory to create your own middleware to run logic before, and after each Lambda invocation synchronously. I refactored your code to use this utility and reduced the number of lines of code.

import functools
import traceback

from aws_lambda_powertools import Logger
from aws_lambda_powertools.event_handler.exceptions import ServiceError

from aws_lambda_powertools.event_handler.api_gateway import ApiGatewayResolver
from aws_lambda_powertools.middleware_factory import lambda_handler_decorator


logger = Logger(service="execution_summary")
app = ApiGatewayResolver()


class ExpectedException(Exception):
    pass

@lambda_handler_decorator
def catch_all_error(handler, event, context, logger):
    try:
        response = handler(event, context)
    except Exception:
        logger.exception("Unhandled error")
        raise
    else:
        logger.append_keys(status_code=response["statusCode"])
        logger.info("Request processed")
        return response


@app.exception_handler(ExpectedException)
def handle_value_error(ex: ExpectedException):
    logger.append_keys(
        exception_name=str(ex.__class__.__name__),
        exception="".join(
            traceback.format_exception(type(ex), ex, ex.__traceback__)
        ),
    )
    raise ServiceError(status_code=503, msg=f"Expected exception happened: {ex}")


@app.get(".+")
def my_view():
    raise ExpectedException()
    #raise ValueError()
    return {'result': 'Test'}


@logger.inject_lambda_context(clear_state=True)
@catch_all_error(logger=logger)
def lambda_handler(event, context):
    return app.resolve(event, context)

Thank you

[iago1460]

Hi @leandrodamascena, happy to provide a PR with this change.

Also thanks for suggesting the Middleware Factory utility.

[github-actions]

This is now released under 2.9.0 version!

[github-actions]

This is now released under 2.25.1 version!