classification
Title: test_multiprocessing_spawn ResourceWarning with -Werror
Type: behavior Stage: resolved
Components: Interpreter Core, Library (Lib), Tests Versions: Python 3.6, Python 3.5
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: davin, jnoller, martin.panter, pitrou, python-dev, sbt, serhiy.storchaka, vstinner
Priority: normal Keywords: patch

Created on 2015-11-18 07:13 by martin.panter, last changed 2016-04-15 08:31 by vstinner. This issue is now closed.

Files
File name Uploaded Description Edit
cleanup_std_streams.patch serhiy.storchaka, 2015-11-18 12:20 review
multiprocessing_no_close_fd.patch serhiy.storchaka, 2015-11-19 10:18 review
Messages (27)
msg254834 - (view) Author: Martin Panter (martin.panter) * (Python committer) Date: 2015-11-18 07:13
Running the test suite with -Werror enabled causes test_multiprocessing_spawn to print out lots of unhandled errors from the garbage collector, and one of these causes a test failure. It looks like there are lots of files that should be explicitly closed rather than leaving them for the garbage collector.

Also, one error occurred _after_ the test command had exiting. That can’t be a good thing, though I have never used the multiprocessing module so maybe this is unavoidable.

$ ./python -Werror -m unittest -v test.test_multiprocessing_spawn
. . .
======================================================================
FAIL: test_sys_exit (test.test_multiprocessing_spawn.WithProcessesTestSubclassingProcess)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/media/disk/home/proj/python/cpython/Lib/test/_test_multiprocessing.py", line 483, in test_sys_exit
    self.assertEqual(f.read().rstrip(), str(reason))
AssertionError: "[1, 2, 3]\nException ignored in: <_io.Fi[136 chars]-8'>" != '[1, 2, 3]'
- [1, 2, 3]
?          -
+ [1, 2, 3]- Exception ignored in: <_io.FileIO name='/dev/null' mode='rb' closefd=True>
- ResourceWarning: unclosed file <_io.TextIOWrapper name='/dev/null' mode='r' encoding='UTF-8'>

----------------------------------------------------------------------
Ran 265 tests in 151.904s

FAILED (failures=1, skipped=15)
[Exit 1]
$ Exception ignored in: <_io.FileIO name='/dev/null' mode='rb' closefd=True>
ResourceWarning: unclosed file <_io.TextIOWrapper name='/dev/null' mode='r' encoding='UTF-8'>
msg254843 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2015-11-18 12:20
sys.stdin is set to open(os.devnull) in multiprocessing.forkserer and multiprocessing.process (see issue5313). At shutdown stage sys.std* streams are restored to sys.__std*__. Here the resource warning is emitted.

An example that demonstrates similar issue:

$ ./python -We -c 'import sys; sys.stdin = open("/dev/null")'
Exception ignored in: <_io.FileIO name='/dev/null' mode='rb' closefd=True>
ResourceWarning: unclosed file <_io.TextIOWrapper name='/dev/null' mode='r' encoding='UTF-8'>

A workaround is to set sys.__stdin__ as well as sys.stdin. Now a resource warning is no longer emitted at the stage of restoring standard streams, but it can be randomly emitted at the stage of clearing sys dict (depending on the order of deallocating stdin and stderr). The question is why a resource warning is not emitted in normal case, with standard stdin.

Proposed patch closes sys.__stdin__ and set it to sys.stdin in multiprocessing, makes standard streams cleanup at shutdown more reliable, and fixes two tests that set sys.stderr.
msg254864 - (view) Author: Martin Panter (martin.panter) * (Python committer) Date: 2015-11-19 00:06
Perhaps we don’t normally see a warning because stdin normally has closefd=False set?
msg254885 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2015-11-19 08:26
Good point!

The question is whether we want to see resource warnings when override standard streams with open files (usually without closefd=False)?
msg254888 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2015-11-19 08:45
You can commit your patch right now (it shouldn't make things worse), and continue to work on additional tests.
msg254893 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2015-11-19 10:18
Here is an alternative patch that uses closefd=False.
msg254912 - (view) Author: Davin Potts (davin) * (Python committer) Date: 2015-11-19 17:02
Note issue21779 has been around for quite some time with its own patch specifically for multiprocessing, making its tests more robust.

I am hesitant to embrace the patch suggested here.
msg254915 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2015-11-19 17:57
Oh, I forgot about issue21779. And there was at least yet one duplicate issue23827. Thanks for the reminder Davin.

The patch in issue21779 fixes only symptoms, makes failed test more lenient. I prefer to got rid of resource warnings at all.
msg262358 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2016-03-24 15:23
I marked the issue #10305 as a duplicate of this issue.
msg262391 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2016-03-25 00:27
Oh, with fixes for issues #21925 and #26637, test_multiprocessing_spawn started to fail:

http://buildbot.python.org/all/builders/AMD64%20Debian%20root%203.5/builds/727/steps/test/logs/stdio

======================================================================
FAIL: test_sys_exit (test.test_multiprocessing_spawn.WithProcessesTestSubclassingProcess)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/root/buildarea/3.5.angelico-debian-amd64/build/Lib/test/_test_multiprocessing.py", line 483, in test_sys_exit
    self.assertEqual(f.read().rstrip(), str(reason))
AssertionError: "[1, 2, 3]\nsys:1: ResourceWarning: unclo[67 chars]-8'>" != '[1, 2, 3]'
- [1, 2, 3]
?          -
+ [1, 2, 3]- sys:1: ResourceWarning: unclosed file <_io.TextIOWrapper name='/dev/null' mode='r' encoding='UTF-8'>
msg262406 - (view) Author: Roundup Robot (python-dev) (Python triager) Date: 2016-03-25 08:33
New changeset 9faa03e9cea8 by Victor Stinner in branch 'default':
Issue #25654:
https://hg.python.org/cpython/rev/9faa03e9cea8
msg262407 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2016-03-25 08:41
I pushed a change based on multiprocessing_no_close_fd.patch. I changed multiprocessing.util._close_stdin() to try to replace sys.stdin with os.devnull even if stdin.close() raised an exception. Since stdin is read-only, I don't expect an exception on stdin.close(), but it's just in case :-) What do you think? Is it better to keep stdin if stdin.close() raises an exception?

