| Re: [jetty-users] SSLEngineImpl initHandshaker Internal error |
> 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/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@6fad21e
2016-12-21T23:44:12.818Z DEBUG <> [qtp294008652-58364] o.e.j.u.t.s.ExecuteProduceConsume - EPC Prod/Pend/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@6fad21e run SelectChannelEndPoint@5a23fff6{/10.30.64.212:16725<->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] org.eclipse.jetty.io.FillInterest - FillInterest@61f9356f{true,AC.ReadCB@5b279677{SslConnection@5b279677{NEED_UNWRAP,eio=-1/-1,di=-1} -> HttpConnection@1c7c0306[DecryptedEndPoint@2917e8db{/201.114.209.201:61299<->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{/201.114.209.201:61299<->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] o.eclipse.jetty.io.ssl.SslConnection - onFillable enter DecryptedEndPoint@2917e8db{/201.114.209.201:61299<->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] org.eclipse.jetty.io.FillInterest - FillInterest@4cbb0278{true,AC.ReadCB@1c7c0306{HttpConnection@1c7c0306[DecryptedEndPoint@2917e8db{/201.114.209.201:61299<->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{/201.114.209.201:61299<->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{/201.114.209.201:61299<->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] org.eclipse.jetty.io.ChannelEndPoint - filled 182 SelectChannelEndPoint@5a23fff6{/10.30.64.212:16725<->4443,Open,in,OSHUT,-,-,1847/30000,SslConnection@5b279677}{io=1/0,kio=1,kro=1}
2016-12-21T23:44:12.829Z DEBUG <> [qtp294008652-58364] o.eclipse.jetty.io.ssl.SslConnection - SslConnection@5b279677{NEED_UNWRAP,eio=107/-1,di=-1} -> HttpConnection@1c7c0306[DecryptedEndPoint@2917e8db{/201.114.209.201:61299<->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] org.eclipse.jetty.io.ChannelEndPoint - close SelectChannelEndPoint@5a23fff6{/10.30.64.212:16725<->4443,CLOSED,in,OSHUT,-,-,2/30000,SslConnection@5b279677}{io=1/0,kio=1,kro=1}
2016-12-21T23:44:12.834Z DEBUG <> [qtp294008652-58364] org.eclipse.jetty.io.ManagedSelector - Queued change org.eclipse.jetty.io.ManagedSelector$2@5292d3d8 on org.eclipse.jetty.io.ManagedSelector@6501b105 id=0 keys=942 selected=904
2016-12-21T23:44:12.836Z DEBUG <> [qtp294008652-58364] o.e.jetty.server.HttpConnection - HttpConnection@1c7c0306[DecryptedEndPoint@2917e8db{/201.114.209.201:61299<->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 sun.security.ssl.SSLEngineImpl.initHandshaker(SSLEngineImpl.java:470)
at sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:1007)
at sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.java:907)
at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:781)
at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624)
at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.fill(SslConnection.java:525)
at org.eclipse.jetty.server.HttpConnection.fillRequestBuffer(HttpConnection.java:325)
at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:233)
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:273)
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:95)
at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:202)
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:273)
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:95)
at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93)
at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume(ExecuteProduceConsume.java:303)
at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume(ExecuteProduceConsume.java:148)
at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:136)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:671)
at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:589)
at java.lang.Thread.run(Thread.java:745)
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}
Attachment:
suspect3.pcap
Description: Binary data
Attachment:
signature.asc
Description: Message signed with OpenPGP using GPGMail