classification
Title: test_check_hostname() of test_ftplib started to fail randomly
Type: behavior Stage: resolved
Components: SSL, Tests Versions: Python 3.8, Python 3.7
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: christian.heimes Nosy List: barry, christian.heimes, fdrake, giampaolo.rodola, ned.deily, vstinner
Priority: critical Keywords: patch

Created on 2018-01-29 11:27 by vstinner, last changed 2018-12-18 21:56 by vstinner. This issue is now closed.

Pull Requests
URL Status Linked Edit
PR 5422 merged vstinner, 2018-01-29 11:41
Messages (14)
msg311096 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-01-29 11:27
It may be a regression caused by this recent change:
---
commit 61d478c71c5341cdc54e6bfb4ace4252852fd972
Author: Christian Heimes <christian@python.org>
Date:   Sat Jan 27 15:51:38 2018 +0100

    bpo-31399: Let OpenSSL verify hostname and IP address (#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
msg311097 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-01-29 11:30
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.
msg311110 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-01-29 12:21
New changeset 51500f37453bbcbc5f1dbc3c38d079c3c1efe5de by Victor Stinner in branch 'master':
bpo-32706: Skip test_ftplib.test_check_hostname() (#5422)
https://github.com/python/cpython/commit/51500f37453bbcbc5f1dbc3c38d079c3c1efe5de
msg311127 - (view) Author: Christian Heimes (christian.heimes) * (Python committer) Date: 2018-01-29 13:20
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.
msg311616 - (view) Author: Christian Heimes (christian.heimes) * (Python committer) Date: 2018-02-04 19:38
poplib is also affected, see #32753
msg311809 - (view) Author: Barry A. Warsaw (barry) * (Python committer) Date: 2018-02-07 22:38
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.
msg312895 - (view) Author: Christian Heimes (christian.heimes) * (Python committer) Date: 2018-02-26 08:44
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.
msg313039 - (view) Author: Ned Deily (ned.deily) * (Python committer) Date: 2018-02-27 23:46
Let's get the changes into master first and stabilized there and then we can discuss the possibility of a 3.7 backport.
msg315728 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-04-25 13:25
Christian Heimes: "Ned, I'm going to rewrite part of the test infrastructure during beta phase. (...)"

Any progress on rewriting these tests?
msg317530 - (view) Author: Ned Deily (ned.deily) * (Python committer) Date: 2018-05-24 05:54
Since this is just an intermittent test failure and we have lived with it this long, I think it can wait for 3.7.1 at this point.  Downgrading to "critical".
msg317576 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-05-24 14:23
Oh. I forgot about this change. The test is still skipped :-(
msg326056 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-09-21 23:02
Christian: It seems like the test now pass on my Fedora 27. Is it time to enable the test again?
msg326247 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-09-24 15:17
> Christian: It seems like the test now pass on my Fedora 27. Is it time to enable the test again?

Ignore my comment. I forgot that it's a race condition and I'm still able to get the failure using msg311097 scenario.
msg332089 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-12-18 21:56
Ok, let's keep this permanent temporary fix (test skipped until someone finds a solution). I close the issue.
History
Date User Action Args
2018-12-18 21:56:34vstinnersetstatus: open -> closed
resolution: fixed
messages: + msg332089

stage: needs patch -> resolved
2018-09-24 15:17:16vstinnersetmessages: + msg326247
2018-09-21 23:02:26vstinnersetmessages: + msg326056
2018-05-24 14:23:27vstinnersetmessages: + msg317576
2018-05-24 05:54:29ned.deilysetpriority: deferred blocker -> critical

messages: + msg317530
2018-04-25 13:25:22vstinnersetmessages: + msg315728
2018-04-09 19:02:37fdrakesetnosy: + fdrake
2018-02-27 23:46:55ned.deilysetmessages: + msg313039
2018-02-26 08:44:37christian.heimessetpriority: high -> deferred blocker
nosy: + ned.deily
messages: + msg312895

2018-02-07 22:38:42barrysetnosy: + barry
messages: + msg311809
2018-02-04 19:40:19christian.heimeslinkissue32753 superseder
2018-02-04 19:38:53christian.heimessetpriority: normal -> high
versions: + Python 3.8
messages: + msg311616

type: behavior
stage: patch review -> needs patch
2018-01-29 13:20:00christian.heimessetnosy: + giampaolo.rodola
messages: + msg311127
2018-01-29 12:21:39vstinnersetmessages: + msg311110
2018-01-29 11:41:45vstinnersetkeywords: + patch
stage: patch review
pull_requests: + pull_request5257
2018-01-29 11:30:55vstinnersetmessages: + msg311097
2018-01-29 11:27:36vstinnercreate