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.

Do you have a minimal docker image/git repo or something one can directly use and debug? — Tarun Lalwani, Jul 15 '18 at 17:16
The phrase "log into docker" makes it worth pointing out that the app (uwsgi) only need log to STDOUT|STDERR for output to make it to the docker log. UWSGI [writes to STDOUT by default](https://uwsgi-docs.readthedocs.io/en/latest/Logging.html) I suspect the StreamHandler() writing to a file or something "file-like" that is not where the container is watching for log output. — Boyd Hemphill, Jul 15 '18 at 23:00
@TarunLalwani currently I don't have one, but I try to create one within the next couple of days. My problem as I have mentioned at the end of the question is that I have duplicate logs in `docker logs`. Read **EDIT-2** section. — Alireza, Jul 16 '18 at 05:37
@BoydHemphill first problem has been solved. If you read on the question you would see that I have problem on duplicate logs in docker logs. Read **EDIT-2** section plz. Thanks — Alireza, Jul 16 '18 at 05:38
Thanks for the feedback @ALH, however I came across this b/c of its title and did not find an answer yet. Thus I offered an answer to the original question in case others find their way here. If you could provide your solution to the original question that would be super helpful! — Boyd Hemphill, Jul 17 '18 at 18:20
Here is a SWAG on the second issue: Given that the messages are not identical, (one has a datestamp while the other does not), I assert there are multiple processes tied to STDOUT|STDERR. IIRC, it is possible to be running both the built in flask server and UWSGI. A way to check for this is to `docker exec` into the contain and then run the `ps` command. — Boyd Hemphill, Jul 17 '18 at 18:23
@BoydHemphill, I have mentioned in **EDIT-1** section that by setting `app.logger.setLevel(logging.DEBUG) ` problem gone away and logs appear in docker logs. I will do `ps` today and report the results. — Alireza, Jul 18 '18 at 05:54
@BoydHemphill could you kindly take a look at the section `EDIT-3`? — Alireza, Jul 18 '18 at 15:30
@ALH `ps` is showing only `uwsgi` process and nothing from `flask` so my above assertion is incorrect. The answer from below is quite promising. — Boyd Hemphill, Jul 18 '18 at 23:32
Is there even a way to avoid duplicate logging in debug mode? — jtlz2, Aug 23 '18 at 15:11

null · Accepted Answer · 2018-07-20T18:15:33.607

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

By using `dictConfig`, app.logger works as expected, I really appreciate for the time. — Alireza, Jul 22 '18 at 18:42

score 0 · Answer 2 · answered Jun 21 '20 at 15:04

I had a similar problem (Special: I wanted to use the syslog). First I had to add a rule to the Dockerfile:

RUN apt-get install -y rsyslog
service rsyslog start

Flask comes with build-in logging, so I just had to add some twigs

from flask import Flask
import logging
import logging.handlers

handler = logging.handlers.SysLogHandler(address = '/dev/log')
handler.setFormatter(logging.Formatter('flask [%(levelname)s] %(message)s'))

app = Flask(__name__)
app.logger.addHandler(handler)

Additional settings can be handled through the syslog-daemon

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

2 Answers2

Linked