t/external/ocsp.t failing

noxxi / p5-io-socket-ssl

IO::Socket::SSL Perl Module

36 stars 60 forks source link

t/external/ocsp.t failing #63

Closed briang closed 7 years ago

briang commented 7 years ago

I've tried various perls (5.27.4, 5.24.2, 5.24.1) and this test consistently fails. IO::Socket::SSL 2.050 is also failing. This is a recent thing, 2.050 on perl 5.24.2 was working when I installed it in June and on perl 5.27.3 in August.


$ perl -v | grep version

This is perl 5, version 24, subversion 2 (v5.24.2) built for x86_64-linux-thread-multi-ld
(with 1 registered patch, see perl -V for more detail)

$ prove -vl t/01loadmodule.t t/protocol_version.t t/external/ocsp.t 
t/01loadmodule.t ...... 
1..3
ok 1 - loaded
# openssl version=0x1000207f
# Net::SSLeay version=1.81
# parent IO::Socket::IP version=0.39
ok 2 - IO::Socket::SSL::DEBUG 1
ok 3 - Net::SSLeay::trace 1
ok

t/protocol_version.t .. 
ok 1 - accept SSLv23 with any, got TLSv1_2
# looks like OpenSSL was compiled without SSLv3 support
ok 2 - accept TLSv1 with any, got TLSv1
ok 3 - accept TLSv1_1 with any, got TLSv1_1
ok 4 - accept TLSv1 with TLSv1
ok 5 - accept SSLv23:!TLSv1_2:!TLSv1_1 with TLSv1
ok 6 - accept TLSv1_1 with TLSv1_1
ok 7 - accept SSLv23:!TLSv1_2 with TLSv1_1
ok 8 - accept TLSv1_2 with TLSv1_2
ok 9 - accept SSLv23 with TLSv1_2
1..9
ok

t/external/ocsp.t ..... 
1..3
# tcp connect to www.chksum.de:443 ok
ok 1 # skip fingerprints do not match
# tcp connect to www.spiegel.de:443 ok
# fingerprint matches
# validation with default CA w/o OCSP ok
not ok 2 - SSL upgrade with OCSP stapling failed: SSL wants a read first
#   Failed test 'SSL upgrade with OCSP stapling failed: SSL wants a read first'
#   at t/external/ocsp.t line 93.
# tcp connect to revoked.grc.com:443 ok
ok 3 # skip fingerprints do not match
# Looks like you failed 1 test of 3.
Dubious, test returned 1 (wstat 256, 0x100)
Failed 1/3 subtests 
    (less 2 skipped subtests: 0 okay)

Test Summary Report
-------------------
t/external/ocsp.t   (Wstat: 256 Tests: 3 Failed: 1)
  Failed test:  2
  Non-zero exit status: 1
Files=3, Tests=15, 12 wallclock secs ( 0.04 usr  0.00 sys +  0.42 cusr  0.07 csys =  0.53 CPU)
Result: FAIL

noxxi commented 7 years ago

It does not fail for me with the same reported version of OpenSSL and Net::SSLeay. I've updated the fingerprints in the tests so it will no skip some hosts. Could you please try a current checkout from git (at least 75faf14) so that tests with other hosts will be run? And could you also add t/external/usable_ca.t to your test output, i.e. additionally to t/01loadmodule.t and t/external/ocsp.t ? I don't expect it to succeed but I'm interested if this is the only failing host or if the others have the same problem. I'm also interested what the actual running version of OpenSSL is (i.e. linked vs. loaded) because I just realized that the reported one might differ from the actual running one and added additional output to t/01loadmodule.t.

briang commented 7 years ago

Using 75faf14fc09f5a447b43a8cde858c29e61e52bd9:

$ perl -v | grep version
This is perl 5, version 24, subversion 3 (v5.24.3) built for x86_64-linux-thread-multi-ld

$ prove -vl t/01loadmodule.t t/external/ocsp.t t/external/usable_ca.t
t/01loadmodule.t ........ 
1..3
ok 1 - loaded
# openssl version compiled=0x1000207f linked=0x1000207f
# Net::SSLeay version=1.81
# parent IO::Socket::IP version=0.39
ok 2 - IO::Socket::SSL::DEBUG 1
ok 3 - Net::SSLeay::trace 1
ok

