Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Http2Exception: Flow control window exceeded for stream: 0 when sending a ~64 KiB attachment #4814

Closed
ppalaga opened this issue Aug 20, 2023 · 8 comments

Comments

@ppalaga
Copy link

ppalaga commented Aug 20, 2023

Version

Reproducible on Vert.x Core 4.4.4 (Quarkus 3.3.0, 3.2.4), Vert.x Core 4.4.2 (Quarkus 3.1), Vert.x Core 4.4.1 (Quarkus 3.0)

It works on the following versions: Core 4.3.7 (Quarkus 2.16)

Context

There are two slightly different ways to reproduce the issue. Both are present in quarkiverse/quarkus-cxf#974

  1. Send an attachment over 64 KiB - see MtomTest.largeAttachment() in added getters to HttpServerResponse #971
  2. Soak the endpoint with requests slightly under 64 KiB - see MtomTest.soak() in added getters to HttpServerResponse #971

In both cases, the stack trace (on the server side) is the following:

WARN  [org.apa.cxf.pha.PhaseInterceptorChain] (executor-thread-1) Interceptor for {https://quarkiverse.github.io/quarkiverse-docs/quarkus-cxf/test/mtom}MtomService has thrown exception, unwinding now: java.lang.RuntimeException: java.io.IOException: java.io.IOException: io.netty.handler.codec.http2.Http2Exception: Flow control window exceeded for stream: 0
        at org.apache.cxf.attachment.LazyAttachmentCollection$1.hasNext(LazyAttachmentCollection.java:108)
        at org.apache.cxf.binding.soap.saaj.SAAJInInterceptor.handleMessage(SAAJInInterceptor.java:209)
        at org.apache.cxf.jaxws.handler.soap.SOAPMessageContextImpl.getMessage(SOAPMessageContextImpl.java:79)
        at org.apache.cxf.jaxws.handler.soap.SOAPHandlerInterceptor.getOpQName(SOAPHandlerInterceptor.java:318)
        at org.apache.cxf.jaxws.handler.AbstractJAXWSHandlerInterceptor.setupBindingOperationInfo(AbstractJAXWSHandlerInterceptor.java:110)
        at org.apache.cxf.jaxws.handler.soap.SOAPHandlerInterceptor.createProtocolMessageContext(SOAPHandlerInterceptor.java:253)
        at org.apache.cxf.jaxws.handler.soap.SOAPHandlerInterceptor.handleMessageInternal(SOAPHandlerInterceptor.java:158)
        at org.apache.cxf.jaxws.handler.soap.SOAPHandlerInterceptor.handleMessage(SOAPHandlerInterceptor.java:121)
        at org.apache.cxf.jaxws.handler.soap.SOAPHandlerInterceptor.handleMessage(SOAPHandlerInterceptor.java:70)
        at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:307)
        at org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:121)
        at org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(AbstractHTTPDestination.java:265)
        at org.apache.cxf.transport.servlet.ServletController.invokeDestination(ServletController.java:233)
        at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:207)
        at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:159)
        at io.quarkiverse.cxf.transport.CxfHandler.process(CxfHandler.java:245)
        at io.quarkiverse.cxf.transport.CxfHandler.handle(CxfHandler.java:182)
        at io.quarkiverse.cxf.transport.CxfHandler.handle(CxfHandler.java:46)
        at io.vertx.ext.web.impl.BlockingHandlerDecorator.lambda$handle$0(BlockingHandlerDecorator.java:48)
        at io.vertx.core.impl.ContextBase.lambda$null$0(ContextBase.java:137)
        at io.vertx.core.impl.ContextInternal.dispatch(ContextInternal.java:264)
        at io.vertx.core.impl.ContextBase.lambda$executeBlocking$1(ContextBase.java:135)
        at io.quarkus.vertx.core.runtime.VertxCoreRecorder$14.runWith(VertxCoreRecorder.java:577)
        at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2513)
        at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1538)
        at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
        at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: java.io.IOException: java.io.IOException: io.netty.handler.codec.http2.Http2Exception: Flow control window exceeded for stream: 0
        at io.quarkus.vertx.http.runtime.VertxInputStream$VertxBlockingInput.readBlocking(VertxInputStream.java:255)
        at io.quarkus.vertx.http.runtime.VertxInputStream.readIntoBuffer(VertxInputStream.java:122)
        at io.quarkus.vertx.http.runtime.VertxInputStream.read(VertxInputStream.java:84)
        at io.quarkiverse.cxf.transport.VertxHttpServletRequest$1.read(VertxHttpServletRequest.java:122)
        at java.base/java.io.FilterInputStream.read(FilterInputStream.java:132)
        at java.base/java.io.FilterInputStream.read(FilterInputStream.java:132)
        at java.base/java.io.PushbackInputStream.read(PushbackInputStream.java:182)
        at org.apache.cxf.attachment.MimeBodyPartInputStream.read(MimeBodyPartInputStream.java:80)
        at java.base/java.io.InputStream.read(InputStream.java:218)
        at org.apache.cxf.attachment.DelegatingInputStream.read(DelegatingInputStream.java:95)
        at org.apache.cxf.helpers.IOUtils.copy(IOUtils.java:222)
        at org.apache.cxf.helpers.IOUtils.copy(IOUtils.java:179)
        at org.apache.cxf.attachment.AttachmentDeserializer.cache(AttachmentDeserializer.java:268)
        at org.apache.cxf.attachment.AttachmentDeserializer.cacheStreamedAttachments(AttachmentDeserializer.java:241)
        at org.apache.cxf.attachment.AttachmentDeserializer.readNext(AttachmentDeserializer.java:222)
        at org.apache.cxf.attachment.LazyAttachmentCollection$1.hasNext(LazyAttachmentCollection.java:101)
        ... 28 more
