Bug 55976 - Broken response from NIO connector in Tomcat 7.0.50
Broken response from NIO connector in Tomcat 7.0.50
Status: CLOSED FIXED
Product: Tomcat 7
Classification: Unclassified
Component: Connectors
trunk
PC All
: P2 normal (vote)
: ---
Assigned To: Tomcat Developers Mailing List
:
Depends on:
Blocks:
  Show dependency tree
 
Reported: 2014-01-08 09:52 UTC by Ognjen Blagojevic
Modified: 2014-01-10 19:51 UTC (History)
1 user (show)



Attachments
Correct request and correct response (1.33 KB, text/plain)
2014-01-08 10:22 UTC, Ognjen Blagojevic
Details
Correct request and broken response (6.29 KB, text/plain)
2014-01-08 10:23 UTC, Ognjen Blagojevic
Details
Java test class (7.44 KB, text/plain)
2014-01-08 11:15 UTC, Ognjen Blagojevic
Details
TCP data log (908.46 KB, application/zip)
2014-01-08 16:22 UTC, Konstantin Preißer
Details
multi-threaded WebCrawler (9.25 KB, text/x-java)
2014-01-09 17:02 UTC, Rainer Jung
Details
Alternative Testcase - WAR (161.54 KB, application/octet-stream)
2014-01-09 17:07 UTC, Konstantin Preißer
Details
Alternative Test Case - Java class (1.60 KB, text/plain)
2014-01-09 17:07 UTC, Konstantin Preißer
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Ognjen Blagojevic 2014-01-08 09:52:04 UTC
Tomcat 7.0.50 (proposed for voting at the time of submitting this issue) with Oracle Java 1.7.0_40 on Win7 64-bit, sometimes returns incorrect response when NIO connector is used.

Start of the report, and steps to reproduce the problem are in this thread:

  http://www.mail-archive.com/dev@tomcat.apache.org/msg80175.html

-Ognjen
Comment 1 Ognjen Blagojevic 2014-01-08 10:20:30 UTC
Java client is used for smoke testing Tomcat 7.0.50. Java client fails with following exception:

====
Exception in thread "main" java.lang.RuntimeException: java.io.IOException: Invalid Http response
	at webcrawler.WebCrawler.getpage(WebCrawler.java:117)
	at webcrawler.WebCrawler.repeat(WebCrawler.java:191)
	at webcrawler.WebCrawler.main(WebCrawler.java:30)
Caused by: java.io.IOException: Invalid Http response
	at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1342)
	at java.net.URL.openStream(URL.java:1037)
	at webcrawler.WebCrawler.getpage(WebCrawler.java:94)
	... 2 more
----


Relevant lines from sun.net.www.protocol.http.HttURLConnection.getInputStream:

====
respCode = getResponseCode();
if (respCode == -1) {
    disconnectInternal();
    throw new IOException ("Invalid Http response");
}
----


So, getResponseCode returns -1. Relevant part from sun.net.www.protocol.http.HttURLConnection.getResponseCode():

====
        /*
         * Examine the status-line - should be formatted as per
         * section 6.1 of RFC 2616 :-
         *
         * Status-Line = HTTP-Version SP Status-Code SP Reason-Phrase
         *
         * If status line can't be parsed return -1.
         */
        if (statusLine.startsWith("HTTP/1.")) {
            int codePos = statusLine.indexOf(' ');
            if (codePos > 0) {

                int phrasePos = statusLine.indexOf(' ', codePos+1);
                if (phrasePos > 0 && phrasePos < statusLine.length()) {
                    responseMessage = statusLine.substring(phrasePos+1);
                }

                // deviation from RFC 2616 - don't reject status line
                // if SP Reason-Phrase is not included.
                if (phrasePos < 0)
                    phrasePos = statusLine.length();

                try {
                    responseCode = Integer.parseInt
                            (statusLine.substring(codePos+1, phrasePos));
                    return responseCode;
                } catch (NumberFormatException e) { }
            }
        }
        return -1;
----

So it seems that response from Tomcat doesn't contain string "HTTP/1." in the first line.
Comment 2 Ognjen Blagojevic 2014-01-08 10:22:11 UTC
Created attachment 31182 [details]
Correct request and correct response
Comment 3 Ognjen Blagojevic 2014-01-08 10:23:00 UTC
Created attachment 31183 [details]
Correct request and broken response
Comment 4 Ognjen Blagojevic 2014-01-08 10:33:07 UTC
I took localhost dump using RawCap. The dump contains traffic from the smoke testing. I then opened it with wireshark. 

