test_check_hostname() of test_ftplib started to fail randomly

[vstinner]

BPO	32706
Nosy	@freddrake, @warsaw, @vstinner, @giampaolo, @tiran, @ned-deily
PRs	bpo-32706: Skip test_ftplib.test_check_hostname() #5422

^{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 = 'https://github.com/tiran'
closed_at = <Date 2018-12-18.21:56:34.016>
created_at = <Date 2018-01-29.11:27:36.905>
labels = ['3.7', 'expert-SSL', '3.8', 'type-bug', 'tests']
title = 'test_check_hostname() of test_ftplib started to fail randomly'
updated_at = <Date 2018-12-18.21:56:34.014>
user = 'https://github.com/vstinner'

bugs.python.org fields:

activity = <Date 2018-12-18.21:56:34.014>
actor = 'vstinner'
assignee = 'christian.heimes'
closed = True
closed_date = <Date 2018-12-18.21:56:34.016>
closer = 'vstinner'
components = ['Tests', 'SSL']
creation = <Date 2018-01-29.11:27:36.905>
creator = 'vstinner'
dependencies = []
files = []
hgrepos = []
issue_num = 32706
keywords = ['patch']
message_count = 14.0
messages = ['311096', '311097', '311110', '311127', '311616', '311809', '312895', '313039', '315728', '317530', '317576', '326056', '326247', '332089']
nosy_count = 6.0
nosy_names = ['fdrake', 'barry', 'vstinner', 'giampaolo.rodola', 'christian.heimes', 'ned.deily']
pr_nums = ['5422']
priority = 'critical'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue32706'
versions = ['Python 3.7', 'Python 3.8']

[vstinner]

It may be a regression caused by this recent change:
---
commit 61d478c
Author: Christian Heimes <christian@python.org>
Date: Sat Jan 27 15:51:38 2018 +0100

bpo-31399: Let OpenSSL verify hostname and IP address (bpo-3462)

bpo-31399: Let OpenSSL verify hostname and IP

The ssl module now uses OpenSSL's X509_VERIFY_PARAM_set1_host() and
X509_VERIFY_PARAM_set1_ip() API to verify hostname and IP addresses.

* Remove match_hostname calls
* Check for libssl with set1_host, libssl must provide X509_VERIFY_PARAM_set1_host()
* Add documentation for OpenSSL 1.0.2 requirement
* Don't support OpenSSL special mode with a leading dot, e.g. ".example.org" matches "www.example.org". It's not standard conform.
* Add hostname_checks_common_name

Signed-off-by: Christian Heimes <christian@python.org>

---

Travis CI output, reformatted to make it more readable:

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

test_check_hostname (test.test_ftplib.TestTLS_FTPClass) ...

Exception in thread Thread-83:
Traceback (most recent call last):
  File "/home/travis/build/python/cpython/Lib/asynchat.py", line 251, in initiate_send
    num_sent = self.send(data)
  File "/home/travis/build/python/cpython/Lib/test/test_ftplib.py", line 381, in send
    return super(SSLConnection, self).send(data)
  File "/home/travis/build/python/cpython/Lib/asyncore.py", line 360, in send
    result = self.socket.send(data)
  File "/home/travis/build/python/cpython/Lib/ssl.py", line 963, in send
    return self._sslobj.write(data)
  File "/home/travis/build/python/cpython/Lib/ssl.py", line 670, in write
    return self._sslobj.write(data)
ssl.SSLError: [SSL: SSLV3_ALERT_BAD_CERTIFICATE] sslv3 alert bad certificate (_ssl.c:2206)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/travis/build/python/cpython/Lib/asyncore.py", line 83, in read
    obj.handle_read_event()
  File "/home/travis/build/python/cpython/Lib/test/test_ftplib.py", line 369, in handle_read_event
    super(SSLConnection, self).handle_read_event()
  File "/home/travis/build/python/cpython/Lib/asyncore.py", line 422, in handle_read_event
    self.handle_read()
  File "/home/travis/build/python/cpython/Lib/asynchat.py", line 171, in handle_read
    self.found_terminator()
  File "/home/travis/build/python/cpython/Lib/test/test_ftplib.py", line 116, in found_terminator
    method(arg)
  File "/home/travis/build/python/cpython/Lib/test/test_ftplib.py", line 231, in cmd_list
    self.dtp.push(LIST_DATA)
  File "/home/travis/build/python/cpython/Lib/test/test_ftplib.py", line 73, in push
    super(DummyDTPHandler, self).push(what.encode('ascii'))
  File "/home/travis/build/python/cpython/Lib/asynchat.py", line 202, in push
    self.initiate_send()
  File "/home/travis/build/python/cpython/Lib/asynchat.py", line 253, in initiate_send
    self.handle_error()
  File "/home/travis/build/python/cpython/Lib/test/test_ftplib.py", line 402, in handle_error
    raise Exception
Exception

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/travis/build/python/cpython/Lib/threading.py", line 917, in _bootstrap_inner
    self.run()
  File "/home/travis/build/python/cpython/Lib/test/test_ftplib.py", line 279, in run
    asyncore.loop(timeout=0.1, count=1)
  File "/home/travis/build/python/cpython/Lib/asyncore.py", line 207, in loop
    poll_fun(timeout, map)
  File "/home/travis/build/python/cpython/Lib/asyncore.py", line 150, in poll
    read(obj)
  File "/home/travis/build/python/cpython/Lib/asyncore.py", line 87, in read
    obj.handle_error()
  File "/home/travis/build/python/cpython/Lib/test/test_ftplib.py", line 402, in handle_error
    raise Exception
Exception

ERROR

======================================================================
ERROR: test_check_hostname (test.test_ftplib.TestTLS_FTPClass)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/home/travis/build/python/cpython/Lib/test/test_ftplib.py", line 958, in test_check_hostname
    self.client.quit()
  File "/home/travis/build/python/cpython/Lib/ftplib.py", line 665, in quit
    resp = self.voidcmd('QUIT')
  File "/home/travis/build/python/cpython/Lib/ftplib.py", line 278, in voidcmd
    return self.voidresp()
  File "/home/travis/build/python/cpython/Lib/ftplib.py", line 251, in voidresp
    resp = self.getresp()
  File "/home/travis/build/python/cpython/Lib/ftplib.py", line 236, in getresp
    resp = self.getmultiline()
  File "/home/travis/build/python/cpython/Lib/ftplib.py", line 222, in getmultiline
    line = self.getline()
  File "/home/travis/build/python/cpython/Lib/ftplib.py", line 204, in getline
    line = self.file.readline(self.maxline + 1)
  File "/home/travis/build/python/cpython/Lib/socket.py", line 582, in readinto
    return self._sock.recv_into(b)
socket.timeout: timed out

[vstinner]

I'm able to reproduce the failure on my Fedora 27 using two terminals:

(1) Run the test in a loop:
vstinner@apu$ ./python -m test -v test_ftplib -m test_check_hostname -F

(2) Stress the system, example:
vstinner@apu$ ./python -m test -j0 -r

When the system load becomes higher than 2 (I have 8 logical CPUs), test_check_hostname() fails.

[vstinner]

New changeset 51500f3 by Victor Stinner in branch 'master':
bpo-32706: Skip test_ftplib.test_check_hostname() (bpo-5422)
51500f3

[tiran]

Some tests still use asyncore to test TLS. Yes, that's old asyncore, not asyncio. I suggest that we replace asyncore with a threaded test server from test_ssl.

[tiran]

poplib is also affected, see bpo-32753

[warsaw]

Yep, I'm seeing those same failures in our internal build of 3.7.0b1. I'll just disable the tests for now and nosy on this issue.

[tiran]

Ned, I'm going to rewrite part of the test infrastructure during beta phase. The ssl module now works according to specifications. When the client doesn't recognize a hostname, it aborts the TLS connection with a TLS ALERT message. The old asynchat test system cannot handle TLS connection abort correctly.

It's really just testing. No public APIs will be affected.

[ned-deily]

Let's get the changes into master first and stabilized there and then we can discuss the possibility of a 3.7 backport.