t/external/ocsp.t ....... 
1..3
# tcp connect to www.chksum.de:443 ok
# fingerprint matches
# validation with default CA w/o OCSP ok
# got stapled response as expected
# validation with default CA with OCSP defaults ok
# validation with default CA with OCSP full chain ok
ok 1 - OCSP tests www.chksum.de:443 ok
# tcp connect to www.spiegel.de:443 ok
# fingerprint matches
# validation with default CA w/o OCSP ok
not ok 2 - SSL upgrade with OCSP stapling failed: SSL wants a read first
#   Failed test 'SSL upgrade with OCSP stapling failed: SSL wants a read first'
#   at t/external/ocsp.t line 93.
# tcp connect to revoked.grc.com:443 ok
# fingerprint matches
# validation with default CA w/o OCSP ok
ok 3 - revoked as expected (asked OCSP server)
# Looks like you failed 1 test of 3.
Dubious, test returned 1 (wstat 256, 0x100)
Failed 1/3 subtests 

t/external/usable_ca.t .. # found 172 CA certs

1..21
# have root CA for www.spiegel.de in store
# 5 connections to www.spiegel.de ok
# fingerprint www.spiegel.de matches
# check www.spiegel.de against builtin CA store ok
ok 1 - SSL upgrade www.spiegel.de with default CA and SSL_verifycn_name
ok 2 - SSL upgrade www.spiegel.de with no CA failed but not because of verify problem: SSL wants a read first
ok 3 - SSL upgrade www.spiegel.de with no CA failed
# have root CA for www.yahoo.com in store
# 5 connections to www.yahoo.com ok
# fingerprint www.yahoo.com matches
# check www.yahoo.com against builtin CA store ok
ok 4 - SSL upgrade www.yahoo.com with default CA and SSL_verifycn_name
ok 5 - SSL upgrade www.yahoo.com with default CA and SSL_hostname
ok 6 - SSL upgrade www.yahoo.com with no CA failed
# have root CA for www.comdirect.de in store
# 5 connections to www.comdirect.de ok
# fingerprint www.comdirect.de matches
# check www.comdirect.de against builtin CA store ok
ok 7 - SSL upgrade www.comdirect.de with default CA and SSL_verifycn_name
ok 8 - SSL upgrade www.comdirect.de with default CA and SSL_hostname
ok 9 - SSL upgrade www.comdirect.de with no CA failed
# have root CA for meine.deutsche-bank.de in store
# 5 connections to meine.deutsche-bank.de ok
# fingerprint meine.deutsche-bank.de matches
# check meine.deutsche-bank.de against builtin CA store ok
ok 10 - SSL upgrade meine.deutsche-bank.de with default CA and SSL_verifycn_name
ok 11 - SSL upgrade meine.deutsche-bank.de with default CA and SSL_hostname
ok 12 - SSL upgrade meine.deutsche-bank.de with no CA failed
# have root CA for www.twitter.com in store
# 5 connections to www.twitter.com ok
ok 13 # skip fingerprint mismatch (sha1$d1d1933e219881202f69fafca898bceb3c612039) - probably SSL interception or certificate changed
ok 14 # skip fingerprint mismatch (sha1$d1d1933e219881202f69fafca898bceb3c612039) - probably SSL interception or certificate changed
ok 15 # skip fingerprint mismatch (sha1$d1d1933e219881202f69fafca898bceb3c612039) - probably SSL interception or certificate changed
# have root CA for www.facebook.com in store
# 5 connections to www.facebook.com ok
# fingerprint www.facebook.com matches
# check www.facebook.com against builtin CA store ok
ok 16 - SSL upgrade www.facebook.com with default CA and SSL_verifycn_name
ok 17 - SSL upgrade www.facebook.com with default CA and SSL_hostname
ok 18 - SSL upgrade www.facebook.com with no CA failed
# have root CA for www.live.com in store
# 5 connections to www.live.com ok
# fingerprint www.live.com matches
# check www.live.com against builtin CA store ok
ok 19 - SSL upgrade www.live.com with default CA and SSL_verifycn_name
ok 20 - SSL upgrade www.live.com with default CA and SSL_hostname
ok 21 - SSL upgrade www.live.com with no CA failed
ok

