apache+python中对logging模块的使用问题

问题描述：

使用 http://blog.youkuaiyun.com/hqin6/article/details/6719182搭建的服务器，在使用python的logging模块时，使用如下配置文件：

#logging.conf
[loggers]
keys=root,example

[handlers]
keys=exampleHandler

[formatters]
keys=exampleFormatter

[logger_example]
level=DEBUG
handlers=exampleHandler
qualname=example
propagate=0

[logger_root]
level=DEBUG
handlers=exampleHandler
qualname=root
propagate=0

[handler_exampleHandler]
class=handlers.RotatingFileHandler
level=DEBUG
formatter=exampleFormatter
args=('/tmp/example.log', 'a', 10*1024*1024, 5)

[formatter_exampleFormatter]
format=[%(asctime)s](%(levelname)s)%(name)s : %(message)s
datefmt=%a, %d %b %Y %H:%M:%S

有如下两个脚本：

1.test_log1.py

import logging
import logging.config

from mod_python import apache

logging.config.fileConfig("logger.conf");
logger = logging.getLogger("root");

def handler(req):
	logger.debug("this is a log in log_test1 file");
	return apache.OK;

2.test_log2.py

import logging
import logging.config

from mod_python import apache

logging.config.fileConfig("logger.conf");
logger = logging.getLogger("root");

def handler(req):
	logger.debug("this is a log in log_test2 file");
	return apache.OK;

发现顺序执行：

curl test_log1.py 能写出日志

curl test_log1.py 能写出日志

curl test_log2.py 不能写出日志

curl test_log1.py 不能写出日志

重启apache服务：

curl test_log2.py 能写出日志

curl test_log2.py 能写出日志

curl test_log1.py 不能写出日志

curl test_log2.py 不能写出日志

解决

logging对root的logger有特殊处理，最好不在程序中使用，而是使用上述配置文件中的example

原因

在python/logging/__init__.py中有如下代码：

1081     def handle(self, record):
1082         """
1083         Call the handlers for the specified record.
1084 
1085         This method is used for unpickled records received from a socket, as
1086         well as those created locally. Logger-level filtering is applied.
1087         """
1088         if (not self.disabled) and self.filter(record):
1089             self.callHandlers(record)

注意，这个函数是写日志的时候需要调用的，它有判断self.disabled这个变量！当这个变量为1时，将不能写日志。

在python/logging/config.py中有如下代码：

 55 def fileConfig(fname, defaults=None):
 ……
 96     try:
 97         try:
                ……
140             #at last, the loggers...first the root...
141             llist = cp.get("loggers", "keys")
142             llist = string.split(llist, ",")
143             llist.remove("root")#注意这行
                ……
167             existing = root.manager.loggerDict.keys()
168             #now set up the new ones...
169             for log in llist:
170                 sectname = "logger_%s" % log
171                 qn = cp.get(sectname, "qualname")
172                 opts = cp.options(sectname)
173                 if "propagate" in opts:
174                     propagate = cp.getint(sectname, "propagate")
175                 else:
176                     propagate = 1
177                 logger = logging.getLogger(qn)
178                 if qn in existing:
179                     existing.remove(qn)#注意这行
                    ……
186                 logger.disabled = 0#注意这行
                    ……
195             for log in existing:
196                 root.manager.loggerDict[log].disabled = 1#注意这行

能看到fileConfig函数执行时，将root从llist删除了，那么如果existing（即loggerDict）中存在root的话，上述代码就会将其root的disabled设置为1；

但是对于普通的logger（比如上述的example），则不然，example等将会在179行中从existing中remove，从而不会设置这些普通的logger的disabled

在 python/logging/__init__.py中有如下代码：

 825 class Manager:
 ……
 830     def __init__(self, rootnode):
 ……
 834         self.root = rootnode
 835         self.disable = 0
 836         self.emittedNoHandlerWarning = 0
 837         self.loggerDict = {}#注意这行
 838 
 839     def getLogger(self, name):
 ……
 852         try:
 853             if self.loggerDict.has_key(name):
				 ……
 862             else:
 863                 rv = _loggerClass(name)
 864                 rv.manager = self
 865                 self.loggerDict[name] = rv#注意这行

可以看到，对于第一次getLogger('root')调用，会将root写入到loggerDict中

所以，第一次的getLogger('root’)调用能正常写日志，因为第一次loggerDict中为{}，（837行）即空，所以按照上面代码分析，不会将root的disabled设置为1，能写入日志

但是第二次，由于已经将root放入了loggerDict，root的disabled将会被设置为1，本应该不能写日志，但是由于为了python的解析加速，第一次解析python文件后会生成一个.pyc文件，从而不进行第二次解析（可以删除该文件再试试，失败）

但是当我们请求另一个文件的时候（即test_log2.py），再次调用函数，root的disabled被设置为1，所以出现了问题，不能写日志。

同理，再次重新调用test_log1.py时写日志失败，因为root的disabled已经被设置为了1

使用example将不存在这样的问题！分析同上！