I'm doing performance testing in my Flask application.
ngnix -> gunicorn -> flask
Log files:
I'm using ab testing tool. My requests are handled properly and logged properly in Flask log file in my Dev environment (MacOS 10.10.5).
ab -c 10 -n 10 -A username:password https://1.1.1.1:8443/api/1.0/echo/
When I move to production, (Ubuntu) I can't see all 10 requests being logged in Flask log file. I only see 1 in api log file. ab tool reports all requests are handled properly.
I do see 10 requests in Ngnix, Gunicorn, but not in Flask.
gunicorn start script (Supervisord)
GUNICORN_LOGFILE=/usr/local/src/imbue/application/imbue/log/gunicorn.log
NUM_WORKERS=8
TIMEOUT=60
WORKER_CONNECTIONS=2000
BACKLOG=1000
exec gunicorn api:api_app --bind 0.0.0.0:8081 --log-level=DEBUG --log-file=$GUNICORN_LOGFILE --workers $NUM_WORKERS --worker-connections=$WORKER_CONNECTIONS --backlog=$BACKLOG --timeout $TIMEOUT
api file:
from application.app import api_app
if __name__ == "__main__":
api_app.run(debug=False, threaded=True)
api_app Flask application
# =========================================================
# API Logs
# =========================================================
log = logging_conf.LoggerManager().getLogger("___app___", logging_file=settings.api_logfile)
# =========================================================
# Flask Application imports and database
# =========================================================
from flask import Flask
from flask.ext import restful
from werkzeug.contrib.fixers import ProxyFix
# =========================================================
# Flask Main Application
# =========================================================
api_app = Flask(__name__) # Flask Application
api_app.config.from_pyfile("../../../conf/settings.py") # Flask configuration
imbue_api = restful.Api(api_app) # Define API
db = Model.db.init_app(api_app) # Initialize database
# =========================================================
# API Definition
# =========================================================
imbue_api.add_resource(ApiBase, settings.BASE_API_URL)
imbue_api.add_resource(Echo, '/api/1.0/echo/')
# =========================================================
# API Proxy WSGi for gunicorn
# =========================================================
api_app.wsgi_app = ProxyFix(api_app.wsgi_app)
log.info('Initializing API >>>')
api_main
import logging
# =========================================================
# IMBUE imports
# =========================================================
from flask import current_app
from flask import jsonify, request, Response, url_for
from flask.ext import restful
from flask.ext.restful import Resource
# =========================================================
# API Controller
# =========================================================
api = restful.Api
# =========================================================
# API Logs
# =========================================================
log = logging_conf.LoggerManager().getLogger("___app___", logging_file=settings.api_logfile)
# =========================================================
# API Version information
# =========================================================
class Echo(Resource):
@authenticator.requires_auth
def get(self):
"""
:return:
"""
try:
# =========================================================
# GET API
# =========================================================
log.info(request.remote_addr + ' ' + request.__repr__())
if request.headers['Content-Type'] == 'application/json':
# =========================================================
# Send API version information
# =========================================================
log.info('api() | GET | Version' + settings.api_version)
response = json.dumps('version: ' + settings.api_version)
resp = Response(response, status=200, mimetype='application/json')
return resp
Versions
gunicorn==19.3.0
Flask==0.10.1
Flask-HTTPAuth==2.7.0
Flask-Limiter==0.9.3
Flask-Login==0.3.2
Flask-Mail==0.9.1
Flask-Migrate==1.6.0
Flask-OAuthlib==0.9.1
Flask-Principal==0.4.0
Flask-RateLimiter==0.2.0
Flask-RESTful==0.3.5
Flask-Restless==0.17.0
Flask-Script==2.0.5
Flask-Security==1.7.5
Flask-SQLAlchemy==2.1
Flask-WTF==0.12
logging_conf
class Singleton(type):
"""
"""
_instances = {}
def __call__(cls, *args, **kwargs):
if cls not in cls._instances.keys():
cls._instances[cls] = super(Singleton, cls).__call__(*args, **kwargs)
return cls._instances[cls]
class LoggerManager(object):
"""
"""
__metaclass__ = Singleton
_loggers = {}
def __init__(self, *args, **kwargs):
pass
@staticmethod
def getLogger(name='___app___', logging_file='imbued.log', **kwargs):
"""
:param name:
:param logging_file:
:param kwargs:
:return:
"""
# Define timezone
logging.basicConfig(filename=logging_file,
filemode='w+',
level=logging.INFO,
format='%(asctime)s.%(msecs).03d %(levelname)s %(message)s',
datefmt='%m/%d/%Y %H:%M:%S')
if not name:
return logging.getLogger()
elif name not in LoggerManager._loggers.keys():
LoggerManager._loggers[name] = logging.getLogger(str(name))
return LoggerManager._loggers[name]
The problem happens when you declare log variable. The multiple threads of gunicorn calls multiple instances of getLogger and then overwrites your logfile. That doesn't happen when you use Werkzeug server with threaded param app.run(threaded=True).
If you just need to log the requests you can use the param --access-logfile REQUEST_LOG_FILE on gunicorn start script
GUNICORN_LOGFILE=/usr/local/src/imbue/application/imbue/log/gunicorn.log
NUM_WORKERS=8
TIMEOUT=60
WORKER_CONNECTIONS=2000
BACKLOG=1000
REQUEST_LOG_FILE=./request-log-file.log
exec gunicorn api:api_app --bind 0.0.0.0:8081 --log-level=DEBUG --log-file=$GUNICORN_LOGFILE --workers $NUM_WORKERS --worker-connections=$WORKER_CONNECTIONS --backlog=$BACKLOG --timeout $TIMEOUT --access-logfile REQUEST_LOG_FILE
See more on about loggin on documentation.
Warning: PROBABLY NOT SAFE
As a simple workaround, you can change the basicConfig method inside getLogger to, instead of overwrite the file, append to an existing file. That is not safe, multiple threads changing the same file can leads to unexpected results.
logging.basicConfig(filename=logging_file,
filemode='w+', # Open, read and truncate the file.
level=logging.INFO,
format='%(asctime)s.%(msecs).03d %(levelname)s %(message)s',
datefmt='%m/%d/%Y %H:%M:%S')
to
logging.basicConfig(filename=logging_file,
filemode='a+', # Open, read and append to a file.
level=logging.INFO,
format='%(asctime)s.%(msecs).03d %(levelname)s %(message)s',
datefmt='%m/%d/%Y %H:%M:%S')
EDIT 1
Apparently logging is thread safe but I'm not sure if that will be extended for gunicorn workers...