In the dump, there is a number of requests for file prelude.jspf.html:

  "GET /examples/jsp/jsp2/misc/prelude.jspf.html HTTP/1.1"

Tomcat generally responds correctly, as seen in attachment 31182 [details].

But, in one request, instead of responding with content from "prelude.jspf.html" Tomcat responds with partial content from a different file -- "/docs/architecture/startup/serverStartup.txt".

As one can see in attachment 31183 [details], the response also doesn't contain any header. That is the reason why Java client fails.
Comment 5 Mark Thomas 2014-01-08 10:44:58 UTC
Can you provide the source code of the test client you are using so the committers can try and reproduce this?
Comment 6 Ognjen Blagojevic 2014-01-08 11:15:30 UTC
Created attachment 31184 [details]
Java test class

Here is Java class used for testing.

You should call it with one argument - starting URL (e.g. "http://localhost:8080/")

At the first phase, it crawls all pages starting from the root. During the crawl, Java stack traces for 401s and 404s will be printed on the console, and may be ignored.

At the second phase, it will repeatedly read all collected URLs, 500 times in a row. In total, it reads around 140k pages. 

If there is an error during the test, exception will be thrown, e.g:

====
Round: 154 / 500
Round: 155 / 500
Round: 156 / 500
Exception in thread "main" java.lang.RuntimeException: java.io.IOException: Invalid Http response
	at webcrawler.WebCrawler.getpage(WebCrawler.java:117)
	at webcrawler.WebCrawler.repeat(WebCrawler.java:191)
	at webcrawler.WebCrawler.main(WebCrawler.java:30)
Caused by: java.io.IOException: Invalid Http response
	at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1342)
	at java.net.URL.openStream(URL.java:1037)
	at webcrawler.WebCrawler.getpage(WebCrawler.java:94)
	... 2 more
----

Sometimes exception is thrown after 5k requests, sometimes only after running this test several times.

-Ognjen
Comment 7 Konstantin Preißer 2014-01-08 16:22:29 UTC
Created attachment 31185 [details]
TCP data log

