Python日志模块在“附加”属性上引发KeyError异常

Question

我遇到一个问题，我想在一个Python CGI脚本中记录一些额外的信息，比如用户ID和连接的主机IP。这个脚本是在RHEL 5系统上运行的Python 2.6.8版本。我按照文档的说明，尝试在基本的日志字典中添加这些属性，代码如下：

from __future__ import print_function
import logging
import os
import sys

LOG_DIR = '/apps/log'
LOG_PAGE = re.sub(r'\/(.*)\/.*$', r'\1', os.environ['REQUEST_URI'])
#
# The log format should be 
# <date stamp>  <level>   <remote user> <remote IP>: <message>
#
LOG_FORMAT = '%(asctime)-19s %(levelname)-9s %(user)-7s %(clientip)-15s - %(message)s'
LOG_DATE = '%Y-%m-%d %H:%M:%S'
orig_user = os.environ['REMOTE_USER']
orig_ip = os.environ['REMOTE_ADDR']
xtras = { 'user': orig_user, 'clientip': orig_ip }
#
# Set up logging
#
LOG_FILE = LOG_DIR + '/' + LOG_PAGE
logging.basicConfig(format=LOG_FORMAT, datefmt=LOG_DATE, level=logging.DEBUG, filename=LOG_FILE)
logit = logging.getLogger('groups')

然后我用以下方式调用它：

logit.debug('user visited page',extra=xtras)
logit.warn('user has no account under domain %s', myDOM, extra=xtras)

每次记录信息时，网页服务器的错误日志中都会出现3个KeyError异常：

s = self._fmt % record.__dict__, referer: https://its-serv-dev.case.edu/googlegroups/index.cgi
KeyError: 'user', referer: https://its-serv-dev.case.edu/googlegroups/index.cgi
Traceback (most recent call last):, referer: https://its-serv-dev.case.edu/googlegroups/index.cgi
File "/usr/lib64/python2.6/logging/__init__.py", line 776, in emit, referer: https://its-serv-dev.case.edu/googlegroups/index.cgi
msg = self.format(record), referer: https://its-serv-dev.case.edu/googlegroups/index.cgi
File "/usr/lib64/python2.6/logging/__init__.py", line 654, in format, referer: https://its-serv-dev.case.edu/googlegroups/index.cgi
return fmt.format(record), referer: https://its-serv-dev.case.edu/googlegroups/index.cgi
File "/usr/lib64/python2.6/logging/__init__.py", line 439, in format, referer: https://its-serv-dev.case.edu/googlegroups/index.cgi
s = self._fmt % record.__dict__, referer: https://its-serv-dev.case.edu/googlegroups/index.cgi
KeyError: 'user', referer: https://its-serv-dev.case.edu/googlegroups/index.cgi

奇怪的是，这些KeyError异常只针对其中一个“额外”的字典项产生，而信息实际上是正确记录到文件中的。我尝试了不同的组合，去掉这两个额外的部分（错误信息就会转移到剩下的部分），但似乎没有什么办法能阻止异常的产生，除非我完全去掉这些额外的信息。

我想我可以把这些信息放在格式字符串中作为消息的一部分，但这样做感觉像是在重复造轮子。

Answer 1

通过调用 logging.basicConfig，你实际上是在改变 RootLogger 的 formatter，而 RootLogger 是所有 Logger 的祖先。所以，这样做会影响到其他的 loggers。

你可以从这个 github 讨论 中获取更多细节。

Answer 2

我遇到过类似的问题。我觉得这个错误发生的原因是，有些日志记录器在使用时没有添加过滤器（过滤器是用来在创建日志记录器时添加额外信息的），但它们仍然在使用与这些额外信息对应的格式将记录传递给格式化器。

这是一个关于如何使用过滤器的文档示例链接

Answer 3

我搞明白这里发生了什么：

我还在使用谷歌的oauth2client.client模块，这个模块也在用日志记录功能。因为oauth2client.client模块被认为是我页面的“子模块”，所以日志信息被传递到了我的日志对象上。而且，由于谷歌模块在调用时没有包含额外的日志字典，所以是谷歌模块导致了KeyError异常，而不是我自己的代码。为了暂时解决这个问题，我把额外的内容作为消息的一部分加上了。接下来我还需要深入了解一下日志模块，看看有没有更好的方法来避免谷歌的oauth2client.client模块的日志和我页面的日志发生冲突。