Missing error requests in the tomcat's localhost_access log, while IOException during the Jackson invocation appears in the application log

Question

Some weird situation. During a performance test of a web application (war), the client gets 500 on about 2% of the requests. When searching the application log, there are some exceptions there:

 java.io.IOException: Stream closed
    at org.apache.catalina.connector.InputBuffer.read(InputBuffer.java:394)
    at org.apache.catalina.connector.CoyoteReader.read(CoyoteReader.java:110)
    at org.codehaus.jackson.impl.ReaderBasedParserBase.loadMore(ReaderBasedParserBase.java:95)
    at org.codehaus.jackson.impl.ReaderBasedParser._skipWSOrEnd(ReaderBasedParser.java:935)
    at org.codehaus.jackson.impl.ReaderBasedParser.nextToken(ReaderBasedParser.java:245)
    at org.codehaus.jackson.map.ObjectMapper._initForReading(ObjectMapper.java:2432)
    at org.codehaus.jackson.map.ObjectMapper._readMapAndClose(ObjectMapper.java:2389)
    at org.codehaus.jackson.map.ObjectMapper.readValue(ObjectMapper.java:1618)
    at MyServlet.doPost(MyServlet.java:25)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:641)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:722)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:304)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
    at MyFilter.doFilter(MyFilter.java:67)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
    at MyFilter.doFilter(MyFilter.java:28)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:224)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:169)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:472)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:168)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:100)
    at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:929)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:405)
    at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:964)
    at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:515)
    at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:304)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
    at java.lang.Thread.run(Thread.java:662)

However, the localhost_access is empty and all requests there have 200 status code.

I'll appreciate any insights on this problem:

• How can happen that localhost_access log is missing 500 requests, while client is getting them. When at all does this happen?
• Why java.io.IOException is thrown only occasionally (less then 2% of requests)?

Update 1: The problem occurs with Tomcat 7.0.22 and Java 6

Update 2: Here's some sample request to a static html file (not even to a servlet, so there is no exception in log and nothing in localhost_access):

Response headers:
HTTP/1.1 500 Internal Server Error
Server: Apache-Coyote/1.1
Content-Type: text/html;charset=utf-8
Transfer-Encoding: chunked
Date: Mon, 02 Apr 2012 07:35:06 GMT
Connection: close

Update 3: to eliminate the network I ran the same tests on the localhost. It didn't affect the test results. So it isn't the network.

Update 4: Restarting Tomcat helped. And still I don't understand what caused the original problem.

Update 5: Tomcat upgraded to 7.0.26, but it didn't solve the problem.

Update 6: Moved to Jetty. The errors are gone. Should I say "Good Bye" to Tomcat after all these years?

Answer 1

Error message suggests that IOException comes right when Jackson tries to initialize parsing, meaning that underlying HTTP connection is already closed when starting to parse request. So something has closed the connection; and while it could be client as well as server (HTTP allows both ends to close connections at any point), it is often something in the middle (firewall, proxy, loadbalancer); often due to a timeout of some kind.

Answer 2

You don't say what version of Tomcat you are running which would be a big help. My guess - based on what you see - is that it is relatively old.
The access log is implemented as a Valve. If a request is rejected before it gets as far as the Valves it will never appear in the access log. This usually happens when the request is malformed but there are other circumstances that could trigger it.
As of Tomcat 6.0.30 (and all 7.0.x versions) the access logging mechanism was refactored to ensure that messages are written to the access log even if the request is rejected before it reaches the AccessLogValve.

The IOException is thrown when the client closes the connection. Whether that is because of the 500 or is causing the 500 is unclear from the information provided.

Answer 3

AJAX Post on IE have intermittent failure issues. We have seen sockettimeoutexceptions. You can disable KeepAlive and try, or disable KeepAlive for AJAX POST by using a 'connection:close' header. Tune apache requestreadtimeout for no body request.