Calling `logging` interferes other modules

user_342553 0
Viewed 66

Say I have the following a.py which calls b.py

b.py

import logging
  
logging.info('11111 in b')     

def do():                      
    logging.info('2222222 in b')

a.py

import logging
import sys
import b

logging.basicConfig(stream=sys.stdout, level=logging.INFO)
logging.info('11111111 in a')
b.do()

When I execute a.py, nothing gets logged to stdout, but when I comment out logging.info('11111 in b') from b.py as below:

b.py

import logging
  
# logging.info('11111 in b')     

def do():                      
    logging.info('2222222 in b')

I can see log output:

INFO:root:11111111 in a
INFO:root:2222222 in b

So obviously there is something to do with that commented out line, but I would have thought the basicConfig() would set something straight after importing b module but it's not.

Could someone please explain what's happening here?

python-3.x python
2 Answers

The import statement import b has triggered a logging event before the logging system gets configured. When events are logged with an unconfigured logging system, it gets auto-configured with a default configuration: a stream handler at level WARNING on stderr.

The subsequent basicConfig call does nothing if the root logger already has handlers configured. Hence the INFO level events are filtered out, because the root logger is configured with a handler at the higher threshold of WARNING.

The proper solution is ensure events are not logged before the logging system has been configured. Usually this means avoiding log events or doing any work at the global (module level) scope.

However, since Python 3.8 there is a workaround to force reconfiguring the logging system:

logging.basicConfig(stream=sys.stdout, level=logging.INFO, force=True)

In older Python versions, you could clear the root logging handlers manually:

del logging.getLogger().handlers[:]
logging.basicConfig(stream=sys.stdout, level=logging.INFO)
user_6740390

I suspect it has something to do with how the output is being configured. I don't think setting it in a.py will set it for both files, kind of like how you have to import logging in both files or else get an error.

If you add the basicConfig line to b.py, then you can keep your logging.info('11111 in b') and see it printed.

user_46386410
Related