(In reply to Ognjen Blagojevic from comment #6)
> Created attachment 31184 [details]
> Java test class

Hi,

I can reproduce the problem with your test class with Tomcat 7.0.50, Tomcat 7.0.47 and Tomcat 8.0.0-RC10 on Windows 8.1 x64 with Java 1.7.0_45.


To provide an additional example of a broken HTTP response, I used a self-written tool to intercept the TCP connections from the Java client to Tomcat and log all data of each TCP connection channel to a file and I attached a Zip file containing the logs of the last few TCP connections.

The logs of connections 262-267 look normal (each HTTP request is replied to with an HTTP response), but if you look at 268 (where a single HTTP request was sent), Tomcat did not start the reply with an HTTP response, but with some random data chunks that seem to belong to different responses, and later sent the actual HTTP response for the request.
Comment 8 Jess Holle 2014-01-08 16:36:52 UTC
(In reply to Konstantin Preißer from comment #7)
> I can reproduce the problem with your test class with Tomcat 7.0.50, Tomcat
> 7.0.47 and Tomcat 8.0.0-RC10 on Windows 8.1 x64 with Java 1.7.0_45.

So that's critical information -- this isn't a regression since 7.0.47, i.e. in the 7.0.50 release.  It might be a regression in 7.0.47, but that was already released as stable.
Comment 9 Mark Thomas 2014-01-09 16:32:05 UTC
Can someone who has been able to repeat this please test with tomcat/trunk from svn and see if they can still repeat it. I have been trying to repeat this for several hours with no success. I am wondering if the root cause is a bug that has been fixed since the last release.
Comment 10 Rainer Jung 2014-01-09 17:02:47 UTC
Created attachment 31190 [details]
multi-threaded WebCrawler

Slightly enhanced version of the provided WebCrawler class:

- Params URL ITERATIONS THREADS
  (crawl recursively starting at URL, retrieve found list of pages ITERATIONS times distributed on THREADS threads)
- Log timestamp if an error occurs
- don't convert bytes to strings when in replay mode

Example: 

/path/to/bin/java webcrawler.WebCrawler http://myserver:8080/docs/ 1000 10

Code tunables:

    public static final int BUFSZ = 1000; // Buffer size for reading responses
    public static final int CONNECT_TIMEOUT = 5000; // Connect timeout
    public static final int READ_TIMEOUT = 30000; // Connect timeout
Comment 11 Konstantin Preißer 2014-01-09 17:07:28 UTC
Created attachment 31191 [details]
Alternative Testcase - WAR
Comment 12 Konstantin Preißer 2014-01-09 17:07:32 UTC
Created attachment 31192 [details]
Alternative Test Case - Java class

Hi Mark,

(In reply to Mark Thomas from comment #9)
> Can someone who has been able to repeat this please test with tomcat/trunk
> from svn and see if they can still repeat it. I have been trying to repeat
> this for several hours with no success. I am wondering if the root cause is
> a bug that has been fixed since the last release.

I could reproduce the issues with Tomcat 8 trunk, SVN r1556836 on Windows 8.1 x64, Java 1.7.0_45 x64.

I uploaded an alternative Testcase which maybe makes reproducing easier - a WAR that contains 100 text files, and a Java class that starts 100 Threads that concurrently download 100 URLs.

Normally, the only things that should be displayed in the console are "Starting..." and "Finished.". This happens when running with the BIO connector.

However, with Tomcat NIO connector, I mostly get exceptions like this:

java.io.IOException: Invalid Http response
	at sun.net.www.protocol.http.HttpURLConnection.getInputStream(Unknown Source)
	at test.TomcatNioTest.readUrl(TomcatNioTest.java:23)
	at test.TomcatNioTest.access$0(TomcatNioTest.java:19)
	at test.TomcatNioTest$1.run(TomcatNioTest.java:48)
	at java.lang.Thread.run(Unknown Source)
Exception in thread "Thread-93" java.lang.RuntimeException: Size mismatch for URL http://localhost:8080/testnio/files/TextFile81.txt - Expected: 58003, Got: 65536
	at test.TomcatNioTest.readUrl(TomcatNioTest.java:31)
	at test.TomcatNioTest.access$0(TomcatNioTest.java:19)
	at test.TomcatNioTest$1.run(TomcatNioTest.java:48)
	at java.lang.Thread.run(Unknown Source)

Also, most of the time the program never finishes - it seems Tomcat does not serve some requests.


Sometimes I also get these Exceptions in Tomcat:

09-Jan-2014 17:40:48.143 SEVERE [http-nio-8080-exec-76] org.apache.coyote.http11.AbstractHttp11Processor.process Error processing request
 java.lang.NullPointerException
	at org.apache.coyote.http11.Http11NioProcessor.actionInternal(Http11NioProcessor.java:321)
	at org.apache.coyote.http11.AbstractHttp11Processor.action(AbstractHttp11Processor.java:843)
	at org.apache.coyote.Request.action(Request.java:381)
	at org.apache.catalina.connector.Request.getRemoteAddr(Request.java:1240)
	at org.apache.catalina.connector.Request.getRemoteHost(Request.java:1255)
	at org.apache.catalina.valves.AccessLogValve$HostElement.addElement(AccessLogValve.java:1366)
	at org.apache.catalina.valves.AccessLogValve.log(AccessLogValve.java:963)
	at org.apache.catalina.core.AccessLogAdapter.log(AccessLogAdapter.java:51)
	at org.apache.catalina.core.ContainerBase.logAccess(ContainerBase.java:1044)
	at org.apache.catalina.core.ContainerBase.logAccess(ContainerBase.java:1051)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:573)
	at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1015)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:646)
	at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:223)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1576)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1534)
	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:744)

09-Jan-2014 17:40:48.518 WARNING [http-nio-8080-exec-76] org.apache.catalina.connector.CoyoteAdapter.log Exception while attempting to add an entry to the access log
 java.lang.NullPointerException
	at org.apache.coyote.http11.Http11NioProcessor.actionInternal(Http11NioProcessor.java:321)
	at org.apache.coyote.http11.AbstractHttp11Processor.action(AbstractHttp11Processor.java:843)
	at org.apache.coyote.Request.action(Request.java:381)
	at org.apache.catalina.connector.Request.getRemoteAddr(Request.java:1240)
	at org.apache.catalina.connector.Request.getRemoteHost(Request.java:1255)
	at org.apache.catalina.valves.AccessLogValve$HostElement.addElement(AccessLogValve.java:1366)
	at org.apache.catalina.valves.AccessLogValve.log(AccessLogValve.java:963)
	at org.apache.catalina.core.AccessLogAdapter.log(AccessLogAdapter.java:51)
	at org.apache.catalina.core.StandardEngine.logAccess(StandardEngine.java:344)
	at org.apache.catalina.connector.CoyoteAdapter.log(CoyoteAdapter.java:644)
	at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1044)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:646)
	at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:223)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1576)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1534)
	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:744)

