https://bz.apache.org/bugzilla/show_bug.cgi?id=63682
Bug ID: 63682
Summary: Async servlet over HTTP/2 non-blocking write hanging
on certain flow control window update pattern from
client
Product: Tomcat 9
Version: 9.0.21
Hardware: PC
OS: Linux
Status: NEW
Severity: normal
Priority: P2
Component: Servlet
Assignee: [email protected]
Reporter: [email protected]
Target Milestone: -----
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
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
