Why is Flask application not creating any logs when hosted by Gunicorn?

Question

I'm trying to add logging to a web application which uses Flask.

When hosted using the built-in server (i.e. python3 server.py), logging works. When hosted using Gunicorn, the log file is not created.

The simplest code which reproduces the problem is this one:

#!/usr/bin/env python

import logging
from flask import Flask
flaskApp = Flask(__name__)


@flaskApp.route('/')
def index():
    flaskApp.logger.info('Log message')
    print('Direct output')
    return 'Hello World\n'


if __name__ == "__main__":
    logHandler = logging.FileHandler('/var/log/demo/app.log')
    logHandler.setLevel(logging.INFO)
    flaskApp.logger.addHandler(logHandler)
    flaskApp.logger.setLevel(logging.INFO)
    flaskApp.run()

The application is called using:

gunicorn server:flaskApp -b :80 -w 4
    --access-gfile /var/log/demo/access.log
    --error-logfile /var/log/demo/error.log

When doing a request to the home page of the site, the following happens:

1. I receive the expected HTTP 200 "Hello World\n" in response.

2. There is a trace of the request in /var/log/demo/access.log.

3. /var/log/demo/error.log stays the same (there are just the boot events).

4. There is the "Direct output" line in the terminal.

5. There is no '/var/log/demo/app.log'. If I create the file prior to launching the application, the file is not modified.

Note that:

• The directory /var/log/demo can be accessed (read, write, execute) by everyone, so this is not the permissions issue.

• If I add StreamHandler as a second handler, there is still no trace of the "Log message" message neither in the terminal, nor in Gunicorn log files.

• Gunicorn is installed using pip3 install gunicorn, so there shouldn't be any mismatch with Python versions.

What's happening?

Solution 1

When you use python3 server.py you are running the server3.py script.

When you use gunicorn server:flaskApp ... you are running the gunicorn startup script which then imports the module server and looks for the variable flaskApp in that module.

Since server.py is being imported the __name__ var will contain "server", not "__main__" and therefore you log handler setup code is not being run.

You could simply move the log handler setup code outside of the if __name__ == "__main__": stanza. But ensure that you keep flaskApp.run() in there since you do not want that to be run when gunicorn imports server.

More about what does if __name__ == “__main__”: do?

Solution 2

This approach works for me: Import the Python logging module and add gunicorn's error handlers to it. Then your logger will log into the gunicorn error log file:

import logging

app = Flask(__name__)

gunicorn_error_logger = logging.getLogger('gunicorn.error')
app.logger.handlers.extend(gunicorn_error_logger.handlers)
app.logger.setLevel(logging.DEBUG)
app.logger.debug('this will show in the log')

My Gunicorn startup script is configured to output log entries to a file like so:

gunicorn main:app \
    --workers 4 \
    --bind 0.0.0.0:9000 \
    --log-file /app/logs/gunicorn.log \
    --log-level DEBUG \
    --reload

Solution 3

There are a couple of reasons behind this: Gunicorn has its own loggers, and it’s controlling log level through that mechanism. A fix for this would be to add app.logger.setLevel(logging.DEBUG).
But what’s the problem with this approach? Well, first off, that’s hard-coded into the application itself. Yes, we could refactor that out into an environment variable, but then we have two different log levels: one for the Flask application, but a totally separate one for Gunicorn, which is set through the --log-level parameter (values like “debug”, “info”, “warning”, “error”, and “critical”).

A great solution to solve this problem is the following snippet:

import logging
from flask import Flask, jsonify

app = Flask(__name__)

@app.route('/')
def default_route():
    """Default route"""
    app.logger.debug('this is a DEBUG message')
    app.logger.info('this is an INFO message')
    app.logger.warning('this is a WARNING message')
    app.logger.error('this is an ERROR message')
    app.logger.critical('this is a CRITICAL message')
    return jsonify('hello world')

if __name__ == '__main__':
    app.run(host=0.0.0.0, port=8000, debug=True)

else:
    gunicorn_logger = logging.getLogger('gunicorn.error')
    app.logger.handlers = gunicorn_logger.handlers
    app.logger.setLevel(gunicorn_logger.level)

Refrence: Code and Explanation is taken from here

Comments

[patricksurry]

Also note that flask runs in production mode by default under gunicorn, where the app.logger level is set to WARN, so you won't see app.logger.info() or app.logger.debug(). If you want that, set app.debug = True.

[Augmented Jacob]

Can I add the path of the log file inside the script inside instead at the command line?

[pdoherty926]

Does this result in log messages being printed twice for you, @pkout? (It does for me.)

[Iron Bishop]

@pdoherty926 for the doublie logging issue, refer to medium.com/@trstringer/…

[pdoherty926]

Thanks for the suggestion, @IronBishop. Unfortunately, this post is what initially led me down this path, so it won't help me. I think I've determined that the double logging issue I'm seeing is being caused by something one of my dependencies (Plotly Dash) is doing. It seems to be creating a new logging handler which is also tapping into my application logs.

[Awaldeep Singh]

Worked for me THANKS ! :)

[Raman Joshi]

Do I need to create /app/logs/gunicorn.log this path and file manually?