Skip to main content

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index] [List Home]
Re: [jetty-users] SSLEngineImpl initHandshaker Internal error


nice analysis!  Yes that exchange does look a little suspect, although I will have to discuss with other team members to be sure, as TLS can be a strange and variable beast.

I see it is coming from an intermediary in your data center as we don't have the source IP address.  Are you able to identify the source IP from the proxy log?  It would be interesting to see if you could identify the source IP address... then if so see if you can find any valid requests from that IP and look at the user-agent.

Jetty too has issues with handling of spontaneous closes causing races.  We think we have handled all (most?) of them, but to do so means that we can't be as elegant in our error handling as we'd like to be, as the error handling itself can cause exceptions and races etc.     We are working in this area to try to client up these problems and there have been improvements in the latest 9.3.x releases, so perhaps worth a try to see if it reports it better.


On 22 December 2016 at 11:53, Steven Schlansker <stevenschlansker@xxxxxxxxx> wrote:

> On Dec 21, 2016, at 1:56 PM, Greg Wilkins <gregw@xxxxxxxxxxx> wrote:
> I think you will need to have a little look with wireshark, but perhaps not too much pulling them apart.

I was afraid you'd say that :)
So at this point I have a tcpdump of the time period in question.
I also turned on Jetty DEBUG level logging.  This is a beast -- a few minutes of DEBUG logs are 3GB, and the tcpdump is well over a billion packets... lots to dig through!

The problem I ran into first is that it is very difficult to determine which connection is actually erroring out.  The "Internal error" reported does not log the endpoint or EPC operation.  Maybe the EPC strategy or somewhere up the chain needs to catch an exception and explicitly attach which operation was in progress when this happens.  It's doubly confusing due to async, I am not entirely sure how far back I can assume the same thread held the same connection.  But I think I might have found a culprit just by poking around and trying to correlate timestamps.

> First question we need answered is if this is happening on a new connection or an existing one.  Given it is in initHandshaker, it is probably a new connection, but renegotiation may also be happening on an existing connection.

I think it is a new connection.  If I grabbed the correct conversation, it looks like we get Client / Server Hello, Server / Client KEX, then the client initiates a Change Cipher Spec / Encrypted Handshake, then the server responds with a Warning Alert: Close Notify and FINs the connection.  I attached the pcap.

> Then it would be good to see exactly how many packets have been exchanged prior to this.
> At this stage, this looks like clients sending bad negotiation packets, maybe not even TLS.  So bad client is the suspect until proven otherwise.

It really does look very suspicious.  This connection lasted almost 1.5 minutes but only exchanged 19 packets.
I wonder if this is someone scanning us for vulnerabilities or something like that.  This is a moderately popular public website and we do get botnet scans / drive-by attacks on a pretty consistent basis...

One random observation: the ChannelEndPoint indicates that it closed the endpoint, and the unwrap fails immediately afterwards.  The Netty bug I linked earlier was a race between connection close and SSLEngine.unwrap() that caused this exact exception.
I know the likely cause is still a bad client or other problems on our end, not trying to besmirch Jetty, just keeping all possibilities open :)

These are the tail of Jetty logs for the thread that died:

