Python logging multiple modules logger not working

Question

My goal is to log from multiple modules, while only configuring the logger in one place - in the main program. As shown in this answer, one should include

logging.config.fileConfig('/path/to/logging.conf') 

in the main program, then in all other modules include

logger = logging.getLogger(__name__)

I believe that's what I've done below, yet I get unexpected behaviour.

c.py

# c.py
import logging
import logging.config
import d

logging.config.fileConfig("logging.conf")
logger = logging.getLogger(__name__)

logger.warning('logging from c')
d.foo()

d.py

# d.py
import logging

logger = logging.getLogger(__name__)

# this will print when d is imported
logger.warning('logging from d on import')

def foo():
    # this does not print
    logger.warning("logging from d on call foo()")

Output

$ python c.py
logging from d on import
logging from c

What I would expect, is that when d.foo() executes in c.py, that a message would be logged from d, however, that's not the case. This is confusing because when the logger is called from module level in d, it logs a message to the console, but when called from inside foo() it doesn't.

Config file

[loggers]
keys=root

[handlers]
keys=consoleHandler

[formatters]
keys=simpleFormatter

[logger_root]
level=DEBUG
handlers=consoleHandler

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

[formatter_simpleFormatter]
format=%(message)s
datefmt=

Further analysis

So I've noticed that if I remove the line

logging.config.fileConfig("logging.conf")

from c.py, then logging from d.foo() works as expected. So there's either something wrong in the configuration file or due to the fact that I provide a configuration file something causes the logger in d.py to get messed up.

Question

1. Why does a message get logged from d when called from module level, but not from inside d.foo()?
2. And how can I achieve the goal of logging from multiple modules, while only configuring the logging in the main program?

Answer 1

The problem lies in the fact that

import d

comes before

logging.config.fileConfig("logging.conf")

as pointed out by @davidejones. Here's why:

As stated in the docs, when logging.config.fileConfig() is called, its default behaviour is to disable any existing loggers. So when import d happens, logger is initialised in d, then when logging.config.fileConfig() is called, the logger in d is disabled, which is why we didn't see any logging when d.foo() was called.

Solution

logging.config.fileConfig() takes an argument, disable_existing_loggers, which is True by default. Use

logging.config.fileConfig("logging.conf", disable_existing_loggers=False)

And output becomes

>>> python c.py
logging from d on import
logging from c
logging from d on call foo()

As expected.

Answer 2

I think that the import of d is happening before the config of the logger so doing something like this might give what you want?

# c.py
import logging
import logging.config

logging.config.fileConfig("logging.conf")
logger = logging.getLogger(__name__)

import d


logger.warning('logging from c')
d.foo()

it gives me these results

logging from d on import
logging from c
logging from d on call foo()

EDIT

Looking at the code it might make more sense to have a seperate file to have the logging setup then you import that once in you main file the other modules will have it then and it doesn't look as messy. So maybe having a logsetup.py like this

import logging
import logging.config

logging.config.fileConfig("logging.conf")

and then c.py looking like this instead which still gives the same results

# c.py
import logsetup
import logging
import d

logger = logging.getLogger(__name__)

logger.warning('logging from c')
d.foo()