[Libevent-users] One out of 10 ssl connections stalling.

[Tommy van Leeuwen <chiparus@xxxxxxxxx>]

Hello everyone.

I have a case where one out of 10 or so SSL connections are not
correctly negotiating it seems.

I use the ssl echo server from
http://www.wangafu.net/~nickm/libevent-book/Ref6a_advanced_bufferevents.html
to test it and this little perl script to setup a connection and dump
certificate details and send a little test string.

#!/usr/bin/perl -w
use warnings;
use strict;
use IO::Socket::SSL;
my $host = $ARGV[0];
die "Usage: $0 hostname:port\n" if ( ! defined $host );
my $client = IO::Socket::SSL->new($host)
    || die "Can't connect: ".IO::Socket::SSL::errstr(). " ($!)\n";
print $client->get_cipher() ."\n";
print $client->dump_peer_certificate();
$client->printf("TEST\r\n");
print $client->getline();

This works well most of the time, but sometimes hangs at attempting a
connection (hangs in IO::Socket::SSL::new).

This is a strace from a connection which is stalling: (just stripped
some long lines)

170 accept(6, {sa_family=AF_INET, sin_port=htons(52427),
sin_addr=inet_addr("81.56.122.150")}, [16]) = 7^M
171 fcntl(7, F_GETFL)                       = 0x2 (flags O_RDWR)^M
172 fcntl(7, F_SETFL, O_RDWR|O_NONBLOCK)    = 0^M
173 epoll_ctl(3, EPOLL_CTL_ADD, 7, {EPOLLIN, {u32=7, u64=7}}) = 0^M
174 epoll_ctl(3, EPOLL_CTL_MOD, 7, {EPOLLIN|EPOLLOUT, {u32=7, u64=7}}) = 0^M
175 fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 3), ...}) = 0^M
176 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS,
-1, 0) = 0x7f97ec79e000^M
177 write(1, "New connection accepted..\n", 26New connection accepted..^M
178 ) = 26^M
179 accept(6, 0x7fff93320bd0, [128])        = -1 EAGAIN (Resource
temporarily unavailable)^M
180 epoll_wait(3, {{EPOLLIN|EPOLLOUT, {u32=7, u64=7}}}, 32, 4294967295) = 1^M
181 brk(0x953000)                           = 0x953000^M
182 read(7, "\200g\1\3\1\0N\0\0\0\20", 11)  = 11^M
183 read(7, "\0\0009\0\0008\0\377Y\204\353\214\t\37{9UI\203\30\322\4f\37",
94)     = 94^M
184 write(7, "..lots of ssl stuff stripped from strace..Domain Control
Validated - RapidSSL(R)1\0330\31\6\3U\244\267[v\25j\241\0070"...,
1353) = 1353^M
185 read(7, 0x9324b3, 5)                    = -1 EAGAIN (Resource
temporarily unavailable)^M
186 epoll_ctl(3, EPOLL_CTL_MOD, 7, {EPOLLIN, {u32=7, u64=7}}) = 0^M
187 epoll_wait(3,

Now basically the echo server hangs here in epoll_wait. It never
(retries?) the above read from line 185 and the client is waiting here
from response from the server.

During a working connection, things look a bit different:

184 read(7, 0x16b04b3, 5)                   = -1 EAGAIN (Resource
temporarily unavailable)^M
185 epoll_ctl(3, EPOLL_CTL_MOD, 7, {EPOLLIN, {u32=7, u64=7}}) = 0^M
186 epoll_wait(3, {{EPOLLIN, {u32=7, u64=7}}}, 32, 4294967295) = 1^M
187 read(7, "\26\3\1\1\6", 5)               = 5^M
188 read(7, "\20\0\1\2\1\0\17\255 very long data stripped
cS\2P\346p\316\240\216", 262) = 262^M
189 read(7, "\24\3\1\0\1", 5)               = 5^M
190 read(7, "\1", 1)                        = 1^M
191 read(7, "\26\3\1\0000", 5)              = 5^M
Reading normal conversation here..

Anyone knows what's going on here? I've discovered this on a nntp
server of ours where i have no control over all the different clients
used to connect.

I also have a good reproduction since 1 out of 10 or so connections are failing.

Any pointers to how (and where) to debug this further are appreciated.

Thanks for any insights!
Tommy
***********************************************************************
To unsubscribe, send an e-mail to majordomo@xxxxxxxxxxxxx with
unsubscribe libevent-users    in the body.