[asio-users] handle_connect called before the socket was actually connected

[Nikki Chumakov]

Hi,

I'm using boost-1.49 (also tried boost-1.53b1), RedHat5.8, kernel
2.6.32.26-17.el5, glibc 2.5-81.el5_8.7

Have a strange bug in async tcp client, when handle_connect is called
too early, before the tcp sockets is actually connected.

The trivial async http client example does not demonstrate this problem.

My code is too big to be posted here. It's a framework that utilize
custom invocation handlers, allocators, exception transporting between
threads, boost-log, et cetera, et cetera.

The scenario was trimmed to following conditions:

- just two threads was used: one for io_services::run and other for
creating client requests (objects).

- client opens the connection to http server, and closes after that
(technically it has the "return;" in handle_connect.

- the client requests runs one-by-one in a loop.

The handle_connect is simple:

void
session::handle_connect (const boost::system::error_code& err,
future::promise<void> promise)
{
if (! err)
{
promise.set (); // signal the caller about success
return;
}
else
{
std::cerr << "connect error: " << err.message () << '\n';
abort ();
}
}


Below is the listing of "strace -ff -e network,desc -e \!bind,stat,futex"


normal connect
~~~~~~~~~~~~~~
[pid 25441] socket(PF_INET, SOCK_STREAM, IPPROTO_TCP) = 7

[pid 25442] epoll_wait(5, <unfinished ...>
[pid 25441] epoll_ctl(5, EPOLL_CTL_ADD, 7,
{EPOLLIN|EPOLLPRI|EPOLLOUT|EPOLLERR|EPOLLHUP|EPOLLET, {u32=1811954288,
u64=140515962010224}}) = 0
[pid 25442] <... epoll_wait resumed> {{EPOLLOUT|EPOLLHUP,
{u32=1811954288, u64=140515962010224}}}, 128, 300000) = 1
[pid 25441] ioctl(7, FIONBIO <unfinished ...>
[pid 25442] kill(1, SIG_0 <unfinished ...>
[pid 25441] <... ioctl resumed> , [1]) = 0
[pid 25442] <... kill resumed> ) = -1 EPERM (Operation not permitted)

[pid 25441] connect(7, {sa_family=AF_INET, sin_port=htons(80),
sin_addr=inet_addr("xxx.xxx.193.11")}, 16 <unfinished ...>

[pid 25442] epoll_wait(5, <unfinished ...>
[pid 25441] <... connect resumed> ) = -1 EINPROGRESS (Operation now
in progress)

[pid 25441] epoll_ctl(5, EPOLL_CTL_MOD, 7,
{EPOLLIN|EPOLLPRI|EPOLLOUT|EPOLLERR|EPOLLHUP|EPOLLET, {u32=1811954288,
u64=140515962010224}}) = 0
[pid 25442] <... epoll_wait resumed> {{EPOLLOUT, {u32=1811954288,
u64=140515962010224}}}, 128, 300000) = 1

[pid 25442] kill(1, SIG_0) = -1 EPERM (Operation not permitted)
*********** calling handle_connect
[pid 25442] getsockopt(7, SOL_SOCKET, SO_ERROR, [7782263930402897920],
[4]) = 0
[pid 25442] getpeername(7, {sa_family=AF_INET, sin_port=htons(80),
sin_addr=inet_addr("xxx.xxx.193.11")}, [140514150055952]) = 0
[pid 25442] getsockname(7, {sa_family=AF_INET, sin_port=htons(47210),
sin_addr=inet_addr("xxx.xxx.145.88")}, [140514150055952]) = 0
[pid 25442] setsockopt(7, SOL_SOCKET, SO_KEEPALIVE, [1], 4) = 0
[pid 25442] epoll_wait(5, {}, 128, 0) = 0
[pid 25442] kill(1, SIG_0) = -1 EPERM (Operation not permitted)
[pid 25442] close(7) = 0

early connect
~~~~~~~~~~~~~
[pid 25441] socket(PF_INET, SOCK_STREAM, IPPROTO_TCP) = 9

[pid 25441] epoll_ctl(5, EPOLL_CTL_ADD, 9,
{EPOLLIN|EPOLLPRI|EPOLLOUT|EPOLLERR|EPOLLHUP|EPOLLET, {u32=1811961744,
u64=140515962017680}} <unfinished ...>
[pid 25442] epoll_wait(5, <unfinished ...>
[pid 25441] <... epoll_ctl resumed> ) = 0
[pid 25442] <... epoll_wait resumed> {{EPOLLOUT, {u32=1811958752,
u64=140515962014688}}, {EPOLLIN, {u32=1811943784, u64=140515961999720}},
{EPOLLOUT|EPOLLHUP, {u32=1811961744, u64=140515962017680}}}, 128, 0) = 3
[pid 25441] ioctl(9, FIONBIO <unfinished ...>
[pid 25442] kill(1, SIG_0 <unfinished ...>
[pid 25441] <... ioctl resumed> , [1]) = 0
[pid 25442] <... kill resumed> ) = -1 EPERM (Operation not permitted)

[pid 25441] connect(9, {sa_family=AF_INET, sin_port=htons(80),
sin_addr=inet_addr("xxx.xxx.193.11")}, 16) = -1 EINPROGRESS
(Operation now in progress)
*********** no epoll_wait after connect **********

[pid 25441] epoll_ctl(5, EPOLL_CTL_MOD, 9,
{EPOLLIN|EPOLLPRI|EPOLLOUT|EPOLLERR|EPOLLHUP|EPOLLET, {u32=1811961744,
u64=140515962017680}} <unfinished ...>
[pid 25442] kill(1, SIG_0 <unfinished ...>
[pid 25441] <... epoll_ctl resumed> ) = 0
[pid 25442] <... kill resumed> ) = -1 EPERM (Operation not permitted)
[pid 25442] kill(1, SIG_0) = -1 EPERM (Operation not permitted)

*********** calling handle_connect
[pid 25442] getsockopt(9, SOL_SOCKET, SO_ERROR, [7782250667543887872],
[4]) = 0
[pid 25442] getpeername(9, 0x40450360, [140514150055964]) = -1 ENOTCONN
(Transport endpoint is not connected)
[pid 25442] write(2, "connect error: ", 15connect error: ) = 15
[pid 25442] write(2, "Transport endpoint is not connec"..., 35Transport
endpoint is not connected) = 35
[pid 25442] write(2, "\n", 1
) = 1
[pid 25442] rt_sigprocmask(SIG_UNBLOCK, [ABRT], NULL, 8) = 0
[pid 25442] tgkill(25441, 25442, SIGABRT) = 0
[pid 25442] --- SIGABRT (Aborted) @ 0 (0) ---
Process 25442 detached
+++ killed by SIGABRT +++

I inserted "kill (1, SIG_0)" in asio/detail/impl/epoll_reactor.ipp,
function epoll_reactor::descriptor_state::do_complete, just before
"op->complete(...)" line, to indicate in strace output when the handlers
are going to be called.

So, in abnormal case, asio calls "::connect" and then immediately calls
user handle_connect handler _without_calling_(!!!) (and waiting for)
epoll_wait between ::connect and handle_connect. Thus handle_connect is
called before the socket was actually connected.

Tcpdump packet sniffer shows the normal TCP handshake, just
handle_connected is called before it was completed.

Any ideas of what can be the reason of this bug, what should I check or
debug here?

Regards,
Nikki

[Florian Pflug]

Post by Nikki Chumakov
Have a strange bug in async tcp client, when handle_connect is called
too early, before the tcp sockets is actually connected.

A very similar problems seems to have been observed on cygwin:
http://cygwin.com/ml/cygwin/2011-05/msg00242.html

Though it seems that asio's epoll reactor is careful to only retry an
operation *after* epoll has signalled the file descriptor, unless the
operation explicitly asks for speculative calls by passing true as the
last argument to start_op().

You could try to set a breakpoint in
reactive_socket_connect_op_base::do_perform()

That function should only be called once epoll() has returned, though
it seems that in your case, it's called earlier. Maybe the callstack of
that early invocation sheds some light on this.

best regards,
Florian Pflug

[Nikki Chumakov]

Post by Florian Pflug

Post by Nikki Chumakov
Have a strange bug in async tcp client, when handle_connect is called
too early, before the tcp sockets is actually connected.

http://cygwin.com/ml/cygwin/2011-05/msg00242.html
Though it seems that asio's epoll reactor is careful to only retry an
operation *after* epoll has signalled the file descriptor, unless the
operation explicitly asks for speculative calls by passing true as the
last argument to start_op().
You could try to set a breakpoint in
reactive_socket_connect_op_base::do_perform()
That function should only be called once epoll() has returned, though
it seems that in your case, it's called earlier. Maybe the callstack of
that early invocation sheds some light on this.

Thank you for response.

The reactive_socket_connect_op_base::do_perform backtrace does not show
anything unusual.

The abnormal scenario looks to me as this:

1. main thread calls do_open and adds the socket to epoll queue.

2. service thread calls epoll_wait and it returns several events
INCLUDING that socket.

3. main thread calls async_connect (and modifies the socket in epoll
queue, but it does not matter at this point)

4. service thread processes the events it got form epoll_wait at step #2
in a loop, and when it process that socket, the completion connect
handler is called.

I would think the lock is needed to suspend async_connect (step3) while
service thread processing epoll_wait results (step 2-4).

Regards,
Nikki

[Florian Pflug]

Post by Nikki Chumakov
1. main thread calls do_open and adds the socket to epoll queue.

Hm, wait, why is it setting EPOLLOUT when *opening* the socket? Shouldn't
it set only EPOLLIN? Your strace clearly shows it doing

epoll_ctl(5, EPOLL_CTL_ADD, 7, {EPOLLIN|EPOLLPRI|EPOLLOUT|EPOLLERR|
EPOLLHUP|EPOLLET, {u32=1811954288, u64=140515962010224}}) = 0

and it's doing that *before* the connect(), i.e the call can't come
from start_op().

But epoll_reactor::egister_descriptor() says

ev.events = EPOLLIN | EPOLLERR | EPOLLHUP | EPOLLPRI | EPOLLET;

Post by Nikki Chumakov
2. service thread calls epoll_wait and it returns several events
INCLUDING that socket.
3. main thread calls async_connect (and modifies the socket in epoll
queue, but it does not matter at this point)
4. service thread processes the events it got form epoll_wait at step #2
in a loop, and when it process that socket, the completion connect
handler is called.

Hm, that sounds plausible, except for the EPOLLOUT issue. What version
of asio are you using? I'm looking at the boost version of asio from
boost 1.51.

Post by Nikki Chumakov
I would think the lock is needed to suspend async_connect (step3) while
service thread processing epoll_wait results (step 2-4).

That would make async_connect() occupy a worker thread until all previously
signalled events have been dealt with, though. That seems pretty undesirably.

Also, epoll_wait() currently requests only the next 128 events. If there
are more pending events than that, I think the following would be possible:

1: <add socket to epoll fd>
2: <epoll_wait returns, but nevents too small to include socket>
3: <connect>
4: <epoll_wait returns again, reports socket due to (1), not (3)>
5: <connect wrongly assumes to have completed>

ISTM that the most robust solution would be to make non_blocking_connect
safe even if called early. Maybe the following could work:

ec = getsockopt(SO_ERROR);
if (ec)
return true;
else if (getpeername(socket) == 0)
return true;
else if (errno == ENOTCONN)
return false;
else {
ec = errno;
return true;
}

Another idea would be to deregister the descriptor before doing the
connect(), then reregister afterwards (before doing start_op()). That
should make sure that all previous operations are cancelled, and no
state events remain. I'm not sure whether's it's safe to do that from
async_connect(), though.

best regards,
Florian

[Nikki Chumakov]

Post by Florian Pflug
Hm, wait, why is it setting EPOLLOUT when *opening* the socket? Shouldn't
it set only EPOLLIN? Your strace clearly shows it doing
epoll_ctl(5, EPOLL_CTL_ADD, 7, {EPOLLIN|EPOLLPRI|EPOLLOUT|EPOLLERR|
EPOLLHUP|EPOLLET, {u32=1811954288, u64=140515962010224}}) = 0
and it's doing that *before* the connect(), i.e the call can't come
from start_op().
But epoll_reactor::egister_descriptor() says
ev.events = EPOLLIN | EPOLLERR | EPOLLHUP | EPOLLPRI | EPOLLET;

I am using boost 1.49. It has:

ev.events = EPOLLIN | EPOLLERR | EPOLLHUP | EPOLLOUT | EPOLLPRI | EPOLLET;

Ok, I take epoll_reactor files from boost 1.52 and put in into my
headers. Unfortunately it is not enough, because the EPOLLHUP event is
triggered as well:

[pid 25442] <... epoll_wait resumed> {{EPOLLOUT, {u32=1811958752,
u64=140515962014688}}, {EPOLLIN, {u32=1811943784, u64=140515961999720}},
{EPOLLOUT|EPOLLHUP, {u32=1811961744, u64=140515962017680}}}, 128, 0) = 3

