Steps to reproduce: $ git clone https://github.com/dapengzhang0/servlettest.git $ cd servlettest $ git checkout large-write $ ./gradlew clean test Basically the test client sends outbound HTTP/2 settings with INITIAL_WINDOW_SIZE=1048576 and then immediately sends outbound WINDOW_UPDATE with streamId=0 windowSizeIncrement=983041 before sending the request. The servlet responds with an initial 1048576 bytes, and then repeatedly responds with 4096 bytes. The test fails on both linux and mac. The test only fails for Tomcat 9.0.21+, but does not fail for Tomcat 9.0.20. The test does not fail for Undertow/Jetty. The log of a failed test is like following: LargeAsyncWriteTest > reproduceBug STANDARD_ERROR Aug 21, 2019 5:19:16 PM org.apache.coyote.http11.AbstractHttp11Protocol configureUpgradeProtocol INFO: The ["http-nio-auto-1"] connector has been configured to support HTTP upgrade to [h2c] Aug 21, 2019 5:19:16 PM org.apache.coyote.AbstractProtocol init INFO: Initializing ProtocolHandler ["http-nio-auto-1"] Aug 21, 2019 5:19:16 PM org.apache.catalina.core.StandardService startInternal INFO: Starting service [Tomcat] Aug 21, 2019 5:19:16 PM org.apache.catalina.core.StandardEngine startInternal INFO: Starting Servlet engine: [Apache Tomcat/9.0.21] Aug 21, 2019 5:19:17 PM org.apache.coyote.AbstractProtocol start INFO: Starting ProtocolHandler ["http-nio-auto-1-44507"] Sending request(s)... Aug 21, 2019 5:19:17 PM io.netty.handler.codec.http2.Http2FrameLogger logSettings INFO: [id: 0x913e4c7e, L:/127.0.0.1:51738 - R:/127.0.0.1:44507] OUTBOUND SETTINGS: ack=false settings={INITIAL_WINDOW_SIZE=1048576} Aug 21, 2019 5:19:17 PM io.netty.handler.codec.http2.Http2FrameLogger logWindowsUpdate INFO: [id: 0x913e4c7e, L:/127.0.0.1:51738 - R:/127.0.0.1:44507] OUTBOUND WINDOW_UPDATE: streamId=0 windowSizeIncrement=983041 Aug 21, 2019 5:19:17 PM io.netty.handler.codec.http2.Http2FrameLogger logHeaders INFO: [id: 0x913e4c7e, L:/127.0.0.1:51738 - R:/127.0.0.1:44507] OUTBOUND HEADERS: streamId=3 headers=DefaultHttp2Headers[:path: /large_async_write, :method: GET, :scheme: http, :authority: 127.0.0.1:44507, accept-encoding: gzip, accept-encoding: deflate] streamDependency=0 weight=16 exclusive=false padding=0 endStream=true Aug 21, 2019 5:19:17 PM io.netty.handler.codec.http2.Http2FrameLogger logSettings INFO: [id: 0x913e4c7e, L:/127.0.0.1:51738 - R:/127.0.0.1:44507] INBOUND SETTINGS: ack=false settings={MAX_CONCURRENT_STREAMS=100} Aug 21, 2019 5:19:17 PM io.netty.handler.codec.http2.Http2FrameLogger logSettingsAck INFO: [id: 0x913e4c7e, L:/127.0.0.1:51738 - R:/127.0.0.1:44507] OUTBOUND SETTINGS: ack=true Aug 21, 2019 5:19:17 PM io.netty.handler.codec.http2.Http2FrameLogger logSettingsAck INFO: [id: 0x913e4c7e, L:/127.0.0.1:51738 - R:/127.0.0.1:44507] INBOUND SETTINGS: ack=true Aug 21, 2019 5:19:17 PM io.netty.handler.codec.http2.Http2FrameLogger logPing INFO: [id: 0x913e4c7e, L:/127.0.0.1:51738 - R:/127.0.0.1:44507] INBOUND PING: ack=false bytes=1 Aug 21, 2019 5:19:17 PM io.netty.handler.codec.http2.Http2FrameLogger logPingAck INFO: [id: 0x913e4c7e, L:/127.0.0.1:51738 - R:/127.0.0.1:44507] OUTBOUND PING: ack=true bytes=1 onWritePossible() ENTRY Send out 1048576 bytes Aug 21, 2019 5:19:17 PM io.netty.handler.codec.http2.Http2FrameLogger logHeaders INFO: [id: 0x913e4c7e, L:/127.0.0.1:51738 - R:/127.0.0.1:44507] INBOUND HEADERS: streamId=3 headers=DefaultHttp2Headers[:status: 200, content-type: application/binary, date: Thu, 22 Aug 2019 00:19:17 GMT] padding=0 endStream=false Send out 4096 bytes Send out 4096 bytes onWritePossible() EXIT, output stream becomes not ready Aug 21, 2019 5:19:17 PM io.netty.handler.codec.http2.Http2FrameLogger logData INFO: [id: 0x913e4c7e, L:/127.0.0.1:51738 - R:/127.0.0.1:44507] INBOUND DATA: streamId=3 padding=0 endStream=false length=8192 bytes=00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000... Aug 21, 2019 5:19:17 PM io.netty.handler.codec.http2.Http2FrameLogger logData INFO: [id: 0x913e4c7e, L:/127.0.0.1:51738 - R:/127.0.0.1:44507] INBOUND DATA: streamId=3 padding=0 endStream=false length=8192 bytes=00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000... ... repeated INBOUND DATA log ... Aug 21, 2019 5:19:17 PM io.netty.handler.codec.http2.Http2FrameLogger logData INFO: [id: 0x913e4c7e, L:/127.0.0.1:51738 - R:/127.0.0.1:44507] INBOUND DATA: streamId=3 padding=0 endStream=false length=8192 bytes=00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000... Aug 21, 2019 5:19:17 PM io.netty.handler.codec.http2.Http2FrameLogger logWindowsUpdate INFO: [id: 0x913e4c7e, L:/127.0.0.1:51738 - R:/127.0.0.1:44507] OUTBOUND WINDOW_UPDATE: streamId=0 windowSizeIncrement=524288 Aug 21, 2019 5:19:17 PM io.netty.handler.codec.http2.Http2FrameLogger logWindowsUpdate INFO: [id: 0x913e4c7e, L:/127.0.0.1:51738 - R:/127.0.0.1:44507] OUTBOUND WINDOW_UPDATE: streamId=3 windowSizeIncrement=524288 Aug 21, 2019 5:19:17 PM io.netty.handler.codec.http2.Http2FrameLogger logData INFO: [id: 0x913e4c7e, L:/127.0.0.1:51738 - R:/127.0.0.1:44507] INBOUND DATA: streamId=3 padding=0 endStream=false length=8192 bytes=00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000... Aug 21, 2019 5:19:17 PM io.netty.handler.codec.http2.Http2FrameLogger logData INFO: [id: 0x913e4c7e, L:/127.0.0.1:51738 - R:/127.0.0.1:44507] INBOUND DATA: streamId=3 padding=0 endStream=false length=8192 bytes=00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000... ... repeated INBOUND DATA log ... Aug 21, 2019 5:19:17 PM io.netty.handler.codec.http2.Http2FrameLogger logData INFO: [id: 0x913e4c7e, L:/127.0.0.1:51738 - R:/127.0.0.1:44507] INBOUND DATA: streamId=3 padding=0 endStream=false length=8192 bytes=00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000... Aug 21, 2019 5:19:17 PM io.netty.handler.codec.http2.Http2FrameLogger logData INFO: [id: 0x913e4c7e, L:/127.0.0.1:51738 - R:/127.0.0.1:44507] INBOUND DATA: streamId=3 padding=0 endStream=false length=8192 bytes=00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000... Aug 21, 2019 5:19:17 PM io.netty.handler.codec.http2.Http2FrameLogger logWindowsUpdate INFO: [id: 0x913e4c7e, L:/127.0.0.1:51738 - R:/127.0.0.1:44507] OUTBOUND WINDOW_UPDATE: streamId=0 windowSizeIncrement=524288 Aug 21, 2019 5:19:17 PM io.netty.handler.codec.http2.Http2FrameLogger logWindowsUpdate INFO: [id: 0x913e4c7e, L:/127.0.0.1:51738 - R:/127.0.0.1:44507] OUTBOUND WINDOW_UPDATE: streamId=3 windowSizeIncrement=524288 Aug 21, 2019 5:20:17 PM org.apache.coyote.AbstractProtocol pause INFO: Pausing ProtocolHandler ["http-nio-auto-1-44507"] Aug 21, 2019 5:20:17 PM org.apache.catalina.core.StandardService stopInternal INFO: Stopping service [Tomcat] Aug 21, 2019 5:20:19 PM org.apache.coyote.AbstractProtocol stop INFO: Stopping ProtocolHandler ["http-nio-auto-1-44507"] LargeAsyncWriteTest > reproduceBug FAILED java.lang.IllegalStateException at LargeAsyncWriteTest.java:97
Sorry I haven't responded to this for a while. It has been on the TODO list for before the next release and I have been working on it on and off but I only made progress today. I believe I have identified the root cause. Hopefully I'll have a patch for this shortly.
Thanks for the test case. There was a timing factor at play here that would have made this rather tricky to track down without the test case. Fixed in: - master for 9.0.25 onwards - 8.5.x for 8.5.46 onwards
Thank you Mark for the fix! I can verify the issue is fixed by testing my project where the issue was originally found. BTW I also had been working on and off on making a reproducible minimum test case.