"unclosed file" warning when defining unused logging FileHandler in dictConfig

[wdoekes]

BPO	23010
Nosy	@vsajip, @iritkatriel

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = <Date 2021-12-14.10:08:04.239>
created_at = <Date 2014-12-08.13:46:54.981>
labels = ['invalid', 'library', '3.11']
title = '"unclosed file" warning when defining unused logging FileHandler in dictConfig'
updated_at = <Date 2021-12-14.10:08:04.238>
user = 'https://bugs.python.org/wdoekes'

bugs.python.org fields:

activity = <Date 2021-12-14.10:08:04.238>
actor = 'vinay.sajip'
assignee = 'none'
closed = True
closed_date = <Date 2021-12-14.10:08:04.239>
closer = 'vinay.sajip'
components = ['Library (Lib)']
creation = <Date 2014-12-08.13:46:54.981>
creator = 'wdoekes'
dependencies = []
files = []
hgrepos = []
issue_num = 23010
keywords = []
message_count = 11.0
messages = ['232302', '232321', '232326', '232337', '232350', '232356', '233316', '233353', '233531', '407151', '407192']
nosy_count = 3.0
nosy_names = ['vinay.sajip', 'wdoekes', 'iritkatriel']
pr_nums = []
priority = 'normal'
resolution = 'not a bug'
stage = 'resolved'
status = 'closed'
superseder = None
type = None
url = 'https://bugs.python.org/issue23010'
versions = ['Python 3.11']

[wdoekes]

If you define a FileHandler in your logging dictConfig but fail to use it in the same configuration, the file handle is leaked and a ResourceWarning is thrown.

Versions:

    $ python3 -V
    Python 3.4.0
    $ apt-cache show python3.4 | grep ^Version
    Version: 3.4.0-2ubuntu1

Expected:

    $ PYTHONWARNINGS="default,ignore::DeprecationWarning" \
        python3 problem.py 
    imported once

Observed:

    $ PYTHONWARNINGS="default,ignore::DeprecationWarning" \
        python3 problem.py 
    .../lib/python3.4/importlib/_bootstrap.py:656:
        ResourceWarning: unclosed file
          <_io.FileIO name='/tmp/debug.log' mode='ab'>
      code = marshal.loads(data)
    imported once

To reproduce, save below as problem.py:

    if __name__ == '__main__':
        LOGGING = {
            'version': 1,
            'handlers': {
                'logfile': {
                    'level': 'DEBUG',
                    'class': 'logging.FileHandler',
                    'filename': '/tmp/debug.log',
                },
            },
        }
        
        from logging.config import dictConfig
        dictConfig(LOGGING)
        
        # 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')
    else:
        print('imported once')

Fixed by:

--- /usr/lib/python3.4/logging/config.py.orig	2014-12-08 14:06:24.911460799 +0100
+++ /usr/lib/python3.4/logging/config.py	2014-12-08 14:16:17.519460799 +0100
@@ -637,6 +637,16 @@ class DictConfigurator(BaseConfigurator)
                     except Exception as e:
                         raise ValueError('Unable to configure root '
                                          'logger: %s' % e)
+
+                # Close unused loggers
+                used_handlers = set()
+                for logger in logging.root.manager.loggerDict.values():
+                    if hasattr(logger, 'handlers') and logger.handlers:
+                        used_handlers.add(*logger.handlers)
+                for name, handler in handlers.items():
+                    if handler not in used_handlers:
+                        if hasattr(handler, 'close'):
+                            handler.close()
         finally:
             logging._releaseLock()

The fix above might not be the best fix, but it proves where the problem is. Perhaps the handlers shouldn't be instantiated until the first user of such a handler is instantiated.

This issue was found by using Django 1.7 with Python 3.4 when enabling the PYTHONWARNINGS.

Cheers,
Walter Doekes
OSSO B.V.

[vsajip]

Well, it's possible that you could configure handlers in the configuration for later use (i.e. at some point after the dictConfig() call returns).

If you want to avoid opening the file until it's actually needed, you can specify delay=True, and then you shouldn't see the resource leak because the stream will be opened when it's actually needed.

Unless there's some reason you can't do that, or there's something I've overlooked, I think I should close this as invalid.

[wdoekes]

Thanks for the quick response!

Well, it's possible that you could configure handlers in the configuration for later use (i.e. at some point after the dictConfig() call returns).

After the dictConfig call returns, the StreamHandler/FileHandler is not referenced by anyone anymore. That's what causes the ResourceWarning. Unless I'm severely mistaken, there is no way to reach that old FileHandler instance.

If you want to avoid opening the file until it's actually needed, you can specify delay=True.

I am aware of that, but that's a workaround, not a fix. (And it has drawbacks of its own, for example in forking and/or setuid situations.)

Unless there's some reason you can't do that, or there's something I've overlooked, I think I should close this as invalid.

You could do that, but -- barring me overlooking something here -- I think that would only be correct if the dictionary that I passed to dictConfig is judged as being illegal, because it contains unused handlers.

