DeferredResult timeout and Tomcat IllegalStateException [SPR-10710]

[spring-projects-issues]

Peter De Wachter opened SPR-10710 and commented

I'm using Spring 3.2.3 and Tomcat 7.0.41 with the NIO backend. I'm (still) experiencing problems with timeout handling of DeferredResult. (See #15118 for an earlier bug.)

Consider the following code:

@Controller
public class TestController {

    @RequestMapping(value="/test")
    @ResponseBody
    public DeferredResult<String> test() {
        return new DeferredResult<String>(50L, "timeout\n");
    }

}

Now, create 100 threads which send this request in a loop: (The "parallel" command here is GNU parallel.)

yes 'curl --silent http://localhost:8080/test' | parallel -j100

Some of these requests will fail and Tomcat will log the this exception:

jul 01, 2013 11:42:38 AM org.apache.coyote.AbstractProtocol$AbstractConnectionHandler process
SEVERE: Error reading request, ignored
java.lang.IllegalStateException: Calling [asyncPostProcess()] is not valid for a request with Async state [STARTED]
        at org.apache.coyote.AsyncStateMachine.asyncPostProcess(AsyncStateMachine.java:204)
        at org.apache.coyote.AbstractProcessor.asyncPostProcess(AbstractProcessor.java:116)
        at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:593)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1686)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:724)

---

Affects: 3.2.3

Reference URL: spring-attic/spring-framework-issues#53

[spring-projects-issues]

Peter De Wachter commented

Added sping-framework-issues link

[spring-projects-issues]

Rossen Stoyanchev commented

It's not fully obvious that this is related to Spring MVC. There was an IllegalStateException that was actually a bug I reported not long ago.

It would be worth trying without Spring MVC, something like:

public class AsyncServlet extends HttpServlet {

  @Override
  protected void doGet(final HttpServletRequest request, HttpServletResponse response)
      throws ServletException, IOException {

    if (request.isAsyncStarted()) {
      response.getWriter().write("asyncResult=" + request.getAttribute("asyncResult"));
    }
    else {
      final AsyncContext asyncContext = request.startAsync(request, response);

      asyncContext.addListener(new AsyncListener() {
        public void onTimeout(AsyncEvent event) throws IOException {
            request.setAttribute("asyncResult", "timeout\n");
            asyncContext.dispatch();
        }
        public void onStartAsync(AsyncEvent event) throws IOException {}
        public void onError(AsyncEvent event) throws IOException {}
        public void onComplete(AsyncEvent event) throws IOException {}
      });

      asyncContext.setTimeout(50L);
    }
  }
}

Out of curiosity why do you set the timeout to 50 milliseconds?

[spring-projects-issues]

Peter De Wachter commented

Your code produces an identical exception (I've upgraded in the meantime to Tomcat 7.0.42). But your version consistently fails, where my Spring versions usually works. Perhaps a timing difference due to the extra Spring code? Anyway, this demonstrates that it is a Tomcat bug. Should I report the bug there, or will you do that?

The 50ms was just an attempt to make the problem easier to reproduce, by creating a busier mix of connections and timeouts. My real code has timeouts of 30 or 60 seconds and there I see this problem a few times per day.

[spring-projects-issues]

Rossen Stoyanchev commented

Go ahead and open a ticket in Tomcat's bug repository since you've already reproduced it. You can attach the code sample.

[spring-projects-issues]

Rossen Stoyanchev commented

I'm resolving this but feel free to add a reference to Tomcat's ticket. Thanks!

[spring-projects-issues]

Jonghwa Park commented

This issue seems to be the reason.

https://issues.apache.org/bugzilla/show_bug.cgi?id=55331

It doesn't occur with Tomcat7 trunk version.