Bug 51197 - sendError/sendRedirect don't work with AsyncContext
Summary: sendError/sendRedirect don't work with AsyncContext
Status: RESOLVED FIXED
Alias: None
Product: Tomcat 7
Classification: Unclassified
Component: Servlet & JSP API (show other bugs)
Version: 7.0.25
Hardware: All All
: P2 major (vote)
Target Milestone: ---
Assignee: Tomcat Developers Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2011-05-13 12:50 UTC by Dan Checkoway
Modified: 2012-03-05 12:25 UTC (History)
0 users



Attachments
test.war - Reproducer for issue in Comment 3 (4.11 KB, application/zip)
2012-02-20 01:21 UTC, Konstantin Kolinko
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Dan Checkoway 2011-05-13 12:50:26 UTC
For some reason, response.sendRedirect and response.sendError are not producing expected behavior when using an AsyncContext.  On the server side, the async request completes normally, and everything looks hunky dory, but the client never gets ANY response from the server.  It appears that Tomcat simply times out after the default 10 seconds and closes the connection.  No headers are returned, no content, nothing.  I've confirmed with thread dumps that the server isn't stuck.

Yet...if you use response.setStatus and response.setHeader instead, it works absolutely fine.  The client gets the response every time.

I put together a very simple test that isolates the issue reliably:

https://github.com/dcheckoway/async-test

See the README in there for details.

NOTE: the behavior for sendError changed slightly from 7.0.12 to 7.0.14.  As of 7.0.14, sendError seems to close the connection immediately, but the client still never gets any response of any kind.
Comment 1 Dan Checkoway 2011-05-13 12:52:10 UTC
Forgot to mention, I use the NIO connector:

    <Connector port="8080" protocol="org.apache.coyote.http11.Http11NioProtocol" 
               connectionTimeout="20000" 
               redirectPort="8443" />
Comment 2 Mark Thomas 2011-05-18 17:25:38 UTC
Thanks for the report. This has been fixed in 7.0.x and will be included in 7.0.15 onwards.
Comment 3 Zack Radick 2012-02-17 18:34:07 UTC
I am seeing the same behavior with Tomcat 7.0.25.  Within an asynchronous context this does not work as expected (the client does not receive any output):

HttpServletResponse response = (HttpServletResponse)asyncContext.getResponse();
response.sendError( responseCode, error );

However, this does (the client receives the error output with an appropriate status code):

HttpServletResponse response = (HttpServletResponse)asyncContext.getResponse();
response.setStatus( responseCode );
response.getOutputStream().write( error.getBytes() );
response.getOutputStream().flush();

In both cases the underlying ServletResponse has the appropriate status set, but the results sent to the client differ.  I am using the default HTTP1.1 connector.

