UserAgent; SSL connect attempt failed because of handshake problems; Inactivity timeout

[Tim]

Hi,

in the following setup I get an inactivity timeout after 5 min without render. But I am expecting the timeout in $tx->error after 30 sec.

How can I fix this?

Thanks

$c->inactivity_timeout(300);
$ua->connect_timeout(15)->inactivity_timeout(30);
$c->delay(
    sub {
        $ua->get($url, shift->delay);
    },
    sub {
        my ($delay, $tx) = @_;
        
        $c->render(json => {
            url => $tx->req->url->to_string,
            err => $tx->error,
        });
    }
);

 

[error] SSL connect attempt failed because of handshake problems
[debug] Inactivity timeout.

[Jan Henning Thorsen]

Your code is incomplete, so I need to make a guess: Are you constructing $ua inside that action/sub/function? If so, is it going out of scope?

Try running with MOJO_USERAGENT_DEBUG=1 and see if you get any response from the server at all. Maybe you need to do

  $c->stash(my_ua => $ua);

[Tim]

nope. It is the controller ua.

my $ua = $c->app->ua;

I think the SSL error prevents the ua from invoking the callback.

[sri]

I think the SSL error prevents the ua from invoking the callback.

I dount that, and i'm unable to replicate your problem.

--

sebastian

[Tim]

Here is a debug output of an example where ua will NEVER complete the request (say dumper($tx) is never executed)

(https with port 80 is only there to produce the error)

my $ua = Mojo::UserAgent->new;

$ua->proxy->http("http://$proxy")->https("http://$proxy");

my $tx = $ua->get('https://HOST:80/');

say dumper($tx);

