Jetty.project: JDK9 Test failure: org.eclipse.jetty.server.ThreadStarvationTest.testWriteStarvation[https/ssl/tls]

[joakime]

jetty-9.4.x branch.
Linux build.
Bare metal build. (no container / docker)

Error Message
javax.net.ssl.SSLException: Received close_notify during handshake
Stacktrace
java.util.concurrent.ExecutionException: javax.net.ssl.SSLException: Received close_notify during handshake
    at org.eclipse.jetty.server.ThreadStarvationTest.testWriteStarvation(ThreadStarvationTest.java:346)
Caused by: javax.net.ssl.SSLException: Received close_notify during handshake
    at org.eclipse.jetty.server.ThreadStarvationTest.lambda$testWriteStarvation$4(ThreadStarvationTest.java:316)
Standard Error
Running org.eclipse.jetty.server.ThreadStarvationTest.testWriteStarvation[https/ssl/tls]()
2018-02-22 23:32:13.870:INFO:oejs.Server:main: jetty-9.4.9-SNAPSHOT; built: 2018-02-22T23:27:01Z; git: 4d2cbf76d7969df741032731f80d2e774a9e7587; jvm 9.0.1+11
2018-02-22 23:32:13.870:INFO:oejut.ThreadPoolBudget:main: ReservedThreadExecutor@69fa5536{s=0/1,p=0} requires 1 threads from QueuedThreadPool@qtp861554088{STARTING,5<=0<=5,i=0,q=0,r=ReservedThreadExecutor@69fa5536{s=0/1,p=0}}
2018-02-22 23:32:13.870:WARN:oejut.ThreadPoolBudget:main: Low configured threads: (max=5 - required=1)=4 < warnAt=32 for QueuedThreadPool@qtp861554088{STARTING,5<=0<=5,i=0,q=0,r=ReservedThreadExecutor@69fa5536{s=0/1,p=0}}
2018-02-22 23:32:13.870:INFO:oejut.ThreadPoolBudget:main: ServerConnector@4512f5f1{SSL,[ssl, http/1.1]}{0.0.0.0:45177} requires 1 threads from QueuedThreadPool@qtp861554088{STARTED,5<=5<=5,i=5,q=0,r=ReservedThreadExecutor@69fa5536{s=0/1,p=0}}
2018-02-22 23:32:13.871:INFO:oejus.SslContextFactory:main: x509=X509@2a22e7e2(jetty,h=[jetty.eclipse.org],w=[]) for SslContextFactory@3bfead8d[provider=null,keyStore=file:///home/jenkins/agent/workspace/jetty.project_jetty-9.4.x-INBQ7QOOOQAKBR7QXCZRBSZMK7E2XO45CPMMWPFUPSXZHYWIIW5Q/jetty-server/src/test/resources/keystore,trustStore=file:///home/jenkins/agent/workspace/jetty.project_jetty-9.4.x-INBQ7QOOOQAKBR7QXCZRBSZMK7E2XO45CPMMWPFUPSXZHYWIIW5Q/jetty-server/src/test/resources/keystore]
2018-02-22 23:32:13.871:INFO:oejus.SslContextFactory:main: x509=X509@5799b8a2(mykey,h=[],w=[]) for SslContextFactory@3bfead8d[provider=null,keyStore=file:///home/jenkins/agent/workspace/jetty.project_jetty-9.4.x-INBQ7QOOOQAKBR7QXCZRBSZMK7E2XO45CPMMWPFUPSXZHYWIIW5Q/jetty-server/src/test/resources/keystore,trustStore=file:///home/jenkins/agent/workspace/jetty.project_jetty-9.4.x-INBQ7QOOOQAKBR7QXCZRBSZMK7E2XO45CPMMWPFUPSXZHYWIIW5Q/jetty-server/src/test/resources/keystore]
2018-02-22 23:32:13.872:INFO:oejut.ThreadPoolBudget:main: SelectorManager@ServerConnector@4512f5f1{SSL,[ssl, http/1.1]}{0.0.0.0:45177} requires 1 threads from QueuedThreadPool@qtp861554088{STARTED,5<=5<=5,i=5,q=0,r=ReservedThreadExecutor@69fa5536{s=0/1,p=0}}
2018-02-22 23:32:13.872:INFO:oejs.AbstractConnector:main: Started ServerConnector@4512f5f1{SSL,[ssl, http/1.1]}{0.0.0.0:45177}
2018-02-22 23:32:13.873:INFO:oejs.Server:main: Started @46833ms
2018-02-22 23:32:48.987:INFO:oejs.AbstractConnector:main: Stopped ServerConnector@4512f5f1{SSL,[ssl, http/1.1]}{0.0.0.0:0}

[gregw]

further debug on this issue is available at in jenkins run 46 which shows a queued jobs:

 |   +> jobs - size=7
 |       +- CEP:SocketChannelEndPoint@79faab84{/127.0.0.1:51710<->/127.0.0.1:43941,CLOSED,fill=-,flush=-,to=3000/30000}{io=0/0,kio=-1,kro=-1}->SslConnection@5363345f{NEED_UNWRAP,eio=31/-1,di=-1}=>HttpConnection@61b3727d[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@30a064f1{s=START}]=>HttpChannelOverHttp@1749a070{r=0,c=false,a=IDLE,uri=null,age=0}:runFillable:BLOCKING
 |       +- ReservedThreadExecutor@73cfafd8{s=1/1,p=1}@5d42bf0a
 |       +- org.eclipse.jetty.io.ManagedSelector$DestroyEndPoint@27980e45
 |       +- SSL:SslConnection@142c71ab{NOT_HANDSHAKING,eio=-1/-1,di=-1}=>HttpConnection@4ebc097e[p=HttpParser{s=END,0 of -1},g=HttpGenerator@64e554c{s=COMMITTED}]=>HttpChannelOverHttp@61c399e6{r=1,c=true,a=DISPATCHED,uri=https://localhost/,age=33004}<-SocketChannelEndPoint@11c69ef2{/127.0.0.1:51714<->/127.0.0.1:43941,OPEN,fill=-,flush=-,to=1409/30000}{io=0/0,kio=0,kro=4}->SslConnection@142c71ab{NOT_HANDSHAKING,eio=-1/-1,di=-1}=>HttpConnection@4ebc097e[p=HttpParser{s=END,0 of -1},g=HttpGenerator@64e554c{s=COMMITTED}]=>HttpChannelOverHttp@61c399e6{r=1,c=true,a=DISPATCHED,uri=https://localhost/,age=33004}:runCompleteWrite:NON_BLOCKING
 |       +- org.eclipse.jetty.io.ManagedSelector$DestroyEndPoint@16951d5c
 |       +- SSL:SslConnection@38cc0109{NOT_HANDSHAKING,eio=-1/-1,di=-1}=>HttpConnection@4c5cd769[p=HttpParser{s=END,0 of -1},g=HttpGenerator@312d7bad{s=COMMITTED}]=>HttpChannelOverHttp@f6cff29{r=1,c=true,a=DISPATCHED,uri=https://localhost/,age=31231}<-SocketChannelEndPoint@6389c423{/127.0.0.1:51708<->/127.0.0.1:43941,OPEN,fill=-,flush=-,to=1101/30000}{io=0/0,kio=0,kro=4}->SslConnection@38cc0109{NOT_HANDSHAKING,eio=-1/-1,di=-1}=>HttpConnection@4c5cd769[p=HttpParser{s=END,0 of -1},g=HttpGenerator@312d7bad{s=COMMITTED}]=>HttpChannelOverHttp@f6cff29{r=1,c=true,a=DISPATCHED,uri=https://localhost/,age=31231}:runCompleteWrite:NON_BLOCKING

There are two runCompleteWrite jobs queued, even though they are non-blocking??? Inspecting the code, this is likely to be a result of these lines which execute a _runCompleteWrite to avoid recursion! This can cause flow control events to be queued in a starved ThreadPool!

@sbordet need help on how to fix this!

[gregw]

@sbordet I have pushed a speculative fix as I wanted this to run in the jetty-9.4.x CI build exactly as before. But let's chat about the fix when you are on line.

[gregw]

@sbordet @joakime I have pushed a better fix that protects from recursion (it is ugly). I will now create a branch to see if we can make flush better.

[gregw]

Reports of spin loops in 9.4.11 at:

By sampling the stacks, I am able to notice a couple of hot spots:

"default-pool-4665" #4665 prio=5 os_prio=0 tid=0x00000000013c5000 nid=0x1258 runnable [0x00007ff9eb1ef000]
   java.lang.Thread.State: RUNNABLE
        at org.eclipse.jetty.io.ssl.SslConnection$1.run(SslConnection.java:121)
        at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onIncompleteFlush(SslConnection.java:545)
        at org.eclipse.jetty.io.AbstractEndPoint$2.onIncompleteFlush(AbstractEndPoint.java:54)
        at org.eclipse.jetty.io.WriteFlusher.write(WriteFlusher.java:332)
        at org.eclipse.jetty.io.AbstractEndPoint.write(AbstractEndPoint.java:380)
        at org.eclipse.jetty.server.HttpConnection$SendCallback.process(HttpConnection.java:804)
        at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:241)
        at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:224)
        at org.eclipse.jetty.server.HttpConnection.send(HttpConnection.java:538)
        at org.eclipse.jetty.server.HttpChannel.sendResponse(HttpChannel.java:795)

"default-pool-4665" #4665 prio=5 os_prio=0 tid=0x00000000013c5000 nid=0x1258 runnable [0x00007ff9eb1ef000]
   java.lang.Thread.State: RUNNABLE
        at java.lang.ThreadLocal$ThreadLocalMap.getEntryAfterMiss([email protected]/ThreadLocal.java:443)
        at java.lang.ThreadLocal$ThreadLocalMap.getEntry([email protected]/ThreadLocal.java:418)
        at java.lang.ThreadLocal$ThreadLocalMap.access$000([email protected]/ThreadLocal.java:298)
        at java.lang.ThreadLocal.get([email protected]/ThreadLocal.java:163)
        at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onIncompleteFlush(SslConnection.java:547)
        at org.eclipse.jetty.io.AbstractEndPoint$2.onIncompleteFlush(AbstractEndPoint.java:54)
        at org.eclipse.jetty.io.WriteFlusher.write(WriteFlusher.java:332)
        at org.eclipse.jetty.io.AbstractEndPoint.write(AbstractEndPoint.java:380)
        at org.eclipse.jetty.server.HttpConnection$SendCallback.process(HttpConnection.java:804)
        at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:241)
        at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:224)

