title: Python logging: Why is __init__ called twice?
body: <p>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 <code>__init__</code> being called twice and <code>__del__</code> being called once. When I remove the whole config file stuff and create the handler directly within the code <code>__init__</code> is called once and <code>__del__</code> is never called.</p>
  
  <p>My questions:</p>
  
  <ol>
  <li>Why is <code>__init__</code> called twice?</li>
  <li>Why is <code>__del__</code> called less often than <code>__init__</code>?</li>
  </ol>
  
  <p>The code:</p>
  
  <pre><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")
  </code></pre>
  
  <p>The config file:</p>
  
  <pre><code>[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
  </code></pre>
  
  <p>Output looks like this:</p>
  
  <pre><code>init called
  init called
  del called
  </code></pre>
  
  <p>Using the debugger to get the stack trace as suggested by Sentinal reveals this:</p>
  
  <p>First call:</p>
  
  <pre><code>&gt; /root/test1.py(12)__init__()
  -&gt; print "init called"
  (Pdb) where
    /root/test1.py(21)&lt;module&gt;()
  -&gt; logging.config.fileConfig('/root/test1.conf')
    /usr/local/python/2.6.4/lib/python2.6/logging/config.py(84)fileConfig()
  -&gt; handlers = _install_handlers(cp, formatters)
    /usr/local/python/2.6.4/lib/python2.6/logging/config.py(156)_install_handlers()
  -&gt; klass = _resolve(klass)
    /usr/local/python/2.6.4/lib/python2.6/logging/config.py(94)_resolve()
  -&gt; found = __import__(used)
    /root/test1.py(21)&lt;module&gt;()
  -&gt; logging.config.fileConfig('/root/test1.conf')
    /usr/local/python/2.6.4/lib/python2.6/logging/config.py(84)fileConfig()
  -&gt; handlers = _install_handlers(cp, formatters)
    /usr/local/python/2.6.4/lib/python2.6/logging/config.py(159)_install_handlers()
  -&gt; h = klass(*args)
  &gt; /root/test1.py(12)__init__()
  -&gt; print "init called"
  (Pdb) c
  init called
  </code></pre>
  
  <p>Second call:</p>
  
  <pre><code>&gt; /root/test1.py(12)__init__()
  -&gt; print "init called"
  (Pdb) w
    /root/test1.py(21)&lt;module&gt;()
  -&gt; logging.config.fileConfig('/root/test1.conf')
    /usr/local/python/2.6.4/lib/python2.6/logging/config.py(84)fileConfig()
  -&gt; handlers = _install_handlers(cp, formatters)
    /usr/local/python/2.6.4/lib/python2.6/logging/config.py(159)_install_handlers()
  -&gt; h = klass(*args)
  &gt; /root/test1.py(12)__init__()
  -&gt; print "init called"
  </code></pre>