On 08/04/2019 14:16, Rémy Maucherat wrote: > On Mon, Apr 8, 2019 at 11:05 AM Mark Thomas <ma...@apache.org> wrote: >> On 08/04/2019 09:57, Rémy Maucherat wrote: >>> On Sun, Apr 7, 2019 at 10:42 PM <ma...@apache.org> wrote:
<snip/> >>>> commit 6d3c117384c11f1bfd9393fb1484cd5a708a8245 >>>> Author: Mark Thomas <ma...@apache.org> >>>> AuthorDate: Sun Apr 7 21:39:15 2019 +0100 >>>> >>>> Fix the HTTP/2 equivalent of swallowInput >>>> >>>> When Tomcat writes a final response without reading all of an HTTP/2 >>>> request, reset the stream to inform the client that the remaining >>>> request body is not required. >>>> >>> >>> After this change, I do get this CI failure "reliably": >>> >> https://ci.apache.org/projects/tomcat/tomcat9/logs/4183/TEST-org.apache.coyote.http2.TestHttp2Section_6_8.NIO2.txt >>> >>> Unsure if this is relatively normal or a bug. >> >> I saw that failure but couldn't reproduce it locally. I'll take another >> look. >> > > It seems ok to ignore it for now, it doesn't really look related although I > didn't get it before. > > With logging, it goes like this at the end of the test: > FAIL: > 08-Apr-2019 10:50:18.982 FINE [main] > org.apache.coyote.http2.HpackEncoder.encode Encoding header [:method] with > value [GET] > 08-Apr-2019 10:50:18.982 FINE [main] > org.apache.coyote.http2.HpackEncoder.encode Encoding header [:scheme] with > value [http] > 08-Apr-2019 10:50:18.982 FINE [main] > org.apache.coyote.http2.HpackEncoder.encode Encoding header [:path] with > value [/simple] > 08-Apr-2019 10:50:18.982 FINE [main] > org.apache.coyote.http2.HpackEncoder.encode Encoding header [:authority] > with value [localhost:41523] > 08-Apr-2019 10:50:18.982 FINE [main] > org.apache.coyote.http2.Http2Parser.validateFrame Connection [-1], Stream > [3], Frame type [HEADERS], Flags [4], Payload size [37] > 08-Apr-2019 10:50:18.982 FINE [http-nio2-127.0.0.1-auto-1-exec-4] > org.apache.coyote.http2.Http2Parser.validateFrame Connection [0], Stream > [5], Frame type [HEADERS], Flags [5], Payload size [4] > 08-Apr-2019 10:50:18.982 FINE [main] > org.apache.coyote.http2.Http2Parser.readHeaderPayload Connection [-1], > Stream [3], Processing headers payload of size [37] > 08-Apr-2019 10:50:18.983 FINE [main] > org.apache.coyote.http2.Http2Parser.swallow Connection [-1], Stream [3], > Swallowed [0] bytes > 08-Apr-2019 10:50:18.983 FINE [main] > org.apache.coyote.http2.Http2Parser.validateFrame Connection [-1], Stream > [3], Frame type [DATA], Flags [1], Payload size [8192] > 08-Apr-2019 10:50:18.983 FINE [main] > org.apache.coyote.http2.Http2Parser.readDataFrame Connection [-1], Stream > [3], Data length, [8192], Padding length [none] > 08-Apr-2019 10:50:18.983 FINE [main] > org.apache.coyote.http2.Http2Parser.swallow Connection [-1], Stream [3], > Swallowed [8192] bytes >>>>> 08-Apr-2019 10:50:18.983 FINE [main] > org.apache.coyote.http2.Http2Parser.validateFrame Connection [-1], Stream > [3], Frame type [RST], Flags [0], Payload size [4] > 08-Apr-2019 10:50:18.984 INFO [main] > org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler > ["http-nio2-127.0.0.1-auto-1-41523"] > 08-Apr-2019 10:50:18.984 INFO [main] > org.apache.catalina.core.StandardService.stopInternal Stopping service > [Tomcat] > 08-Apr-2019 10:50:18.996 INFO [main] > org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler > ["http-nio2-127.0.0.1-auto-1-41523"] > > vs PASS: > 08-Apr-2019 15:06:16.315 FINE [main] > org.apache.coyote.http2.HpackEncoder.encode Encoding header [:method] with > value [GET] > 08-Apr-2019 15:06:16.316 FINE [main] > org.apache.coyote.http2.HpackEncoder.encode Encoding header [:scheme] with > value [http] > 08-Apr-2019 15:06:16.317 FINE [main] > org.apache.coyote.http2.HpackEncoder.encode Encoding header [:path] with > value [/simple] > 08-Apr-2019 15:06:16.317 FINE [main] > org.apache.coyote.http2.HpackEncoder.encode Encoding header [:authority] > with value [localhost:34997] > 08-Apr-2019 15:06:16.318 FINE [main] > org.apache.coyote.http2.Http2Parser.validateFrame Connection [-1], Stream > [3], Frame type [HEADERS], Flags [4], Payload size [37] > 08-Apr-2019 15:06:16.318 FINE [http-nio2-127.0.0.1-auto-1-exec-6] > org.apache.coyote.http2.Http2Parser.validateFrame Connection [0], Stream > [5], Frame type [HEADERS], Flags [5], Payload size [4] > 08-Apr-2019 15:06:16.318 FINE [main] > org.apache.coyote.http2.Http2Parser.readHeaderPayload Connection [-1], > Stream [3], Processing headers payload of size [37] > 08-Apr-2019 15:06:16.319 FINE [main] > org.apache.coyote.http2.Http2Parser.swallow Connection [-1], Stream [3], > Swallowed [0] bytes > 08-Apr-2019 15:06:16.320 FINE [main] > org.apache.coyote.http2.Http2Parser.validateFrame Connection [-1], Stream > [3], Frame type [DATA], Flags [1], Payload size [8192] > 08-Apr-2019 15:06:16.320 FINE [main] > org.apache.coyote.http2.Http2Parser.readDataFrame Connection [-1], Stream > [3], Data length, [8192], Padding length [none] > 08-Apr-2019 15:06:16.321 FINE [main] > org.apache.coyote.http2.Http2Parser.swallow Connection [-1], Stream [3], > Swallowed [8192] bytes > 08-Apr-2019 15:06:16.358 FINE [http-nio2-127.0.0.1-auto-1-exec-4] > org.apache.coyote.http2.Http2UpgradeHandler.headersStart Connection [0], > Stream [5], Stream ignored as no new streams are permitted on this > connection > 08-Apr-2019 15:06:16.358 FINE [main] > org.apache.coyote.http2.Http2Parser.validateFrame Connection [-1], Stream > [0], Frame type [GOAWAY], Flags [0], Payload size [8] > 08-Apr-2019 15:06:16.359 FINE [http-nio2-127.0.0.1-auto-1-exec-4] > org.apache.coyote.http2.Http2Parser.readHeaderPayload Connection [0], > Stream [5], Processing headers payload of size [4] > 08-Apr-2019 15:06:16.359 FINE [http-nio2-127.0.0.1-auto-1-exec-4] > org.apache.coyote.http2.Http2Parser.swallow Connection [0], Stream [5], > Swallowed [0] bytes > 08-Apr-2019 15:06:16.359 INFO [main] > org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler > ["http-nio2-127.0.0.1-auto-1-34997"] > 08-Apr-2019 15:06:16.359 FINE [http-nio2-127.0.0.1-auto-1-exec-4] > org.apache.coyote.http2.Http2UpgradeHandler.upgradeDispatch Entry, > Connection [0], SocketStatus [OPEN_READ] > 08-Apr-2019 15:06:16.359 INFO [main] > org.apache.catalina.core.StandardService.stopInternal Stopping service > [Tomcat] > > So the server is reading a reset frame first when it fails I guess. It > doesn't seem broken to me overall. If you agree, maybe the test should > ignore the last frame or allow a reset as well ? > > Note: I don't get the failure with the new NIO async code. I'm not sure. Do you have the complete logs for those tests? I'd like to look at everything sent from the client to the server for stream 3. I'd got as far as thinking that the server wasn't (always) marking stream 3 as half-closed and my next steps are to try and figure out why. Mark --------------------------------------------------------------------- To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org For additional commands, e-mail: dev-h...@tomcat.apache.org
