classification
Title: test_communicate_epipe() of test_subprocess fails randomly on AMD64 Windows7 SP1 3.x
Type: Stage: resolved
Components: Tests, Windows Versions: Python 3.7, Python 3.6, Python 3.5, Python 2.7
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: eryksun, paul.moore, steve.dower, tim.golden, vstinner, zach.ware
Priority: normal Keywords:

Created on 2017-05-20 22:32 by vstinner, last changed 2017-06-09 14:15 by vstinner. This issue is now closed.

Pull Requests
URL Status Linked Edit
PR 2002 merged vstinner, 2017-06-08 14:56
PR 2004 merged vstinner, 2017-06-08 15:34
PR 2005 merged vstinner, 2017-06-08 15:37
PR 2006 merged vstinner, 2017-06-08 15:40
Messages (12)
msg294056 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2017-05-20 22:32
Hum, the following failing looks like bpo-19612, but it seems like the code took the "raise" path instead of the "pass" fails.

            try:
                self.stdin.write(input)   <~~~~ HERE
            except BrokenPipeError:
                pass  # communicate() must ignore broken pipe errors.
            except OSError as e:
                if e.errno == errno.EINVAL and self.poll() is not None:
                    # Issue #19612: On Windows, stdin.write() fails with EINVAL
                    # if the process already exited before the write
                    pass
                else:
                    raise

On AMD64 Windows7 SP1 3.x:

http://buildbot.python.org/all/builders/AMD64%20Windows7%20SP1%203.x/builds/452/steps/test/logs/stdio

...
test_communicate (test.test_subprocess.ProcessTestCase) ... ok
test_communicate_eintr (test.test_subprocess.ProcessTestCase) ... skipped 'Requires signal.SIGUSR1'
test_communicate_epipe (test.test_subprocess.ProcessTestCase) ... ERROR
C:\buildbot.python.org\3.x.kloth-win64\build\lib\subprocess.py:763: ResourceWarning: subprocess 1780 is still running
  ResourceWarning, source=self)
test_communicate_epipe_only_stdin (test.test_subprocess.ProcessTestCase) ... ok
test_communicate_errors (test.test_subprocess.ProcessTestCase) ... ok
test_communicate_pipe_buf (test.test_subprocess.ProcessTestCase) ... ok
...
======================================================================
ERROR: test_communicate_epipe (test.test_subprocess.ProcessTestCase)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\test\test_subprocess.py", line 1219, in test_communicate_epipe
    p.communicate(b"x" * 2**20)
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\subprocess.py", line 838, in communicate
    stdout, stderr = self._communicate(input, endtime, timeout)
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\subprocess.py", line 1072, in _communicate
    self._stdin_write(input)
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\subprocess.py", line 778, in _stdin_write
    self.stdin.write(input)
OSError: [Errno 22] Invalid argument

----------------------------------------------------------------------
Ran 261 tests in 43.540s

FAILED (errors=1, skipped=150)
test test_subprocess failed
msg294066 - (view) Author: Eryk Sun (eryksun) * (Python triager) Date: 2017-05-21 02:00
Seeing EINVAL here while the child process is alive could mean the read end of the pipe was closed. For example:

    >>> import time, subprocess
    >>> cmd = 'python -c "import os, time; os.close(0); time.sleep(15)"'
    >>> p = subprocess.Popen(cmd, stdin=subprocess.PIPE, bufsize=0)
    >>> time.sleep(5); p.communicate(b'spam')
    Traceback (most recent call last):
      File "<stdin>", line 1, in <module>
      File "C:\Program Files\Python36\lib\subprocess.py", line 821, in communicate
        self._stdin_write(input)
      File "C:\Program Files\Python36\lib\subprocess.py", line 776, in _stdin_write
        self.stdin.write(input)
    OSError: [Errno 22] Invalid argument

If buffered, the error would instead occur at self.stdin.close(). Both cases are currently checked, but the error is only ignored when the child process is still alive.

The underlying Windows error is ERROR_NO_DATA. If we could know that for certain, then we could ignore it as a BrokenPipeError. Currently all we have to go on from _Py_write is the CRT's EINVAL errno value. In contrast, when creating an OSError from the Windows last error value, winerror_to_errno() maps ERROR_NO_DATA as EPIPE.
msg294067 - (view) Author: Eryk Sun (eryksun) * (Python triager) Date: 2017-05-21 02:04
> but the error is only ignored when the child process is still alive.