The behavior is reproducible in 7.0.16 as well (7.0.15 is no longer in the archives it seems).  I also tried using the Writer (as opposed to the OutputStream) to ensure that nothing had previously been written to the Stream, but it exhibited the same behavior.
Comment 4 Mark Thomas 2012-02-18 21:17:11 UTC
(In reply to comment #3)
> I am seeing the same behavior with Tomcat 7.0.25.

The report is lacking in specifics of how to reproduce the problem. There is a unit test already for this issue that passes. I expanded it to cover calling sendError in a new thread and the same thread (this is one of the specifics the report is lacking) and both tests pass with BIO.

> (7.0.15 is no longer in the archives it seems)

7.0.15 was never in the archives since it was never released.

Before re-opening this issue, please ensure you have a complete minimal test case (i.e. a single servlet in source form) that can be used to demonstrate the issue on a clean Tomcat 7.0.x install using the latest available  version (7.0.25 at the time of writing this).

You may wish to explore this issue on the users mailing list first to confirm that there is indeed a bug here.
Comment 5 Konstantin Kolinko 2012-02-20 01:00:26 UTC
(In reply to comment #4)
> There is a unit test already for this issue that passes. I expanded it
> to cover calling
> sendError in a new thread and the same thread (this is one of the specifics the
> report is lacking) and both tests pass with BIO.

For reference,
the test is TestAsyncContextImpl - search for "51197" and see r1124342 and r1290875

The test does not check what response text is sent to the client. It just checks response status and the access log.

It might be that client is responded with correct HTTP status line, but HTTP response content is empty.


1. I tried to update the doTestBug51197(..) test in TestAsyncContextImpl to test for error message, but it is not trivial.
As of now it is not possible to use the ByteChunk passed to getUrl() call. The URLConnection used to implement getUrl() cannot read content if response code is >= 400.  If I remove status code check in TomcatBaseTest#getUrl() to always read response text regardless of status code, it just fails with an IOException:

[[[
Testcase: testBug51197b took 4,188 sec
	Caused an ERROR
Server returned HTTP response code: 400 for URL: http://localhost:3596/asyncErrorServlet
java.io.IOException: Server returned HTTP response code: 400 for URL: http://localhost:3596/asyncErrorServlet
	at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
	at sun.net.www.protocol.http.HttpURLConnection$6.run(HttpURLConnection.java:1491)
	at java.security.AccessController.doPrivileged(Native Method)
	at sun.net.www.protocol.http.HttpURLConnection.getChainedException(HttpURLConnection.java:1485)
	at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1139)
	at org.apache.catalina.startup.TomcatBaseTest.getUrl(TomcatBaseTest.java:239)
	at org.apache.catalina.startup.TomcatBaseTest.getUrl(TomcatBaseTest.java:206)
	at org.apache.catalina.startup.TomcatBaseTest.getUrl(TomcatBaseTest.java:200)
	at org.apache.catalina.core.TestAsyncContextImpl.doTestBug51197(TestAsyncContextImpl.java:1207)
	at org.apache.catalina.core.TestAsyncContextImpl.testBug51197b(TestAsyncContextImpl.java:1177)

Caused by: java.io.IOException: Server returned HTTP response code: 400 for URL: http://localhost:3596/asyncErrorServlet
	at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1436)
	at java.net.HttpURLConnection.getResponseCode(HttpURLConnection.java:379)
	at org.apache.catalina.startup.TomcatBaseTest.getUrl(TomcatBaseTest.java:232)
]]]


2. I enabled access log in the test, by adding the following line to build.properties:

test.accesslog=true

The access log shows as if error message was sent to the client - see bytes count in the last column:
[[[
127.0.0.1 - - [20/Feb/2012:04:14:50 +0400] "GET /asyncErrorServlet HTTP/1.1" 400 5 http-bio-127.0.0.1-auto-32-exec-2 3985
127.0.0.1 - - [20/Feb/2012:04:14:56 +0400] "GET /asyncErrorServlet HTTP/1.1" 400 5 http-bio-127.0.0.1-auto-33-exec-3 4000

127.0.0.1 - - [20/Feb/2012:04:15:50 +0400] "GET /asyncErrorServlet HTTP/1.1" 400 5 http-nio-127.0.0.1-auto-32-exec-2 4000
127.0.0.1 - - [20/Feb/2012:04:15:56 +0400] "GET /asyncErrorServlet HTTP/1.1" 400 5 http-nio-127.0.0.1-auto-33-exec-3 4000

127.0.0.1 - - [20/Feb/2012:04:16:57 +0400] "GET /asyncErrorServlet HTTP/1.1" 400 5 http-apr-127.0.0.1-auto-32-exec-3 4000
127.0.0.1 - - [20/Feb/2012:04:17:02 +0400] "GET /asyncErrorServlet HTTP/1.1" 400 5 http-apr-127.0.0.1-auto-33-exec-4 4000
]]]


3. Finally I was able to reproduce the issue.
I extracted AsyncErrorServlet as a standalone class, configured a simple web application and tried to access it directly. It reproduces the issue! The response is empty. Moreover access log shows that only 5 bytes were sent to the client.

[[[
127.0.0.1 - - [20/Feb/2012:04:39:53 +0400] "GET /test/asyncErrorServlet?status=404&treaded=true HTTP/1.1" 404 5
127.0.0.1 - - [20/Feb/2012:04:40:03 +0400] "GET /test/asyncErrorServlet?status=404&treaded=false HTTP/1.1" 404 5
127.0.0.1 - - [20/Feb/2012:04:40:42 +0400] "GET /test/asyncErrorServlet HTTP/1.1" 500 1472
]]]

I converted the constructor arguments to request parameters. If I call the servlet without arguments it fails on parseInt call, and see above - it responds with proper error 500 message of 1472 bytes.

I will attach the war below.


4. sendError() call as used in Comment 3 interacts with error handling.
I have not tested how it behaves when there is a custom error page configured.

5. BTW, r1290875 has not been merged into 7.0.x yet.
Comment 6 Konstantin Kolinko 2012-02-20 01:21:48 UTC
Created attachment 28356 [details]
test.war - Reproducer for issue in Comment 3

