Bug 58659 - Http2Parser.readFrame() hanging on an unconditional blocking read (TestHttp2Section_5_3 test)
Summary: Http2Parser.readFrame() hanging on an unconditional blocking read (TestHttp2S...
Status: RESOLVED FIXED
Alias: None
Product: Tomcat 9
Classification: Unclassified
Component: Catalina (show other bugs)
Version: 9.0.0.M1
Hardware: PC All
: P2 normal (vote)
Target Milestone: -----
Assignee: Tomcat Developers Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2015-11-27 08:53 UTC by Konstantin Kolinko
Modified: 2015-12-15 14:30 UTC (History)
0 users



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Konstantin Kolinko 2015-11-27 08:53:25 UTC
Trunk at revision 1716783

Buildbot run:
https://ci.apache.org/builders/tomcat-trunk/builds/690

Log file:
https://ci.apache.org/projects/tomcat/tomcat9/logs/logs/1716783/TEST-org.apache.coyote.http2.TestHttp2Section_5_3.NIO.txt

In TestHttp2Section_5_3.java there is a comment on lines 127-144:

// The loop below handles 0, 1 or 2 stream being blocked
<...>
// - If 2 streams are blocked the connection window will be set to one
//   but one byte will be permitted for both streams (due to rounding in
//   the allocation). The window size should be -1 (see below). Two
//   frames (one for each stream will be written) one of which will be
//   consumed by the client. The loop will start again and the Window
//   size incremented to zero. No data will be written by the streams
//   but the second data frame written in the last iteration of the loop
//   will be read. The loop will then exit since frames from both
//   streams will have been observed.

The sequence of events in while(!seen19 || !seen21) loop (line 147) on this test run was:
iteration 1: a body of stream 21 was read ("21-Body-1")
iteration 2: "parser.readFrame(true);" call blocks until it times out after waiting for 30 seconds

[[[
Testcase: testWeighting took 35.576 sec
	Caused an ERROR
Read timed out
java.net.SocketTimeoutException: Read timed out
	at java.net.SocketInputStream.socketRead0(Native Method)
	at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
	at java.net.SocketInputStream.read(SocketInputStream.java:170)
	at java.net.SocketInputStream.read(SocketInputStream.java:141)
	at org.apache.coyote.http2.Http2TestBase$TestInput.fill(Http2TestBase.java:720)
	at org.apache.coyote.http2.Http2Parser$Input.fill(Http2Parser.java:565)
	at org.apache.coyote.http2.Http2Parser.readFrame(Http2Parser.java:75)
	at org.apache.coyote.http2.Http2Parser.readFrame(Http2Parser.java:68)
	at org.apache.coyote.http2.TestHttp2Section_5_3.testWeighting(TestHttp2Section_5_3.java:149)
]]]

My concern is implementation of Http2Parser.readFrame() method.
It starts with unconditionally calling "input.fill(block, frameHeaderBuffer)" regardless of whether the frame bytes have already been read. I think it shall check whether the blocking read is necessary or if enough the data have already been received.

The comment that I cited says "but the second data frame written in the last iteration of the loop will be read". I think that because of unconditional call to input.fill() the thread will block reading for data, regardless of whether the second data frame has already been received.
Comment 1 Mark Thomas 2015-12-09 14:27:16 UTC
The root cause analysis here is wrong.

Data is not buffered in the Http2Parser, it is buffered in the SocketWrapper so the call to input.fill() in parser.readFrame() is correct.

Further analysis is required to work out why this is failing.
Comment 2 Mark Thomas 2015-12-15 11:11:33 UTC
I've found the problem. There is a deadlock. I'm working on a fix.
Comment 3 Mark Thomas 2015-12-15 14:30:56 UTC
This is fixed in 9.0.x for 9.0.0.M2 onwards.