[gregw]

@sbordet The /jetty-9.4.x-2233-SslFlushTryAgain-2 branch is much improved, but currently failing org.eclipse.jetty.http.client.HttpClientTest.testClientCannotValidateServerCertificate frequently. Would you mind having a bit of a look at the branch and this test in particular.

@joakime the branch is probably good enough to try on windows and java-11 if you have time.

[gregw]

Fixed by #2726

[pavanpatel20]

We are also facing same issue in our jetty server (jetty-all-9.4.11.v20180605-uber) and jetty threads are taking 300% to 400% CPU. This is not happening in all the servers, but in just one server. From this bug thread I understand that the fix is available in 9.4.12. But before upgrade need information on how to reproduce this issue. As this issue happened just once, we are bit confused how we will test our server after upgrading to 9.4.12 to validate that issue is fixed. Please provide more information on what are the possible causes of jetty thread entering in this state.

"EndPoint-98" #98 prio=5 os_prio=0 tid=0x00007ff4f1171000 nid=0x3978 runnable [0x00007ff44a1dd000]
java.lang.Thread.State: RUNNABLE
at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onIncompleteFlush(SslConnection.java:545)
at org.eclipse.jetty.io.AbstractEndPoint$2.onIncompleteFlush(AbstractEndPoint.java:54)
at org.eclipse.jetty.io.WriteFlusher.write(WriteFlusher.java:332)
at org.eclipse.jetty.io.AbstractEndPoint.write(AbstractEndPoint.java:380)
at org.eclipse.jetty.server.HttpConnection$SendCallback.process(HttpConnection.java:804)
at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:241)
at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:224)
at org.eclipse.jetty.server.HttpConnection.send(HttpConnection.java:538)
at org.eclipse.jetty.server.HttpChannel.sendResponse(HttpChannel.java:795)
at org.eclipse.jetty.server.HttpChannel.write(HttpChannel.java:846)
at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:240)
at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:216)
at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:515)
at org.glassfish.jersey.servlet.internal.ResponseWriter$NonCloseableOutputStreamWrapper.write(ResponseWriter.java:303)
at org.glassfish.jersey.message.internal.CommittingOutputStream.write(CommittingOutputStream.java:229)
at org.glassfish.jersey.message.internal.WriterInterceptorExecutor$UnCloseableOutputStream.write(WriterInterceptorExecutor.java:299)
at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
at sun.nio.cs.StreamEncoder.implWrite(StreamEncoder.java:282)
at sun.nio.cs.StreamEncoder.write(StreamEncoder.java:125)

• locked <0x00000005c72fd980> (a java.io.OutputStreamWriter)
  at sun.nio.cs.StreamEncoder.write(StreamEncoder.java:135)
  at java.io.OutputStreamWriter.write(OutputStreamWriter.java:220)
  at org.glassfish.jersey.message.internal.ReaderWriter.writeToAsString(ReaderWriter.java:192)

[gregw]

If you are to upgrade, you should upgrade to 9.4.27 (or the soon to be released 9.4.28)
The issue has a complex cause due to the SSL conversation requirements that sometimes you need to read before writing or write before reading. The issue was some incorrect handling when these counter flows were blocked and had to be retried.

I don't know of anyway to reproduce in the wild on an arbitrary instance of the server running an arbitrary application.