Bug 63682

Summary: Async servlet over HTTP/2 non-blocking write hanging on certain flow control window update pattern from client
Product: Tomcat 9 Reporter: Dapeng Zhang <zdapeng>
Component: ServletAssignee: Tomcat Developers Mailing List <dev>
Status: RESOLVED FIXED    
Severity: normal    
Priority: P2    
Version: 9.0.21   
Target Milestone: -----   
Hardware: PC   
OS: Linux   

Description Dapeng Zhang 2019-08-22 00:36:14 UTC
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
Comment 1 Mark Thomas 2019-09-13 15:00:15 UTC
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.
Comment 2 Mark Thomas 2019-09-13 16:00:35 UTC
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
Comment 3 Dapeng Zhang 2019-09-16 21:28:44 UTC
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.