And epoll_reactor::descriptor_state::perform_io() calls the handlers
unconditionally if EPOLLERR or EPOLLHUP was seen.

Then I tried to drop EPOLLHUP from perform_io ():

for (int j = max_ops - 1; j >= 0; --j)
{
if (events & (flag[j] | EPOLLERR)) /* | EPOLLHUP)) */
{
while (reactor_op* op = op_queue_[j].front())
{
if (op->perform())
{
op_queue_[j].pop();
io_cleanup.ops_.push(op);
}
else
break;
}
}
}

And is works! No more early connects.

Although it is completely wrong way, just for testing only, because it
probably breaks socket errors handling.

Regards,
Nikki

[Florian Pflug]

Post by Nikki Chumakov
Ok, I take epoll_reactor files from boost 1.52 and put in into my
headers. Unfortunately it is not enough, because the EPOLLHUP event is
[pid 25442] <... epoll_wait resumed> {{EPOLLOUT, {u32=1811958752,
u64=140515962014688}}, {EPOLLIN, {u32=1811943784, u64=140515961999720}},
{EPOLLOUT|EPOLLHUP, {u32=1811961744, u64=140515962017680}}}, 128, 0) = 3
And epoll_reactor::descriptor_state::perform_io() calls the handlers
unconditionally if EPOLLERR or EPOLLHUP was seen.

