Bug 58751 - Strange behaviour after calling sendError when an async request times out
Summary: Strange behaviour after calling sendError when an async request times out
Status: RESOLVED FIXED
Alias: None
Product: Tomcat 8
Classification: Unclassified
Component: Catalina (show other bugs)
Version: 8.0.30
Hardware: PC Mac OS X 10.1
: P2 normal (vote)
Target Milestone: ----
Assignee: Tomcat Developers Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2015-12-17 20:51 UTC by Andy Wilkinson
Modified: 2016-01-04 18:24 UTC (History)
0 users



Attachments
Sample the reproduces the problem (2.21 KB, text/plain)
2015-12-17 20:51 UTC, Andy Wilkinson
Details
Another variant of the testcase the resulting in a ClientAbortException (2.45 KB, text/plain)
2015-12-18 10:29 UTC, Andy Wilkinson
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Andy Wilkinson 2015-12-17 20:51:23 UTC
Created attachment 33359 [details]
Sample the reproduces the problem

This problem's probably most easily described with the attached sample. There's a servlet mapped to /error and a custom error page registered with /error as it's location. Another servlet is mapped to /timeout. It deliberately allows an async request to timeout and then calls response.sendError(503).

My expectation is that this will result in the request being routed to the error servlet and that, as a result, a 503 response will be returned with "Error!" in the body.

The actual outcome is that a 500 response is returned with "Error!" in the body:

$ curl -i localhost:8080/timeout
HTTP/1.1 500 Internal Server Error
Server: Apache-Coyote/1.1
Content-Length: 7
Date: Thu, 17 Dec 2015 20:49:00 GMT
Connection: close

Error!

And the following severe message and exception are logged:

SEVERE: Exception Processing ErrorPage[errorCode=0, location=/error]
java.lang.IllegalStateException: Cannot forward after response has been committed
	at org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:327)
	at org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:317)
	at org.apache.catalina.core.StandardHostValve.custom(StandardHostValve.java:445)
	at org.apache.catalina.core.StandardHostValve.status(StandardHostValve.java:304)
	at org.apache.catalina.core.StandardHostValve.throwable(StandardHostValve.java:399)
	at org.apache.catalina.core.AsyncContextImpl.setErrorState(AsyncContextImpl.java:451)
	at org.apache.catalina.connector.CoyoteAdapter.asyncDispatch(CoyoteAdapter.java:293)
	at org.apache.coyote.http11.AbstractHttp11Processor.asyncDispatch(AbstractHttp11Processor.java:1716)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:650)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1500)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1456)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:745)
Comment 1 Andy Wilkinson 2015-12-18 10:29:18 UTC
Created attachment 33363 [details]
Another variant of the testcase the resulting in a ClientAbortException

I've attached another testcase that behaves slightly differently. In this test, the response is sent back to the client before the custom error page is called. When the error page is then called it flushes the response and a ClientAbortException is thrown.
Comment 2 Mark Thomas 2016-01-01 15:39:58 UTC
The test case is invalid.

Tomcat enforces the requirements set on page 2-18 of Servlet 3.1. To quote the relevant section:

<quote>
In the event that an asynchronous operation times out, the container must run through the following steps:
- Invoke the AsyncListener.onTimeout method on all the AsyncListener instances registered with the ServletRequest on which the asynchronous operation was initiated.
- If none of the listeners called AsyncContext.complete() or any of the AsyncContext.dispatch methods, perform an error dispatch with a status code equal to HttpServletResponse.SC_INTERNAL_SERVER_ERROR.
- If no matching error page was found, or the error page did not call AsyncContext.complete() or any of the AsyncContext.dispatch methods, the container MUST call AsyncContext.complete().
</quote>

The provided test case does not call AsyncContext.complete() during onTimeout() so Tomcat performs the error dispatch required above.

If the expected call to AsyncContext.complete() is added to onTimeout(), the behaviour the test case expects is observed.

Tomcat might be able to handle this better but given the number of errors that preceed this, (async timeout, failure to call complete()) I'm not sure it is worth putting much/any effort into investigating possible improvements.
Comment 3 Andy Wilkinson 2016-01-02 15:00:55 UTC
Mark, did you miss the second variant of the problem? It does call dispatch but still behaves strangely. Tomcat appears to try to send two responses. The second fails with a ClientAbortException.
Comment 4 Mark Thomas 2016-01-04 17:58:16 UTC
The report suggested the test cases were variations of the same issue, not different issues. Hence why the bug was closed when the first issue was found to be invalid.

I've taken a closer look at the second issue and there is a problem with at least 9.0.x and probably earlier versions as well.
Comment 5 Mark Thomas 2016-01-04 18:24:28 UTC
Fixed in 9.0.x for 9.0.0.M2 onwards, 8.0.x for 8.0.31 onwards and 7.0.x for 7.0.68 onwards.