[Flask] App factory logging setup

[JohnSnock]

Hi,
ich versuche gerade eine vernünftige Vorlage für Web-Projekte mit Flask zu erstellen.
Ich bin da noch ziemlich am Anfang und komme jetzt schon nicht weiter.

Und zwar habe ich massive Probleme das Logging irgendwie korrekt zu konfigurieren...
Ich habe schon mega viel recherchiert und Code-Schnipsel ausprobiert, aber irgendwie mag es nicht funktionieren.

Hier erst mal die Probleme, danach der Code.

Problem 1: Das gesetzte Log Level wird nicht respektiert.
Ich habe ERROR als Log level gesetzt, trotzdem werden auch logs für DEBUG, INFO und WARNING angezeigt.

Problem 2: Einige Logger tauchen nicht in der Liste aller Logger auf.
Die Logger flaskapp und werkzeug werden nicht aufgelistet. Vermutlich wurden sie deshalb auch nicht mit dem korrekten Level (ERROR) ausgestattet?

Code: Alles auswählen

# __init__.py

import os
from dotenv import load_dotenv
from flask import Flask
from flaskapp.config import config
from flaskapp.logging import MyLogger


# Load env vars from .env file
load_dotenv()

# Instanciate extensions
log = MyLogger()


def create_app():
    app = Flask(__name__)

    # Select config class depending on env var
    app.config.from_object(config[os.getenv('APPLICATION_ENV')])

    # Initialize extensions
    log.init_app(app)

    # TEST
    app.logger.debug('**DEBUG** after initializing log extension')
    app.logger.info('**INFO** after initializing log extension')
    app.logger.warning('**WARNING** after initializing log extension')
    app.logger.error('**ERROR** after initializing log extension')
    app.logger.critical('**CRITICAL** after initializing log extension')

    # Import and register blueprints
    from flaskapp.main.routes import main
    app.register_blueprint(main)

    return app

Code: Alles auswählen

# logging.py

import logging


class MyLogger:
    def __init__(self, app=None):
        if app is not None:
            self.init_app(app)

    def init_app(self, app):
        # Set log level
        logging.basicConfig(level=logging.ERROR)

        # Get list of all available loggers including root logger
        all_loggers = [logging.getLogger()]
        all_loggers = all_loggers + [logging.getLogger(name) for name in logging.root.manager.loggerDict]

        # TEST
        for i in all_loggers:
            print(i)

Und hier noch die Terminal Ausgabe beim Starten der Flask Anwendung (Mit Kommentaren):

Code: Alles auswählen

 * Serving Flask app '/home/myuser/projekte/flask-template/flaskapp' (lazy loading)
 * Environment: development
 * Debug mode: on
 
 # Die drei Logger wurde auf Level ERROR gesetzt
 # Aber die anderen zwei Logger 'werkzeug' und 'flaskapp' fehlen
<RootLogger root (ERROR)>
<Logger dotenv.main (ERROR)>
<Logger dotenv (ERROR)>

# Es werden alle Log Levels ausgegeben, nicht nur ERROR.
DEBUG:flaskapp:**DEBUG** after initializing log extension
INFO:flaskapp:**INFO** after initializing log extension
WARNING:flaskapp:**WARNING** after initializing log extension
ERROR:flaskapp:**ERROR** after initializing log extension
CRITICAL:flaskapp:**CRITICAL** after initializing log extension

INFO:werkzeug: * Running on http://127.0.0.1:5000 (Press CTRL+C to quit)
INFO:werkzeug: * Restarting with stat

<RootLogger root (ERROR)>
<Logger dotenv.main (ERROR)>
<Logger dotenv (ERROR)>

DEBUG:flaskapp:**DEBUG** after initializing log extension
INFO:flaskapp:**INFO** after initializing log extension
WARNING:flaskapp:**WARNING** after initializing log extension
ERROR:flaskapp:**ERROR** after initializing log extension
CRITICAL:flaskapp:**CRITICAL** after initializing log extension

WARNING:werkzeug: * Debugger is active!
INFO:werkzeug: * Debugger PIN: 648-368-123

Ich habe daraufhin mal zum Testen die folgenden Zeilen in logging.py (direkt unter logging.basicConfig) ergänzt:

Code: Alles auswählen

werkzeug_logger = logging.getLogger('werkzeug')
flaskapp_logger = logging.getLogger('flaskapp')

Das Ergebnis:

Code: Alles auswählen

 * Serving Flask app '/home/myuser/projekte/flask-template/flaskapp' (lazy loading)
 * Environment: development
 * Debug mode: on
 
 # Jetzt werden auch die anderen zwei Logger angezeigt
<RootLogger root (ERROR)>
<Logger dotenv.main (ERROR)>
<Logger dotenv (ERROR)>
<Logger werkzeug (ERROR)>
<Logger flaskapp (ERROR)>

# Trotzdem werden auch Meldungen unter Level ERROR ausgegeben :(
DEBUG:flaskapp:**DEBUG** after initializing log extension
INFO:flaskapp:**INFO** after initializing log extension
WARNING:flaskapp:**WARNING** after initializing log extension
ERROR:flaskapp:**ERROR** after initializing log extension
CRITICAL:flaskapp:**CRITICAL** after initializing log extension

INFO:werkzeug: * Running on http://127.0.0.1:5000 (Press CTRL+C to quit)
INFO:werkzeug: * Restarting with stat

<RootLogger root (ERROR)>
<Logger dotenv.main (ERROR)>
<Logger dotenv (ERROR)>
<Logger werkzeug (ERROR)>
<Logger flaskapp (ERROR)>

DEBUG:flaskapp:**DEBUG** after initializing log extension
INFO:flaskapp:**INFO** after initializing log extension
WARNING:flaskapp:**WARNING** after initial
ERROR:flaskapp:**ERROR** after initializing log extension
CRITICAL:flaskapp:**CRITICAL** after initializing log extension

WARNING:werkzeug: * Debugger is active!
INFO:werkzeug: * Debugger PIN: 648-368-123

[__blackjack__]

@JohnSnock: Alles aus dem Gedächtnis: Mit `basicConfig()` setzt Du das Level vom Root-Logger. Das greift wenn über den protokolliert wird, oder ein anderer Logger seine Nachrichten in der Loggerhierarchie weiter propagiert, und die am Ende beim Root-Logger landen. Das greift *nicht* wenn man auf einem Logger protokolliert der seine(n) eigenen Handler hat (und der seine Nachrichten vielleicht auch nicht weiter propagiert).

Aus der Flask-Dokumentation zum Thema „Logging“:

Default Configuration

If you do not configure logging yourself, Flask will add a StreamHandler to app.logger automatically. During requests, it will write to the stream specified by the WSGI server in environ['wsgi.errors'] (which is usually sys.stderr). Outside a request, it will log to sys.stderr.

[JohnSnock]

Aber die anderen Logger erhalten durch basicConfig offensichtlich das angegebene Level (ERROR), das sieht man im Output.
Also scheint es vom Root Logger schon irgendwie vererbt zu werden.
Die Logger werden mit dem korrekten Level (ERROR) angezeigt, aber verhalten sich nicht dementsprechend.
Das verwundert mich.

Ja die Flask Doku zu dem Thema habe ich auch schon zig mal durch, aber da ist nicht sonderlich viel zu finden. Verständlich, denn es wird das ganz normale Python logging verwendet. Und auf die Doku wird auch verwiesen.

Ich werde nicht schlau daraus.

[__blackjack__]

@JohnSnock: Die Angaben über den Level sind irreführend denn Dir wird da nicht angezeigt welchen Level die tatsächlich haben, sondern der Effektive *zu dem Zeitpunkt*. Live-Beispiel:

Code: Alles auswählen

In [214]: logging.Logger.manager.loggerDict                                     
Out[214]: 
{'concurrent.futures': <Logger concurrent.futures (WARNING)>,
 'concurrent': <logging.PlaceHolder at 0x7f7b657c0240>,
 'asyncio': <Logger asyncio (WARNING)>,
 'prompt_toolkit': <Logger prompt_toolkit (WARNING)>,
 'parso.python.diff': <Logger parso.python.diff (WARNING)>,
 'parso.python': <logging.PlaceHolder at 0x7f7b649b38d0>,
 'parso': <logging.PlaceHolder at 0x7f7b662aa080>,
 'parso.cache': <Logger parso.cache (WARNING)>,
 'TerminalIPythonApp': <Logger TerminalIPythonApp (WARNING)>,
 'PIL.Image': <Logger PIL.Image (WARNING)>,
 'PIL': <logging.PlaceHolder at 0x7f7b648efe80>,
 'vlc': <Logger vlc (WARNING)>,
 '__main__': <Logger __main__ (WARNING)>}

In [215]: logging.getLogger().setLevel(logging.ERROR)                           