Ok, so that approach doesn't lead anywhere…

I've whipped up a quick patch that makes non_blocking_connect()
return false to indicate "retry" unless either SOL_ERROR returns an error
or getpeername returns success.

I googled around a bit, and using getpeername to distinguish between
states in-progress and connected is also suggested here by D. J.
Bernstein (of Qmail and DJB-DNS fame) here:

http://cr.yp.to/docs/connect.html

Which gives me some faith that this approach works cross-platform…

best regards,
Florian Pflug

[Nikki Chumakov]

Post by Nikki Chumakov
Ok, I take epoll_reactor files from boost 1.52 and put in into my
headers. Unfortunately it is not enough, because the EPOLLHUP event is
[pid 25442] <... epoll_wait resumed> {{EPOLLOUT, {u32=1811958752,
u64=140515962014688}}, {EPOLLIN, {u32=1811943784, u64=140515961999720}},
{EPOLLOUT|EPOLLHUP, {u32=1811961744, u64=140515962017680}}}, 128, 0) = 3
And epoll_reactor::descriptor_state::perform_io() calls the handlers
unconditionally if EPOLLERR or EPOLLHUP was seen.

Ok, so that approach doesn't lead anywhere…

What we need is to ignore EPOLLHUP until the socket will be connected.

The patch below works for me.

