classification
Title: test_asyncio: test_subprocess test_stdin_broken_pipe() failure on Travis CI
Type: Stage:
Components: asyncio, Tests Versions: Python 3.8, Python 3.7, Python 3.6
process
Status: open Resolution:
Dependencies: Superseder:
Assigned To: Nosy List: asvetlov, christian.heimes, eitan.adler, terry.reedy, vstinner, yselivanov
Priority: normal Keywords:

Created on 2018-05-16 06:29 by vstinner, last changed 2018-06-08 06:59 by vstinner.

Messages (11)
msg316770 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-05-16 06:29
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.
msg316995 - (view) Author: Terry J. Reedy (terry.reedy) * (Python committer) Date: 2018-05-18 00:57
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.
msg316996 - (view) Author: Terry J. Reedy (terry.reedy) * (Python committer) Date: 2018-05-18 01:04
I just got the two broken pipe error on Travis.
msg316998 - (view) Author: Terry J. Reedy (terry.reedy) * (Python committer) Date: 2018-05-18 01:24
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.
msg317081 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-05-19 00:42
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.
msg317242 - (view) Author: Andrew Svetlov (asvetlov) * (Python committer) Date: 2018-05-21 17:25
Fixed failed sendfile tests on Windows (at least I hope so).
msg317272 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-05-22 12:26
> Fixed failed sendfile tests on Windows (at least I hope so).

I guess that Andrew means the following fix:

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

    Fix asyncio flaky tests (#7023)
msg317320 - (view) Author: Terry J. Reedy (terry.reedy) * (Python committer) Date: 2018-05-22 18:32
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
msg319027 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-06-08 06:54
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 bb9474f1fb2fc7c7ed9f826b78262d6a12b5f9e8
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 ad74d50517c069359578014bb32e660828d68332
Author: Yury Selivanov <yury@magic.io>
Date:   Tue May 29 20:57:50 2018 -0400

    A better fix for asyncio test_stdin_broken_pipe (#7221)

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

    Attempt to fix test_stdin_broken_pipe on Travis (#7210)
msg319028 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-06-08 06:57
Python 3.6 got the first change:

commit 6aacc160a880de3b82c51193a4594b87fb7ace5f
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 (#7212)
msg319029 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-06-08 06:59
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.
History
Date User Action Args
2018-06-08 06:59:54vstinnersetmessages: + msg319029
2018-06-08 06:57:39vstinnersetmessages: + msg319028
2018-06-08 06:54:58vstinnersetmessages: + msg319027
versions: + Python 3.6, Python 3.7
2018-05-22 18:32:49terry.reedysetmessages: + msg317320
2018-05-22 12:26:35vstinnersetmessages: + msg317272
2018-05-21 17:25:09asvetlovsetmessages: + msg317242
2018-05-19 09:33:03christian.heimessetnosy: + christian.heimes
2018-05-19 00:42:04vstinnersetmessages: + msg317081
2018-05-18 01:24:52terry.reedysetmessages: + msg316998
2018-05-18 01:04:37terry.reedysetmessages: + msg316996
2018-05-18 00:57:14terry.reedysetnosy: + terry.reedy
messages: + msg316995
2018-05-16 06:32:28eitan.adlersetnosy: + eitan.adler
2018-05-16 06:29:52vstinnercreate