I have a Flask
application inside of Docker
that was logging into docker logs
when it was running without UWSGI
in front. Now I have used UWSGI
with the config below to run my application inside of Docker
:
[uwsgi]
master = true
processes = 5
threads = 2
socket = 127.0.0.1:3031
chmod-socket = 664
stats=0.0.0.0:30310
chdir = /etc/fantas
uid = root
gid = root
wsgi-file=uwsgi_fantas.py
callable=app
vacuum = true
The uwsgi_fantas.py
file contains:
from fantas.fantas_app import FantasApp
app = FantasApp().setup()
The setup
method returns app
:
from flask_restful import Api
from fantas import app
class FantasApp(object):
def setup(self):
api = Api(app)
api.add_resource(Token, '/users')
return app
Finally the part that initiates the Flask
framework is inside of __init__.py
in the root directory of project:
from flask import Flask
import logging
app = Flask(__name__)
s_handler = logging.StreamHandler()
s_handler.setLevel(logging.DEBUG)
app.logger.addHandler(s_handler)
As UWSGI
works directly with the app
object I have configured logger inside of __init__.py
, but the problem is that it does not log anything into Docker
when it is run, it just logs UWSGI
requests.
What is wrong in the process of app.logger configuration?
Problem has been solved, but now logs get duplicated!
EDIT-1:
I set app.logger.setLevel(logging.DEBUG)
and it seems that Flask
logs into Docker
successfully. The weird part is that it logs 3 times! I removed all logger configs and handlers and just used:
app.logger.setLevel(logging.DEBUG)
But now it logs 2 times:
proj_fantas.1.huagnqqpzo1n@linuxkit-025000000001 | [2018-07-13 07:02:38,008] DEBUG in token: [Token] authenticating user...
proj_fantas.1.huagnqqpzo1n@linuxkit-025000000001 | DEBUG:flask.app:[Token] authenticating user...
Why it is like that?
EDIT-2:
The output of app.logger.handlers
is [<logging.StreamHandler object at 0x7f0f430ca8d0>]
. It just shows the StreamHandler that I initialized earlier, nothing more.
EDIT-3:
The output of ps -ef
command inside of Docker
:
UID PID PPID C STIME TTY TIME CMD
root 1 0 0 15:26 ? 00:00:00 uwsgi uwsgi_coconuty.ini
root 10 1 0 15:26 ? 00:00:00 uwsgi uwsgi_coconuty.ini
root 12 1 0 15:26 ? 00:00:00 uwsgi uwsgi_coconuty.ini
root 13 1 0 15:26 ? 00:00:00 uwsgi uwsgi_coconuty.ini
root 15 1 0 15:26 ? 00:00:00 uwsgi uwsgi_coconuty.ini
root 16 1 0 15:26 ? 00:00:00 uwsgi uwsgi_coconuty.ini
root 20 0 0 15:27 pts/0 00:00:00 /bin/bash
root 112 20 0 15:28 pts/0 00:00:00 ps -ef
There is no other process running inside of Docker
.
First of all, there are recent changes in the way Flask logs are initialized from version 0.9 to the current stable 1.0.2, for example. You can check this here. I am assuming your docker image uses the most recent version.
If that is the case, even without any custom logging config, actually it is logging for your output stream, but it is filtering out lower than WARNING logs (DEBUG and INFO). This happens when you rely on Flask initializing the log for you and you do not set a --debug flag (uwsgi case).
There are multiple strategies that can be looked at when you configure logging. One suggestion is to use the dictConfig initialization mentioned by the library itself, at the uwsgi master, before defining the app, which then forks. Following your example, at __init__.py
:
from flask import Flask
from logging.config import dictConfig
dictConfig({
'version': 1,
'formatters': {'default': {
'format': '[%(asctime)s] %(levelname)s in %(module)s: %(message)s',
}},
'handlers': {'wsgi': {
'class': 'logging.StreamHandler',
'formatter': 'default'
}},
'root': {
'level': 'DEBUG',
'handlers': ['wsgi']
}
})
app = Flask(__name__)
The problem you mention in EDIT-1 looks like a python logging propagation issue. There is a standalone case, easier to debug, here.
Even though you have only set one Stream Handler, as your log shows, it probably has a parent attached. If you check for its parent it will probably have a handler attached different from the one you mentioned in EDIT-2 :
print logger.handlers
[<logging.StreamHandler object at 0x7f15669c1550>]
print logger.parent.handlers
[<logging.StreamHandler object at 0x7f15669c1610>]
This happens when the logging propagation is enabled and there happened some logging initialization elsewhere. You can check how propagation works by looking at callHandlers
in python's source code:
...
hdlr.handle(record)
if not c.propagate:
c = None #break out
else:
c = c.parent
...
Back to your case (Flask), by looking at the traces in your logs, there is a logger named flask.app
, which is the one created by Flask itself. There is the formatted version, and the unformatted one (logging.BASIC_FORMAT), respectively. So it is probably being initialized somewhere in your code or in one of the libraries you import.
There are multiple ways you can solve this: