Python logging incompatibilty between 2.5 and 2.6

Question

Could you help me solve the following incompatibility issue between Python 2.5 and 2.6?

logger.conf:

[loggers]
keys=root,aLogger,bLogger

[handlers]
keys=consoleHandler

[formatters]
keys=

[logger_root]
level=NOTSET
handlers=consoleHandler

[logger_aLogger]
level=DEBUG
handlers=consoleHandler
propagate=0
qualname=a

[logger_bLogger]
level=INFO
handlers=consoleHandler
propagate=0
qualname=b

[handler_consoleHandler]
class=StreamHandler
args=(sys.stderr,)

module_one.py:

import logging
import logging.config

logging.config.fileConfig('logger.conf')
a_log = logging.getLogger('a.submod')
b_log = logging.getLogger('b.submod')

def function_one():
    b_log.info("function_one() called.")

module_two.py:

import logging
import logging.config

logging.config.fileConfig('logger.conf')
a_log = logging.getLogger('a.submod')
b_log = logging.getLogger('b.submod')

def function_two():
    a_log.info("function_two() called.")

logger.py:

from module_one import function_one
from module_two import function_two

function_one()
function_two()

Output of calling logger.py under Ubuntu 9.04:

$ python2.5 logger.py
$

$ python2.6 logger.py
function_one() called.
function_two() called.
$

Answer 1

I don't understand the reasons of this behavior myself but as you well stated in 2.6 it works differently. We can assume this is a bug affecting 2.5

As a workaround I suggest the following:

extra_module.py:

import logging
import logging.config

logging.config.fileConfig('logger.conf')
a_log = logging.getLogger('a.submod')
b_log = logging.getLogger('b.submod')

module_one.py:

from extra_module import a_log

def function_one():
    a_log.info("function_one() called.")

module_two.py:

from extra_module import b_log

def function_two():
    b_log.info("function_two() called.")

by using this scheme I was able to run logger.py on python2.5.4 with the same behavior as of 2.6

Answer 2

Interesting... I played a little in the console and it looks like the second call to logging.config.fileConfig is mucking things up. Not sure why this is though... Here's a transcript that shows the problem:

lorien$ python2.5
Python 2.5.1 (r251:54863, Feb  6 2009, 19:02:12) 
[GCC 4.0.1 (Apple Inc. build 5465)] on darwin
Type "help", "copyright", "credits" or "license" for more information.
>>> import logging
>>> import logging.config
>>> logging.config.fileConfig('logger.conf')
>>> alog = logging.getLogger('a.submod')
>>> alog.info('foo')
foo
>>> import logging
>>> import logging.config
>>> alog.info('foo')
foo
>>> logging.config.fileConfig('logger.conf')
>>> alog.info('foo')
>>> alog = logging.getLogger('a.submod')
>>> alog.info('foo')
>>> 
>>> blog = logging.getLogger('b.submod')
>>> blog.info('foo')
foo
>>>

As soon as I call logging.config.fileConfig the second time, my logger instance stops logging. Grabbing a new logging instance doesn't help since it's the same object. If I wait until after configuring both times to fetch the logger instances, then things work - this is why the blog instance works.

My suggestion is to delay grabbing the logger instances until you are in the functions. If you move the calls to logging.getLogger() into function_one and function_two, then everything works well.

Answer 3

This is a bug which was fixed between 2.5 and 2.6. The fileConfig() function is intended for one-off configuration and so should not be called more than once - however you choose to arrange this. The intended behaviour of fileConfig is to disable any loggers which are not explicitly mentioned in the configuration, and leave enabled the mentioned loggers and their children; the bug was causing the children to be disabled when they shouldn't have been. The example logger configuration mentions loggers 'a' and 'b'; after calling getLogger('a.submod') a child logger is created. The second fileConfig call wrongly disables this in Python 2.5 - in Python 2.6 the logger is not disabled as it is a child of a logger explicitly mentioned in the configuration.

Answer 4

I was able to fix this by changing the names of the loggers like so, in both files:

logging.config.fileConfig('logger.conf')
a_log = logging.getLogger('a')
b_log = logging.getLogger('b')

I'm not sure of the exact error, but the v2.5 logger module seems to have trouble matching names passed to getLogger() with names in the config file.