Python root logger messages not being logged via handler configured with fileConfig

Question

The Problem:

Given a logging config and a logger that employs that config, I see log messages from the script in which the log handler is configured, but not from the root logger, to which the same handler is assigned.

Details:

(Using Python 2.7)

I have a module my_mod which instantiates a logger. my_mod has a function my_command which logs some messages using that logger. my_mod exists inside of a library my_lib, so I don't want to configure the logger with any handlers; as recommended, I want to leave the log handling to the developer using my_mod. my_mod looks like:

import logging

LOGGER = logging.getLogger(__name__)

def my_command():
    LOGGER.debug("This is a log message from module.py")
    print "This is a print statement from module.py"

I also have a python script my_script.py, which uses my_mod.my_command. my_script.py instantiates a logger, and in this case I do have handlers and formatters configured. my_script.py configures handlers and formatters using fileConfig and a config file that lives alongside my_script.py:

import os
import logging
import logging.config
from my_mod.module import my_command

logging.config.fileConfig('{0}/logging.cfg'.format(
    os.path.dirname(os.path.realpath(__file__))))
LOGGER = logging.getLogger(__name__)

LOGGER.debug("This is a log message from script.py")
my_command()

From what I can tell, my config file appears to be set up correctly...

[loggers]
keys=root,script

[handlers]
keys=consoleHandler

[formatters]
keys=simpleFormatter

[logger_root]
level=DEBUG
handlers=consoleHandler

[logger_script]
level=DEBUG
handlers=consoleHandler
qualname=script
propagate=0

[handler_consoleHandler]
class=StreamHandler
level=DEBUG
formatter=simpleFormatter
args=(sys.stdout,)

[formatter_simpleFormatter]
format=%(asctime)s [%(levelname)s] %(name)s: %(message)s
datefmt=

...but when I run my_script.py I get only the log line from my_script.py, and not the one from my_mod.my_command. I know that my_command is working, though, because the print statement in my_command after the debug log statement successfully prints to the console:

20:27 $ python script.py 
2015-06-15 20:27:54,488 [DEBUG] __main__: This is a log message from script.py
This is a print statement from module.py

What am I doing wrong?

NOTE: The example shows using debug, but even when I keep logging.cfg specifying level=DEBUG (I also tried level=NOTSET) for root logger and call LOGGER.info(message) in my_command, nothing is logged to the console.

Answer 1

A potential problem is that you are importing the module before you set up the logger configuration. That way, the module requests a logger before the logging is setup.

Looking a fileConfig()'s documentation, the reason subsequent logging to the pre-obtained loggers fails is the default value for its disable_existing_loggers argument:

logging.config.fileConfig(fname, defaults=None, disable_existing_loggers=True)

If you change your code to

logging.config.fileConfig(
    '{0}/logging.cfg'.format(os.path.dirname(os.path.realpath(__file__))),
    disable_existing_loggers=False
)

the problem should go away.

Note that existing loggers are only disabled when they are not explicitly named in the configuration file. For example:

import logging
import logging.config

lFooBefore = logging.getLogger('foo')
lScriptBefore = logging.getLogger('script')
logging.config.fileConfig('logger.ini')

lFooBefore.debug('Does not log')
lScriptBefore.debug('Does log')
logging.getLogger('foo').debug('Does also not log')
logging.getLogger('bar').debug('Does log')

No idea why the default value for disable_existing_loggers is the way it is ...