Logging doesn't seem to be working correctly in python 3.9.4

Question

Goal:

To use the logging module in multiple files / modules in my python project. These logs should all go to one log file.

Issue:

The logging module in python 3.9.4 only seems to be working for a logging object in one file. The naming process, i.e. module naming doesn't seem to be working as well.

Question

In the "Examples" section is the logging module supposed to work in that manner? I can understand if you need to define a "root" or "initial" logger (the last example wouldn't be an issue). This doesn't seem correct to me. Am I wrong?

Examples

I coped the code exactly as it is from the logging cookbook here. I used the first example "Using Logging in Multiple Modules"

When I cut and paste the code runs with no errors. I added a new file just to test and the code runs well. see results below which matches the original run.

2021-05-18 20:13:56,270 - spam_application - INFO - creating an instance of auxiliary_module.Auxiliary
2021-05-18 20:13:56,270 - spam_application.auxiliary.Auxiliary - INFO - creating an instance of Auxiliary
2021-05-18 20:13:56,270 - spam_application - INFO - created an instance of auxiliary_module.Auxiliary
2021-05-18 20:13:56,270 - spam_application - INFO - calling auxiliary_module.Auxiliary.do_something
2021-05-18 20:13:56,270 - spam_application.auxiliary.Auxiliary - INFO - doing something
2021-05-18 20:13:56,270 - spam_application.auxiliary.Auxiliary - INFO - done doing something
2021-05-18 20:13:56,270 - spam_application - INFO - finished auxiliary_module.Auxiliary.do_something
2021-05-18 20:13:56,270 - spam_application - INFO - calling auxiliary_module.some_function()
2021-05-18 20:13:56,270 - spam_application.auxiliary - INFO - received a call to "some_function"
2021-05-18 20:13:56,270 - spam_application - INFO - done with auxiliary_module.some_function()

Below is the code in new_file.py ->

import logging

nf_logger = logging.getLogger('spam_application.new_file')

def test_logging():
    nf_logger.info('in test_logging()')

Below are the results with new_file.py which are good.

2021-05-18 20:13:56,270 - spam_application - INFO - creating an instance of auxiliary_module.Auxiliary
2021-05-18 20:13:56,270 - spam_application.auxiliary.Auxiliary - INFO - creating an instance of Auxiliary
2021-05-18 20:13:56,270 - spam_application - INFO - created an instance of auxiliary_module.Auxiliary
2021-05-18 20:13:56,270 - spam_application - INFO - calling auxiliary_module.Auxiliary.do_something
2021-05-18 20:13:56,270 - spam_application.auxiliary.Auxiliary - INFO - doing something
2021-05-18 20:13:56,270 - spam_application.auxiliary.Auxiliary - INFO - done doing something
2021-05-18 20:13:56,270 - spam_application - INFO - finished auxiliary_module.Auxiliary.do_something
2021-05-18 20:13:56,270 - spam_application - INFO - calling auxiliary_module.some_function()
2021-05-18 20:13:56,270 - spam_application.auxiliary - INFO - received a call to "some_function"
2021-05-18 20:13:56,270 - spam_application - INFO - done with auxiliary_module.some_function()
2021-05-18 20:13:56,270 - spam_application - INFO - before test_logging
2021-05-18 20:13:56,270 - spam_application.new_file - INFO - in test_logging()
2021-05-18 20:13:56,270 - spam_application - INFO - after test_logging

This is where the weird part comes in. If I replace the code in auxilary_module.py from module_logger = logging.getLogger('spam_application.auxiliary') to module_logger = logging.getLogger('__name__') I get the following results ->

2021-05-18 20:20:02,233 - spam_application - INFO - creating an instance of auxiliary_module.Auxiliary
2021-05-18 20:20:02,233 - spam_application.auxiliary.Auxiliary - INFO - creating an instance of Auxiliary
2021-05-18 20:20:02,233 - spam_application - INFO - created an instance of auxiliary_module.Auxiliary
2021-05-18 20:20:02,233 - spam_application - INFO - calling auxiliary_module.Auxiliary.do_something
2021-05-18 20:20:02,233 - spam_application.auxiliary.Auxiliary - INFO - doing something
2021-05-18 20:20:02,233 - spam_application.auxiliary.Auxiliary - INFO - done doing something
2021-05-18 20:20:02,234 - spam_application - INFO - finished auxiliary_module.Auxiliary.do_something
2021-05-18 20:20:02,234 - spam_application - INFO - calling auxiliary_module.some_function()
2021-05-18 20:20:02,234 - spam_application - INFO - done with auxiliary_module.some_function()
2021-05-18 20:20:02,234 - spam_application - INFO - before test_logging
2021-05-18 20:20:02,234 - spam_application.new_file - INFO - in test_logging()
2021-05-18 20:20:02,234 - spam_application - INFO - after test_logging

I'm missing this line - spam_application.auxiliary - INFO - received a call to "some_function"

If I replace nf_logger = logging.getLogger('spam_application.new_file') with nf_logger = logging.getLogger(__name__) I get the following results ->

2021-05-18 20:23:09,820 - spam_application - INFO - creating an instance of auxiliary_module.Auxiliary
2021-05-18 20:23:09,820 - spam_application.auxiliary.Auxiliary - INFO - creating an instance of Auxiliary
2021-05-18 20:23:09,820 - spam_application - INFO - created an instance of auxiliary_module.Auxiliary
2021-05-18 20:23:09,820 - spam_application - INFO - calling auxiliary_module.Auxiliary.do_something
2021-05-18 20:23:09,820 - spam_application.auxiliary.Auxiliary - INFO - doing something
2021-05-18 20:23:09,820 - spam_application.auxiliary.Auxiliary - INFO - done doing something
2021-05-18 20:23:09,820 - spam_application - INFO - finished auxiliary_module.Auxiliary.do_something
2021-05-18 20:23:09,820 - spam_application - INFO - calling auxiliary_module.some_function()
2021-05-18 20:23:09,820 - spam_application - INFO - done with auxiliary_module.some_function()
2021-05-18 20:23:09,820 - spam_application - INFO - before test_logging
2021-05-18 20:23:09,820 - spam_application - INFO - after test_logging

I'm missing the log line - spam_application - INFO - done with auxiliary_module.some_function().

If I replace logger = logging.getLogger('spam_application') with logger = logging.getLogger(__name__) I get the following results ->

2021-05-18 20:24:50,729 - __main__ - INFO - creating an instance of auxiliary_module.Auxiliary
2021-05-18 20:24:50,729 - __main__ - INFO - created an instance of auxiliary_module.Auxiliary
2021-05-18 20:24:50,729 - __main__ - INFO - calling auxiliary_module.Auxiliary.do_something
2021-05-18 20:24:50,729 - __main__ - INFO - finished auxiliary_module.Auxiliary.do_something
2021-05-18 20:24:50,729 - __main__ - INFO - calling auxiliary_module.some_function()
2021-05-18 20:24:50,729 - __main__ - INFO - done with auxiliary_module.some_function()
2021-05-18 20:24:50,729 - __main__ - INFO - before test_logging
2021-05-18 20:24:50,729 - __main__ - INFO - after test_logging

I'm missing a 5 log lines. The logging in the class object is not called.

In the advanced logging tutorial here a good convention is to use logger = logging.getLogger(__name__). That doesn't seem to work in python 3.9.4.

user_803194 · Answer

Loggers exist in a hierarchy. Every logger has their own level. The root loggers default level is WARNING.

The hierarchy works such that dot-separated names tell you where are logger belongs in it. A logger called x.y.z can be thought of as a logger named z that is a child of y which is itself a child of x. By default when a logger receives a log, it propagates them up the hierarchy to all its parents. So the logger called 'spam_application.auxiliary' is sending their logs to the spam_application logger. If you change the name to something that isn't a child of that anymore the logs will not be sent there. All loggers are however children of the root logger but that doesn't help you here because it's default level is WARNING and that is higher than INFO.

The __name__ convention is useful if your modules are also organized in a hierarchy, because in that case the loggers hierarchy will exactly match the hierarchy of your modules and submodules.

The documentation also has a useful graph to help determine when a log will be logged: https://docs.python.org/3/howto/logging.html#logging-flow

user_9808239 · Answer

I recommend using contextlib instead of the logging module. Personally I find the logging module quite hard to use. contextlib is very simple and intuitive, you can just redirect your output to a log file that you specify:

with open("log_file.log", "w") as log, contextlib.redirect_stdout(log), contextlib.redirect_stderr(log):

put this at the start of a function or a python file, everything printed underneath will be redirected to the log file, both stdout and stderr.

Logging doesn't seem to be working correctly in python 3.9.4

2 Answers