How do I write Flask's excellent debug log message to a file in production?

Question

I have a Flask application that works well and produces an occasional error, which is visible when it is running with debug=True:

if __name__ == '__main__':
    app.run(debug=True)

I get useful error messages such as:

Traceback (most recent call last):
  File "./main.py", line 871, in index_route

KeyError: 'stateIIIII'

I would like to get error messages like these saved to a file when I run the application in production (using Lighttpd + fastcgi).

After looking at various StackOverflow questions (http://flask.pocoo.org/docs/errorhandling/, http://docs.python.org/2/library/logging.html, etc.); the Flask mailing list; and a few blogs, it seems there is no easy way just to send all the great error messages to a file - I need to use the Python logging module to customise things. So I came up with the following code.

At the top of my application file I have various imports followed by:

app = Flask(__name__)

if app.debug is not True:   
    import logging
    from logging.handlers import RotatingFileHandler
    file_handler = RotatingFileHandler('python.log', maxBytes=1024 * 1024 * 100, backupCount=20)
    file_handler.setLevel(logging.ERROR)
    app.logger.setLevel(logging.ERROR)
    app.logger.addHandler(file_handler)

I have then put the code for each route in a try/except statement and use traceback to work out which line the error came from and print a nice error message:

def some_route():
    try:
        # code for route in here (including a return statement)

    except:
        exc_type, exc_value, exc_traceback = sys.exc_info()
        app.logger.error(traceback.print_exception(exc_type, exc_value, exc_traceback, limit=2))
        return render_template('error.html')

And then right at the end of the file I remove the debug=True statement. Though I don't think I need to do that as the application is being run by a fastcgi server(?) when it is run in production. The last two lines of my application code look like this:

if __name__ == '__main__':
    app.run()

I am struggling to get this working. I think the best I have managed is to get a single error log message to be saved in the file using (app.logger.error('test message') ), but it only prints that one message. An attempt to log another error directly after that one is simply ignored.

Hybridize

See also: flask.pocoo.org/docs/0.12/errorhandling – Thun

Answer 1

I don't know why it's not working but I can tell how am doing this.

First of all, you don't need to set the level of app.logger. So remove this line app.logger.setLevel().

You want to save exception and return error page for every view. It is a lot of work to write this code everywhere. Flask provides a method to do this. Define an errorhandler method like this.

    @app.errorhandler(500)
    def internal_error(exception):
        app.logger.error(exception)
        return render_template('500.html'), 500

Whenever a view raises an exception, this method will be called and passed the exception as argument. Python logging provides exception method that is used to save full traceback of the exception.

Since this handles all exception, you don't even need to put code in try/except block. Though, if you want to do something before calling the errorhandler(for e.g. rollback session or transaction) then do this:

    try:
        #code
    except:
        #code
        raise

If you would like the date and time added for each entry in your log file, the following code can be used (in place of the similar code featured in the question).

if app.debug is not True:   
    import logging
    from logging.handlers import RotatingFileHandler
    file_handler = RotatingFileHandler('python.log', maxBytes=1024 * 1024 * 100, backupCount=20)
    file_handler.setLevel(logging.ERROR)
    formatter = logging.Formatter("%(asctime)s - %(name)s - %(levelname)s - %(message)s")
    file_handler.setFormatter(formatter)
    app.logger.addHandler(file_handler)

Pragmaticism

But the documentation seems to imply that flask will log exceptions automatically? the docs say, if you add a mail handler, you'll automatically get emailed if errors happen. So the @app.errorhandler shouldn't be necessary? – Selenodont

aha. figured it out. 400 errors (keyerrors on request.form) aren't logged as real exceptions by default, but 500s are. – Selenodont

Could you please talk about why the error level need not or should not be set? (app.logger.setLevel) – Subclavian

Save me hours of debugging :)! Kudos for the awesome explanation. – Semaphore

when I set the file_handler.setLevel(logging.INFO), it still only logs to warning level(root default). I had to set it to app.logger.setLevel(logging.INFO), it then starts logging info and above levels. Any idea why that's the case? – Bidden

If i were to use uwsgi ... where should I put my logs? What are the permission I should set for my log? Thanks! – Homopterous

"if app.debug is not True" should alway be "if not app.debug" </sermon> – Anglice

@Bidden Use app.logger.exception(exception) and the stacktrace will be record. – Caruso

I would note that the method decorated with @app.errorhandler(500) is not needed (writing as of Flask 0.12.1). By default, Flask will log all unhandled exceptions to your logger and your handler. If you add the method, it will work, you'll just get doubly logged exceptions by the default logger and the extra log you create with app.logger.error(exception). – Columbus

2020-01-29 20:04:05,456 - ds_app.ds_backend - ERROR - 2020-01-29 20:04:32,518 - ds_app.ds_backend - ERROR - 2020-01-29 20:04:33,674 - ds_app.ds_backend - ERROR - 2020-01-29 20:04:34,887 - ds_app.ds_backend - ERROR - 2020-01-29 20:04:36,022 - ds_app.ds_backend - ERROR - I followed above . Its capuring error but not passing the traceback the exception. Could you please help me with this? – Bondman

Answer 2

For those who read this later on.

I think it is better idea to push more useful info into error messages. URL, client IP, user-agent etc. Flask logs exceptions internally (in app.debug==False mode) with Flask.log_exception function. So, instead of logging things manually in @app.errorhandler I do something like this:

class MoarFlask(Flask):
    def log_exception(self, exc_info):
        """...description omitted..."""
        self.logger.error(
            """
Request:   {method} {path}
IP:        {ip}
User:      {user}
Agent:     {agent_platform} | {agent_browser} {agent_browser_version}
Raw Agent: {agent}
            """.format(
                method = request.method,
                path = request.path,
                ip = request.remote_addr,
                agent_platform = request.user_agent.platform,
                agent_browser = request.user_agent.browser,
                agent_browser_version = request.user_agent.version,
                agent = request.user_agent.string,
                user=user
            ), exc_info=exc_info
        )

