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?