Why does calling logging.info change what my logger prints?

Question

I'm trying to get Python to log stuff and, despite having read over the logging docs and how-to, I don't understand its behavior.

I set the global log level and then tried logging something:

logger = logging.getLogger()
print("Initially should be warn: %d" % logger.getEffectiveLevel())
logger.setLevel(logging.DEBUG)
print("Logger level: %d" % logger.getEffectiveLevel())

logger.info("Maybe I am printed?")

But running python my_script.py just prints:

Initially should be warn: 30
Logger level: 10

However, if I add a line logging.info call, e.g.,

logger = logging.getLogger()
print("Initially should be warn: %d" % logger.getEffectiveLevel())
logger.setLevel(logging.DEBUG)
print("Logger level: %d" % logger.getEffectiveLevel())

logging.info("I am printed")
logger.info("Maybe I am printed?")

then the logging all shows up:

Initially should be warn: 30
Logger level: 10
INFO:root:I am printed
INFO:root:Maybe I am printed?

What is logging.info doing?

Cavaz · Accepted Answer · 2017-10-05T07:51:06.350

The first example will actually warn you that No handlers could be found for logger "root" (see here). This is because, as suggested, you did not define any handler for logger.

Here is the implementation of logging.info:

def info(msg, *args, **kwargs):
    """
    Log a message with severity 'INFO' on the root logger.
    """
    if len(root.handlers) == 0:
        basicConfig()
    root.info(msg, *args, **kwargs)

As you can see, when no handler is found, it will call basicConfig which will take also care of initializing a default handler, thus fixing the logging in your following statements.

Matt Hardcastle · Answer 2 · 2017-10-04T15:36:15.360

The call to logging.info is configuring the logging handler and formatter so it can output the logs. If you want to do that yourself the following code will set it up:

logger = logging.getLogger()
logger.setLevel(logging.DEBUG)
handler = logging.StreamHandler()
handler.setLevel(logging.DEBUG)
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
handler.setFormatter(formatter)
logger.addHandler(handler)
logger.info("boo")

There are more details on configuring logging in the configuring logging section of the tutorial.

The code that logging.info calls to setup logging is available in github.com. It essentially just create the handler if no handlers exist.

Why does calling logging.info change what my logger prints?

2 Answers2