Logging an application in Python

Question

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.

Requisites:

1. provide logging in an easy way, preferentially by being able to initialize it with only one line in the Python modules

2. logging should not interfere with unit tests

3. it should not prevent the independent execution of individual modules

4. 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.

log.log_factory.py

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:

a_file.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.

My questions:

1. 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?

2. 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?

3. Other than the above points, what are the problems I should fix in the above code?

4. Am I reinventing the wheel?

• Greg Burghardt: Well, the answer to #2 is yes, you can avoid this. And the answer to #4 is most assuredly yes, you are reinventing the wheel. I would research Python logging packages first. You should also decide where logging is crucial, and only do it there instead of all over the place. This is why many loggers used in Java and C# use class reflection to insert logging without developers writing the logging calls in code.
• Quaestor Lucem: Hi Greg, thanks for your reply. I did read the logging documentation on docs.python.org, which includes advance usage: docs.python.org/3/howto/logging.html. Also read the logging cookbook, from the Python's logging author. I am trying to find a way to configure Python's native logging to avoid reinventing the wheel. From what you said, would I be correct in assume that is really not easy to configure and use Python logging across an application?
• user2313067: Why do you need a separate root logger? Python already has a root logger you can access using logging.getLogger().
• null: would dependency injection help?inject the logger into the classes that uses it? medium.com/@shivama205/dependency-injection-python-cb2b5f336dce

Answer 1

Loggers in Python logging modules are Singletons, crucially here is that everytime you fetch a logger with the same name, you're always fetching the same logger instance. You don't need to keep a reference to the logger instance as the logging module will do it for you. You can also configure the loggers before you create or use the logger.

Generally, you'd use the logging module in this way:

1. In your main module, you configure your loggers:

   if __name__ == "__main__":
    logging.fileConfig("production.ini")
    logging.getLogger().info("calling a")
    a_some_function()
    logging.getLogger().info("a called")
   

2. In other modules:

   logger = logging.getLogger(__name__)
   def some_function(arg):
    logger.info("info message")
    some_other_function(
    child_logger=logger.getChild(get_child_logger_name(arg))
    )
    yet_another_function()
    return "abc"
   def some_other_function(child_logger):
    child_logger.info("info message into a child logger")
   def yet_another_function():
    logging.getLogger("special").info("info message not to the module logger")
   

3. In unit test, it's simply the same as regular main app run, you're just using a different configuration:

   if __name__ == "__main__":
    logging.fileConfig("test.ini")
    unittest.main()
   

Answer 2

I solved the issue #1, having the logger creation in the middle of the imports, by changing the algorithm of log_factory. Now, this module will create the root_logger on first access and store it. When the "main" module is ready, it can retrieve it from log_factory and change the logging level if so desired.

New implementations:

log.log_factory.py import logging

__root_logger_initialized = False
__root_logger_name = 'application'
__root_logger = None
def create_logger(logger_name, logging_level=logging.INFO, log_file_name='log.log'):
 global __root_logger_initialized, __root_logger_name
 if not __root_logger_initialized:
 __create_root_logger(logging_level, log_file_name)
 __root_logger_initialized = True
 hierarchized_logger_name = __root_logger_name + '.' + logger_name
 return logging.getLogger(hierarchized_logger_name)
def __create_root_logger(logging_level, log_file_name):
 global __root_logger
 logger = logging.getLogger(__root_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)
 __root_logger = logger
def get_root_logger():
 return __root_logger
def change_logging_level(logging_level):
 __root_logger.setLevel(logging_level)

main.py

import logging
from log.logger_factory import get_root_logger, change_logging_level
from a_file import some_function as a_some_function
from util.another_file import another_function
logger = get_root_logger()
change_logging_level(logging.DEBUG)
logger.info("calling a_some_function")
a_some_function()
logger.info("a_some_function called")
logger.info("calling another_function")
another_function()
logger.info("another_function called")

• Alexander: What's the point of the __root_logger global, if you appliation is going to be accessing it via its own reference? Get rid of the global.