test_asyncio: test_subprocess test_stdin_broken_pipe() failure on Travis CI

[vstinner]

BPO	33531
Nosy	@terryjreedy, @vstinner, @tiran, @asvetlov, @1st1, @grimreaper

^{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 2018-09-19.23:25:51.017>
created_at = <Date 2018-05-16.06:29:52.901>
labels = ['3.8', '3.7', 'tests', 'expert-asyncio']
title = 'test_asyncio: test_subprocess test_stdin_broken_pipe() failure on Travis CI'
updated_at = <Date 2018-09-19.23:25:51.016>
user = 'https://github.com/vstinner'

bugs.python.org fields:

activity = <Date 2018-09-19.23:25:51.016>
actor = 'vstinner'
assignee = 'none'
closed = True
closed_date = <Date 2018-09-19.23:25:51.017>
closer = 'vstinner'
components = ['Tests', 'asyncio']
creation = <Date 2018-05-16.06:29:52.901>
creator = 'vstinner'
dependencies = []
files = []
hgrepos = []
issue_num = 33531
keywords = []
message_count = 11.0
messages = ['316770', '316995', '316996', '316998', '317081', '317242', '317272', '317320', '319027', '319028', '319029']
nosy_count = 6.0
nosy_names = ['terry.reedy', 'vstinner', 'christian.heimes', 'asvetlov', 'yselivanov', 'eitan.adler']
pr_nums = []
priority = 'normal'
resolution = 'out of date'
stage = 'resolved'
status = 'closed'
superseder = None
type = None
url = 'https://bugs.python.org/issue33531'
versions = ['Python 3.6', 'Python 3.7', 'Python 3.8']

[vstinner]

https://travis-ci.org/python/cpython/jobs/379560387

======================================================================
FAIL: test_stdin_broken_pipe (test.test_asyncio.test_subprocess.SubprocessFastWatcherTests)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/home/travis/build/python/cpython/Lib/test/test_asyncio/test_subprocess.py", line 214, in test_stdin_broken_pipe
    self.loop.run_until_complete, coro)
AssertionError: (<class 'BrokenPipeError'>, <class 'ConnectionResetError'>) not raised by run_until_complete

======================================================================
FAIL: test_stdin_broken_pipe (test.test_asyncio.test_subprocess.SubprocessSafeWatcherTests)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/home/travis/build/python/cpython/Lib/test/test_asyncio/test_subprocess.py", line 214, in test_stdin_broken_pipe
    self.loop.run_until_complete, coro)
AssertionError: (<class 'BrokenPipeError'>, <class 'ConnectionResetError'>) not raised by run_until_complete

It looks like bpo-30382 which has been closed because it disappears from "AMD64 FreeBSD CURRENT Non-Debug 3.x", but this bug was already random.

[terryjreedy]

I have also gotten test_async errors on AppVeyor and MSTS Windows.

ERROR: test__sock_sendfile_native_failure (test.test_asyncio.test_base_events.BaseLoopSockSendfileTests)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "C:\projects\cpython\lib\test\test_asyncio\test_base_events.py", line 1881, in test__sock_sendfile_native_failure
    sock, proto = self.prepare()
  File "C:\projects\cpython\lib\test\test_asyncio\test_base_events.py", line 1866, in prepare
    self.run_loop(self.loop.sock_connect(sock, (support.HOST, port)))
  File "C:\projects\cpython\lib\test\test_asyncio\test_base_events.py", line 1846, in run_loop
    return self.loop.run_until_complete(coro)
  File "C:\projects\cpython\lib\asyncio\base_events.py", line 566, in run_until_complete
    return future.result()
  File "C:\projects\cpython\lib\asyncio\selector_events.py", line 475, in sock_connect
    return await fut
  File "C:\projects\cpython\lib\asyncio\selector_events.py", line 505, in _sock_connect_cb
    raise OSError(err, f'Connect call failed {address}')
ConnectionRefusedError: [Errno 10061] Connect call failed ('127.0.0.1', 6284)

