Hi,
we have web application running MyFaces, Richfaces (+ Atmosphere 1.0.18)
on Tomcat 7.0.55, Oracle JDK 7u67. Tomcat is configured to use Nio
connector:
<Connector URIEncoding="UTF-8" acceptCount="150"
compressableMimeType="text/html,text/xml,text/css,text/javascript"
compression="on" compressionMinSize="2048" connectionTimeout="60000"
disableUploadTimeout="true" enableLookups="false"
maxHttpHeaderSize="8192" maxThreads="150"
noCompressionUserAgents="gozilla, traviata" port="8090"
protocol="org.apache.coyote.http11.Http11NioProtocol"
socket.bufferPool="0" useBodyEncodingForURI="true"/>
Problem is that user opens application in browser and sometimes sees
only blank page and spinning load indicator, indefinitely. It's caused
by one or more css/javascript resources in page that didn't load.
Browser console shows that request has been sent and it is waiting for
response. Using apache-bench and wireshark I found that tomcat sends RST
packet, here are related log items:
2014-11-10 10:13:35.064 [http-nio-8090-exec-4] - - DEBUG
o.a.coyote.http11.Http11NioProtocol - Socket:
[org.apache.tomcat.util.net.NioEndpoint$KeyAttachment@28697f3f:org.apache.tomcat.util.net.NioChannel@73f0f55d:java.nio.channels.SocketChannel[connected
local=/192.168.1.156:8090 remote=/192.168.1.156:53187]], Status in:
[OPEN_READ], State out: [CLOSED]
2014-11-10 10:13:35.064 [http-nio-8090-exec-4] - - DEBUG
o.a.tomcat.util.threads.LimitLatch - Counting down[http-nio-8090-exec-4]
latch=238
2014-11-10 10:13:35.064 [http-nio-8090-Acceptor-0] - - DEBUG
o.a.tomcat.util.threads.LimitLatch - Counting
up[http-nio-8090-Acceptor-0] latch=238
2014-11-10 10:13:35.065 [http-nio-8090-ClientPoller-1] - - ERROR
o.a.tomcat.util.net.NioEndpoint - Error allocating socket processor
java.lang.NullPointerException: null
at
org.apache.tomcat.util.net.NioEndpoint.processSocket(NioEndpoint.java:742)
~[tomcat-coyote.jar:7.0.55]
at
org.apache.tomcat.util.net.NioEndpoint$Poller.processKey(NioEndpoint.java:1273)
[tomcat-coyote.jar:7.0.55]
at
org.apache.tomcat.util.net.NioEndpoint$Poller.run(NioEndpoint.java:1226)
[tomcat-coyote.jar:7.0.55]
at java.lang.Thread.run(Thread.java:745) [na:1.7.0_67]
2014-11-10 10:13:35.065 [http-nio-8090-ClientPoller-1] - - ERROR
o.a.tomcat.util.net.NioEndpoint -
java.lang.NullPointerException: null
at
java.util.concurrent.ConcurrentHashMap.hash(ConcurrentHashMap.java:333)
~[na:1.7.0_67]
at
java.util.concurrent.ConcurrentHashMap.remove(ConcurrentHashMap.java:1175)
~[na:1.7.0_67]
at
org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.release(Http11NioProtocol.java:196)
~[tomcat-coyote.jar:7.0.55]
at
org.apache.tomcat.util.net.NioEndpoint$Poller.cancelledKey(NioEndpoint.java:1098)
[tomcat-coyote.jar:7.0.55]
at
org.apache.tomcat.util.net.NioEndpoint$Poller.processKey(NioEndpoint.java:1283)
[tomcat-coyote.jar:7.0.55]
at
org.apache.tomcat.util.net.NioEndpoint$Poller.run(NioEndpoint.java:1226)
[tomcat-coyote.jar:7.0.55]
at java.lang.Thread.run(Thread.java:745) [na:1.7.0_67]
Problem is not easily reproducible, I need running application, opened
browser on application page for a long time (last time I let it run over
the weekend). It may be related to session timeouts and someting strange
in RichFaces/Atmosphere. If it starts doing problems, it's reproducible
using apache bench in one of tens of requests (If it runs concurrently,
in one of less than ten).
There are some related exceptions:
2014-11-10 09:50:37.682 [http-nio-8090-exec-28] - - ERROR
o.a.c.c.C.[.[.[.[Faces Servlet] - Servlet.service() for servlet [Faces
Servlet] in context with path [/mcc-launcher] threw exception
java.lang.NullPointerException: null
at
org.apache.coyote.http11.Http11NioProcessor.actionInternal(Http11NioProcessor.java:320)
~[tomcat-coyote.jar:7.0.55]
at
org.apache.coyote.http11.AbstractHttp11Processor.action(AbstractHttp11Processor.java:902)
[tomcat-coyote.jar:7.0.55]
at org.apache.coyote.Request.action(Request.java:346)
~[tomcat-coyote.jar:7.0.55]
at
org.apache.catalina.connector.Request.getRemoteAddr(Request.java:1287)
~[catalina.jar:7.0.55]
at
org.apache.catalina.connector.Request.getRemoteHost(Request.java:1302)
~[catalina.jar:7.0.55]
at
org.apache.catalina.connector.RequestFacade.getRemoteHost(RequestFacade.java:529)
~[catalina.jar:7.0.55]
at
ch.qos.logback.classic.helpers.MDCInsertingServletFilter.insertIntoMDC(MDCInsertingServletFilter.java:59)
~[logback-classic-1.1.2.jar:na]
at
ch.qos.logback.classic.helpers.MDCInsertingServletFilter.doFilter(MDCInsertingServletFilter.java:49)
~[logback-classic-1.1.2.jar:na]
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
~[catalina.jar:7.0.55]
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
~[catalina.jar:7.0.55]
at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)
~[catalina.jar:7.0.55]
at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)
[catalina.jar:7.0.55]
at
org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:501)
[catalina.jar:7.0.55]
at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:171)
[catalina.jar:7.0.55]
at
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)
[catalina.jar:7.0.55]
at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
[catalina.jar:7.0.55]
at
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408)
[catalina.jar:7.0.55]
at
org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1070)
[tomcat-coyote.jar:7.0.55]
at
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:611)
[tomcat-coyote.jar:7.0.55]
at
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1736)
[tomcat-coyote.jar:7.0.55]
at
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1695)
[tomcat-coyote.jar:7.0.55]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[na:1.7.0_67]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[na:1.7.0_67]
at
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
[tomcat-coyote.jar:7.0.55]
at java.lang.Thread.run(Thread.java:745) [na:1.7.0_67]
2014-11-10 09:50:37.683 [http-nio-8090-exec-28] - - ERROR
o.a.c.http11.Http11NioProcessor - Error processing request
java.lang.NullPointerException: null
at
org.apache.coyote.http11.Http11NioProcessor.setCometTimeouts(Http11NioProcessor.java:253)
~[tomcat-coyote.jar:7.0.55]
at
org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1082)
~[tomcat-coyote.jar:7.0.55]
at
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:611)
[tomcat-coyote.jar:7.0.55]
at
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1736)
[tomcat-coyote.jar:7.0.55]
at
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1695)
[tomcat-coyote.jar:7.0.55]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[na:1.7.0_67]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[na:1.7.0_67]
at
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
[tomcat-coyote.jar:7.0.55]
at java.lang.Thread.run(Thread.java:745) [na:1.7.0_67]
2014-11-10 12:40:57.530 [http-nio-8090-ClientPoller-1] - - ERROR
o.a.tomcat.util.net.NioEndpoint -
java.nio.channels.ClosedChannelException: null
at
java.nio.channels.spi.AbstractSelectableChannel.register(AbstractSelectableChannel.java:194)
~[na:1.7.0_67]
at
org.apache.tomcat.util.net.NioEndpoint$PollerEvent.run(NioEndpoint.java:912)
~[tomcat-coyote.jar:7.0.55]
at
org.apache.tomcat.util.net.NioEndpoint$Poller.events(NioEndpoint.java:1054)
[tomcat-coyote.jar:7.0.55]
at
org.apache.tomcat.util.net.NioEndpoint$Poller.run(NioEndpoint.java:1170)
[tomcat-coyote.jar:7.0.55]
at java.lang.Thread.run(Thread.java:745) [na:1.7.0_67]
These exceptions are IMHO not root causes, but result of someting else,
may be in asynchronous processing (Atmosphere).
There is interesting think in log from LimitLatch, there are numbers
like 238, but there are currently no other requests (may be related to
bug 56518).
If I open web in browser, browser shows blank page and It is waiting for
a data, then I press stop button, It makes log messages:
2014-11-10 12:18:30.295 [http-nio-8090-exec-24] - - DEBUG
o.a.c.http11.Http11NioProcessor - Error parsing HTTP request header
java.io.EOFException: Unexpected EOF read on the socket
at
org.apache.coyote.http11.InternalNioInputBuffer.readSocket(InternalNioInputBuffer.java:447)
~[tomcat-coyote.jar:7.0.55]
at
org.apache.coyote.http11.InternalNioInputBuffer.fill(InternalNioInputBuffer.java:795)
~[tomcat-coyote.jar:7.0.55]
at
org.apache.coyote.http11.InternalNioInputBuffer.parseRequestLine(InternalNioInputBuffer.java:227)
~[tomcat-coyote.jar:7.0.55]
at
org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:984)
~[tomcat-coyote.jar:7.0.55]
at
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:611)
[tomcat-coyote.jar:7.0.55]
at
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1736)
[tomcat-coyote.jar:7.0.55]
at
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1695)
[tomcat-coyote.jar:7.0.55]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[na:1.7.0_67]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[na:1.7.0_67]
at
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
[tomcat-coyote.jar:7.0.55]
at java.lang.Thread.run(Thread.java:745) [na:1.7.0_67]
Do you have any idea how to debug this or whether It is known bug or
there is some workaroud?
Thanks
Jan Dosoudil
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org
