python logging - message not showing up in child

Question

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 1

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.