Test test_101_ssl_reneg.py failing on Debian Buster / Ubuntu Bionic

[elukey]

Hi!

I can't make the test_101_ssl_reneg.py test to succeed on Debian Buster / Ubuntu Bionic. I tried to debug a bit the problem, and I was a bit puzzled by the second failure, that ends up in a HTTP 404 rather than a HTTP 403.

I haven't been able to test this on a system with TLS 1.2 only. I may be related to TLS 1.3 and renegotiation but I didn't find a clear proof in the logs.

The httpd code that I am testing is the last version of 2.4.x (including mod_h2). I am probably missing something obvious, in case apologies in advance for the noise :)

$ pytest-3 test_101_ssl_reneg.py
========================================================================= test session starts =========================================================================
platform linux -- Python 3.6.8, pytest-3.3.2, py-1.5.2, pluggy-0.6.0
rootdir: /tmp/mod_h2/test/e2e, inifile:
collected 8 items

test_101_ssl_reneg.py .F.....F                                                                                                                                  [100%]

============================================================================== FAILURES ===============================================================================
________________________________________________________________________ TestStore.test_101_02 ________________________________________________________________________

self = <test_101_ssl_reneg.TestStore object at 0x7fc2e34b8940>

    def test_101_02(self):
        url = TestEnv.mkurl("https", "ssl", "/renegotiate/cipher/")
        r = TestEnv.curl_get( url, options=[ "-vvv" ] )
>       assert 0 != r["rv"]
E       assert 0 != 0