Then, at configuration time, bind FileHandler to app.logger and go on. I don't use StreamHandler cause many servers (e.g. uWSGI) like to pollute it with their own proprietary-wordy-useless-not-turnable-off messages.

Don't be afraid of extending Flask. You'll be forced to do it sooner or later ;)

Janiecejanifer

Cool answer Ivan, looking to implement this myself! Could you possibly provide some more info on how you went about binding FileHandler to app.logger? I got your idea, I just don't see how you executed it :-) – Trigon

Sorry @Juxhih, I'd like to answer you, but last time I used Python was 2 years ago and I completely forgot that stuff. – Janiecejanifer

What a shame, would've loved to implement this as it's nice and concise. If you do happen to stumble upon the old code, please do let us (me) know – Trigon

Can you post this as a separate question that I could possibly answer? I need some time to find this in my archives and I'd like to get some karma bonus in return ;) – Janiecejanifer

I'll try to remember to add a post later on this evening :-) – Trigon

I'm really digging 'proprietary-wordy-useless-not-turnable-off' as a description of uWSGI errors! – Ratter

Juxhin , use the last code of the previos answer :) – Armet

just an fyi: the dedent function from textwrap could really help out your error template there. docs.python.org/2/library/textwrap.html#textwrap.dedent – Remissible

Answer 3

This is what I generally do when a service requires logging. I'm not a specialist on the subject, but these observations are something to take in consideration, in my humble opinion:

• at the beginning of every function (route), create a timestamp object, in order to registry the exact time when the request was made, independently if it was successful or not

• use @app.after_request, for registering every successful request

• use @app.errorhandler, for registering general errors + Tracebacks

Here is an example that demonstrates this idea:

#/usr/bin/python3
""" Demonstration of logging feature for a Flask App. """

from logging.handlers import RotatingFileHandler
from flask import Flask, request, jsonify
from time import strftime

__author__ = "@ivanleoncz"

import logging
import traceback


app = Flask(__name__)

@app.route("/")
@app.route("/index")
def get_index():
    """ Function for / and /index routes. """
    return "Welcome to Flask! "


@app.route("/data")
def get_data():
    """ Function for /data route. """
    data = {
            "Name":"Ivan Leon",
            "Occupation":"Software Developer",
            "Technologies":"[Python, Flask, JavaScript, Java, SQL]"
    }
    return jsonify(data)


@app.route("/error")
def get_nothing():
    """ Route for intentional error. """
    return foobar # intentional non-existent variable


@app.after_request
def after_request(response):
    """ Logging after every request. """
    # This avoids the duplication of registry in the log,
    # since that 500 is already logged via @app.errorhandler.
    if response.status_code != 500:
        ts = strftime('[%Y-%b-%d %H:%M]')
        logger.error('%s %s %s %s %s %s',
                      ts,
                      request.remote_addr,
                      request.method,
                      request.scheme,
                      request.full_path,
                      response.status)
    return response


@app.errorhandler(Exception)
def exceptions(e):
    """ Logging after every Exception. """
    ts = strftime('[%Y-%b-%d %H:%M]')
    tb = traceback.format_exc()
    logger.error('%s %s %s %s %s 5xx INTERNAL SERVER ERROR\n%s',
                  ts,
                  request.remote_addr,
                  request.method,
                  request.scheme,
                  request.full_path,
                  tb)
    return "Internal Server Error", 500


if __name__ == '__main__':
    handler = RotatingFileHandler('app.log', maxBytes=10000, backupCount=3)        
    logger = logging.getLogger(__name__)
    logger.setLevel(logging.ERROR)
    logger.addHandler(handler)
    app.run(host="127.0.0.1",port=8000)

For more information regarding logrotate and logs on stdout and file at the same time: this Gist

Miche

Wouldn't this log the error twice? Don't both the errorhandler and then after_request functions get called when an error occurs? @Miche – Vizier

Hi, Davi. Thanks for your question :). Well, I think so, because it generates a Traceback for the request which was registered, but let me check here. Tomorrow, I'll do my best to give an update for this answer, if I find anything better, but the core of the answer works fine: I have been using this until and works pretty well. Regards. – Miche

Thanks for the response! @Miche After some testing I think it does call both but I realized its not necessarily a bad thing because it is nice to have a record of all the requests made (in the same format). I the only thing I have changed is making the after_request use logger.info instead of logger.error (but if you aren't using any special formatting it doesn't really matter) – Vizier

Awesome, @EpicDavi! Yes, indeed is a good thing to have both. Anyway, I discovered another way to record requests into a log file, but it would be necessary (in my perspective) to have the @app.after_request decorator, because you can track special situations like general errors or Tracebacks. I'll make some tests here during the week and I'll provide an update for this response, in order to give another possibilities. Thanks for getting in touch and contributing :). Regards! – Miche

Answer 4

If you are using gunicorn to run your Flask app, you can log all Flask exceptions to the gunicorn logs by adding the gunicorn error handlers to the Flask logger:

In module/__init__.py:

@app.before_first_request
def setup_logging():
    if not app.debug:
        import logging
        gunicorn_logger = logging.getLogger('gunicorn.error')
        for handler in gunicorn_logger.handlers:
            app.logger.addHandler(handler)

Horgan

Answer 5

In Development, make sure to set: app.config['PROPAGATE_EXCEPTIONS'] = False. Default is None: https://flask.palletsprojects.com/en/1.1.x/config/

Killen