Flask: Design issue with flask.logger.create_logger().

[itsjohncs]

flask.logger.create_logger() destroys any log handlers that have been added previously. Because the creation of the logger (and the calling of create_logger() that this entails) is deferred until the first time flask.app.logger is accessed, this can lead to the destruction of log handlers that were purposefully added by the application.

I just tracked down a bug due to this that took me a very long time to debug because I had no idea this went on. To my eyes, it looked like the standard logging module was breaking at a seemingly random moment (it wasn't even my code that was accessing app.logger, it was Flask's internal error handling code). Therefore, I think one of two courses of action should be taken:

• Because this behavior of create_logger() seems very strange, perhaps it should be removed. As in don't delete log handlers that are already in place when create_logger() gets called.
• If there is a good reason for this behavior to remain, it should be documented clearly in app.logger's docstring.

I am happy to carry out either (or some other) change and send a pull request.

[itsjohncs]

Do any of the devs have thoughts on this issue? I'm happy to carry out any required changed.

[untitaker]

Can you give me an example code that does not do what you want? From what i see, adding log handlers already counts as accessing the logger.

[itsjohncs]

I ran into this problem because I allow the sysadmins to configure the logging handlers to suit their needs by having them set up logging in their configuration file. For example, the example configuration file I provide in my docs is this:

config = {}

config["web/DEBUG"] = False
config["web/SECRET_KEY"] = "asldfhlaskdjf"
config["web/HOST_URL"] = "http://localhost:5000"
config["web/USE_X_SENDFILE"] = True

import logging
import logging.handlers

# Explanation of this at http://serverfault.com/a/408491
class BOMLessFormatter(logging.Formatter):
    def format(self, record):
        return logging.Formatter.format(self, record).encode("utf-8")

logger = logging.getLogger("galah")
logger.setLevel(logging.DEBUG)
log_handler = logging.handlers.SysLogHandler(address = "/dev/log")

# Modify this formatter if you want to change the layout of log messages.
formatter = BOMLessFormatter("%(name)s[%(process)d]: %(message)s")
log_handler.setFormatter(formatter)

logger.addHandler(log_handler)

I don't really want to have to make them import app from my application as that just introduces more unpleasant circular dependencies, not to mention only one part of my project uses Flask.

There is a much more insidious case when this behavior becomes very annoying though... You may notice by glancing through my project's code that I always use logging directly, and never use app.logger. I did this originally because I couldn't figure out why my config file's logging handlers were being ignored, but now I do it because it adds consistency to my code (I only use Flask in one portion of the project). Now then, even though I never use app.logger, because Flask's internal error handling code accesses the logger object, my log handlers were randomly getting blown away in the middle of my application (the first time a non-HTTP exception occurred). I can code up an example Flask application the demonstrates this case, but I think it's fairly easy to see how it would happen.

[untitaker]

Couldn't you somehow get the standard handlers from the logging module and explicitly apply them to the flask logger (in your app's code)?

[itsjohncs]

I'm not sure I understand what you mean. Could you provide an example?

I don't see why the current functionality exists though (blowing away any log handlers). I already came up with a workaround for it (I just perform a "no-op" access to app.logger before I load the configuration), but that doesn't change the fact that it seems like very strange functionality. But even if the functionality should stay, it really needs to be documented. I spent a very long time debugging this problem, I should have just been able to glance at the documentation and see that this was the cause.

[untitaker]

Actually my suggestion was a vague idea, when looking at the docs of the logging module, i can't find a way to get any handlers.

I agree that this behavior should be documented.

[untitaker]

I don't see why the current functionality exists though

I think this is just lazy evaluation.

[itsjohncs]

I agree that this behavior should be documented.

At the very least it should be documented, but I really think the functionality should be removed (see below).

I think this is just lazy evaluation

Yes, this lazy evaluation. create_logger() is not called until the first time app.logger is accessed. The lazy evaluation component is not what I'm talking about however.

When create_logger() is called, all of the log handlers that have been registered are removed. This is the functionality I am speaking of, and the functionality I do not understand the purpose of.

[mitsuhiko]

I ran into so many issues if the old handlers were not cleared out. The problem is that the standard libary's logging module is not very clever and no matter how you try to use it it will break someone else's usecase. Especially all the unittests are creating apps over and over again and if flask would not clear out the loggers these would have more and more loggers as the tests are running.

Not sure what the correct solution to this problem is.

[itsjohncs]

I can't imagine too many scenarios when a user would want Flask to do this clearing of the log handlers for them. The scenario that your pointing out, the unit tests, makes me think that the unit tests themselves should be responsible for removing the log handlers they create (or a simpler solution would be to just clear the log handlers within the unit tests' setup code). It seems like whenever a user would want this, they would be capable of doing it themselves simply.

[reustle]

I believe I may have run into a related issue today. I have it described with code examples here: http://stackoverflow.com/questions/18672847/python-logger-activated-after-twilio

[mrj0]

