Log all exceptions

[adriangb]

I'd like to log all exceptions, including falcon exceptions.

I made a catch-all handler:

def catchall_handler(req, resp, ex, params):
    logger.error("Exception handled by catchall_handler", exc_info=ex)
    raise ex

But the way handler resolution is set up, the most specific Exception subclass is chosen. Which means that in order to log falcon.HTTPError I have to do this:

api.add_error_handler(Exception, catchall_handler)  # catches non-falcon exceptions
api.add_error_handler(falcon.HTTPError, catchall_handler)  # override the default handler

Which works, but is a bit janky. Is there any way to log falcon.HTTPError exceptions without overriding the default handler?

Thanks

[CaselIT]

Hi,

If you just want to log them and otherwise let the default error handler create the response, I think at the moment the best options may be to override the _handle_exception method to log the exception and then call the super implementation https://github.com/falconry/falcon/blob/e255bff9ae5a90d0cb3fe9af7c16917f18a92dc3/falcon/app.py#L1004-L1038

[adriangb]

Overriding a private method of the App class seems like an even worse solution than https://github.com/falconry/falcon/issues/1942#issue-959347522. Maybe the default exception handler could be made public such that it can be wrapped and overriden in a less hacky way.

Is exc_info somehow propagated with the response, such that I could do this in Middleware? (otherwise I loose the traceback info, even if I could filter by status code)

[CaselIT]

I agree that's not optional.

What is your use case? Do you just wanted to log the exception and retain the default handlers?

[adriangb]

Yes, exactly. I just want to log the exceptions, I don't want to do anything else with them. As far as I can tell, Falcon does not log them.

Modifying the server's (in my case Gunicorn) loggers is not an option because:

1. Once Falcon's exception handlers run exc_info is lost.
2. I have a logging filter that injects trace / context IDs into log statements, but it depends on a Falcon middleware that sets/resets a ContextVar (and thus there is no context info anymore once the response hits the WSGI server).

[vytas7]

Hi @adriangb ! Reraising an instance of HTTPError is currently the recommended way, albeit probably slightly inelegant for your use case.

OTOH, do you really need to pass the exception object? I think Python's logging is able to extract the last exception automatically, if you pass exc_info=True, or simply use .exception(...) to log. Which means you should be able to log from middleware too (?)

I've hacked together the following prototype using the reraising approach:

import logging

import falcon

logging.basicConfig(format='%(asctime)-15s [%(levelname)s] %(message)s')

def handle_uncaught_exception(req, resp, ex, params):
    logging.exception('Unhandled error')
    raise falcon.HTTPInternalServerError(title='App error')

def handle_http_error(req, resp, ex, params):
    logging.exception('HTTP error')
    raise ex

class FaultyResource:
    def on_get(self, req, resp):
        0 / 0

app = falcon.App()
app.add_error_handler(falcon.HTTPError, handle_http_error)
app.add_error_handler(Exception, handle_uncaught_exception)

app.add_route('/fault', FaultyResource())

[adriangb]

Hey @vytas7, thanks for the quick response!

Python's logging is able to extract the last exception automatically

Yes, but only if you are within a try/catch block (i.e. if you can call sys.exc_info() or something like that). In this case, I guess this is happening within a try/except block, but I can't know that without looking at Falcon's source code, and it's an implementation detail. Thus, to avoid confusing other devs and relying on an implementation detail, I'm consciously choosing the safer route of explicitly passing the exc object to exc_info. Explicit is better than implicit

I've hacked together the following prototype using the reraising approach

That's very similar to what I ended up with. Thank you for confirming that this is the best approach, I'll move forward with it.

[adriangb]

@vytas7 is there any reason not to add a logging.exception to the default error handlers? Worst case is that if someone like me already set up their own logging handling, they'll get duplicate logs (which is not a huge deal).

[vytas7]

I think we already have something like that for the generic Exception handler. As to other errors like 404, it might be a performance issue / unexpected bulk spam if the said path is hit often.

That said, I think we should reopen this issue, at least in terms of documentation/recipes. It's not an unreasonable request to be able to log all errors.

[CaselIT]

Yes, the default generic error logger does log to req.log_error but depending on the server it might not be configured

[adriangb]

Related to this, over in https://github.com/open-telemetry/opentelemetry-python-contrib/pull/644 we realized that exc_info from within a middleware response handler now returns None. Two options I can think of:

1. Execute the middleware within the context (that is, the except clause) that caught the exception.
2. Make the default error handler public so that a custom error handler can grab the exception info, bind it to the response and then delegate to the default error handler.

Option (2) I think also resolves this issue, which is why I think it's relevant.

[vytas7]

See also https://github.com/snapADDY/elastic-apm-falcon/issues/1 by @benedikt-budig and @severinsimmler, which could also make use of this functionality if added in some form.