WAR that reproduces the issue.


[[[
127.0.0.1 - - [20/Feb/2012:04:39:53 +0400] "GET
/test/asyncErrorServlet?status=404&treaded=true HTTP/1.1" 404 5
]]]

I made a typo while testing it, it should have been s/treaded/threaded/. An odd thing is that I do not see any difference whether "threaded" is true or false. The request takes ~3 seconds to execute regardless of that parameter.


[[[
127.0.0.1 - - [20/Feb/2012:04:16:57 +0400] "GET /asyncErrorServlet HTTP/1.1"
400 5 http-apr-127.0.0.1-auto-32-exec-3 4000
127.0.0.1 - - [20/Feb/2012:04:17:02 +0400] "GET /asyncErrorServlet HTTP/1.1"
400 5 http-apr-127.0.0.1-auto-33-exec-4 4000
]]]

Apparently "5" above was the size. The 4000 is the timing. Why it is 4000 and not 3000 (TIMEOUT)?
Comment 7 Christopher Schultz 2012-02-21 16:48:05 UTC
Konstantin,

(In reply to comment #5)
> The
> URLConnection used to implement getUrl() cannot read content if response code
> is >= 400.If I remove status code check in TomcatBaseTest#getUrl() to always
> read response text regardless of status code, it just fails with an
> IOException:

You have to use URLConnection.getErrorStream if the response code is "problematic". I have this code in a class that fetches data from an HTTP server:

        int responseCode = conn.getResponseCode();

        boolean error = 5 == responseCode / 100
            || 4 == responseCode / 100;

        if(error)
            in = new BufferedInputStream(conn.getErrorStream());
        else
            in = new BufferedInputStream(conn.getInputStream());

Then I just use "in" as I please.

> Caused by: java.io.IOException: Server returned HTTP response code: 400 for
> URL: http://localhost:3596/asyncErrorServlet
>     at
> sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1436)
>     at java.net.HttpURLConnection.getResponseCode(HttpURLConnection.java:379)
>     at
> org.apache.catalina.startup.TomcatBaseTest.getUrl(TomcatBaseTest.java:232)
> ]]]

Weird that it's throwing an exception from getResponseCode. What JRE are you using?
Comment 8 Konstantin Kolinko 2012-02-21 17:17:06 UTC
(In reply to comment #7)
> You have to use URLConnection.getErrorStream if the response code is
> "problematic". I have this code in a class that fetches data from an HTTP
> server:
> 
>         int responseCode = conn.getResponseCode();
> 
>         boolean error = 5 == responseCode / 100
>             || 4 == responseCode / 100;
> 
>         if(error)
>             in = new BufferedInputStream(conn.getErrorStream());
>         else
>             in = new BufferedInputStream(conn.getInputStream());
> 
> Then I just use "in" as I please.
> 

Thank you! Good advise.

> > Caused by: java.io.IOException: Server returned HTTP response code: 400 for
> > URL: http://localhost:3596/asyncErrorServlet
> >     at
> > sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1436)
> >     at java.net.HttpURLConnection.getResponseCode(HttpURLConnection.java:379)
> >     at
> > org.apache.catalina.startup.TomcatBaseTest.getUrl(TomcatBaseTest.java:232)
> > ]]]
> 
> Weird that it's throwing an exception from getResponseCode. What JRE are you
> using?

6u31.
getResponseCode() call cashes the exception but does not return it. Then subsequent call to getInputStream() wraps this original exception as the cause.
Comment 9 Christopher Schultz 2012-02-21 19:53:33 UTC
(In reply to comment #8)
> getResponseCode() call [caches] the exception but does not return it. Then
> subsequent call to getInputStream() wraps this original exception as the cause.

That's ... confusing behavior. Thanks for identifying that. I was hoping that my code wouldn't still fail because of the exception's stack trace (indicating that the exception was thrown from getResponseCode). Looks like it's *initialized* in getResponseCode but not actually thrown until later. Weird.
Comment 10 Mark Thomas 2012-03-05 12:25:29 UTC
The base test case has been updated to return a response body for error responses.

The ErrorReportValve has been updated to write a response body if sendError() is called during an async request if it is being handled on a container thread. As per SRV 10.9.2, if an error occurs during an async request on an application thread, writing the response body - if any - is entirely an application responsibility.