Trying to understand logging.Filter

[Rene Pijlman]

I'd expect the program below to put only one line with "Eat me" in the log
file. However, I get this with Python 2.4.2 in WingIDE on Windows XP:

Eat me
Ignore me

My understanding is:
1. Event "Ignore me" is logged to logger 'spam'.
2. Logger 'spam' has no handler associated with it, so this logger doesn't
do anything with the event.
3. The event is dispatched to the root logger as well, since this is an
ancestor of 'spam'. This works as expected, since the event "Eat me" is
logged by the root logger.
4. The root logger has a Filter, which requires the logger of the event to
be 'ham', or offspring thereof. 'spam' is not offspring of 'ham' in the
dotted name hierarchy, so the event should be ignored.

So why does "Ignore me" end up in the logfile? What am I missing?

import logging

rootLogger = logging.getLogger()
rootLogger.addHandler(logging.FileHandler(r'C:\Scratch\SiteChecker\Sitechecker.log'))
rootLogger.addFilter(logging.Filter('ham'))
rootLogger.setLevel(logging.DEBUG)

logging.getLogger('ham.eggs').info("Eat me")
logging.getLogger('spam').info("Ignore me")
logging.getLogger().info("Ignore me too")

logging.shutdown()

 

[Rene Pijlman]

Rene Pijlman:

3. The event is dispatched to the root logger as well,

Got it. The event is not dispatched to ancestor loggers, but to the
handlers associated with ancestor loggers (Doc: "In addition to any
handlers directly associated with a logger, all handlers associated with
all ancestors of the logger are called to dispatch the message.").

Filters of ancester loggers are not applied, therefore, but filters of
handlers of ancestor loggers are. When I add the filter to the handler
rather than the logger, it works as expected:

import logging

rootLogger = logging.getLogger()
handler = logging.FileHandler(r'C:\Scratch\SiteChecker\Sitechecker.log')
handler.addFilter(logging.Filter('ham'))
rootLogger.addHandler(handler)
rootLogger.setLevel(logging.DEBUG)

logging.getLogger('ham.eggs').info("Eat me")
logging.getLogger('spam').info("Ignore me")
logging.getLogger().info("Ignore me too")

logging.shutdown()