Bug 482117

Comment 1 Matt Painter 2015-11-13 13:13:13 EST

Verified to happen on 9.3.5 also

Comment 2 Matt Painter 2015-11-13 13:44:30 EST

We have seen a lot of this in the logs:

2015-11-13 18:32:41.247 [Scheduler-81153283] DEBUG o.eclipse.jetty.io.AbstractEndPoint - onIdleExpired - || - Ignored idle endpoint SelectChannelEndPoint@6ba4dafd{/10.0.0.194:61581<->8888,Open,in,out,-,-,30001/30000,HttpConnection}{io=0/0,kio=0,kro=1}
2015-11-13 18:32:41.253 [Scheduler-81153283] DEBUG o.eclipse.jetty.io.AbstractEndPoint - onIdleExpired - || - Ignored idle endpoint SelectChannelEndPoint@24e35471{/10.0.0.194:62914<->8888,Open,in,out,-,-,30001/30000,HttpConnection}{io=0/0,kio=0,kro=1}
2015-11-13 18:32:41.262 [Scheduler-81153283] DEBUG o.eclipse.jetty.io.AbstractEndPoint - onIdleExpired - || - Ignored idle endpoint SelectChannelEndPoint@61cfce31{/10.0.0.194:62973<->8888,Open,in,out,-,-,30000/30000,HttpConnection}{io=0/0,kio=0,kro=1}
2015-11-13 18:32:41.263 [Scheduler-81153283] DEBUG o.eclipse.jetty.io.AbstractEndPoint - onIdleExpired - || - Ignored idle endpoint SelectChannelEndPoint@453da72{/10.0.0.194:62818<->8888,Open,in,out,-,-,30001/30000,HttpConnection}{io=0/0,kio=0,kro=1}
2015-11-13 18:32:41.263 [Scheduler-81153283] DEBUG o.eclipse.jetty.io.AbstractEndPoint - onIdleExpired - || - Ignored idle endpoint SelectChannelEndPoint@27a4425{/10.0.0.194:61466<->8888,Open,in,out,-,-,30000/30000,HttpConnection}{io=0/0,kio=0,kro=1}
2015-11-13 18:32:41.276 [Scheduler-81153283] DEBUG o.eclipse.jetty.io.AbstractEndPoint - onIdleExpired - || - Ignored idle endpoint SelectChannelEndPoint@79576c07{/10.0.0.194:62804<->8888,Open,in,out,-,-,30000/30000,HttpConnection}{io=0/0,kio=0,kro=1}
2015-11-13 18:32:41.287 [Scheduler-81153283] DEBUG o.eclipse.jetty.io.AbstractEndPoint - onIdleExpired - || - Ignored idle endpoint SelectChannelEndPoint@353db1e3{/10.0.0.194:62150<->8888,Open,in,out,-,-,30001/30000,HttpConnection}{io=0/0,kio=0,kro=1}
2015-11-13 18:32:41.304 [Scheduler-81153283] DEBUG o.eclipse.jetty.io.AbstractEndPoint - onIdleExpired - || - Ignored idle endpoint SelectChannelEndPoint@5b5922ab{/10.0.0.194:63083<->8888,Open,in,out,-,-,30001/30000,HttpConnection}{io=0/0,kio=0,kro=1}
2015-11-13 18:32:41.307 [Scheduler-81153283] DEBUG o.eclipse.jetty.io.AbstractEndPoint - onIdleExpired - || - Ignored idle endpoint SelectChannelEndPoint@49b03a47{/10.0.0.194:62268<->8888,Open,in,out,-,-,30000/30000,HttpConnection}{io=0/0,kio=0,kro=1}
2015-11-13 18:32:41.309 [Scheduler-81153283] DEBUG o.eclipse.jetty.io.AbstractEndPoint - onIdleExpired - || - Ignored idle endpoint SelectChannelEndPoint@306e4257{/10.0.0.194:62764<->8888,Open,in,out,-,-,30001/30000,HttpConnection}{io=0/0,kio=0,kro=1}
2015-11-13 18:32:41.326 [Scheduler-81153283] DEBUG o.eclipse.jetty.io.AbstractEndPoint - onIdleExpired - || - Ignored idle endpoint SelectChannelEndPoint@6a1b1403{/10.0.0.194:63093<->8888,Open,in,out,-,-,30001/30000,HttpConnection}{io=0/0,kio=0,kro=1}
2015-11-13 18:32:41.329 [Scheduler-81153283] DEBUG o.eclipse.jetty.io.AbstractEndPoint - onIdleExpired - || - Ignored idle endpoint SelectChannelEndPoint@d50b02e{/10.0.0.194:62543<->8888,Open,in,out,-,-,30000/30000,HttpConnection}{io=0/0,kio=0,kro=1}
2015-11-13 18:32:41.340 [Scheduler-81153283] DEBUG o.eclipse.jetty.io.AbstractEndPoint - onIdleExpired - || - Ignored idle endpoint SelectChannelEndPoint@34f16be{/10.0.0.194:62663<->8888,Open,in,out,-,-,30000/30000,HttpConnection}{io=0/0,kio=0,kro=1}
2015-11-13 18:32:41.358 [Scheduler-81153283] DEBUG o.eclipse.jetty.io.AbstractEndPoint - onIdleExpired - || - Ignored idle endpoint SelectChannelEndPoint@59d76062{/10.0.0.194:61479<->8888,Open,in,out,-,-,30001/30000,HttpConnection}{io=0/0,kio=0,kro=1}^C

These connections seem to all map to connections in CLOSE_WAIT.