I hate having to push changes without careful review. I wanted to fix buildbots as soon as possible. I'm working hard since 1 week to fix all random bugs on buildbots, so it's annoying when *all* buildbots are red :-/

I will read again the change later, but IMHO the approach is the good one. Python initialization also creates files (stdin, stdout, stderr) with closefd=False.

The change should be backported to Python 3.5. I'm waiting for buildbots and I have to read again the change later.

Note: It looks like all ResourceWarning of unit tests are now fixed. The following change succeed:

./python -Werror -m test -j0 test_multiprocessing_fork.py test_multiprocessing_forkserver.py test_multiprocessing_spawn.py test_multiprocessing_main_handling.py
msg262411 - (view) Author: Roundup Robot (python-dev) (Python triager) Date: 2016-03-25 09:11
New changeset 357d1ed928fe by Victor Stinner in branch '3.5':
Issue #25654:
https://hg.python.org/cpython/rev/357d1ed928fe
msg262413 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2016-03-25 09:13
> The change should be backported to Python 3.5. I'm waiting for buildbots and I have to read again the change later.

Oh, I didn't notice that 3.5 buildbots were also all red. So I
backported the fix immediatly.
msg262414 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2016-03-25 09:36
> What do you think? Is it better to keep stdin if stdin.close() raises an exception?

I don't know. I don't know why OSError and ValueError are caught at all.

What are you think about deterministic closing standard streams in leanup_std_streams.patch? There is no haste to commit this.
msg262415 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2016-03-25 09:49
> I don't know. I don't know why OSError and ValueError are caught at all.

Ha ha, me neither. Maybe it's time to remove them an wait for user feedback :-)

> What are you think about deterministic closing standard streams in cleanup_std_streams.patch? There is no haste to commit this.

This change has two parts.

For the "stdout.flush() ... stdout.close() ... stdout = None" part:

* It looks like a good idea to set stout (and stderr) to None, since I see many C code having an explicit "stream is None" check (handle correctly this case).
* For the flush part: I would prefer to share code with pylifecycle.c, flush_std_files(). Maybe we can log flush error into the C stderr stream? (Maybe with a flag when we know that Python finalization has started, or check _Py_Finalizing?)
* For the close part: I don't know. I like the idea of being able to use print until the last Python instruction.

Instead of closing and setting stdout/stderr to None, what do you think of using something similar than Py_Initialize():

    /* Set up a preliminary stderr printer until we have enough
       infrastructure for the io module in place. */
    pstderr = PyFile_NewStdPrinter(fileno(stderr));
    if (pstderr == NULL)
        Py_FatalError("Py_Initialize: can't set preliminary stderr");
    _PySys_SetObjectId(&PyId_stderr, pstderr);
    PySys_SetObject("__stderr__", pstderr);
    Py_DECREF(pstderr);

This printer has limitations, but it can help to get very late messages during Python finalization.

If we use this printer, it reduces the pressure on the exact order of operations.
msg262416 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2016-03-25 09:56
By the way, I'm not sure that using UTF-8/backslashescape is the
encoding :-/ It's common to use Latin1 on a terminal. UTF-8 is very
rare on Windows for the console for example.
msg262417 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2016-03-25 09:56
ASCII/backslashescape is maybe a better encoding for this printer.
msg262418 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2016-03-25 10:09
Lets open new issue for this.
msg262419 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2016-03-25 10:16
Serhiy:
> Lets open new issue for this.

I agree with PyImport_Cleanup() deserves a dedicated issue.

Myself:
> This change has two parts.

Oops, I forgot to discuss the second part :-) You also added "sys.__stderr__ = sys.stderr" in multiprocessing.

I don't understand this change. Can you please explain why you want to do that?

Above, you wrote "A workaround is to set sys.__stdin__ as well as sys.stdin."

