You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@tomcat.apache.org by bu...@apache.org on 2018/10/03 13:26:38 UTC
[Bug 62799] New: mod_jk doesn't handle the EINPROGRESS state
appropriately for non-blocking sockets.
https://bz.apache.org/bugzilla/show_bug.cgi?id=62799
Bug ID: 62799
Summary: mod_jk doesn't handle the EINPROGRESS state
appropriately for non-blocking sockets.
Product: Tomcat Connectors
Version: 1.2.42
Hardware: All
OS: Linux
Status: NEW
Severity: major
Priority: P2
Component: mod_jk
Assignee: dev@tomcat.apache.org
Reporter: mark@blackmans.org
Target Milestone: ---
We can see that when we use non-blocking sockets as result of the event MPM in
Apache 2.4, a value of 5 seconds for the connect_socket_timeout results in
connection errors due to EINPROGRESS (115) errors like so:
[Mon Sep 24 10:58:25.282 2018] [3334428:140116430018304] [info]
jk_open_socket::jk_connect.c (817): connect to 10.212.32.20:10153 failed
(errno=115)
[Mon Sep 24 10:58:25.283 2018] [3334428:140116430018304] [info]
ajp_connect_to_endpoint::jk_ajp_common.c (1068): (dw15716_rtc_0) Failed opening
socket to (10.212.32.20:10153) (errno=115)
[Mon Sep 24 10:58:25.283 2018] [3334428:140116430018304] [error]
ajp_send_request::jk_ajp_common.c (1728): (dw15716_rtc_0) connecting to backend
failed. Tomcat is probably not started or is listening on the wrong port
(errno=115)
[Mon Sep 24 10:58:25.283 2018] [3334428:140116430018304] [info]
ajp_service::jk_ajp_common.c (2778): (dw15716_rtc_0) sending request to tomcat
failed (recoverable), because of error during request sending (attempt=3)
EINPROGRESS should not be a failing error state. I assume values other than 5
seconds would have the same outcome.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 62799] mod_jk doesn't handle the EINPROGRESS state
appropriately for non-blocking sockets.
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=62799
--- Comment #1 from Rainer Jung <ra...@kippdata.de> ---
Hi Mark,
just to make sure: did you notice that the unit of socket_connect_timeout is
milliseconds, so did you set it to 5000?
In version 1.2.44 it switched to seconds due to a regression which will be
fixed in the forthcoming 1.2.46, switching back to milliseconds.
Furthermore: which platform is this? And do you have a socket_timeout
configured in addition (not recommending it, just asking)?
I do not directly see any relevance of the event MPM here. The connection in
question is the backend connection completely controlled by mod_jk.
Furthermore, EINPROGRESS is already handled in the code. There might be a
problem in that handling, but I don't immediately see it.
If you can easily reproduce it, it would be interesting to see, where in the
following block of code we actually leave nb_connect() in common/jk_connect.c:
284 if ((rc == -1) && (errno == EINPROGRESS || errno == EALREADY)
285 && (timeout > 0)) {
Do we get in here and what is the value of errno?
286 fd_set wfdset;
287 struct timeval tv;
288 socklen_t rclen = (socklen_t)sizeof(rc);
289
290 FD_ZERO(&wfdset);
291 FD_SET(sd, &wfdset);
292 tv.tv_sec = timeout / 1000;
293 tv.tv_usec = (timeout % 1000) * 1000;
294 rc = select(sd + 1, NULL, &wfdset, NULL, &tv);
295 if (rc <= 0) {
Do we get in here and what is the value of errno?
296 /* Save errno */
297 int err = errno;
298 soblock(sd);
299 errno = err;
300 JK_TRACE_EXIT(l);
301 return -1;
302 }
303 rc = 0;
304 #ifdef SO_ERROR
Do we get in here?
305 if (!FD_ISSET(sd, &wfdset) ||
306 (getsockopt(sd, SOL_SOCKET, SO_ERROR,
307 (char *)&rc, &rclen) < 0) || rc) {
Do we get in here and due to which of the three conditions?
308 if (rc)
309 errno = rc;
310 rc = -1;
311 }
312 #endif /* SO_ERROR */
313 }
314 /* Not sure we can be already connected */
315 if (rc == -1 && errno == EISCONN)
316 rc = 0;
Do we get up until here and what is the value of errno?
317 soblock(sd);
What is the value of errno here?
318 JK_TRACE_EXIT(l);
319 return rc;
As an alternative: in 1.2.44 that part of the code was changed on platforms
that support poll, using poll instead of select there. 1.2.46 is not yet
released, but you can grab it for your tests from
https://dist.apache.org/repos/dist/dev/tomcat/tomcat-connectors/jk/
Regards,
Rainer
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 62799] mod_jk doesn't handle the EINPROGRESS state
appropriately for non-blocking sockets.
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=62799
--- Comment #5 from Rainer Jung <ra...@kippdata.de> ---
Hi Mark,
(In reply to mark from comment #4)
> I know for a fact the connection is taking longer than 5 second to become
> established, because the backend is turned off. We're testing how mod_jk +
> Apache 2.4 handle the case where the backend becomes completely unavailable.
OK, so the fact that mod_jk terminates the connection setup after 5 seconds
just works as expected. The admin has configured it and mod_jk reacts as
configured.
Note that even if a backend service is down, a connection setup to it often
fails quickly: if the node is reachable but no service is bound to the given
port (eg. process crash) and also if the node is not reachable at all due to
orderly shutdown.
The typical cases for slow connection setup are either packet drop due to some
overloaded network component or bad cabling, or if you cut or unplug a cable,
or if a machine stops in an abnormal way (power outage etc.). Then the last
network hop that's reachable on the way to the backend still has the next MAC
address in its table and thinks the next hop is reachable. It takes some time
before the MAC gets out of the table and the component can immediately return
with a "not reachable". When a backend interface is shutdown normally, it
signals the other side, so that the MAC address gets immediately removed.
> My point, which seems might not be clear yet, is that EINPROGRESS should
> never be a connection failure while a socket is still in progress, because,
> by definition, it has *NOT YET* timed out.
EINPROGRESS is a system level errno indicating the socket status. From the
point of view of the system, the connect is still in progress. Is has not timed
out in the operating system. Since the admin has configured mod_jk to not wait
any longer, the connect has timed out in mod_jk, so mod_jk stops connection
setup and reports the mod_jk timeout as a mod_jk error. The errno 115 is just
an additional detail info. That info is helpful here, because it shows us that
the socket connect had not yet finished with error or success, when the mod_jk
timeout fired.
> The socket state should change from EINPROGRESS to something else after the
> timeout expires, to indicate connection failure. EINPROGRESS should never
> never be the cause of connection failure, ever, in my opinion.
I think we can not set the internal OS socket state. What is documented is,
that we should close the socket for clean up. That's what we actually do.
EINPROGRESS is not the cause of the connection failure. The cause is the
application software (mod_jk) timeout the admin has explicitly configured.
After the timeout the socket connect is in state EINPROGRESS, so it has not
completed so it failed to complete faster than the configured timeout. That's
an error from the point of view of mod_jk.
So what do you suggest should happen instead?
If you do not want an error, increase the connect timeout and accept to wait
and hang longer if connects are slow. Or do you suggest a different way of
logging? Or do you want a connection setup timeout in mod_jk to not get handled
as an error? What else should it be?
Regards,
Rainer
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 62799] mod_jk doesn't handle the EINPROGRESS state
appropriately for non-blocking sockets.
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=62799
--- Comment #2 from mark@blackmans.org ---
Yes, it was set to 5000 milliseconds (i.e. 5 seconds).
Well, we don't see this behaviour in Apache 2.2 with the prefork MPM and we do
see it with Apache 2.4 in the event MPM. However, I can imagine that might not
be important.
There's a redhat article,
https://access.redhat.com/solutions/1229213
which specifically recommends not setting the timeouts due to non-blocking
sockets. We are using 1.2.42, so we haven't been hit by that 1.2.44 bug of
course.
I cannot reproduce the issue outside of a production environment at the moment.
If EINPROGRESS is handled, why is it associated with a connection failure? I
believe 115 should never be the cause of a connection failure.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 62799] mod_jk doesn't handle the EINPROGRESS state
appropriately for non-blocking sockets.
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=62799
mark@blackmans.org changed:
What |Removed |Added
----------------------------------------------------------------------------
Status|NEW |RESOLVED
Resolution|--- |LATER
--- Comment #10 from mark@blackmans.org ---
this did get rolled out to the prod environment, but the reporting user has
moved to mod_proxy_ajp and I have no had time to run my own tests, but I would
say this is a weakly positive improvement. I would like to test this sometime,
but not sure when I can. I'll reopen if I find any negative feedback.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 62799] mod_jk doesn't handle the EINPROGRESS state
appropriately for non-blocking sockets.
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=62799
--- Comment #3 from Rainer Jung <ra...@kippdata.de> ---
I assume you are on RHEL 6 or 7?
The Red Hat article unfortunately doesn't state, which version of mod_jk it is
for. The man pages for connect() tells us:
=== Cite ===
EINPROGRESS
The socket is nonblocking and the connection cannot be
completed immediately. It is possible to select(2) or poll(2) for completion
by selecting the socket for writing. After select(2) indicates writability,
use getsockopt(2) to read the SO_ERROR option at level SOL_SOCKET to determine
whether connect() completed successfully (SO_ERROR is zero) or
unsuccessfully (SO_ERROR is one of the usual error codes listed here,
explaining the reason for the failure).
=== Cite ===
In our case the socket is non-blocking, because mod_jk puts the fresh socket
into non-blocking mode. After connect() it does call select() and uses
getsockopt() to check, whether connect completed successfully. I did a test
compilation on RHEL 6 and RHEL 7 and verified that SO_ERROR is defined, so that
code is executed.
I can think of the following situations:
a) select is documented to behave undefined, if the number of file descriptors
goes above FD_SETSIZE, which on Linux is 1024. So it could be that it might
return immediately without signalling an error.
b) the clock jumping and letting select return much quicker than after 5
seconds with the connection not yet set up
c) the connection taking longer than 5 seconds to get established
To rule out a), you could try using version 1.2.44 but configure the connection
setup timeout to "5" instead of "5000" due to the bug handling the config value
in that specific version. Or you use the likely to get released soon version
1.2.46. These versions use poll() on RHEL which does not have the 1024 file
descriptor limitations. There's no way around the select limitation using
limits. It is a hard implementation limit of select on Linux.
Regards,
Rainer
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 62799] mod_jk doesn't handle the EINPROGRESS state
appropriately for non-blocking sockets.
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=62799
--- Comment #4 from mark@blackmans.org ---
I know for a fact the connection is taking longer than 5 second to become
established, because the backend is turned off. We're testing how mod_jk +
Apache 2.4 handle the case where the backend becomes completely unavailable.
My point, which seems might not be clear yet, is that EINPROGRESS should never
be a connection failure while a socket is still in progress, because, by
definition, it has *NOT YET* timed out.
The socket state should change from EINPROGRESS to something else after the
timeout expires, to indicate connection failure. EINPROGRESS should never never
be the cause of connection failure, ever, in my opinion.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 62799] mod_jk doesn't handle the EINPROGRESS state
appropriately for non-blocking sockets.
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=62799
--- Comment #6 from mark@blackmans.org ---
(In reply to Rainer Jung from comment #5)
> Hi Mark,
>
> (In reply to mark from comment #4)
> > I know for a fact the connection is taking longer than 5 second to become
> > established, because the backend is turned off. We're testing how mod_jk +
> > Apache 2.4 handle the case where the backend becomes completely unavailable.
>
> OK, so the fact that mod_jk terminates the connection setup after 5 seconds
> just works as expected. The admin has configured it and mod_jk reacts as
> configured.
Thanks.
Unfortunately, I am still not making myself clear and I think it's because I am
referring to two different two different scenarios. For the particular log
messages above, the connection is showing failed due to EINPROGRESS long before
the 5 second expiry, usually within milliseconds.
I have two goals, both of which are admirably satisifed by mod_jk 1.2.42 and
Apache 2.2, but failing miserably with mod_jk 1.2.42 and Apache 2.4
What I want:
1. Backend connection failures should be caught by a timeout, probably
socket_connect_timeout
2. incomplete connections before the timeout expiry should never be flagged as
failures.
What I observe:
If I set a socket_connect_timeout of 5000 milliseconds, loads of perfectly good
backends are getting failed due to EINPROGRESS DESPITE the timeout not yet
expiring.
If I don't set a socket_connect_timeout at all (i.e. no timeout at all), then
the request hangs indefinitely when the backend is missing.
In other words, I have found no configuration that satifies goals 1 and 2
simultaneously, primarily, I believe, because the current code is treating
EINPROGRESS as a failure way before the timeout expires.
I can accept my interpretation of the underlying behaviours is wrong, but the
fact is that mod_jk is marking backends down that are not down.
I am open to suggestion on how I can demonstrate this behaviour more clearly
that are achievable outside of our production environments.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 62799] mod_jk doesn't handle the EINPROGRESS state
appropriately for non-blocking sockets.
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=62799
--- Comment #8 from mark@blackmans.org ---
(In reply to Rainer Jung from comment #7)
> > For the particular
> > log messages above, the connection is showing failed due to EINPROGRESS long
> > before the 5 second expiry, usually within milliseconds.
>
> OK, here I suggest to check using 1.2.44 (and switching temporarily to the
> value 5 due to the "seconds instead of milliseconds" bug in 1.2.44) or
> 1.2.46 pre-release and recheck. It could well be that the poll() system call
> used there for RHEL is more reliable due to the known limitations of
> select() on Linux.
Thanks, that's a clear path to test.
> > What I want:
> >
> > 1. Backend connection failures should be caught by a timeout, probably
> > socket_connect_timeout
>
> For clarity: socket_connect_timeout is not a generic connection timeout, it
> is instead a timeout for socket connect, that means only for the process of
> setting up a new connection (connect() system call). That's what it is meant
> for, nothing else.
That is absolutely perfect, that is 100% the desired case I want to handle
correctly. Any backend that we cannot set up a new connection to, should be
considered failed, but only after the timeout has expired.
>
> If you need to tackle more types of "connection failures", there's probably
> other features handling them, but not socket_connect_timeout.
For all post-new-connection cases, I am expecting to rely on the full suite of
CPING/CPONG tests and I am hopeful for these cases.
>
> > 2. incomplete connections before the timeout expiry should never be flagged
> > as failures.
>
> Agreed but as I wrote before, this could happen due to the select()
> limitation in 1.2.42 (not sure but could be), or time jumping forward
I will lean towards 'select' letting us down rather than time jumping forward
for now.
>
> > What I observe:
> >
> > If I set a socket_connect_timeout of 5000 milliseconds, loads of perfectly
> > good backends are getting failed due to EINPROGRESS DESPITE the timeout not
> > yet expiring.
>
> How do you know that "the timeout" is "not expiring"?
I can see the initial connection attempt at time t0 and i can see failure
notifications at time t0+delta where delta is much less than 5 seconds.
>
> > If I don't set a socket_connect_timeout at all (i.e. no timeout at all),
> > then the request hangs indefinitely when the backend is missing.
>
> More precisely *setup of new connections* will hang (if the network doesn't
> respond with a no route to host or similar).
>
> > In other words, I have found no configuration that satifies goals 1 and 2
> > simultaneously, primarily, I believe, because the current code is treating
> > EINPROGRESS as a failure way before the timeout expires.
>
> As I tried to explain several times now: the current code handles EINPROGRES
> as a normal return value and after EINPROGRESS waits for the timeout to
> happen and then checks the socket status again. We might have done this
> wrong, but it is not as obvious as you think.
Ok, great, perhaps under some circumstances that handling is thwarted by other
effects, like a dodgy 'select'. I do find the code a little hard to follow,
but I completely agree that on the face of it, it should not be failing the
connection because of EINPROGRESS.
>
> > I can accept my interpretation of the underlying behaviours is wrong, but
> > the fact is that mod_jk is marking backends down that are not down.
> >
> > I am open to suggestion on how I can demonstrate this behaviour more clearly
> > that are achievable outside of our production environments.
>
> We could add some lines to the code which track the connection setup in
> mod_jk and log the details only if the setup fails due to
> socket_connect_timeout. But before doing this I would be interested in the
> behavior of recent code (1.2.44 with config "5" or 1.2.46 pre-release).
Sounds like a plan, thank you.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 62799] mod_jk doesn't handle the EINPROGRESS state
appropriately for non-blocking sockets.
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=62799
--- Comment #9 from mark@blackmans.org ---
We'll wait for the formal release of 1.2.46 to test that using poll instead of
select avoids the issue as we only observe the problem in production
environments.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 62799] mod_jk doesn't handle the EINPROGRESS state
appropriately for non-blocking sockets.
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=62799
--- Comment #7 from Rainer Jung <ra...@kippdata.de> ---
(In reply to mark from comment #6)
> (In reply to Rainer Jung from comment #5)
> > Hi Mark,
> >
> > (In reply to mark from comment #4)
> > > I know for a fact the connection is taking longer than 5 second to become
> > > established, because the backend is turned off. We're testing how mod_jk +
> > > Apache 2.4 handle the case where the backend becomes completely unavailable.
> >
> > OK, so the fact that mod_jk terminates the connection setup after 5 seconds
> > just works as expected. The admin has configured it and mod_jk reacts as
> > configured.
>
> Thanks.
>
> Unfortunately, I am still not making myself clear and I think it's because I
> am referring to two different two different scenarios.
Making that clear from the beginning would have saved quite some time used for
responses :(
> For the particular
> log messages above, the connection is showing failed due to EINPROGRESS long
> before the 5 second expiry, usually within milliseconds.
OK, here I suggest to check using 1.2.44 (and switching temporarily to the
value 5 due to the "seconds instead of milliseconds" bug in 1.2.44) or 1.2.46
pre-release and recheck. It could well be that the poll() system call used
there for RHEL is more reliable due to the known limitations of select() on
Linux.
> I have two goals, both of which are admirably satisifed by mod_jk 1.2.42 and
> Apache 2.2, but failing miserably with mod_jk 1.2.42 and Apache 2.4
I remember you said 2.2 with prefork. So you could also cross check with 2.4
and prefork. Because with prefork, theres much less file descriptors in use. If
prefork and 2.4 work well, that might be another hint at using the poll() impl
provided by 1.2.44+.
> What I want:
>
> 1. Backend connection failures should be caught by a timeout, probably
> socket_connect_timeout
For clarity: socket_connect_timeout is not a generic connection timeout, it is
instead a timeout for socket connect, that means only for the process of
setting up a new connection (connect() system call). That's what it is meant
for, nothing else.
If you need to tackle more types of "connection failures", there's probably
other features handling them, but not socket_connect_timeout.
> 2. incomplete connections before the timeout expiry should never be flagged
> as failures.
Agreed but as I wrote before, this could happen due to the select() limitation
in 1.2.42 (not sure but could be), or time jumping forward.
> What I observe:
>
> If I set a socket_connect_timeout of 5000 milliseconds, loads of perfectly
> good backends are getting failed due to EINPROGRESS DESPITE the timeout not
> yet expiring.
How do you know that "the timeout" is "not expiring"?
> If I don't set a socket_connect_timeout at all (i.e. no timeout at all),
> then the request hangs indefinitely when the backend is missing.
More precisely *setup of new connections* will hang (if the network doesn't
respond with a no route to host or similar).
> In other words, I have found no configuration that satifies goals 1 and 2
> simultaneously, primarily, I believe, because the current code is treating
> EINPROGRESS as a failure way before the timeout expires.
As I tried to explain several times now: the current code handles EINPROGRES as
a normal return value and after EINPROGRESS waits for the timeout to happen and
then checks the socket status again. We might have done this wrong, but it is
not as obvious as you think.
> I can accept my interpretation of the underlying behaviours is wrong, but
> the fact is that mod_jk is marking backends down that are not down.
>
> I am open to suggestion on how I can demonstrate this behaviour more clearly
> that are achievable outside of our production environments.
We could add some lines to the code which track the connection setup in mod_jk
and log the details only if the setup fails due to socket_connect_timeout. But
before doing this I would be interested in the behavior of recent code (1.2.44
with config "5" or 1.2.46 pre-release).
Regards,
Rainer
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org