I remember when the logging package seemed big and complicated and
forbidding. And then I remember when I finally "got" it, started using it,
even liked it. And then I've discovered that I didn't really understand
the model after all.
Consider this: we have two loggers
root
\
-- mylogger
configured as follows:
import logging
root = logging.getLogger()
root.setLevel(logging.INFO)
root.addHandler(logging.FileHandler("info.log"))
mylogger = logging.getLogger('mylogger')
mylogger.setLevel(logging.DEBUG)
mylogger.addHandler(logging.FileHandler("debug.log"))
What happens when I do mylogger.debug('Hi')?
Answer: the message appears in both debug.log and info.log.
That was surprising to me. I'd always thought that a logger's level was
a gatekeeper to all of that logger's handlers. In other words, I always
thought that when a message was propagating from a logger to its parent (here
from mylogger to root), it was also being filtered against the parent's log
level. That turns out not to be the case.
What actually happens is that a message is tested against the level of
the logger where it was initially logged, and if it passes the check, it
gets passed to all the handlers of that logger and all its ancestors with no
further checks. Unless the propagation is stopped somewhere by one of the
loggers having propagate set to False. And of course each handler has its own
level filtering. And I'm ignoring filters
and the global level override.
Part of the confusion was caused by my misunderstanding of
logging.NOTSET. I assumed, incorrectly, that it was just a
regular logging level, one even less severe than DEBUG. So when I
wrote code like this:
import logging
root = logging.getLogger()
root.setLevel(logging.INFO)
root.addHandler(logging.FileHandler("info.log"))
mylogger = logging.getLogger('mylogger')
mylogger.setLevel(logging.NOTSET)
mylogger.debug("debug message")
I saw the debug message being suppressed and assumed it was because of the
root logger's level. Which is correct, in a way, just not the way I thought
about it.
NOTSET does not mean "pass all messages through", it
means "inherit the log level from the parent logger". The documentation
actually describes
this, although in a rather convoluted way. My own fault for misunderstanding
it, I guess.
