Is this a bug of logging module

Description:

import logging

logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)
logger.addHandler(logging.NullHandler())

logging.basicConfig()  # set formatter and handler for root logger(WARNING level)

logger.debug("This is a debug message")  # Should this be logged?

if I logged a message with matching level on the child logger, the message will also be propagated to the parent, even if the parent logger has a higher level configured.

Actual Result

DEBUG:__main__:This is a debug message

This message is logged by the handlers of the root logger, even if the root logger’s level is WARNING.

This behavior of basicConfig is documented:

This function does nothing if the root logger already has handlers configured, unless the keyword argument force is set to True.

I don’t see how this is related, because I do created a __main__ logger that is different from root logger in the example.

I believe the answer lies in propagate.

Messages are passed directly to the ancestor loggers’ handlers - neither the level nor filters of the ancestor loggers in question are considered.

The __main__ logger is set to debug. Then you configure the root logger with a basicConfig that has a stream handler. That stream handler does not have a level set, so it will emit logs sent to it from lower levels.

1 Like

Ah, I see. I think the behavior is still as documented, although it is a bit surprising. The documentation for propagate says (emphasis added):

If this attribute evaluates to true, events logged to this logger will be passed to the handlers of higher level (ancestor) loggers, in addition to any handlers attached to this logger. Messages are passed directly to the ancestor loggers’ handlers - neither the level nor filters of the ancestor loggers in question are considered.

It also documented that handlers by default have a “NOTSET” level which means they will process everything. So the NullHandler doesn’t log the message, but since it still has propagate == True, the message is sent to the handler of the root logger, which has level NOTSET, and thus handles and prints it as usual.

Another section of the docs seems to tell people to do this to suppress log messages. But it does say that this is to prevent your library from logging “in the absence of any logging configuration”. So I guess when you do basicConfig you’re setting up the log to output any messages that lower-level loggers handle, even if they don’t themselves output them.

It has been mentioned many times that the logging module is pretty messed up in various ways. This seems like another example of that. :C I suppose it could be useful to have a “SwallowHandler” or something which is like NullHandler but additionally has propagate = False so that it completely swallows all messages it handles.

The handler doesn’t have a propagate setting, the logger at that level has it. The logger objects are the nodes of the tree, passing messages up toward the root. Each node has one or more handlers that it can use to emit messages that it receives.

True.

Well, only sort of. :slight_smile: I mean, if it worked that way, you wouldn’t expect one logger to be sending messages to the handlers of another logger, right? The tree is actually much more messy and confusing, in that messages can be passed not only between loggers but from one logger to a handler of another. We could say that each node has one or more handlers that it or another node can use to emit messages that that node receives.

Thank you very much, so it turns out to be well-documented. Then it makes sense, changing the behavior may break existing applications.