Is "sys.__stderr__ = sys.stderr" also a workaround?
msg262421 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2016-03-25 11:07
> Oops, I forgot to discuss the second part :-) You also added "sys.__stderr__ = sys.stderr" in multiprocessing.

At the start of PyImport_Cleanup() sys.stdXXX is set to sys.__stdXXX__. If sys.stdXXX is not sys.__stdXXX__ and here is the last reference to the stream, this causes deallocating sys.stdXXX and emitting a resource warning. If set sys.__stdXXX__ to sys.stdXXX, deallocating the stream is deferred to the end of PyImport_Cleanup(). Other changes make PyImport_Cleanup() to close standard streams explicitly before deallocating, thus resource warning are not emitted.

This workaround is not needed if deallocating sys.stdin doesn't emit a resource warning (since it is opened with closefd=False). But it still may be needed in tests if apply proposed changes to PyImport_Cleanup(), since sys.stderr is set to a file opened with closefd=True.
msg262437 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2016-03-25 13:13
> Lets open new issue for this.

I opened the issue #26642 "Replace stdout and stderr with simple standard printers at Python exit".
msg262458 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2016-03-25 23:02
I'm not sure why Python 2.7 was in the Versions. I just ran "python2.7 -Werror -m test.regrtest -v test_multiprocessing" => no error. ResourceWarning doesn't exist in Python 2.

Is it still something to do on multiprocessing about ResourceWarning?

I didn't understand if you (Martin and Serhiy) are ok with my change (based on Serhiy's change).
msg262480 - (view) Author: Martin Panter (martin.panter) * (Python committer) Date: 2016-03-26 01:31
Sorry, but I don’t think I have the time/motivation/expertise to look into the fix in detail. But there are no warnings or failures anymore when I use -Werror, so I am happy!

BTW the spurious background processes are still there (visible if you run “ps” or “pstree” immediately after the test finishes), but they no longer print errors.
msg263406 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2016-04-14 12:54
Since the initial issue is fixed (test failures when using -Werror), I suggest to close this issue.

> BTW the spurious background processes are still there (visible if you run “ps” or “pstree” immediately after the test finishes), but they no longer print errors.

Please open a new issue for that.
msg263447 - (view) Author: Martin Panter (martin.panter) * (Python committer) Date: 2016-04-15 04:50
Opened Issue 26762 about the leftover processes.
msg263459 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2016-04-15 08:31
Thanks.
History
Date User Action Args
2016-04-15 08:31:42vstinnersetmessages: + msg263459
2016-04-15 04:50:25martin.pantersetstatus: open -> closed
resolution: fixed
messages: + msg263447

stage: patch review -> resolved
2016-04-14 12:54:16vstinnersetmessages: + msg263406
2016-03-26 01:31:44martin.pantersetmessages: + msg262480
2016-03-25 23:02:53vstinnersetmessages: + msg262458
versions: - Python 2.7, Python 3.4
2016-03-25 13:13:59vstinnersetmessages: + msg262437
2016-03-25 11:07:50serhiy.storchakasetmessages: + msg262421
2016-03-25 10:16:30vstinnersetmessages: + msg262419
2016-03-25 10:09:48serhiy.storchakasetmessages: + msg262418
2016-03-25 09:56:45vstinnersetmessages: + msg262417
2016-03-25 09:56:30vstinnersetmessages: + msg262416
2016-03-25 09:49:19vstinnersetmessages: + msg262415
2016-03-25 09:36:11serhiy.storchakasetmessages: + msg262414
2016-03-25 09:13:20vstinnersetmessages: + msg262413
2016-03-25 09:11:26python-devsetmessages: + msg262411
2016-03-25 08:41:25vstinnersetmessages: + msg262407
2016-03-25 08:33:04python-devsetnosy: + python-dev
messages: + msg262406
2016-03-25 00:27:48vstinnersetmessages: + msg262391
2016-03-24 15:23:47vstinnersetmessages: + msg262358
2016-03-24 15:23:35vstinnerlinkissue10305 superseder
2016-03-24 15:21:25vstinnersetnosy: + vstinner
2015-11-19 17:58:27serhiy.storchakalinkissue21779 superseder
2015-11-19 17:57:40serhiy.storchakasetnosy: + sbt
messages: + msg254915
2015-11-19 17:02:21davinsetnosy: + davin
messages: + msg254912
2015-11-19 10:18:04serhiy.storchakasetfiles: + multiprocessing_no_close_fd.patch

messages: + msg254893
2015-11-19 08:45:10serhiy.storchakasetmessages: + msg254888
2015-11-19 08:26:49serhiy.storchakasetmessages: + msg254885
2015-11-19 00:06:41martin.pantersetmessages: + msg254864
2015-11-18 12:20:11serhiy.storchakasetfiles: + cleanup_std_streams.patch

components: + Interpreter Core, Library (Lib)
versions: + Python 2.7, Python 3.4, Python 3.5
keywords: + patch
nosy: + serhiy.storchaka, pitrou, jnoller

messages: + msg254843
stage: patch review
2015-11-18 07:13:48martin.pantercreate