box box - 3 months ago 11
Python Question

python logging - message not showing up in child

I am having some difficulties using python's logging. I have two files, main.py and mymodule.py. Generally main.py is run, and it will import mymodule.py and use some functions from there. But sometimes, I will run mymodule.py directly.

I tried to make it so that logging is configured in only 1 location, but something seems wrong.

Here is the code.


# main.py
import logging
import mymodule

logger = logging.getLogger(__name__)

def setup_logging():
# only cofnigure logger if script is main module
# configuring logger in multiple places is bad
# only top-level module should configure logger
if not len(logger.handlers):
logger.setLevel(logging.DEBUG)
# create console handler with a higher log level
ch = logging.StreamHandler()
ch.setLevel(logging.DEBUG)
formatter = logging.Formatter('%(levelname)s: %(asctime)s %(funcName)s(%(lineno)d) -- %(message)s', datefmt = '%Y-%m-%d %H:%M:%S')
ch.setFormatter(formatter)
logger.addHandler(ch)

if __name__ == '__main__':
setup_logging()
logger.info('calling mymodule.myfunc()')
mymodule.myfunc()


and the imported module:

# mymodule.py
import logging

logger = logging.getLogger(__name__)

def myfunc():
msg = 'myfunc is being called'
logger.info(msg)
print('done with myfunc')


if __name__ == '__main__':
# only cofnigure logger if script is main module
# configuring logger in multiple places is bad
# only top-level module should configure logger
if not len(logger.handlers):
logger.setLevel(logging.DEBUG)
# create console handler with a higher log level
ch = logging.StreamHandler()
ch.setLevel(logging.DEBUG)
formatter = logging.Formatter('%(levelname)s: %(asctime)s %(funcName)s(%(lineno)d) -- %(message)s', datefmt = '%Y-%m-%d %H:%M:%S')
ch.setFormatter(formatter)
logger.addHandler(ch)
logger.info('myfunc was executed directly')
myfunc()


When I run the code, I see this output:

$>python main.py
INFO: 2016-07-14 18:13:04 <module>(22) -- calling mymodule.myfunc()
done with myfunc


But I expect to see this:

$>python main.py
INFO: 2016-07-14 18:13:04 <module>(22) -- calling mymodule.myfunc()
INFO: 2016-07-14 18:15:09 myfunc(8) -- myfunc is being called
done with myfunc


Anybody have any idea why the second logging.info call doesn't print to screen? thanks in advance!

Answer

Loggers exist in a hierarchy, with a root logger (retrieved with logging.getLogger(), no arguments) at the top. Each logger inherits configuration from its parent, with any configuration on the logger itself overriding the inherited configuration. In this case, you are never configuring the root logger, only the module-specific logger in main.py. As a result, the module-specific logger in mymodule.py is never configured.

The simplest fix is probably to use logging.basicConfig in main.py to set options you want shared by all loggers.