tomcat-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Rainer Jung <rainer.j...@kippdata.de>
Subject Re: Hang in TestSsl testRenegotiateWorks for NIO2 (was Re: [VOTE] Release Apache Tomcat 8.0.43)
Date Thu, 06 Apr 2017 19:57:15 GMT
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.jung@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-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org


Mime
View raw message