-- Blocking request (https://HOST:80/)

-- Connect (https:HOST:80)

-- Client >>> Server (https://HOST:80/)

CONNECT HOST:80 HTTP/1.1

User-Agent: Mojolicious (Perl)

Connection: keep-alive

Accept-Encoding: gzip

Content-Length: 0

Host: HOST:80

-- Client <<< Server (https://HOST:80/)

HTTP/1.0 200 Connection established

Mojo::Reactor::EV: Read failed: Mojo::UserAgent: SSL connect attempt failed because of handshake problems

[sri]

Here is a debug output of an example where ua will NEVER complete the request (say dumper($tx) is never executed)

This turned out to be a little more complicated than expected, but i believe i found the problem.

    https://github.com/kraih/mojo/commit/5c958f2efe94fa0afa3090b01026c8e07ec2d427

Getting it covered by unit tests will be quite a bit harder though. :/

--

sebastian 

[Tim]

Thanks again for the fast fix :)

I will test it soon.

[Tim]

Your fix worked for me, thanks.

But I got another error:

Mojo::Reactor::Poll: Timer a8665afb344a7d4e85fa162c15e77c77 failed: Mojo::UserAgent: Event "timeout" failed: Can't call method "steal_handle" on an undefined value at /usr/local/share/perl/5.14.2/Mojo/UserAgent.pm line 155

[sri]

But I got another error:

Mojo::Reactor::Poll: Timer a8665afb344a7d4e85fa162c15e77c77 failed: Mojo::UserAgent: Event "timeout" failed: Can't call method "steal_handle" on an undefined value at /usr/local/share/perl/5.14.2/Mojo/UserAgent.pm line 155

Well, you know what to do now. ;)

--

sebastian 

[Tim]

Unfortunately I can't give an example or more debug information, because this error occurs only very rarely.

[Tim]

I encountered another strange thing.

I got the error message "SSL connect attempt failed\n" (with the line break) in $tx->error after 1041 seconds although connect_timeout was set to 15 seconds and inactivity_timeout was set to 30 seconds.

I used the same code posted before.

[Tim]

Here is a debug output for this error

Mojo::Reactor::Poll: Timer 8c95563d3ebc122fe9c49b346f16a653 failed: Mojo::UserAgent: Event "timeout" failed: Can't call method "steal_handle" on an undefined value at /usr/local/share/perl/5.14.2/Mojo/UserAgent.pm line 155.

-- Blocking request (https://HOST/)
-- Connect (https:HOST:443)
-- Client >>> Server (https://HOST/)
CONNECT HOST:443 HTTP/1.1

User-Agent: Mojolicious (Perl)
Connection: keep-alive
Accept-Encoding: gzip
Content-Length: 0
Host: HOST

-- Client <<< Server (https://HOST/)
HTTP/1.1 200 OK
Date: Mon, 11 Aug 2014 07:16:24 GMT
Server: Apache/2.2.8 (Win32) PHP/5.2.6
X-Powered-By: PHP/5.2.6
Keep-Alive: timeout=5, max=100
Connection: Keep-Alive
Transfer-Encoding: chunked
Content-Type: text/html
2077
<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN"
"http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd">
<html xmlns="http://www.w3.org/1999/xhtml">

 

<some more html>

 

Mojo::Reactor::EV: Timer 46532da0bf10681d0a1ae8eb98fa1a62 failed: Mojo::UserAgent: Event "timeout" failed: Can't call method "steal_handle" on an undefined value at /Library/Perl/5.16/Mojo/UserAgent.pm line 155, <DATA> line 1.

[sri]

Here is a debug output for this error

Mojo::Reactor::Poll: Timer 8c95563d3ebc122fe9c49b346f16a653 failed: Mojo::UserAgent: Event "timeout" failed: Can't call method "steal_handle" on an undefined value at /usr/local/share/perl/5.14.2/Mojo/UserAgent.pm line 155.

You have to give us something we can replicate, and it appears you're not even using the latest version of Mojolicious, since that line number is wrong. The first rule of reporting issues, always try the latest version!

--

sebastian

[Tim]

I updated to the lastest version. The "steal_handle" error is gone.

But there is definitely somewhere another bug in the latest version which causes the ua to freeze indefinitely.

The only thing I can say is that is has to do with proxy over HTTPS and maybe chunked transfer encoding.

Mostly some of the response HTML is received and then the ua aborts with an error (Proxy connection failed / SSL connection attempt failed). This is ok.

But sometimes the request never completes.

[Tekki]

Don't know if this is related to your problem, but did you update IO::Socket::SSL too?

Am Dienstag, 12. August 2014 18:15:25 UTC+2 schrieb Tim:

I updated to the lastest version. The "steal_handle" error is gone.

But ...

 

[Tim]

Yes.

Mojolicious is up to date. (5.28)

IO::Socket::SSL is up to date. (1.997)

Net::SSLeay is up to date. (1.65)

Here is another example where Mojo::UserAgent never returns (I was expecting an inactivity timeout or a SSL error):

-- Blocking request (https://HOST)

-- Connect (https:HOST:443)

-- Client >>> Server (https://HOST)

CONNECT HOST:443 HTTP/1.1

User-Agent: Mojolicious (Perl)

Connection: keep-alive

Accept-Encoding: gzip

Content-Length: 0

Host: HOST

-- Client <<< Server (https://HOST)

HTTP/1.0 200 Connection established

Proxy-agent: CCProxy 6.64

[sri]

Here is another example where Mojo::UserAgent never returns (I was expecting an inactivity timeout or a SSL error):

-- Blocking request (https://HOST)

-- Connect (https:HOST:443)

-- Client >>> Server (https://HOST)

CONNECT HOST:443 HTTP/1.1

User-Agent: Mojolicious (Perl)

Connection: keep-alive

Accept-Encoding: gzip

Content-Length: 0

Host: HOST

-- Client <<< Server (https://HOST)

HTTP/1.0 200 Connection established

Proxy-agent: CCProxy 6.64

This exact case is tested...

    https://github.com/kraih/mojo/blob/master/t/mojo/websocket_proxy.t#L51

--

sebastian 

[Tim]

I have made tcp dumps of two hanging requests: http://pastebin.com/s03HVipg

Maybe you can build a test case with malformed SSL responses?

[sri]

Maybe you can build a test case with malformed SSL responses?

Such a test case already exists.

    https://github.com/kraih/mojo/blob/master/t/mojo/websocket_proxy_tls.t#L292

You will have to make a new one.

--

sebastian

[Tim]

I have just built a simple test script.

Maybe you have to run this script several times and you will notice that it hangs forever at some point.

#!/usr/bin/perl


use strict;
use warnings;
use feature 'say';


use Mojo::UserAgent;
use Mojo::Util 'steady_time';


while(<DATA>) {
    chomp;
    next unless length;
    my $p = "http://$_";
    say $p;

    my $ua = Mojo::UserAgent->new;

    $ua->proxy->http($p)->https($p);
    my $t = steady_time;
    my $tx = $ua->get('https://www.google.com');
    $t = sprintf('%.3fs', steady_time - $t);
    if($tx->success) {
        say "ok: ", $tx->res->code;
    } else {
        say "fail: ", ($tx->error->{message} // '-');
    }
    say "time: $t\n";
}


__DATA__
190.102.28.40:80
61.150.76.205:808
60.251.152.85:80
218.92.227.165:17945
183.223.29.120:8123
163.125.207.112:9999

[sri]

I have just built a simple test script.

And i've already been able to track it down. :) Turns out it's not actually a real bug, the socket was just sitting there idle in the reactor without any activity, and we never applied a timeout for TLS upgrades. This little change should take care of it.

    https://github.com/kraih/mojo/commit/63ed603b29482da39934ba6bd78d3dee4adf4fff

--

sebastian

[Tim]

Very nice, thanks sebastian! ;)