Flask app logger not working when running within gunicorn

Question

I'm trying to save application log messages from a very simple flask app in a log file. While this works flawlessly when I'm running the app with the embedded Flask server, it is not working at all when running within gUnicorn, basically, no application output is redirected neither the log file (the one specified in my Flask app) or to the STDOUT when running gunicorn.

That said, this is my Flask app:

@app.route('/')
def index():
    app.logger.debug('Into /!!!!')
    print 'Will this print?'
    return 'Flask is running!'


if __name__ == '__main__':
    #Setup the logger
    file_handler = FileHandler('test.log')
    handler = logging.StreamHandler()
    file_handler.setLevel(logging.DEBUG)
    handler.setLevel(logging.DEBUG)
    file_handler.setFormatter(Formatter(
    '%(asctime)s %(levelname)s: %(message)s '
    '[in %(pathname)s:%(lineno)d]'))
    handler.setFormatter(Formatter(
    '%(asctime)s %(levelname)s: %(message)s '
    '[in %(pathname)s:%(lineno)d]'))
    app.logger.addHandler(handler)
    app.logger.addHandler(file_handler)
    app.run(debug=True)

Now if I start the app as:

python app.py

I get the expected output:

 * Running on http://127.0.0.1:5000/ (Press CTRL+C to quit)
 * Restarting with stat

--------------------------------------------------------------------------------
DEBUG in app [app.py:23]:
Into /!!!!
--------------------------------------------------------------------------------
2015-03-11 09:36:18,375 DEBUG: Into /!!!! [in app.py:23]
Will this print?
127.0.0.1 - - [11/Mar/2015 09:36:18] "GET / HTTP/1.1" 200 -

Tailing test.log, I see:

2015-03-11 09:36:18,375 DEBUG: Into /!!!! [in app.py:23]

Everything looks great so far, then when I try to run the app with nginx + gunicorn, first I've tried to run gunicorn like this:

gunicorn app:app -b localhost:8000 --debug --log-level debug

App is working, if I go to http://localhost:

curl http://localhost
Flask is running!

But looking at the log file, is empty, nothing is being written. I've added 777 permissions just to check if it was a permission problem to no avail. Then looking at gunicorn stdout, nothing is being written besides the print statement:

2015-03-11 09:42:06 [25641] [DEBUG] GET /
Will this print?

Looking around, I've tried to redirect all output to gunicorn logs, then starting gunicorn like this:

gunicorn app:app -b localhost:8000 --debug --log-file /tmp/test.log --log-level debug --error-logfile /tmp/error.log

But now I don't even get print statements in gunicorn files, this is the output from both test.log and error.log (they are identical):

2015-03-11 09:46:17 [26257] [DEBUG]   tmp_upload_dir: None
2015-03-11 09:46:17 [26257] [DEBUG]   keyfile: None
2015-03-11 09:46:17 [26257] [DEBUG]   backlog: 2048
2015-03-11 09:46:17 [26257] [DEBUG]   logger_class: simple
2015-03-11 09:46:17 [26257] [INFO] Starting gunicorn 17.5
2015-03-11 09:46:17 [26257] [DEBUG] Arbiter booted
2015-03-11 09:46:17 [26257] [INFO] Listening at: http://127.0.0.1:8000 (26257)
2015-03-11 09:46:17 [26257] [INFO] Using worker: sync
2015-03-11 09:46:17 [26262] [INFO] Booting worker with pid: 26262
2015-03-11 09:48:15 [26262] [DEBUG] GET /

There is a very similar question here, one of the answers seems to suggest that no application logger is available when runnning within gunicorn??? This sounds, at least, quite strange...how am I supposed to log then?

Another proposed solution seems to suggest not using Flask logger, but is not related with gunicorn (I think)...

What I'm missing? Should I give up on gunicorn and go for Apache-mod wsgi? Nginx-uWSGI? FastCGI? Any ideas?

Thanks! Alejandro

EDIT:

I've tried this very same setup with uWGSI instead of gunicorn and same behaviour, no application logging is obtained whatsoever.

Now based on this response and this other one, I came up with this (on gUnicorn and uWSGI, in both it works)

from flask import Flask
import logging
from logging import Formatter, FileHandler

app = Flask(__name__)

LOGGER = logging.getLogger('whatever')
file_handler = FileHandler('test.log')
handler = logging.StreamHandler()
file_handler.setFormatter(Formatter(
    '%(asctime)s %(levelname)s: %(message)s '
    '[in %(pathname)s:%(lineno)d]'
))
handler.setFormatter(Formatter(
    '%(asctime)s %(levelname)s: %(message)s '
    '[in %(pathname)s:%(lineno)d]'
))
LOGGER.addHandler(file_handler)
LOGGER.addHandler(handler)
LOGGER.setLevel(logging.INFO)

@app.route('/')
def hello():
    LOGGER.info('info log')
    LOGGER.debug('debug log')
    return 'Hello!'

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

Output from gunicorn:

2015-03-11 12:25:01 [11540] [INFO] Starting gunicorn 17.5
2015-03-11 12:25:01 [11540] [INFO] Listening at: http://127.0.0.1:8000 (11540)
2015-03-11 12:25:01 [11540] [INFO] Using worker: sync
2015-03-11 12:25:01 [11545] [INFO] Booting worker with pid: 11545
2015-03-11 12:26:20,765 INFO: info log [in /home/mosquito/www/flask-project/flask-project/app.py:24]

And looking at my test.log file:

2015-03-11 12:26:20,765 INFO: info log [in /home/mosquito/www/flask-project/flask-project/app.py:24]

So yeah, it kinda works, but original question still remains...why the heck the Flask logger does not seem to work when running inside wsgi containers - gunicorn, uWSGI?

Solution 1

Flask uses Werkzeug for WSGI. The "Flask logs" you see are actually from Werkzeug's builtin development server and not from Flask itself.

When you replace that development server with something like Gunicorn or uWSGI, you don't see its logs.

The same goes for the Debugger. You can see the familiar "Flask debug page" even if you only use Werkzeug's Debugger.

Now you know. :)

Solution 2

You answered your question yourself here. Though I'll add my answer in hope that it would help someone else having similar issue.

Since your question has 2 parts, of which the first part is solved, ill mark my response for each part:

PART 1: No logging happening if instead of directly running the app via python, you run it under gunicorn This was because, when directly running, the name == 'main' is True, and your code initialized both a FileHandler and a StreamHandler, and logging worked. But when run through gunicorn, name == 'main' would fail, as name would then contain the name of your module. This means no effective handlers will be initialized. And hence no logging is seen.

PART 2: Why doesn't Flask logger work by default under gunicorn/uWSGI The latest flask versions initialize app.logger from scratch and attach a few handlers like DebugHandler, StreamHandler by default depending on if app.debug==True. Still the logger is not enough and will only log to STDERR. There have been multiple changes in gunicorn over last few versions. Version 19.4.1 doesn't capture STDOUT and STDERR to the gunicorn error.log. But it does make available loggers with names 'gunicorn' , 'gunicorn.access' and 'gunicorn.error'. The last one has a FileHandler writing to the configured error.log. In case you want logs from your flask app to go to error.log use one of the following approaches: Approach1:

#only use gunicorn.error logger for all logging
LOGGER = logging.getLogger('gunicorn.error')
LOGGER.info('my info')
LOGGER.debug('debug message')
# this would write the log messages to error.log

Approach2:

# Only use the FileHandler from gunicorn.error logger
gunicorn_error_handlers = logging.getLogger('gunicorn.error').handlers
app.logger.handlers.extend(gunicorn_error_handlers )
app.logger.addHandler(myhandler1)
app.logger.addHandler(myhandler2)
app.logger.info('my info')
app.logger.debug('debug message')

Will recommend approach 2, as you can keep whatever handlers you wish in addition to gunicorn.error. Also, you can choose to not add gunicorn.error handlers based on a condition.

thanks

Solution 3

With gunicorn 19.6, --capture-output --enable-stdio-inheritance seems to work.

Solution 4

Someone can search: how to see errors with Python error stack when using Flask with Gunicorn.

Just set up the flag --error-logfile to the file path where you want to see error stacks. Particularly (when using in Docker) you can set it up in GUNICORN_CMD_ARGS environment variable to the next value (an example):

--bind=0.0.0.0:8000 --access-logfile=/logs/rest.app/access.log --error-logfile=/logs/rest.app/error.log --capture-output --enable-stdio-inheritance

Solution 5

@Auguiwan's answer does explain the origin question, but not talked about how to solve it.@indrajeet 's answer is quite comprehensive and provides a kind of solution. However, they don't solve my related problem.

My answer mainly tries to help people who get here by searched similar keywords "flask gunicorn log" like me. I find this link is very helpful among related search result https://medium.com/@yoanis_gil/logging-with-docker-part-1-1-965cb5e17165

The part Gunicorn configuration

exec gunicorn ${WSGI_MODULE}:${WSGI_APP} \
  --name $NAME \
  --workers $NUM_WORKERS \
  --user=$USER --group=$GROUP \
  --bind=unix:$SOCKFILE \
  --log-level=info \
  --log-file=/dev/stdout

really helps me out. The core configuration is --log-level and --log-file part.
If you are using supervisored with gunicorn.conf like me, just change related gunicorn.conf file.

View more solutions

Comments

[AlejandroVK]

I like the approach, will test it out, thanks @indrajeet

[Tom Parker-Shemilt]

Nope, no luck with this

[makkasi]

The only solution that worked for me. Thank you. Using this you don't need any of these handlers :) Just import logging and logging.basicConfig(level='DEBUG') and use logging.info('something to log') , works with gunicorn and wsgi

[w00dy]

Approach 2 works with me but it prints twice on stdout [2020-02-26 14:28:53 +0000] [21] [INFO] checking db \n checking db

[ssc]

worked for me once I set PYTHONUNBUFFERED=TRUE environment variable (as mentioned in the docs)

[incandenza]

This answer worked for FastAPI & gunicorn. Thank you.

[Aravind]

This helped me. I want to add a formatted and it worked moving my flask logs to gunicorn in the specified format.