test_communicate_epipe() of test_subprocess fails randomly on AMD64 Windows7 SP1 3.x

[vstinner]

BPO	30418
Nosy	@pfmoore, @vstinner, @tjguk, @zware, @eryksun, @zooba
PRs	bpo-30418: Popen.communicate() always ignore EINVAL #2002 [3.6] bpo-30418: Popen.communicate() always ignore EINVAL (#2002) #2004 [3.5] bpo-30418: Popen.communicate() always ignore EINVAL (#2002) #2005 [2.7] bpo-30418: Popen.communicate() always ignore EINVAL (#2002) #2006

^{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 2017-06-09.14:15:07.524>
created_at = <Date 2017-05-20.22:32:01.235>
labels = ['3.7', 'tests', 'OS-windows']
title = 'test_communicate_epipe() of test_subprocess fails randomly on AMD64 Windows7 SP1 3.x'
updated_at = <Date 2017-06-09.14:15:07.522>
user = 'https://github.com/vstinner'

bugs.python.org fields:

activity = <Date 2017-06-09.14:15:07.522>
actor = 'vstinner'
assignee = 'none'
closed = True
closed_date = <Date 2017-06-09.14:15:07.524>
closer = 'vstinner'
components = ['Tests', 'Windows']
creation = <Date 2017-05-20.22:32:01.235>
creator = 'vstinner'
dependencies = []
files = []
hgrepos = []
issue_num = 30418
keywords = []
message_count = 12.0
messages = ['294056', '294066', '294067', '294069', '294072', '294087', '294088', '295448', '295453', '295454', '295466', '295529']
nosy_count = 6.0
nosy_names = ['paul.moore', 'vstinner', 'tim.golden', 'zach.ware', 'eryksun', 'steve.dower']
pr_nums = ['2002', '2004', '2005', '2006']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = None
url = 'https://bugs.python.org/issue30418'
versions = ['Python 2.7', 'Python 3.5', 'Python 3.6', 'Python 3.7']

[vstinner]

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 bpo-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

[eryksun]

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.

[eryksun]

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.

[vstinner]

Would you like to work on a PR Eryk? It seems like you understand the bug
better than me ;-)

[eryksun]

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.

[vstinner]

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().

[vstinner]

So, would you mind to write such PR?

[vstinner]

New changeset d52aa31 by Victor Stinner in branch 'master':
bpo-30418: Popen.communicate() always ignore EINVAL (bpo-2002)
d52aa31

[vstinner]

New changeset df04c08 by Victor Stinner in branch '3.5':
bpo-30418: Popen.communicate() always ignore EINVAL (bpo-2002) (bpo-2005)
df04c08

[vstinner]

New changeset e5bdad2 by Victor Stinner in branch '2.7':
bpo-30418: Popen.communicate() always ignore EINVAL (bpo-2002) (bpo-2006)
e5bdad2

[vstinner]

New changeset b319d09 by Victor Stinner in branch '3.6':
bpo-30418: Popen.communicate() always ignore EINVAL (bpo-2002) (bpo-2004)
b319d09

[vstinner]

The bug should now be fixed. EINVAL is now also ignored even if the process is still running, same behaviour than UNIX with EPIPE.