Flaky test `testRequestIdleTimeout` with H2/H2C

[lorban]

Jetty version(s)
12.1.x

Description
org.eclipse.jetty.test.client.transport.HttpClientTest.testRequestIdleTimeout() running with H2 and H2C sometimes fails with:

java.util.concurrent.ExecutionException: java.nio.channels.ClosedChannelException
	at java.base/java.util.concurrent.CompletableFuture.wrapInExecutionException(CompletableFuture.java:345)
	at java.base/java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:440)
	at java.base/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2094)
	at org.eclipse.jetty.client.transport.HttpRequest.send(HttpRequest.java:731)
	at org.eclipse.jetty.test.client.transport.HttpClientTest.testRequestIdleTimeout(HttpClientTest.java:978)
	at java.base/java.lang.reflect.Method.invoke(Method.java:565)
	at java.base/java.util.Optional.ifPresent(Optional.java:178)
	at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:186)
	at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:214)
	at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:186)
	at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:186)
	at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:214)
	at java.base/java.util.Iterator.forEachRemaining(Iterator.java:133)
	at java.base/java.util.Spliterators$IteratorSpliterator.forEachRemaining(Spliterators.java:1939)
	at java.base/java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:803)
	at java.base/java.util.stream.ReferencePipeline$7$1FlatMap.accept(ReferencePipeline.java:293)
	at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:214)
	at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:214)
	at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:214)
	at java.base/java.util.Spliterators$ArraySpliterator.forEachRemaining(Spliterators.java:1024)
	at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:570)
	at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:560)
	at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:153)
	at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:176)
	at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:265)
	at java.base/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:632)
	at java.base/java.util.stream.ReferencePipeline$7$1FlatMap.accept(ReferencePipeline.java:293)
	at java.base/java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1716)
	at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:570)
	at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:560)
	at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:153)
	at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:176)
	at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:265)
	at java.base/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:632)
	at java.base/java.util.stream.ReferencePipeline$7$1FlatMap.accept(ReferencePipeline.java:293)
	at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:214)
	at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:214)
	at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:214)
	at java.base/java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1716)
	at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:570)
	at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:560)
	at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:153)
	at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:176)
	at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:265)
	at java.base/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:632)
	at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:511)
	at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1450)
	at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:2019)
	at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:187)
Caused by: java.nio.channels.ClosedChannelException
	at org.eclipse.jetty.http2.HTTP2Session$StreamsState.onShutdown(HTTP2Session.java:2173)
	at org.eclipse.jetty.http2.HTTP2Session.onShutdown(HTTP2Session.java:1206)
	at org.eclipse.jetty.http2.HTTP2Connection$HTTP2Producer.produce(HTTP2Connection.java:441)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.produceTask(AdaptiveExecutionStrategy.java:509)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:251)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.produce(AdaptiveExecutionStrategy.java:196)
	at org.eclipse.jetty.http2.HTTP2Connection.produce(HTTP2Connection.java:237)
	at org.eclipse.jetty.http2.HTTP2Connection.onFillable(HTTP2Connection.java:165)
	at org.eclipse.jetty.http2.HTTP2Connection$FillableCallback.succeeded(HTTP2Connection.java:592)
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105)
	at org.eclipse.jetty.io.ssl.SslConnection$SslEndPoint.onFillable(SslConnection.java:614)
	at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:415)
	at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:156)
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105)
	at org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:54)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:492)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.epcRunTask(AdaptiveExecutionStrategy.java:428)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:401)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:255)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.run(AdaptiveExecutionStrategy.java:204)
	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:317)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:1009)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1239)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1194)
	at java.base/java.lang.Thread.run(Thread.java:1474)

See: https://jenkins.webtide.net/job/jetty.project/job/jetty-12.1.x/1064/testReport/org.eclipse.jetty.test.client.transport/HttpClientTest/Parallel_Stage___Build___Test___JDK25___testRequestIdleTimeout_TransportType__4__H2/

[lorban]

This may be unrelated, but it looks like HttpChannelState might be used after being recycled when HttpStream.cancelSend() is used with H2: sometimes the assert _callbackCompleted in HttpChannelState.LastWriteCallback.completeLastWrite() does trigger, so I replaced it with if (!_callbackCompleted) throw new AssertionError("reuse after recycle, stream=" + _stream + " HttpChannelState=" + HttpChannelState.this); and I get this:

