Help me understanding python's logging module and its handlers

Question

I really miss something basic about python's logging module.

In the following code, I create a logger object (log) and add to it two handlers. One with 'INFO' level and one with 'WARNING' level. Both of them are supposed to print to stdout. I expect that calling to log.info(msg) will result in one copy of msg in my stdout and calling to log.warn(msg) sould result in two copies of msg printed to my stdout. Here is the code:

import logging
import sys


logging.basicConfig()
log = logging.getLogger('myLogger')
log.handlers = []
h1 = logging.StreamHandler(sys.stdout)
h1.level = logging.INFO
h1.formatter = logging.Formatter('H1 H1 %(message)s ')
h2 = logging.StreamHandler(sys.stdout) 
h2.level = logging.WARNING
h2.formatter = logging.Formatter('H2 H2 %(message)s')
log.addHandler(h1)
log.addHandler(h2)

print 'log.level == %s'%logging.getLevelName(log.level)
print 'log.info'
log.info('this is some info')
print 'done'
print 'log.warn'
log.warn('this is a warning')
print 'done'

The output is really very strange to me. The .info call results in no visual effect. However, calling to warn results in two copies of msg printed to stdout (which is OK), but also one copy printed to stderr (why?). This is the output of the above code. Note the formatting of the last line in this output. This line is printed to stderr.

log.level == NOTSET
log.info
done
log.warn
H1 H1 this is a warning 
H2 H2 this is a warning
done
WARNING:myLogger:this is a warning

So my questions are:

1. why does my call to info result in no output, despite the fact that h1's level is set to INFO?
2. why does my call to warn results in additional output to stderr?

Answer 1

There are two things you need to know:

1. The root logger is initialized with a level of WARNING.

   Any log message that reaches a logger is discarded if its level is below the logger's level. If a logger's level is not set, it will take its "effective level" from its parent logger. So if the root logger has a level of WARNING, all loggers have a default effective level of WARNING. If you don't configure it otherwise, all log messages with a level below that will be discarded.

2. When you call basicConfig(), the system automatically sets up a StreamHandler on the root logger that prints to the standard error stream.

   When your program prints out its log messages, there are actually three handlers: the two that you've added, which have their own levels, and one from the system that will print out any message not rejected by its logger. That's why you get the line

   WARNING:myLogger:this is a warning
   

   It comes from the system logger. It doesn't do this for the INFO level message, because as previously discussed, the root logger is configured to reject those messages by default.

   If you don't want this output, don't call basicConfig().

Further reading: http://docs.python.org/howto/logging.html

Answer 2

There are actually five levels of logging: debug, info, warning, error, and critical. I see that when you are setting up your logger you aren't explicitly setting your level--I believe the logger may default to warning if the level is not set.

As to why it is printing out multiple times for warning, I believe this is due to your creating two handlers for info & warning. What happens is that the logger cascades down in severity from warning -> info -> debug, calling the handler for each. Since your level is set to warning, the info handler is ignored. Also, I believe warning messages are normally written to sys.stderr.

Try the following:

logging.basicConfig(level=logging.INFO)

See also:

• Logging module docs
• Logging basic example