09-Jan-2014 17:47:37.091 SEVERE [http-nio-8080-ClientPoller-1] org.apache.tomcat.util.net.NioEndpoint.processSocket Error allocating socket processor
 java.lang.NullPointerException
	at org.apache.tomcat.util.net.NioEndpoint.processSocket(NioEndpoint.java:622)
	at org.apache.tomcat.util.net.NioEndpoint$Poller.processKey(NioEndpoint.java:1144)
	at org.apache.tomcat.util.net.NioEndpoint$Poller.run(NioEndpoint.java:1101)
	at java.lang.Thread.run(Thread.java:744)
Comment 13 Rainer Jung 2014-01-09 17:15:13 UTC
I can reproduce errors even for trunk but there currently only read timeouts. I'm using a relatively slow server and remote access from a more powerful machine using 10 threads in the improved version of the WebCrawler. Crawling the docs/ webapp suffices to produce those read timeouts (30 seconds). The CPU on the server is not fully saturated and other parametrization shows that those requests would hang indefinitely if no timeout were applied.

For TC 7.0.50 I could also produce other types of errors, but didn't play long enough with trunk.

Not directly related to the read timeout occurences I see on the server side sometimes messages:

09-Jan-2014 17:56:33.691 SEVERE [http-nio-8080-ClientPoller-1] org.apache.tomcat.util.net.NioEndpoint$PollerEvent.run
 java.nio.channels.ClosedChannelException
        at java.nio.channels.spi.AbstractSelectableChannel.register(AbstractSelectableChannel.java:194)
        at org.apache.tomcat.util.net.NioEndpoint$PollerEvent.run(NioEndpoint.java:797)
        at org.apache.tomcat.util.net.NioEndpoint$Poller.events(NioEndpoint.java:925)
        at org.apache.tomcat.util.net.NioEndpoint$Poller.run(NioEndpoint.java:1085)
        at java.lang.Thread.run(Thread.java:744)

Regards,

Rainer
Comment 14 Rainer Jung 2014-01-09 17:19:02 UTC
When crawling not only /docs but also /examples, I get more types of errors.

In the access log (non-200, non-302)

195.227.30.185 - - 18:11:12.441 "GET /docs/cgi-howto.html HTTP/1.1" 400 -
- - - 00:59:59.00-1 "-" 500 -
195.227.30.185 - - 18:11:12.895 "GET /examples/jsp/jsp2/simpletag/book.jsp HTTP/1.1" 400 951
195.227.30.185 - - 18:11:13.050 "GET /examples/jsp/jsp2/simpletag/book.jsp HTTP/1.1" 400 951
195.227.30.185 - - 18:11:33.967 "GET /examples/servlets/nonblocking/numberwriter HTTP/1.1" 500 49200
195.227.30.185 - - 18:11:35.036 "GET /examples/servlets/nonblocking/numberwriter HTTP/1.1" 500 155800
- - - 00:59:59.00-1 "-" 500 -
- - - 00:59:59.00-1 "-" 400 -
195.227.30.185 - - 18:11:35.486 "GET /docs/jspapi/index.html HTTP/1.1" 400 -
195.227.30.185 - - 18:11:35.674 "GET /examples/jsp/jsp2/jspattribute/jspattribute.html HTTP/1.1" 500 2221
- - - 00:59:59.00-1 "-" 500 -
195.227.30.185 - - 18:11:35.888 "GET /docs/config/cluster-valve.html HTTP/1.1" 400 10669
195.227.30.185 - - 18:11:35.887 "GET /docs/config/cluster-valve.html HTTP/1.1" 400 -

etc.

In the tomcat logs

