帮助我理解Python的日志模块及其处理器

Question

我对Python的日志模块有些基本的困惑。

在下面的代码中，我创建了一个日志记录器对象（log），并给它添加了两个处理器。一个是'INFO'级别，另一个是'WARNING'级别。它们都应该打印到标准输出（stdout）。我本来期待调用log.info(msg)时，会在我的标准输出中看到一份msg，而调用log.warn(msg)时，会在标准输出中看到两份msg。以下是代码：

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'

但是输出结果让我感到很奇怪。调用.info时没有任何可见的效果。不过，调用warn时却在标准输出中打印了两份msg（这没问题），但同时还在标准错误输出（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

所以我有两个问题：

1. 为什么我调用info时没有任何输出，尽管h1的级别设置为INFO？
2. 为什么我调用warn时会额外输出到标准错误输出？

Answer 1

其实，日志记录有五个级别：调试、信息、警告、错误和严重错误。我注意到你在设置日志记录器时没有明确指定级别——我觉得如果不设置，日志记录器可能默认会使用警告级别。

至于为什么警告会打印多次，我认为这是因为你为信息和警告各创建了一个处理器。发生的情况是，日志记录器会从警告级别向下检查，依次是警告 -> 信息 -> 调试，并为每个级别调用处理器。因为你的级别设置为警告，所以信息处理器会被忽略。此外，我认为警告信息通常会写入sys.stderr。

你可以尝试以下代码：

logging.basicConfig(level=logging.INFO)

另外，看看这些链接：

• 日志模块文档
• 日志基本示例

Answer 2

你需要知道两件事：

1. 根日志记录器的初始级别是 WARNING。

   任何到达日志记录器的日志信息，如果它的级别低于日志记录器的级别，就会被丢弃。如果一个日志记录器没有设置级别，它会从它的父日志记录器那里继承一个“有效级别”。所以，如果根日志记录器的级别是 WARNING，那么所有的日志记录器默认的有效级别也是 WARNING。如果你没有做其他配置，所有级别低于这个的日志信息都会被丢弃。

2. 当你调用 basicConfig() 时，系统会自动在根日志记录器上设置一个 StreamHandler，它会将信息打印到标准错误流。

   当你的程序打印日志信息时，实际上有 三个处理器：你添加的两个处理器，它们有自己的级别，还有一个来自系统的处理器，它会打印出任何没有被日志记录器拒绝的信息。这就是你看到的那一行

   WARNING:myLogger:this is a warning
   

   它来自系统日志记录器。对于 INFO 级别的信息，它不会这样做，因为正如之前讨论的，根日志记录器默认配置是拒绝这些信息的。

   如果你不想看到这个输出，就不要调用 basicConfig()。

进一步阅读： http://docs.python.org/howto/logging.html