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: 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.