09-Jan-2014 18:10:40.405 SEVERE [http-nio-8080-ClientPoller-1] org.apache.tomcat.util.net.NioEndpoint$PollerEvent.run
 java.nio.channels.ClosedChannelException
        at java.nio.channels.spi.AbstractSelectableChannel.register(AbstractSelectableChannel.java:194)
        at org.apache.tomcat.util.net.NioEndpoint$PollerEvent.run(NioEndpoint.java:797)
        at org.apache.tomcat.util.net.NioEndpoint$Poller.events(NioEndpoint.java:925)
        at org.apache.tomcat.util.net.NioEndpoint$Poller.run(NioEndpoint.java:1085)
        at java.lang.Thread.run(Thread.java:744)

09-Jan-2014 18:11:11.341 SEVERE [http-nio-8080-exec-9] org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process Error reading request, ignored
 java.lang.NullPointerException
        at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.release(Http11NioProtocol.java:243)
        at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:698)
        at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:223)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1576)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1534)
        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:744)

09-Jan-2014 18:11:12.450 INFO [http-nio-8080-exec-26] org.apache.coyote.http11.AbstractHttp11Processor.process Error parsing HTTP request header
 Note: further occurrences of HTTP header parsing errors will be logged at DEBUG level.
09-Jan-2014 18:11:12.745 SEVERE [http-nio-8080-exec-29] org.apache.coyote.http11.AbstractHttp11Processor.process Error processing request
 java.lang.NullPointerException
        at org.apache.catalina.connector.Request.notifyAttributeAssigned(Request.java:1512)
        at org.apache.catalina.connector.Request.setAttribute(Request.java:1503)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:162)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:76)
        at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:934)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:90)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:522)
        at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1015)
        at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:646)
        at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:223)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1576)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1534)
        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:744)

09-Jan-2014 18:11:12.752 SEVERE [http-nio-8080-exec-29] org.apache.coyote.http11.AbstractHttp11Processor.endRequest Error finishing response
 java.lang.NullPointerException
        at org.apache.coyote.http11.InternalNioOutputBuffer.flushBuffer(InternalNioOutputBuffer.java:235)
        at org.apache.coyote.http11.InternalNioOutputBuffer.addToBB(InternalNioOutputBuffer.java:190)
        at org.apache.coyote.http11.InternalNioOutputBuffer.access$000(InternalNioOutputBuffer.java:42)
        at org.apache.coyote.http11.InternalNioOutputBuffer$SocketOutputBuffer.doWrite(InternalNioOutputBuffer.java:321)
        at org.apache.coyote.http11.filters.ChunkedOutputFilter.end(ChunkedOutputFilter.java:166)
        at org.apache.coyote.http11.AbstractOutputBuffer.endRequest(AbstractOutputBuffer.java:379)
        at org.apache.coyote.http11.AbstractHttp11Processor.endRequest(AbstractHttp11Processor.java:1704)
        at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1071)
        at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:646)
        at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:223)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1576)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1534)
        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:744)

...

09-Jan-2014 18:11:33.966 SEVERE [http-nio-8080-exec-9] org.apache.catalina.connector.CoyoteAdapter.asyncDispatch Exception while processing an asynchronous request
 java.lang.IllegalStateException: Calling [asyncTimeout()] is not valid for a request with Async state [READ_WRITE_OP]
        at org.apache.coyote.AsyncStateMachine.asyncTimeout(AsyncStateMachine.java:265)
        at org.apache.coyote.http11.AbstractHttp11Processor.action(AbstractHttp11Processor.java:802)
        at org.apache.coyote.Request.action(Request.java:381)
        at org.apache.catalina.core.AsyncContextImpl.timeout(AsyncContextImpl.java:139)
        at org.apache.catalina.connector.CoyoteAdapter.asyncDispatch(CoyoteAdapter.java:306)
        at org.apache.coyote.http11.AbstractHttp11Processor.asyncDispatch(AbstractHttp11Processor.java:1618)
        at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:640)
        at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:223)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1576)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1534)
        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:744)

