Python logging: Why is __init__ called twice?

Question

I am trying to use python logging with a config file and an own handler. This works to some degree. What really puzzle me is __init__ being called twice and __del__ being called once. When I remove the whole config file stuff and create the handler directly within the code __init__ is called once and __del__ is never called.

My questions:

1. Why is __init__ called twice?
2. Why is __del__ called less often than __init__?

The code:

#!/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")

The config file:

[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

Output looks like this:

init called
init called
del called

Using the debugger to get the stack trace as suggested by Sentinal reveals this:

First call:

> /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

Second call:

> /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. Why is init called twice?

If you follow the code of the logging module, you'll see that when you're loading the logging configuration file, it instantiates all the handlers (First instantiation).

In your code, you declare your handler like test1.Test1TimedRotatingFileHandler, so when it try to import your handler, it parses the code in the test1 module... so it recreates the handler !!

Corrected code will guard using __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 . Why is del called less often than init?

In general, the __del__ operator is called when-python-wants, more exactly, it is called when the garbage collector decides to garbage-collect the object; this is not necessarily just after you release it.

Answer 2

You are missing an if __name__ == "__main__": guard around your logging configuration code. It is getting executed a second time when logging imports your test1 module to find the class reference.

Alternatively, use the name __main__.Test1TimedRotatingFileHandler in the config file, or else put the configuration code and the handler class in different files.