> 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{/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}
suspect3.pcap
Description: Binary data
signature.asc
Description: Message signed with OpenPGP using GPGMail
_______________________________________________ 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
