99

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')
vvvvv
  • 25,404
  • 19
  • 49
  • 81
djvg
  • 11,722
  • 5
  • 72
  • 103

3 Answers3

95

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').

djvg
  • 11,722
  • 5
  • 72
  • 103
  • 2
    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? – Aenaon Apr 12 '21 at 20:55
  • 2
    @Aenaon: according to the [docs](https://docs.python.org/3/library/logging.html#logging.getLogger) `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. – djvg Apr 13 '21 at 08:33
  • 1
    @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` – djvg Apr 13 '21 at 08:37
24

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__
shmee
  • 4,721
  • 2
  • 18
  • 27
  • 1
    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](https://docs.python.org/2/howto/logging.html#advanced-logging-tutorial) would suggest otherwise. – djvg Jun 06 '18 at 08:24
  • 4
    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. – shmee Jun 06 '18 at 08:47
  • 2
    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. – shmee Jun 06 '18 at 08:56
  • 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](https://stackoverflow.com/a/14132912)). – djvg Jun 06 '18 at 09:38
0

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
Josef
  • 2,869
  • 2
  • 22
  • 23
  • Yes, that's how you would normally do it, [as described in the docs](https://docs.python.org/3/library/logging.html#logger-objects). 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`). – djvg Jul 27 '21 at 10:40
  • 2
    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. – loris Sep 01 '21 at 12:53
  • 1
    @loris A bit late, but anyway: If you configure the *root* logger properly, e.g. by calling [logging.basicConfig(level=logging.INFO)](https://docs.python.org/3/library/logging.html#logging.basicConfig) ([source](https://github.com/python/cpython/blob/9f2f1dd131b912e224cd0269adde8879799686c4/Lib/logging/__init__.py#L2028)), then it should work. – djvg Sep 30 '22 at 15:28