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 Tue, 04 Apr 2017 22:32:13 GMT
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