======================================================================
ERROR: test_sock_sendfile_fallback (test.test_asyncio.test_base_events.BaseLoopSockSendfileTests)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "C:\projects\cpython\lib\test\test_asyncio\test_base_events.py", line 1903, in test_sock_sendfile_fallback
    sock, proto = self.prepare()
  File "C:\projects\cpython\lib\test\test_asyncio\test_base_events.py", line 1866, in prepare
    self.run_loop(self.loop.sock_connect(sock, (support.HOST, port)))
  File "C:\projects\cpython\lib\test\test_asyncio\test_base_events.py", line 1846, in run_loop
    return self.loop.run_until_complete(coro)
  File "C:\projects\cpython\lib\asyncio\base_events.py", line 566, in run_until_complete
    return future.result()
  File "C:\projects\cpython\lib\asyncio\selector_events.py", line 475, in sock_connect
    return await fut
  File "C:\projects\cpython\lib\asyncio\selector_events.py", line 505, in _sock_connect_cb
    raise OSError(err, f'Connect call failed {address}')
ConnectionRefusedError: [Errno 10061] Connect call failed ('127.0.0.1', 6303)

======================================================================
ERROR: test_sock_sendfile_fallback_offset_and_count (test.test_asyncio.test_base_events.BaseLoopSockSendfileTests)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "C:\projects\cpython\lib\test\test_asyncio\test_base_events.py", line 1914, in test_sock_sendfile_fallback_offset_and_count
    sock, proto = self.prepare()
  File "C:\projects\cpython\lib\test\test_asyncio\test_base_events.py", line 1866, in prepare
    self.run_loop(self.loop.sock_connect(sock, (support.HOST, port)))
  File "C:\projects\cpython\lib\test\test_asyncio\test_base_events.py", line 1846, in run_loop
    return self.loop.run_until_complete(coro)
  File "C:\projects\cpython\lib\asyncio\base_events.py", line 566, in run_until_complete
    return future.result()
  File "C:\projects\cpython\lib\asyncio\selector_events.py", line 475, in sock_connect
    return await fut
  File "C:\projects\cpython\lib\asyncio\selector_events.py", line 505, in _sock_connect_cb
    raise OSError(err, f'Connect call failed {address}')
ConnectionRefusedError: [Errno 10061] Connect call failed ('127.0.0.1', 6308)

======================================================================
ERROR: test_sock_sendfile_no_fallback (test.test_asyncio.test_base_events.BaseLoopSockSendfileTests)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "C:\projects\cpython\lib\test\test_asyncio\test_base_events.py", line 1892, in test_sock_sendfile_no_fallback
    sock, proto = self.prepare()
  File "C:\projects\cpython\lib\test\test_asyncio\test_base_events.py", line 1866, in prepare
    self.run_loop(self.loop.sock_connect(sock, (support.HOST, port)))
  File "C:\projects\cpython\lib\test\test_asyncio\test_base_events.py", line 1846, in run_loop
    return self.loop.run_until_complete(coro)
  File "C:\projects\cpython\lib\asyncio\base_events.py", line 566, in run_until_complete
    return future.result()
  File "C:\projects\cpython\lib\asyncio\selector_events.py", line 475, in sock_connect
    return await fut
  File "C:\projects\cpython\lib\asyncio\selector_events.py", line 505, in _sock_connect_cb
    raise OSError(err, f'Connect call failed {address}')
ConnectionRefusedError: [Errno 10061] Connect call failed ('127.0.0.1', 6338)

---

Ran 1729 tests in 89.932s

Before that, for Brett
test_popen (test.test_asyncio.test_windows_utils.PopenTests) ... Warning -- asyncio.get_event_loop_policy was modified by test_asyncio
  Before: <asyncio.windows_events._WindowsDefaultEventLoopPolicy object at 0x03DA7850>
  After:  <asyncio.windows_events._WindowsDefaultEventLoopPolicy object at 0x0436F410> 
test test_asyncio crashed -- Traceback (most recent call last):
  File "C:\projects\cpython\lib\test\libregrtest\runtest.py", line 179, in runtest_inner
    test_time = time.time() - start_time
  File "C:\projects\cpython\lib\test\libregrtest\save_env.py", line 305, in __exit__
    current = get()
  File "C:\projects\cpython\lib\test\libregrtest\save_env.py", line 80, in get_asyncio_get_event_loop
    return asyncio.get_event_loop()
  File "C:\projects\cpython\lib\asyncio\events.py", line 645, in get_event_loop
    % threading.current_thread().name)