09-Jan-2014 18:11:34.685 SEVERE [http-nio-8080-exec-21] org.apache.catalina.connector.CoyoteAdapter.asyncDispatch Exception while processing an asynchronous request
 java.lang.IllegalStateException: In non-blocking mode you may not write to the ServletOutputStream until the previous write has completed and isReady() returns true
        at org.apache.catalina.connector.CoyoteOutputStream.checkNonBlockingWrite(CoyoteOutputStream.java:128)
        at org.apache.catalina.connector.CoyoteOutputStream.write(CoyoteOutputStream.java:96)
        at org.apache.catalina.connector.CoyoteOutputStream.write(CoyoteOutputStream.java:90)
        at nonblocking.NumberWriter$NumberWriterListener.onWritePossible(NumberWriter.java:132)
        at nonblocking.NumberWriter$NumberWriterListener.onAllDataRead(NumberWriter.java:120)
        at org.apache.catalina.connector.CoyoteAdapter.asyncDispatch(CoyoteAdapter.java:391)
        at org.apache.coyote.http11.AbstractHttp11Processor.asyncDispatch(AbstractHttp11Processor.java:1618)
        at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:631)
        at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:223)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1576)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1534)
        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:744)

09-Jan-2014 18:11:34.967 SEVERE [http-nio-8080-exec-20] org.apache.catalina.connector.CoyoteAdapter.asyncDispatch Exception while processing an asynchronous request
 java.lang.IllegalStateException: The request associated with the AsyncContext has already completed processing.
        at org.apache.catalina.core.AsyncContextImpl.check(AsyncContextImpl.java:532)
        at org.apache.catalina.core.AsyncContextImpl.complete(AsyncContextImpl.java:91)
        at nonblocking.NumberWriter$NumberWriterListener.onError(NumberWriter.java:145)
        at org.apache.catalina.connector.CoyoteAdapter.asyncDispatch(CoyoteAdapter.java:395)
        at org.apache.coyote.http11.AbstractHttp11Processor.asyncDispatch(AbstractHttp11Processor.java:1618)
        at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:631)
        at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:223)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1576)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1534)
        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:744)



...

09-Jan-2014 18:11:36.787 SEVERE [http-nio-8080-exec-4] org.apache.coyote.http11.AbstractHttp11Processor.process Error processing request
 java.lang.NullPointerException
        at org.apache.tomcat.util.buf.MessageBytes.toChars(MessageBytes.java:228)
        at org.apache.catalina.mapper.Mapper.map(Mapper.java:665)
        at org.apache.catalina.connector.CoyoteAdapter.postParseRequest(CoyoteAdapter.java:794)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:517)
        at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1015)
        at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:646)
        at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:223)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1576)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1534)
        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:744)



Some of which are possibly because the client calls URLs that it shouldn't.
Comment 15 Mark Thomas 2014-01-09 19:16:41 UTC
(In reply to Konstantin Preißer from comment #11)
> Created attachment 31191 [details]
> Alternative Testcase - WAR

Thanks. I can repeat the problem with that variation of the test case. My testing shows the issue is related to sendFile. If I set useSendFile="false" on the NIO connector everything works as expected. I'm looking at the sendFile code now to see if I can figure out where I (assuming it was me but it is a pretty good bet that it was) broke it.
Comment 16 Rainer Jung 2014-01-09 20:37:59 UTC
Just in case others want to check as well, it is useSendfile="false" (lower case "file").

Running test with my multi-threaded version of the crawler against alls tc webaps right now. Looks better than before, no errors yet, will let it run for another hour or so.
Comment 17 Mark Thomas 2014-01-09 21:33:48 UTC
I believe I have fixed this in 8.0.x trunk. I'd be grateful if one or more of you who were able to repeat this issue are able to validate (or not) my fix.
Comment 18 Ognjen Blagojevic 2014-01-10 00:07:29 UTC
So far so good. Tomcat 8 trunk (r1556957) works for me. No exception on client side, or in server logs, no HTTP 500 errors.
Comment 19 Rainer Jung 2014-01-10 00:20:48 UTC
Looks promising. I did not get any errors with sendfile turned off and 50000 iterations distributed on 20 threads. I now run the recent trunk with your fix again with 20 threads and the first 2000 iterations are good. I'll let it run until 50000 and will check tomorrow whether 7.0.50 runs without problems when switching off sendfile.!gre
Comment 20 Mark Thomas 2014-01-10 08:42:25 UTC
Fixed applied to 7.0.x for 7.0.51 onwards.
Comment 21 Ognjen Blagojevic 2014-01-10 19:51:38 UTC
(In reply to Mark Thomas from comment #20)
> Fixed applied to 7.0.x for 7.0.51 onwards.

Tomcat 7.0.x trunk also works correctly. I'm closing this bug.