The ResourceWarning thrown is hard to understand because of where it is raised (at random points in a different modules), so like it is now, it may dissuade users from enabling more (visual) warnings. I'd rather see a warning raised earlier from dictConfig() that I configured an unused handler, so I have a better indication of what to fix.

[vsajip]

The delay= is not really a workaround for this particular circumstance, it's mainly there to avoid leaving empty files around and allocating resources that might never be used (which is analogous to this issue, but delay was not implemented to work around this specific scenario).

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

A config dictionary is not judged as being illegal just because it contains unused handlers - you just happen to allocate resource that you never use. 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. Python doesn't warn you for allocating a dictionary that you never populate, or if you populate a dictionary that you then never interrogate. The type of unnecessary allocation of resources you're talking about happens a lot in programs - in fact, it also applies to loggers, since you might never use them in a specific program run, because of which code gets run based on command-line arguments, or with handlers that are "used" (in the sens you mean here, because they are linked to loggers), but never *actually* used because the levels in the configuration are set to CRITICAL, and there are no .critical() calls encountered during a program run. I'm not sure a line can usefully be drawn regarding "useless" allocations.

[wdoekes]

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')

[vsajip]

Aha. But that's the point. They aren't.

Ok, I'll investigate further. Thanks for your persistence :-)

[vsajip]

Sorry I've not had much time to look at this yet. I haven't forgotten.

[wdoekes]

No worries. I know how it is ;)
Thanks for the update.

[vsajip]

Data point: if you print out _handlerList immediately after the dictConfig() call, it *is* there, as I would have expected. The following script saved as logtest6.py:

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)
from logging import \_handlerList

print('%s: after dictconfig' % (datetime.now(),))
sys.stdout.flush()
print('\_handlerList 1:', \_handlerList)
\# using importlib on a new file triggers the warnings
import importlib, shutil, os
print('\_handlerList 2:', \_handlerList)
shutil.copy(__file__, \_\_file__ + '.new')
os.unlink(__file__)
os.rename(__file__ + '.new', \_\_file__)
importlib.import_module('logtest6')
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 3:', _handlerList)
else:
    print('imported once')

When run, yields

$ python3.4 logtest6.py 
2015-01-06 12:26:46.910634: starting
2015-01-06 12:26:47.290223: after dictconfig
_handlerList 1: [<weakref at 0xb7223e34; to 'FileHandler' at 0xb71680dc>]
/home/vinay/projects/python/3.4/Lib/collections/__init__.py:373: ResourceWarning: unclosed file <_io.FileIO name='/tmp/debug.log' mode='ab'>
  exec(class_definition, namespace)
_handlerList 2: []
imported once
2015-01-06 12:26:47.388877: after error
2015-01-06 12:26:52.394514: after sleep
_handlerList 3: []

[iritkatriel]

Reproduced on 3.11.

[vsajip]

This had dropped off my radar completely, but I still can't see where there's an actual bug here. This simplified script:

import logging
import sys

LOGGING = {
    'version': 1,
    'handlers': {
        'logfile': {
            'level': 'DEBUG',
            'class': 'logging.FileHandler',
            'filename': '/tmp/debug.log',
        },
    },
}

print('Starting: %s' % sys.version)
from logging.config import dictConfig
dictConfig(LOGGING)
print('After dictconfig')
print('_handlerList 1, initial:', logging._handlerList, len(logging._handlers))
import importlib
print('_handlerList 2, about to import shutil:', logging._handlerList, len(logging._handlers))
import shutil
print('_handlerList 3, just imported shutil:', logging._handlerList, len(logging._handlers))
print('')

when run with Python 3.10, produces

Starting: 3.10.0+ (heads/3.10:7203ecd332, Oct 29 2021, 10:04:19) [GCC 7.5.0]
After dictconfig
_handlerList 1, initial: [<weakref at 0x7f3e25e9e070; to 'FileHandler' at 0x7f3e25e63dc0>] 1
_handlerList 2, about to import shutil: [<weakref at 0x7f3e25e9e070; to 'FileHandler' at 0x7f3e25e63dc0>] 1
/home/vinay/.local/lib/python3.10/_compression.py:33: ResourceWarning: unclosed file <_io.FileIO name='/tmp/debug.log' mode='ab' closefd=True>
class DecompressReader(io.RawIOBase):
ResourceWarning: Enable tracemalloc to get the object allocation traceback
_handlerList 3, just imported shutil: [] 0

But ... there are no loggers that use this handler, so the only reference would be the weak reference in _handlerList - it gets freed up at some point (in this case, when shutil is imported, but I don't believe that's necessarily relevant) and that causes the ResourceWarning, but where's the problem? If you either add a reference to the handler (by adding it to a logger) or adding "delay: True" to the handler configuration dict to delay opening the file, the ResourceWarning is no longer seen.

I tested with Python 3.4 - 3.10 and all versions behave the same way - it could just be down to where weak references get dumped, which is down to the vagaries of GC. I don't see this as a "leak" - the ResourceWarning is showing the developer that they opened a file for no particular reason and didn't use it.