Caused by: java.io.IOException: io.netty.handler.codec.http2.Http2Exception: Flow control window exceeded for stream: 0
        at io.quarkus.vertx.http.runtime.VertxInputStream$VertxBlockingInput$2.handle(VertxInputStream.java:202)
        at io.quarkus.vertx.http.runtime.VertxInputStream$VertxBlockingInput$2.handle(VertxInputStream.java:198)
        at io.vertx.core.impl.ContextInternal.dispatch(ContextInternal.java:264)
        at io.vertx.core.http.impl.HttpEventHandler.handleException(HttpEventHandler.java:89)
        at io.vertx.core.http.impl.Http2ServerRequest.notifyException(Http2ServerRequest.java:133)
        at io.vertx.core.http.impl.Http2ServerRequest.handleException(Http2ServerRequest.java:118)
        at io.vertx.core.http.impl.Http2ServerStream.handleException(Http2ServerStream.java:177)
        at io.vertx.core.http.impl.Http2ConnectionBase.lambda$onConnectionError$1(Http2ConnectionBase.java:120)
        at io.vertx.core.impl.ContextInternal.dispatch(ContextInternal.java:264)
        at io.vertx.core.impl.ContextInternal.dispatch(ContextInternal.java:246)
        at io.vertx.core.http.impl.Http2ConnectionBase.onConnectionError(Http2ConnectionBase.java:120)
        at io.vertx.core.http.impl.VertxHttp2ConnectionHandler.onConnectionError(VertxHttp2ConnectionHandler.java:158)
        at io.netty.handler.codec.http2.Http2ConnectionHandler.onError(Http2ConnectionHandler.java:654)
        at io.netty.handler.codec.http2.Http2ConnectionHandler.exceptionCaught(Http2ConnectionHandler.java:580)
        at io.vertx.core.http.impl.VertxHttp2ConnectionHandler.exceptionCaught(VertxHttp2ConnectionHandler.java:117)
        at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:346)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:447)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
        at io.vertx.core.http.impl.Http1xUpgradeToH2CHandler.channelRead(Http1xUpgradeToH2CHandler.java:133)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
        at io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:286)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
        at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:346)
        at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:333)
        at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:454)
        at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:290)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
        at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
        at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562)
        at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
        at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
        ... 2 more
Caused by: io.netty.handler.codec.http2.Http2Exception: Flow control window exceeded for stream: 0
        at io.netty.handler.codec.http2.Http2Exception.connectionError(Http2Exception.java:109)
        at io.netty.handler.codec.http2.Http2Exception.streamError(Http2Exception.java:152)
        at io.netty.handler.codec.http2.DefaultHttp2LocalFlowController$DefaultState.receiveFlowControlledFrame(DefaultHttp2LocalFlowController.java:429)
        at io.netty.handler.codec.http2.DefaultHttp2LocalFlowController.receiveFlowControlledFrame(DefaultHttp2LocalFlowController.java:273)
        at io.vertx.core.http.impl.VertxHttp2ConnectionHandler.channelRead(VertxHttp2ConnectionHandler.java:412)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)
        ... 30 more

Some observations:

Do you have a reproducer?

A reproducer is a simple project hosted on GitHub (or another forge supporting git clone operation) that has a build file that can be executed to reproduce the issue.

Reproducers are very helpful for contributors and will likely help them fixing your bug faster.

Steps to reproduce

git clone git@github.com:quarkiverse/quarkus-cxf.git
cd quarkus-cxf
mvnd clean install -DskipTests -Dquarkus.build.skip
cd integration-tests/mtom
mvnd test
@cescoffier
Copy link
Contributor

Do you know if the connection is using TLS? (h2 vs h2c)

@ppalaga
Copy link
Author

ppalaga commented Aug 20, 2023

The test does not set any certs on the server side. That implies h2c, I guess?

@vietj
Copy link
Member

vietj commented Aug 20, 2023

sounds like #4802

@vietj vietj added this to the 4.4.5 milestone Aug 20, 2023
@cescoffier
Copy link
Contributor

It's what I was thinking too (so my question about h2c). However, the stack trace is very different and the fact that it was working before may indicate it's something else.

@ppalaga
Copy link
Author

ppalaga commented Aug 21, 2023