test_101_ssl_reneg.py:79: AssertionError
------------------------------------------------------------------------ Captured stdout setup ------------------------------------------------------------------------
setup_method: test_101_02
------------------------------------------------------------------------ Captured stdout call -------------------------------------------------------------------------
execute: /usr/bin/curl -ks -D /tmp/mod_h2/test/gen/curl.headers --resolve ssl.tests.httpd.apache.org:42002:127.0.0.1 --connect-timeout 5 -vvv https://ssl.tests.httpd.apache.org:42002/renegotiate/cipher/
exit code 0, stderr:
* Added ssl.tests.httpd.apache.org:42002:127.0.0.1 to DNS cache
* Hostname ssl.tests.httpd.apache.org was found in DNS cache
*   Trying 127.0.0.1...
* TCP_NODELAY set
* Connected to ssl.tests.httpd.apache.org (127.0.0.1) port 42002 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* successfully set certificate verify locations:
*   CAfile: /etc/ssl/certs/ca-certificates.crt
  CApath: /etc/ssl/certs
} [5 bytes data]
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
} [512 bytes data]
* TLSv1.3 (IN), TLS handshake, Server hello (2):
{ [122 bytes data]
* TLSv1.3 (IN), TLS Unknown, Certificate Status (22):
{ [1 bytes data]
* TLSv1.3 (IN), TLS handshake, Unknown (8):
{ [19 bytes data]
* TLSv1.3 (IN), TLS Unknown, Certificate Status (22):
{ [1 bytes data]
* TLSv1.3 (IN), TLS handshake, Certificate (11):
{ [1184 bytes data]
* TLSv1.3 (IN), TLS Unknown, Certificate Status (22):
{ [1 bytes data]
* TLSv1.3 (IN), TLS handshake, CERT verify (15):
{ [264 bytes data]
* TLSv1.3 (IN), TLS Unknown, Certificate Status (22):
{ [1 bytes data]
* TLSv1.3 (IN), TLS handshake, Finished (20):
{ [52 bytes data]
* TLSv1.3 (OUT), TLS change cipher, Client hello (1):
} [1 bytes data]
* TLSv1.3 (OUT), TLS Unknown, Certificate Status (22):
} [1 bytes data]
* TLSv1.3 (OUT), TLS handshake, Finished (20):
} [52 bytes data]
* SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384
* ALPN, server accepted to use h2
* Server certificate:
*  subject: C=DE; ST=NRW; L=Muenster; postalCode=48155; street=Hafenweg 16; O=greenbytes GmbH; CN=a test certficate; emailAddress=webmaster@test.greenbytes.de
*  start date: Sep 29 17:25:33 2019 GMT
*  expire date: Sep 28 17:25:33 2022 GMT
*  issuer: C=DE; ST=NRW; L=Muenster; postalCode=48155; street=Hafenweg 16; O=greenbytes GmbH; CN=a test certficate; emailAddress=webmaster@test.greenbytes.de
*  SSL certificate verify result: unable to get local issuer certificate (20), continuing anyway.
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
} [5 bytes data]
* TLSv1.3 (OUT), TLS Unknown, Unknown (23):
} [1 bytes data]
* TLSv1.3 (OUT), TLS Unknown, Unknown (23):
} [1 bytes data]
* TLSv1.3 (OUT), TLS Unknown, Unknown (23):
} [1 bytes data]
* Using Stream ID: 1 (easy handle 0x55e2befa4580)
} [5 bytes data]
* TLSv1.3 (OUT), TLS Unknown, Unknown (23):
} [1 bytes data]
> GET /renegotiate/cipher/ HTTP/2
> Host: ssl.tests.httpd.apache.org:42002
> User-Agent: curl/7.58.0
> Accept: */*
>
{ [5 bytes data]
* TLSv1.3 (IN), TLS Unknown, Certificate Status (22):
{ [1 bytes data]
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [297 bytes data]
* TLSv1.3 (IN), TLS Unknown, Certificate Status (22):
{ [1 bytes data]
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [297 bytes data]
* TLSv1.3 (IN), TLS Unknown, Unknown (23):
{ [1 bytes data]
* Connection state changed (MAX_CONCURRENT_STREAMS updated)!
} [5 bytes data]
* TLSv1.3 (OUT), TLS Unknown, Unknown (23):
} [1 bytes data]
* TLSv1.3 (IN), TLS Unknown, Unknown (23):
{ [1 bytes data]
* TLSv1.3 (IN), TLS Unknown, Unknown (23):
{ [1 bytes data]
< HTTP/2 403
< date: Sun, 29 Sep 2019 18:52:21 GMT
< server: Apache/2.4.42-dev (Unix) OpenSSL/1.1.1
< content-length: 199
< content-type: text/html; charset=iso-8859-1
<
{ [199 bytes data]
* Connection #0 to host ssl.tests.httpd.apache.org left intact

stdout:
<!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 2.0//EN">
<html><head>
<title>403 Forbidden</title>
</head><body>
<h1>Forbidden</h1>
<p>You don't have permission to access this resource.</p>
</body></html>

reading 1st response line: HTTP/2 403

reading header line: date: Sun, 29 Sep 2019 18:52:21 GMT

reading header line: server: Apache/2.4.42-dev (Unix) OpenSSL/1.1.1

reading header line: content-length: 199

reading header line: content-type: text/html; charset=iso-8859-1

---------------------------------------------------------------------- Captured stdout teardown -----------------------------------------------------------------------
teardown_method: test_101_02
________________________________________________________________________ TestStore.test_101_11 ________________________________________________________________________

self = <test_101_ssl_reneg.TestStore object at 0x7fc2e348c630>

    def test_101_11(self):
        url = TestEnv.mkurl("https", "ssl", "/renegotiate/err-doc-cipher")
        r = TestEnv.curl_get( url, options=[ "-vvv" ] )
>       assert 0 != r["rv"]
E       assert 0 != 0

test_101_ssl_reneg.py:141: AssertionError
------------------------------------------------------------------------ Captured stdout setup ------------------------------------------------------------------------
setup_method: test_101_11
------------------------------------------------------------------------ Captured stdout call -------------------------------------------------------------------------
execute: /usr/bin/curl -ks -D /tmp/mod_h2/test/gen/curl.headers --resolve ssl.tests.httpd.apache.org:42002:127.0.0.1 --connect-timeout 5 -vvv https://ssl.tests.httpd.apache.org:42002/renegotiate/err-doc-cipher
exit code 0, stderr:
* Added ssl.tests.httpd.apache.org:42002:127.0.0.1 to DNS cache
* Hostname ssl.tests.httpd.apache.org was found in DNS cache
*   Trying 127.0.0.1...
* TCP_NODELAY set
* Connected to ssl.tests.httpd.apache.org (127.0.0.1) port 42002 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* successfully set certificate verify locations:
*   CAfile: /etc/ssl/certs/ca-certificates.crt
  CApath: /etc/ssl/certs
} [5 bytes data]
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
} [512 bytes data]
* TLSv1.3 (IN), TLS handshake, Server hello (2):
{ [122 bytes data]
* TLSv1.3 (IN), TLS Unknown, Certificate Status (22):
{ [1 bytes data]
* TLSv1.3 (IN), TLS handshake, Unknown (8):
{ [19 bytes data]
* TLSv1.3 (IN), TLS Unknown, Certificate Status (22):
{ [1 bytes data]
* TLSv1.3 (IN), TLS handshake, Certificate (11):
{ [1184 bytes data]
* TLSv1.3 (IN), TLS Unknown, Certificate Status (22):
{ [1 bytes data]
* TLSv1.3 (IN), TLS handshake, CERT verify (15):
{ [264 bytes data]
* TLSv1.3 (IN), TLS Unknown, Certificate Status (22):
{ [1 bytes data]
* TLSv1.3 (IN), TLS handshake, Finished (20):
{ [52 bytes data]
* TLSv1.3 (OUT), TLS change cipher, Client hello (1):
} [1 bytes data]
* TLSv1.3 (OUT), TLS Unknown, Certificate Status (22):
} [1 bytes data]
* TLSv1.3 (OUT), TLS handshake, Finished (20):
} [52 bytes data]
* SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384
* ALPN, server accepted to use h2
* Server certificate:
*  subject: C=DE; ST=NRW; L=Muenster; postalCode=48155; street=Hafenweg 16; O=greenbytes GmbH; CN=a test certficate; emailAddress=webmaster@test.greenbytes.de
*  start date: Sep 29 17:25:33 2019 GMT
*  expire date: Sep 28 17:25:33 2022 GMT
*  issuer: C=DE; ST=NRW; L=Muenster; postalCode=48155; street=Hafenweg 16; O=greenbytes GmbH; CN=a test certficate; emailAddress=webmaster@test.greenbytes.de
*  SSL certificate verify result: unable to get local issuer certificate (20), continuing anyway.
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
} [5 bytes data]
* TLSv1.3 (OUT), TLS Unknown, Unknown (23):
} [1 bytes data]
* TLSv1.3 (OUT), TLS Unknown, Unknown (23):
} [1 bytes data]
* TLSv1.3 (OUT), TLS Unknown, Unknown (23):
} [1 bytes data]
* Using Stream ID: 1 (easy handle 0x55fcf6235580)
} [5 bytes data]
* TLSv1.3 (OUT), TLS Unknown, Unknown (23):
} [1 bytes data]
> GET /renegotiate/err-doc-cipher HTTP/2
> Host: ssl.tests.httpd.apache.org:42002
> User-Agent: curl/7.58.0
> Accept: */*
>
{ [5 bytes data]
* TLSv1.3 (IN), TLS Unknown, Certificate Status (22):
{ [1 bytes data]
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [297 bytes data]
* TLSv1.3 (IN), TLS Unknown, Certificate Status (22):
{ [1 bytes data]
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [297 bytes data]
* TLSv1.3 (IN), TLS Unknown, Unknown (23):
{ [1 bytes data]
* Connection state changed (MAX_CONCURRENT_STREAMS updated)!
} [5 bytes data]
* TLSv1.3 (OUT), TLS Unknown, Unknown (23):
} [1 bytes data]
* TLSv1.3 (IN), TLS Unknown, Unknown (23):
{ [1 bytes data]
* TLSv1.3 (IN), TLS Unknown, Unknown (23):
{ [1 bytes data]
< HTTP/2 404
< date: Sun, 29 Sep 2019 18:52:22 GMT
< server: Apache/2.4.42-dev (Unix) OpenSSL/1.1.1
< content-length: 196
< content-type: text/html; charset=iso-8859-1
<
{ [5 bytes data]
* TLSv1.3 (IN), TLS Unknown, Unknown (23):
{ [1 bytes data]
* Connection #0 to host ssl.tests.httpd.apache.org left intact

stdout:
<!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 2.0//EN">
<html><head>
<title>404 Not Found</title>
</head><body>
<h1>Not Found</h1>
<p>The requested URL was not found on this server.</p>
</body></html>

reading 1st response line: HTTP/2 404

reading header line: date: Sun, 29 Sep 2019 18:52:22 GMT

reading header line: server: Apache/2.4.42-dev (Unix) OpenSSL/1.1.1

reading header line: content-length: 196

reading header line: content-type: text/html; charset=iso-8859-1

---------------------------------------------------------------------- Captured stdout teardown -----------------------------------------------------------------------
teardown_method: test_101_11
teardown_module: test_101_ssl_reneg
execute: /usr/local/apache2/bin/apachectl -d /tmp/mod_h2/test/gen/apache -k stop
checking reachability of http://127.0.0.1:42001
waited for a apache.is_dead, rv=0
------------------------------------------------------------------------ Captured log teardown ------------------------------------------------------------------------
connectionpool.py          208 DEBUG    Starting new HTTP connection (1): 127.0.0.1
================================================================= 2 failed, 6 passed in 0.67 seconds ==================================================================

[icing]

This test case is triggering a TLSv1.2 renegotiation by changing the cipher and checks that it is properly denied for h2.

Since TLSv1.3 does use a separte cipher suite, this configuration does not trigger anything and the request goes through normally. I think the test suite should skip this, or force 1.2.

WDYT?

[elukey]

+1 it seems sound!

Is the 404 expected as well? I get the 403 in this case, but not the latter.. (sorry I might miss something obvious).

[icing]

Yes, I think 404 is correct. It's a Location without any mapping.

[elukey]

I just noticed the /renegotiate/cipher/ vs /renegotiate/cipher, ok now it makes sense :D

[elukey]

Getting back to this.. Would it be possible with the current setup to force TLS 1.2? Because from what I can see curl supports --tls12 that is for TLS 1.2+ (so even 1.3 if available).

[icing]

Thanks for the PR that fixed this!