Test Summary Report
-------------------
t/external/ocsp.t     (Wstat: 256 Tests: 3 Failed: 1)
  Failed test:  2
  Non-zero exit status: 1
Files=3, Tests=27, 44 wallclock secs ( 0.04 usr  0.01 sys +  0.72 cusr  0.13 csys =  0.90 CPU)
Result: FAIL

noxxi commented 7 years ago

test-spiegelde.pl.txt Based on this output it looks like that the problem is restricted to access for www.spiegel.de. Could you please try the attached script to further check the connectivity to this site from your place?

briang commented 7 years ago


$ perl test-spiegelde.pl.txt 
 0.0000 got 6 address to test: 128.65.210.180 128.65.210.181 128.65.210.182 128.65.210.183 128.65.210.184 128.65.210.185
 0.2216 ssl upgrade 128.65.210.180 without OCSP stapling success
 0.2271 ssl upgrade 128.65.210.181 without OCSP stapling success
 0.2171 ssl upgrade 128.65.210.182 without OCSP stapling success
 0.2199 ssl upgrade 128.65.210.183 without OCSP stapling success
 0.1418 ssl upgrade 128.65.210.184 without OCSP stapling success
 0.2165 ssl upgrade 128.65.210.185 without OCSP stapling success
10.0518 SSL upgrade 128.65.210.180 with OCSP stapling failed: SSL wants a read first
10.0499 SSL upgrade 128.65.210.181 with OCSP stapling failed: SSL wants a read first
10.0521 SSL upgrade 128.65.210.182 with OCSP stapling failed: SSL wants a read first
10.0505 SSL upgrade 128.65.210.183 with OCSP stapling failed: SSL wants a read first
10.0516 SSL upgrade 128.65.210.184 with OCSP stapling failed: SSL wants a read first
10.0512 SSL upgrade 128.65.210.185 with OCSP stapling failed: SSL wants a read first
 0.1468 ssl upgrade 128.65.210.180 without OCSP stapling success
 0.1470 ssl upgrade 128.65.210.181 without OCSP stapling success
 0.2399 ssl upgrade 128.65.210.182 without OCSP stapling success
 0.2251 ssl upgrade 128.65.210.183 without OCSP stapling success
 0.2188 ssl upgrade 128.65.210.184 without OCSP stapling success
 0.1453 ssl upgrade 128.65.210.185 without OCSP stapling success
10.0445 SSL upgrade 128.65.210.180 with OCSP stapling failed: SSL wants a read first
10.0523 SSL upgrade 128.65.210.181 with OCSP stapling failed: SSL wants a read first
10.0518 SSL upgrade 128.65.210.182 with OCSP stapling failed: SSL wants a read first
10.0528 SSL upgrade 128.65.210.183 with OCSP stapling failed: SSL wants a read first
10.0473 SSL upgrade 128.65.210.184 with OCSP stapling failed: SSL wants a read first
10.0518 SSL upgrade 128.65.210.185 with OCSP stapling failed: SSL wants a read first

noxxi commented 7 years ago

Thanks for the feedback.

