Регистрация в Python: почему __init__ вызывается дважды?

Question

Я пытаюсь использовать python logging с файлом конфигурации и собственным обработчиком.Это работает в некоторой степени.Что меня действительно озадачивает, так это то, что __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

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-want, точнее, он вызывается, когда сборщик мусора решает собрать мусоробъект;это не обязательно только после того, как вы отпустите его.

Answer 2

Вам не хватает if __name__ == "__main__": защиты для вашего кода конфигурации логирования. Он выполняется во второй раз, когда logging импортирует ваш модуль test1, чтобы найти ссылку на класс.

Либо используйте имя __main__.Test1TimedRotatingFileHandler в файле конфигурации, либо поместите код конфигурации и класс обработчика в разные файлы.