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: > > > >> This is an automated email from the ASF dual-hosted git repository. > >> > >> markt pushed a commit to branch master > >> in repository https://gitbox.apache.org/repos/asf/tomcat.git > >> > >> > >> The following commit(s) were added to refs/heads/master by this push: > >> new 6d3c117 Fix the HTTP/2 equivalent of swallowInput > >> 6d3c117 is described below > >> > >> 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. Rémy > > Mark > > > > > > Rémy > > > > > >> --- > >> java/org/apache/coyote/AbstractProcessor.java | 7 +++++-- > >> java/org/apache/coyote/AbstractProcessorLight.java | 10 +++++++-- > >> .../apache/coyote/http2/LocalStrings.properties | 1 + > >> java/org/apache/coyote/http2/Stream.java | 2 +- > >> java/org/apache/coyote/http2/StreamProcessor.java | 24 > >> +++++++++++++++++++++- > >> webapps/docs/changelog.xml | 5 +++++ > >> 6 files changed, 43 insertions(+), 6 deletions(-) > >> > >> diff --git a/java/org/apache/coyote/AbstractProcessor.java > >> b/java/org/apache/coyote/AbstractProcessor.java > >> index 205a789..e7909ba 100644 > >> --- a/java/org/apache/coyote/AbstractProcessor.java > >> +++ b/java/org/apache/coyote/AbstractProcessor.java > >> @@ -197,7 +197,7 @@ public abstract class AbstractProcessor extends > >> AbstractProcessorLight implement > >> > >> > >> @Override > >> - public final SocketState dispatch(SocketEvent status) { > >> + public final SocketState dispatch(SocketEvent status) throws > >> IOException { > >> > >> if (status == SocketEvent.OPEN_WRITE && > >> response.getWriteListener() != null) { > >> asyncStateMachine.asyncOperation(); > >> @@ -950,6 +950,9 @@ public abstract class AbstractProcessor extends > >> AbstractProcessorLight implement > >> * > >> * @return The state to return for the socket once the clean-up for > >> the > >> * current request has completed > >> + * > >> + * @throws IOException If an I/O error occurs while attempting to > end > >> the > >> + * request > >> */ > >> - protected abstract SocketState dispatchEndRequest(); > >> + protected abstract SocketState dispatchEndRequest() throws > >> IOException; > >> } > >> diff --git a/java/org/apache/coyote/AbstractProcessorLight.java > >> b/java/org/apache/coyote/AbstractProcessorLight.java > >> index 340c986..7a46c79 100644 > >> --- a/java/org/apache/coyote/AbstractProcessorLight.java > >> +++ b/java/org/apache/coyote/AbstractProcessorLight.java > >> @@ -152,10 +152,16 @@ public abstract class AbstractProcessorLight > >> implements Processor { > >> * Uses currently include Servlet 3.0 Async and HTTP upgrade > >> connections. > >> * Further uses may be added in the future. These will typically > >> start as > >> * HTTP requests. > >> + * > >> * @param status The event to process > >> - * @return the socket state > >> + * > >> + * @return The state the caller should put the socket in when this > >> method > >> + * returns > >> + * > >> + * @throws IOException If an I/O error occurs during the processing > >> of the > >> + * request > >> */ > >> - protected abstract SocketState dispatch(SocketEvent status); > >> + protected abstract SocketState dispatch(SocketEvent status) throws > >> IOException; > >> > >> protected abstract SocketState asyncPostProcess(); > >> > >> diff --git a/java/org/apache/coyote/http2/LocalStrings.properties > >> b/java/org/apache/coyote/http2/LocalStrings.properties > >> index c948c29..1320e60 100644 > >> --- a/java/org/apache/coyote/http2/LocalStrings.properties > >> +++ b/java/org/apache/coyote/http2/LocalStrings.properties > >> @@ -103,6 +103,7 @@ stream.reset.send=Connection [{0}], Stream [{1}], > >> Reset sent due to [{2}] > >> stream.trailerHeader.noEndOfStream=Connection [{0}], Stream [{1}], The > >> trailer headers did not include the end of stream flag > >> stream.writeTimeout=Timeout waiting for client to increase flow control > >> window to permit stream data to be written > >> > >> +streamProcessor.cancel=Connection [{0}], Stream [{1}], The remaining > >> request body is not required. > >> streamProcessor.error.connection=Connection [{0}], Stream [{1}], An > error > >> occurred during processing that was fatal to the connection > >> streamProcessor.error.stream=Connection [{0}], Stream [{1}], An error > >> occurred during processing that was fatal to the stream > >> streamProcessor.flushBufferedWrite.entry=Connection [{0}], Stream > [{1}], > >> Flushing buffered writes > >> diff --git a/java/org/apache/coyote/http2/Stream.java > >> b/java/org/apache/coyote/http2/Stream.java > >> index 3e64329..7337eb9 100644 > >> --- a/java/org/apache/coyote/http2/Stream.java > >> +++ b/java/org/apache/coyote/http2/Stream.java > >> @@ -676,7 +676,7 @@ class Stream extends AbstractStream implements > >> HeaderEmitter { > >> } > >> > >> > >> - private final boolean isInputFinished() { > >> + final boolean isInputFinished() { > >> return !state.isFrameTypePermitted(FrameType.DATA); > >> } > >> > >> diff --git a/java/org/apache/coyote/http2/StreamProcessor.java > >> b/java/org/apache/coyote/http2/StreamProcessor.java > >> index 6870926..90bf224 100644 > >> --- a/java/org/apache/coyote/http2/StreamProcessor.java > >> +++ b/java/org/apache/coyote/http2/StreamProcessor.java > >> @@ -361,6 +361,13 @@ class StreamProcessor extends AbstractProcessor { > >> setErrorState(ErrorState.CLOSE_NOW, e); > >> } > >> > >> + if (!isAsync()) { > >> + // If this is an async request then the request ends when > it > >> has > >> + // been completed. The AsyncContext is responsible for > calling > >> + // endRequest() in that case. > >> + endRequest(); > >> + } > >> + > >> if (sendfileState == SendfileState.PENDING) { > >> return SocketState.SENDFILE; > >> } else if (getErrorState().isError()) { > >> @@ -402,7 +409,22 @@ class StreamProcessor extends AbstractProcessor { > >> > >> > >> @Override > >> - protected final SocketState dispatchEndRequest() { > >> + protected final SocketState dispatchEndRequest() throws > IOException { > >> + endRequest(); > >> return SocketState.CLOSED; > >> } > >> + > >> + > >> + private void endRequest() throws IOException { > >> + if (!stream.isInputFinished()) { > >> + // The request has been processed but the request body has > >> not been > >> + // fully read. This typically occurs when Tomcat rejects an > >> upload > >> + // of some form (e.g. PUT or POST). Need to tell the client > >> not to > >> + // send any more data. > >> + StreamException se = new StreamException( > >> + sm.getString("streamProcessor.cancel", > >> stream.getConnectionId(), > >> + stream.getIdentifier()), Http2Error.CANCEL, > >> stream.getIdAsInt()); > >> + handler.sendStreamReset(se); > >> + } > >> + } > >> } > >> diff --git a/webapps/docs/changelog.xml b/webapps/docs/changelog.xml > >> index 7a7601c..ae3d717 100644 > >> --- a/webapps/docs/changelog.xml > >> +++ b/webapps/docs/changelog.xml > >> @@ -132,6 +132,11 @@ > >> query string present in the original HTTP/1.1 request is passed > >> to the > >> HTTP/2 request processing. (markt) > >> </fix> > >> + <fix> > >> + 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. (markt) > >> + </fix> > >> </changelog> > >> </subsection> > >> <subsection name="Jasper"> > >> > >> > >> --------------------------------------------------------------------- > >> To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org > >> For additional commands, e-mail: dev-h...@tomcat.apache.org > >> > >> > > > > > --------------------------------------------------------------------- > To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org > For additional commands, e-mail: dev-h...@tomcat.apache.org > >
