Using logging's root logger before app.run() breaks Flask logging

[ramnes]

On latest PyPI's release (1.0.2), using logging's root logger before running Flask breaks its logging.

For example, with such a run.py file:

import logging
import flask

logging.info("it breaks")
flask.Flask(__name__).run()

python run.py outputs this:

 * Serving Flask app "run" (lazy loading)
 * Environment: production
   WARNING: Do not use the development server in a production environment.
   Use a production WSGI server instead.
 * Debug mode: off

and then stops any kind of logging.

The application is running and answering, but you don't get the Running on http://... line, nor any request logging.

It's worth noting that using the root logger inside a route doesn't break Flask.

[ghost]

TL;DR: This behavior is caused by flask.logging.has_level_handler() and logging.basicConfig(). Specifically, using the root logger (i.e. calling logging.<function()>) before calling app.logger will add a handler to the root logger and cause flask.logging.has_level_handler() to return True when it should return False.

When you use any function from the logging module such as logging.info('message') or logging.basicConfig(filename='some_log_file'), you work with the root logger. The root logger is a Logger object that sits inside the logging module with a default level of logging.WARNING. The root logger isn't created with any handlers attached, but when you use a module-level function like those I offered previously (specifically any function that feeds into basicConfig()), they will attach a file handler or a stream handler to the root logger for you.

From the logging module (3.7):

def info(msg, *args, **kwargs):
    ...
    if len(root.handlers) == 0:
        basicConfig()  # logging.debug(), etc... all feed into basicConfig()
   ...

def basicConfig(**kwargs):
    ...
        if len(root.handlers) == 0:
            ...  # left out for brevity
            if handlers is None:
                filename = kwargs.pop("filename", None)  # if you use basicConfig() directly
                mode = kwargs.pop("filemode", 'a')
                if filename:
                    h = FileHandler(filename, mode)
                else:
                    stream = kwargs.pop("stream", None)  # if you use message-emitting functions like info()
                    h = StreamHandler(stream)
            ...  # Some formatting stuff
                root.addHandler(h)  # Adds the stream or file handler to the root logger
            ...

In the scenario laid out by @ramnes, the root logger is used first, will have a default level of warning, and will have a stream handler attached to it. Now if we go to flask.logging.create_logger() (which is where all of the calls to the application-level logger will feed into some time after the call to logging.info()), we see the following in the flask.logging module:

def create_logger(app)
    ...
   logger = logging.getLogger('flask.app')
   
    # This prevents the problem if FLASK_DEBUG is set, but it won't trigger in this example.
    if app.debug and logger.level == logging.NOTSET:
        logger.setLevel(logging.DEBUG)

    if not has_level_handler(logger):                                
        logger.addHandler(default_handler)

    return logger

The primary issue lies with has_level_handler():

def has_level_handler(logger):
    ...
    level = logger.getEffectiveLevel()  # This is the first culprit, it will return 30 (the root logger's level)
    current = logger

    while current:
        if any(handler.level <= level for handler in current.handlers):  # This is the second culprit
            return True

        if not current.propagate:
            break

        current = current.parent  # This is the third culprit

    return False

has_level_handler() has three lines that cause the problem if used after a root logger is configured.

First, in our example, getEffectiveLevel() will return a value of 30 (warning). The application logger begins its life with a level of 0, so getEffectiveLevel() will defer to the nearest level in the logging tree. In our case, that's the root logger with a level of 30 (the 30 is returned). Next, we enter the loop and check the application logger for any handlers with a level of 30 or below. We don't find any, so we get the logger's parent (the root logger) and loop again. This time, we do find a handler: the handler logging attached to the root logger for us. All handlers begin their life with a level of 0, so this incidental handler fits the the conditional if any(handler.level <= level for handler in current.handlers) and has has_level_handler() return True when it should return False. Hopping back to create_logger(), this means that the application logger will never be given the default handler.

Now, whenever the application logger is asked to emit a message, it will have to defer to the nearest handler in the logging tree, which just so happens to be the incidental handler that we attached the root logger when we used it at the very beginning. In our example, this is a stream handler, which happens to default to stderr. Recall that the root logger defaults to a level of warning. This means that any messages with a debug- or info-level messages that the application logger attempts to emit will be suppressed. In our example, warning messages and above will still be output to stderr. If you call basicConfig(filename='file.log'), then warning messages and above will be appended to file.log. Notice that the werkzeug logger will still emit some warning messages if you haven't touched with it.

There are a couple of potential quick fixes (these won't solve the problem, only mask it)

1. Call the application logger (app.logger.<something>) before the root logger so that it uses its own default handler (recommended).
2. Give the application logger the level and handler (also with a level) you want before using it
3. Set the root logger's level to something different
4. Set the root logger's file / stream handler to something different
5. Add more handlers (with levels) to the root logger

For a longer-fix, I would look at patching flask.logging.has_level_handler(), although I'm not sure how because I don't understand its intentions.

[davidism]

This is absolutely intentional. #2436 Flask previously had behavior where it would clear any existing handlers and insert its own, which is bad behavior for a library and was disruptive to people who were configuring logging. Now it will only insert a handler if logging was not otherwise configured to handle its logs. If you want to use Python's logging, you should configure it very early and not rely on Flask's default behavior.

[ramnes]

Whether this behavior is the resultant of an intentional implementation or not is not the point here. I do agree that #2436 make things much better than just removing any existing handler as Flask used to do, but please understand that the current behavior is very developer-hostile in that particular case. No one, beside someone that perfectly knows Flask internals, would consider logging.info("it breaks") as a way of configuring (or just altering) Flask's logging. And yet, the root logger is mostly used by beginners, and developers that just want to throw some logging somewhere quickly for debugging purposes. I don't know any library other than Flask which has its logging altered by a simple use of the root logger.

[davidism]

It's not Flask's logging you're configuring, it's Python's. Open an issue with Python if you find that confusing. There is no 100% solution, I'm not changing this again.

[ramnes]

I do agree that the fault mostly comes from Python here. But still, I could not understand why there was no log at all rather than some logs using the default handler, so I gave a quick look in the code. The reason actually lies in Werkzeug, not Flask. Please consider the following PR for a proposal of changes that would fix this "for free": pallets/werkzeug#1407

[celvartamfam]

I see a different behavior. When I configure the root logger before any flask code is executed I still get a handler attached to the "werkzeug" handler that outputs plain text to stderr but leaves the propagate flag on.

I have configured my service to output JSON formatted log messages that can be parsed by an ELK stack with the field I want so I can correlate all the log messages from any given operation all through all of the microservices it uses.

As a result of the added handler... If I do nothing I get both a JSON line and a plain text line.

[davidism]

@celvartamfam see the linked PR in the comment above yours.

[davidism]

Logging configuration should be done for each library that outputs logging, that's just how Python is set up. This is discussed in the documentation. Flask's logging does not affect Werkzeug's.

Also, it sounds like you're using the dev server in a production environment, which is the only time werkzeug logs would output. Don't do that.