Why does logging seem to require a handler in each module in order to print to console?

StackOverflow https://stackoverflow.com/questions/23486310

  •  16-07-2023
  •  | 
  •  

Question

In my programs, I generally want to log to both a file and to the screen. If I import a module, I want the calls to logger within that module's functions/classes to also result in a log to a file and the screen. Test_module_A does this, and test_module_B logs to the file but not the screen. Is this because the loggers in the modules propagate up to the root logger which through basicConfig is only setup to log to the file? I just want to make sure I'm using logging properly, as I am going to rewrite all my code to use this type of logging rather than "print." Going forward, I am only going to use logging and not print, as I figure logging is more flexible. Is this a good idea?

main.py

import logging

logger = logging.getLogger(__name__)

task_file='temp.txt'
format_str = '%(asctime)s %(module)s %(levelname)s: %(message)s'
datefmt_str = '%m/%d/%Y %I:%M:%S%p'
logging.basicConfig(filename=task_file, format=format_str, datefmt=datefmt_str, 
                    level=logging.INFO)
console = logging.StreamHandler()
#console.setLevel(logging.INFO)
formatter = logging.Formatter(format_str)
formatter.datefmt = datefmt_str
console.setFormatter(formatter)
logger.addHandler(console)

logger.info("from main.py")
import test_module_A
import test_module_B

test_module_A.py

import logging

logger = logging.getLogger(__name__)
format_str = '%(asctime)s %(module)s %(levelname)s: %(message)s'
datefmt_str = '%m/%d/%Y %I:%M:%S%p'
console = logging.StreamHandler()
formatter = logging.Formatter(format_str)
formatter.datefmt = datefmt_str
console.setFormatter(formatter)
logger.addHandler(console)

logger.info("upon import of test_module_A")

test_module_B.py

import logging

logger = logging.getLogger(__name__)

logger.info("upon import of test_module_B")

Upon running main.py:

#screen output
05/06/2014 12:36:33AM main INFO: from main.py
05/06/2014 12:36:33AM test_module_A INFO: upon import of test_module_A

# test.txt
05/06/2014 12:36:33AM main INFO: from main.py
05/06/2014 12:36:33AM test_module_A INFO: upon import of test_module_A
05/06/2014 12:36:33AM test_module_B INFO: upon import of test_module_B
Was it helpful?

Solution

It's not good practice to configure logging (add handlers, etc.) in each module: the way to do it is to just have

logger = logging.getLogger(__name__)

and actual logging calls in each module as required, and only have the configuration done in one place (called from the main script early on)

if __name__ == '__main__':
    logging.basicConfig(level=..., format=..., ...) #or other configuration code
    handler = logging.FileHandler(...)
    # set formatters, filters etc.
    logging.getLogger().addHandler(handler) # add to root logger
    main()

The basicConfig() call adds to the root logger a handler which writes to sys.stderr, and together with the FileHandler added explicitly, the logs from all modules should be written to both screen and file.

Licensed under: CC-BY-SA with attribution
Not affiliated with StackOverflow
scroll top