Re: Hang in TestSsl testRenegotiateWorks for NIO2 (was Re: [VOTE] Release Apache Tomcat 8.0.43)

Tue, 04 Apr 2017 15:32:44 -0700 

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

Reply via email to