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.
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 itsdisable_existing_loggers
argument:If you change your code to
the problem should go away.
Note that existing loggers are only disabled when they are not explicitly named in the configuration file. For example:
No idea why the default value for
disable_existing_loggers
is the way it is ...