flask logging duplicate output

Question

I would like to change the flask logging format to the console, and I tried this,

Provide extra information to Flask's app.logger

But it did not work for me; its 3+ years old and perhaps out of date?

I can add an additional console handler, which works, but then I get duplicate output, once from the flask default console handler, and once from my added handler.

The source,

import sys
import logging
from flask import Flask


def setup_logging(level=logging.INFO):

    # FIXME: logs are coming out "twice", once with the format from flask, and again from
    #        the format from consoleHandler.  app.logger level and the console handler
    #        level seem to be linked
    app.logger.setLevel(level)

    # Here we define our formatter
    FORMAT = "%(relativeCreated)6d %(threadName)15s %(filename)25s:%(lineno)4s - %(name)30s:%(funcName)20s() %(levelname)-5.5s : %(message)s"
    formatter = logging.Formatter(FORMAT)

    consoleHandler = logging.StreamHandler(stream=sys.stdout)
    consoleHandler.setFormatter(formatter)
    consoleHandler.setLevel(level)

    app.logger.addHandler(consoleHandler)

    # this did not work :(
    # https://stackoverflow.com/questions/27775026/provide-extra-information-to-flasks-app-logger


app = Flask(__name__)

@app.route('/')
def hello_world():
    app.logger.info("Foo Bar")
    return 'Hello, World!'


setup_logging()

app.run(host="0.0.0.0", port=6800, debug=False)

The output,

 * Serving Flask app "SO_log_01" (lazy loading)
 * Environment: production
   WARNING: Do not use the development server in a production environment.
   Use a production WSGI server instead.
 * Debug mode: off
 * Running on http://0.0.0.0:6800/ (Press CTRL+C to quit)
[2018-07-02 17:35:52,906] INFO in SO_log_01: Foo Bar
127.0.0.1 - - [02/Jul/2018 17:35:52] "GET / HTTP/1.1" 200 -
  5083        Thread-1              SO_log_01.py:  39 -                      flask.app:         hello_world() INFO  : Foo Bar
127.0.0.1 - - [02/Jul/2018 17:35:55] "GET /favicon.ico HTTP/1.1" 404 -

Answer 1

If you want to replace the logger formatting, you need to remove previous logger handlers.

app.logger.handlers.clear()
app.logger.addHandler(consoleHandler)

https://code.luasoftware.com/tutorials/flask/change-flask-logging-output-format/

Answer 2

In Flask 1.1.x the key is to configure your logging before creating the application object.

See Basic Configuration

When you want to configure logging for your project, you should do it as soon as possible when the program starts. If app.logger is accessed before logging is configured, it will add a default handler. If possible, configure logging before creating the application object.

A working example.

import os
from flask import Flask
from logging.config import dictConfig

dictConfig({
    'version': 1,
    'formatters': {
        'default': {
            'format': '%(asctime)s.%(msecs)03d, %(levelname)s, %(message)s',
            'datefmt': '%Y-%m-%dT%H:%M:%S'
        },
    },
    'handlers': {
        'stdout': {
            'class': "logging.StreamHandler",
            'stream': 'ext://sys.stdout',
            'formatter': 'default'
        }
    },
    'root': {
        'handlers': ['stdout'],
        'level': os.getenv('APP_LOG_LEVEL', 'INFO')},
})

app = Flask(__name__)
app.logger.info("App started")


@app.route('/')
def hello_world():
    app.logger.info("Foo Bar")
    return 'Hello, World!'

Run it and get some output by hitting http://localhost:5000/ a few times.

$ FLASK_APP=app.py FLASK_ENV=development APP_LOG_LEVEL=DEBUG flask run
 * Serving Flask app "app.py" (lazy loading)
 * Environment: development
 * Debug mode: on
2020-04-20T14:35:46.480, INFO, App started
2020-04-20T14:35:46.486, INFO,  * Running on http://127.0.0.1:5000/ (Press CTRL+C to quit)
2020-04-20T14:35:46.487, INFO,  * Restarting with stat
2020-04-20T14:35:47.024, INFO, App started
2020-04-20T14:35:47.028, WARNING,  * Debugger is active!
2020-04-20T14:35:47.035, INFO,  * Debugger PIN: 329-665-000
2020-04-20T14:35:54.362, INFO, Foo Bar
2020-04-20T14:35:54.363, INFO, 127.0.0.1 - - [20/Apr/2020 14:35:54] "GET / HTTP/1.1" 200 -
2020-04-20T14:35:54.879, INFO, Foo Bar
2020-04-20T14:35:54.880, INFO, 127.0.0.1 - - [20/Apr/2020 14:35:54] "GET / HTTP/1.1" 200 -
2020-04-20T14:35:55.356, INFO, Foo Bar
2020-04-20T14:35:55.356, INFO, 127.0.0.1 - - [20/Apr/2020 14:35:55] "GET / HTTP/1.1" 200 -

The key bit to understand is that dictConfig(...) is invoked before Flask(__name__).