Why does logger.info() only appear after calling logging.info()?

Question

I am using Python 3.6.4. I first encountered an issue where logger.setLevel(logging.INFO) was ignored, and came across this answer, which confused me and gave rise to this question.

Given the code below,

1. Why does logging.info('2') get printed in Snippet 2, but not in 1? (Isn't logging.info() is a module level function? Why does naming a logger affect this call?)

2. Why does logger.info('3') get printed, but not logger.info('1')?

Snippet 1

>>> import logging
>>> logger = logging.getLogger('foo')  # named logger
>>> logger.setLevel(logging.INFO)
>>> logger.info('1')
>>> logging.info('2')  # prints nothing
>>> logger.info('3')
INFO:foo:3

Snippet 2

>>> import logging
>>> logger = logging.getLogger()  # no name
>>> logger.setLevel(logging.INFO)
>>> logger.info('1')
>>> logging.info('2')  # printed
INFO:root:2
>>> logger.info('3')
INFO:root:3

Answer 1

As you point out, the difference between the snippets is in how you get the logger object:

logger = logging.getLogger('foo')
logger = logging.getLogger()

The key thing is that, in the second case, you are getting the "root" logger. In the first case, on the other hand, you are getting a "sublogger" of the root called foo.

Now, let's go step by step.

logger.setLevel(logging.INFO)

Here you set the level of the logger. In the first case, you are setting the level for the logger foo. On creation, new loggers do not have a level, so they process every message; here you are saying that only messages with severity INFO or higher should be processed. But, in the second case, logger is the root logger. The confusing bit here is that, unlike new loggers, the root logger default level is WARN, so nothing below that level is processed unless you change it. So, after this line:

• In the first snippet, the root logger is set to WARN level, and the foo logger is set to INFO level.
• In the second snippet, the root logger is set to INFO level.

logger.info('1')

First logged line. Here you have the same behavior in both cases. The message is INFO, and logger is set to that severity, so the message is processed. However, you do not have any handler set in logger, so nothing is actually done with the message.

logging.info('2')

Now this is more interesting. What is important here is what logging.info actually does, which is not the same as if you call the info method of the root logger object:

Log a message with severity 'INFO' on the root logger. If the logger has no handlers, call basicConfig() to add a console handler with a pre-defined format.

So, this function will make a console handler by itself if no handlers are registered for the root logger. So any message received by the root logger or subloggers will now be printed to console. In the first case, however, turns out that the root logger has still its default severity filter, WARN, so the console handler is registered, but the message is actually ignored. In the second case, though, you set the severity level of the root logger to INFO, so the message is processed and printed by the console handler.

logger.info('3')

Hopefully this should make sense now. Now you have a console handler attached to the root logger. In the first case, logger is the foo logger, and its severity is set to INFO, so the message is processed and, since it is a sublogger of the root logger, it is printed by the console handler registered for that one. In the second case, you are just logging to the root logger, which has INFO severity and the registered console handler.

Note that in the last line of the first case, the message processed by the foo logger is handled by the handler registered in the root logger even though the severity level of the root logger is WARN. Log handlers are not responsible for filtering by severity, that is done by the logger itself, so once a logger has decided that a message should be processed, it is handled by all its handlers and the handlers from parent loggers. This is a very useful feature, since it allows you to have a higher system-level log level and a lower one for specific modules that you are more interested in (e.g. for debugging or simply reporting).

Answer 2

Refer to the accepted answer on that post:

If you don't configure logging with any handlers (as in your post - you only configure a level for your logger, but no handlers anywhere), you'll get an internal handler "of last resort" which is set to output just the message (with no other formatting) at the WARNING level.

Your level is currently less than WARNING, so it is not output. This changes with a call to basicConfig() which you may/should do explicitly, otherwise it's not being handled until it's called from logging.info (or one of the other convenience functions).

The documentation observes this:

Note The above module-level convenience functions, which delegate to the root logger, call basicConfig() to ensure that at least one handler is available. Because of this, they should not be used in threads, in versions of Python earlier than 2.7.1 and 3.2, unless at least one handler has been added to the root logger before the threads are started. In earlier versions of Python, due to a thread safety shortcoming in basicConfig(), this can (under rare circumstances) lead to handlers being added multiple times to the root logger, which can in turn lead to multiple messages for the same event.