You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@tomcat.apache.org by bu...@apache.org on 2019/08/22 00:36:14 UTC
[Bug 63682] New: Async servlet over HTTP/2 non-blocking write
hanging on certain flow control window update pattern from client
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: dev@tomcat.apache.org
Reporter: zdapeng@google.com
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: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 63682] Async servlet over HTTP/2 non-blocking write hanging on
certain flow control window update pattern from client
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=63682
--- Comment #3 from Dapeng Zhang <zd...@google.com> ---
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.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 63682] Async servlet over HTTP/2 non-blocking write hanging on
certain flow control window update pattern from client
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=63682
Mark Thomas <ma...@apache.org> changed:
What |Removed |Added
----------------------------------------------------------------------------
Resolution|--- |FIXED
Status|NEW |RESOLVED
--- Comment #2 from Mark Thomas <ma...@apache.org> ---
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
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 63682] Async servlet over HTTP/2 non-blocking write hanging on
certain flow control window update pattern from client
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=63682
--- Comment #1 from Mark Thomas <ma...@apache.org> ---
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.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org