Python日志：为什么__init__被调用两次？

Question

我正在尝试使用 Python 的日志功能，并且想用一个配置文件和自己的处理器。这在某种程度上是可以工作的。不过让我感到困惑的是，__init__ 这个方法被调用了两次，而 __del__ 只被调用了一次。当我把整个配置文件的内容去掉，直接在代码里创建处理器时，__init__ 只被调用了一次，而 __del__ 根本没有被调用。

我有几个问题：

1. 为什么 __init__ 会被调用两次？
2. 为什么 __del__ 被调用的次数比 __init__ 少？

代码如下：

#!/bin/env python

import logging
import logging.handlers
import logging.config

class Test1TimedRotatingFileHandler(logging.handlers.TimedRotatingFileHandler):
    def __init__(self,filename):
        print "init called"
        logging.handlers.TimedRotatingFileHandler.__init__(self,filename, when='S', interval=86400, backupCount=8, encoding=None)

    def __del__(self):
        print "del called"
        if hasattr(logging.handlers.TimedRotatingFileHandler,"__del__"):
            logging.handlers.TimedRotatingFileHandler.__del__(self)

logging.config.fileConfig('/root/test1.conf')
logger = logging.getLogger("test1")

配置文件内容：

[formatters]
keys: simple

[handlers]
keys: file

[loggers]
keys: root

[formatter_simple]
format: "%(message)s"

[handler_file]
class: test1.Test1TimedRotatingFileHandler
args: ("/root/test1.log",)
level=INFO

[logger_root]
level: INFO
handlers: file
qualname: test1

输出结果看起来是这样的：

init called
init called
del called

使用调试工具查看调用栈，正如 Sentinal 所建议的，结果是这样的：

第一次调用：

> /root/test1.py(12)__init__()
-> print "init called"
(Pdb) where
  /root/test1.py(21)<module>()
-> logging.config.fileConfig('/root/test1.conf')
  /usr/local/python/2.6.4/lib/python2.6/logging/config.py(84)fileConfig()
-> handlers = _install_handlers(cp, formatters)
  /usr/local/python/2.6.4/lib/python2.6/logging/config.py(156)_install_handlers()
-> klass = _resolve(klass)
  /usr/local/python/2.6.4/lib/python2.6/logging/config.py(94)_resolve()
-> found = __import__(used)
  /root/test1.py(21)<module>()
-> logging.config.fileConfig('/root/test1.conf')
  /usr/local/python/2.6.4/lib/python2.6/logging/config.py(84)fileConfig()
-> handlers = _install_handlers(cp, formatters)
  /usr/local/python/2.6.4/lib/python2.6/logging/config.py(159)_install_handlers()
-> h = klass(*args)
> /root/test1.py(12)__init__()
-> print "init called"
(Pdb) c
init called

第二次调用：

> /root/test1.py(12)__init__()
-> print "init called"
(Pdb) w
  /root/test1.py(21)<module>()
-> logging.config.fileConfig('/root/test1.conf')
  /usr/local/python/2.6.4/lib/python2.6/logging/config.py(84)fileConfig()
-> handlers = _install_handlers(cp, formatters)
  /usr/local/python/2.6.4/lib/python2.6/logging/config.py(159)_install_handlers()
-> h = klass(*args)
> /root/test1.py(12)__init__()
-> print "init called"

Answer 1

你在日志配置代码周围缺少一个 if __name__ == "__main__": 的保护。这段代码在 logging 导入你的 test1 模块时会被执行第二次，以找到类的引用。

另外，你可以在配置文件中使用名称 __main__.Test1TimedRotatingFileHandler，或者把配置代码和处理类放在不同的文件里。

Answer 2

1. 为什么init会被调用两次？

如果你查看一下logging模块的代码，你会发现，当你加载日志配置文件时，它会创建所有的处理器（第一次创建）。

在你的代码中，你声明了一个处理器，比如test1.Test1TimedRotatingFileHandler，所以当它试图导入你的处理器时，它会解析test1模块中的代码……这就导致处理器被重新创建了！！

正确的代码应该使用__name__ == '__main__'来进行保护：

#!/bin/env python

import logging
import logging.handlers
import logging.config

class Test1TimedRotatingFileHandler(logging.handlers.TimedRotatingFileHandler):
    def __init__(self,filename):
        print "init called"
        logging.handlers.TimedRotatingFileHandler.__init__(self,filename, when='S', interval=86400, backupCount=8, encoding=None)

    def __del__(self):
        print "del called"
        if hasattr(logging.handlers.TimedRotatingFileHandler,"__del__"):
            logging.handlers.TimedRotatingFileHandler.__del__(self)

if __name__ == "__main__":
    logging.config.fileConfig('./test1.conf')
    logger = logging.getLogger("test1")

2. 为什么del被调用的次数比init少？

一般来说，__del__这个操作符是在Python想要的时候被调用，具体来说，是在垃圾回收器决定要回收这个对象的时候；这并不一定是在你释放它之后马上发生的。