tomcat的localhost_access日志中缺少错误请求,而Jackson调用期间的IOException出现在应用程序日志中

Question

有些奇怪的情况.在Web应用程序(战争)的性能测试期间,客户端在大约2%的请求上获得500.搜索应用程序日志时,有一些例外:

 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)

但是,localhost_access为空,并且所有请求都有200个状态代码.

我会很感激这个问题的任何见解:

• 当客户端获取500个请求时,localhost_access日志如何丢失500个请求.什么时候发生这种情况？
• 为什么java.io.IOException偶尔抛出(少于2%的请求)？

更新1: Tomcat 7.0.22和Java 6出现问题

更新2: 这是对静态html文件的一些示例请求(甚至不是servlet,因此日志中没有异常,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

更新3:消除网络我在localhost上运行相同的测试.它没有影响测试结果.所以它不是网络.

更新4:重启Tomcat有帮助.而且我仍然不明白是什么导致了原始问题.

更新5: Tomcat升级到7.0.26,但它没有解决问题.

更新6:移动到Jetty.错误消失了.这些年来,我应该对Tomcat说"再见"吗？

Answer 1

你没有说你正在运行什么版本的Tomcat,这将是一个很大的帮助.我的猜测 - 基于你所看到的 - 是相对陈旧的.
访问日志实现为Valve.如果请求在到达Valves之前被拒绝,它将永远不会出现在访问日志中.这通常发生在请求格式错误但有其他情况可能触发它的情况下.
从Tomcat 6.0.30(以及所有7.0.x版本)开始,重构了访问日志记录机制,以确保即使请求在到达AccessLogValve之前被拒绝,也会将消息写入访问日志.

客户端关闭连接时抛出IOException.无论是因为500还是造成500还不清楚所提供的信息.

Answer 2

错误消息表明IOException当 Jackson 尝试初始化解析时正确，这意味着在开始解析请求时底层 HTTP 连接已经关闭。所以有些东西关闭了连接；虽然它可以是客户端也可以是服务器（HTTP 允许两端在任何时候关闭连接），但它通常是中间的东西（防火墙、代理、负载均衡器）；通常是由于某种超时。