Random notes from mg

a blog by Marius Gedminas

Marius is a Python hacker. He works for Programmers of Vilnius, a small Python/Zope 3 startup. He has a personal home page at http://gedmin.as. His email is marius@gedmin.as. He does not like spam, but is not afraid of it.

Thu, 12 Apr 2012

Logging levels and hierarchies

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)  # <-- that's the default level, actually
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.

posted at 18:01 | tags: | permanent link to this entry | 3 comments
Thanks for that Marius, I've never really taken the time to grok the logging module. Your blog does invite the question though: how do you get the behavior that you actually wanted? i.e., what you originally thought would happen?
posted by mike at Fri Apr 13 00:22:18 2012
Mike: you could set the logging levels on the handlers directly.
posted by Marius Gedminas at Fri Apr 13 17:19:29 2012
My level of understanding of the logging module is similar to yours.  Every time I think I understand it, I learn I'm wrong.

I would have voted that the current 'NOTSET' be used as you describe and a constant with a more descriptive name, 'INHERIT_FROM_PARENT' perhaps, be used to avoid such confusion.
posted by JS at Tue Jul 16 00:54:00 2013

Name (required)


E-mail (will not be shown)


URL


Comment (some HTML allowed)