CODEWITHSUNDEEP
pythonlogging
box
box

Reputation: 93

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!

Upvotes: 8

Views: 8536

Answers (4)

Ujjwal Singh
Ujjwal Singh

Reputation: 4988

Chaining through getChild method sorted the issue of sub-module's messages Not showing up.
Also when using the root logger (unnamed), debug messages from other library modules also began showing up. Hence I used a named logger.

Main file:

logging.getLogger('app')

Module file

logger = logging.getLogger('app').getChild(__name__)

Message show up as:

<app>.<sub_module>

Upvotes: 0

Alaroff
Alaroff

Reputation: 2298

While the logging-package is conceptually arranged in a namespace hierarchy using dots as separators, all loggers implicitly inherit from the root logger (like every class in Python 3 silently inherits from object). Each logger passes log messages on to its parent.

In your case, your loggers are incorrectly chained. Try adding print(logger.name) in your both modules and you'll realize, that your instantiation of logger in main.py is equivalent to

logger = logging.getLogger('__main__')

while in mymodule.py, you effectively produce

logger = logging.getLogger('mymodule')

The call to log INFO-message from myfunc() passes directly the root logger (as the logger in main.py is not among its ancestors), which has no handler set up (in this case the default message dispatch will be triggered, see here)

Upvotes: 1

Kemin Zhou
Kemin Zhou

Reputation: 6891

Chepner is correct. I got absorbed into this problem. The problem is simply in your main script

16 log = logging.getLogger() # use this form to initialize the root logger
17 #log = logging.getLogger(__name__) # never use this one

If you use line 17, then your imported python modules will not log any messages

In you submodule.py

import logging
logger = logging.getLogger()
logger.debug("You will not see this message if you use line 17 in main")

Hope this posting can help someone who got stuck on this problem.

Upvotes: 5

chepner
chepner

Reputation: 531490

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.

Upvotes: 6

Related Questions