I burned some time on this recently. For us the fix is to simply set LOGGER_NAME = 'flask' in our config and done. I would suggest that this should be the default instead of the import_name. Then you don't run the risk of interfering with the user's logging in their own package.

[jonblack]

Using the LOGGER_NAME setting helped me to create the correct "top-level" logger, but the default level for subsequent child loggers is being mysteriously set to WARNING instead of NOTSET (which means, use the parent's level). Here's an example output:

myapp -> DEBUG
myapp.factory -> WARNING
myapp.measurements -> WARNING
myapp.measurements.views -> WARNING

I worked around this by in the very beginning of my application, creating the same logger that Flask is going to create for me anyway and setting the level to debug:

import logging

_log = logging.getLogger(__name__)
_log.setLevel(logging.DEBUG)
...
# Other imports here
...
app = create_app() # app.logger is accessed in here for the first time

By taking ownership of logger creation, Flask is making a lot of assumptions (e.g. users want a StreamHandler; DEBUG is the default level) and adding a lot of surprises (handlers get deleted; the logger is created when app.logger is first accessed).

• Why does app.logger exist? Is there a reason to use app.logger over logging.getLogger()?
• What is Flask trying to achieve by creating the logger?
• Is it an option that Flask doesn't setup any logging at all?

[itsjohncs]

I would avoid Flask's logger if it's not configured to suite your needs already, as I don't think its issues will be resolved. To disable it stick this somewhere in your applications startup logic:

app.logger_name = "nowhere"
app.logger

The second line is necessary due to some processing that only happens when app.logger is first accessed.

[btoconnor]

Just coming here to voice my concern over this as well. I spent a lot of time trying to figure out why app.logger wasn't formatting and handling my log lines the way I configured them, only to find out flask was removing them.

My solution has been, like others have stated, to set the LOGGER_NAME to something unused in the config, and then manually use logging.getLogger() in my files. If app.logger will continue to have this behavior, it should really be documented - but ideally just removed.

[dtheodor]

This is a serious issue if you want the Flask.logger to be usable in an application that plays by the rules of the python logging module. At the moment I also resort to completely ignoring the Flask.logger, not to mention having this ugly line in my code app.logger just because I have to invoke the "lazy initialization" stuff.

Playing by the logging module's rules, you have 1 place at script startup where you initialize all your loggers, including custom loggers and library loggers, (commonly by using logging.config.dictConfig and fileConfig). And script startup does not necessarily mean Flask app creation. Here is library logging done right: http://docs.sqlalchemy.org/en/rel_0_9/core/engines.html#configuring-logging.

I can think of a couple ways to allow Flask to play with centralized log configuration

1. In the spirit of SQL alchemy's solution, do not add any of this custom code https://github.com/mitsuhiko/flask/blob/master/flask/logging.py#L50 unless a flag such as app.create_new_logger is set to True. If False, create_logger should simply do a return logging.getLogger(app.logger_name) and expect the user to have configured it properly.
2. Since logging.addHandler() will not add an already existing handler, you can instantiate your handlers once (at module level) and then add them to your logger without having to call the disrupting del logger.handlers[:]. The handlers have a dependency on app so the flask.current_app magic should suffice.

Thoughts?

[ghost]

@dtheodor I completely agree with you. I wasted a good morning figuring out why logging doesn't work in production mode. If effectively comes down to the lazy loading of the logger coupled with the removal of any handlers (via create_logger).

I worked around this by explicitly calling app.logger.

There are 2 options IMO:
1) Instead of deleting the handlers outright, re-add them after the class change
2) Create a wrapper so that the developer can disable the call to create_logger and define their own.

[crazygit]

@bhafichuk-redfall I completely agree with you. I wasted a good morning figuring out why config app logger from configure file not work.

[kerma]

So what's wrong with the #1311 that it has been hanging here for a year and more? Another soul here who spent hours to figure this out. Now I have to go with dropping app.logging usage and adding the ugly hack :(

[tinproject]

For the record, @jonblack:

Using the LOGGER_NAME setting helped me to create the correct "top-level" logger, but the default level for subsequent child loggers is being mysteriously set to WARNING instead of NOTSET (which means, use the parent's level). Here's an example output:

myapp -> DEBUG
myapp.factory -> WARNING
myapp.measurements -> WARNING
myapp.measurements.views -> WARNING

this happen because flask don't set explicitely the level for it's logger, instead _'subclass'_ the logger to return a effective level of DEBUG in the case of the level of the logger is NOSET (https://github.com/pallets/flask/blob/master/flask/logging.py#L61).
This allows debug messages to be logged whichever the effective level is inherited from it's parent.
But all the children are normal loggers (logging.Logger) so inherits their parent level, and as the Flask logger has really a NOSET level, surely, their inherit the default WARNING level from the root logger.

[davidism]

I've created #2436 that hopefully simplifies Flask's logging configuration. It also splits out and updates the documentation to help clarify how everything works. If anyone here wants to take a look and make sure it addresses the points brought up here, I'd appreciate it.

Closing this to move discussion either to the PR or #2023.