--- boost_1_53_0_beta1/boost/asio/detail/epoll_reactor.hpp 2012-05-28
14:16:08.000000000 +0400
+++ boost/asio/detail/epoll_reactor.hpp 2013-02-01 17:01:14.000000000 +0400
@@ -62,6 +62,7 @@
int descriptor_;
boost::uint32_t registered_events_;
op_queue<reactor_op> op_queue_[max_ops];
+ bool connected_;
bool shutdown_;

BOOST_ASIO_DECL descriptor_state();

--- boost_1_53_0_beta1/boost/asio/detail/impl/epoll_reactor.ipp
2012-07-16 10:26:30.000000000 +0400
+++ boost/asio/detail/impl/epoll_reactor.ipp 2013-02-01
18:27:15.000000000 +0400
@@ -155,6 +155,7 @@

descriptor_data->reactor_ = this;
descriptor_data->descriptor_ = descriptor;
+ descriptor_data->connected_ = false;
descriptor_data->shutdown_ = false;
}

@@ -180,6 +181,7 @@

descriptor_data->reactor_ = this;
descriptor_data->descriptor_ = descriptor;
+ descriptor_data->connected_ = false;
descriptor_data->shutdown_ = false;
descriptor_data->op_queue_[op_type].push(op);
}
@@ -615,10 +617,13 @@
static const int flag[max_ops] = { EPOLLIN, EPOLLOUT, EPOLLPRI };
for (int j = max_ops - 1; j >= 0; --j)
{
- if (events & (flag[j] | EPOLLERR | EPOLLHUP))
+ if (events & (flag[j] | EPOLLERR | (connected_ ? EPOLLHUP : 0)))
{
while (reactor_op* op = op_queue_[j].front())
{
+ if (j == connect_op)
+ connected_ = true;
+
if (op->perform())
{
op_queue_[j].pop();

Regards,
Nikki

[Marat Abrarov]

Hi, Nikki.

Seems the issue you found isn't related to socket reuse but note that
according to Asio documentation
(http://www.boost.org/doc/libs/1_52_0/doc/html/boost_asio/reference/basic_st
ream_socket/async_connect.html):
~~~~~~~~~~~~~~~~~~~~~~~~~~
basic_stream_socket::async_connect
....
The socket is automatically opened if it is not already open.
(!) If the connect fails, and the socket was automatically opened, the
socket is not returned to the closed state.
~~~~~~~~~~~~~~~~~~~~~~~~~~

May this be the cause of issue?

Regards,
Marat Abrarov.

[Nikki Chumakov]

Post by Marat Abrarov
Seems the issue you found isn't related to socket reuse but note that
according to Asio documentation
(http://www.boost.org/doc/libs/1_52_0/doc/html/boost_asio/reference/basic_st
~~~~~~~~~~~~~~~~~~~~~~~~~~
basic_stream_socket::async_connect
....
The socket is automatically opened if it is not already open.
(!) If the connect fails, and the socket was automatically opened, the
socket is not returned to the closed state.
~~~~~~~~~~~~~~~~~~~~~~~~~~
May this be the cause of issue?

Marat,

I believe the issue is not related to socket reuse at all, but is a
minor bug in epoll_reactor. The question is not about auto-closing or
not closing the socket. It's about: why connect_hanlder is called by
asio before the tcp 3-way handshake completes?

I filled the bug report https://svn.boost.org/trac/boost/ticket/7961 ,
let's see what Christopher will answer.

Regards,
Nikki