Skip Menu |
 

This queue is for tickets about the IO-Socket-SSL CPAN distribution.

Report information
The Basics
Id: 124141
Status: resolved
Priority: 0/
Queue: IO-Socket-SSL

People
Owner: Nobody in particular
Requestors: SREZIC [...] cpan.org
Cc:
AdminCc:

Bug Information
Severity: (no value)
Broken in: 2.052
Fixed in: (no value)



Subject: ocsp test fails from time to time
Download (untitled) / with headers
text/plain 884b
Sometimes t/external/ocsp.t fails on some of my FreeBSD smokers: ... # tcp connect to www.chksum.de:443 ok # tcp connect to www.spiegel.de:443 ok # fingerprint matches # validation with default CA w/o OCSP ok # Failed test 'SSL upgrade with OCSP stapling failed: SSL connect attempt failed error:2707307D:OCSP routines:OCSP_check_validity:status expired' # 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 # Looks like you failed 1 test of 3. t/external/ocsp.t ................. Dubious, test returned 1 (wstat 256, 0x100) Failed 1/3 subtests (less 1 skipped subtest: 1 okay) ... If it fails, then it seems always to be the spiegel.de test. The failures don't seem to be permanent: I saw them already around 2017-12-19, then the failures stopped around 2017-12-24. Today I see them again.
Download (untitled) / with headers
text/plain 9.4k
On 2018-01-20 06:13:42, SREZIC wrote: Show quoted text
> Sometimes t/external/ocsp.t fails on some of my FreeBSD smokers: > > ... > # tcp connect to www.chksum.de:443 ok > # tcp connect to www.spiegel.de:443 ok > # fingerprint matches > # validation with default CA w/o OCSP ok > > # Failed test 'SSL upgrade with OCSP stapling failed: SSL connect > attempt failed error:2707307D:OCSP routines:OCSP_check_validity:status > expired' > # 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 > # Looks like you failed 1 test of 3. > t/external/ocsp.t ................. > Dubious, test returned 1 (wstat 256, 0x100) > Failed 1/3 subtests > (less 1 skipped subtest: 1 okay) > ... > > > If it fails, then it seems always to be the spiegel.de test. The > failures don't seem to be permanent: I saw them already around 2017- > 12-19, then the failures stopped around 2017-12-24. Today I see them > again.
I put $IO::Socket::SSL::DEBUG = 3; into the test script and ran it again: DEBUG: .../IO/Socket/SSL.pm:2843: free ctx 34434678272 open= DEBUG: .../IO/Socket/SSL.pm:2854: OK free ctx 34434678272 # tcp connect to www.spiegel.de:443 ok DEBUG: .../IO/Socket/SSL.pm:2821: new ctx 34434678272 DEBUG: .../IO/Socket/SSL.pm:1519: start handshake DEBUG: .../IO/Socket/SSL.pm:698: ssl handshake not started DEBUG: .../IO/Socket/SSL.pm:731: using SNI with hostname www.spiegel.de DEBUG: .../IO/Socket/SSL.pm:787: set socket to non-blocking to enforce timeout=10 DEBUG: .../IO/Socket/SSL.pm:800: call Net::SSLeay::connect DEBUG: .../IO/Socket/SSL.pm:803: done Net::SSLeay::connect -> -1 DEBUG: .../IO/Socket/SSL.pm:813: ssl handshake in progress DEBUG: .../IO/Socket/SSL.pm:823: waiting for fd to become ready: SSL wants a read first DEBUG: .../IO/Socket/SSL.pm:843: socket ready, retrying connect DEBUG: .../IO/Socket/SSL.pm:800: call Net::SSLeay::connect DEBUG: .../IO/Socket/SSL.pm:803: done Net::SSLeay::connect -> -1 DEBUG: .../IO/Socket/SSL.pm:813: ssl handshake in progress DEBUG: .../IO/Socket/SSL.pm:823: waiting for fd to become ready: SSL wants a read first DEBUG: .../IO/Socket/SSL.pm:843: socket ready, retrying connect DEBUG: .../IO/Socket/SSL.pm:800: call Net::SSLeay::connect DEBUG: .../IO/Socket/SSL.pm:803: done Net::SSLeay::connect -> 1 DEBUG: .../IO/Socket/SSL.pm:858: ssl handshake done # fingerprint matches DEBUG: .../IO/Socket/SSL.pm:2843: free ctx 34434678272 open= DEBUG: .../IO/Socket/SSL.pm:2854: OK free ctx 34434678272 DEBUG: .../IO/Socket/SSL.pm:2821: new ctx 34434678272 DEBUG: .../IO/Socket/SSL.pm:1519: start handshake DEBUG: .../IO/Socket/SSL.pm:698: ssl handshake not started DEBUG: .../IO/Socket/SSL.pm:731: using SNI with hostname www.spiegel.de DEBUG: .../IO/Socket/SSL.pm:787: set socket to non-blocking to enforce timeout=10 DEBUG: .../IO/Socket/SSL.pm:800: call Net::SSLeay::connect DEBUG: .../IO/Socket/SSL.pm:803: done Net::SSLeay::connect -> -1 DEBUG: .../IO/Socket/SSL.pm:813: ssl handshake in progress DEBUG: .../IO/Socket/SSL.pm:823: waiting for fd to become ready: SSL wants a read first DEBUG: .../IO/Socket/SSL.pm:843: socket ready, retrying connect DEBUG: .../IO/Socket/SSL.pm:800: call Net::SSLeay::connect DEBUG: .../IO/Socket/SSL.pm:2675: ok=1 [2] /C=US/O=GeoTrust Inc./CN=GeoTrust Global CA/C=US/O=GeoTrust Inc./CN=GeoTrust Global CA DEBUG: .../IO/Socket/SSL.pm:2675: ok=1 [1] /C=US/O=GeoTrust Inc./CN=GeoTrust Global CA/C=US/O=GeoTrust Inc./CN=GeoTrust SSL CA - G3 DEBUG: .../IO/Socket/SSL.pm:2675: ok=1 [0] /C=US/O=GeoTrust Inc./CN=GeoTrust SSL CA - G3/C=DE/ST=Hamburg/L=Hamburg/O=SPIEGEL ONLINE GmbH/CN=www.spiegel.de DEBUG: .../IO/Socket/SSL.pm:1739: scheme=default cert=34437812224 DEBUG: .../IO/Socket/SSL.pm:1749: identity=www.spiegel.de cn=www.spiegel.de alt=2 www.spiegel.de 2 spiegel.de DEBUG: .../IO/Socket/SSL.pm:803: done Net::SSLeay::connect -> -1 DEBUG: .../IO/Socket/SSL.pm:813: ssl handshake in progress DEBUG: .../IO/Socket/SSL.pm:823: waiting for fd to become ready: SSL wants a read first DEBUG: .../IO/Socket/SSL.pm:843: socket ready, retrying connect DEBUG: .../IO/Socket/SSL.pm:800: call Net::SSLeay::connect DEBUG: .../IO/Socket/SSL.pm:803: done Net::SSLeay::connect -> 1 DEBUG: .../IO/Socket/SSL.pm:858: ssl handshake done # validation with default CA w/o OCSP ok DEBUG: .../IO/Socket/SSL.pm:2843: free ctx 34434678272 open= DEBUG: .../IO/Socket/SSL.pm:2847: free ctx 34434678272 callback DEBUG: .../IO/Socket/SSL.pm:2854: OK free ctx 34434678272 DEBUG: .../IO/Socket/SSL.pm:2821: new ctx 34434678272 DEBUG: .../IO/Socket/SSL.pm:1519: start handshake DEBUG: .../IO/Socket/SSL.pm:698: ssl handshake not started DEBUG: .../IO/Socket/SSL.pm:731: using SNI with hostname www.spiegel.de DEBUG: .../IO/Socket/SSL.pm:766: request OCSP stapling DEBUG: .../IO/Socket/SSL.pm:787: set socket to non-blocking to enforce timeout=10 DEBUG: .../IO/Socket/SSL.pm:800: call Net::SSLeay::connect DEBUG: .../IO/Socket/SSL.pm:803: done Net::SSLeay::connect -> -1 DEBUG: .../IO/Socket/SSL.pm:813: ssl handshake in progress DEBUG: .../IO/Socket/SSL.pm:823: waiting for fd to become ready: SSL wants a read first DEBUG: .../IO/Socket/SSL.pm:843: socket ready, retrying connect DEBUG: .../IO/Socket/SSL.pm:800: call Net::SSLeay::connect DEBUG: .../IO/Socket/SSL.pm:2675: ok=1 [2] /C=US/O=GeoTrust Inc./CN=GeoTrust Global CA/C=US/O=GeoTrust Inc./CN=GeoTrust Global CA DEBUG: .../IO/Socket/SSL.pm:2675: ok=1 [1] /C=US/O=GeoTrust Inc./CN=GeoTrust Global CA/C=US/O=GeoTrust Inc./CN=GeoTrust SSL CA - G3 DEBUG: .../IO/Socket/SSL.pm:2675: ok=1 [0] /C=US/O=GeoTrust Inc./CN=GeoTrust SSL CA - G3/C=DE/ST=Hamburg/L=Hamburg/O=SPIEGEL ONLINE GmbH/CN=www.spiegel.de DEBUG: .../IO/Socket/SSL.pm:1739: scheme=default cert=34437812224 DEBUG: .../IO/Socket/SSL.pm:1749: identity=www.spiegel.de cn=www.spiegel.de alt=2 www.spiegel.de 2 spiegel.de DEBUG: .../IO/Socket/SSL.pm:2725: got stapled OCSP response run basic verify at /home/cpansand/.cpan/build/2018012018/IO-Socket-SSL-2.052-0/blib/lib/IO/Socket/SSL.pm line 2732. found issuer in chain at /home/cpansand/.cpan/build/2018012018/IO-Socket-SSL-2.052-0/blib/lib/IO/Socket/SSL.pm line 2739. got issuer at /home/cpansand/.cpan/build/2018012018/IO-Socket-SSL-2.052-0/blib/lib/IO/Socket/SSL.pm line 2739. DEBUG: .../IO/Socket/SSL.pm:803: done Net::SSLeay::connect -> -1 DEBUG: .../IO/Socket/SSL.pm:806: SSL connect attempt failed DEBUG: .../IO/Socket/SSL.pm:806: local error: SSL connect attempt failed error:2707307D:OCSP routines:OCSP_check_validity:status expired DEBUG: .../IO/Socket/SSL.pm:809: fatal SSL error: SSL connect attempt failed error:2707307D:OCSP routines:OCSP_check_validity:status expired DEBUG: .../IO/Socket/SSL.pm:1936: downgrading SSL only, not closing socket DEBUG: .../IO/Socket/SSL.pm:2843: free ctx 34434678272 open= DEBUG: .../IO/Socket/SSL.pm:2847: free ctx 34434678272 callback DEBUG: .../IO/Socket/SSL.pm:2854: OK free ctx 34434678272 DEBUG: .../IO/Socket/SSL.pm:2821: new ctx 34434678272 DEBUG: .../IO/Socket/SSL.pm:1519: start handshake DEBUG: .../IO/Socket/SSL.pm:698: ssl handshake not started DEBUG: .../IO/Socket/SSL.pm:731: using SNI with hostname www.spiegel.de DEBUG: .../IO/Socket/SSL.pm:766: request OCSP stapling DEBUG: .../IO/Socket/SSL.pm:787: set socket to non-blocking to enforce timeout=10 DEBUG: .../IO/Socket/SSL.pm:800: call Net::SSLeay::connect DEBUG: .../IO/Socket/SSL.pm:803: done Net::SSLeay::connect -> -1 DEBUG: .../IO/Socket/SSL.pm:813: ssl handshake in progress DEBUG: .../IO/Socket/SSL.pm:823: waiting for fd to become ready: SSL wants a read first DEBUG: .../IO/Socket/SSL.pm:843: socket ready, retrying connect DEBUG: .../IO/Socket/SSL.pm:800: call Net::SSLeay::connect DEBUG: .../IO/Socket/SSL.pm:2675: ok=1 [2] /C=US/O=GeoTrust Inc./CN=GeoTrust Global CA/C=US/O=GeoTrust Inc./CN=GeoTrust Global CA DEBUG: .../IO/Socket/SSL.pm:2675: ok=1 [1] /C=US/O=GeoTrust Inc./CN=GeoTrust Global CA/C=US/O=GeoTrust Inc./CN=GeoTrust SSL CA - G3 DEBUG: .../IO/Socket/SSL.pm:2675: ok=1 [0] /C=US/O=GeoTrust Inc./CN=GeoTrust SSL CA - G3/C=DE/ST=Hamburg/L=Hamburg/O=SPIEGEL ONLINE GmbH/CN=www.spiegel.de DEBUG: .../IO/Socket/SSL.pm:1739: scheme=default cert=34437812224 DEBUG: .../IO/Socket/SSL.pm:1749: identity=www.spiegel.de cn=www.spiegel.de alt=2 www.spiegel.de 2 spiegel.de DEBUG: .../IO/Socket/SSL.pm:2725: got stapled OCSP response run basic verify at /home/cpansand/.cpan/build/2018012018/IO-Socket-SSL-2.052-0/blib/lib/IO/Socket/SSL.pm line 2732. found issuer in chain at /home/cpansand/.cpan/build/2018012018/IO-Socket-SSL-2.052-0/blib/lib/IO/Socket/SSL.pm line 2739. got issuer at /home/cpansand/.cpan/build/2018012018/IO-Socket-SSL-2.052-0/blib/lib/IO/Socket/SSL.pm line 2739. DEBUG: .../IO/Socket/SSL.pm:803: done Net::SSLeay::connect -> -1 DEBUG: .../IO/Socket/SSL.pm:806: SSL connect attempt failed DEBUG: .../IO/Socket/SSL.pm:806: local error: SSL connect attempt failed error:2707307D:OCSP routines:OCSP_check_validity:status expired DEBUG: .../IO/Socket/SSL.pm:809: fatal SSL error: SSL connect attempt failed error:2707307D:OCSP routines:OCSP_check_validity:status expired DEBUG: .../IO/Socket/SSL.pm:1936: downgrading SSL only, not closing socket DEBUG: .../IO/Socket/SSL.pm:2843: free ctx 34434678272 open= DEBUG: .../IO/Socket/SSL.pm:2847: free ctx 34434678272 callback DEBUG: .../IO/Socket/SSL.pm:2854: OK free ctx 34434678272 not ok 2 - SSL upgrade with OCSP stapling failed: SSL connect attempt failed error:2707307D:OCSP routines:OCSP_check_validity:status expired # Failed test 'SSL upgrade with OCSP stapling failed: SSL connect attempt failed error:2707307D:OCSP routines:OCSP_check_validity:status expired' # at t/external/ocsp.t line 95.
Download (untitled) / with headers
text/plain 646b
Show quoted text
> > # tcp connect to www.spiegel.de:443 ok > > # fingerprint matches > > # validation with default CA w/o OCSP ok > > > > # Failed test 'SSL upgrade with OCSP stapling failed: SSL connect > > attempt failed error:2707307D:OCSP > > routines:OCSP_check_validity:status > > expired'
It looks like www.spiegel.de has no enabled OCSP stapling but from to time they send an expired OCSP response, probably because they do not retrieve a new response on time (known problem with several setups). I've switched to a different site for the external tests and hopefully this will resolve the problem. Should be fixed in the just released version 2.053.


This service is sponsored and maintained by Best Practical Solutions and runs on Perl.org infrastructure.

Please report any issues with rt.cpan.org to rt-cpan-admin@bestpractical.com.