Using a http/2 client such as Java can cause jersey-rs based on grizzly-http to hang; Upgrade header handling issue? #6059
Description
I've observed the following stack trace in my program which prevents request processing from starting on Jersey side when the standard Java HttpClient attempts to talk with Jersey. The HTTP request looks like this, with h2c (the cleartext version of http/2) protocol attempted by the client:
PUT /Print/pdf HTTP/1.1
Connection: Upgrade, HTTP2-Settings
HTTP2-Settings: AAEAAEAAAAIAAAAAAAMAAAAAAAQBAAAAAAUAAEAAAAYABgAA
Upgrade: h2c
Content-Length: 355828
Host: print-test:8080
User-Agent: Java-http-client/21.0.9
Content-Type: application/json
There is also a very long JSON body which is elided here. On server side, it causes this timeout condition with the following stack trace:
tammi 20 12:42:08 print-test java[94843]: java.io.IOException: java.util.concurrent.TimeoutException
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.grizzly.nio.transport.TCPNIOTransportFilter.handleRead(TCPNIOTransportFilter.java:72)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.grizzly.filterchain.TransportFilter.handleRead(TransportFilter.java:133)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.grizzly.filterchain.ExecutorResolver$9.execute(ExecutorResolver.java:88)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:246)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:178)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.grizzly.filterchain.DefaultFilterChain.read(DefaultFilterChain.java:309)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.grizzly.filterchain.FilterChainContext.read(FilterChainContext.java:663)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.grizzly.http.io.InputBuffer.blockingRead(InputBuffer.java:1037)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.grizzly.http.server.io.ServerInputBuffer.blockingRead(ServerInputBuffer.java:70)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.grizzly.http.io.InputBuffer.fill(InputBuffer.java:1060)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.grizzly.http.io.InputBuffer.read(InputBuffer.java:307)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.grizzly.http.server.NIOInputStreamImpl.read(NIOInputStreamImpl.java:60)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.jersey.innate.io.InputStreamWrapper.read(InputStreamWrapper.java:55)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.jersey.innate.io.InputStreamWrapper.read(InputStreamWrapper.java:55)
tammi 20 12:42:08 print-test java[94843]: at com.fasterxml.jackson.core.json.UTF8StreamJsonParser._loadMore(UTF8StreamJsonParser.java:220)
tammi 20 12:42:08 print-test java[94843]: at com.fasterxml.jackson.core.json.UTF8StreamJsonParser._skipWSOrEnd2(UTF8StreamJsonParser.java:3110)
tammi 20 12:42:08 print-test java[94843]: at com.fasterxml.jackson.core.json.UTF8StreamJsonParser._skipWSOrEnd(UTF8StreamJsonParser.java:3105)
tammi 20 12:42:08 print-test java[94843]: at com.fasterxml.jackson.core.json.UTF8StreamJsonParser.nextToken(UTF8StreamJsonParser.java:716)
tammi 20 12:42:08 print-test java[94843]: at com.fasterxml.jackson.databind.ObjectReader._verifyNoTrailingTokens(ObjectReader.java:2247)
tammi 20 12:42:08 print-test java[94843]: at com.fasterxml.jackson.databind.ObjectReader._bind(ObjectReader.java:2104)
tammi 20 12:42:08 print-test java[94843]: at com.fasterxml.jackson.databind.ObjectReader.readValue(ObjectReader.java:1249)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.jersey.jackson.internal.jackson.jaxrs.base.ProviderBase.readFrom(ProviderBase.java:840)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.jersey.message.internal.ReaderInterceptorExecutor$TerminalReaderInterceptor.invokeReadFrom(ReaderInterceptorExecutor.java:236)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.jersey.message.internal.ReaderInterceptorExecutor$TerminalReaderInterceptor.aroundReadFrom(ReaderInterceptorExecutor.java:215)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.jersey.message.internal.ReaderInterceptorExecutor.proceed(ReaderInterceptorExecutor.java:135)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.jersey.server.internal.MappableExceptionWrapperInterceptor.aroundReadFrom(MappableExceptionWrapperInterceptor.java:49)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.jersey.message.internal.ReaderInterceptorExecutor.proceed(ReaderInterceptorExecutor.java:135)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.jersey.message.internal.MessageBodyFactory.readFrom(MessageBodyFactory.java:1072)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.jersey.message.internal.InboundMessageContext.readEntity(InboundMessageContext.java:657)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.jersey.server.ContainerRequest.readEntity(ContainerRequest.java:290)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.jersey.server.internal.inject.EntityParamValueParamProvider$EntityValueSupplier.apply(EntityParamValueParamProvider.java:73)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.jersey.server.internal.inject.EntityParamValueParamProvider$EntityValueSupplier.apply(EntityParamValueParamProvider.java:56)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.jersey.server.spi.internal.ParamValueFactoryWithSource.apply(ParamValueFactoryWithSource.java:50)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.jersey.server.spi.internal.ParameterValueHelper.getParameterValues(ParameterValueHelper.java:68)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$AbstractMethodParamInvoker.getParamValues(JavaResourceMethodDispatcherProvider.java:109)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$ResponseOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:176)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:93)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:478)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:400)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:81)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.jersey.server.ServerRuntime$1.run(ServerRuntime.java:274)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.jersey.internal.Errors$1.call(Errors.java:248)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.jersey.internal.Errors$1.call(Errors.java:244)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.jersey.internal.Errors.process(Errors.java:292)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.jersey.internal.Errors.process(Errors.java:274)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.jersey.internal.Errors.process(Errors.java:244)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:266)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:253)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:696)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.jersey.grizzly2.httpserver.GrizzlyHttpContainer.service(GrizzlyHttpContainer.java:367)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.grizzly.http.server.HttpHandler$1.run(HttpHandler.java:190)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:535)
tammi 20 12:42:08 print-test java[94843]: at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:515)
tammi 20 12:42:08 print-test java[94843]: at java.base/java.lang.Thread.run(Thread.java:1474)
The central problem seems to be triggered by JAX-RS feature flag JaxRSFeature.READ_FULL_STREAM where Jackson by default attempts to ensure that after the JSON data of a request body has been read, any trailing garbage is also consumed. The javadoc explains:
/**
* For HTTP keep-alive or multipart content to work correctly, Jackson must read the entire HTTP input
* stream up until reading EOF (-1).
* <a href="https://github.com/FasterXML/jackson-jaxrs-providers/issues/108">Issue #108</a>
* If set to true, always consume all input content. This has a side-effect of failing on trailing content.
*<p>
* Feature is enabled by default.
* Note that this means that behavior in earlier versions
* (2.14 and before) differs from 2.15 and later.
*
* @since 2.15
*/
READ_FULL_STREAM(true),And the consequence is that this enables the verifyNoTrailingTokens path within Jackson after the value is read, which in turn causes a read to be issued to client which results in blocking on that read, as seen here:
tammi 20 12:42:08 print-test java[94843]: at com.fasterxml.jackson.databind.ObjectReader._verifyNoTrailingTokens(ObjectReader.java:2247)
tammi 20 12:42:08 print-test java[94843]: at com.fasterxml.jackson.databind.ObjectReader._bind(ObjectReader.java:2104)
tammi 20 12:42:08 print-test java[94843]: at com.fasterxml.jackson.databind.ObjectReader.readValue(ObjectReader.java:1249)
The verify feature should read -1 to signal EOF, as the entire Content-Length has been read, and request processing should start. Instead, the read instead goes to the underlying client socket and blocks there, waiting for data from client which is never going to come.
The immediate workaround is to disable http/2 support in the Java HttpClient by specifying Version.HTTP_1_1. This doesn't imply that http/2 is used, as we are talking http/1.1 and I don't even have http/2 enabled in Grizzly. The Upgrade header handling seems to be the cause, as I can replicate the problem using a http/1.1 client with any Upgrade header value, giving the same Timeout and stack trace issue:
curl --http1.1 -X PUT -H 'Content-Type: application/json' -H 'Upgrade: definitelynotalegitimateprotocol' --data-raw '{"xxx":"yyy"}' -v http://print-test.internal.bel.fi:8080/Print/pdfThis is in my opinion a spec violation, as if the server can't upgrade to the requested protocol, it should process the request as if the header wasn't there, but at the very least something is different about how the underlying TCP sockets are handled which trips up in this bug.