java.lang.AssertionError: reuse after recycle, stream=null HttpChannelState=oejsi.HttpChannelState@2cb46cd6[:handling=null,handled=false,send=SENDING,completed=false,request=null]
	at org.eclipse.jetty.server.internal.HttpChannelState$LastWriteCallback.completeLastWrite(HttpChannelState.java:793)
	at org.eclipse.jetty.server.internal.HttpChannelState$LastWriteCallback.failed(HttpChannelState.java:783)
	at org.eclipse.jetty.http2.server.internal.HttpStreamOverHTTP2.lambda$cancelSend$1(HttpStreamOverHTTP2.java:468)
	at org.eclipse.jetty.util.Callback$5.completed(Callback.java:259)
	at org.eclipse.jetty.util.Callback$Completing.succeeded(Callback.java:600)
	at org.eclipse.jetty.util.Callback$Nested.succeeded(Callback.java:651)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1604)
	at org.eclipse.jetty.http2.internal.HTTP2Flusher.finish(HTTP2Flusher.java:350)
	at org.eclipse.jetty.http2.internal.HTTP2Flusher.process(HTTP2Flusher.java:317)
	at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:377)
	at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:354)
	at org.eclipse.jetty.http2.HTTP2Session.frame(HTTP2Session.java:983)
	at org.eclipse.jetty.http2.HTTP2Session.flush(HTTP2Session.java:882)
	at org.eclipse.jetty.http2.server.internal.HttpStreamOverHTTP2.lambda$cancelSend$0(HttpStreamOverHTTP2.java:464)
	at org.eclipse.jetty.util.thread.Invocable$ReadyTask.run(Invocable.java:178)
	at org.eclipse.jetty.util.thread.Invocable$ReadyTask.run(Invocable.java:178)
	at org.eclipse.jetty.util.thread.SerializedInvoker$Link.run(SerializedInvoker.java:274)
	at org.eclipse.jetty.http2.server.internal.HttpStreamOverHTTP2$FailureTask.run(HttpStreamOverHTTP2.java:768)
	at org.eclipse.jetty.util.thread.ThreadPool.executeImmediately(ThreadPool.java:112)
	at org.eclipse.jetty.http2.server.internal.HTTP2ServerConnection.onStreamFailure(HTTP2ServerConnection.java:228)
	at org.eclipse.jetty.http2.server.HTTP2ServerConnectionFactory$HTTPServerSessionListener.onFailure(HTTP2ServerConnectionFactory.java:180)
	at org.eclipse.jetty.http2.server.HTTP2ServerConnectionFactory$HTTPServerSessionListener.onReset(HTTP2ServerConnectionFactory.java:167)
	at org.eclipse.jetty.http2.HTTP2Stream.notifyReset(HTTP2Stream.java:928)
	at org.eclipse.jetty.http2.HTTP2Stream.onReset(HTTP2Stream.java:635)
	at org.eclipse.jetty.http2.HTTP2Stream.process(HTTP2Stream.java:374)
	at org.eclipse.jetty.http2.HTTP2Session.onReset(HTTP2Session.java:426)
	at org.eclipse.jetty.http2.HTTP2Connection.onReset(HTTP2Connection.java:284)
	at org.eclipse.jetty.http2.parser.BodyParser.notifyReset(BodyParser.java:139)
	at org.eclipse.jetty.http2.parser.ResetBodyParser.onReset(ResetBodyParser.java:94)
	at org.eclipse.jetty.http2.parser.ResetBodyParser.parse(ResetBodyParser.java:61)
	at org.eclipse.jetty.http2.parser.Parser.parseBody(Parser.java:235)
	at org.eclipse.jetty.http2.parser.Parser.parse(Parser.java:162)
	at org.eclipse.jetty.http2.parser.ServerParser.parse(ServerParser.java:121)
	at org.eclipse.jetty.http2.HTTP2Connection$HTTP2Producer.produce(HTTP2Connection.java:390)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.produceTask(AdaptiveExecutionStrategy.java:509)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:251)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.produce(AdaptiveExecutionStrategy.java:196)
	at org.eclipse.jetty.http2.HTTP2Connection.produce(HTTP2Connection.java:237)
	at org.eclipse.jetty.http2.HTTP2Connection.onFillable(HTTP2Connection.java:165)
	at org.eclipse.jetty.http2.HTTP2Connection$FillableCallback.succeeded(HTTP2Connection.java:592)
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105)
	at org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:54)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:492)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.epcRunTask(AdaptiveExecutionStrategy.java:428)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:401)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:255)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.run(AdaptiveExecutionStrategy.java:204)
	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:317)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:1009)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1239)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1194)
	at java.base/java.lang.Thread.run(Thread.java:1474)

[lorban]

Even when the recycling of HTTP channels is disabled (by commenting out setRecycleHttpChannels(true) in HTTP2ServerConnection's constructor) the test still fails, so the above assertion error is an unrelated issue.