You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@tomcat.apache.org by Violeta Georgieva <vi...@apache.org> on 2017/04/04 14:12:08 UTC
Hang in TestSsl testRenegotiateWorks for NIO2 (was Re: [VOTE] Release
Apache Tomcat 8.0.43)
Hi Rainer,
2017-03-30 23:59 GMT+03:00 Rainer Jung <ra...@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.
Regards,
Violeta
> Same as with 8.0.42 so likely reproducible.
>
> Details
> =======
>
> - MD5 OK
> - signatures OK
> - key in KEYS file
> - gz and zip for src and bin consistent
> - src completely consistent with svn tag
> - builds fine
> - warning about unchecked calls or conversions in:
> - org/apache/catalina/tribes/tipis/AbstractReplicatedMap.java
> - org/apache/tomcat/jdbc/pool/PoolProperties.java
> Not a regression
> - build result looks consistent with binaries
> - no checkstyle complaints
> - no Javadoc warnings
>
> - Unit tests: Hang for NIO2 in TestSsl testRenegotiateWorks.
> Same as for 8.0.42, see my vote mail there for stack and logs.
> No other failures.
> - ERROR message:
> - more "Incomplete jul log message ... (only message)" (4 versus 6)
> - more "ERROR:null" (4 versus 6)
>
> - WARN messages:
> - less Tribes warnings (68 versus 58)
> - more
org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads
>
> - SEVERE messages
> - new org.apache.catalina.connector.CoyoteAdapter.asyncDispatch
Exception while processing an asynchronous request" (bio 1)
>
> - Exceptions: not compared
>
> - JMX MBean Comparison with 8.0.42:
> - ThreadPool MBean attribute currentThreadCount changed
> from 0 to 10 (ajp) resp. 1 to 10 (http)
> - Threading MBean analogously shows 19 more daemon threads
> - ProtocolHandler MBean for http new attribute
> "compressibleMimeType:
text/html,text/xml,text/plain,text/css,text/javascript,application/javascript"
>
> Build and tests were done using Java 1.7.0_80. OS was Solaris 10 Sparc,
tcnative was 1.2.12 based on APR 1.5.2 and OpenSSL 1.0.2k.
>
> Thanks for RM and regards,
>
> Rainer
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: dev-help@tomcat.apache.org
>
Re: Hang in TestSsl testRenegotiateWorks for NIO2 (was Re: [VOTE]
Release Apache Tomcat 8.0.43)
Posted by Rémy Maucherat <re...@apache.org>.
2017-04-07 14:49 GMT+02:00 Rainer Jung <ra...@kippdata.de>:
> Am 07.04.2017 um 11:22 schrieb Rémy Maucherat:
>
>> 2017-04-06 21:57 GMT+02:00 Rainer Jung <ra...@kippdata.de>:
>>
>> 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.
>>>
>>> This test is skipped with NIO. With NIO2, it works for me, so it's not,
>>>
>> but when I had a look then, I became convinced it's impossible to
>> guarantee
>> the process will work with async IO and the SSL engine. Basically, it's
>> really a blocking IO thing, preferably all integrated like with java.io.
>> However, the feature should be kept since usually the user will not be in
>> the worst case scenario, unlike the test.
>>
>> So if this bothers you, the easiest at this point is to skip the test for
>> NIO2 in Tomcat 8.0.
>>
>
> Hi Rémy
>
> what about:
>
> Index: build.xml
> ===================================================================
> --- build.xml (revision 1790439)
> +++ build.xml (working copy)
> @@ -1480,6 +1480,8 @@
> <exclude name="org/apache/tomcat/util/net/jsse/openssl/**"
> unless="${test.openssl.exists}" />
> <!-- Exclude performance tests. E.g. on systems with
> slow/inconsistent timing -->
> <exclude name="**/*Performance.java"
> if="${test.excludePerformance}" />
> + <!-- Exclude a configurable list of tests -->
> + <exclude name="${test.exclude}" />
> </fileset>
> </batchtest>
> </junit>
>
>
> so one can exclude tests by listing them in property "test.exclude". For
> me on Solaris TestSsl hangs the test suite, so I would prefer to
> skip/exclude it, all others currently do not have a problem with it. So we
> can keep the test enabled for now and I will disable it in my environment
> using the new test.exclude property. Once more people or Gump etc. report
> failures we can officially skip it.
>
> WDYT?
>
> +1, this option won't hurt obviously.
Right now, the code is:
protected static boolean isRenegotiationSupported(Tomcat tomcat) {
String protocol =
tomcat.getConnector().getProtocolHandlerClassName();
if (protocol.contains("Apr")) {
// Disabled by default in 1.1.20 windows binary (2010-07-27)
return false;
}
if (protocol.contains("NioProtocol") ||
(protocol.contains("Nio2Protocol") && isMacOs())) {
// Doesn't work on all platforms - see BZ 56448.
return false;
}
return true;
}
So if we know it doesn't work on Solaris, it can be filtered out there.
Rémy
Re: Hang in TestSsl testRenegotiateWorks for NIO2 (was Re: [VOTE]
Release Apache Tomcat 8.0.43)
Posted by Rainer Jung <ra...@kippdata.de>.
Am 07.04.2017 um 11:22 schrieb R�my Maucherat:
> 2017-04-06 21:57 GMT+02:00 Rainer Jung <ra...@kippdata.de>:
>
>> 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.
>>
>> This test is skipped with NIO. With NIO2, it works for me, so it's not,
> but when I had a look then, I became convinced it's impossible to guarantee
> the process will work with async IO and the SSL engine. Basically, it's
> really a blocking IO thing, preferably all integrated like with java.io.
> However, the feature should be kept since usually the user will not be in
> the worst case scenario, unlike the test.
>
> So if this bothers you, the easiest at this point is to skip the test for
> NIO2 in Tomcat 8.0.
Hi R�my
what about:
Index: build.xml
===================================================================
--- build.xml (revision 1790439)
+++ build.xml (working copy)
@@ -1480,6 +1480,8 @@
<exclude name="org/apache/tomcat/util/net/jsse/openssl/**"
unless="${test.openssl.exists}" />
<!-- Exclude performance tests. E.g. on systems with
slow/inconsistent timing -->
<exclude name="**/*Performance.java"
if="${test.excludePerformance}" />
+ <!-- Exclude a configurable list of tests -->
+ <exclude name="${test.exclude}" />
</fileset>
</batchtest>
</junit>
so one can exclude tests by listing them in property "test.exclude". For
me on Solaris TestSsl hangs the test suite, so I would prefer to
skip/exclude it, all others currently do not have a problem with it. So
we can keep the test enabled for now and I will disable it in my
environment using the new test.exclude property. Once more people or
Gump etc. report failures we can officially skip it.
WDYT?
Regards,
Rainer
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: Hang in TestSsl testRenegotiateWorks for NIO2 (was Re: [VOTE]
Release Apache Tomcat 8.0.43)
Posted by Rémy Maucherat <re...@apache.org>.
2017-04-06 21:57 GMT+02:00 Rainer Jung <ra...@kippdata.de>:
> 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.
>
> This test is skipped with NIO. With NIO2, it works for me, so it's not,
but when I had a look then, I became convinced it's impossible to guarantee
the process will work with async IO and the SSL engine. Basically, it's
really a blocking IO thing, preferably all integrated like with java.io.
However, the feature should be kept since usually the user will not be in
the worst case scenario, unlike the test.
So if this bothers you, the easiest at this point is to skip the test for
NIO2 in Tomcat 8.0.
Rémy
Re: Hang in TestSsl testRenegotiateWorks for NIO2 (was Re: [VOTE]
Release Apache Tomcat 8.0.43)
Posted by Rainer Jung <ra...@kippdata.de>.
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 <ra...@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
Re: Hang in TestSsl testRenegotiateWorks for NIO2 (was Re: [VOTE]
Release Apache Tomcat 8.0.43)
Posted by Rainer Jung <ra...@kippdata.de>.
Hi Violeta,
Am 04.04.2017 um 16:12 schrieb Violeta Georgieva:
> Hi Rainer,
>
> 2017-03-30 23:59 GMT+03:00 Rainer Jung <ra...@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