How to use logging.getLogger(__name__) in multiple modules

Question

From the logging howto for Python 2.7 (my emphasis):

A good convention to use when naming loggers is to use a module-level logger, in each module which uses logging, named as follows:

logger = logging.getLogger(__name__)

This means that logger names track the package/module hierarchy, and it’s intuitively obvious where events are logged just from the logger name.

Sounds like good advice.

Now, the logging cookbook provides an example for multiple modules, which uses hard-coded logger names instead of the __name__ constant. In the "main module" from the example we find

logger = logging.getLogger('spam_application')

and in the "auxiliary module" we find

module_logger = logging.getLogger('spam_application.auxiliary')

I copied this example verbatim into a package folder with the following structure:

cookbook-example
|- __init__.py
|- main_module.py
|- auxiliary_module.py

This runs without issue, producing the expected logging output from both the main module and the auxiliary module, but here's the thing:

If I now replace the hard-coded logger names by the __name__ constant, as recommended by the logging howto, the cookbook example breaks down: I only get logging messages from the main module, but nothing from the auxiliary module.

I must be missing something obvious. Any ideas what I am doing wrong?

Note:

There are a lot of very similar questions and related answers, e.g.: 1, 2, 3, 4, 5, 6, and many more. However, none of those appear to address this specific question.

--Edit--

Here's a minimal example based on the cookbook example, with the explicit name strings replaced by __name__.

main_module.py

import logging
import auxiliary_module

# create and configure main logger
logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)
# create console handler with a higher log level
handler = logging.StreamHandler()
handler.setLevel(logging.DEBUG)
# create formatter and add it to the handler
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
handler.setFormatter(formatter)
# add the handler to the logger
logger.addHandler(handler)

logger.info('message from main module')
auxiliary_module.some_function()

auxiliary_module.py

import logging

# create logger
module_logger = logging.getLogger(__name__) 

def some_function():
    module_logger.info('message from auxiliary module')

Accouplement

Answer 1

As pointed out by @shmee in this answer, the logger hierarchy must be defined explicitly in the logger name, using dot-notation. That is, if the logger name in main_module.py is e.g. 'a', then the logger name in auxiliary_module.py must be 'a.b' (not just 'b'), in order for it to inherit the configuration of logger 'a'. This is also mentioned in the getLogger() documentation.

However, this should be taken care of automatically when using __name__, as noted in the logging how-to:

This means that logger names track the package/module hierarchy, and it’s intuitively obvious where events are logged just from the logger name.

The thing is, for this to work, you need to use __name__ in the correct way, and I did not do that.

The problem in my example is in the organization of the files in the cookbook-example package folder:

Both the main module and the auxiliary module are at the same level (i.e. in the same folder). So, as explained here, the __name__ for the main module will then be '__main__' (as it is the top-level script), and the __name__ for the auxiliary module will be 'auxiliary_module' (i.e. the filename), NOT '__main__.auxiliary_module'.

As a result, the logger in the auxiliary module will be a child of the root logger, not a child of the '__main__' logger, and it will thus inherit the root logger configuration (which still has the default logging level WARNING) instead of the configuration specified in the main module.

So, to make the example work, we have several options:

1. Replace getLogger(__name__) in the main module by getLogger(). This will apply the config to the root logger and therefore also to the auxiliary module logger, as suggested by @shmee.

2. Replace getLogger(__name__) in the auxiliary module by getLogger('__main__.' + __name__). The result will be equivalent to the original cookbook-example (except that the main logger is now called '__main__' instead of 'spam_application').

Accouplement

For some reason using logger = logging.getLogger() in both the main_module.py and auxiliary_module.py looks to be working too. Does anyone know if that is ok or if there is something really bad hidden underneath please? – Violet

@Aenaon: according to the docs getLogger() (without an input argument) will return the root logger. So, indeed, you will see logging output from both main_module and auxiliary_module, but both messages will come from the root logger. The point of using getLogger(__name__) is that it lets us know from which module the log message originates. – Accouplement

@Aenaon: to clarify, instead of 2021-04-13 10:27:58 - root - INFO - message from auxiliary module we want to see 2021-04-13 10:27:58 - auxiliary_module - INFO - message from auxiliary module – Accouplement

Answer 2

The naming of the loggers is what you are missing. In the example, a logger named spam_application is created in the main module. Then handlers and formatters are created and added to that logger.

In auxiliary_module loggers are created with names that start with spam_application resp. spam_application.auxiliary. This effectively creates a hierarchy of loggers that propagate to their respective parents unless explicitly disabled. This hierarchy is spam_appliclation <- spam_application.auxiliary <- spam_application.auxiliary.Auxiliary or logger <- module_logger <- self.logger in the case of the cookbook example.

If you replace the explicit logger names by __name__ you end up having a configured logger named __main__ in your main module, which is configured with handlers, but the naming of your auxiliary loggers is not in a way that it would create a hierarchy, hence your auxiliary_module loggers propagate to the implicit root logger which has no handlers configured.

Try the following: Change your class' init method as follows:

def __init__(self):
    self.logger = logging.getLogger('spam_application.auxiliary.Auxiliary')
    print self.logger.parent
    self.logger.info('creating an instance of Auxiliary')

Then run your main module once with

self.logger = logging.getLogger('spam_application.auxiliary.Auxiliary')

and once with

self.logger = logging.getLogger(__name__)

The output should look like this:

<Logger spam_application.auxiliary (WARNING)> # with explicit logger name
<RootLogger root (WARNING)>                   # using __name__

Breadnut

Thanks, I was thinking along those lines (see minimal example after edit). But do we really need to define the hierarchy explicitly? To me the statement "This means that logger names track the package/module hierarchy ..." from the logging howto would suggest otherwise. – Accouplement

It sure is confusing, I was strugggling with the same thing when I got into logging. However, module/package hierarchy is not the same thing as logger hierarchy. The latter is purely based on dot-notated strings, whereas the former relies on folder structure and the fact that your main module's name will always be __main__. Even if you created and configured your parent logger in a way that names based on __name__ would create said hierarchy, you'll always end up having trouble with your main module or constructs like the dedicated class logger in Auxiliary. – Breadnut

So, since you have to configure at least one logger anyway, why not follow the suggestion to explicitly configure the root logger? That way you can pretty much safely use getLogger(__name__) anywhere. That's what I ended up doing ultimatley. – Breadnut

Indeed, if I simply remove the name argument from getLogger() in the main module and use getLogger(__name__) in the auxiliary module, the config is applied to the root logger, and the auxiliary logger message also appears. I guess this is more of a relative import issue, rather than a logging issue, and has to do with the behavior of __name__ (as explained here). – Accouplement

Answer 3

I think an easier, more professional solution would be to change your folder structure. Create another folder called packages (or something) and move the auxiliary_module there.

The logger would infer the module hierarchy and add the dots where needed.

cookbook-example
|- __init__.py
|- main_module.py
|- packages
    |- __init__.py
    |- auxiliary_module.py

Lawmaker

Yes, that's how you would normally do it, as described in the docs. However, the question was about understanding the underlying mechanism, and, especially, about understanding why it does not work if you put the auxiliary_module at the same level as the top-level script (main_module). – Accouplement

Does changing the structure help? If I call python main_module.py then __name__ is still going to resolve to __main__, and packages.auxiliary_module in auxiliary_module.py. Then I still have the problems that the loggers are not children of the same parent. – Difficult

@Difficult A bit late, but anyway: If you configure the root logger properly, e.g. by calling logging.basicConfig(level=logging.INFO) (source), then it should work. – Accouplement