It looks like it is reliably failing any SSL handshakes with OCSP stapling enabled. And it is only failing for this specific site even though OCSP stapling is also used with the other sites (it's the default). And, it is not failing with OCSP stapling for me although I use the same target IP address and the same version of OpenSSL, Net::SSLeay etc as you do. Very strange.

In my opinion this should already fail on a simple

   perl -MIO::Socket::SSL -e 'IO::Socket::SSL->new(q[www.spiegel.de:443]) or die $SSL_ERROR'

Could you please verify this and make a packet capture of this failing connection (tcpdump -s0 -w capture.pcap -i your-interface port 443) and provide the capture file (maybe send it to sullr@cpan.org) so that I can check if there are any differences compared to what I get from my system?

briang commented 7 years ago

I timed the script, because it looked like a timeout:

$ time $( perl -MIO::Socket::SSL -e 'IO::Socket::SSL->new(q[www.spiegel.de:443]) or die $SSL_ERROR' )
SSL connect attempt failed because of handshake problems at -e line 1.

real    1m6.123s
user    0m0.072s
sys 0m0.020s

tcpdump just hung - I left it >30mins. Does this command line look right?


sudo tcpdump -s0 -w capture.pcap -i enp0s3 port 443

noxxi commented 7 years ago

tcpdump just hung - I left it >30mins. Does this command line look right?

You have to start tcpdump immediately before you do the perl test and kill it manually after the test with Control-C. It will not finish by its own since it does not know when it should stop capturing data. And, if enp0s3 is your internet facing interface then the command line is correct. If you have successfully captured data you should see something like this after the Control-C:

18 packets captured
18 packets received by filter
0 packets dropped by kernel

noxxi commented 7 years ago

Thanks for the packet capture. From the capture it looks like that some middlebox (firewall or similar) is inferring with the connection in a bad way. The initial TCP handshake succeeds but the initial ClientHello from the client at the start of the SSL handshake gets lost. The clients tries to retransmit the packet multiple times and after 67 seconds the server closes the connection without having received the ClientHello (as can be seen from the sequence numbers). Details of this analysis using tshark -r capture.pcap:

Initial TCP handshake:

    1   0.000000  192.168.0.5 → 128.65.210.182 TCP 74 35436 → 443 [SYN] Seq=0 Win=29200 Len=0 MSS=1460 SACK_PERM=1 TSval=8540293 TSecr=0 WS=128
    2   0.037228 128.65.210.182 → 192.168.0.5  TCP 74 443 → 35436 [SYN, ACK] Seq=0 Ack=1 Win=7240 Len=0 MSS=1460 SACK_PERM=1 TSval=3603427651 TSecr=8540293 WS=128
    3   0.037403  192.168.0.5 → 128.65.210.182 TCP 66 35436 → 443 [ACK] Seq=1 Ack=1 Win=29312 Len=0 TSval=8540302 TSecr=3603427651

Client sends ClientHello and receives no ACK from server. Retransmits multiple times:

    4   0.037834  192.168.0.5 → 128.65.210.182 SSL 275 Client Hello
    5   0.275905  192.168.0.5 → 128.65.210.182 TCP 275 [TCP Retransmission] 35436 → 443 [PSH, ACK] Seq=1 Ack=1 Win=29312 Len=209 TSval=8540362 TSecr=3603427651
    6   0.515381  192.168.0.5 → 128.65.210.182 TCP 275 [TCP Retransmission] 35436 → 443 [PSH, ACK] Seq=1 Ack=1 Win=29312 Len=209 TSval=8540422 TSecr=3603427651
    ....
   15  61.611800  192.168.0.5 → 128.65.210.182 TCP 275 [TCP Retransmission] 35436 → 443 [PSH, ACK] Seq=1 Ack=1 Win=29312 Len=209 TSval=8555696 TSecr=3603427651

Server closes the connection after 67 seconds of inactivity. The Ack=1 in the FIN shows that the server has not received any data from the client, i.e. not the ClientHello:

   16  67.986070 128.65.210.182 → 192.168.0.5  TCP 66 443 → 35436 [FIN, ACK] Seq=1 Ack=1 Win=7296 Len=0 TSval=3603495599 TSecr=8540302

Such behavior is known for example with some deep packet inspection firewalls. The only strange thing is that the ClientHello which does not request an OCSP stapling seems to work, which suggests a broken firewall which either blocks things it should not block or can be bypassed by not doing OCSP stapling.

Can you please verify again that the TLS handshake w/o OCSP stapling really comes through with the following command:

perl -MIO::Socket::SSL -e 'IO::Socket::SSL->new(PeerAddr => q[www.spiegel.de:443], SSL_ocsp_mode => SSL_OCSP_NO_STAPLE) or die $SSL_ERROR; warn "ok"'

briang commented 7 years ago

$ perl -MIO::Socket::SSL -e 'IO::Socket::SSL->new(PeerAddr => q[www.spiegel.de:443], SSL_ocsp_mode => SSL_OCSP_NO_STAPLE) or die $SSL_ERROR; warn "ok"'
ok at -e line 1.

I'll see if I can get any significant results on other OSs (*BSD, Debian, various Ubuntus).

noxxi commented 7 years ago

ok at -e line 1.

Thanks for checking. This is really a very strange behavior. Do you know which kind of firewall or other deep packet inspection is employed at your place? Because this looks like a bug in this product for me.

I'll see if I can get any significant results on other OSs (*BSD, Debian, various Ubuntus).

I'll doubt that this is a problem with the OS but more a problem of some middlebox. Although different versions of OpenSSL might result in a different behavior because the ClientHello might look slightly different.

briang commented 7 years ago

IO::S::SSL installed without problem on a clean install of Debian 9.1 with OpenSSL:

$ prove -vl t/01loadmodule.t t/external/usable_ca.t 
t/01loadmodule.t ........ 
1..3
ok 1 - loaded
ok 2 - IO::Socket::SSL::DEBUG 1
ok 3 - Net::SSLeay::trace 1
# openssl version=0x1010006f
# Net::SSLeay version=1.81
# parent IO::Socket::IP version=0.37
ok

t/external/usable_ca.t .. # found 167 CA certs

1..21
# have root CA for www.spiegel.de in store
# 5 connections to www.spiegel.de ok
# fingerprint www.spiegel.de matches
# check www.spiegel.de against builtin CA store ok
ok 1 - SSL upgrade www.spiegel.de with default CA and SSL_verifycn_name
ok 2 - SSL upgrade www.spiegel.de with default CA and SSL_hostname
ok 3 - SSL upgrade www.spiegel.de with no CA failed
# have root CA for www.yahoo.com in store
# 5 connections to www.yahoo.com ok
ok 4 # skip fingerprint mismatch (sha1$dc0866cdf51594fd85ccf249d507164552828ad2) - probably SSL interception or certificate changed
ok 5 # skip fingerprint mismatch (sha1$dc0866cdf51594fd85ccf249d507164552828ad2) - probably SSL interception or certificate changed
ok 6 # skip fingerprint mismatch (sha1$dc0866cdf51594fd85ccf249d507164552828ad2) - probably SSL interception or certificate changed
# have root CA for www.comdirect.de in store
# 5 connections to www.comdirect.de ok
ok 7 # skip fingerprint mismatch (sha1$cda53778d01ff728fe90fe0399b17586f1aef0bf) - probably SSL interception or certificate changed
ok 8 # skip fingerprint mismatch (sha1$cda53778d01ff728fe90fe0399b17586f1aef0bf) - probably SSL interception or certificate changed
ok 9 # skip fingerprint mismatch (sha1$cda53778d01ff728fe90fe0399b17586f1aef0bf) - probably SSL interception or certificate changed
# have root CA for meine.deutsche-bank.de in store
# 5 connections to meine.deutsche-bank.de ok
ok 10 # skip fingerprint mismatch (sha1$27d647fd859bf824d9f537a09aa98e4923fb6942) - probably SSL interception or certificate changed
ok 11 # skip fingerprint mismatch (sha1$27d647fd859bf824d9f537a09aa98e4923fb6942) - probably SSL interception or certificate changed
ok 12 # skip fingerprint mismatch (sha1$27d647fd859bf824d9f537a09aa98e4923fb6942) - probably SSL interception or certificate changed
# have root CA for www.twitter.com in store
# 5 connections to www.twitter.com ok
ok 13 # skip fingerprint mismatch (sha1$d1d1933e219881202f69fafca898bceb3c612039) - probably SSL interception or certificate changed
ok 14 # skip fingerprint mismatch (sha1$d1d1933e219881202f69fafca898bceb3c612039) - probably SSL interception or certificate changed
ok 15 # skip fingerprint mismatch (sha1$d1d1933e219881202f69fafca898bceb3c612039) - probably SSL interception or certificate changed
# have root CA for www.facebook.com in store
# 5 connections to www.facebook.com ok
ok 16 # skip fingerprint mismatch (sha1$936f912bafad216fa515256e572cdc35a1451aa5) - probably SSL interception or certificate changed
ok 17 # skip fingerprint mismatch (sha1$936f912bafad216fa515256e572cdc35a1451aa5) - probably SSL interception or certificate changed
ok 18 # skip fingerprint mismatch (sha1$936f912bafad216fa515256e572cdc35a1451aa5) - probably SSL interception or certificate changed
# have root CA for www.live.com in store
# 5 connections to www.live.com ok
ok 19 # skip fingerprint mismatch (sha1$3b9e5cc01313b6f86709646f1be4a057ed75bcc9) - probably SSL interception or certificate changed
ok 20 # skip fingerprint mismatch (sha1$3b9e5cc01313b6f86709646f1be4a057ed75bcc9) - probably SSL interception or certificate changed
ok 21 # skip fingerprint mismatch (sha1$3b9e5cc01313b6f86709646f1be4a057ed75bcc9) - probably SSL interception or certificate changed
ok
All tests successful.
Files=2, Tests=24,  3 wallclock secs ( 0.04 usr  0.03 sys +  0.23 cusr  0.11 csys =  0.41 CPU)
Result: PASS

Different OpenSSL version!

Do you know which kind of firewall or other deep packet inspection is employed at your place? Because this looks like a bug for me.

I'm at home running VirtualBox VMs on a Windows 7 host. My Internet connection is through a Virgin Media cable modem/router (a re-badged NetGear, IIRC).

So, two firewalls: Windows & the router and I haven't changed either in a long, long time.

Google doesn't seem to think that Virgin is doing any DPI now, but they did trial it for "statistical" purposes about 10 years ago.

noxxi commented 7 years ago

So, two firewalls: Windows & the router and I haven't changed either in a long, long time.

Windows should not do any DPI by itself. But maybe some Antivirus solution on the machine? And I doubt that the Netgear does it, unless one could configure anything about blocking sites or parental protection or similar. Anyway, the problem is strange but outside of IO::Socket::SSL so I can close the issue.

briang commented 7 years ago

some Antivirus

Avast Antivirus. I disabled it but it didn't fix the failing test

I can close the issue.

OK, thanks for your time and help

briang commented 7 years ago

FYI

And, as if by magic, it's all changed today!

Previous ocsp.t results (summarised):

ok 1 - OCSP tests www.chksum.de:443 ok
not ok 2 - SSL upgrade with OCSP stapling failed: SSL wants a read first
ok 3 - revoked as expected (asked OCSP server)

Todays results:

ok 1 # skip fingerprints do not match
ok 2 - OCSP tests www.spiegel.de:443 ok
ok 3 # skip fingerprints do not match

noxxi commented 7 years ago

ok 1 # skip fingerprints do not match ok 2 - OCSP tests www.spiegel.de:443 ok ok 3 # skip fingerprints do not match

fingerprints do not match shows that something is still inferring with the connection, i.e. doing SSL interception. But at least it seems to infer in a more consistent way now.

briang commented 7 years ago

Using IO::Socket::SSL 2.052:

$ prove -vl t/external/ocsp.t 
t/external/ocsp.t .. 
1..3
# tcp connect to www.chksum.de:443 ok
# fingerprint matches
# validation with default CA w/o OCSP ok
# got stapled response as expected
# validation with default CA with OCSP defaults ok
# validation with default CA with OCSP full chain ok
ok 1 - OCSP tests www.chksum.de:443 ok
# tcp connect to www.spiegel.de:443 ok
# fingerprint matches
# validation with default CA w/o OCSP ok
# validation with default CA with OCSP defaults ok
ok 2 - OCSP tests www.spiegel.de:443 ok
# validation with default CA with OCSP full chain ok
# tcp connect to revoked.grc.com:443 ok
# fingerprint matches
# validation with default CA w/o OCSP ok
ok 3 - revoked as expected (asked OCSP server)
ok
All tests successful.
Files=1, Tests=3, 15 wallclock secs ( 0.03 usr  0.00 sys +  0.19 cusr  0.04 csys =  0.26 CPU)
Result: PASS

So, yay, I guess :)