Thanks for the suggestion, @vietj!

I have cherry-picked 322d095 on top of 4.4.4, I have rebuilt vert.x and then I re-run the test.

The soak test failed much later on round 2205 and the error message is fully different:

$ mvnd clean test -Dtest=MtomTest#soak
...
[INFO] [stdout] 2023-08-21 09:51:31,536 INFO  [io.qua.cxf.it.ws.mto.ser.MtomServiceImpl] (executor-thread-1) Received 64647 bytes of content type application/octet-stream
[INFO] [stdout] 2023-08-21 09:51:31,539 INFO  [io.qua.cxf.it.ws.mto.ser.MtomTest] (main) Soaking with 64647 bytes, round 2205
[ERROR] unable to create native thread: possibly out of memory or process/resource limits reached
[INFO] 
[INFO] Results:
[INFO] 
[INFO] Tests run: 0, Failures: 0, Errors: 0, Skipped: 0
[INFO] 
[WARN] Corrupted channel by directly writing to native stream in forked JVM 1. See FAQ web page and the dump file /home/ppalaga/orgs/cxf/quarkiverse-cxf/integration-tests/mtom/target/surefire-reports/2023-08-21T09-49-34_678-jvmRun1.dumpstream
[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time:  39.941 s (Wall Clock)
[INFO] Finished at: 2023-08-21T09:51:32+02:00
[INFO] ------------------------------------------------------------------------
[ERROR] Failed to execute goal org.apache.maven.plugins:maven-surefire-plugin:3.1.2:test (default-test) on project quarkus-cxf-integration-test-mtom: 
[ERROR] 
[ERROR] Please refer to /home/ppalaga/orgs/cxf/quarkiverse-cxf/integration-tests/mtom/target/surefire-reports for the individual test results.
[ERROR] Please refer to dump files (if any exist) [date].dump, [date]-jvmRun[N].dump and [date].dumpstream.
[ERROR] There was an error in the forked process
[ERROR] unable to create native thread: possibly out of memory or process/resource limits reached
[ERROR] org.apache.maven.surefire.booter.SurefireBooterForkException: There was an error in the forked process
[ERROR] unable to create native thread: possibly out of memory or process/resource limits reached
[ERROR]         at org.apache.maven.plugin.surefire.booterclient.ForkStarter.fork(ForkStarter.java:628)
[ERROR]         at org.apache.maven.plugin.surefire.booterclient.ForkStarter.run(ForkStarter.java:285)
[ERROR]         at org.apache.maven.plugin.surefire.booterclient.ForkStarter.run(ForkStarter.java:250)
[ERROR]         at org.apache.maven.plugin.surefire.AbstractSurefireMojo.executeProvider(AbstractSurefireMojo.java:1203)
[ERROR]         at org.apache.maven.plugin.surefire.AbstractSurefireMojo.executeAfterPreconditionsChecked(AbstractSurefireMojo.java:1055)
[ERROR]         at org.apache.maven.plugin.surefire.AbstractSurefireMojo.execute(AbstractSurefireMojo.java:871)
[ERROR]         at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:126)
[ERROR]         at org.apache.maven.lifecycle.internal.MojoExecutor.doExecute2(MojoExecutor.java:342)
[ERROR]         at org.apache.maven.lifecycle.internal.MojoExecutor.doExecute(MojoExecutor.java:330)
[ERROR]         at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:213)
[ERROR]         at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:175)
[ERROR]         at org.apache.maven.lifecycle.internal.MojoExecutor.access$000(MojoExecutor.java:76)
[ERROR]         at org.apache.maven.lifecycle.internal.MojoExecutor$1.run(MojoExecutor.java:163)
[ERROR]         at org.apache.maven.buildcache.BuildCacheMojosExecutionStrategy.execute(BuildCacheMojosExecutionStrategy.java:130)
[ERROR]         at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:160)
[ERROR]         at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:105)
[ERROR]         at io.takari.maven.builder.smart.SmartBuilderImpl.buildProject(SmartBuilderImpl.java:204)
[ERROR]         at io.takari.maven.builder.smart.SmartBuilderImpl$ProjectBuildTask.run(SmartBuilderImpl.java:78)
[ERROR]         at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
[ERROR]         at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
[ERROR]         at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
[ERROR]         at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
[ERROR]         at java.base/java.lang.Thread.run(Thread.java:833)

@vietj
Copy link
Member

vietj commented Aug 21, 2023

the issue does not clearly indicates the problem you should look at the JVM dump

@ppalaga
Copy link
Author

ppalaga commented Aug 21, 2023

The largeAttachment test (that gradually increments the size of the payload) passes. But it only does 1022 iterations, so when it would do more, maybe the resource limits would hit as well.

@ppalaga
Copy link
Author

ppalaga commented Aug 21, 2023

the issue does not clearly indicates the problem you should look at the JVM dump

Yes, the issue with the limits is definitely different from the one reported initially. I need to investigate it further.
The original issue can be considered solved as a duplicate of #4802 , IMO.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

3 participants