This should instead be the error is only ignored when child process is *no longer* alive.
msg294069 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2017-05-21 02:27
Would you like to work on a PR Eryk? It seems like you understand the bug
better than me ;-)
msg294072 - (view) Author: Eryk Sun (eryksun) * (Python triager) Date: 2017-05-21 04:16
Addressing the underlying problem would require rewriting _Py_read and _Py_write_impl to directly call ReadFile and WriteFile instead of the CRT read and write functions. Barring that, on Windows _stdin_write would have to always ignore EINVAL.
msg294087 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2017-05-21 08:21
Basically, Windows EINVAL here looks like UNIX EPIPE. I agree to always
ignore it (remove the check on poll()).

I added the poll() check when I added the EINVAL test because I don't know
well Windows and I didn't know that write () can also fail with EINVAL if
the process is still running.

Your example makes it perfectly clear.

In short, Python must behave the same on Windows and UNIX on your example:
ignore errors on stdin.write().
msg294088 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2017-05-21 08:22
So, would you mind to write such PR?
msg295448 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2017-06-08 15:30
New changeset d52aa31378ae43e044a300edfe8285954c167216 by Victor Stinner in branch 'master':
bpo-30418: Popen.communicate() always ignore EINVAL (#2002)
https://github.com/python/cpython/commit/d52aa31378ae43e044a300edfe8285954c167216
msg295453 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2017-06-08 16:20
New changeset df04c088493bdbc2defea5e225a94e9bdd8e759f by Victor Stinner in branch '3.5':
bpo-30418: Popen.communicate() always ignore EINVAL (#2002) (#2005)
https://github.com/python/cpython/commit/df04c088493bdbc2defea5e225a94e9bdd8e759f
msg295454 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2017-06-08 16:34
New changeset e5bdad2201de45c203037e59491e4fea56def56d by Victor Stinner in branch '2.7':
bpo-30418: Popen.communicate() always ignore EINVAL (#2002) (#2006)
https://github.com/python/cpython/commit/e5bdad2201de45c203037e59491e4fea56def56d
msg295466 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2017-06-08 21:14
New changeset b319d09ee4427aac1ee8f298692127d34ef57dc0 by Victor Stinner in branch '3.6':
bpo-30418: Popen.communicate() always ignore EINVAL (#2002) (#2004)
https://github.com/python/cpython/commit/b319d09ee4427aac1ee8f298692127d34ef57dc0
msg295529 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2017-06-09 14:15
The bug should now be fixed. EINVAL is now also ignored even if the process is still running, same behaviour than UNIX with EPIPE.
History
Date User Action Args
2017-06-09 14:15:07vstinnersetstatus: open -> closed
resolution: fixed
messages: + msg295529

stage: resolved
2017-06-08 21:14:09vstinnersetmessages: + msg295466
2017-06-08 16:34:33vstinnersetmessages: + msg295454
2017-06-08 16:20:48vstinnersetmessages: + msg295453
2017-06-08 15:40:21vstinnersetpull_requests: + pull_request2073
2017-06-08 15:37:02vstinnersetpull_requests: + pull_request2072
2017-06-08 15:35:09vstinnersetversions: + Python 2.7, Python 3.5, Python 3.6
2017-06-08 15:34:46vstinnersetpull_requests: + pull_request2071
2017-06-08 15:30:42vstinnersetmessages: + msg295448
2017-06-08 14:56:15vstinnersetpull_requests: + pull_request2069
2017-05-21 08:22:20vstinnersetmessages: + msg294088
2017-05-21 08:21:11vstinnersetmessages: + msg294087
2017-05-21 04:16:45eryksunsetmessages: + msg294072
2017-05-21 02:27:40vstinnersetmessages: + msg294069
2017-05-21 02:04:54eryksunsetmessages: + msg294067
2017-05-21 02:00:22eryksunsetnosy: + eryksun
messages: + msg294066
2017-05-20 22:32:14vstinnersetcomponents: + Tests
2017-05-20 22:32:01vstinnercreate