classification
Title: test_asyncio test_start_tls_server_1 fails in AMD64 FreeBSD CURRENT buildbots
Type: behavior Stage: resolved
Components: asyncio, Tests Versions: Python 3.8, Python 3.7, Python 3.6
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: asvetlov, christian.heimes, miss-islington, ned.deily, op368, pablogsal, terry.reedy, vstinner, yselivanov
Priority: normal Keywords: patch

Created on 2018-10-20 14:06 by pablogsal, last changed 2019-10-14 21:07 by vstinner. This issue is now closed.

Pull Requests
URL Status Linked Edit
PR 10011 merged pablogsal, 2018-10-20 17:00
PR 10496 merged miss-islington, 2018-11-13 01:06
PR 14148 merged vstinner, 2019-06-17 09:06
PR 14150 merged miss-islington, 2019-06-17 09:48
PR 14151 merged miss-islington, 2019-06-17 09:48
PR 14188 merged ned.deily, 2019-06-18 08:16
PR 14191 merged miss-islington, 2019-06-18 08:37
PR 14192 merged miss-islington, 2019-06-18 08:37
Messages (24)
msg328138 - (view) Author: Pablo Galindo Salgado (pablogsal) * (Python committer) Date: 2018-10-20 14:06
https://buildbot.python.org/all/#/builders/168/builds/91
https://buildbot.python.org/all/#/builders/172/builds/41
https://buildbot.python.org/all/#/builders/173/builds/51

CURRENT-amd64% ./python -m test test_asyncio -m test_start_tls_server_1
Run tests sequentially
0:00:00 load avg: 3.36 [1/1] test_asyncio

