Logging module weirdness, wrong display of log message?

Question

Here is a small example of something I find very weird about the logging module:

import logging
logging.basicConfig()

#
# making a hierarchy like this:
#     root
#       |- session
#             |-session.foo
#
root_logger = logging.getLogger()
session_logger = logging.getLogger("session")
foo_logger = logging.getLogger("session.foo")
#
# root_logger and session_logger effective log levels
# are set to 30 (= WARNING)
#
foo_logger.debug("WA") #nothing is printed, so far so good
#
# and now enters the problem...
#
foo_logger.setLevel(logging.DEBUG)
foo_logger.debug("HELLO") #HELLO log message is printed!!!

I do not get why the 'HELLO' log message is printed, to my understanding since there is no handler attached to logger foo_logger the log message should bubble up, and effectively be stopped by higher level logger (session), since its level is set to WARNING (by default).

It seems like setting the level on foo_logger gives it rights to display through the handler but it is very unclear to me.

Can someone explain to me why the message is printed ? And what should I do to have the logger hierarchy as I would like ?

this may be useful https://stackoverflow.com/questions/8391411/suppress-calls-to-print-python#8391735 — Dadu Khan, May 28 '19 at 14:48
@DaduKhan sorry but it does not help, since the link you provide is not related to Python logging. My problem is not with print, it is with the fact I can't understand how loggers hierarchy and rules to display or not messages are applied — mguijarr, May 28 '19 at 14:50
`foo_logger` had inherited its logging level from its parent, then you overrode that level. — pythomatic, May 28 '19 at 14:53
@Eqomatic can you elaborate? `foo_logger` has no handler. `.propagate` is set to `True` so I would have expected the log message to bubble up to `session` logger. And the message to not be displayed... — mguijarr, May 28 '19 at 14:56
`foo_logger` also inherited the handler from its parent since `.propogate` is set to `True`. — pythomatic, May 28 '19 at 14:59

score 1 · Accepted Answer · answered May 28 '19 at 15:10

Both loggers AND handlers have a level setting, and the default level for handlers is 0. You'd need to set the level of the parent handler - in your case root_logger.handlers[0] above logging.DEBUG to filter out the debug() calls on foo_logger:

root_logger.handlers[0].level = logging.WARN
foo_logger.debug("peekaboo") # should not be printed

Note that logging.basicConfig() only does a very simplistic config - it's mostly meant as a way to get started with logging, for any serious configuration you want dictConfig instead, which let you specify the handlers, formatters, levels etc as you see fit. Also note that a logger actually has a list of handlers (not a single one) and that multiple loggers can use the same handler, so who logs what (and where) depends on the combination of loggers AND handlers levels (and on the logger's propagate option too).

As a practical example, on my current (django) project we have (amongst others) a "console" handler (logs to stdout, which gunicorn redirects to it's own log file) whose level is set to INFO and a "notify" handler (sends emails notifications) with level set to WARN, so that some of our loggers (those for the most sensitive parts) will send INFO and above messages to gunicorn's logs and send WARN messages and above as notification emails too.

Logging module weirdness, wrong display of log message?

1 Answers1