RuntimeError: There is no current event loop in thread 'MainThread'.
C:\projects\cpython\lib\asyncio\base_events.py:605: ResourceWarning: unclosed event loop <_WindowsSelectorEventLoop running=False closed=False debug=False>
  source=self)
ok

---

Ran 1729 tests in 25.061s
OK (skipped=66)
1 test failed again:
test_asyncio

Before that, Brett got both sets of errors.

Before that, three jobs got the 4 ConnectionRefused errors.

[terryjreedy]

I just got the two broken pipe error on Travis.

[terryjreedy]

The Travis retest (for 3.7 backport) just failed with the same errors. Why can't we disable this tests. It now takes hours to do a merge with two backports.

[vstinner]

Terry: " The Travis retest (for 3.7 backport) just failed with the same errors. Why can't we disable this tests. It now takes hours to do a merge with two backports."

Usually, I prefer to try to understand a bug before disabling, even temporarely, a test. Most of the time, a test failure means a regression. If we disable a test, we reduce the code coverage and more generally reduces the quality of the code.

I would prefer to only disable the test if nobody understand the issue and the issue blocks the workflow longer than a few days. This week, there was a CPython sprint during Pycon US, so yeah, it was annoying.

[asvetlov]

Fixed failed sendfile tests on Windows (at least I hope so).

[vstinner]

Fixed failed sendfile tests on Windows (at least I hope so).

I guess that Andrew means the following fix:

commit e253752
Author: Andrew Svetlov <andrew.svetlov@gmail.com>
Date: Mon May 21 12:03:45 2018 +0300

Fix asyncio flaky tests (bpo-7023)

[terryjreedy]

The patch seems to have worked. The last AppVeyor failure was a day ago, when testing the 3.7 backport of the fix.
https://ci.appveyor.com/project/python/cpython/history

[vstinner]

Yury made 3 changes in the master branch for this change:

• Workaround: await asyncio.sleep(0.5, loop=self.loop)
• Use stdout to synchrone parent and child process
• Revert the second change (stdout sync)

commit bb9474f
Author: Yury Selivanov <yury@magic.io>
Date: Tue May 29 22:00:31 2018 -0400

Revert "A better fix for asyncio test_stdin_broken_pipe (GH-7221)" (GH-7235)

This reverts commit ad74d50517c069359578014bb32e660828d68332.

Turns out it's not a good fix -- Travis has just crashed on this test.

commit ad74d50
Author: Yury Selivanov <yury@magic.io>
Date: Tue May 29 20:57:50 2018 -0400

A better fix for asyncio test_stdin_broken_pipe (bpo-7221)

commit 4fadf0c
Author: Yury Selivanov <yury@magic.io>
Date: Tue May 29 13:40:47 2018 -0400

Attempt to fix test_stdin_broken_pipe on Travis (bpo-7210)

[vstinner]

Python 3.6 got the first change:

commit 6aacc16
Author: Yury Selivanov <yury@magic.io>
Date: Tue May 29 14:57:38 2018 -0400

Fix ci for 3.6 / asyncio / test_stdin_broken_pipe (bpo-7212)

[vstinner]

As expected, the workaround adding a delay of 500 ms is not perfect, the test still fails on the very slow x86 Windows7 3.6 buildbot when tests are run in parallel:

http://buildbot.python.org/all/#/builders/90/builds/383

======================================================================
FAIL: test_stdin_broken_pipe (test.test_asyncio.test_subprocess.SubprocessProactorTests)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "D:\cygwin\home\db3l\buildarea\3.6.bolen-windows7\build\lib\test\test_asyncio\test_subprocess.py", line 221, in test_stdin_broken_pipe
    self.loop.run_until_complete, coro)
AssertionError: (<class 'BrokenPipeError'>, <class 'ConnectionResetError'>) not raised by run_until_complete

But hopefully, test_asyncio passed when re-run sequentially.