Python2.7 log level of logging doesn't work

Question

It seems recently there were some changes of python logging package. Some code work previously doesn't work now. And I am confused. My python version is Python 2.7.15.

The first example I don't understand is that below only prints "WARNING:root:hello from warn". If I understand correctly, "logging.info" actually calls the root logger, and root logger default to warn level. So the first "hello from info" is ignored, which is fine. But why the second "hello from info" is also not printed?

import logging 
logging.info("hello from info")
logging.warn("hello from warn")

logging.basicConfig(level=logging.INFO)
logging.info("hello from info")

The second question is the logging level of Handler versus logger. If we set the log level for both the handler and logger, which one is working? Or what if we just set level for Handler? Take the example as below. We already set the log level for StreamHandler, but the "hello from info" is not printed to stdout. Only the "hello from warn" (Besides, it is not "WARNING:t:hello from warn"). Why is that?

import logging
ch = logging.StreamHandler()
ch.setLevel(logging.INFO)
logger = logging.getLogger('t')
logger.addHandler(ch)
logger.info("hello from info")
logger.warn("hello from warn")

hoefling hoefling · Accepted Answer · 2018-08-18T11:55:00

But why the second "hello from info" is also not printed?

Because

logging.info / warn / error / debug call logging.basicConfig under the hood. Example:

def info(msg, *args, **kwargs):
    if len(root.handlers) == 0:
        basicConfig()
    root.info(msg, *args, **kwargs)

logging.basicConfig does not do anything if the root logger is already configured. Quote from the docs:

This function does nothing if the root logger already has handlers configured for it.

So, in your code, the root logger is configured with WARN level when logging.info("hello from info") is executed. The subsequent call of logging.basicConfig(level=logging.INFO) has no effect.

Rule of thumb: configure the loggers (no matter if manually or via logging.basicConfig()) as early as possible in your code.

If we set the log level for both the handler and logger, which one is working?

Both! Logger level and handler level are two different stages of filtering records. The logger level defines what records are actually passed to its handlers, while the handler level defines what records will be handled by the particular handler. Examples:

logger.setLevel(logging.INFO)
handler.setLevel(logging.ERROR)
logger.addHandler(handler)
logger.info('spam')

Since logger has level INFO, it will process spam record and pass it to its handlers. However, handler has level ERROR, so the record will not be processed by handler.

logger.setLevel(logging.WARN)
handler.setLevel(logging.DEBUG)
logger.addHandler(handler)
logger.info('spam')

Now the handler will process almost any record, including spam record since its level is INFO, thus greater than DEBUG. However, the handler will never receive spam to process because the logger will not process it, thus not passing spam to its handlers.

logger.setLevel(logging.INFO)
h1 = logging.StreamHandler()
h1.setLevel(logging.CRITICAL)
h2 = logging.FileHandler('some.log')
h2.setLevel(logging.DEBUG)
logger.addHandler(h1)
logger.addHandler(h2)
logger.info('spam')

Now the logger has two handlers, h1 printing records to terminal, h2 writing them to file. The logger will pass only records of level INFO or greater to its handlers. However, you will see only records with level CRITICAL in terminal, but all records in log file.

Python2.7 log level of logging doesn't work

1 Answers