2016-12-21T23:44:12.816Z DEBUG <> [qtp294008652-58364] o.e.j.util.thread.QueuedThreadPool - queue EPC Prod/Pend/$SelectorProducer@6fad21e
2016-12-21T23:44:12.818Z DEBUG <> [qtp294008652-58364] o.e.j.u.t.s.ExecuteProduceConsume - EPC Prod/Pend/$SelectorProducer@6fad21e run SelectChannelEndPoint@5a23fff6{/<->4443,Open,in,OSHUT,FI,-,1838/30000,SslConnection@5b279677}{io=1/0,kio=1,kro=1}:runFillable
2016-12-21T23:44:12.820Z DEBUG <> [qtp294008652-58364] - FillInterest@61f9356f{true,AC.ReadCB@5b279677{SslConnection@5b279677{NEED_UNWRAP,eio=-1/-1,di=-1} -> HttpConnection@1c7c0306[DecryptedEndPoint@2917e8db{/<->443,Open,in,OSHUT,FI,-,1856/30000,HttpConnection@1c7c0306}->org.eclipse.jetty.server.ProxyConnectionFactory$ProxyEndPoint@4652e3e9][p=HttpParser{s=CLOSE,0 of 0},g=HttpGenerator@abb7162{s=START},c=HttpChannelOverHttp@7ed6c14d{r=0,c=false,a=IDLE,uri=null}]}} fillable AC.ReadCB@5b279677{SslConnection@5b279677{NEED_UNWRAP,eio=-1/-1,di=-1} -> HttpConnection@1c7c0306[DecryptedEndPoint@2917e8db{/<->443,Open,in,OSHUT,FI,-,1856/30000,HttpConnection@1c7c0306}->org.eclipse.jetty.server.ProxyConnectionFactory$ProxyEndPoint@4652e3e9][p=HttpParser{s=CLOSE,0 of 0},g=HttpGenerator@abb7162{s=START},c=HttpChannelOverHttp@7ed6c14d{r=0,c=false,a=IDLE,uri=null}]}
2016-12-21T23:44:12.821Z DEBUG <> [qtp294008652-58364] - onFillable enter DecryptedEndPoint@2917e8db{/<->443,Open,in,OSHUT,FI,-,1857/30000,HttpConnection@1c7c0306}->org.eclipse.jetty.server.ProxyConnectionFactory$ProxyEndPoint@4652e3e9
2016-12-21T23:44:12.823Z DEBUG <> [qtp294008652-58364] - FillInterest@4cbb0278{true,AC.ReadCB@1c7c0306{HttpConnection@1c7c0306[DecryptedEndPoint@2917e8db{/<->443,Open,in,OSHUT,FI,-,1859/30000,HttpConnection@1c7c0306}->org.eclipse.jetty.server.ProxyConnectionFactory$ProxyEndPoint@4652e3e9][p=HttpParser{s=CLOSE,0 of 0},g=HttpGenerator@abb7162{s=START},c=HttpChannelOverHttp@7ed6c14d{r=0,c=false,a=IDLE,uri=null}]}} fillable AC.ReadCB@1c7c0306{HttpConnection@1c7c0306[DecryptedEndPoint@2917e8db{/<->443,Open,in,OSHUT,FI,-,1859/30000,HttpConnection@1c7c0306}->org.eclipse.jetty.server.ProxyConnectionFactory$ProxyEndPoint@4652e3e9][p=HttpParser{s=CLOSE,0 of 0},g=HttpGenerator@abb7162{s=START},c=HttpChannelOverHttp@7ed6c14d{r=0,c=false,a=IDLE,uri=null}]}
2016-12-21T23:44:12.825Z DEBUG <> [qtp294008652-58364] o.e.jetty.server.HttpConnection - HttpConnection@1c7c0306[DecryptedEndPoint@2917e8db{/<->443,Open,in,OSHUT,-,-,1861/30000,HttpConnection@1c7c0306}->org.eclipse.jetty.server.ProxyConnectionFactory$ProxyEndPoint@4652e3e9][p=HttpParser{s=CLOSE,0 of 0},g=HttpGenerator@abb7162{s=START},c=HttpChannelOverHttp@7ed6c14d{r=0,c=false,a=IDLE,uri=null}] onFillable enter HttpChannelState@54687c6f{s=IDLE a=NOT_ASYNC i=true r=!P!U w=false} null
2016-12-21T23:44:12.826Z DEBUG <> [qtp294008652-58364] - filled 182 SelectChannelEndPoint@5a23fff6{/<->4443,Open,in,OSHUT,-,-,1847/30000,SslConnection@5b279677}{io=1/0,kio=1,kro=1}
2016-12-21T23:44:12.829Z DEBUG <> [qtp294008652-58364] - SslConnection@5b279677{NEED_UNWRAP,eio=107/-1,di=-1} -> HttpConnection@1c7c0306[DecryptedEndPoint@2917e8db{/<->443,Open,ISHUT,OSHUT,-,-,1865/30000,HttpConnection@1c7c0306}->org.eclipse.jetty.server.ProxyConnectionFactory$ProxyEndPoint@4652e3e9][p=HttpParser{s=CLOSE,0 of 0},g=HttpGenerator@abb7162{s=START},c=HttpChannelOverHttp@7ed6c14d{r=0,c=false,a=IDLE,uri=null}] shutdownOutput: oshut=true, ishut=true
2016-12-21T23:44:12.832Z DEBUG <> [qtp294008652-58364] - close SelectChannelEndPoint@5a23fff6{/<->4443,CLOSED,in,OSHUT,-,-,2/30000,SslConnection@5b279677}{io=1/0,kio=1,kro=1}
2016-12-21T23:44:12.834Z DEBUG <> [qtp294008652-58364] - Queued change$2@5292d3d8 on id=0 keys=942 selected=904
2016-12-21T23:44:12.836Z DEBUG <> [qtp294008652-58364] o.e.jetty.server.HttpConnection - HttpConnection@1c7c0306[DecryptedEndPoint@2917e8db{/<->443,CLOSED,ISHUT,OSHUT,-,-,1871/30000,HttpConnection@1c7c0306}->org.eclipse.jetty.server.ProxyConnectionFactory$ProxyEndPoint@4652e3e9][p=HttpParser{s=CLOSE,0 of 0},g=HttpGenerator@abb7162{s=START},c=HttpChannelOverHttp@7ed6c14d{r=0,c=false,a=IDLE,uri=null}] onFillable exit HttpChannelState@54687c6f{s=IDLE a=NOT_ASYNC i=true r=!P!U w=false} HeapByteBuffer@6964b723[p=0,l=0,c=17408,r=0]={<<<>>>GET /apple-app-si...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
2016-12-21T23:44:12.837Z WARN  <> [qtp294008652-58364] o.e.j.util.thread.QueuedThreadPool -
java.lang.IllegalStateException: Internal error
        at org.eclipse.jetty.server.HttpConnection.fillRequestBuffer(
        at org.eclipse.jetty.server.HttpConnection.onFillable(
        at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume(
        at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume(
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(
        at org.eclipse.jetty.util.thread.QueuedThreadPool$

2016-12-21T23:44:12.839Z WARN  <> [qtp294008652-58364] o.e.j.util.thread.QueuedThreadPool - Unexpected thread death: org.eclipse.jetty.util.thread.QueuedThreadPool$2@6792928d in qtp294008652{STARTED,10<=63<=1000,i=19,q=0}

jetty-users mailing list
To change your delivery options, retrieve your password, or unsubscribe from this list, visit


Back to the top