Long delay with Crypt::SSLeay and LWP

[waldo22]

I just upgraded to Debian Wheezy from Lenny (long story) and a few of my Perl packages didn't make the upgrade for some reason, among them Crypt::SSLeay (libcrypt-ssleay-perl).

I was unable to connect to my credit card payment gateway (Payflow Pro) using LWP until I installed libcrypt-ssleay-perl, and now it "works", but it takes 15-20 seconds to make the SSL connection due to the very unhelpful error message "error in unknown state":

    SSL_connect:before/connect initialization
    SSL_connect:unknown state
    (waiting 15-20 seconds...) #this comment is from waldo22
    SSL_connect:error in unknown state
    SSL_connect:before/connect initialization
    SSL_connect:SSLv3 write client hello A
    SSL_connect:SSLv3 read server hello A
    SSL_connect:SSLv3 read server certificate A
    SSL_connect:SSLv3 read server done A
    SSL_connect:SSLv3 write client key exchange A
    SSL_connect:SSLv3 write change cipher spec A
    SSL_connect:SSLv3 write finished A
    SSL_connect:SSLv3 flush data
    SSL_connect:SSLv3 read finished A

Here's a pastebin of the console from the actual request/response:

I should note that there was no delay with the previous version of LWP::UA, and that the request is clearly working, but with the unacceptable delay.

I have a feeling this has something to do with LWP changing the default behavior for certificate authorities and server certificiate verification:
lwp SSL validation
and possibly:
certificate verify failed

The PayflowPro Perl module is using Crypt::SSLeay via LWP::useragent.

Current versions of relevant libraries are:

PayflowPro    3101  (just upgraded from 2111, but same results)
libwww-perl              6.04-1
libcrypt-ssleay-perl    0.58-1
liblwp-protocol-https    6.03-1

Obviously 15-20 seconds is way too long to wait to make an SSL connection, but without a more helpful error message, I don't know what to do.

Does anyone have any suggestions on how to better debug this or to get more verbose output?

Thanks a bunch,

-Wes

[Anonymous Monk]

Try Net::SSLeay on for size :)

