Default async request timeout handling does not work with Jetty 9.x [SPR-14669]

[spring-projects-issues]

Izek Greenfield opened SPR-14669 and commented

when I use async spring-mvc I send request with body:

PUT http://localhost/kuku?key=EKUpdateTestUpdate

Body: { "1": 1 }

if the request timed out then the error I get is:

org.springframework.http.converter.HttpMessageNotReadableException: Required request body is missing:

log file attached!

---

Affects: 4.3.2

Attachments:

• izek-sim.zip (62.26 kB)
• log.txt (12.29 kB)

Issue Links:

• Default async timeout handling results in Logged Exception for Tomcat 8.5.x [SPR-14739] #19305 Default async timeout handling results in Logged Exception for Tomcat 8.5.x

Backported to: 4.2.8

2 votes, 2 watchers

[spring-projects-issues]

Rossen Stoyanchev commented

I've looked at the log but It's hard to infer from the given amount of detail what may be going on. Is this reproducible in a small example application? We have project templates that may help.

[spring-projects-issues]

Izek Greenfield commented

attached project that reproduce the problem.

send request:

POST: http://localhost:1357/dummy?sleep=9000
HEADER: Content-Type: application/json
BODY:
{
"name": "izek",
"age": 1
}

[spring-projects-issues]

Rossen Stoyanchev commented

Thanks for the sample. Something strange is going on and I suspect a Jetty issue but not 100% sure yet.

The default behavior in Spring MVC, based on the TimeoutDeferredResultProcessingInterceptor is to call sendError on the response with a 503. So the client should simply get a server unavailable status. Instead Jetty seems to send an ERROR dispatch back to the original URL "/dummy" which (unsurprisingly) fails to read the body.

Simply upgrading Jetty to the latest 9.3 changes the behavior. There is no longer an ERROR dispatch and the client does get the 503 but there is a different exception in the logs and I'm not sure what it's about since the response from a client perspective is the one I would expect to see:

2016-09-08 14:30:15.957  WARN 13071 --- [tp1710044330-22] org.eclipse.jetty.server.HttpChannel     : //localhost:1357/dummy?sleep=40000
java.lang.IllegalStateException: cannot reset buffer on committed response
	at org.eclipse.jetty.server.Response.resetBuffer(Response.java:1245) ~[jetty-server-9.3.11.v20160721.jar:9.3.11.v20160721]
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:371) [jetty-server-9.3.11.v20160721.jar:9.3.11.v20160721]
	at org.eclipse.jetty.server.HttpChannel.run(HttpChannel.java:266) [jetty-server-9.3.11.v20160721.jar:9.3.11.v20160721]
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:671) [jetty-util-9.3.11.v20160721.jar:9.3.11.v20160721]
	at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:589) [jetty-util-9.3.11.v20160721.jar:9.3.11.v20160721]
	at java.lang.Thread.run(Thread.java:745) [na:1.8.0_77]

I will experiment a little more to see if I can reproduce this with just Servlet API and Jetty.

[spring-projects-issues]

Rossen Stoyanchev commented

BTW I used the following Filter to "see" the dispatches:

@Bean
public FilterRegistrationBean myFilter() {

	Filter filter = new Filter() {

		@Override
		public void doFilter(ServletRequest request, ServletResponse response, FilterChain filterChain)
				throws IOException, ServletException {

			logger.info("\n\n" + ((HttpServletRequest) request).getMethod() + " " +
					((HttpServletRequest) request).getRequestURI() +
					", DispatcherType: " + request.getDispatcherType() + "\n\n");

			filterChain.doFilter(request, response);
		}

		public void init(FilterConfig filterConfig) throws ServletException {}

		public void destroy() {}
	};

	FilterRegistrationBean bean = new FilterRegistrationBean(filter);
	bean.setDispatcherTypes(DispatcherType.REQUEST, DispatcherType.ASYNC, DispatcherType.ERROR,
			DispatcherType.FORWARD, DispatcherType.INCLUDE);

	return bean;
}

[spring-projects-issues]

Rossen Stoyanchev commented

I've been able to reproduce the same behavior with a plain Servlet project running on Jetty (source here).

In Jetty 9.3 a call to sendError(503) from the timeout listener results in the right response status but also with the same ISE above while a call to setStatus(503) causes Jetty to fire an additional ERROR dispatch with the original request URL. I cannot find anything in the Servlet spec that says what should happen after a timeout so I guess it's up to servers to do this if they please. One would think that setting the response status to 503 via sendError or setStatus is enough of a signal that we are done, and that used to work, but apparently in more recent versions Jetty does more after the timeout.

I will experiment with a fix in the TimeoutDeferredResultProcessingInterceptor that sets the DeferredResult to an exception, that is then handled as a 503 in the resulting ASYNC dispatch. After the ASYNC dispatch is complete, the response should be over.

[spring-projects-issues]

Rossen Stoyanchev commented

Meanwhile as a workaround you can add the following config:

@Configuration
public static class WebConfig extends WebMvcConfigurerAdapter {

  @Override
  public void configureAsyncSupport(AsyncSupportConfigurer configurer) {
    configurer.setDefaultTimeout(5000);
    configurer.registerDeferredResultInterceptors(
        new DeferredResultProcessingInterceptorAdapter() {
          @Override
          public <T> boolean handleTimeout(NativeWebRequest req, DeferredResult<T> result) {
            return result.setErrorResult(new AsyncTimeoutException());
          }
        });
  }
}

Where the AsyncTimeoutException is:

@ResponseStatus(HttpStatus.SERVICE_UNAVAILABLE)
public static class AsyncTimeoutException extends Exception { 
}

[spring-projects-issues]

Izek Greenfield commented

thanks for that!!

How I configure that with XML?

thanks

[spring-projects-issues]

Rossen Stoyanchev commented

There is an <async-support> element as well (in the XML namespace).

[spring-projects-issues]

Rossen Stoyanchev commented

This should now be fixed in the latest snapshots of all 3 fix versions. I've tested with your sample project and also another sample app but if you get a chance to confirm that would be great, thanks!