Logging detailed information when Flask deals with exceptions

I use the Flask web development framework, written in Python, as the tool of choice for writing web applications. Its simple, lightweight, easy and well documented. It makes writing web applications a breeze – freeing me to write the important stuff.

Flask integrates into the Python API wherever possible and takes care of most things for you. When something goes badly wrong in your code Flask catches exceptions and sends them through Python’s logging framework. This is very useful – in addition to telling the user, Flask can be configured to send logging to a file and to e-mail, so I get to hear about it even if a user doesn’t report a fault. This is where tools like Sentry also fit in – although I don’t use them.

The problem is that default logging, whilst dumping a full stack trace, does not add any Flask or web-specific details. The log format only contains the default log record attributes:

Message type:       ERROR
Location:           /usr/lib/python2.6/site-packages/flask/app.py:1306
Module:             app
Function:           log_exception
Time:               2013-05-03 15:35:57,170
Logger Name:        bargate
Process ID:         1877

Message:

Exception on /login [POST]

The worst part of the above is the lack of relevant information, but also the fact that because the exception is handled by several wapper functions, the ‘Location’ and ‘Function’ and ‘Module’ parts are all irrelevant because they refer to the function dealing with the exception rather than where it was generated from.

Either way, I wanted to extend the log format (the emails generated) when exceptions occur. A thread on the Flask mailing list led me toward messing with subclassing parts of Python’s logging classes (as indicated by other developers), but this led me astray. After extensive reading of ‘logging’ and thinking about the problem in detail, I realised this was nonsense – there was no way to inject additional custom attributes into exception logs like that.

The way to do it is to inject custom data into a log with the “extra=” kwargs flag when calling “logger.error”. The problem of course is that code you write within Flask doesn’t (generally) call logger.error at all – Flask does this for you within app.log_exception. The solution then is deliciously simple – and a recommended way of using Flask – subclass Flask itself.

Thus I subclassed Flask like so:

class BargateFlask(Flask):
        def log_exception(self, exc_info):
                """Logs an exception.  This is called by :meth:`handle_exception`
                if debugging is disabled and right before the handler is called.
                This implementation logs the exception as error on the
                :attr:`logger` but sends extra information such as the remote IP
                address, the username, etc.

                .. versionadded:: 0.8
                """

                if 'username' in session:
                        usr = session['username']
                else:
                        usr = 'Not logged in'

                self.logger.error("""Path:                 %s 
HTTP Method:          %s
Client IP Address:    %s
User Agent:           %s
User Platform:        %s
User Browser:         %s
User Browser Version: %s
Username:             %s
""" % (
                        request.path,
                        request.method,
                        request.remote_addr,
                        request.user_agent.string,
                        request.user_agent.platform,
                        request.user_agent.browser,
                        request.user_agent.version,
                        usr,

                ), exc_info=exc_info)

In the above example I decided not to use the extra kwargs flag and modify the Formatter object when setting up e-mail alerts as that would mean every call to app.logger.error would require me to send the same extra= flags. Instead I added the information I wanted via the message parameter (which achieves the same end result). This way, error e-mails are much more useful:

A fatal error occured in Bargate.

Message type:       ERROR
Location:           /data/fwa/bargate/__init__.py:104
Module:             __init__
Function:           log_exception
Time:               2013-05-05 09:43:59,942
Logger Name:        bargate
Process ID:         12141

Further Details:

Path:                 / 
HTTP Method:          POST
Client IP Address:    152.78.130.147
User Agent:           Wget/1.11.4 Red Hat modified
User Platform:        None
User Browser:         None
User Browser Version: None
Username:             Not logged in