test_ssl: test_pha_required_nocert() emits a ResourceWarning

[vstinner]

BPO	37322
Nosy	@vstinner, @tiran, @ambv, @miss-islington, @matthewhughes934
PRs	bpo-37322: Fix test_ssl.test_pha_required_nocert() ResourceWarning #14662 [3.8] bpo-37322: Fix test_ssl.test_pha_required_nocert() ResourceWarning (GH-14662) #14665 bpo-37322: Fix again test_ssl.test_pha_required_nocert() ResourceWarning #14667 Revert "bpo-37322: Fix test_ssl.test_pha_required_nocert() ResourceWarning (GH-14662)" #14669 bpo-37322: ssl test_pha_required_nocert() ignores expected SSLError #14670 [3.8] bpo-37322: ssl test_pha_required_nocert() ignores expected SSLError (GH-14670) #14673 bpo-37322: Fix ResourceWarning in test_ssl #21393 bpo-37322: Fix ResourceWarning and exception handling in test (GH-25553) #25553 [3.9] bpo-37322: Fix ResourceWarning and exception handling in test (GH-25553) #25572 [3.8] bpo-37322: Fix ResourceWarning and exception handling in test (GH-25553) #25573
Files	naive_proof_of_concept.patch

^{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 2021-09-21.22:24:43.818>
created_at = <Date 2019-06-17.20:35:34.826>
labels = ['3.8', 'tests', '3.9', '3.10', '3.11']
title = 'test_ssl: test_pha_required_nocert() emits a ResourceWarning'
updated_at = <Date 2021-09-21.22:24:43.818>
user = 'https://github.com/vstinner'

bugs.python.org fields:

activity = <Date 2021-09-21.22:24:43.818>
actor = 'vstinner'
assignee = 'none'
closed = True
closed_date = <Date 2021-09-21.22:24:43.818>
closer = 'vstinner'
components = ['Tests']
creation = <Date 2019-06-17.20:35:34.826>
creator = 'vstinner'
dependencies = []
files = ['49294']
hgrepos = []
issue_num = 37322
keywords = ['patch']
message_count = 15.0
messages = ['345903', '347535', '347542', '347547', '347551', '347553', '347555', '347558', '372939', '372940', '391669', '391761', '392690', '392704', '402399']
nosy_count = 5.0
nosy_names = ['vstinner', 'christian.heimes', 'lukasz.langa', 'miss-islington', 'mhughes']
pr_nums = ['14662', '14665', '14667', '14669', '14670', '14673', '21393', '25553', '25572', '25573']
priority = 'high'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = None
url = 'https://bugs.python.org/issue37322'
versions = ['Python 3.8', 'Python 3.9', 'Python 3.10', 'Python 3.11']

[vstinner]

vstinner@apu$ ./python -X tracemalloc=10 -m test --fail-env-changed -v test_ssl -m test_pha_required_nocert
== CPython 3.9.0a0 (heads/master-dirty:00f6493084, Jun 17 2019, 21:50:32) [GCC 9.1.1 20190503 (Red Hat 9.1.1-1)]
== Linux-5.1.6-300.fc30.x86_64-x86_64-with-glibc2.29 little-endian
== cwd: /home/vstinner/prog/python/master/build/test_python_23407
== CPU count: 8
== encodings: locale=UTF-8, FS=utf-8
Run tests sequentially
0:00:00 load avg: 0.58 [1/1] test_ssl
test_ssl: testing with 'OpenSSL 1.1.1c FIPS 28 May 2019' (1, 1, 1, 3, 15)
 under 'Linux-5.1.6-300.fc30.x86_64-x86_64-with-glibc2.29'
 HAS_SNI = True
 OP_ALL = 0x80000054
 OP_NO_TLSv1_1 = 0x10000000
test_pha_required_nocert (test.test_ssl.TestPostHandshakeAuth) ... Exception in thread Thread-2:
Traceback (most recent call last):
 File "/home/vstinner/prog/python/master/Lib/test/test_ssl.py", line 2287, in run
 msg = self.read()
 File "/home/vstinner/prog/python/master/Lib/test/test_ssl.py", line 2264, in read
 return self.sslconn.read()
 File "/home/vstinner/prog/python/master/Lib/ssl.py", line 1090, in read
 return self._sslobj.read(len)
ssl.SSLError: [SSL: PEER_DID_NOT_RETURN_A_CERTIFICATE] peer did not return a certificate (_ssl.c:2540)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
 File "/home/vstinner/prog/python/master/Lib/threading.py", line 938, in _bootstrap_inner
 self.run()
 File "/home/vstinner/prog/python/master/Lib/test/test_ssl.py", line 2373, in run
 raise ssl.SSLError('tlsv13 alert certificate required')
ssl.SSLError: ('tlsv13 alert certificate required',)
/home/vstinner/prog/python/master/Lib/threading.py:938: ResourceWarning: unclosed <ssl.SSLSocket fd=5, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('127.0.0.1', 53571), raddr=('127.0.0.1', 34676)>
 self.run()
Object allocated at (most recent call last):
 File "/home/vstinner/prog/python/master/Lib/threading.py", lineno 896
 self._bootstrap_inner()
 File "/home/vstinner/prog/python/master/Lib/threading.py", lineno 938
 self.run().
 File "/home/vstinner/prog/python/master/Lib/test/test_ssl.py", lineno 2283
 if not self.wrap_conn():
 File "/home/vstinner/prog/python/master/Lib/test/test_ssl.py", lineno 2207
 self.sslconn = self.server.context.wrap_socket(
 File "/home/vstinner/prog/python/master/Lib/ssl.py", lineno 489
 return self.sslsocket_class._create(
 File "/home/vstinner/prog/python/master/Lib/ssl.py", lineno 992
 self = cls.__new__(cls, **kwargs)
ok

---

Ran 1 test in 0.100s

OK

== Tests result: SUCCESS ==

1 test OK.

Total duration: 1 sec 430 ms
Tests result: SUCCESS

The test fails using -Werror.

[vstinner]

I marked bpo-37525 as duplicate of this issue.

[vstinner]

New changeset cf9c41c by Victor Stinner in branch 'master':
bpo-37322: Fix test_ssl.test_pha_required_nocert() ResourceWarning (GH-14662)
cf9c41c

[vstinner]

New changeset cf9c41c by Victor Stinner in branch 'master':
bpo-37322: Fix test_ssl.test_pha_required_nocert() ResourceWarning (GH-14662)

Oh. This test started to fail on Windows with this change. Example:

https://buildbot.python.org/all/#/builders/3/builds/3121

ERROR: test_pha_required_nocert (test.test_ssl.TestPostHandshakeAuth)
----------------------------------------------------------------------

Traceback (most recent call last):
 File "D:\buildarea\3.x.bolen-windows10\build\lib\test\test_ssl.py", line 4344, in test_pha_required_nocert
 s.recv(1024)
 File "D:\buildarea\3.x.bolen-windows10\build\lib\ssl.py", line 1226, in recv
 return self.read(buflen)
 File "D:\buildarea\3.x.bolen-windows10\build\lib\ssl.py", line 1101, in read
 return self._sslobj.read(len)
ConnectionResetError: [WinError 10054] An existing connection was forcibly closed by the remote host

I proposed PR 14669 to revert it.

[vstinner]

New changeset 61b1bc5 by Victor Stinner in branch 'master':
Revert "bpo-37322: Fix test_ssl.test_pha_required_nocert() ResourceWarning (GH-14662)" (GH-14669)
61b1bc5

[vstinner]

The test also logs an "Exception in thread Thread-2:" error:
---

vstinner@apu$ ./python -m test test_ssl -m test_pha_required_nocert -v
== CPython 3.9.0a0 (heads/master:110a47c4f4, Jul 8 2019, 23:52:00) [GCC 9.1.1 20190503 (Red Hat 9.1.1-1)]
== Linux-5.1.15-300.fc30.x86_64-x86_64-with-glibc2.29 little-endian
== cwd: /home/vstinner/python/master/build/test_python_21491
== CPU count: 8
== encodings: locale=UTF-8, FS=utf-8
Run tests sequentially
0:00:00 load avg: 1.77 [1/1] test_ssl
test_ssl: testing with 'OpenSSL 1.1.1c FIPS 28 May 2019' (1, 1, 1, 3, 15)
 under 'Linux-5.1.15-300.fc30.x86_64-x86_64-with-glibc2.29'
 HAS_SNI = True
 OP_ALL = 0x80000054
 OP_NO_TLSv1_1 = 0x10000000
test_pha_required_nocert (test.test_ssl.TestPostHandshakeAuth) ... Exception in thread Thread-2:
Traceback (most recent call last):
 File "/home/vstinner/python/master/Lib/test/test_ssl.py", line 2299, in run
 msg = self.read()
 File "/home/vstinner/python/master/Lib/test/test_ssl.py", line 2276, in read
 return self.sslconn.read()
 File "/home/vstinner/python/master/Lib/ssl.py", line 1101, in read
 return self._sslobj.read(len)
ssl.SSLError: [SSL: PEER_DID_NOT_RETURN_A_CERTIFICATE] peer did not return a certificate (_ssl.c:2560)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
 File "/home/vstinner/python/master/Lib/threading.py", line 938, in _bootstrap_inner
 self.run()
 File "/home/vstinner/python/master/Lib/test/test_ssl.py", line 2385, in run
 raise ssl.SSLError('tlsv13 alert certificate required')
ssl.SSLError: ('tlsv13 alert certificate required',)
/home/vstinner/python/master/Lib/threading.py:938: ResourceWarning: unclosed <ssl.SSLSocket fd=5, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('127.0.0.1', 37995), raddr=('127.0.0.1', 52176)>
 self.run()
ResourceWarning: Enable tracemalloc to get the object allocation traceback
ok

---

Ran 1 test in 0.028s

OK

== Tests result: SUCCESS ==

1 test OK.

Total duration: 179 ms
Tests result: SUCCESS
---

Attached PR 14670 makes this log quiet.

[vstinner]

New changeset 73ea546 by Victor Stinner in branch 'master':
bpo-37322: ssl test_pha_required_nocert() ignores expected SSLError (GH-14670)
73ea546

[miss-islington]

New changeset 4c403b8 by Miss Islington (bot) in branch '3.8':
bpo-37322: ssl test_pha_required_nocert() ignores expected SSLError (GH-14670)
4c403b8

[matthewhughes934]

I noticed this test was still emitting a "ResourceWarning":
----------------------------------------------------------------------

$ ./python -m test test_ssl -m TestPostHandshakeAuth 
0:00:00 load avg: 0.74 Run tests sequentially
0:00:00 load avg: 0.74 [1/1] test_ssl
/home/mjh/src/cpython/Lib/test/support/threading_helper.py:209: ResourceWarning: unclosed <ssl.SSLSocket fd=5, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('127.0.0.1', 33451), raddr=('127.0.0.1', 34038)>
 del self.thread
ResourceWarning: Enable tracemalloc to get the object allocation traceback

== Tests result: SUCCESS ==

1 test OK.

Total duration: 1.1 sec
Tests result: SUCCESS
----------------------------------------------------------------------
and thought I would try silencing it by ensuring the SSL connection handled by the separate thread was closed before exiting. My attempt involved checking the thread's exception and acting accordingly, but I ran into a race condition which (solely as a proof of concept) I resolved by adding a sleep() call (see patch).

While I continue to search for a proper resolution I was wondering what approach someone with more insight might suggest.

[matthewhughes934]

Whoops, I realise the patch I shared contained a combination of two (independent) approaches I tried:

1. Add sleep and perform cleanup
2. Naively patch catch_threading_exception to accept a cleanup routine to be run upon exiting but before removing the thread.

[tiran]

I wasn't aware of this bpo and created bpo-43885 a couple of days ago.

tl;dr I do not understand test changes in fb7e750 at all. I think that these changes are broken, too. ThreadedEchoServer and ConnectionHandler must not raise unhandled exceptions. An unhandled exception can break tests and sometimes causes threaded tests to hang indefinitely.