tomcat-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Jan Dosoudil <jan.dosou...@aura.cz>
Subject Tomcat NIO broken connections
Date Mon, 10 Nov 2014 11:53:54 GMT
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-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org


Mime
View raw message