Some Eclipse Foundation services are deprecated, or will be soon. Please ensure you've read this important communication.

Bug 370532

Summary:	Invalid handling of idled (closed) ssl connections, causes client destination connection cache overflow
Product:	[RT] Jetty	Reporter:	Ivan Prisyazhniy <john.koepi>
Component:	client	Assignee:	Jan Bartel <janb>
Status:	CLOSED FIXED	QA Contact:
Severity:	critical
Priority:	P3	CC:	jesse.mcconnell, jetty-inbox, tbecker
Version:	unspecified
Target Milestone:	7.5.x
Hardware:	PC
OS:	Linux
Whiteboard:

Description Ivan Prisyazhniy

2012-02-03 04:07:47 EST

Build Identifier: 8.0.4.v20111024

We use one instance of HttpClient to serve async https (SSL) requests to remote hosts in our server in multithreaded environment. 

It is used always to connect to one host graph.facebook.com. After some time being run (about 10-30 days) any HttpExchange request starts to report expired connection. We were able to did HttpClient dump. It seems that the reason of HttpClient stopped to serve connections is it had over filled HttpDestination connections cache with dead (or stalled) connections that all were closed in NEED_UNWRAP state (some with bufferoverrun). And the idle counter is 0, and pending is 0 too. 

So, it seems to be connection leak there in idle/dead connections handling code. Any way there is no way to clear them up or restart the client. 

I don't know how this can be reproduced. It's not quite easy to detect pattern of failure because we don't have a lot of this kind of error every day. But after it occurs, nothing works.

