Steven, 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. regards On 22 December 2016 at 11:53, Steven Schlansker <[email protected]> wrote: > > > On Dec 21, 2016, at 1:56 PM, Greg Wilkins <[email protected]> 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{/20 > 1.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{/20 > 1.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{/20 > 1.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{/20 > 1.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} > > > > > _______________________________________________ > jetty-users mailing list > [email protected] > To change your delivery options, retrieve your password, or unsubscribe > from this list, visit > https://dev.eclipse.org/mailman/listinfo/jetty-users > -- Greg Wilkins <[email protected]> CTO http://webtide.com
_______________________________________________ jetty-users mailing list [email protected] To change your delivery options, retrieve your password, or unsubscribe from this list, visit https://dev.eclipse.org/mailman/listinfo/jetty-users
