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?

Answer 1

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