This is printed from the code:

    @Override
    protected void onIdleExpired(TimeoutException timeout)
    {
        boolean output_shutdown=isOutputShutdown();
        boolean input_shutdown=isInputShutdown();
        boolean fillFailed = _fillInterest.onFail(timeout);
        boolean writeFailed = _writeFlusher.onFail(timeout);

        // If the endpoint is half closed and there was no fill/write handling, then close here.
        // This handles the situation where the connection has completed its close handling
        // and the endpoint is half closed, but the other party does not complete the close.
        // This perhaps should not check for half closed, however the servlet spec case allows
        // for a dispatched servlet or suspended request to extend beyond the connections idle
        // time.  So if this test would always close an idle endpoint that is not handled, then
        // we would need a mode to ignore timeouts for some HTTP states
        if (isOpen() && (output_shutdown || input_shutdown) && !(fillFailed || writeFailed))
            close();
        else
            LOG.debug("Ignored idle endpoint {}",this);
    }

Perhaps the logic here is incorrect? Or perhaps there's a bug? Trying to investigate further, would be grateful for any pointers or assistance :)

Comment 3 Matt Painter 2015-11-13 14:15:16 EST

Created attachment 257934 [details]
Log showing different behaviour for re-used channel

Here we can see the different behaviour between two requests. 

The second request reads 423 bytes, but because it never re-reads it in ChannelEndpoint.fill (returning -1), it never calls ChannelEndpoint.shutdownInput(). Therefore the input state is never transitioned to ISHUT which then seems to cause a knock-on effect, with the channel never able to be closed.

Comment 4 Matt Painter 2015-11-14 03:18:40 EST

This may seemingly be due to the AWS ELB issuing a 504 gateway timeout, that is the number of CLOSE_WAITs seems to link directly with the number of 504s the load balancer issues.

Comment 5 Greg Wilkins 2015-11-14 20:49:15 EST

Matt,

The thing of concern here is that the endpoints have io=0, so it is not interested in any operations - hence it is not seeing a close.    This is typically the state when a request has been dispatch, but no io operation has been attempted.   It should not be a state for an idle connection.


The shutdownInput issue is unlikely to be the issue.  With HTTP the server will never instigate an input side shutdown.  It may shutdown output and wait to read a -1,  or it may read a -1 and then do a close.   But perhaps we have an error in that logic somewhere?

It is also probably an issue that such a endpoint is surviving a timeout and not being closed.

So we need to find a way to reproduce this issue.  Can you capture a tcp/ip trace of the interaction from proxy to server when a 504 occurs.

Comment 6 Greg Wilkins 2015-11-17 23:03:20 EST

Matt,

can you give us any more information on this one???    It would be good to see the full log, or at least everything done by thread qtp1181693689-125.    Very strange to see the 9s between the last fill on the connection and the interest ops being set to 0.

So we really need to full debug trace and a tcp trace as well.

Comment 7 Matt Painter 2015-11-18 01:59:06 EST

Hi

Sorry for the delay, have been investigating and patching our production. 

I need to set up an aws environment in aws just to try to reproduce it by triggering an elb timeout. It only happens under load in production, so trying to get a TCP track for this wouldn't make sense due to excessive noise. 

I have worked around it for now by ensuring that the continuation is timed out and closed from our side before the elb times it out. It seems to me like jetty needs to periodically check if waiting continuations have been closed from the other side, even if it hasn't reached a time out yet. If I'm correct there's no way in Java to detect to aoxket close without trying to read or write though?

Comment 8 Greg Wilkins 2015-11-18 02:37:15 EST

Matt,

ah that makes sense - you are using continuations and the requests are suspended (Note that you should switch to the AsyncContext API in the servlet spec as continuations are deprecated).

So there is no read interest set, hence the close is not seen and the timeouts are ignored.

This is an unsolvable problem with java as you can't register for just error/close events.  If we read periodically, then we have a DOS problem as if content is sent, we have to put it somewhere.

You can periodically send some noop content while waiting - which depends on your content-type.  Some clients can accept 102-processing responses as interim responses.

Or you can just use something like cometd and we'll deal with all of the details for you.

I'm closing this for now, as I think this is just a known problem.

Comment 9 Axel Uhl 2018-01-30 11:54:17 EST

We've been facing a very similar issue. For reasons too long to explain here we're still running 9.2.2 in our production environment. An Amazon Application Load Balancer (ALB), more specifically one of its target groups, is doing health checks on our Jetty instances. When under heavy load, we recently "lost" two instances to the CLOSE_WAIT issue, with ~30k sockets in that state, running into the limits for file descriptors, stalling the instance.

Maybe worth noting: the lsof output lists those sockets as all IPv6:

java    22664 xxxx 570u  IPv6           57747443       0t0        TCP localhost:ddi-tcp-1->localhost:60836 (CLOSE_WAIT)

When we put an Apache reverse proxy between the ALB and the instance and have the ALB run its health check through the reverse proxy then the problem doesn't seem to occur. The Apache server will use IPv4 to connect to the Jetty instance.

It seems weird that Apache would be able to handle this properly while Jetty chokes an entire server based on this. I would really hope there are ways to get this fixes and would be happy if this bug could be re-opened. In our case it poses a severe risk for our production environment in case anyone tries to set up health checks straight to the Jetty port.

Comment 10 Jan Bartel 2018-01-30 12:23:55 EST

Axel,

We can't reopen this issue, as the jetty project moved to using github issues some time ago. The link is here: https://github.com/eclipse/jetty.project/issues.

I've opened a fresh issue there, and added in your comment: https://github.com/eclipse/jetty.project/issues/2169

Comment 11 Axel Uhl 2018-01-30 12:35:26 EST

Great, thanks! Added another comment there.