I am not much close, but r1781988 broke it:
"Ensure that executor thread pools used with connectors pre-start the
configured minimum number of idle threads."
The change itself is OK, but as a consequence the test is now
executing with more threads in the executor:
Index: java/org/apache/tomcat/util/threads/ThreadPoolExecutor.java
===================================================================
--- java/org/apache/tomcat/util/threads/ThreadPoolExecutor.java
(revision 1781987)
+++ java/org/apache/tomcat/util/threads/ThreadPoolExecutor.java
(revision 1781988)
@@ -63,19 +63,23 @@
public ThreadPoolExecutor(int corePoolSize, int maximumPoolSize,
long keepAliveTime, TimeUnit unit, BlockingQueue<Runnable> workQueue,
RejectedExecutionHandler handler) {
super(corePoolSize, maximumPoolSize, keepAliveTime, unit,
workQueue, handler);
+ prestartAllCoreThreads();
}
public ThreadPoolExecutor(int corePoolSize, int maximumPoolSize,
long keepAliveTime, TimeUnit unit, BlockingQueue<Runnable> workQueue,
ThreadFactory threadFactory,
RejectedExecutionHandler handler) {
super(corePoolSize, maximumPoolSize, keepAliveTime, unit,
workQueue, threadFactory, handler);
+ prestartAllCoreThreads();
}
public ThreadPoolExecutor(int corePoolSize, int maximumPoolSize,
long keepAliveTime, TimeUnit unit, BlockingQueue<Runnable> workQueue,
ThreadFactory threadFactory) {
super(corePoolSize, maximumPoolSize, keepAliveTime, unit,
workQueue, threadFactory, new RejectHandler());
+ prestartAllCoreThreads();
}
public ThreadPoolExecutor(int corePoolSize, int maximumPoolSize,
long keepAliveTime, TimeUnit unit, BlockingQueue<Runnable> workQueue) {
super(corePoolSize, maximumPoolSize, keepAliveTime, unit,
workQueue, new RejectHandler());
+ prestartAllCoreThreads();
}
public long getThreadRenewalDelay() {
So at least that's why I observed it first in 8.0.42, the version that
change was included.
But I'm not close to the root cause.
Reproducability on my slow Solaris 10 Sparc system is very good, about
80% of all attempts show the hang.
Regards,
Rainer
Am 05.04.2017 um 00:32 schrieb Rainer Jung:
Hi Violeta,
Am 04.04.2017 um 16:12 schrieb Violeta Georgieva:
Hi Rainer,
2017-03-30 23:59 GMT+03:00 Rainer Jung <rainer.j...@kippdata.de>:
Am 28.03.2017 um 17:28 schrieb Violeta Georgieva:
The proposed Apache Tomcat 8.0.43 release is now available for voting.
It can be obtained from:
https://dist.apache.org/repos/dist/dev/tomcat/tomcat-8/v8.0.43/
The Maven staging repo is:
https://repository.apache.org/content/repositories/orgapachetomcat-1127/
The svn tag is:
http://svn.apache.org/repos/asf/tomcat/tc8.0.x/tags/TOMCAT_8_0_43/
The proposed 8.0.43 release is:
[ ] Broken - do not release
[X] Stable - go ahead and release as 8.0.43
+1 to release but note one hang in TestSsl testRenegotiateWorks for
NIO2.
I cannot reproduce this hanging test neither on MAC nor Ubuntu.
Is it possible that it is related to something with your setup?
Also Buildbot and Gump are OK.
For me it fails about 50% of the time (NIO2).
I added some debug logging: the handshake in the TesterHandshakeListener
happens during the first request in the loop in
TestSsl.testRenegotiateWorks(), but then when executing the second
request in the loop it hangs when trying to read the first character of
the first response line.
Here's a log using FINEST log level. The SEVERE lines are not errors,
but the log output I added to the test class:
00:18:21.141 FINE [main]
org.apache.catalina.util.LifecycleBase.setStateInternal Setting state
for [Connector[org.apache.coyote.http11.Http11Nio2Protocol-auto-3]] to
[STARTING_PREP]
00:18:21.141 FINE [main]
org.apache.catalina.util.LifecycleBase.setStateInternal Setting state
for [Connector[org.apache.coyote.http11.Http11Nio2Protocol-auto-3]] to
[STARTING]
00:18:21.142 INFO [main] org.apache.coyote.AbstractProtocol.start
Starting ProtocolHandler ["http-nio2-127.0.0.1-auto-3-35749"]
00:18:21.156 FINE [main]
org.apache.catalina.util.LifecycleBase.setStateInternal Setting state
for [Connector[org.apache.coyote.http11.Http11Nio2Protocol-auto-3]] to
[STARTED]
00:18:21.156 FINE [main]
org.apache.catalina.util.LifecycleBase.setStateInternal Setting state
for [StandardService[Tomcat]] to [STARTED]
00:18:21.157 FINE [main]
org.apache.catalina.util.LifecycleBase.setStateInternal Setting state
for [StandardServer[-1]] to [STARTED]
00:18:21.163 FINE [http-nio2-127.0.0.1-auto-3-Acceptor-0]
org.apache.tomcat.util.threads.LimitLatch.countUpOrAwait Counting
up[http-nio2-127.0.0.1-auto-3-Acceptor-0] latch=0
00:18:21.194 FINE [http-nio2-127.0.0.1-auto-3-Acceptor-0]
org.apache.tomcat.util.threads.LimitLatch.countUpOrAwait Counting
up[http-nio2-127.0.0.1-auto-3-Acceptor-0] latch=1
00:18:21.197 SEVERE [main]
org.apache.tomcat.util.net.TestSsl.testRenegotiateWorks begin request
before socket.startHandshake
00:18:21.198 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
begin request
00:18:21.289 FINE [http-nio2-127.0.0.1-auto-3-exec-4]
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.register
Register
Tomcat:type=RequestProcessor,worker="http-nio2-127.0.0.1-auto-3-35749",name=HttpRequest1
00:18:21.290 FINE [http-nio2-127.0.0.1-auto-3-exec-4]
org.apache.tomcat.util.modeler.Registry.registerComponent Managed=
Tomcat:type=RequestProcessor,worker="http-nio2-127.0.0.1-auto-3-35749",name=HttpRequest1
00:18:21.291 FINER [http-nio2-127.0.0.1-auto-3-exec-4]
com.sun.jmx.mbeanserver.Repository.contains name =
Tomcat:type=RequestProcessor,worker="http-nio2-127.0.0.1-auto-3-35749",name=HttpRequest1
00:18:21.291 FINER [http-nio2-127.0.0.1-auto-3-exec-4]
com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerMBean
ObjectName =
Tomcat:type=RequestProcessor,worker="http-nio2-127.0.0.1-auto-3-35749",name=HttpRequest1
00:18:21.291 FINE [http-nio2-127.0.0.1-auto-3-exec-4]
org.apache.tomcat.util.modeler.BaseModelMBean.preRegister preRegister
org.apache.coyote.RequestInfo@1c22e0
Tomcat:type=RequestProcessor,worker="http-nio2-127.0.0.1-auto-3-35749",name=HttpRequest1
00:18:21.291 FINER [http-nio2-127.0.0.1-auto-3-exec-4]
com.sun.jmx.mbeanserver.Repository.addMBean name =
Tomcat:type=RequestProcessor,worker="http-nio2-127.0.0.1-auto-3-35749",name=HttpRequest1
00:18:21.292 FINER [http-nio2-127.0.0.1-auto-3-exec-4]
com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.addObject Send
create notification of object
Tomcat:name=HttpRequest1,type=RequestProcessor,worker="http-nio2-127.0.0.1-auto-3-35749"
00:18:21.292 FINER [http-nio2-127.0.0.1-auto-3-exec-4]
com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.sendNotification
JMX.mbean.registered
Tomcat:type=RequestProcessor,worker="http-nio2-127.0.0.1-auto-3-35749",name=HttpRequest1
00:18:21.293 FINE [http-nio2-127.0.0.1-auto-3-exec-4]
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process
Socket:
[org.apache.tomcat.util.net.Nio2Endpoint$Nio2SocketWrapper@1b4ba80:org.apache.tomcat.util.net.SecureNio2Channel@32156a:sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected
local=/127.0.0.1:35749 remote=/127.0.0.1:35750]], Status in:
[OPEN_READ], State out: [LONG]
00:18:21.294 FINE [http-nio2-127.0.0.1-auto-3-exec-5]
org.apache.coyote.http11.AbstractNioInputBuffer.parseRequestLine
Received [GET /tester HTTP/1.1
[junit] ]
00:18:21.295 FINE [http-nio2-127.0.0.1-auto-3-exec-5]
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process
Socket:
[org.apache.tomcat.util.net.Nio2Endpoint$Nio2SocketWrapper@1b4ba80:org.apache.tomcat.util.net.SecureNio2Channel@32156a:sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected
local=/127.0.0.1:35749 remote=/127.0.0.1:35750]], Status in:
[OPEN_READ], State out: [LONG]
00:18:21.297 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
flush request
00:18:21.297 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
begin response
00:18:21.302 FINE [http-nio2-127.0.0.1-auto-3-exec-6]
org.apache.tomcat.util.http.Parameters.setQueryStringEncoding Set query
string encoding to UTF-8
00:18:21.303 FINE [http-nio2-127.0.0.1-auto-3-exec-6]
org.apache.catalina.connector.CoyoteAdapter.parsePathParameters The
variable [uriBC] has value [/tester]
00:18:21.303 FINE [http-nio2-127.0.0.1-auto-3-exec-6]
org.apache.catalina.connector.CoyoteAdapter.parsePathParameters The
variable [semicolon] has value [-1]
00:18:21.304 FINE [http-nio2-127.0.0.1-auto-3-exec-6]
org.apache.catalina.connector.CoyoteAdapter.parsePathParameters The
variable [enc] has value [utf-8]
00:18:21.305 FINE [http-nio2-127.0.0.1-auto-3-exec-6]
org.apache.catalina.realm.RealmBase.findSecurityConstraints No
applicable constraints defined
00:18:21.306 FINE [http-nio2-127.0.0.1-auto-3-exec-6]
org.apache.catalina.core.StandardWrapper.allocate Allocating non-STM
instance
00:18:21.306 FINER [http-nio2-127.0.0.1-auto-3-exec-6]
org.apache.catalina.core.StandardWrapper.allocate Returning non-STM
instance
00:18:21.310 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
Read response line character: H=72
00:18:21.310 FINE [http-nio2-127.0.0.1-auto-3-exec-6]
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process
Socket:
[org.apache.tomcat.util.net.Nio2Endpoint$Nio2SocketWrapper@1b4ba80:org.apache.tomcat.util.net.SecureNio2Channel@32156a:sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected
local=/127.0.0.1:35749 remote=/127.0.0.1:35750]], Status in:
[OPEN_READ], State out: [OPEN]
00:18:21.311 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
Read response line character: T=84
00:18:21.311 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
Read response line character: T=84
00:18:21.312 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
Read response line character: P=80
00:18:21.312 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
Read response line character: /=47
00:18:21.312 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
Read response line character: 1=49
00:18:21.312 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
Read response line character: .=46
00:18:21.313 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
Read response line character: 1=49
00:18:21.313 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
Read response line character: =32
00:18:21.313 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
Read response line character: 2=50
00:18:21.313 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
Read response line character: 0=48
00:18:21.314 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
Read response line character: 0=48
00:18:21.314 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
Read response line character: =32
00:18:21.314 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
Read response line character: O=79
00:18:21.314 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
Read response line character: K=75
00:18:21.315 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
Read response line character:
00:18:21.315 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
Read response line character:
[junit] =10
00:18:21.315 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
begin response headers
00:18:21.317 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
begin response body
00:18:21.317 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
end response body
00:18:21.318 SEVERE [main]
org.apache.tomcat.util.net.TestSsl.testRenegotiateWorks end request
before socket.startHandshake
00:18:21.320 SEVERE [main]
org.apache.tomcat.util.net.TestSsl.testRenegotiateWorks begin
socket.startHandshake
00:18:21.327 SEVERE [main]
org.apache.tomcat.util.net.TestSsl.testRenegotiateWorks end
socket.startHandshake
00:18:21.327 SEVERE [main]
org.apache.tomcat.util.net.TestSsl.testRenegotiateWorks begin request 1
00:18:21.329 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
begin request
00:18:21.330 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
flush request
00:18:21.330 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
begin response
00:18:21.336 FINE [http-nio2-127.0.0.1-auto-3-exec-8]
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process
Socket:
[org.apache.tomcat.util.net.Nio2Endpoint$Nio2SocketWrapper@1b4ba80:org.apache.tomcat.util.net.SecureNio2Channel@32156a:sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected
local=/127.0.0.1:35749 remote=/127.0.0.1:35750]], Status in:
[OPEN_READ], State out: [LONG]
00:18:21.340 FINE [http-nio2-127.0.0.1-auto-3-exec-9]
org.apache.coyote.http11.AbstractNioInputBuffer.parseRequestLine
Received [GET /tester HTTP/1.1
[junit] Host: localhost
[junit] Connection: Keep-Alive
[junit]
[junit] ]
00:18:21.341 FINE [http-nio2-127.0.0.1-auto-3-exec-9]
org.apache.catalina.connector.CoyoteAdapter.parsePathParameters The
variable [uriBC] has value [/tester]
00:18:21.341 FINE [http-nio2-127.0.0.1-auto-3-exec-9]
org.apache.catalina.connector.CoyoteAdapter.parsePathParameters The
variable [semicolon] has value [-1]
00:18:21.342 FINE [http-nio2-127.0.0.1-auto-3-exec-9]
org.apache.catalina.connector.CoyoteAdapter.parsePathParameters The
variable [enc] has value [utf-8]
00:18:21.343 FINE [http-nio2-127.0.0.1-auto-3-exec-9]
org.apache.catalina.realm.RealmBase.findSecurityConstraints No
applicable constraints defined
00:18:21.343 FINER [http-nio2-127.0.0.1-auto-3-exec-9]
org.apache.catalina.core.StandardWrapper.allocate Returning non-STM
instance
00:18:21.347 FINE [http-nio2-127.0.0.1-auto-3-exec-9]
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process
Socket:
[org.apache.tomcat.util.net.Nio2Endpoint$Nio2SocketWrapper@1b4ba80:org.apache.tomcat.util.net.SecureNio2Channel@32156a:sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected
local=/127.0.0.1:35749 remote=/127.0.0.1:35750]], Status in:
[OPEN_READ], State out: [OPEN]
00:18:21.353 FINE [http-nio2-127.0.0.1-auto-3-exec-10]
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process
Socket:
[org.apache.tomcat.util.net.Nio2Endpoint$Nio2SocketWrapper@1b4ba80:org.apache.tomcat.util.net.SecureNio2Channel@32156a:sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected
local=/127.0.0.1:35749 remote=/127.0.0.1:35750]], Status in:
[OPEN_READ], State out: [LONG]
00:18:21.354 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
Read response line character: H=72
00:18:21.354 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
Read response line character: T=84
00:18:21.354 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
Read response line character: T=84
00:18:21.355 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
Read response line character: P=80
00:18:21.355 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
Read response line character: /=47
00:18:21.355 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
Read response line character: 1=49
00:18:21.355 SEVERE [HandshakeCompletedNotify-Thread]
org.apache.tomcat.util.net.TestSsl$TesterHandshakeListener.handshakeCompleted
handshakeCompleted
00:18:21.355 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
Read response line character: .=46
00:18:21.357 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
Read response line character: 1=49
00:18:21.357 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
Read response line character: =32
00:18:21.357 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
Read response line character: 2=50
00:18:21.358 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
Read response line character: 0=48
00:18:21.358 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
Read response line character: 0=48
00:18:21.358 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
Read response line character: =32
00:18:21.358 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
Read response line character: O=79
00:18:21.359 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
Read response line character: K=75
00:18:21.359 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
Read response line character:
00:18:21.359 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
Read response line character:
[junit] =10
00:18:21.360 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
begin response headers
00:18:21.361 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
begin response body
00:18:21.361 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
end response body
00:18:21.361 SEVERE [main]
org.apache.tomcat.util.net.TestSsl.testRenegotiateWorks end request 1
00:18:21.362 SEVERE [main]
org.apache.tomcat.util.net.TestSsl$TesterHandshakeListener.isComplete
isComplete returning true
00:18:21.362 SEVERE [main]
org.apache.tomcat.util.net.TestSsl.testRenegotiateWorks
listener.isComplete(): true
00:18:21.362 SEVERE [main]
org.apache.tomcat.util.net.TestSsl$TesterHandshakeListener.isComplete
isComplete returning true
00:18:21.362 SEVERE [main]
org.apache.tomcat.util.net.TestSsl.testRenegotiateWorks Set
listenerComplete to: 1
00:18:21.363 SEVERE [main]
org.apache.tomcat.util.net.TestSsl.testRenegotiateWorks begin request 2
00:18:21.363 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
begin request
00:18:21.364 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
flush request
00:18:21.364 SEVERE [main] org.apache.tomcat.util.net.TestSsl.doRequest
begin response
Unfortunately there's not so much log output from NIO2 itself. Just:
00:18:21.141 FINE [main]
org.apache.catalina.util.LifecycleBase.setStateInternal Setting state
for [Connector[org.apache.coyote.http11.Http11Nio2Protocol-auto-3]] to
[STARTING_PREP]
00:18:21.141 FINE [main]
org.apache.catalina.util.LifecycleBase.setStateInternal Setting state
for [Connector[org.apache.coyote.http11.Http11Nio2Protocol-auto-3]] to
[STARTING]
00:18:21.142 INFO [main] org.apache.coyote.AbstractProtocol.start
Starting ProtocolHandler ["http-nio2-127.0.0.1-auto-3-35749"]
00:18:21.156 FINE [main]
org.apache.catalina.util.LifecycleBase.setStateInternal Setting state
for [Connector[org.apache.coyote.http11.Http11Nio2Protocol-auto-3]] to
[STARTED]
00:18:21.156 FINE [main]
org.apache.catalina.util.LifecycleBase.setStateInternal Setting state
for [StandardService[Tomcat]] to [STARTED]
00:18:21.157 FINE [main]
org.apache.catalina.util.LifecycleBase.setStateInternal Setting state
for [StandardServer[-1]] to [STARTED]
00:18:21.163 FINE [http-nio2-127.0.0.1-auto-3-Acceptor-0]
org.apache.tomcat.util.threads.LimitLatch.countUpOrAwait Counting
up[http-nio2-127.0.0.1-auto-3-Acceptor-0] latch=0
00:18:21.194 FINE [http-nio2-127.0.0.1-auto-3-Acceptor-0]
org.apache.tomcat.util.threads.LimitLatch.countUpOrAwait Counting
up[http-nio2-127.0.0.1-auto-3-Acceptor-0] latch=1
00:18:21.289 FINE [http-nio2-127.0.0.1-auto-3-exec-4]
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.register
Register
Tomcat:type=RequestProcessor,worker="http-nio2-127.0.0.1-auto-3-35749",name=HttpRequest1
00:18:21.290 FINE [http-nio2-127.0.0.1-auto-3-exec-4]
org.apache.tomcat.util.modeler.Registry.registerComponent Managed=
Tomcat:type=RequestProcessor,worker="http-nio2-127.0.0.1-auto-3-35749",name=HttpRequest1
00:18:21.291 FINER [http-nio2-127.0.0.1-auto-3-exec-4]
com.sun.jmx.mbeanserver.Repository.contains name =
Tomcat:type=RequestProcessor,worker="http-nio2-127.0.0.1-auto-3-35749",name=HttpRequest1
00:18:21.291 FINER [http-nio2-127.0.0.1-auto-3-exec-4]
com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerMBean
ObjectName =
Tomcat:type=RequestProcessor,worker="http-nio2-127.0.0.1-auto-3-35749",name=HttpRequest1
00:18:21.291 FINE [http-nio2-127.0.0.1-auto-3-exec-4]
org.apache.tomcat.util.modeler.BaseModelMBean.preRegister preRegister
org.apache.coyote.RequestInfo@1c22e0
Tomcat:type=RequestProcessor,worker="http-nio2-127.0.0.1-auto-3-35749",name=HttpRequest1
00:18:21.291 FINER [http-nio2-127.0.0.1-auto-3-exec-4]
com.sun.jmx.mbeanserver.Repository.addMBean name =
Tomcat:type=RequestProcessor,worker="http-nio2-127.0.0.1-auto-3-35749",name=HttpRequest1
00:18:21.292 FINER [http-nio2-127.0.0.1-auto-3-exec-4]
com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.addObject Send
create notification of object
Tomcat:name=HttpRequest1,type=RequestProcessor,worker="http-nio2-127.0.0.1-auto-3-35749"
00:18:21.292 FINER [http-nio2-127.0.0.1-auto-3-exec-4]
com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.sendNotification
JMX.mbean.registered
Tomcat:type=RequestProcessor,worker="http-nio2-127.0.0.1-auto-3-35749",name=HttpRequest1
00:18:21.293 FINE [http-nio2-127.0.0.1-auto-3-exec-4]
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process
Socket:
[org.apache.tomcat.util.net.Nio2Endpoint$Nio2SocketWrapper@1b4ba80:org.apache.tomcat.util.net.SecureNio2Channel@32156a:sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected
local=/127.0.0.1:35749 remote=/127.0.0.1:35750]], Status in:
[OPEN_READ], State out: [LONG]
00:18:21.294 FINE [http-nio2-127.0.0.1-auto-3-exec-5]
org.apache.coyote.http11.AbstractNioInputBuffer.parseRequestLine
Received [GET /tester HTTP/1.1
[junit] ]
00:18:21.295 FINE [http-nio2-127.0.0.1-auto-3-exec-5]
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process
Socket:
[org.apache.tomcat.util.net.Nio2Endpoint$Nio2SocketWrapper@1b4ba80:org.apache.tomcat.util.net.SecureNio2Channel@32156a:sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected
local=/127.0.0.1:35749 remote=/127.0.0.1:35750]], Status in:
[OPEN_READ], State out: [LONG]
00:18:21.302 FINE [http-nio2-127.0.0.1-auto-3-exec-6]
org.apache.tomcat.util.http.Parameters.setQueryStringEncoding Set query
string encoding to UTF-8
00:18:21.303 FINE [http-nio2-127.0.0.1-auto-3-exec-6]
org.apache.catalina.connector.CoyoteAdapter.parsePathParameters The
variable [uriBC] has value [/tester]
00:18:21.303 FINE [http-nio2-127.0.0.1-auto-3-exec-6]
org.apache.catalina.connector.CoyoteAdapter.parsePathParameters The
variable [semicolon] has value [-1]
00:18:21.304 FINE [http-nio2-127.0.0.1-auto-3-exec-6]
org.apache.catalina.connector.CoyoteAdapter.parsePathParameters The
variable [enc] has value [utf-8]
00:18:21.305 FINE [http-nio2-127.0.0.1-auto-3-exec-6]
org.apache.catalina.realm.RealmBase.findSecurityConstraints No
applicable constraints defined
00:18:21.306 FINE [http-nio2-127.0.0.1-auto-3-exec-6]
org.apache.catalina.core.StandardWrapper.allocate Allocating non-STM
instance
00:18:21.306 FINER [http-nio2-127.0.0.1-auto-3-exec-6]
org.apache.catalina.core.StandardWrapper.allocate Returning non-STM
instance
00:18:21.310 FINE [http-nio2-127.0.0.1-auto-3-exec-6]
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process
Socket:
[org.apache.tomcat.util.net.Nio2Endpoint$Nio2SocketWrapper@1b4ba80:org.apache.tomcat.util.net.SecureNio2Channel@32156a:sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected
local=/127.0.0.1:35749 remote=/127.0.0.1:35750]], Status in:
[OPEN_READ], State out: [OPEN]
[junit] =10
00:18:21.336 FINE [http-nio2-127.0.0.1-auto-3-exec-8]
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process
Socket:
[org.apache.tomcat.util.net.Nio2Endpoint$Nio2SocketWrapper@1b4ba80:org.apache.tomcat.util.net.SecureNio2Channel@32156a:sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected
local=/127.0.0.1:35749 remote=/127.0.0.1:35750]], Status in:
[OPEN_READ], State out: [LONG]
00:18:21.340 FINE [http-nio2-127.0.0.1-auto-3-exec-9]
org.apache.coyote.http11.AbstractNioInputBuffer.parseRequestLine
Received [GET /tester HTTP/1.1
[junit] Host: localhost
[junit] Connection: Keep-Alive
[junit]
[junit] ]
00:18:21.341 FINE [http-nio2-127.0.0.1-auto-3-exec-9]
org.apache.catalina.connector.CoyoteAdapter.parsePathParameters The
variable [uriBC] has value [/tester]
00:18:21.341 FINE [http-nio2-127.0.0.1-auto-3-exec-9]
org.apache.catalina.connector.CoyoteAdapter.parsePathParameters The
variable [semicolon] has value [-1]
00:18:21.342 FINE [http-nio2-127.0.0.1-auto-3-exec-9]
org.apache.catalina.connector.CoyoteAdapter.parsePathParameters The
variable [enc] has value [utf-8]
00:18:21.343 FINE [http-nio2-127.0.0.1-auto-3-exec-9]
org.apache.catalina.realm.RealmBase.findSecurityConstraints No
applicable constraints defined
00:18:21.343 FINER [http-nio2-127.0.0.1-auto-3-exec-9]
org.apache.catalina.core.StandardWrapper.allocate Returning non-STM
instance
00:18:21.347 FINE [http-nio2-127.0.0.1-auto-3-exec-9]
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process
Socket:
[org.apache.tomcat.util.net.Nio2Endpoint$Nio2SocketWrapper@1b4ba80:org.apache.tomcat.util.net.SecureNio2Channel@32156a:sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected
local=/127.0.0.1:35749 remote=/127.0.0.1:35750]], Status in:
[OPEN_READ], State out: [OPEN]
00:18:21.353 FINE [http-nio2-127.0.0.1-auto-3-exec-10]
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process
Socket:
[org.apache.tomcat.util.net.Nio2Endpoint$Nio2SocketWrapper@1b4ba80:org.apache.tomcat.util.net.SecureNio2Channel@32156a:sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected
local=/127.0.0.1:35749 remote=/127.0.0.1:35750]], Status in:
[OPEN_READ], State out: [LONG]
All of the next request (that finally hangs) does not seem to trigger
any NIO2 log output.
The only NIO2 thread that's not idle in the pool is the acceptor:
"http-nio2-127.0.0.1-auto-3-Acceptor-0" daemon prio=3 tid=0x00da3c00
nid=0x41 waiting on condition [0xb367f000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0xe73c5b30> (a
java.util.concurrent.CountDownLatch$Sync)
at
java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
at
java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:834)
at
java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:994)
at
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1303)
at
java.util.concurrent.CountDownLatch.await(CountDownLatch.java:236)
at sun.nio.ch.PendingFuture.get(PendingFuture.java:180)
at
org.apache.tomcat.util.net.Nio2Endpoint$Acceptor.run(Nio2Endpoint.java:721)
at java.lang.Thread.run(Thread.java:745)
The last latch log lines were:
00:18:21.163 FINE [http-nio2-127.0.0.1-auto-3-Acceptor-0]
org.apache.tomcat.util.threads.LimitLatch.countUpOrAwait Counting
up[http-nio2-127.0.0.1-auto-3-Acceptor-0] latch=0
00:18:21.194 FINE [http-nio2-127.0.0.1-auto-3-Acceptor-0]
org.apache.tomcat.util.threads.LimitLatch.countUpOrAwait Counting
up[http-nio2-127.0.0.1-auto-3-Acceptor-0] latch=1
Any ideas? Anything in NIO2 that I should track?
Regards,
Rainer
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org
For additional commands, e-mail: dev-h...@tomcat.apache.org
