Net::SSLeay::connect -> -1

bliako has asked for the wisdom of the Perl Monks concerning the following question:

Dear Monks, I am accessing a server with LWP::UserAgent over SSL for some time now and just recently I encountered this 500 Server closed connection without sending any data back (Client-Warning: Internal response). It appears randomly but often. Some comments I read suggested that this happens at the SSL setup phase where server closes connection and LWP issues this warning (hence Internal response). I have allowed a large timeout of 600s in the setup of LWP::UserAgent.

I have created a simple script to hit an irrelevant server (not the one I use for obvious reasons) just to test whether I have setup LWP+SSL correctly and also getting maximum debugging information.

#!/usr/bin/perl

use Test::More;

use LWP::ConsoleLogger::Easy qw( debug_ua );
use IO::Socket::SSL;
use LWP::UserAgent;

my $DEBUG = 1;

my $num_tests = 0;

my %pages = (
        # some name for the page to hit
        'google' =>
                [
                        # the url to hit
                        'https://www.google.com',
                        # regex obj to validate returned content
                        qr/Google Search/,
                ],
);

my $ua = LWP::UserAgent->new(ssl_opts => { verify_hostname => 1 });
if( $DEBUG == 1 ){
        LWP::ConsoleLogger::Easy::debug_ua($ua, 6);
        $IO::Socket::SSL::DEBUG = 3;
}

my ($response, $content, $aurl, $regex_validator, $apage);

foreach $apage (keys %pages){
        ($aurl, $regex_validator) = @{$pages{$apage}};
        $response = $ua->get($aurl);
        ok(defined($response), "$apage hit : $aurl"); $num_tests++;
        ok($response->is_success==1, "$apage hit got success status co
+de : $aurl") or BAIL_OUT("$apage : failed to hit : $aurl"); $num_test
+s++;
        $content = $response->decoded_content;
        ok($content =~ $regex_validator, "$apage validated OK") or pri
+nt "$apage : failed to validate the following content:\n".$content."\
+nend content.\n"; $num_tests++;
}
# END
done_testing($num_tests);
[download]

Here is part of the output:

DEBUG: .../IO/Socket/SSL.pm:2853: new ctx 93957261363856
DEBUG: .../IO/Socket/SSL.pm:692: socket not yet connected
DEBUG: .../IO/Socket/SSL.pm:694: socket connected
DEBUG: .../IO/Socket/SSL.pm:717: ssl handshake not started
DEBUG: .../IO/Socket/SSL.pm:750: using SNI with hostname www.google.co
+m
DEBUG: .../IO/Socket/SSL.pm:785: request OCSP stapling
DEBUG: .../IO/Socket/SSL.pm:806: set socket to non-blocking to enforce
+ timeout=180
DEBUG: .../IO/Socket/SSL.pm:819: call Net::SSLeay::connect
DEBUG: .../IO/Socket/SSL.pm:822: done Net::SSLeay::connect -> -1
DEBUG: .../IO/Socket/SSL.pm:832: ssl handshake in progress
DEBUG: .../IO/Socket/SSL.pm:842: waiting for fd to become ready: SSL w
+ants a read first
DEBUG: .../IO/Socket/SSL.pm:862: socket ready, retrying connect
DEBUG: .../IO/Socket/SSL.pm:819: call Net::SSLeay::connect
DEBUG: .../IO/Socket/SSL.pm:2707: ok=1 [2] /OU=GlobalSign Root CA - R2
+/O=GlobalSign/CN=GlobalSign/OU=GlobalSign Root CA - R2/O=GlobalSign/C
+N=GlobalSign
[download]

When hitting my server (and not google) the process hangs exactly at waiting for fd to become ready: SSL wants a read first but with a slightly different output (it does not have did not get stapled OCSP response) and repeated instances of:

DEBUG: .../IO/Socket/SSL.pm:832: ssl handshake in progress
DEBUG: .../IO/Socket/SSL.pm:842: waiting for fd to become ready: SSL w
+ants a read first
DEBUG: .../IO/Socket/SSL.pm:862: socket ready, retrying connect
DEBUG: .../IO/Socket/SSL.pm:819: call Net::SSLeay::connect
DEBUG: .../IO/Socket/SSL.pm:822: done Net::SSLeay::connect -> -1
[download]

I am asking for your wisdom. My questions are:

1) is the way I am using LWP+SSL in the example script correct? Any suggestions on best/preferred way to do this?
2) Does the output done Net::SSLeay::connect -> -1 signify an error? I could not figure out what this -1 is (as opposed to 1 in other instances) from documentation.
3) Any suggestions on improving debug/trace levels?

Run on latest Linux kernel with perl v5.26.2, OpenSSL 1.1.0, IO::Socket::SSL 2.060, Net::SSLeay 1.85

Comment on Net::SSLeay::connect -> -1 Select or Download Code

