classification
Title: logging.config.dictConfig with file handler leaks resources
Type: resource usage Stage: resolved
Components: Library (Lib) Versions: Python 3.6
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: maggyero, vinay.sajip, xtreak
Priority: normal Keywords: patch

Created on 2018-06-27 09:29 by maggyero, last changed 2018-07-02 11:36 by maggyero. This issue is now closed.

Files
File name Uploaded Description Edit
33978.patch xtreak, 2018-06-28 07:13
Pull Requests
URL Status Linked Edit
PR 8008 merged xtreak, 2018-06-29 12:36
PR 8044 merged miss-islington, 2018-07-02 09:02
PR 8045 merged xtreak, 2018-07-02 09:07
Messages (8)
msg320560 - (view) Author: Géry (maggyero) * Date: 2018-06-27 09:29
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)
msg320652 - (view) Author: Karthikeyan Singaravelan (xtreak) * (Python triager) Date: 2018-06-28 07:13
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 https://github.com/python/cpython/commit/00ee7baf49430d8a6eed355a5fd7a05179325747 12 years back but doesn't produce any effect on Python 2.7 does -W all or -Wall have any effect ? 


Thanks
msg320653 - (view) Author: Karthikeyan Singaravelan (xtreak) * (Python triager) Date: 2018-06-28 07:19
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
msg320856 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2018-07-02 08:57
New changeset 087570af6d5d39b51bdd5e660a53903960e58678 by Vinay Sajip (Xtreak) in branch 'master':
bpo-33978: Close existing handlers before logging (re-)configuration. (GH-8008)
https://github.com/python/cpython/commit/087570af6d5d39b51bdd5e660a53903960e58678
msg320859 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2018-07-02 09:35
New changeset 6f49afc3d983350f4f04d221a26573721f23c475 by Vinay Sajip (Miss Islington (bot)) in branch '3.7':
bpo-33978: Close existing handlers before logging (re-)configuration. (GH-8008) (GH-8044)
https://github.com/python/cpython/commit/6f49afc3d983350f4f04d221a26573721f23c475
msg320860 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2018-07-02 09:35
New changeset b6c1989168efeb8b6320bec958e7e339270ac0ce by Vinay Sajip (Xtreak) in branch '3.6':
[3.6] bpo-33978: Close existing handlers before logging (re-)configuration. (GH-8008). (GH-8045)
https://github.com/python/cpython/commit/b6c1989168efeb8b6320bec958e7e339270ac0ce
msg320861 - (view) Author: Karthikeyan Singaravelan (xtreak) * (Python triager) Date: 2018-07-02 09:45
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
msg320873 - (view) Author: Géry (maggyero) * Date: 2018-07-02 11:36
Thanks @xtreak and @vinay.sajip for the fix.
History
Date User Action Args
2018-07-02 11:36:33maggyerosetmessages: + msg320873
2018-07-02 09:45:45xtreaksetmessages: + msg320861
versions: - Python 3.7, Python 3.8
2018-07-02 09:36:28vinay.sajipsetstatus: open -> closed
stage: patch review -> resolved
resolution: fixed
versions: + Python 3.7, Python 3.8
2018-07-02 09:35:54vinay.sajipsetmessages: + msg320860
2018-07-02 09:35:12vinay.sajipsetmessages: + msg320859
2018-07-02 09:07:50xtreaksetpull_requests: + pull_request7654
2018-07-02 09:02:32miss-islingtonsetpull_requests: + pull_request7653
2018-07-02 08:57:53vinay.sajipsetmessages: + msg320856
2018-06-29 12:39:21xiang.zhangsetnosy: + vinay.sajip
2018-06-29 12:36:20xtreaksetstage: patch review
pull_requests: + pull_request7613
2018-06-28 07:19:01xtreaksetmessages: + msg320653
2018-06-28 07:13:24xtreaksetfiles: + 33978.patch

nosy: + xtreak
messages: + msg320652

keywords: + patch
2018-06-27 09:29:16maggyerocreate