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)

History Show all quoted text
  Sat Jan 20 06:13:42 2018 SREZIC [...] cpan.org - Ticket created
Subject: ocsp test fails from time to time
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.
  Sat Jan 20 06:20:52 2018 SREZIC [...] cpan.org - Correspondence added
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.
  Sun Jan 21 05:29:26 2018 Steffen_Ullrich [...] genua.de - Correspondence added
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.
  Sun Jan 21 05:29:27 2018 The RT System itself - Status changed from 'new' to 'open'
  Sun Jan 21 05:29:27 2018 Steffen_Ullrich [...] genua.de - Status changed from 'open' to 'resolved'