Why Flask logger does not log in docker when using UWSGI in front?

Question

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.

Answer 1

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:

• Setting the propagation to false (easy solution, but workaround)
• Searching for the "invalid" configuration and removing it
• Use the dictConfig initialization, before instantiating the app, as the Flask logging tutorial suggests