Spring's DeferredResult setResult interaction with timeouts

Question

I'm experimenting with Spring's DeferredResult on Tomcat, and I'm getting crazy results. Is what I'm doing wrong, or is there some bug in Spring or Tomcat? My code is simple enough.

@Controller
public class Test {
    private DeferredResult<String> deferred;

    static class DoSomethingUseful implements Runnable {
        public void run() {
            try { Thread.sleep(2000); } catch (InterruptedException e) { }
        }
    }

    @RequestMapping(value="/test/start")
    @ResponseBody
    public synchronized DeferredResult<String> start() {
        deferred = new DeferredResult<>(4000L, "timeout\n");
        deferred.onTimeout(new DoSomethingUseful());
        return deferred;
    }

    @RequestMapping(value="/test/stop")
    @ResponseBody
    public synchronized String stop() {
        deferred.setResult("stopped\n");
        return "ok\n";
    }
}

So. The start request creates a DeferredResult with a 4 second timeout. The stop request will set a result on the DeferredResult. If you send stop before or after the deferred result times out, everything works fine.

However if you send stop at the same time as start times out, things go crazy. I've added an onTimeout action to make this easy to reproduce, but that's not necessary for the problem to occur. With an APR connector, it simply deadlocks. With a NIO connector, it sometimes works, but sometimes it incorrectly sends the "timeout" message to the stop client and never answers the start client.

To test this:

curl http://localhost/test/start & sleep 5; curl http://localhost/test/stop

I don't think I'm doing anything wrong. The Spring documentation seems to say it's okay to call setResult at any time, even after the request already expired, and from any thread ("the application can produce the result from a thread of its choice").

Versions used: Tomcat 7.0.39 on Linux, Spring 3.2.2.

Answer 1

This is an excellent bug find !
Just adding more information about the bug (that got fixed) for a better understanding.

There was a synchronized block inside setResult() that extended up to the part of submitting a dispatch. This can cause a deadlock if a timeout occurs at the same time since the Tomcat timeout thread has its own locking that permits only one thread to do timeout or dispatch processing.

Detailed explanation:

When you call "stop" at the same time as the request "times out", two threads are attempting to lock the DeferredResult object 'deferred'.

1. The thread that executes the "onTimeout" handler Here is the excerpt from the Spring doc:

   This onTimeout method is called from a container thread when an async request times out before the DeferredResult has been set. It may invoke setResult or setErrorResult to resume processing.

2. Another thread that executes the "stop" service.

If the dispatch processing called during the stop() service obtains the 'deferred' lock, it will wait for a tomcat lock (say TomcatLock) to finish the dispatch.
And if the other thread doing timeout handling has already acquired the TomcatLock, that thread waits to acquire a lock on 'deferred' to complete the setResult()!

So, we end up in a classic deadlock situation !