Recently I have worked in a small standalone Python console application and have inherited some code from another team. Although some of us have written small Python scripts in the past, none of us are experienced in Python.
One thing that bothered me was the way logging was done - the start module would configure the logging and it would pass the logger object as a parameter for all other functions and modules, which is not only cumbersome but also hard to test.
We will start a new project in the near future and I would like to find a better way of logging a standalone Python console application.
For Java, I would use slf4j or log4j, defining a log configuration file and then creating a logger for each class in a single line.
After researching, I built a proof of concept of adding a log to a Python application, but I am pretty sure it is not good, so I would like to see how I could improve it.
provide logging in an easy way, preferentially by being able to initialize it with only one line in the Python modules
logging should not interfere with unit tests
it should not prevent the independent execution of individual modules
when running in production, there is an optional parameter, --debug, that should change the logging level from INFO to DEBUG.
Design idea: a "factory" module will provide creation of loggers. When it is first called, the first client becomes the root logger, from where all others will inherit. If the root logger already exists, just create a standard logger.
import logging __root_logger_initialized = False __root_logger_name = '' def create_logger(logger_name, logging_level=logging.INFO, log_file_name='log.log'): global __root_logger_initialized, __root_logger_name if __root_logger_initialized: hierarchized_logger_name = __root_logger_name + '.' + logger_name return logging.getLogger(hierarchized_logger_name) __root_logger_name = logger_name return __create_root_logger(logger_name, logging_level, log_file_name) def __create_root_logger(logger_name, logging_level, log_file_name): global __root_logger_initialized __root_logger_initialized = True logger = logging.getLogger(logger_name) logger.setLevel(logging_level) log_file_handler = logging.FileHandler(log_file_name, mode='w') # TODO: remove mode W! log_formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s') log_file_handler.setFormatter(log_formatter) logger.addHandler(log_file_handler) return logger
The loader of the application, main.py, is the module that will start the application:
import logging from log.log_factory import create_logger # need to be here, *before* importing other modules, otherwise, they will be defining the log # first, ignoring the log level that should be set by the starting point. # TODO is there any way to circumvent this? logger = create_logger(__name__, logging.DEBUG) from a_file import some_function as a_some_function logger.info("calling a") a_some_function() logger.info("a called")
The other modules will create the logger and use it, under the root logger created by main.py:
from log.log_factory import create_logger logger = create_logger(__name__) def some_function(): logger.info("info message") logger.warning("warning message") logger.debug("debug message") logger.critical("critical message") return "abc"
Running main.py produces this output:
2018-10-09 17:40:01,038 - __main__ - INFO - calling a 2018-10-09 17:40:01,038 - __main__.a_file - INFO - info message 2018-10-09 17:40:01,038 - __main__.a_file - WARNING - warning message 2018-10-09 17:40:01,039 - __main__.a_file - DEBUG - debug message 2018-10-09 17:40:01,039 - __main__.a_file - CRITICAL - critical message 2018-10-09 17:40:01,039 - __main__ - INFO - a called
And if I run the unit test test_unit_sample.py:
import unittest from a_file import some_function class SampleTest(unittest.TestCase): def test_some_test(self): response = some_function() self.assertEqual("abc", response) if __name__ == "__main__": unittest.main()
The test works without problem and the log file is still created, although using defaults only (INFO level, instead of DEBUG, as expected):
2018-10-09 17:45:11,718 - a_file - INFO - info message 2018-10-09 17:45:11,719 - a_file - WARNING - warning message 2018-10-09 17:45:11,719 - a_file - CRITICAL - critical message
In terms of functionality itself, this is roughly what I was looking for.
In order to make main.py log configurations reach log.log_factory first, I need to call the factory before importing my other modules, which is really bad - is there any way I could circumvent this?
When I run the unit_test, a log file will be created in the directory that contains the test - is it possible to avoid this?
Other than the above points, what are the problems I should fix in the above code?
Am I reinventing the wheel?