#!/usr/bin/perl --
use LWP::Simple ;
use IO::Socket::SSL qw(debug3);
get( q{https://pilot-payflowpro.paypal.com/} );
__END__
DEBUG: .../IO/Socket/SSL.pm:1567: new ctx 18240320

DEBUG: .../IO/Socket/SSL.pm:334: socket not yet connected

DEBUG: .../IO/Socket/SSL.pm:336: socket connected

DEBUG: .../IO/Socket/SSL.pm:354: ssl handshake not started

DEBUG: .../IO/Socket/SSL.pm:1555: ok=1 cert=18273264

DEBUG: .../IO/Socket/SSL.pm:1555: ok=1 cert=18997536

DEBUG: .../IO/Socket/SSL.pm:1555: ok=1 cert=18245888

DEBUG: .../IO/Socket/SSL.pm:1170: scheme=www cert=18245888

DEBUG: .../IO/Socket/SSL.pm:1177: identity=pilot-payflowpro.paypal.com
+ cn=pilot-payflowpro.paypal.com alt=2 pilot-payflowpro.paypal.com

DEBUG: .../IO/Socket/SSL.pm:414: Net::SSLeay::connect -> 1

DEBUG: .../IO/Socket/SSL.pm:469: ssl handshake done

DEBUG: .../IO/Socket/SSL.pm:1604: free ctx 18240320 open=18240320

DEBUG: .../IO/Socket/SSL.pm:1609: free ctx 18240320 callback

DEBUG: .../IO/Socket/SSL.pm:1612: OK free ctx 18240320

[waldo22]

Thanks for the tip. That produced slightly more helpful output. Does this mean anything to you?

DEBUG: .../IO/Socket/SSL.pm:196: set domain to 2
DEBUG: .../IO/Socket/SSL.pm:1622: new ctx 33610976
DEBUG: .../IO/Socket/SSL.pm:339: socket not yet connected
DEBUG: .../IO/Socket/SSL.pm:341: socket connected
DEBUG: .../IO/Socket/SSL.pm:359: ssl handshake not started
(long pause again - at least 30 sec.)
DEBUG: .../IO/Socket/SSL.pm:422: Net::SSLeay::connect -> -1
DEBUG: .../IO/Socket/SSL.pm:1299: SSL connect attempt failed with unkn
+own error error:00000000:lib(0):func(0):reason(0)

DEBUG: .../IO/Socket/SSL.pm:428: fatal SSL error: SSL connect attempt 
+failed with unknown error error:00000000:lib(0):func(0):reason(0)
DEBUG: .../IO/Socket/SSL.pm:1299: IO::Socket::INET6 configuration fail
+ed error:00000000:lib(0):func(0):reason(0)

DEBUG: .../IO/Socket/SSL.pm:1659: free ctx 33610976 open=33610976
DEBUG: .../IO/Socket/SSL.pm:1667: OK free ctx 33610976

[Anonymous Monk]

Does this mean anything to you?

:) Not particularly, though it hints to me the problem likely isn't perl specific -- you can probably confirm this hunch by running openssl ... see Debugging SSL communications

[Anonymous Monk]

It definitely sounds like a timeout. One party or the other is probably requesting some verification from someone else and timing-out. What you want to determine is why it thinks it needs to ask somebody "else," knowing as you do that it should not think it needs to.

[waldo22]

Well, perhaps this wasn't a Perl problem, but there's a Perl solution (of course!)

There appears to be a problem with OpenSSL 1.0.1 where attempting to autonegotiate with TLS1.1 (or 1.2???) with some servers causes those servers to drop the connection and reject the request. See:

https://bugs.launchpad.net/ubuntu/+source/openssl/+bug/965371
http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=665452

According to the bug ticket, they say it is "fixed" for Paypal in Debian OpenSSL 1.0.1b, but I'm running 1.0.1c-3 and still experience the problem. I don't know if that means it's fixed for www.paypal.com but not payflowpro.paypal.com, or what.

SOLUTION: Setting $ENV{HTTPS_VERSION} = 3; to force SSL3 seems to fix the problem, at least for Crypt::SSLeay.

Presumably this works because it does not attempt to negotiate TLS1.1, and just uses SSL3.

Testing with openssl s_client, it works with the options -ssl3, -tls1, and -no_tls1, so it must be a negotiation problem, in my opinion.

Anyway, that's a workaround, at least.

Different problem, but same solution: http://www.perlmonks.org/?node_id=746493

-Wes

[wrog]

So I'm going to reply to this (after an appropriately long delay :-), because I just upgraded to wheezy and am having the same problem and search turned this up.

I really hate bashing %ENV to communicate between different parts of Perl. As a general rule of thumb, if you're trying to communicate intra-process, there's nearly always a better way than messing with %ENV.

Also it looks like IO::Socket::SSL is preferred over Net::SSL/Crypt::SSLeay these days. In my original version of this post there was some question of whether the latter is even being maintained and can actually do certificate verification, but apparently it is and can. I got confused because Crypt::SSLeay evidently can't do hostname verification which is a distinct issue (though arguably still an issue). There's also a comment in the Crypt::SSLeay pod to the effect that that module only exists to https-enable LWP::UserAgent whereas IO::Socket::SSL is a more general-purpose package.

I could be wrong about all this, but in any case if you want to be able to explicitly control what you're using, which, unfortunately, you have to in order to be able to specify SSL options to LWP::UserAgent, here's my code:

# Make sure LWP::UserAgent uses the right kind of socket
use IO::Socket::SSL;
$NET::HTTPS::SSL_SOCKET_CLASS = 'IO::Socket::SSL';
use LWP::UserAgent;

# some servers immediately go radio-silent
# if you try SSL versions < 3
our %ssl_options = (SSL_version => 'SSLv3');

...
$ua = LWP::UserAgent->new(ssl_opts => \%ssl_options),

((Update (11/5/2014): leave SSL_version alone; see comment below))

The NET::HTTPS line is for the case where LWP::UserAgent has already been loaded, already chose the wrong default socket implementation because of what was in place when LWP::UserAgent was loaded the first time, and you need to undo that.

I suppose if you badly need to play nice with other packages that explicitly depend on Net::SSL being used, there's also

{
  local $NET::HTTPS::SSL_SOCKET_CLASS = 'IO::Socket::SSL';
  $ua = LWP::UserAgent->new(ssl_opts => \%ssl_options),
}

so that only your own invocations of LWP::UserAgent are affected (though there's an argument that could be made that it's the Net::SSL users that should be doing this instead).

[Anonymous Monk]

Thank you very much. That was my problem. Forcing to v3 worked.