logging.config.dictConfig with file handler leaks resources

[maggyero]

BPO	33978
Nosy	@vsajip, @maggyero, @tirkarthi
PRs	bpo-33978: close resources before deletion of logging handlers #8008 [3.7] bpo-33978: Close existing handlers before logging (re-)configuration. (GH-8008) #8044 [3.6] bpo-33978: Close existing handlers before logging (re-)configuration. (GH-8008) #8045
Files	33978.patch

^{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 2018-07-02.09:36:28.065>
created_at = <Date 2018-06-27.09:29:16.048>
labels = ['library', 'performance']
title = 'logging.config.dictConfig with file handler leaks resources'
updated_at = <Date 2018-07-02.11:36:33.218>
user = 'https://github.com/maggyero'

bugs.python.org fields:

activity = <Date 2018-07-02.11:36:33.218>
actor = 'maggyero'
assignee = 'none'
closed = True
closed_date = <Date 2018-07-02.09:36:28.065>
closer = 'vinay.sajip'
components = ['Library (Lib)']
creation = <Date 2018-06-27.09:29:16.048>
creator = 'maggyero'
dependencies = []
files = ['47656']
hgrepos = []
issue_num = 33978
keywords = ['patch']
message_count = 8.0
messages = ['320560', '320652', '320653', '320856', '320859', '320860', '320861', '320873']
nosy_count = 3.0
nosy_names = ['vinay.sajip', 'maggyero', 'xtreak']
pr_nums = ['8008', '8044', '8045']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'resource usage'
url = 'https://bugs.python.org/issue33978'
versions = ['Python 3.6']

[maggyero]

Calling logging.config.dictConfig several times with a file handler in the same Python process leaks resources.

INPUT:

$ python3 -Wall <<EOF
import logging.config

config = {
    "version": 1,
    "handlers": {
        "file": {
            "class": "logging.FileHandler",
            "filename": "test.log"
        }
    },
    "root": {
        "handlers": ["file"]
    }
}
logging.config.dictConfig(config)
logging.config.dictConfig(config)
EOF

OUTPUT:

/usr/lib/python3.6/logging/config.py:789: ResourceWarning: unclosed file <_io.TextIOWrapper name='/home/maggyero/test.log' mode='a' encoding='UTF-8'>
self.common_logger_config(root, config, incremental)

[tirkarthi]

I think while initializing it on the second call we just delete the handlers list variable which contains references to the file handlers instead of properly closing them like it's done in shutdown. handlers is a list of weakreferences and I don't know if they will close file handlers or other resources automatically as they are deleted. If the initialization is done in a loop involving threads then there might be others who are using the handlers as we delete them. The attached patch tries to close the handlers before deletion thus removing the warning. The same is observed in FileConfig too where handlers list is deleted before removal.

shutdown method : https://github.com/python/cpython/blob/master/Lib/logging/__init__.py#L1994
deletion of handlers before closing them : https://github.com/python/cpython/blob/master/Lib/logging/config.py#L528

I think this is merged from Python 2.7 with commit 00ee7ba 12 years back but doesn't produce any effect on Python 2.7 does -W all or -Wall have any effect ?

Thanks

[tirkarthi]

This seems to be a related issue https://bugs.python.org/issue23010 and fix attached but I think it's more towards file handler to be not opened until it's required.

Thanks

[vsajip]

New changeset 087570a by Vinay Sajip (Xtreak) in branch 'master':
bpo-33978: Close existing handlers before logging (re-)configuration. (GH-8008)
087570a

[vsajip]

New changeset 6f49afc by Vinay Sajip (Miss Islington (bot)) in branch '3.7':
bpo-33978: Close existing handlers before logging (re-)configuration. (GH-8008) (GH-8044)
6f49afc

[vsajip]

New changeset b6c1989 by Vinay Sajip (Xtreak) in branch '3.6':
[3.6] bpo-33978: Close existing handlers before logging (re-)configuration. (GH-8008). (GH-8045)
b6c1989

[tirkarthi]

Thanks much @maggyero for the original report and sample test case this was my first non-easy bug fix. Thanks @vinay.sajip for the guidance on logging module implementation.

Thanks

[maggyero]

Thanks @XTreak and @vinay.sajip for the fix.