[issue23010] "unclosed file" warning when defining unused logging FileHandler in dictConfig

[Walter Doekes]

Walter Doekes added the comment:

> The handlers are AFAIK referenced - if you peek at logging._handlerList or logging._handlers you should see them in there.

Aha. But that's the point. They aren't. If they were, I wouldn't have any problems with this. But I have this problem because the warnings are generated at startup of my program, not at cleanup.

Look at this:

    $ PYTHONWARNINGS=default python3 problem.py 2>&1 | sed -e 's/^/    /'
    2014-12-09 08:58:45.982258: starting
    2014-12-09 08:58:46.011788: after dictconfig
    /usr/lib/python3.4/importlib/_bootstrap.py:321: ResourceWarning: unclosed file <_io.FileIO name='/tmp/debug.log' mode='ab'>
      return f(*args, **kwds)
    imported once
    2014-12-09 08:58:46.019327: after error
    2014-12-09 08:58:51.024376: after sleep
    _handlerList: []
    _handlers: []

If what you say is true, the following wouldn't be:

- _handlerList is non-empty (wrong, see above)
- the warning would be generated at application shutdown (no, it's generated at importlib time, see the timestamps)

(See source below.)


> You could just leave out the handlers, since you're never using them; it's not logging's job to be overly restrictive about this sort of thing.

I could agree with you there. But in that case I still think we should call it illegal (and perhaps raise a more sensible warning).

Obviously you spot the problem immediately in my toy example. But in a large LOGGING dictionary, items may be shuffled around and changed. When that happens, and these warnings turn up out of the blue, that's distracting to put it mildly.

I expect that you'll reconsider your strict opinion after seeing that logging._handlers is indeed empty and the handlers are not referenced (and therefore should have been destroyed properly or not created at all).

Cheers,
Walter



Example source:

    $ cat problem.py | sed -e 's/^/    /'
    from datetime import datetime
    from time import sleep
    import sys
    
    if __name__ == '__main__':
        LOGGING = {
            'version': 1,
            'handlers': {
                'logfile': {
                    'level': 'DEBUG',
                    'class': 'logging.FileHandler',
                    'filename': '/tmp/debug.log',
                },
            },
        }
    
        print('%s: starting' % (datetime.now(),))
        
        from logging.config import dictConfig
        dictConfig(LOGGING)
        
        print('%s: after dictconfig' % (datetime.now(),))
        sys.stdout.flush()
    
        # using importlib on a new file triggers the warnings
        import importlib, shutil, os
        shutil.copy(__file__, __file__ + '.new')
        os.unlink(__file__)
        os.rename(__file__ + '.new', __file__)
        importlib.import_module('problem')
        sys.stderr.flush()
    
        print('%s: after error' % (datetime.now(),))
        sys.stdout.flush()
    
        sleep(5)
        print('%s: after sleep' % (datetime.now(),))
    
        # Vinay Sajip wrote:
        # > The handlers are AFAIK referenced - if you peek at
        # logging._handlerList or logging._handlers you should see them in
        # there.
        from logging import _handlerList, _handlers
        print('_handlerList:', _handlerList)
        print('_handlers:', [i for i in _handlers.values()])
    else:
        print('imported once')

----------

_______________________________________
Python tracker <report at bugs.python.org>
<http://bugs.python.org/issue23010>
_______________________________________