Replies are listed 'Best First'.
Re: Net::SSLeay::connect -> -1 by haj (Vicar) on Oct 23, 2018 at 20:35 UTC
Just a guess, from memory of a similar experience: Do you have some "non-standard" server certificate, e.g. issued by an inhouse CA? If so, maybe there's an issue with the OCSP responder of that certificate. If IO::Socket::SSL can't retrieve an OCSP response, it can't proceed and will apparently hang until the server gives up and terminates the connection. To isolate this problem, you can disable server certificate checking for testing only by setting `SSL_verify_mode => SSL_VERIFY_NONE` in the `ssl_opts` of your LWP user agent. If the problem persists, remove that insecure setting and look elsewhere; if the problem vanishes, examine the certificate: Maybe the OCSP URL can't be reliably received, or it uses a non-standard transport mechanism/port which is blocked by a firewall.	[reply]
Re^2: Net::SSLeay::connect -> -1 by bliako (Abbot) on Oct 23, 2018 at 22:00 UTC
Thanks for the hint. I tried it but the errors still persist. This is what I did: `my $ua = LWP::UserAgent->new(ssl_opts => { verify_hostname => 0, SSL_v +erify_mode => IO::Socket::SSL::SSL_VERIFY_NONE });` [download] Btw, on hitting google I can see mention of OCSP: `DEBUG: .../IO/Socket/SSL.pm:750: using SNI with hostname www.google.co +m DEBUG: .../IO/Socket/SSL.pm:785: request OCSP stapling ...` [download] But with the server I am using there is no mention of OCSP with or without `SSL_verify_mode => SSL_VERIFY_NONE`. Does the following log suggest that SSL is set after a lot of failed (-1) attempts but finally the handshake is done? Because it is after that successful handshake that the server closes the connection. DEBUG: .../IO/Socket/SSL.pm:2853: new ctx 93967426517920 DEBUG: .../IO/Socket/SSL.pm:692: socket not yet connected DEBUG: .../IO/Socket/SSL.pm:694: socket connected DEBUG: .../IO/Socket/SSL.pm:717: ssl handshake not started DEBUG: .../IO/Socket/SSL.pm:750: using SNI with hostname xyz.com DEBUG: .../IO/Socket/SSL.pm:806: set socket to non-blocking to enforce + timeout=60 DEBUG: .../IO/Socket/SSL.pm:819: call Net::SSLeay::connect DEBUG: .../IO/Socket/SSL.pm:822: done Net::SSLeay::connect -> -1 DEBUG: .../IO/Socket/SSL.pm:832: ssl handshake in progress DEBUG: .../IO/Socket/SSL.pm:842: waiting for fd to become ready: SSL w +ants a read first DEBUG: .../IO/Socket/SSL.pm:862: socket ready, retrying connect DEBUG: .../IO/Socket/SSL.pm:819: call Net::SSLeay::connect DEBUG: .../IO/Socket/SSL.pm:822: done Net::SSLeay::connect -> -1 DEBUG: .../IO/Socket/SSL.pm:832: ssl handshake in progress DEBUG: .../IO/Socket/SSL.pm:842: waiting for fd to become ready: SSL w +ants a read first DEBUG: .../IO/Socket/SSL.pm:862: socket ready, retrying connect DEBUG: .../IO/Socket/SSL.pm:819: call Net::SSLeay::connect DEBUG: .../IO/Socket/SSL.pm:822: done Net::SSLeay::connect -> -1 DEBUG: .../IO/Socket/SSL.pm:832: ssl handshake in progress DEBUG: .../IO/Socket/SSL.pm:842: waiting for fd to become ready: SSL w +ants a read first DEBUG: .../IO/Socket/SSL.pm:862: socket ready, retrying connect DEBUG: .../IO/Socket/SSL.pm:819: call Net::SSLeay::connect DEBUG: .../IO/Socket/SSL.pm:822: done Net::SSLeay::connect -> -1 DEBUG: .../IO/Socket/SSL.pm:832: ssl handshake in progress DEBUG: .../IO/Socket/SSL.pm:842: waiting for fd to become ready: SSL w +ants a read first DEBUG: .../IO/Socket/SSL.pm:862: socket ready, retrying connect DEBUG: .../IO/Socket/SSL.pm:819: call Net::SSLeay::connect DEBUG: .../IO/Socket/SSL.pm:822: done Net::SSLeay::connect -> 1 DEBUG: .../IO/Socket/SSL.pm:877: ssl handshake done DEBUG: .../IO/Socket/SSL.pm:2875: free ctx 93967426517920 open=9396742 +6517920 DEBUG: .../IO/Socket/SSL.pm:2886: OK free ctx 93967426517920 [download] thanks, bliako	[reply] [d/l] [select]
Re^3: Net::SSLeay::connect -> -1 by haj (Vicar) on Oct 23, 2018 at 22:46 UTC
Does the following log suggest that SSL is set after a lot of failed (-1) attempts but finally the handshake is done? As far as I recall a `-1` isn't a failure. It just indicates that the handshake isn't completed and yet another round of negotiation is required. So the return value `1` just says that the SSH handshake is done, but maybe server and client haven't found a common ground? During the handshake the SSL protocol version / TLS protocol version, the crypto algorithm and its parameters like forward secrecy need to be agreed upon. "Modern" web servers and "modern" LWP should easily find agreeable values, problems arise if an old or unpatched server only supports features which are considered not secure enough by a recent client - or vice versa. With OpenSSL's `s_client` you can dig into the steps of the handshake (expect lots of output): `openssl s_client -connect your.server:443 -debug` [download]	[reply] [d/l]
Re^4: Net::SSLeay::connect -> -1 by bliako (Abbot) on Oct 24, 2018 at 10:37 UTC
Re^5: Net::SSLeay::connect -> -1 by haj (Vicar) on Oct 24, 2018 at 12:38 UTC