ResourceWarning sometimes doesn't display

[msmhrt]

BPO	21925
Nosy	@pitrou, @vstinner, @ned-deily, @serhiy-storchaka
Files	unload_main_first.patch warnings_shutdown.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 2016-03-24.23:37:36.597>
created_at = <Date 2014-07-06.02:49:33.269>
labels = ['interpreter-core', 'performance']
title = "ResourceWarning sometimes doesn't display"
updated_at = <Date 2016-03-25.09:11:25.605>
user = 'https://bugs.python.org/msmhrt'

bugs.python.org fields:

activity = <Date 2016-03-25.09:11:25.605>
actor = 'python-dev'
assignee = 'none'
closed = True
closed_date = <Date 2016-03-24.23:37:36.597>
closer = 'vstinner'
components = ['Interpreter Core']
creation = <Date 2014-07-06.02:49:33.269>
creator = 'msmhrt'
dependencies = []
files = ['35896', '42276']
hgrepos = []
issue_num = 21925
keywords = ['patch']
message_count = 14.0
messages = ['222390', '222392', '222517', '222518', '222519', '222595', '222937', '262353', '262354', '262384', '262385', '262386', '262408', '262410']
nosy_count = 7.0
nosy_names = ['pitrou', 'vstinner', 'ned.deily', 'Arfrever', 'python-dev', 'serhiy.storchaka', 'msmhrt']
pr_nums = []
priority = 'normal'
resolution = 'fixed'
stage = None
status = 'closed'
superseder = None
type = 'resource usage'
url = 'https://bugs.python.org/issue21925'
versions = ['Python 3.5', 'Python 3.6']

[msmhrt]

It seems that ResouceWarning about unclosed file handles with '-W all' option sometimes doesn't display.
Is this behaviour normal?

$ uname -a
Linux ashrose 3.2.0-65-generic #99-Ubuntu SMP Fri Jul 4 21:03:29 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux
$ python3.4 --version
Python 3.4.1
$ touch spam.txt
$ echo 'a = open("spam.txt")' >test_warning.py
$
$ python3.4 -W all test_warning.py
$ python3.4 -W all test_warning.py
sys:1: ResourceWarning: unclosed file <_io.TextIOWrapper name='spam.txt' mode='r' encoding='UTF-8'>
$ python3.4 -W all test_warning.py
sys:1: ResourceWarning: unclosed file <_io.TextIOWrapper name='spam.txt' mode='r' encoding='UTF-8'>
$ python3.4 -W all test_warning.py
$ python3.4 -W all test_warning.py
$ python3.4 -W all test_warning.py
$ python3.4 -W all test_warning.py
$ python3.4 -W all test_warning.py
sys:1: ResourceWarning: unclosed file <_io.TextIOWrapper name='spam.txt' mode='r' encoding='UTF-8'>
$

[ned-deily]

I believe this is an artifact of hash randomization which affects the order of how objects are destroyed during shutdown. If you run your test using different values of the PYTHONHASHSEED environment variable, you'll probably see predictable results. For example, with a particular build of Python 3.4.1, if I set PYTHONHASHSEED set to 0, thereby disabling hash randomization, I never see the warning:

PYTHONHASHSEED=0 python3.4 -W all test_warning.py

With it set to 1, I always see the warning. With 2, no warning. With no PYTHONHASHSEED, I see random behavior similar to your results.

I don't think there is anything to be done here as Python makes no promises about when and in what order objects are collected.

https://docs.python.org/3/using/cmdline.html#envvar-PYTHONHASHSEED

[vstinner]

The problem is tricky.

The modules are deleted in a random order at exit. The problem is that showing the warning requires to import the linecache module. But during Python finalization, we may or may not be able to import modules.

Py_Finalize() calls PyImport_Cleanup() which starts by setting sys.path and sys.meta_path to None. The _find_spec() function of importlib._bootstrap fails because sys.meta_path is None. In fact, find_spec() starts by emiting a warning which calls formatwarning() which tries to import linecache again... and then importlib emits again a warning... "import linecache" is tried twice and then everything fails.

A workaround would be to unload the __main__ module first, before clearing sys attributes.

Another workaround would be to not try to import modules in warnings.formatwarning() if Python is exiting.

The tricky exit code was already discussed in the issue bpo-19421 ("FileIO destructor imports indirectly the io module at exit"). See also my more general issue bpo-21788 ("Rework Python finalization").

[python-dev]

New changeset 047da19efdab by Victor Stinner in branch '3.4':
Issue bpo-21925: PyImport_Cleanup(): Remove unused parameter in
http://hg.python.org/cpython/rev/047da19efdab

New changeset b255ecb175c4 by Victor Stinner in branch 'default':
(Merge 3.4) Issue bpo-21925: PyImport_Cleanup(): Remove unused parameter in
http://hg.python.org/cpython/rev/b255ecb175c4

[vstinner]

I don't know if it's the best trick, but here is a patch to unload the __main__ module first in PyImport_Cleanup().

[pitrou]

Well, it's unclear to me why we would want to remove the __main__ module first, rather than last.

[serhiy-storchaka]

May be save the timestamp for module importing and then clean up modules them in reversed order?

[vstinner]

It looks like the warnings is logged when the C implemention is used. When the Python implementation is used, "import linecache" or "linecache.getline()" fail, and so the warnings is skipped.

Attached patch makes the Python implementation safer when Python is shutting down. Add "try/except Exception" to ignore exceptions on import, linecache and tracemalloc.

[vstinner]

See also the issue bpo-26637: "importlib: better error message when import fail during Python shutdown".

[vstinner]

It looks like logging a warning at Python exit always works on Python 2.7:
---

import _warnings

class Bla:
    def __del__(self, w=_warnings):
        w.warn_explicit('message', DeprecationWarning, 'x.py', 5)

bla = Bla()

---

It looks like it uses the Python implementation and linecache.getline() always works. Maybe the warning is emitted earlier that the Python 3 code emitting ResourceWarning. I see that warnings.py of Python 2 imports linecache at top level, whereas the Python 3 code imports the module at the first use in showwarning(). I recall that imports at top level are avoided to get faster startup time.

[python-dev]

New changeset 1de90a7065ba by Victor Stinner in branch '3.5':
warnings.formatwarning(): catch exceptions
https://hg.python.org/cpython/rev/1de90a7065ba

New changeset 36be356f6253 by Victor Stinner in branch 'default':
Merge 3.5
https://hg.python.org/cpython/rev/36be356f6253

[vstinner]

I fixed warnings.formatwarning(). I don't expect the code to be perfect (Python shutdown process is complex and fragile), but the fix is quite simple and it's enough to fix the bug described in the initial message. I even added an unit test for it.

I didn't try to force when the __main__ module is unloaded, I didn't see any consensus around that.

Thanks for the bug report, it's now fixed ;-) Sorry for the delay. We had to fix a million of other subtle issues to make the Python shutdown process and the stdlib stronger.