Stderr:
/usr/home/pablo/cpython/Lib/test/test_asyncio/test_sslproto.py:497: DeprecationWarning: The loop argument is deprecated and scheduled for removal in Python 3.10.
  await asyncio.wait_for(
/usr/home/pablo/cpython/Lib/asyncio/sslproto.py:321: ResourceWarning: unclosed transport <asyncio.sslproto._SSLProtocolTransport object at 0x802db68f0>
  warnings.warn(f"unclosed transport {self!r}", ResourceWarning,
Unhandled error in exception handler
context: {'message': 'Future exception was never retrieved', 'exception': ConnectionResetError(54, 'Connection reset by peer'), 'future': <Future finished exception=ConnectionResetError(54, 'Connection reset by peer')>}
Traceback (most recent call last):
  File "/usr/home/pablo/cpython/Lib/test/libregrtest/runtest.py", line 179, in runtest_inner
    test_runner()
  File "/usr/home/pablo/cpython/Lib/test/libregrtest/runtest.py", line 175, in test_runner
    support.run_unittest(tests)
  File "/usr/home/pablo/cpython/Lib/test/support/__init__.py", line 2001, in run_unittest
    _run_suite(suite)
  File "/usr/home/pablo/cpython/Lib/test/support/__init__.py", line 1920, in _run_suite
    raise TestFailed(err)
test.support.TestFailed: Traceback (most recent call last):
  File "/usr/home/pablo/cpython/Lib/test/test_asyncio/test_sslproto.py", line 504, in test_start_tls_server_1
    self.loop.run_until_complete(run_main())
  File "/usr/home/pablo/cpython/Lib/asyncio/base_events.py", line 582, in run_until_complete
    return future.result()
  File "/usr/home/pablo/cpython/Lib/test/test_asyncio/test_sslproto.py", line 497, in run_main
    await asyncio.wait_for(
  File "/usr/home/pablo/cpython/Lib/asyncio/tasks.py", line 457, in wait_for
    raise exceptions.TimeoutError()
asyncio.exceptions.TimeoutError

Stderr:
/usr/home/pablo/cpython/Lib/test/test_asyncio/test_sslproto.py:497: DeprecationWarning: The loop argument is deprecated and scheduled for removal in Python 3.10.
  await asyncio.wait_for(
/usr/home/pablo/cpython/Lib/asyncio/sslproto.py:321: ResourceWarning: unclosed transport <asyncio.sslproto._SSLProtocolTransport object at 0x802db68f0>
  warnings.warn(f"unclosed transport {self!r}", ResourceWarning,


During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/home/pablo/cpython/Lib/asyncio/base_events.py", line 1647, in call_exception_handler
    self._exception_handler(self, context)
  File "/usr/home/pablo/cpython/Lib/test/test_asyncio/functional.py", line 22, in loop_exception_handler
    self.loop.default_exception_handler(context)
AttributeError: 'NoneType' object has no attribute 'default_exception_handler'
/usr/home/pablo/cpython/Lib/test/support/__init__.py:1550: ResourceWarning: unclosed <socket.socket fd=8, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('127.0.0.1', 25746)>
  gc.collect()
test test_asyncio failed -- Traceback (most recent call last):
  File "/usr/home/pablo/cpython/Lib/test/test_asyncio/test_sslproto.py", line 504, in test_start_tls_server_1
    self.loop.run_until_complete(run_main())
  File "/usr/home/pablo/cpython/Lib/asyncio/base_events.py", line 582, in run_until_complete
    return future.result()
  File "/usr/home/pablo/cpython/Lib/test/test_asyncio/test_sslproto.py", line 497, in run_main
    await asyncio.wait_for(
  File "/usr/home/pablo/cpython/Lib/asyncio/tasks.py", line 457, in wait_for
    raise exceptions.TimeoutError()
asyncio.exceptions.TimeoutError

Stderr:
/usr/home/pablo/cpython/Lib/test/test_asyncio/test_sslproto.py:497: DeprecationWarning: The loop argument is deprecated and scheduled for removal in Python 3.10.
  await asyncio.wait_for(
/usr/home/pablo/cpython/Lib/asyncio/sslproto.py:321: ResourceWarning: unclosed transport <asyncio.sslproto._SSLProtocolTransport object at 0x802db68f0>
  warnings.warn(f"unclosed transport {self!r}", ResourceWarning,

test_asyncio failed in 1 min 749 ms

== Tests result: FAILURE ==

1 test failed:
    test_asyncio

Total duration: 1 min 800 ms
Tests result: FAILURE
msg328143 - (view) Author: Pablo Galindo Salgado (pablogsal) * (Python committer) Date: 2018-10-20 15:07
Bisecting points to commit dbf102271fcc316f353c7e0a283811b661d128f2 as the dirst bad commit:

dbf102271fcc316f353c7e0a283811b661d128f2 is the first bad commit
commit dbf102271fcc316f353c7e0a283811b661d128f2
Author: Yury Selivanov <yury@magic.io>
Date:   Mon May 28 14:31:28 2018 -0400

    bpo-33654: Support BufferedProtocol in set_protocol() and start_tls() (GH-7130)

    In this commit:

    * Support BufferedProtocol in set_protocol() and start_tls()
    * Fix proactor to cancel readers reliably
    * Update tests to be compatible with OpenSSL 1.1.1
    * Clarify BufferedProtocol docs
    * Bump TLS tests timeouts to 60 seconds; eliminate possible race from start_serving
    * Rewrite test_start_tls_server_1
msg328145 - (view) Author: Pablo Galindo Salgado (pablogsal) * (Python committer) Date: 2018-10-20 15:17
I think something is going on with the buildbot itself or the test has some race condition because that commit has been built before multiple times with no error. I am investigating in the buildbot itself.
msg328148 - (view) Author: Pablo Galindo Salgado (pablogsal) * (Python committer) Date: 2018-10-20 15:24
Building and testing the parent of dbf102271fcc316f353c7e0a283811b661d128f2 always succeeds.
msg328157 - (view) Author: Pablo Galindo Salgado (pablogsal) * (Python committer) Date: 2018-10-20 16:20
It seems that the problem is that the ServerProto of test_start_tls_server_1 never receives a call to eof_received(). Weirdly enough it seems that if the HELLO_MSG is large enough (1024 * 1024), then the test always succeed. If we deactivate tls in the test, the test succeeds with any message lenght.
msg328163 - (view) Author: Pablo Galindo Salgado (pablogsal) * (Python committer) Date: 2018-10-20 16:57
Re-adding client_context.options |= ssl.OP_NO_TLSv1_3 makes the test pass again.
msg328833 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-10-29 14:31
Any progress on this issue? It's still failing:
https://buildbot.python.org/all/#/builders/168/builds/143
msg328835 - (view) Author: Pablo Galindo Salgado (pablogsal) * (Python committer) Date: 2018-10-29 14:39
Someone needs to review PR10011
msg328837 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-10-29 15:28
note: Roundup sent me comments as email notifications in the backward order, that's funny to see Pablo's answer before my question :-)
msg328839 - (view) Author: Pablo Galindo Salgado (pablogsal) * (Python committer) Date: 2018-10-29 15:47
> note: Roundup sent me comments as email notifications in the backward order, that's funny to see Pablo's answer before my question :-)

Maybe I just answered faster than the speed of light ;)
msg328871 - (view) Author: Pablo Galindo Salgado (pablogsal) * (Python committer) Date: 2018-10-29 20:47
New changeset f6a47f3e316cede2a07a1f74a509f6d80ab8fef0 by Pablo Galindo in branch 'master':
bpo-35031: Fix test_start_tls_server_1 on FreeBSD buildbots (GH-10011)
https://github.com/python/cpython/commit/f6a47f3e316cede2a07a1f74a509f6d80ab8fef0
msg329785 - (view) Author: miss-islington (miss-islington) Date: 2018-11-13 01:24
New changeset 3f9fe53c98978955fea4e36456c784694e6458a8 by Miss Islington (bot) in branch '3.7':
bpo-35031: Fix test_start_tls_server_1 on FreeBSD buildbots (GH-10011)
https://github.com/python/cpython/commit/3f9fe53c98978955fea4e36456c784694e6458a8
msg332756 - (view) Author: Terry J. Reedy (terry.reedy) * (Python committer) Date: 2018-12-30 19:30
should this be closed?
msg332764 - (view) Author: Pablo Galindo Salgado (pablogsal) * (Python committer) Date: 2018-12-30 21:48
I think is missing a manual backport to 3.6, but now that we are in security fixes only I am not sure of what to do.
msg332803 - (view) Author: Ned Deily (ned.deily) * (Python committer) Date: 2018-12-31 05:22
If the failure has regularly shown up on 3.6 FreeBSD buildbots in the past, I would accept a backport of the test change to 3.6.
msg337234 - (view) Author: Open Close (op368) * Date: 2019-03-05 18:02
Am I wrong with something?
But test_start_tls_server_1 in newly made cpython fails on my plain intel linux personal PC.

If I comment out the FreeBSD conditional (to apply ssl.OP_NO_TLSv1_3), 
the test passes.

If I change HELLO_MSG to 1*1024*1024 (msg328157),
the test passes.

I reported the details in https://bugs.python.org/issue35998#msg336986 and the following.
msg345831 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-06-17 09:12
Commit f6a47f3e316cede2a07a1f74a509f6d80ab8fef0 introduced a workaround on Windows and FreeBSD. It was removed by commit f0749da9a535375f05a2015e8960e8ae54877349 in bpo-35998... but then Windows restarted to fail:
https://bugs.python.org/issue35998#msg345644

So I wrote PR 14148 to reintroduce the workaround until someone finds time to have a look.

Note: this issue is open since October 2018.
msg345832 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-06-17 09:47
New changeset c034b7824f5a7c50f2946ab3931633200e31d903 by Victor Stinner in branch 'master':
bpo-35031, test_asycio: disable TLS 1.3 in test_start_tls_server_1() (GH-14148)
https://github.com/python/cpython/commit/c034b7824f5a7c50f2946ab3931633200e31d903
msg345837 - (view) Author: miss-islington (miss-islington) Date: 2019-06-17 10:06
New changeset a5ddbfbf50715e3d4b90ad367ed6827c6cbcc52f by Miss Islington (bot) in branch '3.8':
bpo-35031, test_asycio: disable TLS 1.3 in test_start_tls_server_1() (GH-14148)
https://github.com/python/cpython/commit/a5ddbfbf50715e3d4b90ad367ed6827c6cbcc52f
msg345839 - (view) Author: miss-islington (miss-islington) Date: 2019-06-17 10:10
New changeset 0040903bbae043225499babae23649d896ea2eec by Miss Islington (bot) in branch '3.7':
bpo-35031, test_asycio: disable TLS 1.3 in test_start_tls_server_1() (GH-14148)
https://github.com/python/cpython/commit/0040903bbae043225499babae23649d896ea2eec
msg345961 - (view) Author: Ned Deily (ned.deily) * (Python committer) Date: 2019-06-18 08:37
New changeset a514f782b822bd7bca7c8d78be7bd53bc25c1908 by Ned Deily in branch 'master':
bpo-35031: also disable TLS 1.3 for test_start_tls_server_1 on macOS (GH-14188)
https://github.com/python/cpython/commit/a514f782b822bd7bca7c8d78be7bd53bc25c1908
msg345967 - (view) Author: miss-islington (miss-islington) Date: 2019-06-18 08:56
New changeset f49c85d0cb098ba75191a9e272d149ed6466dfb7 by Miss Islington (bot) in branch '3.8':
bpo-35031: also disable TLS 1.3 for test_start_tls_server_1 on macOS (GH-14188)
https://github.com/python/cpython/commit/f49c85d0cb098ba75191a9e272d149ed6466dfb7
msg345973 - (view) Author: Ned Deily (ned.deily) * (Python committer) Date: 2019-06-18 09:45
New changeset c101d1a88a8e0b0cec479307b4e0ae6866958a49 by Ned Deily (Miss Islington (bot)) in branch '3.7':
bpo-35031: also disable TLS 1.3 for test_start_tls_server_1 on macOS (GH-14188) (GH-14192)
https://github.com/python/cpython/commit/c101d1a88a8e0b0cec479307b4e0ae6866958a49
msg354654 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-10-14 21:07
It seems like the issue has been fixed.

See also bpo-35998 for a similar issue on other platforms.
History
Date User Action Args
2019-10-14 21:07:17vstinnersetstatus: open -> closed
resolution: fixed
messages: + msg354654

stage: patch review -> resolved
2019-06-18 09:45:14ned.deilysetmessages: + msg345973
2019-06-18 08:56:57miss-islingtonsetmessages: + msg345967
2019-06-18 08:37:39ned.deilysetmessages: + msg345961
2019-06-18 08:37:34miss-islingtonsetpull_requests: + pull_request14029
2019-06-18 08:37:26miss-islingtonsetpull_requests: + pull_request14028
2019-06-18 08:16:55ned.deilysetpull_requests: + pull_request14025
2019-06-17 10:10:52miss-islingtonsetmessages: + msg345839
2019-06-17 10:06:56miss-islingtonsetmessages: + msg345837
2019-06-17 09:48:24miss-islingtonsetpull_requests: + pull_request13993
2019-06-17 09:48:16miss-islingtonsetpull_requests: + pull_request13991
2019-06-17 09:47:55vstinnersetmessages: + msg345832
2019-06-17 09:12:06vstinnersetmessages: + msg345831
2019-06-17 09:06:30vstinnersetpull_requests: + pull_request13989
2019-03-05 18:02:46op368setmessages: + msg337234
2019-03-05 17:35:31op368setnosy: + op368
2018-12-31 05:22:58ned.deilysetnosy: + ned.deily
messages: + msg332803
2018-12-30 21:48:11pablogsalsetmessages: + msg332764
2018-12-30 19:30:06terry.reedysetnosy: + terry.reedy
messages: + msg332756
2018-11-13 01:24:44miss-islingtonsetnosy: + miss-islington
messages: + msg329785
2018-11-13 01:06:28miss-islingtonsetpull_requests: + pull_request9757
2018-10-29 20:47:46pablogsalsetmessages: + msg328871
2018-10-29 15:47:02pablogsalsetmessages: + msg328839
2018-10-29 15:28:51vstinnersetmessages: + msg328837
2018-10-29 14:39:31pablogsalsetmessages: + msg328835
2018-10-29 14:31:44vstinnersetnosy: + vstinner
messages: + msg328833
2018-10-25 23:47:37vstinnersetnosy: + christian.heimes
2018-10-20 17:00:42pablogsalsetkeywords: + patch
stage: patch review
pull_requests: + pull_request9351
2018-10-20 16:57:05pablogsalsetmessages: + msg328163
2018-10-20 16:20:48pablogsalsetmessages: + msg328157
2018-10-20 15:24:30pablogsalsetmessages: + msg328148
2018-10-20 15:17:55pablogsalsetmessages: + msg328145
2018-10-20 15:07:32pablogsalsetmessages: + msg328143
2018-10-20 14:48:32pablogsalsettitle: test_asyncio test_start_tls_server_1 fails in -> test_asyncio test_start_tls_server_1 fails in AMD64 FreeBSD CURRENT buildbots
2018-10-20 14:06:47pablogsalcreate