Python logging: file handler not recording submodule logging calls

Question

I have a basic logging configuration file with 1 StreamHandler. After importing it into a main python script, I explicitly add a new FileHandler. This file handler successfully records all the log.[info,warn,...] calls that I make from the main file, but for some reason it ignores all the calls made from the submodules I import into the main file.

How can I fix this? I use Python 3.7 on Ubuntu 20.04. Here's a reproducible example:

main.py:

#!/usr/bin/env python

import logging
import logging.config

# Import basic logging config (which only contains a StreamHandler)
logging.config.fileConfig('logging.conf')
log = logging.getLogger(__name__)

# Add a FileHandler dedicated to the current main/executable file
fh = logging.FileHandler(filename='test.log', mode='w')
fh.setLevel(logging.INFO)

# Use the same format as the (only) existing StreamHandler
fh.setFormatter(logging.getLogger().handlers[0].formatter)
log.addHandler(fh)

# Successfully prints to console and log file
log.info("Info message from main")


import my_lib

# Succesfully prints to console, but not to log file
foo = my_lib.MyClass()

my_lib.py:

#!/usr/bin/env python

import logging
log = logging.getLogger(__name__)

class MyClass:    
    def __init__(self):
        log.info("Info message from submodule")
        log.warn("Warning message from submodule")
        log.error("Error message from submodule")

logging.conf:

[loggers]
keys=root

[handlers]
keys=consoleHandler

[formatters]
keys=simpleFormatter

[logger_root]
level=INFO
handlers=consoleHandler

[handler_consoleHandler]
class=StreamHandler
level=INFO
formatter=simpleFormatter
args=(sys.stdout,)

[formatter_simpleFormatter]
format=%(asctime)s - %(name)s - %(levelname)s - %(message)s

Context: my python project has multiple "main" executables and I want to associate a separate logging file to each. The console output, however, is the same for all so I created a common logging config file with the common StreamHandler.

Answer 1

The problem is caused by the fact that you have the FileHandler attached to the __main__ module (main.py) and the StreamHandler attached to the root logger. The messages logged in my_lib are handled by the handlers of the my_lib logger (there are none) and then the handlers of all ancestors - in this case that means the root logger's handlers, i.e. the StreamHandler writing to the console. Since the __main__ logger is not an ancestor of the my_lib logger, its handlers (just the FileHandler) isn't asked to handle events logged to the my_lib logger.

To fix this, you are better off using dictConfig() rather than fileConfig(): for example, with this configuration in logging.json:

{
    "version": 1,
    "disable_existing_loggers": false,
    "formatters": {
        "simple": {
            "format": "%(asctime)s - %(name)s - %(levelname)s - %(message)s"
        }
    },
    "handlers": {
        "console": {
            "class": "logging.StreamHandler",
            "stream": "ext://sys.stdout",
            "level": "INFO",
            "formatter": "simple"
        },
        "file": {
            "class": "logging.FileHandler",
            "filename": "tbd.log",
            "mode": "w",
            "level": "INFO",
            "formatter": "simple"
        }
    },
    "root": {
        "level": "INFO",
        "handlers": ["console", "file"]        
    }
}

and this slightly modified main program main.py:

#!/usr/bin/env python
import json
import logging
import logging.config
import os

with open('logging.json') as f:
    config = json.load(f)
lfn = os.path.basename(__file__).replace(".py", ".log")
config['handlers']['file']['filename'] = lfn
logging.config.dictConfig(config)
log = logging.getLogger(__name__)

log.info("Info message from main")

import my_lib

foo = my_lib.MyClass()

I get this on the console:

2022-05-30 13:49:55,353 - __main__ - INFO - Info message from main
2022-05-30 13:49:55,354 - my_lib - INFO - Info message from submodule
2022-05-30 13:49:55,354 - my_lib - WARNING - Warning message from submodule
2022-05-30 13:49:55,354 - my_lib - ERROR - Error message from submodule

and this in the file main.log:

2022-05-30 13:49:55,353 - __main__ - INFO - Info message from main
2022-05-30 13:49:55,354 - my_lib - INFO - Info message from submodule
2022-05-30 13:49:55,354 - my_lib - WARNING - Warning message from submodule
2022-05-30 13:49:55,354 - my_lib - ERROR - Error message from submodule