In [216]: logging.Logger.manager.loggerDict                                     
Out[216]: 
{'concurrent.futures': <Logger concurrent.futures (ERROR)>,
 'concurrent': <logging.PlaceHolder at 0x7f7b657c0240>,
 'asyncio': <Logger asyncio (ERROR)>,
 'prompt_toolkit': <Logger prompt_toolkit (ERROR)>,
 'parso.python.diff': <Logger parso.python.diff (ERROR)>,
 'parso.python': <logging.PlaceHolder at 0x7f7b649b38d0>,
 'parso': <logging.PlaceHolder at 0x7f7b662aa080>,
 'parso.cache': <Logger parso.cache (ERROR)>,
 'TerminalIPythonApp': <Logger TerminalIPythonApp (WARNING)>,
 'PIL.Image': <Logger PIL.Image (ERROR)>,
 'PIL': <logging.PlaceHolder at 0x7f7b648efe80>,
 'vlc': <Logger vlc (ERROR)>,
 '__main__': <Logger __main__ (ERROR)>}

Es sieht so aus als hätten die alle den Level WARNING, bis ich den vom Root-Logger auf ERROR ändere — dann sieht es so aus als hätten alle den Level ERROR. Haben sie effektiv auch, aber der tatsächliche Wert ist NOTSET, weshalb die einfach das vom Elternlogger ausgeben. Allerdings schauen sowohl `werkzeug` als auch `flask` beim ersten verwenden welchen Level die Logger haben und wenn der NOTSET ist, dann ändern die den. Du musst die Logger also *explizit* vorher auf einen Level setzen.

Wobei hier auch mit rein spielt, dass Du das in einer Entwicklungsumgebung mit Debug on laufen lässt. Da sind die Logger gesprächiger als in einer Produktivumgebung.

[JohnSnock]

Explizit das Level setzen heißt also quasi folgendes, wenn ich es richtig verstanden habe?

Code: Alles auswählen

import logging

werkzeug_logger = logging.getLogger('werkzeug')
flaskapp_logger = logging.getLogger('flaskapp')

werkzeug_logger.setLevel(logging.ERROR)
flaskapp_logger.setLevel(logging.ERROR)

Jop, das funktioniert wunderbar. Vielen Dank für den Tipp!

Jetzt bleibt nur das Problem, dass mir der flaskapp und werkzeug logger nicht im loggerDict angezeigt werden. Gibt es denn eine bessere Möglichkeit, alle Logger zu bekommen? Dann könnte ich da einfach drüber loopen und das Level explizit setzen.

Bzw. warum werden mir die eigentlich nicht angezeigt? Gibt es die zu dem Zeitpunkt wo log.init_app(app) aufrufe vielleicht noch gar nicht? Werden die von Flask erst später erstellt?

[JohnSnock]

Da das mit dem expliziten konfigurieren des Log Levels funktioniert, bin ich mal einen Schritt weiter gegangen und habe in einem anderen Modul einen Logger erstellt:

Code: Alles auswählen

import logging

log = logging.getLogger(__name__)
log.error('test')

Auch hier muss ich das Level wieder manuell setzen, sonst funktioniert das Level nicht.
Wenn ich jetzt 20 Module habe und damit auch 20 Logger, dann macht es doch keinen Sinn 20 Zeilen im Sinne von .setLevel(LOG_LEVEL) zu schreiben.

[__blackjack__]

@JohnSnock: Man hat ja auch keine 20 Logger beziehungsweise nicht einen Logger pro Modul der unabhängig von den anderen ist. Pro Anwendung/Bibliothek *einen* Hauptlogger, wenn überhaupt mehr als einer alle anderen dann als ”Unterlogger”, dann gilt die Konfiguration des Hauptloggers. Und wenn man bei dem kein Loglevel setzt, dann orientiert sich das doch am Root-Logger. Es sei denn Du fängst da halt auch an in *Deinem* Code dran rum zu schrauben wie Werkzeug und Flask. Dann bist Du aber selbst schuld.

Hast Du denn in der Produktivumgebung überhaupt ein Problem das tatsächlich gelöst werden muss? Denn da verhalten sich Werkzeug und Flask ja anders in der Voreinstellung. Das da so viel protokolliert wird, liegt ja wie gesagt daran, dass Flask selbst und als Entwicklungsumgebung läuft. Da *will* man doch den ganzen Kram sehen um Fehlern auf die Spur zu kommen. Und manche Sachen wie die Werkzeug-Debugger-Pin *muss* man ja auch sehen, sonst kann man den nicht interaktiv benutzen und müsste sich die Frage stellen warum man den überhaupt aktiviert.