May be this is already fixed is some version of jetty async client? I was unable to find relevant bug report on this. But it seems there are a lot of similar reports like FIN_WAIT2 connection handling bug (https://bugs.eclipse.org/bugs/show_bug.cgi?id=364921) and others idle cases.

----

Also it seems that HttpDestination has stop method, that closes any connection there, but it somewhy do not remove them. May be it should?

Also HttpClient.stop() do not clears it's destinations so if destinations are corrupted it still can't be reused.

----

HttpClient dump:


INFO   | jvm 1    | 2012/02/02 19:07:43 | org.eclipse.jetty.client.HttpClient@75013892#STARTED
INFO   | jvm 1    | 2012/02/02 19:07:43 |  +- HttpDestination@25e4ec13//graph.facebook.com:443(10/10,0,0/1000)
INFO   | jvm 1    | 2012/02/02 19:07:43 | idle=0 pending=0
INFO   | jvm 1    | 2012/02/02 19:07:43 |      +- HttpConnection@1481041620//graph.facebook.com:443
INFO   | jvm 1    | 2012/02/02 19:07:43 |      |   +- SSLSCEP@960650666java.nio.channels.SocketChannel[closed][o=false d=false,io=1,w=true,rb=false,wb=false],NEED_UNWRAP, in/out=0/0 bi/o=false/false Status = CLOSED HandshakeStatus = NEED_UNWRAP
INFO   | jvm 1    | 2012/02/02 19:07:43 | bytesConsumed = 0 bytesProduced = 23
INFO   | jvm 1    | 2012/02/02 19:07:43 |      +- HttpConnection@383554963//graph.facebook.com:443
INFO   | jvm 1    | 2012/02/02 19:07:43 |      |   +- SSLSCEP@1993691643java.nio.channels.SocketChannel[closed][o=false d=false,io=5,w=true,rb=false,wb=false],NEED_UNWRAP, in/out=1369/0 bi/o=true/false Status = BUFFER_OVERFLOW HandshakeStatus = NEED_UNWRAP
INFO   | jvm 1    | 2012/02/02 19:07:43 | bytesConsumed = 0 bytesProduced = 0
INFO   | jvm 1    | 2012/02/02 19:07:43 |      +- HttpConnection@1809838494//graph.facebook.com:443
INFO   | jvm 1    | 2012/02/02 19:07:43 |      |   +- SSLSCEP@207154890java.nio.channels.SocketChannel[closed][o=false d=false,io=1,w=true,rb=false,wb=false],NEED_UNWRAP, in/out=0/0 bi/o=false/false Status = CLOSED HandshakeStatus = NEED_UNWRAP
INFO   | jvm 1    | 2012/02/02 19:07:43 | bytesConsumed = 0 bytesProduced = 27
INFO   | jvm 1    | 2012/02/02 19:07:43 |      +- HttpConnection@997192550//graph.facebook.com:443
INFO   | jvm 1    | 2012/02/02 19:07:43 |      |   +- SSLSCEP@726722449java.nio.channels.SocketChannel[closed][o=false d=false,io=1,w=true,rb=false,wb=false],NEED_UNWRAP, in/out=0/0 bi/o=false/false Status = CLOSED HandshakeStatus = NEED_UNWRAP
INFO   | jvm 1    | 2012/02/02 19:07:43 | bytesConsumed = 0 bytesProduced = 23
INFO   | jvm 1    | 2012/02/02 19:07:43 |      +- HttpConnection@852806662//graph.facebook.com:443
INFO   | jvm 1    | 2012/02/02 19:07:43 |      |   +- SSLSCEP@1034755951java.nio.channels.SocketChannel[closed][o=false d=false,io=5,w=true,rb=false,wb=false],NEED_UNWRAP, in/out=0/0 bi/o=false/false Status = CLOSED HandshakeStatus = NEED_UNWRAP
INFO   | jvm 1    | 2012/02/02 19:07:43 | bytesConsumed = 0 bytesProduced = 7
INFO   | jvm 1    | 2012/02/02 19:07:43 |      +- HttpConnection@815708156//graph.facebook.com:443
INFO   | jvm 1    | 2012/02/02 19:07:43 |      |   +- SSLSCEP@219404857java.nio.channels.SocketChannel[closed][o=false d=false,io=5,w=true,rb=false,wb=false],NEED_UNWRAP, in/out=2817/0 bi/o=true/false Status = BUFFER_OVERFLOW HandshakeStatus = NEED_UNWRAP
INFO   | jvm 1    | 2012/02/02 19:07:43 | bytesConsumed = 0 bytesProduced = 0
INFO   | jvm 1    | 2012/02/02 19:07:43 |      +- HttpConnection@71375444//graph.facebook.com:443
INFO   | jvm 1    | 2012/02/02 19:07:43 |      |   +- SSLSCEP@30851237java.nio.channels.SocketChannel[closed][o=false d=false,io=1,w=true,rb=false,wb=false],NEED_UNWRAP, in/out=0/0 bi/o=false/false Status = CLOSED HandshakeStatus = NEED_UNWRAP
INFO   | jvm 1    | 2012/02/02 19:07:43 | bytesConsumed = 0 bytesProduced = 27
INFO   | jvm 1    | 2012/02/02 19:07:43 |      +- HttpConnection@1311212282//graph.facebook.com:443
INFO   | jvm 1    | 2012/02/02 19:07:43 |      |   +- SSLSCEP@1155062286java.nio.channels.SocketChannel[closed][o=false d=false,io=1,w=true,rb=false,wb=false],NEED_UNWRAP, in/out=0/0 bi/o=false/false Status = CLOSED HandshakeStatus = NEED_UNWRAP
INFO   | jvm 1    | 2012/02/02 19:07:43 | bytesConsumed = 0 bytesProduced = 23
INFO   | jvm 1    | 2012/02/02 19:07:43 |      +- HttpConnection@67638060//graph.facebook.com:443
INFO   | jvm 1    | 2012/02/02 19:07:43 |      |   +- SSLSCEP@1299221074java.nio.channels.SocketChannel[closed][o=false d=false,io=5,w=true,rb=false,wb=false],NEED_UNWRAP, in/out=2817/0 bi/o=true/false Status = BUFFER_OVERFLOW HandshakeStatus = NEED_UNWRAP
INFO   | jvm 1    | 2012/02/02 19:07:43 | bytesConsumed = 0 bytesProduced = 0
INFO   | jvm 1    | 2012/02/02 19:07:43 |      +- HttpConnection@774025157//graph.facebook.com:443
INFO   | jvm 1    | 2012/02/02 19:07:43 |          +- SSLSCEP@1286868863java.nio.channels.SocketChannel[closed][o=false d=false,io=5,w=true,rb=false,wb=false],NEED_UNWRAP, in/out=2817/0 bi/o=true/false Status = BUFFER_OVERFLOW HandshakeStatus = NEED_UNWRAP
INFO   | jvm 1    | 2012/02/02 19:07:43 | bytesConsumed = 0 bytesProduced = 0


Reproducible: Sometimes

Steps to Reproduce:
Don't know exactly how to reproduce. But it seems problem is caused by timeout connection or bad closing/shutdown on remote side. Connection timeout = 1sec, Timeout = 3sec, Idle timeout = 10sec. Async http client with SSL.

Comment 1 Jesse McConnell

2012-02-03 12:54:09 EST

Do upgrade to 8.1.0.v20120127 as there have been a lot of work done in the area to address edge cases akin to one you are experiencing here.

Comment 2 Jan Bartel

2012-02-09 02:53:09 EST

Ivan,

If you can do as Jesse suggests and upgrade to 8.1.0.v20120127 then I'm fairly confident this will resolve your problem. If it does not, then please post with another HttpClient dump.

Jan

Comment 3 Ivan Prisyazhniy

2012-02-09 03:01:15 EST

Status report: 

We have been upgraded to 8.1.0.v20120127 since 3 days ago. No stalled connections yet found in HttpClient dump. It seems that new version works fine a lot. Thank you. I'll report if something goes wrong.

Comment 4 Thomas Becker

2012-02-23 09:32:15 EST

Ivan, still no stalled connections? Are you confident that this issue is resolved? Then I'd suggest to close the issue and reopen it if it happens again. Do you agree?

Comment 5 Ivan Prisyazhniy

2012-02-23 09:35:22 EST

Yes, last version of Jetty Client (> 8.1.0.v20120127) is not the case of this.

Comment 6 Thomas Becker

2012-02-23 09:37:00 EST

Great, thx Ivan!